Skip to content

feat(telemetry): flag synchronous code blocking the event loop - #2459

Open
rosetta-livekit-bot[bot] wants to merge 1 commit into
mainfrom
efforts-vilely-nestling
Open

feat(telemetry): flag synchronous code blocking the event loop#2459
rosetta-livekit-bot[bot] wants to merge 1 commit into
mainfrom
efforts-vilely-nestling

Conversation

@rosetta-livekit-bot

@rosetta-livekit-bot rosetta-livekit-bot Bot commented Sep 9, 2026

Copy link
Copy Markdown
Contributor

What

Ports livekit/agents#7128 to flag synchronous work that blocks worker and job event loops. Blocks at or above 100 ms emit structured warnings, backdated event_loop_blocked spans, lk.agents.event_loop.blocked_duration histogram measurements, and per-session stall events/summaries. LIVEKIT_AGENTS_LOOP_BLOCK_WARN_MS=0 disables monitoring; warning and error thresholds otherwise default to 100 ms and 500 ms.

How

  • Runs an unrefed heartbeat on worker and job processes, with one-fifth-threshold sampling bounded to 20-50 ms.
  • Preserves job and active-session OTel parentage for delayed reports.
  • Records metrics and session summaries before 30 spans/minute and 5 logs/minute rate limits.
  • Adds the missing OTel metrics provider/exporter pipeline, including per-job attributes, delta temporality, flush/shutdown handling, and the existing recording-disabled upload gate.
  • Exposes the feature as telemetry.loopMonitor and adds a minor changeset for the new public API.

Runtime-specific gap

Node does not expose a safe cross-thread JavaScript stack sampler equivalent to Python sys._current_frames(), nor Python-style per-loop GC callbacks or loop-thread CPU accounting. Consequently this port cannot attach blocked-task stacks/task names, identify lazy imports, attribute GC time, nest under the exact span active in the blocked callback, or independently distinguish process descheduling from synchronous blocking. It reports measured event-loop delay and process CPU time, with session/job fallback parentage; host scheduling delays can therefore look like code-caused stalls. These behaviors are not silently dropped or approximated with fabricated attribution.

Tests

  • pnpm test agents --silent (2,508 passed, 5 skipped)
  • pnpm build
  • pnpm --filter @livekit/agents build
  • pnpm lint
  • pnpm format:check
  • pnpm typecheck
  • pnpm throws:check
  • pnpm --filter @livekit/agents api:check
Source diff coverage
  • Adapted: livekit-agents/livekit/agents/cli/cli.py -> agents/src/worker.ts. JS AgentServer owns the worker loop for CLI and programmatic use, so it starts/stops the no-span worker monitor there.
  • Adapted: livekit-agents/livekit/agents/ipc/job_proc_lazy_main.py -> agents/src/ipc/job_proc_lazy_main.ts. Captures active job_entrypoint OTel and job contexts for reports.
  • Adapted: livekit-agents/livekit/agents/ipc/proc_client.py -> agents/src/ipc/job_proc_lazy_main.ts. JS has one child-process event loop per job and no Python-style proc_client, so monitor lifecycle belongs in the child bootstrap.
  • Ported: livekit-agents/livekit/agents/telemetry/__init__.py -> agents/src/telemetry/index.ts, exposing telemetry.loopMonitor.
  • Adapted: livekit-agents/livekit/agents/telemetry/loop_monitor.py -> agents/src/telemetry/loop_monitor.ts. Ports thresholds, heartbeat delay detection, CPU timing, rate limits, backdated spans, logs, metrics, context/session attribution, lifecycle, and registry semantics. Cross-thread stack/watchdog/GC/import behavior is unavailable in Node for the reasons above.
  • Adapted: livekit-agents/livekit/agents/telemetry/otel_metrics.py -> agents/src/telemetry/otel_metrics.ts, plus agents/src/telemetry/traces.ts, agents/src/telemetry/upload_gate.ts, agents/package.json, and pnpm-lock.yaml. Adds the metrics SDK/exporter infrastructure absent from the target.
  • Adapted: livekit-agents/livekit/agents/telemetry/session_context.py -> agents/src/telemetry/session_context.ts, using JS AsyncLocalStorage, JobContext._primaryAgentSession, and rootSpanContext.
  • Ported: livekit-agents/livekit/agents/telemetry/trace_types.py -> agents/src/telemetry/trace_types.ts, including all twelve source constants; Node-runtime-specific constants remain declared even when not populated.
  • Adapted: livekit-agents/livekit/agents/voice/agent_session.py -> agents/src/voice/agent_session.ts, adding per-session events and count/total/max attributes.
  • Not applicable: livekit-agents/pyproject.toml. Its livekit Python SDK pin enables Python RPC interception; JS already has its own RPC tracing path and no corresponding dependency.
  • Adapted: tests/test_loop_monitor.py -> agents/src/telemetry/loop_monitor.test.ts. Ports source-equivalent Node behavior for timing, severity, parentage, no-job/worker modes, idle/cooperative/off-loop work, lifecycle, rate limiting, metric/session coverage, environment parsing, constructor validation, registry behavior, and tick bounds. Python-runtime-specific stack, GIL/watchdog, GC, importlib, and thread-identity cases are not applicable.
  • Adapted: tests/test_trace_types_pii.py -> agents/src/telemetry/trace_types.test.ts, classifying every new attribute as non-PII.
  • Adapted: uv.lock -> pnpm-lock.yaml only for target-native OTel metrics dependencies. Python wheel and version-marker changes are not applicable.
  • Target release metadata: .changeset/slow-loops-report.md and agents/etc/agents.api.md are target-required changeset/API report files with no source counterpart.

