feat(telemetry): nest event loop stalls under the blocked span and sample their stacks - #2541
Conversation
🦋 Changeset detectedLatest commit: f6d6d6a The changes in this PR will be included in the next version bump. This PR includes changesets to release 39 packages
Not sure what this means? Click here to learn what changesets are. Click here if you're a maintainer who wants to add another changeset to this PR |
e7ad595 to
7a62e5d
Compare
174b98e to
d743e9c
Compare
d743e9c to
bfc5828
Compare
bfc5828 to
c67fc87
Compare
99f381d to
2c7ad49
Compare
2c7ad49 to
2767781
Compare
12c06b9 to
d8bfa3f
Compare
bbdbc0d to
ca21e29
Compare
![devin-ai-integration[bot]](https://avatars.githubusercontent.com/in/811515?s=60&v=4){kind=small}
This comment was marked as resolved.
This comment was marked as resolved.
Sorry, something went wrong.
ca21e29 to
ed17ea1
Compare
ed17ea1 to
78051b0
Compare
c6fedfb to
d4c0833
Compare
| const sameKind = leaves.filter( | ||
| ([, entry]) => spanName(entry.span) === spanName(newest[1].span), | ||
| ); | ||
| if (sameKind.length <= 1) return newest[1].span; |
There was a problem hiding this comment.
from Codex:
Differently named operations have the same ambiguity. A tool can await I/O, a newer RPC can start and await I/O, then the tool can resume and block. Both spans remain open, but this selects the idle RPC.
Should we use the common ancestor across all overlapping leaves, regardless of span name?
| const consider = (entry: { span: Span; createdAt: number }) => { | ||
| if (entry.createdAt > opened) return; | ||
| if (exclude.has(spanName(entry.span))) return; | ||
| candidates.set(entry.span.spanContext().spanId, entry); |
There was a problem hiding this comment.
also from Codex:
Can we filter candidates by the session/job context’s trace ID before selecting a parent? This processor receives spans from the entire provider. A newer background HTTP span from another trace can win here, moving
event_loop_blockedout of the agent’s trace.
There was a problem hiding this comment.
Note
Newer findings are available below. Devin Review posted a newer report on this PR, in addition to the findings presented here.
Devin Review found 1 new potential issue.
4 flags not posted on this PR by your GitHub settings — view them in Devin Review. (Configure)
| slack = 2, | ||
| ): Span | undefined { | ||
| const opened = startedAt + slack; | ||
| const closed = Math.min(endedAt - slack, startedAt + slack); |
There was a problem hiding this comment.
🟡 Earlier operation claims later stall
When operations run consecutively without a heartbeat, blockedSpan can select an earlier operation that already ended. Its span survives the early cutoff and outranks an older span still doing the long block, misparenting the stall.
Learn more
The monitor dates a stall from the first missed heartbeat, not from the exact start of the synchronous call. This cutoff admits every span that ends after that early point, even when another operation subsequently keeps the loop blocked for most of the report. An ended span with a later creation time can then beat the operation still running when the heartbeat finally fires. The report builder derives that approximate start from the timer lag, so it cannot distinguish consecutive blocking operations by their start times alone.
Example: A turn span starts at 0 ms. An RPC span starts at 15 ms and ends at 50 ms; the turn then blocks until 700 ms without letting the 20 ms heartbeat run. The report starts near 20 ms. Both spans qualify at the 40 ms cutoff, so the RPC claims the entire 680 ms stall even though the turn caused nearly all of it.
Recommended fix: Avoid attributing an entire late heartbeat to a span that only survived the beginning of its interval when another eligible span continued through its end. Preserve the ended-RPC case where it is the only credible blocker; add a consecutive-operations regression test.
Was this helpful? React with 👍 or 👎 to provide feedback.
aa86bbb to
8964dfb
Compare
There was a problem hiding this comment.
Note
Newer findings are available below. Devin Review posted a newer report on this PR, in addition to the findings presented here.
Devin Review found 3 new potential issues.
4 flags not posted on this PR by your GitHub settings — view them in Devin Review. (Configure)
| while ( | ||
| this.#ended.length && | ||
| (this.#ended[0]!.endedAt < cutoff || this.#ended.length > this.#maxEnded) | ||
| ) { | ||
| this.#ended.shift(); |
There was a problem hiding this comment.
🟡 Busy turn drops the blocking parent
If a blocking tool ends before 256 newer spans in one turn, #prune evicts its span before the late heartbeat. The stall loses its tool parent and falls back to an ancestor.
Learn more
The tracker retains ended spans because the monitor emits a stall one heartbeat after the blocking call returns. Each onEnd appends to the queue and enforces a fixed count, regardless of whether the heartbeat has reported a pending stall. Synchronous work or microtasks can end many spans before the next timer turn. When that happens, the blocking span is evicted before blockedContext looks it up.
Example: A tool blocks for 200 ms and ends. Its callback then ends 256 short spans before yielding to timers. The pending stall is eventually emitted under the agent turn instead of the blocking tool.
Recommended fix: Keep ended spans long enough for the monitor's pending stall to be reported, or snapshot the eligible parent at the late heartbeat before count-based eviction can discard it. Keep a bounded policy for spans not needed by pending reports.
Was this helpful? React with 👍 or 👎 to provide feedback.
8964dfb to
3c55365
Compare
3c55365 to
5178bf1
Compare
5178bf1 to
e7efc1c
Compare
…mple their stacks The Python monitor parents a stall under the span the blocked task was in and attaches lk.blocking.stack from its watchdog thread's samples of the loop thread. Node has no cross-thread stack read; this layer gets the same two outcomes by other means. Parent: BlockedSpanTracker, a span processor installed on every provider the framework owns (and on a user's provider through the same registrar as PII redaction), keeps the spans created and ended on the main thread with wall-clock creation and end times. A span created before a stall's window opened and still open, or ended no earlier than the window closed, was current during the stall; the innermost such span (created last) is the stall's parent, then the session root, then the job root. Creation time rather than the span's own start time, so a back-dated span (eou_wait) cannot claim an earlier stall; one heartbeat of slack on both ends, since the block's start is known to within a tick and its end is the late heartbeat's run. Stack: the existing watchdog worker thread attaches an inspector session to the main thread (Session.connectToMainThread) with the debugger domain enabled. It measures the heartbeat's lag from a shared slot the monitor writes each tick; at the warn threshold it posts Debugger.pause, receives the main thread's call frames (function names, files, lines, optimized code included) and resumes about a millisecond later, and looks once more at LATE_SAMPLE_FACTOR (10x) the threshold. The report formats each sample like the Python monitor's: a header with the offset into the stall, then the innermost 20 frames innermost first, Node's internals and everything outer than the framework's job runner cut. The warn log names the innermost frame of the agent's own code. A native call that does not check for interrupts (sync child process, sync fs) keeps the pause waiting until it returns, and the sample then shows the caller's frame, as the Python watchdog sees a native call once it releases the GIL; a pause that lands after the loop moved on is discarded with a note. Frame URLs missing from the pause (vm scripts) are resolved from the debugger's scriptParsed events. Gating: adaptive by default, sampling starts after a process's first code-caused stall; LIVEKIT_AGENTS_LOOP_BLOCK_STACKS=1|always from the start, 0|never not at all. Job processes only (the worker never samples), and never while an inspector is attached to the process, whose session our pauses would land in. Cost, measured on this machine with the framework loaded: enabling the debugger domain enumerates the loaded scripts on the loop once (about 90 ms in a process with @livekit/agents loaded; in adaptive mode that is a stall of its own, reported with a note saying so); with it enabled a mixed workload (object churn, JSON, numeric loops) runs 1.2% slower (1205/1222/1198 vs 1193/1165/1223 units/s interleaved) and idle CPU is unchanged; a pause costs about 1 ms when the loop is blocked, nothing otherwise. V8's sampling profiler was tried first and rejected: on Node 24 only the first profile of a process names code optimized before it started (every later profile attributes a hot function's samples to its caller), reading samples means restarting the profile, and each Profiler.start blocks the loop for 25 to 40 ms with the framework loaded. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Exports in @livekit/agents are not release-tagged, so API Extractor wrote a warning for every one of them into agents.api.md, burying the real changes in each review. Silence that one message for this package and regenerate the report. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Adaptive sampling turned on only for stalls that could carry a span, so the worker process and an idle child reported every stall with a note saying they do not sample. A log with a stack names the blocking code just as a span does, and the Python monitor samples in every process: sampling now starts after the first code stall wherever the monitor runs, and the note is gone. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
… handoff - The blocked-span tracker no longer guesses between two in-flight operations of the same kind (two tools, two RPC handlers): timing cannot say which one blocked, so the stall lands on their nearest common ancestor, or nowhere, instead of on the newer one. Operations of different kinds still resolve to the newest. - A stack sample's offset is measured from the stall's start as the report dates it (the tick that was due), not from the last on-time tick: every header overstated it by one heartbeat interval. - `stacks` other than `never` with `watchdog: false` is normalized to `never`, since the sampler runs on the watchdog thread; the option docs say so and no longer claim the worker process is excluded. - An inspector that attaches after sampling started stops it: the heartbeat checks the inspector URL and has the watchdog disable the debugger domain and disconnect, so a debugger's breakpoints are never resumed by the sampler. Later stalls note that an inspector is attached. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
…osition On a loaded host (CI runs every agents test file at once) the block's stall can be preceded by stalls of the host's own, and the watchdog's pause can land in one of those. The stack tests now look for the report whose sampled stack names the blocking function and retry the block a few times, rather than trusting the first report after it. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
… pause back - BlockedSpanTracker confines candidates to the trace of the fallback context, so a span of an unrelated trace open during a stall (an application's own HTTP request) cannot become the stall's parent - the watchdog's Debugger.paused handler no longer resumes a pause that a real debugger took before the monitor's next heartbeat noticed it: it disables sampling instead The newest-of-different-kinds rule is kept, with the trade-off documented: the common-ancestor alternative would file a stall during any wait (an audio track wait, a user turn) under the session, undoing the blocking-RPC attribution of #2575. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
…heck first; eviction guard - checkStall captures the incident's window before awaiting the pause, so a sample never reads an incident cleared meanwhile - Debugger.paused hands any pause to an attached inspector before treating it as the sample we asked for: resuming could take a breakpoint from under the operator - BlockedSpanTracker's count bound never evicts a span that ended within the last second, so a burst of spans ending before the loop yields cannot drop the blocking span the late heartbeat reports under Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
e7efc1c to
f6d6d6a
Compare
There was a problem hiding this comment.
Devin Review found 1 new potential issue.
⚠️ 1 issue in files not directly in the diff
⚠️ Recovered primary mislabels fallback recognition
If the primary recovers during fallback recognize(), model and provider report the primary instead of the recognizing child. The live sttIdentity callback then credits the fallback transcript to the wrong provider.
4 flags not posted on this PR by your GitHub settings — view them in Devin Review. (Configure)
3 participants
Stacked on #2501. Not a port: the Python monitor gets these from
sys._current_frames()and the blocked task's context, which Node has no equivalent for; this layer reaches the same observable result with Node mechanisms.Description
A cloud export from the JS build showed every
event_loop_blockedspan parented toagent_sessionwith no stack, which made the stalls hard to act on. Two changes, both matching what the Python monitor reports:A stall nests under the span that was blocked. Every framework span is created and ended on the main thread, so a span created before a stall and still open (or ended when the blocking call returned) was current during it.
BlockedSpanTracker, a span processor installed wherever the framework installs its own processors, keeps creation and end times; the monitor parents a stall under the innermost such span, then the session root, then the job root. A slow tool lands underfunction_tool, a slow RPC underrpc_handler, a slow hook underon_user_turn_completed. Creation time is used rather than the span's start time, so a back-datedeou_waitcannot claim a stall that predates it.lk.blocking.stackis populated. The watchdog worker thread attaches an inspector session to the main thread and, when the heartbeat is a warn threshold late, postsDebugger.pause: V8 honours it inside a spinning script, hands back full symbolized frames (optimized code included), and resumes about a millisecond later. A second sample at 10x the threshold, like Python's late sample. The format matches the Python monitor:# loop thread sampled Nms into the stallthen the innermost 20 frames; Node internals dropped except innermost; frames outer than the framework's job runner cut. The warn log names the innermost frame of the agent's own code.Sampling is adaptive by default: off until the process reports its first code-caused stall, then on for that process, so a healthy process never enables the debugger domain.
LIVEKIT_AGENTS_LOOP_BLOCK_STACKS=alwaysturns it on from the start,neveroff. Enabling the debugger domain costs one loop gap of about 90 ms with the framework loaded (script enumeration), once per process; in adaptive mode that gap is itself reported as a stall with the note that the sampler was starting, and inalwaysmode it happens at monitor start, before any job work. Not enabled while an inspector is attached to the process. The worker process and an idle child sample too (third commit): their stalls only reach the log, and a log with a stack names the blocking code just as a span does, so no stall is reported with a note saying its process does not sample.Rejected alternative, not what ships: V8's sampling profiler was tried first. On Node 24 only the first profile of a process names code optimized before it started, reading its samples requires restarting the profile, and each restart blocked the loop for 25 to 40 ms with the framework loaded. Those figures describe the profiler, not the
Debugger.pausemechanism above.Measured overhead of the shipped mechanism with the framework loaded (ten interleaved rounds, medians): with the debugger domain enabled a tight compute loop is 1.1% slower and a mixed JSON/regex/promise workload 0.6% slower; idle CPU with the 20 ms heartbeat is unchanged (0.33% vs 0.31% of a core); a pause sample costs about 1 ms and only while a stall is under way. In adaptive mode none of this is paid until the process's first code-caused stall.
Limits. A native call that does not check for interrupts (sync file or child-process calls, native addons) keeps the pause waiting until it returns; the sample then shows the caller still in the frame that made the call, which is what the Python watchdog sees once a native call releases the GIL.
lk.blocking.taskstays unset: Node has no task names.Verified live
Hotel receptionist example with a
testRPC that spins for 600 ms, called twice from a client: bothrpc_handlerspans underagent_session, both stalls under theirrpc_handler, the first without a stack (adaptive), the second sampled 121 ms into the stall naming the handler, the SDK'sinvokeRpcHandler, and the interceptor'sinterceptIncoming.Testing
telemetry/loop_monitor_stacks.test.ts(13 tests): parenting under an open span, fallbacks, tracker retention, adaptive / always / never, the formatted stack from a real blocked call, restart bounds, env parsing. The existing 28 monitor tests unchanged.agentssuite green; build, typecheck, lint, API report updated.API report noise (second commit). Exports in
@livekit/agentsare not release-tagged, so API Extractor wrote anae-missing-release-tagwarning for every one of them intoagents.api.md(854 by this layer), burying the real changes in each review.agents/api-extractor.jsonnow silences that one message for this package and the report is regenerated: the diff is only the removed warning lines. Other warning kinds (ae-forgotten-export,ae-unresolved-link, ...) are untouched.Review follow-ups (fourth commit)
function_tools of one turn, tworpc_handlers), the tracker no longer picks the newer one, which timing cannot justify: the stall lands on their nearest common ancestor among the open spans, or on the session/job root when there is none. Operations of different kinds (auser_turnopen while anrpc_handlerruns) still resolve to the newest. An exact answer for sampled stalls is possible as a follow-up: evaluate the active span on the paused main thread during the sample, which reads the blocked operation's async context the way Python reads the blocked task's context variables.stacks: always|adaptivewithwatchdog: falseis normalized tonever(the sampler runs on the watchdog thread), documented, so such a configuration does not note on every stall that sampling starts after the first one.debugger;statement in user code is still resumed while no inspector is attached: it only pauses at all because the sampler enabled the domain. Later stalls note that an inspector is attached. Tested against a realinspector.open().🤖 Generated with Claude Code