Large sched_yield() and threading overhead (+25-40% perf boost)

[AndreiLux]

Platform: macOS / Apple M2 Pro

Currently the current thread finalisation / synchronisation logic in ggml_graph_compute_thread relies on sched_yield() to spin idly waiting for other threads to complete :

https://github.com/ggerganov/llama.cpp/blob/master/ggml.c#L16045

            // wait for other threads to finish
            const int last = node_n;
            do {
                sched_yield();
                node_n = atomic_load(&state->shared->node_n);
            } while (node_n == last);

The problem with that is that this is causing absolutely gigantic amounts of overhead due to context switching and falling back to the kernel with no known time as to when the thread will come back to execution.

When profiling time on an M2 Pro:

./build-llvm16-native/bin/main -m ./models/7B/ggml-model-q4_0.bin -t 8 -n 512 -p "Explain a CPU microarchitecture basics." -s 3215465
main: build = 775 (d7d2e6a)
main: seed  = 3215465
llama.cpp: loading model from ./models/7B/ggml-model-q4_0.bin
llama_model_load_internal: format     = ggjt v3 (latest)
llama_model_load_internal: n_vocab    = 32000
llama_model_load_internal: n_ctx      = 512
llama_model_load_internal: n_embd     = 4096
llama_model_load_internal: n_mult     = 256
llama_model_load_internal: n_head     = 32
llama_model_load_internal: n_layer    = 32
llama_model_load_internal: n_rot      = 128
llama_model_load_internal: ftype      = 2 (mostly Q4_0)
llama_model_load_internal: n_ff       = 11008
llama_model_load_internal: model size = 7B
llama_model_load_internal: ggml ctx size =    0.08 MB
llama_model_load_internal: mem required  = 5439.94 MB (+ 1026.00 MB per state)
llama_new_context_with_model: kv self size  =  256.00 MB

system_info: n_threads = 8 / 12 | AVX = 0 | AVX2 = 0 | AVX512 = 0 | AVX512_VBMI = 0 | AVX512_VNNI = 0 | FMA = 0 | NEON = 1 | ARM_FMA = 1 | F16C = 0 | FP16_VA = 1 | WASM_SIMD = 0 | BLAS = 1 | SSE3 = 0 | VSX = 0 | 
sampling: repeat_last_n = 64, repeat_penalty = 1.100000, presence_penalty = 0.000000, frequency_penalty = 0.000000, top_k = 40, tfs_z = 1.000000, top_p = 0.950000, typical_p = 1.000000, temp = 0.800000, mirostat = 0, mirostat_lr = 0.100000, mirostat_ent = 5.000000
generate: n_ctx = 512, n_batch = 512, n_predict = 512, n_keep = 0


(....)

llama_print_timings:        load time =   164.84 ms
llama_print_timings:      sample time =   281.18 ms /   414 runs   (    0.68 ms per token,  1472.36 tokens per second)
llama_print_timings: prompt eval time =   397.91 ms /    11 tokens (   36.17 ms per token,    27.64 tokens per second)
llama_print_timings:        eval time = 21528.10 ms /   413 runs   (   52.13 ms per token,    19.18 tokens per second)
llama_print_timings:       total time = 22244.37 ms

We see that in terms of time spent, the thing is wasting a huge amount of time in swtch_pri which is the system library for thread yielding, further then switching into kernel mode.

56.69 s  100.0%	0 s	 	main (84121)
36.71 s   64.7%	36.71 s	 	 ggml_vec_dot_q4_0_q8_0
15.95 s   28.1%	15.95 s	 	 swtch_pri
1.82 s    3.2%	1.82 s	 	 ggml_compute_forward_mul_mat
980.30 ms    1.7%	980.30 ms	 	 ggml_vec_dot_q6_K_q8_K
445.90 ms    0.7%	445.90 ms	 	 ggml_compute_forward_dup
119.30 ms    0.2%	119.30 ms	 	 ggml_graph_compute_thread

Simply commenting out sched_yield():

            // wait for other threads to finish
            const int last = node_n;
            do {
                //sched_yield();
                node_n = atomic_load(&state->shared->node_n);
            } while (node_n == last);

Results in a massive performance boost:

llama_print_timings:        load time =   129.83 ms
llama_print_timings:      sample time =   291.24 ms /   414 runs   (    0.70 ms per token,  1421.53 tokens per second)
llama_print_timings: prompt eval time =   334.44 ms /    11 tokens (   30.40 ms per token,    32.89 tokens per second)
llama_print_timings:        eval time = 14967.86 ms /   413 runs   (   36.24 ms per token,    27.59 tokens per second)
llama_print_timings:       total time = 15630.33 ms

As new profile looks like this:

41.25 s  100.0%	0 s	 	main (84137)
33.05 s   80.1%	33.05 s	 	 ggml_vec_dot_q4_0_q8_0
4.86 s   11.7%	4.86 s	 	 ggml_graph_compute_thread
1.34 s    3.2%	1.34 s	 	 ggml_compute_forward_mul_mat
930.00 ms    2.2%	930.00 ms	 	 ggml_vec_dot_q6_K_q8_K
490.70 ms    1.1%	490.70 ms	 	 ggml_compute_forward_dup
83.40 ms    0.2%	83.40 ms	 	 llama_sample_repetition_penalty

In the above interactive Terminal command-line example we see a 43% performance boost. The % will differ depending on where you call this from due to macOS thread QoS (ssh is around +25%).

This seems like a gigantic performance issue on the operating systems which do actually yield back to the scheduler.
My solution of just commenting out the yield and just looping probably isn't the best for power efficiency, you'd probably want to implement whatever tight atomic lock / wait across the threads. Up to you what to do here, but anything is better than sched_yield().

Another issue is the thread creation; as the threads get created and joined on each layer/operation, we see the cumulative overhead to be extremely large:

1.02 min  100.0%	0 s	 	main (82676)
36.31 s   59.4%	36.31 s	 	 ggml_vec_dot_q4_0_q8_0
16.74 s   27.4%	16.74 s	 	 swtch_pri
4.51 s    7.3%	4.51 s	 	 thread_start
1.44 s    2.3%	1.44 s	 	 ggml_compute_forward_mul_mat
805.01 ms    1.3%	805.01 ms	 	 ggml_vec_dot_q6_K_q8_K
390.01 ms    0.6%	390.01 ms	 	 ggml_compute_forward_dup
130.01 ms    0.2%	130.01 ms	 	 ggml_graph_compute_thread

It's likely we could see another 7% performance boost here by switching the work dispatch architecture to a thread pool.

Thank you for the work on the otherwise great implementation!

[ggerganov]

The initial implementation indeed was using only busy loops on atomic variables without yield since I've noticed that it can cause significant performance degradation. In #1556 we reimplemented the thread synchronization code and introduced this sched_yield() call. I tried with and without it and it wasn't causing any difference on my machines (one of which is M1 Pro), so I decided to keep it hoping that it will make things slightly more energy efficient.

I just redid the tests and I don't see any performance difference with or without it.
On M1 Pro, I get ~39 ms / tok for that same model and -t 8 -n 64.

I'm surprised that your time on master is so significantly worse.
Anyway, will comment out the sched_yield() call just in case.

Regarding your point about a thread pool - I did try to implement a thread pool some time ago:

ggml-org/whisper.cpp#343

It didn't provide any improvement, but I'm open to revisit this idea today.
The only requirement is to have a minimalistic implementation of the pool - something like in the linked PR.

[mqy]

I can confirm the sched_yield() introduced significant context switch on macOS 2018 Pro.

Let me list some of the change log of ggml threading I know:

1. gg wrote the first spin lock busy spin version.
2. @Safari77 added mem_pause() in use pause asm insn in busyloop to run the CPU (13600K) 10 °C cooler #1314, the mem_pause reduced memory contention somewhat.
3. @zrm added numa and rewrote threading in Numa #1556 which removed atomic_fetch_add/acomic_fetch_sub during spin loop, thus the memory contention mode was changed from read/write to read. sched_yield() should introduced certain overhead, but is not significant because the overall perf (plus numa) is better comparing to previous revision.

The actual behavior of sched_yield() is OS dependent, perhaps we can not simply remove it without cross-platform perf testing.

[ggerganov]

The actual behavior of sched_yield() is OS dependent, perhaps we can not simply remove it without cross-platform perf testing.

Hm, I don't think there is a case where removing it can degrade performance. It could only potentially increase the energy consumption maybe

[evanmiller]

Is there a reason not to use pthread condition variables here?

[mqy]

Is there a reason not to use pthread condition variables here?

Typical compute graph contains more than a thousand tensor nodes to compute, most of the per-node computing time is several us (even less than 1 us), mul_mat for large prompt may take more than 1 ms. Typical pthread cond wait or notify/broadcast take at least several us, at worst tens of us.

[BrickBee]

Hm, I don't think there is a case where removing it can degrade performance. It could only potentially increase the energy consumption maybe

I might have found such a case:
Running on 32 logical AMD Ryzen 9 cores results in the fastest prompt processing speed and I didn't observe an obvious difference in processing time with and without yielding.
The text generation was roughly 6% slower for me when not yielding, compared to before the change.

There is no point in running so many threads for generation, since it's RAM-bound anyway. When running only 6 threads, there was no difference between yielding and not yielding. The text generation speed was also roughly 12% faster than in the previous test with 32 threads. The prompt processing was of course slower, independent of yielding, because it scales with the number of cores.

The energy consumption appeared surprisingly similar between the two versions. I didn't measure it precisely, but a big difference would have stood out.

Maybe others who have machines with a high number of cores can check if they also observe that effect on their systems?

[AndreiLux]

Hm, I don't think there is a case where removing it can degrade performance. It could only potentially increase the energy consumption maybe

I might have found such a case: Running on 32 logical AMD Ryzen 9 cores results in the fastest prompt processing speed and I didn't observe an obvious difference in processing time with and without yielding.

It highly depends on what OS you're running on. If that's Linux, then that's good feedback, if it's Windows, then sched_yield() just reduces back to Sleep(0); , so it doesn't mean much.

[wtarreau]

In any case, pauses and sched_yield() ought to only be called after a failure, and never before the first attempt, as it's extremely expensive, due to being a syscall (count ~400 cycles).

In other code, I'm used to use incremental operations in exponential backoff: loop without any pause a few thousand times, then with incremental count of PAUSE insns a few tens of thousands times, then only switch to sched_yield() as a last resort. I ran some test here a few months ago and won less than 1% with this, the contention being elsewhere, but eventually I should redo some tests.

[wtarreau]

Ouch! the removal is catastrophic here (80-core ARM Ampere Altra / Neoverse N1).

Before (commit ed9a54e with sched_yield()):

llama_print_timings:        load time =   588.23 ms
llama_print_timings:      sample time =   138.38 ms /    34 runs   (    4.07 ms per token,   245.71 tokens per second)
llama_print_timings: prompt eval time = 36128.03 ms /   842 tokens (   42.91 ms per token,    23.31 tokens per second)
llama_print_timings:        eval time =  7293.10 ms /    33 runs   (  221.00 ms per token,     4.52 tokens per second)
llama_print_timings:       total time = 43565.30 ms

After (commit 1d16309 with sched_yield() commented out):

llama_print_timings:        load time =   598.99 ms
llama_print_timings:      sample time =   122.21 ms /    30 runs   (    4.07 ms per token,   245.48 tokens per second)
llama_print_timings: prompt eval time = 42567.61 ms /   842 tokens (   50.56 ms per token,    19.78 tokens per second)
llama_print_timings:        eval time = 90640.44 ms /    29 runs   ( 3125.53 ms per token,     0.32 tokens per second)
llama_print_timings:       total time = 133335.19 ms

It's got 15 times slower!

With the sched_yield() moved after the test:

llama_print_timings:        load time =   594.79 ms
llama_print_timings:      sample time =   134.46 ms /    33 runs   (    4.07 ms per token,   245.43 tokens per second)
llama_print_timings: prompt eval time = 40595.16 ms /   842 tokens (   48.21 ms per token,    20.74 tokens per second)
llama_print_timings:        eval time =  6869.41 ms /    32 runs   (  214.67 ms per token,     4.66 tokens per second)
llama_print_timings:       total time = 47604.23 ms

The performance is back (and admittedly the ctx sw is huge).

Let me check with pause instructions first.

[wtarreau]

With 10 dummy loops before triggering sched_yield() I'm already getting this which is better than the original, and context-sw cut in half:

llama_print_timings:        load time =   597.33 ms
llama_print_timings:      sample time =   195.34 ms /    48 runs   (    4.07 ms per token,   245.73 tokens per second)
llama_print_timings: prompt eval time = 36352.44 ms /   842 tokens (   43.17 ms per token,    23.16 tokens per second)
llama_print_timings:        eval time =  9840.69 ms /    47 runs   (  209.38 ms per token,     4.78 tokens per second)
llama_print_timings:       total time = 46395.99 ms

