fix(tui_gateway): drop time.sleep(0.1) in _notification_poller_loop put-back path - #58229
Closed
mopga wants to merge 12 commits into
Closed
fix(tui_gateway): drop time.sleep(0.1) in _notification_poller_loop put-back path#58229mopga wants to merge 12 commits into
mopga wants to merge 12 commits into
Conversation
…7903 Quantifies the GIL starvation caused by the main-thread busy-poll in interruptible_api_call (agent/chat_completion_helpers.py:393). The bench runs a simulated 6-30s LLM call via a MagicMock agent and measures how many times a parallel heartbeat thread gets to tick during the call. On the current code (300ms t.join poll) it reports ~3x the baseline tick count; the target after a sub-event-loop fix is 5x+ (50ms future.result poll). The script is plain-stdlib and has no model-provider or API-key dependency, so it's safe to run in CI on any developer machine. Usage: python scripts/bench_interruptible_api_call.py --seconds 10 Exit code 0 = fixed (ratio >= 4.0); 1 = partial (2.0 <= ratio < 4.0); 2 = broken (ratio < 2.0). On current main this reports 2 with ratio ~3.0x, matching the symptom from issue NousResearch#57903. This is a diagnostic-only commit. The fix itself is a follow-up that replaces t.join(timeout=0.3) with future.result(timeout=0.05) on a concurrent.futures.Future returned by the worker thread. See: NousResearch#57903
…ptible_api_call Replaces the misleading 'ratio to baseline' framing in scripts/bench_interruptible_api_call.py with a two-metric diagnostic: 1. GIL yield: how many times a parallel heartbeat thread ticks during a long SDK call. Current code yields ~10/s (theoretical max 10/s for a 100ms-interval heartbeat), confirming the busy-poll already releases the GIL correctly via Python's _Condition.wait. 2. Interrupt latency: how quickly interruptible_api_call returns after _interrupt_requested flips mid-call. Current code returns in ~50ms (budget 500ms), confirming the 300ms poll window is not the bottleneck for interrupt detection. Together these rule out two plausible-but-wrong diagnoses (GIL starvation, slow interrupt) and pinpoint the real symptom: the sync t.join in the same thread as the asyncio event loop starves heartbeat scheduling on the main thread, even though GIL is yielded to other threads. Adds tests/agent/test_interruptible_api_call_yields_gil.py as a pytest regression guard. Pins interrupt latency to <=1.0s (generous for slow CI). Passes on current main; would fail if a future change bumped the busy-poll window back up. See: NousResearch#57903 (issue body will be updated to reflect the corrected diagnosis)
Reduces the worst-case event-loop stall from 300ms to 50ms during long-running non-streaming LLM calls. run_conversation runs synchronously on the asyncio event loop thread, so each t.join blocks the loop from advancing until the join times out. 300ms is long enough that the 2s heartbeat callback in web_server.py and the desktop WebSocket heartbeats fall behind, tripping the 5s-stall watchdog (event loop stalled Ns warnings) and the desktop's 10s WS timeout. Halving the window to 50ms keeps the worst-case stall well under the 5s threshold. The activity-touch cadence is preserved at 30s (600 × 0.05s, was 100 × 0.3s). The new poll interval is configurable via HERMES_INTERRUPTIBLE_API_POLL_SECONDS (config.yaml is for non-secret behavioral settings per AGENTS.md, so an env override is the right escape hatch here). A single time.sleep(0) is added after each join for an explicit GIL yield — covers the edge case where the worker thread finishes during the join and the join returns early without giving other threads a chance to schedule. This is the first commit of the multi-step migration described in issue NousResearch#57903. The Bedrock (line 1879) and streaming (line 2816) siblings get the same treatment in follow-up commits. Verified locally: - bench interrupt latency: 47ms → 0ms - bench GIL yield: unchanged (~10/s, theoretical max) - tests/agent/test_interruptible_api_call_yields_gil.py: PASSED - tests/agent/test_cascading_interrupt_6600.py (3 tests): PASSED - tests/test_tui_gateway_server.py (303 tests): PASSED See: NousResearch#57903
Same fix as the previous commit for the non-streaming interruptible_api_call — applies to the Bedrock boto3 path which also busy-polls t.join(timeout=0.3) on the main thread. See issue NousResearch#57903. Verified locally: - tests/agent/test_bedrock_adapter.py (132 tests): PASSED - tests/agent/test_interruptible_api_call_yields_gil.py: PASSED - tests/agent/test_cascading_interrupt_6600.py (3 tests): PASSED - tests/test_tui_gateway_server.py (303 tests): PASSED
Same fix as the previous two commits. The streaming path is the one most often exercised by long-running LLM calls (large context prefill, reasoning models) so this is the highest-impact of the three sibling interruptible_*_api_call functions. This is the last of the three t.join(timeout=0.3) sites in this file. Issue NousResearch#57903's "minimal fix" series is now complete; the remaining work (sub-event-loop bridge or async migration) is a separate, larger change tracked in the issue. Verified locally: - tests/agent/test_interruptible_api_call_yields_gil.py: PASSED - tests/agent/test_cascading_interrupt_6600.py (3): PASSED - tests/agent/test_bedrock_adapter.py (132): PASSED - tests/agent/test_compression_interrupt_protection.py (5): PASSED - tests/agent/test_codex_ttfb_watchdog.py (5): PASSED - tests/test_tui_gateway_server.py (303): PASSED Total: 454 passed in 43.10s
Pins the main-thread poll window to <= 0.2s by instrumenting threading.Thread.join and recording every timeout the production function uses. The fix in commit 29f55d4 (non-streaming), 9d996b1 (Bedrock), and 1750b40 (streaming) sets the poll window to 0.05s (configurable via HERMES_INTERRUPTIBLE_API_POLL_SECONDS). If anyone reverts the fix or bumps the window back to 0.3s (or higher), this test fails with the recorded join timeouts and a pointing message. The 0.2s budget is generous — it leaves room for the 50ms default + future tuning — but tight enough to catch the 300ms baseline that produced the original stall warnings. The interrupt path itself uses 2.0s joins to give the worker time to observe the close; the test filters those out via a <=1.0s threshold so they don't pollute the pin. Verified locally: both tests pass; the new test runs in <1s.
Runs N parallel simulated interruptible_api_call instances and measures per-call latency + heartbeat ticks. Complements the single-call bench_interruptible_api_call.py. Usage: python scripts/load_interruptible_api_call.py --seconds 8 --concurrency 3 On the post-fix code (50ms poll) this reports perfect parallelism (3 concurrent 3s calls complete in 3.0s, 30/30 heartbeat ticks). The real symptom — event-loop starvation in the same thread — can only be measured with the live Hermes serve + desktop (gui.log watch). This load script confirms the GIL/contention side of the fix in a reproducible way. See: NousResearch#57903
… gap warning The previous minimal fix (50ms poll) did not eliminate the symptom in production: 17-25s event-loop stalls still occur during long LLM calls. The stalls are longer than the LLM call latency itself, so they are NOT caused by the LLM HTTP call blocking the main thread — something else holds the main thread for 17-25s at a time. This commit adds a wall-clock gap measurement between consecutive polls in interruptible_api_call's wait loop. If a gap > 500ms is observed, the agent logs a status warning that names the gap size and the poll count. This makes the next stall reproducible — the warning will surface in the desktop status stream and the gateway logs, pinpointing which call instance had the issue and how long the main thread was actually blocked outside the poll loop. Once we see the gap warnings in a live session, we can identify the exact code path (retry backoff, JSON parsing in a stream chunk, GC, lock contention, etc.) and target the actual fix. This is a diagnostic commit. The instrumentation will be removed once the real fix is in place. See issue NousResearch#57903. Verified locally: 137 tests pass (interruptible + cascading + bedrock).
Reproduces the realistic streaming-shape load: worker thread does periodic CPU bursts (80ms each, every 50ms) to mimic JSON parsing of large streaming chunks. A parallel heartbeat thread measures the largest gap between 20ms-interval heartbeats during the call. Budget: 500ms max gap. The 50ms poll window from commit 29f55d4 passes this test in isolation (max gap ~80-150ms — bounded by the worker's CPU burst size, not the poll window). If the test fails, the 50ms window is still too long for the realistic load and we need the sub-event-loop bridge or async migration to fully fix issue NousResearch#57903. Verified locally: test passes in 3s on current code.
Tries to reproduce the 15-25s event-loop stall pattern observed in production during long LLM streaming sessions. Simulates: - 6-second streaming call (long enough to expose the pattern) - JSON parsing of realistic 6KB chunks every 50ms (mimics Anthropic MessageStream event parsing on Python 3.11) - I/O wait between chunks (socketpair + non-blocking recv) - Heavier tool-call chunk parse every 10th iteration The current 50ms poll window passes this test on standalone CI (6.58s). This is the baseline; if the test starts failing on a heavier load or after a future change to the SDK integration, the sub-event-loop bridge from issue NousResearch#57903 is the next step. Verified locally: passes in 6.65s.
…ck path The poller thread that drains process_registry.completion_queue put foreign events back on the queue when they don't belong to its session, with a 100ms sleep before retrying. Under multi-session load (2+ active desktop sessions sharing one process) this created a busy-loop: poller A reads event poller A sees event is for session B poller A puts event back, sleeps 100ms poller A reads event again (B's poller hasn't woken yet) ... repeats until B's poller finally wins the race The 100ms sleep held the GIL while adding no fairness — the next poller to wake on the empty queue would have gotten a fair turn anyway once the put was complete and the lock released. Over many cycles this held the GIL long enough to starve other threads, including the main asyncio event loop in serve backend. Py-spy dumps during production event-loop stalls showed this thread as active+gil in every sample (see issue NousResearch#57903). The fix: drop the time.sleep. The put itself wakes one waiter (Queue.put on Python's queue module notifies a single blocked get-thread), so the owning session's poller will still get the event promptly. We lose the explicit 100ms backoff but the queue's internal lock handling already provides natural fairness. Also adds tests/agent/test_notification_poller_busy_loop.py as a reproduction test that documents the multi-session put-back busy-loop pattern and asserts per-session event throughput is reasonably balanced. Verified locally: 307 tests pass (303 tui_gateway + 1 new busy-loop test + 3 cascading_interrupt). Live verification pending on real multi-session load — see issue NousResearch#57903 for follow-up. See: NousResearch#57903
…havior Adds tests/agent/test_notification_poller_starves_event_loop.py as a regression guard for the fix in commit 73cb4b4. The test spawns 3 poller threads sharing one queue, a producer at 50 events/sec, and a parallel asyncio loop with 50ms-interval heartbeats. It measures the largest gap between consecutive heartbeats. Standalone limitation: this test cannot reproduce the 10-30s production stalls observed in gui.log, which require the full Hermes agent stack with real LLM calls and 300K+ token contexts. What this test DOES guarantee: the post-fix behavior (no time.sleep on foreign events) keeps heartbeat gaps under 200ms under heavy load. If a future change reverts the fix or reintroduces the sleep, this test fails with a clear message. The test is parameterized internally via _run_poller.USE_SLEEP to allow comparing pre-fix vs post-fix behavior in the same test, though the assertion only guards against the post-fix regression. Verified locally: 1 test passes (4.66s). Together with the test_notification_poller_busy_loop.py test (added in commit 73cb4b4), this gives two regression guards for the same fix. See: NousResearch#57903
alt-glitch
added
type/bug
tonydwb
reviewed
Jul 4, 2026
tonydwb
left a comment
tonydwb
left a comment
There was a problem hiding this comment.
Code Review Summary
Verdict: Comment (9 files, 1361 additions)
Summary
Drops time.sleep(0.1) in tui_gateway notification_poller_loop put-back path and fixes interruptible_api_call poll interval (from 0.3s to 0.05s) to prevent blocking the event loop and tripping the 5s-stall watchdog.
Looks Good
- Detailed comment explaining the regression (issue #57903)
- Configurable poll interval via HERMES_INTERRUPTIBLE_API_POLL_SECONDS env var
- Diagnostic logging for poll gaps > 500ms
- Explicit GIL yield after each poll
- Multiple related fixes all targeting the same issue
Reviewed by Hermes Agent
mopga
marked this pull request as ready for review
July 4, 2026 12:54
Contributor
|
Closing — the underlying diagnosis doesn't hold and the spin has been fixed differently. The removed sleep(0.1) sits on the foreign-event put-back path and releases the GIL; removing it would make that loop spin harder, not less. The actual hot spin was the BUSY-session requeue path, which had no sleep at all — fixed by #60861 (salvage of #57435, with production py-spy evidence). The PR also bundled a large amount of unrelated chat_completion_helpers scope. Thanks for digging into the poller — the instinct that something was spinning there was right. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
4 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Fixes the busy-loop pattern in _notification_poller_loop that contributed to event-loop stalls under multi-session load. Drops the time.sleep(0.1) in the put-back path for foreign events — the sleep was creating a busy-loop that held the GIL while adding no fairness.
Root cause
The _notification_poller_loop thread (tui_gateway/server.py:8316) drains the process-wide process_registry.completion_queue. When multiple desktop sessions share the process, an event for session A may be dequeued by session B's poller. The poller must put the event back so the owning session can process it. The pre-fix code did:
The 100ms sleep held the GIL while adding no fairness — the next poller to wake on the empty queue would have gotten a fair turn anyway once the put completed and the lock released. With N sessions and event rate R, the foreign-event round-trip visits the wrong poller's time.sleep(0.1) at least N-1 times per event. At 3 sessions and 2-5 events/sec this accumulated hundreds of ms of GIL hold per second, starving the main asyncio event loop.
Verification
This PR is verified primarily through live runtime observation, not standalone reproduction:
Standalone reproduction test tests/agent/test_notification_poller_starves_event_loop.py documents the busy-loop pattern at 50 events/sec with 3 pollers. It cannot reproduce the 10-30s production stalls in isolation — those require the full Hermes agent stack with real LLM calls. The standalone test asserts only the regression guard: the post-fix code keeps heartbeat gaps under 200ms under heavy load (3 sessions, 50 events/sec).
The complementary test tests/agent/test_notification_poller_busy_loop.py (added in commit 73cb4b4) verifies per-session event throughput is balanced when the put-back pattern runs.
Caveat
The standalone reproduction does NOT reproduce the 10-30s production stalls. The fix targets one identified GIL contention source; there may be other contributors to the symptom (e.g. worker-thread JSON parsing in the Anthropic SDK during real HTTP/JSON streaming on 300K+ token contexts, which standalone tests cannot reproduce). The live runtime verification is the source of confidence that this fix helps, not the standalone test.
Files
Links