Skip to content

Portal silo thread-pool starvation causes routing back-pressure bursts in RoutingGrain (waiting-for-slot legs, all young) #5401

Closed as not planned

Description

@systemorph-com

What is failing

During a ~6-minute burst on the evening of 2026-09-22, RoutingGrain on the memex-portal silo repeatedly crossed its back-pressure threshold (64 dispatches in flight, ~61–62 legs waiting for a routing pool slot). Stream routing to per-user destinations was queued behind those slots, delaying route delivery.

Probable cause (moderate confidence)

The log's own gauges point at a ThreadPool/thread shortage on the silo, not a stuck leg or a slot leak: routing pool subscribing 0 while waiting for a pool slot 62 means virtually every queued leg was waiting for a ThreadPool thread before its subscribe prologue (the exact signature the log text describes as a thread shortage / CPU-starved silo); oldest leg in flight 2–22 ms on every line means no leg was stuck — pure load. Episode counters advanced within one activation (#12→#14) and then a new activation id appears (7396a756), i.e. episodes drained and the grain was recycled, not wedged. Ordered-channel queues were 0 throughout, so there was no head-of-line blocking per destination either. A burst of dispatches (installs/entitlements across many users) briefly saturated the 64-slot routing pool faster than the ThreadPool could service it.

Impact

12 occurrences over ~6 minutes on 2 portal pods, self-resolving — an intermittent, user-visible routing delay under burst load, no data loss and no wedged state. Note: this log site has fanned out into many sibling incidents (many activation ids seen the same evening, see Admin/_LogIncident); this ticket covers the burst-window thread starvation, and the volume of sibling incidents for the same site suggests the threshold/pool sizing deserves a broader look.

Where to look

MeshWeaver.Hosting.Orleans.RoutingGrain — the routing pool sizing (64-slot cap) and the pre-subscribe ThreadPool wait it measures. If the pool cap is below what burst dispatch traffic needs, either raise it or bound/queue the pre-subscribe wait so back-pressure is applied at dispatch rather than as thread starvation. Compare CPU/ThreadPool metrics for the memex-portal pods at 2026-09-22 19:05–19:11 UTC. Related prior issues referenced by the log text: #5009 (per-channel head-of-line), #5018 (pool gauge semantics).


Evidence

Fingerprint 447d40a65dc94a05
Category MeshWeaver.Hosting.Orleans.RoutingGrain
Severity Critical
Namespace memex-cloud
Pods memex-portal-deployment-857546649-vf2q6, memex-portal-deployment-857546649-xx9j4
Occurrences 12
First seen 2026-09-22 19:05:15Z
Last seen 2026-09-22 19:11:02Z
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 19:08:34Z memex-portal-deployment-857546649-vf2q6 crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [8fbd4580#12 started 2026-09-22T19:08:34.0212897Z]: 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 5 ms — dispatch → roland.buergi/_Install/LearningRoadmap (delivery 4n_Kn7w2dUy9M9qJkHgY3A). Latest dispatch target lafayette.alves/_Install/AppleWeather — 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 CR…[truncated]
2026-09-22 19:08:34Z memex-portal-deployment-857546649-vf2q6 crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [8fbd4580#13 started 2026-09-22T19:08:34.0407726Z]: 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 6 ms — dispatch → AppleMusic/_Entitlements/marvinsangi (delivery sDVhHtkeDkmOA_OFN2E0Wg). Latest dispatch target OpenStreetMap/_Access/sebastien.duble_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 T…[truncated]
2026-09-22 19:08:41Z memex-portal-deployment-857546649-vf2q6 crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [8fbd4580#14 started 2026-09-22T19:08:41.2254067Z]: 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 2 ms — dispatch → beat/_Install/RemoteControl (delivery QBMGsKPwB06uTnDa0bWpPA). Latest dispatch target nerijus.vasiliauskas/_Install/Systemorph-MeshWeaver.Plugins — 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 sample…[truncated]
2026-09-22 19:10:49Z memex-portal-deployment-857546649-vf2q6 crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [7396a756#1 started 2026-09-22T19:10:49.0274989Z]: 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 22 ms — dispatch → RolePlay/_Entitlements/quentin.vilcot (delivery tOoE8ZSsnkuWcFULMmOyJg). Latest dispatch target quentin.vilcot/_Install/LearningRoadmap — 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 C…[truncated]
2026-09-22 19:11:02Z memex-portal-deployment-857546649-vf2q6 crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [7396a756#2 started 2026-09-22T19:11:02.5192543Z]: 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 2 ms — dispatch → baisakhi.das/_Install/Analysis (delivery f1W6S76zW0iU_hT62quPfA). Latest dispatch target AppleWeather/_Access/rafael.lerga_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]

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/447d40a65dc94a05. 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 23, 2026
  2. rbuergi commented on Sep 23, 2026

    @rbuergi
    Contributor

    Duplicate of #5118.

    Build: pod(s) memex-portal-deployment-857546649-vf2q6, memex-portal-deployment-857546649-xx9j4. ReplicaSet 857546649 runs 3da3423c / 3.0.0-ci.9193, which does not contain the compile-off-ThreadPool fix (#5327/#5375) (read from Ops/Status/memex-cloud version 3130).

    Window 2026-09-22 19:05:15Z → 2026-09-22 19:11:02Z, 12 occurrence(s), fingerprint 447d40a65dc94a05.

    activation#episode started waiting subscribing deepest channels / dest oldest leg
    8fbd4580#12 19:08:34Z 62 0 0 0 / 0 5 ms
    8fbd4580#13 19:08:34Z 61 0 0 0 / 0 6 ms
    8fbd4580#14 19:08:41Z 61 0 0 0 / 0 2 ms
    7396a756#1 19:10:49Z 62 0 0 0 / 0 22 ms
    7396a756#2 19:11:02Z 61 0 0 0 / 0 2 ms

    This issue's own discriminator: thread shortage (T): waiting for a pool slot high while subscribing ≤ 1. The oldest leg is at most 22 ms, so no leg is minutes old and no slot leaked. Episodes keep advancing on the same activation (8fbd4580, 7396a756), so each episode drained. It is the same log site and the same reading, sampled on the build without the fix. The cause, the fix, and the verification after memex rolls are recorded on #5118.

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