Repository navigation
Hosted sync hub's disposal drain starves on an exhausted thread pool (M1-by-pool-starvation, post-#3593) #4847
Description
What is failing
A hosted sync/* hub (sync/RKMBDmY2kEqHNQLLMOdmwA) posted a 7316 "the pump is not turning" verdict during disposal: its drain was accepted by the turn scheduler but never run for the full 8-second stall budget, so the queued ShutdownRequest never reached a handler and the hub's teardown stalled. This is the first production occurrence read with the post-#3593 instrumentation.
Probable cause — thread-pool starvation on the pod (high confidence)
The verdict's own measurements name the mechanism, per Reading a Disposal Stall Verdict:
drainsInFlight=0+drainsAwaitingScheduler=1+TurnsDequeueddelta 0 ⇒ M1: the scheduler accepted the drain and has not run it.- The line itself confirms the Hub disposal wedges before Quiescing: the action block never dequeues the buffered ShutdownRequest(Quiescing) #3593 fix is deployed ("ScheduleDrainOne asks for PreferFairness since Hub disposal wedges before Quiescing: the action block never dequeues the buffered ShutdownRequest(Quiescing) #3593"), so the drain was queued globally — visible to every worker and to the pool's starvation detection. A hosted hub runs on
TaskScheduler.Default; a dead activation scheduler cannot reach it, and M3 is excluded by construction.
Therefore, per the discriminator table, this is M1-by-pool-starvation: the CLR thread pool on that pod genuinely had no thread to give for at least 8 seconds. The residual hazard the doc names explicitly — DrainLoop's trampoline owning a worker for an unbounded run of synchronous turns, letting a continuously-posted hub hold a pool thread indefinitely — is the leading candidate for what saturated the pool; confirming it needs pool-level telemetry (ThreadPool.ThreadCount, PendingWorkItemCount) from that pod, which this log line does not carry.
Impact
One occurrence, one pod, one hub, resolved within the bounded stall budget. Nuisance today, but the shape is a cascade-risk: if a mass teardown (as in #3593's 47 siblings) hits an exhausted pool, every child's disposal stalls at once.
Where to look
MessageService.ScheduleDrainOne/DrainLoop(trampoline bound) — the pre-existing known residual; the remedy if pool exhaustion is measured as a defect in its own right is a bounded trampoline (TPL Dataflow'sMaxMessagesPerTask), a different change from Hub disposal wedges before Quiescing: the action block never dequeues the buffered ShutdownRequest(Quiescing) #3593.- Start by pulling pod-level thread-pool metrics for the window to confirm starvation and find which work owned the workers.
- Reference: Hub disposal wedges before Quiescing: the action block never dequeues the buffered ShutdownRequest(Quiescing) #3593 (mechanism, fix, and the "what this does NOT fix" note that predicts this reading).
Evidence
| Fingerprint | 21b0b14908f16f59 |
| Category | MeshWeaver.Messaging.MessageHub |
| Severity | Error |
| Namespace | memex-cloud |
| Pods | memex-portal-deployment-7978987466-sq6sq |
| Occurrences | 1 |
| First seen | 2026-09-19 07:58:08Z |
| Last seen | 2026-09-19 07:58:08Z |
Recent log lines
2026-09-19 07:58:08Z memex-portal-deployment-7978987466-sq6sq fail: MeshWeaver.Messaging.MessageHub[7316]
DISPOSAL DEADLOCK DETECTED: Hub sync/RKMBDmY2kEqHNQLLMOdmwA made no teardown progress for 00:00:08 (last progress: sync/RKMBDmY2kEqHNQLLMOdmwA → Started). RunLevel=Started, queue depth 1. THE PUMP IS NOT TURNING: the drain flag is latched, drainsInFlight=0, drainsAwaitingScheduler=1, and NO turn was dequeued in that window (0 dequeued in total since Dispose()). The queued work — the ShutdownRequest included — has therefore never been handed to a handler, so this stall is in THIS hub's turn scheduling and NOT in a hosted hub or a join. MECHANISM: the turn scheduler ACCEPTED 1 drain(s) and has not run them (drainsInFlight=0). The stall is in THAT SCHEDULER, not in this hub. On TaskScheduler.Default (every hosted hub — a hosted hub is built from a fresh configuration and inherits no scheduler) the drain is queued GLOBALLY (ScheduleDrainOne asks for PreferFairness since #3593), so it is visible to every worker AND to the pool's starvation detection — reading this here means the pool genuinely has no thread to give, NOT that the work is parked on the posting thread's local queue; on a ROOT GRAIN hub it is the grain's ActivationTaskScheduler (MessageHubGrain.WithTaskScheduler), where a wedged or deactivated activation parks every turn this hub will ever take. Disposal is NOT forced.
Hub sync/RKMBDmY2kEqHNQLLMOdmwA RunLevel=Started Disposal=Pending Queue(buffer=1,deferred=0,drainsInFlight=0,openGates=0,draining=True)
Opened automatically from Admin/_LogIncident/21b0b14908f16f59. Recurrences are folded into this issue rather than opening new ones.
Activity
systemorph commentedon Sep 19, 2026
Still occurring: 1 more since the last update (2 total).
memex-portal-deployment-7978987466-sq6sq,memex-portal-deployment-85f5bcf79d-n6lj2Recent log lines
systemorph commentedon Sep 19, 2026
Still occurring: 36 more since the last update (38 total).
memex-portal-deployment-7978987466-sq6sq,memex-portal-deployment-85f5bcf79d-n6lj2,memex-portal-deployment-69956b6dbc-v5r29Recent log lines
rbuergi commentedon Sep 21, 2026
Cluster triage: this symptom has five distinct roots
Reviewed together with #1540 #1547 #1548 #3243 #3593 #2833 #2480 #5064 #4859 #5136 #4847 #4883 #4888 #4961 — every one of them reports
ObjectDisposedExceptionwithAutofac.Core.Lifetime.LifetimeScope.ThrowDisposedException()on top, or a teardown that did not finish. They are not one bug. The grouping, the discriminators and the evidence are committed asDoc/Architecture/DisposedScopeAndDyingHubs(added in #5159).Root: the residual #3593 predicted. Still open, and the next step is a measurement I cannot take from here.
Grouped in
Doc/Architecture/DisposedScopeAndDyingHubswith #3593, #4883 and #4888.The verdict's own discriminators settle the mechanism, and I agree with the reading:
drainsInFlight=0+drainsAwaitingScheduler=1+TurnsDequeueddelta 0, on a hosted hub (soTaskScheduler.Default, so M3is excluded by construction), with the #3593 global-queueing fix deployed ⇒ M1-by-pool-starvation.
The pool genuinely had no thread for 8 s.
What is not established is what owned the workers. The named candidate —
DrainLoop's trampolineholding a worker for an unbounded run of synchronous turns, so a continuously-posted hub can keep a pool
thread indefinitely — is plausible and is a different change from #3593 (a bounded trampoline, e.g.
TPL Dataflow's
MaxMessagesPerTask). Confirming it needsThreadPool.ThreadCount/PendingWorkItemCountfrom that pod in that window, which this log line does not carry and which Icannot obtain read-only after the fact.
🚨 The remedy must not be a widened stall budget: the budget is the detector, and raising it only makes
the report arrive later. Leaving open on the pool-telemetry step.
rbuergi commentedon Sep 22, 2026
The residual this issue names has been BOUNDED — in #5182, merged today and not yet rolled
The issue body names the leading candidate for what saturated the pool:
That landed on
mainas #5182 (358ec858aa, "fix: yield synchronous hub drains to queuedpeers", merged 2026-09-22 06:13Z), and the code says so in its own words:
Not closing on that. The merge puts the bound on
main; it does not establish that thetrampoline is what owned the workers on
memex-portal-deployment-7978987466-sq6sqat 2026-09-1907:58:08Z, and the pod-level thread-pool reading this issue asks for was never taken. What the merge
does is make the NEXT occurrence decisive: if this verdict recurs on an image carrying
358ec858aa, the trampoline is excluded and the saturating work is something else — and that is abetter question than the one we have now.
Grouping (full version, with the pairwise discriminators, on #2480): this and #4886 are
the same mechanism class — pool exhaustion — seen through two instruments, the hub's own disposal
verdict and Orleans' silo health monitor. They are not duplicates, and no occurrence yet binds
them: this one is 07:58:08Z on
…7978987466-sq6sq, #4886's stalls are 06:29:21Z on…58dbb6d98d-8mswwand 08:57:04Z on…69956b6dbc-gj8m2— different pods, different hours. Whatwould bind them is a stall window overlapping this 8 s no-turn window on the SAME pod.
Against #4888, the discriminator is inside the verdict and needs no new reading: this one is
RunLevel=Startedwith 0 turns dequeued (the pump never turned at all), #4888 isRunLevel=ShutDownwith the drain running and consciously discarding attributed work.rbuergi commentedon Sep 23, 2026
A second candidate for what starved the pool, now also deployed on memex-cloud. Still not verified
The verdict here is M1-by-pool-starvation: the ThreadPool had no thread for 8 s. The previous comment named
DrainLoop's unbounded trampoline as the candidate owner of the workers, and bounded it in #5182 (358ec858aa). There is a second, measured one: runtime NodeType compiles ran on the shared ThreadPool.OnThreadPoolbound theTask.Runoverload, and Roslyn'sConcurrentBuildfanned every emit back out ontoTaskScheduler.Default. At 6 concurrent emits (the pod'sProcessorCount), the probe measured a ThreadPool start latency of p99 417 ms with 115 items queued. Fixed in #5327 + #5375 (DocCompileOffTheThreadPool). The samples here come from three ReplicaSets within 45 minutes (7978987466at 07:58Z,85f5bcf79d/69956b6dbcat 08:38–08:43Z), which is a roll, and a roll is exactly when serving silos compile.Deployed: memex-cloud has run
39f49494since 22:49Z (ReplicaSets7bb8dfc554, thenc54d5847c, perOps/Status/memex-cloud). That build contains both #5182 and #5327/#5375;merge-base --is-ancestorexits 0 for each. memex (3da3423c) contains #5182 and not the compile fix.Recurrence: the last recurrence folded into this issue is 2026-09-19 08:43:58Z (38 total). No 7316 disposal-stall issue has been opened since (REST search,
"DISPOSAL DEADLOCK" created:>=2026-09-22T12:00Z→ 0). The same memex-cloud build still shows routing thread-shortage crossings after the roll (#5118, 4 samples), so the pool is not free of starvation there. That means an absent 7316 is weak evidence either way.What closes it: a
Logsread forMessageHub[7316]"THE PUMP IS NOT TURNING" over memex-cloud since 22:49Z, and over memex after it rolls to ≥39f49494. None at all → close as fixed by #5182 + #5327/#5375. If some remain, pool telemetry over that window decides which of the two it is. The control instance was answering 503 while I did this, so that read has not been taken.rbuergi commentedon Sep 23, 2026
It recurred on an image that carries both candidate fixes, and so neither one is sufficient (#5569 folded here)
The 2026-09-22 comment set the test: "if this verdict recurs on an image carrying
358ec858aa, the trampoline is excluded". It has recurred.sync/*hubs, 2026-09-23 14:54:01.7–.741Z, podmemex-portal-deployment-777677694-p6hbn, same counters (drainsInFlight=0,drainsAwaitingScheduler=1, 0 dequeued)777677694=3.0.0-ci.9258, commit9a61fed9(Ops/Status/memex-cloud, as quoted on #5555)358ec858aa(bounded trampoline), #5327 + #5375 (compiles on a dedicatedCompileCpulane). All three are ancestors of9a61fed964So neither the drain trampoline nor the compiles are the whole story.
Leading candidate: heap exhaustion. The same ReplicaSet, 32 minutes earlier, on pod
…777677694-cc6zz:[LIVENESS]read heap 2.01 → 11.70 GiB in 107 s,gcPausereached 129 s,poolPendingreached 715,OutOfMemoryException(MessageService DrainLoop throws OutOfMemoryException during hub delivery (recurrence of #4824) #5555, with the readings quoted there).That matches the pattern already established for #4886 (occurrence 2 was a full blocking GC inside #4824's OOM window) and for the 09-19 occurrences of this issue, which fall on the 09-19 OOM day. A whole-runtime stall produces exactly "the drain was accepted and no worker ran it for 8 s". Running disposal drains on dedicated threads would not change that under a blocking GC, and it would only change which line reports it. So no drain-scheduling change is proposed. The root is being worked on #5555.
Not established:
p6hbn's own heap and GC readings at 14:54Z (aLogsread on the control instance, an owner step). That reading decides whether this closes as a symptom of #5555 or needs its own cause.rbuergi commentedon Sep 24, 2026
Heap reading behind the "pool had no thread" verdict. 2026-09-24, memex-cloud
9a61fed964.Every 100 s
[LIVENESS]sample on 4 replicas over 760 min (Ops/logs-memexcloud-20260924-liveness-*, 1,163 lines) shows multi-GiB heap steps that arrive on several replicas within seconds of each other:Each step carries +3.5 to +13.5 s of GC pause inside one 100 s sample. The biggest step also carries
poolPending=688(and 1,690 at 19:41Z on the same pod).That is the whole-runtime stall this issue's M1 verdict describes, and it happens on an image with #5182 and #5327/#5375 applied. It is consistent with the 2026-09-23 reading here: a drain-scheduling change cannot help while the runtime is paused in GC.
The driver is being worked on #5555. My current reading there is live data from mass re-activation on the surviving replicas when one leaves or joins; that is not established.
Not established:
Logsread forMessageHub[7316]on a pod that took a step, next to its[LIVENESS]lines.Stays open.
rbuergi commentedon Sep 24, 2026
No change to the reading here. The shared driver still has no name. #5665 adds the instrument that will name it.
This issue's recurrences on
9a61fed964(#5569) fall on the same ReplicaSet as #5555's heap steps, and those steps carry +3.5 to +13.5 s of GC pause per 100 s sample. A drain-scheduling change still cannot help while the runtime is paused, so none is proposed.On #5555 (comment 5816105941) I recorded that the "replica joins" the steps line up with look like KEDA memory scale-ups caused by the step, not the other way round:
…-5x2kgis in the same ReplicaSet as the pods that stepped;#5665 makes the heartbeat log a
[HEAPSTEP]line naming the types allocated in any tick where the heap grew by ≥ 512 MiB.Next reading after that rolls: a 7316 verdict on a pod, next to that pod's
[HEAPSTEP]and[LIVENESS]lines. Stays open.rbuergi commentedon Oct 10, 2026
Post-roll reading, 2026-10-10 ~05:20Z. All three portals serve core
479c9b72d5(/api/version), which carries #6261 (merged 2026-10-07 17:06Z). Plugins#3109 merged 2026-10-07 17:57Z, before any image in the windows below was built.Governed
Logsreads on the control instance (Ops/Actions/logs-*-20261010-*):warm-up complete)Thread Pool execution stalledThread Pool execution stalled for NN(≥ 10 s)DISPOSAL DEADLOCK DETECTED(MessageHub[7316]/[7317])MessageHub[73xx]or[DISPOSE-*[LIVENESS]tick with heap ≥ 6 GiB on the CURRENT ReplicaSetd9cd97, since 22:34Z; its[HEAPSTEP]lines peak at 5.06 GiB)477bf6, since ~23:00Z;[HEAPSTEP]peak 3.83 GiB)For comparison, the stall band this issue tracked ran at heap 10.2–11.6 GiB with GC at 86–98 % of wall time. The heaviest tick on a #6261 image in either window is memex
cfb58787b-b6kljon 10-09 14:35Z: heap 8.09 GiB, butgcPause +0.19 sper 10 s tick (~2 %) andpoolPending=0. The heap is high there, but the GC is not thrashing.Positive controls. (1) The pool-stall instrument fires in the window: 18 sub-3 s lines, so a ≥ 10 s stall would have printed. (2)
[LIVENESS]/[HEAPSTEP]are ingested from the current pods. (3) The same heap regex returns 255 ≥ 6 GiB ticks from the pre-#62616548d4pods (booted ~10-07 13:15Z, before the merge) up to 10-09 17:58Z. That control separates the images.Not established. Loki keeps under ~4.5 days. A probe for any line from the 10-05 pod
6cfcf78898-kss8qreturned 0, so the 10-05 episode itself cannot be re-read as an in-window control for theDISPOSAL DEADLOCKregex. That regex is the literal text atMessageHub.cs:3084/3116/3145. The windows are 12 h and 24 h of ordinary traffic plus frequent rolls. They are not a reproduction of the 10-05 surge.Closing. The awaited reading was "a 7316 verdict on a pod, next to that pod's
[HEAPSTEP]and[LIVENESS]lines". On the #6261 images[HEAPSTEP]still fires: 191 steps on memex-cloud in 12 h, each 0.5–2.3 GiB. But heap peaks at 5.06 GiB on the current ReplicaSet, and no 7316 verdict appears at all. The multi-GiB steps no longer end in the whole-runtime GC pause that this issue's M1 verdict depended on. Reopen on a 7316 verdict.sev:M sweep, Claude Opus 5.5 (agent session).