feat(telemetry): flag synchronous code blocking the event loop - #2459
feat(telemetry): flag synchronous code blocking the event loop#2459rosetta-livekit-bot[bot] wants to merge 1 commit into
Conversation
🦋 Changeset detectedLatest commit: 8ed7421 The changes in this PR will be included in the next version bump. This PR includes changesets to release 38 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 |
There was a problem hiding this comment.
Devin Review found 2 potential issues.
2 flags not posted on this PR by your GitHub settings — view them in Devin Review. (Configure)
| 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'; |
There was a problem hiding this comment.
🟡 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.
Was this helpful? React with 👍 or 👎 to provide feedback.
| 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'); | ||
| } |
There was a problem hiding this comment.
🟡 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.
| 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'); | |
| } |
Was this helpful? React with 👍 or 👎 to provide feedback.
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_blockedspans,lk.agents.event_loop.blocked_durationhistogram measurements, and per-session stall events/summaries.LIVEKIT_AGENTS_LOOP_BLOCK_WARN_MS=0disables monitoring; warning and error thresholds otherwise default to 100 ms and 500 ms.How
telemetry.loopMonitorand 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 buildpnpm --filter @livekit/agents buildpnpm lintpnpm format:checkpnpm typecheckpnpm throws:checkpnpm --filter @livekit/agents api:checkSource diff coverage
livekit-agents/livekit/agents/cli/cli.py->agents/src/worker.ts. JSAgentServerowns the worker loop for CLI and programmatic use, so it starts/stops the no-span worker monitor there.livekit-agents/livekit/agents/ipc/job_proc_lazy_main.py->agents/src/ipc/job_proc_lazy_main.ts. Captures activejob_entrypointOTel and job contexts for reports.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-styleproc_client, so monitor lifecycle belongs in the child bootstrap.livekit-agents/livekit/agents/telemetry/__init__.py->agents/src/telemetry/index.ts, exposingtelemetry.loopMonitor.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.livekit-agents/livekit/agents/telemetry/otel_metrics.py->agents/src/telemetry/otel_metrics.ts, plusagents/src/telemetry/traces.ts,agents/src/telemetry/upload_gate.ts,agents/package.json, andpnpm-lock.yaml. Adds the metrics SDK/exporter infrastructure absent from the target.livekit-agents/livekit/agents/telemetry/session_context.py->agents/src/telemetry/session_context.ts, using JSAsyncLocalStorage,JobContext._primaryAgentSession, androotSpanContext.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.livekit-agents/livekit/agents/voice/agent_session.py->agents/src/voice/agent_session.ts, adding per-session events and count/total/max attributes.livekit-agents/pyproject.toml. ItslivekitPython SDK pin enables Python RPC interception; JS already has its own RPC tracing path and no corresponding dependency.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.tests/test_trace_types_pii.py->agents/src/telemetry/trace_types.test.ts, classifying every new attribute as non-PII.uv.lock->pnpm-lock.yamlonly for target-native OTel metrics dependencies. Python wheel and version-marker changes are not applicable..changeset/slow-loops-report.mdandagents/etc/agents.api.mdare 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.sleepinon_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:
call_laterevery 20 ms (a fifth of the warn threshold, bounded to 20–50 ms); a block shows up as a late tick (resolution: one interval);sys._current_frames()once the gap crosses the warn threshold, and again at 10x, so the report says where the loop was stuck;event_loop_blockedspan withlk.blocking.{duration,threshold,severity,task,stack,gc_time,cpu_time}, sets statusERRORpast the error threshold, logs a rate-limited warning with the innermost location, and recordslk.agents.event_loop.blocked_duration.Details:
gc.callbacksso a gen-2 pause is not blamed on user code; loop-thread CPU time separates busy work from blocking waits.lk.blocking.suppressed.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.event_loop_blockedhistogram 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_*_MSrejects NaN and infinity like any other garbage value (falls back to the default).job_entrypointspan, so they carry job attribution. A stall during a session is a child ofagent_session(resolved through the job, since the heartbeat's own context predates the session) and the session span gets anevent_loop_blockedevent pluslk.blocking.count/total_duration/max_duration; a stall before or after the session is a child ofjob_entrypointat its real time. Without a job (the worker process) there is no trace to belong to: log and metric only.lk.blocking.count/total_duration/max_duration, oneevent_loop_blockedevent per stall) is updated for every stall, like the histogram, before the span (30/min) and log (5/min) rate limits apply.Task.get_context(), Python 3.12+), so atime.sleepin an RPC handler shows underrpc_handler, a slow tool underfunction_tool, a slow hook underon_user_turn_completed. Older interpreters, and stalls with no sample, fall back toagent_session.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_MSoverride;WARN_MS=0disables.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 mstime.sleepyields one back-dated error span whose stack names the blocking function andtime.sleep, with low CPU time; a 70 ms block is a warning with status UNSET; an idle loop, executor /to_threadwork, 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 togc_time; worker mode logs without spans;set_report_contextparents 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
Stacked on #7127.
🤖 Generated with Claude Code
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.