Source: livekit/agents#7128


Ported from livekit/agents#7128

Original PR description

What

Synchronous work on the agent's event loop (a blocking HTTP client in a tool, heavy numpy in an audio processor, time.sleep in on_enter) shows up as unexplained latency and jitter. asyncio only reports slow callbacks in debug mode, which is too expensive for production and only logs.

This adds telemetry.loop_monitor, which flags blocks of 100 ms or more as spans, warnings, and a histogram, so users see the programming issue next to the turn it delayed.

How

No monkeypatching of asyncio. The monitor observes one loop with:

  • a heartbeat scheduled with call_later every 20 ms (a fifth of the warn threshold, bounded to 20–50 ms); a block shows up as a late tick (resolution: one interval);
  • a watchdog thread that samples the loop thread's stack via sys._current_frames() once the gap crosses the warn threshold, and again at 10x, so the report says where the loop was stuck;
  • when the late tick runs (block over), it emits a back-dated event_loop_blocked span with lk.blocking.{duration,threshold,severity,task,stack,gc_time,cpu_time}, sets status ERROR past the error threshold, logs a rate-limited warning with the innermost location, and records lk.agents.event_loop.blocked_duration.

Details:

  • GC time is measured through gc.callbacks so a gen-2 pause is not blamed on user code; loop-thread CPU time separates busy work from blocking waits.
  • Spans capped at 30/min and logs at 5/min; the next span carries lk.blocking.suppressed.
  • Runs on every job loop (proc_client.run, PROCESS and THREAD executors). The worker loop is monitored too, but there is no job or session to attach a span to there, so it logs and records the metric only.
  • The watchdog thread measures its own late wake-ups: when it stalled along with the loop, the whole process was descheduled (host contention, CPU quota). That is not a programming issue, so it is not logged at all (the span, at warning severity with UNSET status, and the metric keep the record); ERROR is reserved for code that blocked the loop. A native call that holds the GIL for the whole stall also starves the watchdog, so the loop thread's CPU time tells the two apart: a descheduled process burns none, a GIL-holding call burns all of it. That case stays an error, and since the sampler could not run, the stack attribute says so instead of staying empty.
  • The event_loop_blocked histogram is recorded for every stall, before the span (30/min) and log (5/min) rate limits, so dashboards do not undercount sustained blocking.
  • LIVEKIT_AGENTS_LOOP_BLOCK_*_MS rejects NaN and infinity like any other garbage value (falls back to the default).
  • Stack samples keep the innermost frame even when it is asyncio's dispatch frame (a C function scheduled directly has no frame of its own) and are prefixed with when in the stall they were taken.
  • Reports run inside a copy of the job's context taken in the job_entrypoint span, so they carry job attribution. A stall during a session is a child of agent_session (resolved through the job, since the heartbeat's own context predates the session) and the session span gets an event_loop_blocked event plus lk.blocking.count/total_duration/max_duration; a stall before or after the session is a child of job_entrypoint at its real time. Without a job (the worker process) there is no trace to belong to: log and metric only.
  • The session's stall summary (lk.blocking.count/total_duration/max_duration, one event_loop_blocked event per stall) is updated for every stall, like the histogram, before the span (30/min) and log (5/min) rate limits apply.
  • The watchdog gap is race-proof: when a descheduled process resumes, the loop thread may tick before the watchdog has recorded its late wake-up, so the tick also looks at when the watchdog last ran at all; a late-wake record from an earlier stall is discarded rather than mislabelling the next one.
  • A stall the watchdog never observed running anything, with no CPU burned, is host-caused too: nothing blocked the loop, the scheduler or timer coalescing woke it late. A blocking wait in code releases the GIL and gets sampled; a GIL-holding call burns CPU; both stay warnings. If the recorded thread ident does not resolve, the sampler finds the loop thread through the blocked task's coroutine frame and remembers it.
  • A stall nests under the span the blocked task was in: the watchdog sample reads the blocked task's current span (Task.get_context(), Python 3.12+), so a time.sleep in an RPC handler shows under rpc_handler, a slow tool under function_tool, a slow hook under on_user_turn_completed. Older interpreters, and stalls with no sample, fall back to agent_session.
  • Sampled stacks cut through the job runner: everything up to and including the innermost livekit/agents/ipc/ frame (process bootstrap, client loop, entrypoint wrapper) is dropped, since it is the same in every sample; framework frames below the user's code stay because they show what blocked.

