[engine bug] Decode throughput degrades from 60-120 to 11-25 tok/s over runtime; engine-global, cumulative, only reset by restart

[ender2007225]

Before you start

• I have read the FAQ and my problem is not answered there.
• I have read the Roadmap and this is not already planned there.
• I have searched existing issues and found no duplicate.
• I am on the latest release, or on a freshly rebuilt main when building from source.

What happened

Summary

After the engine has been serving for a while (in the cleanest case: ~15 minutes / a few dozen requests), decode throughput degrades from a healthy 60-120 tok/s to a stable 11-25 tok/s and never recovers on its own. The degradation is:

• Engine-global, not session-specific: a brand-new session with a fresh prefix runs at the degraded speed; a concurrently running healthy session earlier in the same engine process hit 62-68 tok/s.
• Cumulative: partially relieved by starting a fresh session (12.5 → <25 tok/s), but only an engine restart restores full speed.
• Constant per phase: two very different loads (127K old branch, 42K fresh compacted prefix) both pinned at ~11-12.5 tok/s, like a fixed degraded gear.

Timeline (2026-09-23, one engine process)

21:03 engine restart, model loaded
21:03-18 HEALTHY: 1 stream 64-74, 2 streams 97-123, 4 streams 110-119 tok/s
21:12:41 WARNING: Input sequence length 249912 exceeds 245760, request 16 is dropped
21:15-16 session A prefill 229K (usage 0.93), decodes 36-47 tok/s — slow but plausible for size
21:16:41 session B (77K, fresh) enters: 62-68 tok/s ← same pool, healthy
21:18:50 session B receives prefill append (+5792 on 122K cached) → drops to 11.2 tok/s
21:18-39 session B pinned at 10.9-12.7 tok/s for 50+ minutes, context 127K→152K
21:39:43 session B completes; client-side /compact executed (151K → 42K summary)
21:39:49 fresh prefix rebuilds KV (#cached-token: 0, usage 0.07→0.17) → still 12.5 tok/s
← compaction with a brand-new prefix does NOT restore speed
21:40+ brand-new session → still <25 tok/s (partial recovery only)
(previous day, same config: ~970 requests over 12h → 14.7 tok/s with queue buildup;
engine restart restored 80+ immediately)

Key evidence

1. Same-pool control: at 21:16, session B (77K) ran 62-68 tok/s while the pool was under load. At 21:40+, a fresh 42K session ran 12.5. Pool state is the variable, not context length or prefix.

2. Compaction negative test: opencode /compact genuinely replaced the history (server-side log shows #cached-token: 0 rebuild, context 151K→42K). Decode stayed 12.5. The slow state is not bound to the session's KV branch.

3. Fresh session partial relief: a new session improves 12.5 → <25 tok/s, consistent with a cleaner working set, but the engine-level degradation persists.

4. Restart restores: previous-day incident — 14.7 tok/s after 12h/970 requests, immediately back to 80+ after engine restart.

Already ruled out

• Not KV pool exhaustion (usage 0.17-0.62 during degraded phase; no queue buildup, no Adjust max_tokens in the clean case)
• Not expert-cache misses alone (config unchanged; healthy phase in the same process ran 2-5x faster)
• Not context length / attention cost (42K fresh prefix as slow as 152K old one)
• Not a client artifact (throughput measured from server-side Decode batch log lines)
• Not model/dtype (same checkpoint, same process, speed varies with engine age)

Hypothesis (unverified, from community diagnosis)

Engine-global cumulative degradation of a shared structure, triggered or accelerated by long-context cached-prefill appends. Candidates:

1. Radix tree global fragmentation — many large appends over 70K-230K branches leave the allocator unable to place new sequences efficiently
2. Mamba/linear-state semantic anchor cache accumulation — hybrid_radix anchors pile up and per-step state reconstruction degrades
3. Expert cache (LRU) pollution across heterogeneous workloads — but miss-rate alone doesn't explain 11 tok/s (bandwidth floor ≈ 34 tok/s for this model)

The consistent signature: degradation begins after a period of heavy prefills, is independent of session identity, persists across session boundaries, and is fully reset by engine restart. A plausible trigger to investigate: large cached-prefill appends on very long branches.

Repro steps (approximate)

1. Serve Qwen3.6-35B-A3B NVFP4 on a 16GB GPU with the config above
2. Drive it with an agent client (opencode) doing long-context work: 70K-230K histories, repeated multi-KB prefill appends
3. Within ~15-40 minutes / a few dozen requests, decode drops to a stable 11-25 tok/s
4. Verify: new sessions run at degraded speed; engine restart restores 60-120 tok/s

Workaround

Restart the engine. Client-side compaction or new sessions only partially help (~2x). One restart per work session is currently the practical cadence.

Happy to collect targeted diagnostics (cache_report, mamba stats, allocator traces) if pointed at the right flags. Full logs from both days available.

Log files (chronological):

• cmdINFO.txt (09-22, healthy morning → first slowdown ~20:40)
• cmdINFO(1).txt (09-23 21:02-21:07, restart + healthy phase)
• cmdINFO(2).txt (09-23 21:08-21:19, degradation onset at 21:18:50)
• cmdINFO(3).txt (09-23 21:19-21:44, pinned 11 tok/s + compaction test)

How did you install FreeToken

pip / uv wheel

FreeToken version

v0.2.0-beta.21 (FreeToken Desktop)

OS

Windows 11

OS details

No response

GPU and driver

NVIDIA GeForce RTX 5080 16GB NVIDIA driver 610.88

CPU and system RAM

AMD Ryzen 9 9950X3D2, 64GB DDR5-6000 (dual channel)

Checkpoint

Qwen3.6-35B-A3B-NVFP4 (FTW checkpoint, local path C:\AI_Models\Qwen3.6-35B-A3B-NVFP4)

Command

ft serve --model C:\AI_Models\Qwen3.6-35B-A3B-NVFP4 --port 1919 --moe-backend auto --max-running-requests 4 --memory-ratio 0.95 --moe-cpu-threads 32 --host 127.0.0.1

Cache config (GUI): KV 240K tokens (4.69 GiB), MoE expert cache 2519/10240 slots, Mamba slots 32
Workload: opencode agent sessions, long contexts (70K-230K), frequent large cached-prefill appends (tool results)

Full log

Full logs attached above (5 files, both days). Key excerpts below.

[1] Startup + cache config (2026-09-23 21:03)
21:03:12  Resolved config: moe_strategy='offload', attention_backend='triton', cache_type='hybrid_radix', page_size=1
21:03:22  Cache rebuilt: KV 245760 pages (245760 tokens, 4.69 GiB), mamba 32 slots (1.92 GiB), MoE cache 2519/10240 (4.17 GiB)

[2] Healthy phase (21:04-21:05)
21:04:24  Decode batch, #running-req: 2, gen throughput (token/s): 101.34
21:04:53  Decode batch, #running-req: 2, gen throughput (token/s): 123.63

[3] Degradation onset (21:18) — same session, same pool, no config change
21:18:50  Prefill batch, #new-token: 5792, #cached-token: 121712, token usage: 0.52
21:18:54  Decode batch, #token: 127542, gen throughput (token/s): 3.63
21:18:57  Decode batch, gen throughput (token/s): 11.20
21:19:11  Decode batch, gen throughput (token/s): 11.49   ← pinned for 50+ minutes

[4] Compaction negative test (21:39-21:40) — fresh 42K prefix, still degraded
21:39:49  Prefill batch, #new-token: 8192, #cached-token: 0, token usage: 0.07
21:40:05  Decode batch, #token: 42028, gen throughput (token/s): 1.80
21:40:08  Decode batch, gen throughput (token/s): 12.53

[5] Prior day (2026-09-22) — same config, longer accumulation
21:12:41  WARNING  Input sequence length 249912 exceeds 245760, request 16 is dropped
~20:52    decode 14.7 tok/s after ~970 requests/12h → 21:03 engine restart → 80+ tok/s immediately

Anything else

user_pasted_clipboard_long_content_as_file_[082822] cmdINFO.txt
user_pasted_clipboard_long_content_as_file_[210242] cmdINFO(2).txt
user_pasted_clipboard_long_content_as_file_[210242] cmdINFO(3).txt
user_pasted_clipboard_long_content_as_file_[210242] cmdINFO.txt
user_pasted_clipboard_long_content_as_file_[210242] cmdINFO(1).txt

[Joeppie]

Maybe I am missing something, but the token count seems to be making your tokens/s go down, which is expected; the longer the context, the slower new tokens are generated. All your log files seem to indicate precisely that expected behavior?

For example here; Decode batch, #running-req: 1, #token: 230129, token usage: 0.94, #mamba-slot: 4/32, mamba usage: 0.12, gen throughput (token/s): 38.16, #queue-req: 0

High token #count, slow generation of new token. Earlier:

#token: 19148, token usage: 0.08, #mamba-slot: 8/32, mamba usage: 0.25, gen throughput (token/s): 115.78, #queue-req: 0

Lower token #count, faster generation of a new token.

That is expected behavior, as the model has to iterate over all tokens before being able to generate the next one.
If that is undesirable, perform compaction, or reduce token count, although that of course might impact the quality of the generation.

With models like these, we have to choose whether to generate and keep many tokens, or go fast. That is the way it currently is; mamba slots help reduce the impact of prefilling though, which happens when you compact (it summarizes and then continues from the smaller summary)