Skip to content

Portal silo thread starvation backs up routing dispatch legs (60+ waiting for a pool slot before their subscribe) #5366

Closed as not planned

Description

@systemorph

What is failing

The routing grain on the memex-portal pod (memex-cloud) hit its 64-in-flight saturation threshold repeatedly because route legs are parked waiting for a ThreadPool thread before their subscribe prologue starts — not because of any routing-structural blockage.

Probable cause

High confidence this is the thread-shortage shape, not a routing defect. Every sample reads waiting for a pool slot 60–62 while routing pool subscribing is 0 and deepest per-channel queue is 0 — legs the pool has accepted but that never reached the gate — which per Reading a Routing Saturation Report is the signature of work that has not reached the gate: a thread shortage. The oldest legs are 3 ms–9.7 s (never minutes), so no slot leaked; the episodes across two activations churn normally. One outlier sample shows 601 waiting, consistent with a burst the process was slow to absorb. Root cause upstream of routing: check the pod for an OutOfMemoryException, a LocalSiloHealthMonitor "Thread Pool execution stalled", or a PlacementWorker timeout in the 15:57–16:00Z window on 2026-09-22 — the routing grain is the instrument that noticed, not the fault.

Impact

29 occurrences over ~2.5 minutes on a single pod, all Critical-rated crossings. The gauge throttles nothing, so this is a capacity/stall symptom; whether any user-visible delivery was delayed is not evidenced in the samples. Judge after correlating pod health in the same window.

Where to look

MeshWeaver.Hosting.Orleans.RoutingGrain (log site), the routing IoPool/IIoPool.CurrentlyWaiting gauge (Controlled I/O Pooling), and the ThreadPool health of memex-portal-deployment-86dbb4d55c-gcrcd. Not a duplicate of #5009 (channel head-of-line) or #5018 (gauge blindness — already fixed, this line carries both pool gauges) — this is the thread-shortage verdict those fixes made decidable.


Evidence

Fingerprint 4852d5a7b5778779
Category MeshWeaver.Hosting.Orleans.RoutingGrain
Severity Critical
Namespace memex-cloud
Pods memex-portal-deployment-86dbb4d55c-gcrcd
Occurrences 29
First seen 2026-09-22 15:57:00Z
Last seen 2026-09-22 15:59:41Z
Routing not determined — no configured route matches the category MeshWeaver.Hosting.Orleans.RoutingGrain. This repository is the configured fallback, not a finding about who owns the fault; the category names the LOGGER, which may not be the subject.
Recent log lines
2026-09-22 15:59:28Z memex-portal-deployment-86dbb4d55c-gcrcd crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [c911059d#6 started 2026-09-22T15:59:28.4181589Z]: 64 route dispatches in flight (reporting threshold 64); ordered channels queued 0 over 0 stream destination(s), deepest per-channel queue 0, routing pool subscribing 0, waiting for a pool slot 62; oldest leg in flight 24 ms — dispatch → MeshWeaverInstance/36d61c0097aa (delivery gqHP_lBv3ka6d3gaf0MSww). Latest dispatch target nerijus.vasiliauskas/_Install/EntityViews — the address that happened to cross the threshold, NOT a diagnosis. A slot is held from dispatch until the leg terminates, INCLUDING the unbounded wait for a ThreadPool thread before the leg's own timeouts start, so a CPU-starved silo raises this with nothing stuck. A CHANNEL is (destination, stream), so a deepest queue of 1 or more means legs of the SAME stream are blocked behind one another (head-of-line within one channel); 0 means nothing is waiting on anything, so read it as load. Many channels over FEW destinations is a multiplexer hub draining in parallel, which is load too — before issue #5009 those legs shared one channel and read as head-of-line. 🚨 THE TWO POOL GAUGES ANSWER DIFFERENT QUESTIONS AND ONLY ONE SEES THE WAIT NAMED ABOVE — issue #5018. 'subscribing' counts legs inside their SUBSCRIBE PROLOGUE only, so a leg still waiting for a ThreadPool thread and a leg already past its subscribe BOTH read 0 there; 'waiting for a pool slot' is the gauge that sees the pre-subscribe wait. High while subscribing is below the pool's cap is a THREAD shortage; both near zero means the legs are past their subscribe and the wait is downstream I/O. 🚨 READ THE OLDEST LEG FIRST: it is the only load-vs-leak discriminator available from a SINGLE line — every leg young is load the silo is absorbing, one leg minutes old is a slot that never came back and the label names it — whereas the episode stamp below needs a SECOND line to say anything. 🚨 Deepest is sampled AT THE CROSS…[truncated]
2026-09-22 15:59:28Z memex-portal-deployment-86dbb4d55c-gcrcd crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [c911059d#7 started 2026-09-22T15:59:28.4359709Z]: 64 route dispatches in flight (reporting threshold 64); ordered channels queued 0 over 0 stream destination(s), deepest per-channel queue 0, routing pool subscribing 0, waiting for a pool slot 62; oldest leg in flight 42 ms — dispatch → MeshWeaverInstance/36d61c0097aa (delivery gqHP_lBv3ka6d3gaf0MSww). Latest dispatch target Indexing/_Policy — the address that happened to cross the threshold, NOT a diagnosis. A slot is held from dispatch until the leg terminates, INCLUDING the unbounded wait for a ThreadPool thread before the leg's own timeouts start, so a CPU-starved silo raises this with nothing stuck. A CHANNEL is (destination, stream), so a deepest queue of 1 or more means legs of the SAME stream are blocked behind one another (head-of-line within one channel); 0 means nothing is waiting on anything, so read it as load. Many channels over FEW destinations is a multiplexer hub draining in parallel, which is load too — before issue #5009 those legs shared one channel and read as head-of-line. 🚨 THE TWO POOL GAUGES ANSWER DIFFERENT QUESTIONS AND ONLY ONE SEES THE WAIT NAMED ABOVE — issue #5018. 'subscribing' counts legs inside their SUBSCRIBE PROLOGUE only, so a leg still waiting for a ThreadPool thread and a leg already past its subscribe BOTH read 0 there; 'waiting for a pool slot' is the gauge that sees the pre-subscribe wait. High while subscribing is below the pool's cap is a THREAD shortage; both near zero means the legs are past their subscribe and the wait is downstream I/O. 🚨 READ THE OLDEST LEG FIRST: it is the only load-vs-leak discriminator available from a SINGLE line — every leg young is load the silo is absorbing, one leg minutes old is a slot that never came back and the label names it — whereas the episode stamp below needs a SECOND line to say anything. 🚨 Deepest is sampled AT THE CROSSING, so like the in-fligh…[truncated]
2026-09-22 15:59:31Z memex-portal-deployment-86dbb4d55c-gcrcd crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [c911059d#8 started 2026-09-22T15:59:31.6083662Z]: 64 route dispatches in flight (reporting threshold 64); ordered channels queued 0 over 0 stream destination(s), deepest per-channel queue 0, routing pool subscribing 0, waiting for a pool slot 61; oldest leg in flight 3 ms — dispatch → Training/_Entitlements/thomas.pepin (delivery AEwXYakJk02bTjcC3pkxng). Latest dispatch target lucas.mebold/_Install/OgCard — the address that happened to cross the threshold, NOT a diagnosis. A slot is held from dispatch until the leg terminates, INCLUDING the unbounded wait for a ThreadPool thread before the leg's own timeouts start, so a CPU-starved silo raises this with nothing stuck. A CHANNEL is (destination, stream), so a deepest queue of 1 or more means legs of the SAME stream are blocked behind one another (head-of-line within one channel); 0 means nothing is waiting on anything, so read it as load. Many channels over FEW destinations is a multiplexer hub draining in parallel, which is load too — before issue #5009 those legs shared one channel and read as head-of-line. 🚨 THE TWO POOL GAUGES ANSWER DIFFERENT QUESTIONS AND ONLY ONE SEES THE WAIT NAMED ABOVE — issue #5018. 'subscribing' counts legs inside their SUBSCRIBE PROLOGUE only, so a leg still waiting for a ThreadPool thread and a leg already past its subscribe BOTH read 0 there; 'waiting for a pool slot' is the gauge that sees the pre-subscribe wait. High while subscribing is below the pool's cap is a THREAD shortage; both near zero means the legs are past their subscribe and the wait is downstream I/O. 🚨 READ THE OLDEST LEG FIRST: it is the only load-vs-leak discriminator available from a SINGLE line — every leg young is load the silo is absorbing, one leg minutes old is a slot that never came back and the label names it — whereas the episode stamp below needs a SECOND line to say anything. 🚨 Deepest is sampled AT THE CROSSING, so li…[truncated]
2026-09-22 15:59:38Z memex-portal-deployment-86dbb4d55c-gcrcd crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [4a24a311#1 started 2026-09-22T15:59:38.1064443Z]: 64 route dispatches in flight (reporting threshold 64); ordered channels queued 0 over 0 stream destination(s), deepest per-channel queue 0, routing pool subscribing 0, waiting for a pool slot 601; oldest leg in flight 6501 ms — dispatch → lucas.mebold/_Install/Publish (delivery QLGXV_H98UWIOiYwgVbioQ). Latest dispatch target roland.buergi/_Install/GraphViews — the address that happened to cross the threshold, NOT a diagnosis. A slot is held from dispatch until the leg terminates, INCLUDING the unbounded wait for a ThreadPool thread before the leg's own timeouts start, so a CPU-starved silo raises this with nothing stuck. A CHANNEL is (destination, stream), so a deepest queue of 1 or more means legs of the SAME stream are blocked behind one another (head-of-line within one channel); 0 means nothing is waiting on anything, so read it as load. Many channels over FEW destinations is a multiplexer hub draining in parallel, which is load too — before issue #5009 those legs shared one channel and read as head-of-line. 🚨 THE TWO POOL GAUGES ANSWER DIFFERENT QUESTIONS AND ONLY ONE SEES THE WAIT NAMED ABOVE — issue #5018. 'subscribing' counts legs inside their SUBSCRIBE PROLOGUE only, so a leg still waiting for a ThreadPool thread and a leg already past its subscribe BOTH read 0 there; 'waiting for a pool slot' is the gauge that sees the pre-subscribe wait. High while subscribing is below the pool's cap is a THREAD shortage; both near zero means the legs are past their subscribe and the wait is downstream I/O. 🚨 READ THE OLDEST LEG FIRST: it is the only load-vs-leak discriminator available from a SINGLE line — every leg young is load the silo is absorbing, one leg minutes old is a slot that never came back and the label names it — whereas the episode stamp below needs a SECOND line to say anything. 🚨 Deepest is sampled AT THE CROSSING, so…[truncated]
2026-09-22 15:59:41Z memex-portal-deployment-86dbb4d55c-gcrcd crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [4a24a311#2 started 2026-09-22T15:59:41.3383667Z]: 64 route dispatches in flight (reporting threshold 64); ordered channels queued 0 over 0 stream destination(s), deepest per-channel queue 0, routing pool subscribing 0, waiting for a pool slot 63; oldest leg in flight 9732 ms — dispatch → ICloud/_Issue/1785 (delivery uzklUCiVkkCpKjxbzblUcQ). Latest dispatch target jacky.enciso/_Install/GoogleMaps — the address that happened to cross the threshold, NOT a diagnosis. A slot is held from dispatch until the leg terminates, INCLUDING the unbounded wait for a ThreadPool thread before the leg's own timeouts start, so a CPU-starved silo raises this with nothing stuck. A CHANNEL is (destination, stream), so a deepest queue of 1 or more means legs of the SAME stream are blocked behind one another (head-of-line within one channel); 0 means nothing is waiting on anything, so read it as load. Many channels over FEW destinations is a multiplexer hub draining in parallel, which is load too — before issue #5009 those legs shared one channel and read as head-of-line. 🚨 THE TWO POOL GAUGES ANSWER DIFFERENT QUESTIONS AND ONLY ONE SEES THE WAIT NAMED ABOVE — issue #5018. 'subscribing' counts legs inside their SUBSCRIBE PROLOGUE only, so a leg still waiting for a ThreadPool thread and a leg already past its subscribe BOTH read 0 there; 'waiting for a pool slot' is the gauge that sees the pre-subscribe wait. High while subscribing is below the pool's cap is a THREAD shortage; both near zero means the legs are past their subscribe and the wait is downstream I/O. 🚨 READ THE OLDEST LEG FIRST: it is the only load-vs-leak discriminator available from a SINGLE line — every leg young is load the silo is absorbing, one leg minutes old is a slot that never came back and the label names it — whereas the episode stamp below needs a SECOND line to say anything. 🚨 Deepest is sampled AT THE CROSSING, so like the in-…[truncated]

Re-addressed by the current identity function: this incident inherited e4a97855ab595beb (Systemorph/MeshWeaver.Plugins#1796). Those nodes are superseded and will not fold, file or comment again.

Opened automatically from Admin/_LogIncident/4852d5a7b5778779. Recurrences are folded into this issue rather than opening new ones.

Activity

  1. added
    bugSomething isn't working
    sev:MMedium - secondary path broken, or easy workaround
    on Sep 22, 2026
  2. rbuergi commented on Sep 22, 2026

    @rbuergi
    Contributor

    Duplicate of #5118, which consolidates this whole family with its cause and its two merged fixes.

    Same log site, same signature: 64 legs in flight, deepest per-channel queue = 0, legs parked waiting for a pool slot / ThreadPool thread before their subscribe prologue. The per-instance variation is the masked activation id, which is the identity defect tracked on #5271.

    Cause: NodeType compiles were holding the silo's shared ThreadPool — OnThreadPool bound the Task.Run overload and Roslyn's ConcurrentBuild fanned each emit back onto TaskScheduler.Default. Measured at 6 concurrent emits (portal ProcessorCount = 6): p99 dispatch 417 ms with 115 queued, versus 0.18 ms and queue 1 once fixed. That is #5327, merged. The reason each episode minted its own Critical ticket is #5322, also merged, which levels a deepest = 0 crossing to Warning.

    🚨 Neither is deployed yet — both portals still serve 3da3423c / 3.0.0-ci.9193, and the newest sealed tag is 3.0.0-ci.9204. So crossings will keep arriving at Critical until a roll happens. If they still arrive with deepest = 0 after the roll, reopen against #5118; if they arrive with deepest >= 1, that is a different and genuine defect and deserves its own issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't workingsev:MMedium - secondary path broken, or easy workaround

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions