Skip to content

docs(mlx): the graph-cache thrashing check kills the runner and masks itself as cudaGraphAddDependencies - #211

Open
glennneuber wants to merge 3 commits into
mainfrom
docs/mlx-thrash-check
Open

docs(mlx): the graph-cache thrashing check kills the runner and masks itself as cudaGraphAddDependencies#211
glennneuber wants to merge 3 commits into
mainfrom
docs/mlx-thrash-check

Conversation

@glennneuber

Copy link
Copy Markdown

99 aborts over ~7h of MLX serving in the 2026-08-22 vision campaign, all on MLX
models and only in think=on cells (17 of 27 tests on gemma4:12b-nvfp4 landed as
error blocks), every one logged as
mlx: cudaGraphAddDependencies(...) failed: invalid argument
and not one line saying why. This note records the cause, a cold-start
reproduction, the proof it predates the v0.32.15 sync, and the mitigation.

Cause, in three parts. (1) MLX's LRUCache keeps a LIFETIME miss counter and
throws std::runtime_error once it exceeds 2 * MLX_CUDA_GRAPH_CACHE_SIZE -- a
performance advisory implemented as a fuse. (2) CommandEncoder::commit()
records graph dependencies BEFORE the cache lookup that throws and resets its
state only on the success path, so the throw leaves from_nodes_/to_nodes_/
graph_ populated and the next commit fails in cudaGraphAddDependencies --
upstream ml-explore/mlx ollama#4326, fix ollama#4356 open and unmerged. (3) Ollama's
request pipeline has defer session.close(), which runs AsyncEval -- a second
commit on the poisoned encoder -- and mlxthread.run() keeps only what
recover() returns, i.e. the LATER panic. The thrash message never reaches the
log. That is why grepping for it finds nothing and why every campaign stack
shows the double panic through cacheSession.close.