Now with a real pause instruction (dmb ish on aarch64), it's getting even better:

llama_print_timings:        load time =   595.64 ms
llama_print_timings:      sample time =   211.63 ms /    52 runs   (    4.07 ms per token,   245.71 tokens per second)
llama_print_timings: prompt eval time = 35610.44 ms /   842 tokens (   42.29 ms per token,    23.64 tokens per second)
llama_print_timings:        eval time = 10195.07 ms /    51 runs   (  199.90 ms per token,     5.00 tokens per second)
llama_print_timings:       total time = 46024.95 ms

Increasing the sched_yield() trigger threshold to 50 iterations yields even more gains:

llama_print_timings:        load time =   590.06 ms
llama_print_timings:      sample time =   349.96 ms /    86 runs   (    4.07 ms per token,   245.74 tokens per second)
llama_print_timings: prompt eval time = 35435.52 ms /   842 tokens (   42.08 ms per token,    23.76 tokens per second)
llama_print_timings:        eval time = 16199.78 ms /    85 runs   (  190.59 ms per token,     5.25 tokens per second)
llama_print_timings:       total time = 51998.77 ms

So basically we were at 4.52 tok/s with sched_yield(), 0.32 tok/s without, and 5.25 with it slightly arranged, hence 16% faster than the original and 16 times faster than the current master.

The patch should be cut in two parts, one to define a pause() instruction and one to use it. I've only done x86_64 and aarch64 but armv7 could benefit from it as well. I cannot test on windows and I don't know if windows on arm is supported by the project, because the asm statement might differ there.

First patch to define ggml_pause():

diff --git a/ggml.c b/ggml.c
index c10877a..fcc9a5e 100644
--- a/ggml.c
+++ b/ggml.c
@@ -15887,6 +15887,14 @@ typedef pthread_t ggml_thread_t;
 
 #endif
 
+#if defined(__x86_64__) || (defined(_MSC_VER) && defined(_M_AMD64))
+#define ggml_pause()    _mm_pause()
+#elif defined(__aarch_64__)
+#define ggml_pause()    __asm__("dmb ish")
+#else
+#define ggml_pause()    __asm__("")
+#endif
+

Second one to use it:

diff --git a/ggml.c b/ggml.c
index c10877a..fcc9a5e 100644
--- a/ggml.c
+++ b/ggml.c
@@ -16045,10 +16053,19 @@ static thread_ret_t ggml_graph_compute_thread(void * data) {
         } else {
             // wait for other threads to finish
             const int last = node_n;
-            do {
-                //sched_yield();
+           unsigned int retries = 0;
+           unsigned int loops;
+
+            while (1) {
                 node_n = atomic_load(&state->shared->node_n);
-            } while (node_n == last);
+                if (node_n != last)
+                    break;
+                retries++;
+                if (retries > 50)
+                    sched_yield();
+                for (loops = 0; loops < (1U << ((retries-1) & 0x7)); loops++)
+                    ggml_pause();
+            }
         }
 
         // check if we should stop

[mqy]

marl use nop + sched_yield() . Since we are not aiming at energy savings and pause may slow down cpu frequency, I prefer nop.

https://github.com/google/marl/blob/aa9e85b2189d6f5dbba6909275661b37dfb5de69/src/scheduler.cpp#L640

[wtarreau]

The problem doesn't have anything to do with energy savings but with the extreme hammering of a shared cache line that's each other thread tries to get exclusive access on, so nobody can work, each finishing thread has to wait for all other ones to accept to give back that cache line for an exclusive access just to perform the atomic_fetch_sub(). I tried already to split n_active from n_nodes just in case, but it brought very marginal gains. The right approach would be to let the threads loop on a distinct counter that serves to start, and that this value is reset only once everyone is ready. It must obviously be located into a distinct cache line so that it never hurts other threads that are trying to touch it, and that it's set only once and reset only once. A counter can work as well (and is often better), as only the thread finishing will have to increment it.

Also on arm the "dmb ish" (equivalent to pause) is much more efficient than a series of NOP because it only flushes the instruction queue (not the cache), so that effectively adds a hole in the pipeline during which a core doesn't hinder the other ones. On x86 it's very interesting because it relinquishes the execution ports for the sibling thread of the same core for a few tens to hundreds of cycles, which is great as well (better perf on the other one, no contention).

I can try to have a look at this later.