Introduction
I run a character chat service on a local LLM with two GPUs at home. The model is a 3-bit GGUF of GLM-5.3-Flash, served by llama-server with four slots.
As the user base grew, up to about five people started talking at once during busy periods. Around then, slow turns became noticeable.
The usual candidates for a fix are these:
- Reduce input tokens (shorten history, replace images with captions)
- Increase parallelism
- Add GPUs
We had even written a design document, and the favorite was captioning persona images when they're saved, so no pixels would be sent during conversation.
To give away the ending: none of these was the real answer. The server sat idle 92% of the day, so capacity was fine. The slowness came from other people's generation nearly stopping while someone's long prefill ran.
The first step of the fix was changing a single startup option.
This article is a record of the log analysis behind that, and of the hypotheses we got wrong along the way.
What the document said
The first document had this summary from 24 hours of logs.
| What was counted | Count | Median | p95 | Max |
|---|---|---|---|---|
| Regular turns | 379 | 10.9 s | 59.9 s | 123.2 s |
| Of those, cache rate 95%+ | 309 | 10.2 s | 42.4 s | 123.2 s |
| Of those, 5,000+ uncached tokens | 32 | 36.3 s | 90.2 s | 98.7 s |
The document was written with Codex and was very careful. It said plainly that "five simultaneous users or summarization alone can't be named as the cause", and concluded that more measurement was needed.
But something in this table is strange. Almost the entire prompt hit the cache, yet the maximum was 123 seconds.
Why does it take two minutes when the input isn't being re-read? Reducing input can't explain that.
Matching the logs task by task
Before adding more instrumentation, I decided to break down the logs I already had.
llama-server's logs contain this for each task:
slot launch_slot_: id 0 | task 789281 | processing task
slot print_timing: id 0 | task 789281 | n_gen = 159, tg = 52.63 t/s, tg_3s = 52.97 t/s
slot print_timing: id 0 | task 789281 | prompt eval time = 612.51 ms / 193 tokens
slot print_timing: id 0 | task 789281 | eval time = 3526.61 ms / 187 tokens
slot release: id 0 | task 789281 | stop processing: n_tokens = 20756
The application logs the purpose of each call (regular turn, summary, translation, and so on). Matching the two by time and input token count puts the start, prefill, generation, and end of 854 tasks on one timeline.
Incidentally, I first read the log time 3517.09.125.958 as "hours.minutes.seconds.milliseconds" and produced a bizarre median of 343 seconds. It's actually "minutes.seconds.milliseconds.microseconds".
Where the time goes
I broke down 7,191 seconds of total chat processing, assuming solo speeds of 52 tok/s for generation and 800 tok/s for prefill.
| Breakdown | Seconds | Share |
|---|---|---|
| Own generation | 3,481 | 48% |
| Added by contention with others | 2,535 | 35% |
| Own prefill | 1,175 | 16% |
The median output is 347 tokens, which takes about 7 seconds even alone. So most of the "median slowness" is simply the length of generation. Contention, however, shapes the tail of slow turns.
What wasn't the cause
Checking one by one eliminated several plausible theories.
| Hypothesis | Result |
|---|---|
| Not enough GPU capacity | The server was idle 92% of the time. Two or more tasks ran together for about 2% of the day |
| Five users fighting over four slots | 3 cache misses in 366 consecutive turns within 5 minutes |
| Background work getting in the way | About 300 unlogged tasks took about 450 s in total; summaries took 728 s |
| Long context slows generation | Levels off around 48 tok/s beyond 10K tokens |
| The app's limit of 3 concurrent calls is too low | Only 2 gate waits |
I was surprised that slots were barely being fought over. llama-server's RAM prompt cache was doing its job. That cache also missed often until recently, which is covered in another article.
The real bottleneck
The decisive comparison was tg_3s (generation speed over the last 3 seconds).
| Situation during my generation | Median tg_3s |
|---|---|
| Overlapping another slot's prefill of 15K+ tokens (59 samples) | 0.34 tok/s |
| Everything else (1,360 samples) | 44.7 tok/s |
About 130 times slower. On screen, that looks completely stopped.
The cause is update_slots in tools/server/server-context.cpp. One pass looks roughly like this:
- Put the next token of each generating slot in the batch
- Fill the batch with prefilling slots' input, up to
n_batch - Process the whole batch
- Only now is the generating slot's next token decided
n_batch defaults to 2048. Prefill runs at about 800 tok/s, so one pass takes about 2.6 seconds. Someone generating advances one token every 2.6 seconds. That works out to about 0.39 tok/s, consistent with the measured 0.34.
GPU time is roughly proportional to the tokens in a batch, so whoever packs more into a pass takes the time.
A: generating, B: prefilling 25K tokens
Pass 1: A 1 token + B 2047 tokens → about 2.6 s → A gets one character
Pass 2: A 1 token + B 2047 tokens → about 2.6 s → A gets one character
... this continues for about 31 seconds
Where do the long prefills come from? Most of the 40 prefills of 5,000+ tokens were one of two things.
| Source | Count | Total new tokens |
|---|---|---|
| The day's first turn | 21 | 330K |
| The turn right after a history summary was applied | 13 | 300K |
Each time someone resumed a conversation or a long history was folded into a summary, a re-read of around 20K tokens ran. That person's wait may be unavoidable, but everyone else was stopping each time too.
A hypothesis that missed cleanly
I got my own explanation wrong at this point.
I explained that "a newly arrived short chat waits depending on the luck of its slot number". When I counted, it was 8.5 seconds with the earlier slot number and 5.3 with the later one, so it made no difference (fewer than 10 cases each).
Looking at the progress logs again, even short chat prefills split into several passes at checkpoint boundaries, and each pass was filled by the long prefill. One turn with 12 new tokens took 10 seconds. This is an interpretation from timing, but it fits far better than slot numbers.
A second cause: waiting the metrics couldn't see
I had been reading prefill time as "time to first character", which was also wrong.
Some tasks had a total time far above prefill plus generation. One had a total of 85.6 seconds, with just 1.9 seconds of prefill and 6.8 of generation. Where did the other 77 seconds go?
The wait before prefill starts isn't included in prompt eval time. After recalculating, the p95 of time to first character was 29.2 seconds, not 19.2.
I sorted those waits by what was running during them.
| Running during the wait | Count | Total wait | Max |
|---|---|---|---|
| A task with a different LoRA setting | 40 | 540 s | 76.8 s |
| A task with the same LoRA setting | 4 | 40 s | 29.1 s |
| Nothing else | 15 | 41 s | 18.6 s |
This service was switching LoRAs per request and applying them to only some turns. llama-server can't put slots with different LoRA settings in the same batch (can_batch_with). While the setting chosen first keeps being processed, a request with another setting can't even start.
My earlier notes said "four slots, so no real harm". There was real harm.
Fix 1: set n_batch to 512
My first idea was to patch llama-server to limit prefill only while a slot is generating.
But my co-developer (the human one) suggested: "if 512 doesn't affect prefill much compared with 2047, worst case just use that everywhere." That was much better.
n_ubatch defaults to 512, so the current 2048 was being processed in chunks of 512 internally anyway. The progress logs also gave speeds by batch size.
| Tokens advanced at once | Prefill speed |
|---|---|
| Nearly 2048 | 845 tok/s |
| 600–1500 | 816 tok/s |
| 256–600 | 719 tok/s |
| 64–256 | 436 tok/s |
Small batches are common right after a checkpoint is created, so they should read low. I judged that the drop at 512 would be small, and added one environment variable.
[Service]
Environment=LLAMA_ARG_BATCH=512
After applying it, I overlapped a prefill of 6,201 tokens with a generation and measured it (once).
| Item | Result |
|---|---|
| Generation speed (before / during / after prefill) | 47.7 / 2.06 / 45.6 tok/s |
| Gap between tokens during prefill | Median 0.44 s, max 1.54 s |
| Prefill speed | 802 tok/s |
| Progress increment | 511 tokens |
Prefill dropped by about 5% against the solo log figure (845 tok/s), while the stalled generation moved up to about 2 tok/s. No patch was needed, and the fork's diff didn't grow. It's still choppy, but "stopped" and "slow" are very different things.
Fix 2: unify the LoRA setting
For the LoRA waits, I first proposed a patch that alternates settings on every pass. That was another idea I offered before measuring, and measuring rejected it.
While the production model was idle, I sent short requests to compare.
| Condition | Prefill time (median) |
|---|---|
| Consecutive without LoRA | 247 ms |
| Consecutive with LoRA | 273 ms |
| Right after switching to LoRA | 1,008 ms |
| Right after switching to no LoRA | 995 ms |
One switch costs about 0.74 seconds. From the code, a LoRA change sets sched_need_reserve, and the next decode's sched_reserve rebuilds the scheduler and reserves the graph three times (I didn't measure the breakdown directly).
Alternating every pass would give two people about 0.65 tok/s each by calculation, not much better than being stopped.
Again it was the human who said: "wouldn't it be better to either use LoRA everywhere or remove it everywhere?" Don't make switching faster; eliminate switching. The speed difference is also small, about 8.5%.
Since this changes the content of the output, I compared everyday conversation, translation, image descriptions, and more across scales, then moved almost all turns to the same setting. The details of the quality evaluation are outside the scope of this article.
Results on real traffic
Using the same script, I compared the 24 hours before the changes (Nov 5 03:20 to Nov 6 03:20) with about 29 hours after both were in (Nov 6 07:57 to Nov 7 12:40).
The overall numbers look better. But they can't simply be called the effect, because usage was much lower afterward.
| Before | After | |
|---|---|---|
| Chat turns | 458 (19/hour) | 315 (11/hour) |
| Time with two or more tasks running | 1,750 s | 414 s |
| Time to first character, p95 (all turns) | 29.2 s | 19.5 s |
So I compared again using only turns under the same conditions. These are short turns with fewer than 1,000 new tokens, which should start right away.
| Time to first character (median / p90) | Before | After |
|---|---|---|
| Nothing else running | 1.4 / 2.5 s (290) | 1.1 / 2.2 s (223) |
| Overlapping another task | 2.0 / 8.7 s (71) | 1.3 / 1.7 s (12) |
| Overlapping a prefill of 5,000+ tokens | 9.0 / 33.3 s (20) | 2.3 / 3.1 s (7) |
The maximum for turns overlapping a long prefill went from 78.7 seconds to 3.1. The indicators for each cause also moved as expected.
| Indicator | Before | After | Mainly due to |
|---|---|---|---|
| Generation speed during a prefill of 15K+ tokens (median) | 0.34 tok/s (58 samples) | 1.62 tok/s (15 samples) | n_batch |
| Waits of 1+ s before prefill starts | 60 cases, 632 s total, max 76.8 s | 1 case, 8 s | LoRA |
| Prefill speed for 5,000+ tokens (median) | 824 tok/s | 830 tok/s | — |
| Generation speed (median) | 47.1 tok/s | 49.0 tok/s | — |
The prefill slowdown I worried about didn't show up on real traffic. Neither did a generation slowdown from applying LoRA to all turns in this comparison. Other conditions are mixed in, so I can't say the cost is zero.
Still, I can't call this solved yet.
- The post-change sample is small. The row I most want to know about has just 7 cases, from a little over a day
- The congestion that started all this didn't recur. Four tasks ran together for just 1 second after the change, so five people talking at once hasn't been measured
- The effects of
n_batchand LoRA can't be separated. I put them in within hours of each other. The design document said "mixing them makes the cause impossible to tell", and I did the opposite. "Mainly due to" in the table above is an inference from the mechanism - The median with nothing else running also moved from 1.4 to 1.1 seconds. A difference of this size can appear regardless of congestion
Fixes we didn't adopt
I re-estimated the effect of image captioning, the original favorite.
- Local-model personas have at most 5 images at 784 tokens each, about 5 seconds in total
- Images only cost anything on a cold start, 27 times a day, and about 30% of personas have two or more
- At most about 40 seconds a day, about 1% of all chat
Shortening the history budget came to about 90 seconds a day. Neither is a bad idea, but the effect wasn't worth trading conversation quality for.
The most carefully designed option was the least effective.
What I learned
1. Before looking at averages, look for contradictions in the tail. The single line "cache hit, yet 123 seconds" showed from the start that reducing input couldn't explain this.
2. Before adding measurements, match the logs you already have. This analysis didn't add a single new metric. Nearly everything needed was already in the logs.
3. Check what your metrics don't measure. prompt eval time doesn't include waiting. This gap is why the LoRA problem had stayed hidden.
4. Keep doubting hypotheses even after counting. After finding 0.34 tok/s, I wrongly blamed "slot number luck", then recommended alternation before measuring switch cost. Getting one piece of data right lends unearned confidence to the next explanation.
5. Before making something faster, ask whether you can remove it. A setting instead of a patch; eliminating switches instead of speeding them up. Both good ideas came from questions that stepped back from the problem.
That a single environment variable got stalled generation moving is a little annoying, and very satisfying.
If you want to reproduce this
To see this on your own setup, you only need to match these:
slot launch_slot_andslot release: task start and endprompt eval time/eval time: prefill and generation timen_gen … tg_3s: instantaneous generation speed (every 3 seconds after 100 tokens)total time - prompt eval - eval: the wait before prefill starts
If your service runs long prefills across multiple slots, start by looking at tg_3s during overlaps with long prefills. Behavior varies with llama-server's version and setup, so read these numbers as coming from GLM-5.3-Flash 3-bit, two GPUs, four slots, and a shared KV.