Defaults: warn at 100 ms, error at 500 ms. LIVEKIT_AGENTS_LOOP_BLOCK_WARN_MS / LIVEKIT_AGENTS_LOOP_BLOCK_ERROR_MS override; WARN_MS=0 disables.

Overhead: one timer callback and one thread wake-up every 20 ms, measured at about 0.5% of a core on an idle loop (0.7% at 10 ms).

Tests

tests/test_loop_monitor.py (unit): a 200 ms time.sleep yields one back-dated error span whose stack names the blocking function and time.sleep, with low CPU time; a 70 ms block is a warning with status UNSET; an idle loop, executor / to_thread work, and ~0.6 s of sustained cooperative load yield nothing; a burst of ready callbacks in one iteration is one stall whose stack ends at the dispatch frame; a GC pause on a large heap is attributed to gc_time; worker mode logs without spans; set_report_context parents the span; stop is idempotent; rate limiter, env parsing, per-loop registry, constructor validation. The module passes repeatedly under 2x-cores CPU burners.

Try it

@function_tool
async def slow_tool(self):
    time.sleep(0.3)  # -> event_loop_blocked span under the turn, warning in logs

Stacked on #7127.

🤖 Generated with Claude Code

  • Lazy imports are named. When the sampled stack is inside the import system, the report carries the module being imported (lk.blocking.import, and in the log line) and the log's location is the caller that triggered it rather than an importlib frame, so the module can be moved to process warm-up.

@rosetta-livekit-bot
rosetta-livekit-bot Bot requested a review from a team as a code owner September 9, 2026 08:15
@changeset-bot

changeset-bot Bot commented Sep 9, 2026

Copy link
Copy Markdown

🦋 Changeset detected

Latest commit: 8ed7421

The changes in this PR will be included in the next version bump.