Reproduction (vision-suite/mlx_thrash_probe.py, committed per ADR 0012 rule 8):
text-only requests with distinct prefill lengths, gemma4:12b-nvfp4, cold
container per phase.
A new image, cache 8 120/120 fail from #1; thrash=372 cudaGraph=4
B new image, defaults, n=1000 clean to 707, ollama#708 = 500-cudaGraph, thrash=0
C OLD image, cache 8 120/120 fail from #1; thrash=372 cudaGraph=3
D new, cache 8, check OFF 120/120 ok, 0.2-0.3 s/request, cudaGraph=0
Phase B is the campaign signature on demand; Phase C closes the regression
question (the check is from ollama#2600, merged 2025-09-19, and is in both pins);
Phase D is the mitigation and the confirmation that the masked first panic was
the thrash throw.

Proposes, without implementing: set MLX_ENABLE_CACHE_THRASHING_CHECK=0 for the
MLX runner subprocess by default in x/mlxrunner/client.go (overridable), and
have mlxthread.run() surface the original panic when a deferred cleanup panics
during unwinding. The first removes the failure; the second makes the log tell
the truth. Even with ollama#4356 upstream, ollama would still lose the request to the
throw itself, so the check is the wrong trade for a server that cannot
catch-and-continue.

Co-Authored-By: Claude Opus 5 noreply@anthropic.com


Companion to #210 (the OOM/admission failure from the same campaign — a different failure class, not to be conflated).

glennneuber and others added 2 commits August 23, 2026 01:38
… itself as cudaGraphAddDependencies

99 aborts over ~7h of MLX serving in the 2026-08-22 vision campaign, all on MLX
models and only in think=on cells (17 of 27 tests on gemma4:12b-nvfp4 landed as
error blocks), every one logged as
  mlx: cudaGraphAddDependencies(...) failed: invalid argument
and not one line saying why. This note records the cause, a cold-start
reproduction, the proof it predates the v0.32.15 sync, and the mitigation.

Cause, in three parts. (1) MLX's LRUCache keeps a LIFETIME miss counter and
throws std::runtime_error once it exceeds 2 * MLX_CUDA_GRAPH_CACHE_SIZE -- a
performance advisory implemented as a fuse. (2) CommandEncoder::commit()
records graph dependencies BEFORE the cache lookup that throws and resets its
state only on the success path, so the throw leaves from_nodes_/to_nodes_/
graph_ populated and the next commit fails in cudaGraphAddDependencies --
upstream ml-explore/mlx ollama#4326, fix ollama#4356 open and unmerged. (3) Ollama's
request pipeline has `defer session.close()`, which runs AsyncEval -- a second
commit on the poisoned encoder -- and mlxthread.run() keeps only what
recover() returns, i.e. the LATER panic. The thrash message never reaches the
log. That is why grepping for it finds nothing and why every campaign stack
shows the double panic through cacheSession.close.

Reproduction (vision-suite/mlx_thrash_probe.py, committed per ADR 0012 rule 8):
text-only requests with distinct prefill lengths, gemma4:12b-nvfp4, cold
container per phase.
  A  new image, cache 8            120/120 fail from #1; thrash=372 cudaGraph=4
  B  new image, defaults, n=1000   clean to 707, ollama#708 = 500-cudaGraph, thrash=0
  C  OLD image, cache 8            120/120 fail from #1; thrash=372 cudaGraph=3
  D  new, cache 8, check OFF       120/120 ok, 0.2-0.3 s/request, cudaGraph=0
Phase B is the campaign signature on demand; Phase C closes the regression
question (the check is from ollama#2600, merged 2025-09-19, and is in both pins);
Phase D is the mitigation and the confirmation that the masked first panic was
the thrash throw.

Proposes, without implementing: set MLX_ENABLE_CACHE_THRASHING_CHECK=0 for the
MLX runner subprocess by default in x/mlxrunner/client.go (overridable), and
have mlxthread.run() surface the original panic when a deferred cleanup panics
during unwinding. The first removes the failure; the second makes the log tell
the truth. Even with ollama#4356 upstream, ollama would still lose the request to the
throw itself, so the check is the wrong trade for a server that cannot
catch-and-continue.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The reproduction section still pointed at the scratch filename and carried
Phase C's mid-run row; C finished 120/120 with cudaGraph=3, the same masked
second failure as A, which is the stronger statement about the pre-merge build.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@glennneuber

Copy link
Copy Markdown
Author

Reviewing as consolidator. This closes a finding I published as unexplained, and the diagnosis is better than the one I guessed at.

I hit this abort on 2026-08-17 — gemma4:31b-nvfp4, think-on, twelfth consecutive cell — and recorded it in the mlx-cuda profile as a probable CUDA-graph-capture defect, naming the prefix cache and batch composition as candidates. That was a guess from a stack trace, and it was wrong about the cause while being right about the symptom.

The three-part mechanism accounts for every detail I could not:

  1. an LRU miss counter that is a lifetime total, throwing once past 2 × MLX_CUDA_GRAPH_CACHE_SIZE — a performance advisory implemented as a fuse
  2. CommandEncoder::commit() recording dependencies before the lookup that throws, and clearing state only on success, so the next commit fails in cudaGraphAddDependencies
  3. defer session.close() running AsyncEval — a second commit on the poisoned encoder — with mlxthread.run() keeping only the later panic

That third part is why my stack showed the double panic through cacheSession.close and why I read the teardown as implicated. It is the reporting path, not the fault. And it explains the thing that bothered me most at the time: grepping for a cause found nothing, because the message that would have named it never reaches the log.

The reproduction is the part that makes this a finding rather than a theory

Four phases, and each one answers a distinct question rather than adding weight to the same one:

  • B produces the campaign signature on demand at defaults (clean to 707, then a 500) — that is what turns "a thing that happens in long runs" into something addressable
  • C on the old image closes the regression question outright, so nobody spends a day bisecting the v0.32.15 sync for it
  • D with the check off is both the mitigation and the proof that the masked first panic was the thrash throw

C is the one I would have skipped and regretted. We merged an upstream sync in that window, and "did the sync cause it" is exactly the question that would otherwise have been asked at the worst moment.

What I will do with it

The mlx-cuda profile records this abort with my cache-and-capture speculation attached. That reason should now point here instead — same as #210 superseded my caching-allocator guess about the qwen35moe OOM. Two of my three MLX/CUDA defect notes have now been replaced by measured causes, and in both cases the real mechanism was one layer below where the stack trace pointed.

On the proposal

Setting MLX_ENABLE_CACHE_THRASHING_CHECK=0 for the runner subprocess by default, overridable, is right — with the caveat that it silences an advisory rather than fixing thrashing. Worth stating in the code comment that the check was telling us something true (graph cache misses are high on these workloads) and that disabling it trades a fatal abort for a performance question nobody is currently measuring. The upstream fix being open and unmerged (ollama#4356) is the reason to carry it locally rather than wait, and citing the issue number means the next pin bump has a reason to re-check.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
glennneuber added a commit that referenced this pull request Aug 24, 2026
…nc (sync15nt)

The think-on half of the sync-0.32.15 parity campaign, re-run with the
graph-cache thrashing check off (#211/#212), plus qwen3.6 nvfp4 in both
modes. Standard tables, the ladder glossary (converged / capped / NOT
CONVERGED), no-regression analysis against the pre-sync 31b repeats, the
loop ranking with the 131072-rung timeout evidence, and the 26b
clean-but-wrong open item.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant