Skip to content

Routing grain dispatch pool starves on ThreadPool threads during load bursts on portal pod #5359

Closed as not planned

Description

@systemorph

What is failing

The Orleans routing grain on the portal pod (memex-portal-deployment-89868db67-7tcrq, namespace memex-cloud) repeatedly hits its 64-dispatch back-pressure threshold with ~60 legs waiting for a routing-pool slot. Per the log's own gauge semantics (see #5018): routing pool subscribing 0 while waiting for a pool slot ≈ 60 means the wait is before the subscribe prologue — a ThreadPool thread shortage on the silo, not stuck legs or head-of-line channel blocking (all ordered-channel queues are 0).

Probable cause (medium-high confidence)

ThreadPool starvation on the portal silo: legs queue for a pool slot but none of the pre-subscribe threads is being granted. The episode counter rises on the same activation (episode 1→3 within one minute) and every episode cleared — in-flight fell back below threshold each time — so no slot leaked (oldest-leg age drops from 6.6 s to 4–9 ms across the three lines). The recurring bursts are absorbed load, but the sheer number of sibling incidents of this fingerprint on the same pod across the day suggests a chronic thread-pool sizing / blocked-thread problem in the silo rather than a one-off spike.

Impact

Dispatch latency spikes and message routing slowdowns on the portal pod whenever the pool saturates; no evidence of lost or stuck deliveries in these samples. Secondary path with a self-healing failure mode.

Where to look

MeshWeaver.Hosting.Orleans.RoutingGrain — the routing pool slot allocation and the ThreadPool wait before the subscribe prologue. Start from the pool sizing configuration and any blocking calls on pool threads. Related: #5009 (channel multiplexing change), #5018 (pool gauge semantics). Many sibling LogIncidents in Admin/_LogIncident carry this same signature from the same pod today — likely one underlying condition fanning out into many fingerprints.


Evidence

Fingerprint 1430cc43dc4f23f7
Category MeshWeaver.Hosting.Orleans.RoutingGrain
Severity Critical
Namespace memex-cloud
Pods memex-portal-deployment-89868db67-7tcrq
Occurrences 3
First seen 2026-09-22 14:58:22Z
Last seen 2026-09-22 14:59:07Z
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 14:58:22Z memex-portal-deployment-89868db67-7tcrq crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [12014a8a#1 started 2026-09-22T14:58:22.4383191Z]: 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 60; oldest leg in flight 6653 ms — dispatch → Google/_Entitlements/afh (delivery 6qi2rwoAB0awzfl72-4oeA). Latest dispatch target OpenStreetMap/_Access/emilia.buergi_Access — 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,…[truncated]
2026-09-22 14:59:04Z memex-portal-deployment-89868db67-7tcrq crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [12014a8a#2 started 2026-09-22T14:59:04.5485159Z]: 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 4 ms — dispatch → Codex (delivery 7J8LB7DsMEKdB1h2H0w6Zg). Latest dispatch target HomeAssistant/_Entitlements/v-ramavakita — 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-flight c…[truncated]
2026-09-22 14:59:07Z memex-portal-deployment-89868db67-7tcrq crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [12014a8a#3 started 2026-09-22T14:59:07.4718507Z]: 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 9 ms — dispatch → jeandavid.goetz/_Install/Google (delivery xM1uO8kVEUKC6MpElieWjg). Latest dispatch target FractalStars/_Entitlements/amit.kumar — 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, …[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/1430cc43dc4f23f7. 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