This PR includes changesets to release 38 packages
Name Type
@livekit/agents Minor
@livekit/agents-plugin-anam Minor
@livekit/agents-plugin-anthropic Minor
@livekit/agents-plugin-assemblyai Minor
@livekit/agents-plugin-azure Minor
@livekit/agents-plugin-baseten Minor
@livekit/agents-plugin-bey Minor
@livekit/agents-plugin-cartesia Minor
@livekit/agents-plugin-cerebras Minor
@livekit/agents-plugin-deepgram Minor
@livekit/agents-plugin-did Minor
@livekit/agents-plugin-elevenlabs Minor
@livekit/agents-plugin-fishaudio Minor
@livekit/agents-plugin-google Minor
@livekit/agents-plugin-hume Minor
@livekit/agents-plugin-inworld Minor
@livekit/agents-plugin-krisp Minor
@livekit/agents-plugin-lemonslice Minor
@livekit/agents-plugin-liveavatar Minor
@livekit/agents-plugin-livekit Minor
@livekit/agents-plugin-minimax Minor
@livekit/agents-plugin-mistral Minor
@livekit/agents-plugin-mistralai Minor
@livekit/agents-plugin-neuphonic Minor
@livekit/agents-plugin-openai Minor
@livekit/agents-plugin-perplexity Minor
@livekit/agents-plugin-phonic Minor
@livekit/agents-plugin-protoface Minor
@livekit/agents-plugin-resemble Minor
@livekit/agents-plugin-rime Minor
@livekit/agents-plugin-runway Minor
@livekit/agents-plugin-sarvam Minor
@livekit/agents-plugin-silero Minor
@livekit/agents-plugin-soniox Minor
@livekit/agents-plugin-tavus Minor
@livekit/agents-plugins-test Minor
@livekit/agents-plugin-trugen Minor
@livekit/agents-plugin-xai Minor

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

@devin-ai-integration devin-ai-integration Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Devin Review found 2 potential issues.

2 flags not posted on this PR by your GitHub settings — view them in Devin Review. (Configure)

Devin Review

Comment on lines +300 to +304
function isNoopMeterProvider(provider: ReturnType<typeof metrics.getMeterProvider>): boolean {
// The API does not publicly export its singleton NoopMeterProvider. The constructor is the
// stable distinction available in OTel API 1.x, equivalent to checking the private proxy/no-op
// provider in the Python SDK.
return provider.constructor.name === 'NoopMeterProvider';

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 Cloud blocking metrics never initialize

On a fresh process, isNoopMeterProvider rejects OpenTelemetry's initial proxy provider. setupCloudMetrics then disables metrics permanently, so blocking measurements never reach LiveKit Cloud.

Prompt for agents
Update agents/src/telemetry/traces.ts so setupCloudMetrics recognizes OpenTelemetry API's initial ProxyMeterProvider as an unconfigured provider. Avoid constructor-name checks if possible. Preserve the existing behavior that refuses to replace a user-installed meter provider, and add a test that starts from the API's default provider and verifies cloud metric provider registration succeeds.
Devin Review

Was this helpful? React with 👍 or 👎 to provide feedback.

Comment on lines +148 to +154
if (this.warnThreshold <= 0) throw new Error('warnThreshold must be > 0');
if (this.errorThreshold < this.warnThreshold) {
throw new Error('errorThreshold must be >= warnThreshold');
}
if (this.tickInterval <= 0 || this.tickInterval > this.warnThreshold) {
throw new Error('tickInterval must be > 0 and <= warnThreshold');
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 Non-finite options bypass monitor validation

A NaN option bypasses EventLoopMonitor validation. A NaN tick interval becomes a zero-delay timer, making the monitor spin continuously.

Suggested change
if (this.warnThreshold <= 0) throw new Error('warnThreshold must be > 0');
if (this.errorThreshold < this.warnThreshold) {
throw new Error('errorThreshold must be >= warnThreshold');
}
if (this.tickInterval <= 0 || this.tickInterval > this.warnThreshold) {
throw new Error('tickInterval must be > 0 and <= warnThreshold');
}
if (!Number.isFinite(this.warnThreshold) || this.warnThreshold <= 0) {
throw new Error('warnThreshold must be finite and > 0');
}
if (!Number.isFinite(this.errorThreshold) || this.errorThreshold < this.warnThreshold) {
throw new Error('errorThreshold must be finite and >= warnThreshold');
}
if (
!Number.isFinite(this.tickInterval) ||
this.tickInterval <= 0 ||
this.tickInterval > this.warnThreshold
) {
throw new Error('tickInterval must be finite, > 0, and <= warnThreshold');
}
Devin Review

Was this helpful? React with 👍 or 👎 to provide feedback.

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

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

0 participants