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

[davidzhao]

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 10 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 10 ms, well under 0.1% of a core.

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

[theomonnom]

Can this detect deadlock? or only short blocking code?

Since deadlock never reports back

[davidzhao]

this is only blocking code. deadlocks will require something more invasive.

IMO deadlocks are more likely in framework code. this is to flag blocking code in user's logic

[theomonnom]

Some customers were running HTTP requests using the requests library. Depending on the timeout, the job process was just getting killed by the worker.

[davidzhao]

do you mean sync http requests? I think those should be flagged with this change pretty easily (since not all of them will hit unresponsive servers).

perhaps when we kill the process, we should log all of the pending frames.. that'll help flag deadlocks

[theomonnom]

Fwiw if the goal is to detect blocking code and not deadlock. asyncio already has a slow code callback

[theomonnom]

I'm wondering if there's something to do with py3.14:

Python 3.14 adds external introspection (python -m asyncio ps PID and pstree), useful for a support engineer poking at a live process, not for automatic detection.

[chenghao-mou]

I notice that all the comments are unnecessarily verbose. It might be worth simplifying them before merging.

[chenghao-mou]

lgtm. One thing I noticed during test:

it constantly reports prewarm stall during start up (4/4):

2026-09-08 10:54:17,418 - WARNING livekit.agents - event loop blocked for 313ms at "<frozen importlib._bootstrap_external>", line 953, in get_data; synchronous work on the agent loop delays audio and turn handling, move it to a thread or an async client {"duration": 0.3127, "threshold": 0.1, "gc_time": 0.0209, "cpu_time": 0.2034, "task": "Task-2", "stack": "# loop thread sampled 102ms into the stall\n  File \"/Users/chenghao/.t3/worktrees/agents/t3code-068f45de/livekit-agents/livekit/agents/llm/llm.py\", line 196, in _prewarm\n    await self._prewarm_impl()\n  File \"/Users/chenghao/.t3/worktrees/agents/t3code-068f45de/livekit-agents/livekit/agents/inference/llm.py\", line 285, in _prewarm_impl\n    await self._client.models.list()\n  File \"/Users/chenghao/.local/share/uv/python/cpython-3.14.0-macos-aarch64-none/lib/python3.14/functools.py\", line 1127, in __get__\n    val = self.func(instance)\n  File \"/Users/chenghao/.t3/worktrees/agents/t3code-068f45de/.venv/lib/python3.14/site-packages/openai/_client.py\", line 954, in models\n    from .resources.models import AsyncModels\n  [import system: 8 frames]\n  File \"<frozen importlib._bootstrap_external>\", line 953, in get_data", "room": "console-e970511d", "pid": 65452, "job_id": "AJ_VGLVEcS7qzAt"}

and sometimes the eot init (1/4):

10:49:04 WARNING livekit.agents event loop blocked for 103ms at "/Users/chenghao/.t3/worktrees/agents/t3code-068f45de/livekit-agents/livekit/agents/inference/eot/transports.py", line 392, in __init__; synchronous work on the agent loop delays audio and turn handling, move it to a thread or an async client {"duration": 0.1028, "threshold": 0.1, "gc_time": 0.0003, "cpu_time": 0.0608, "task": "Task-20", "stack": "# loop thread sampled 92ms into the stall\n  File \"/Users/chenghao/.t3/worktrees/agents/t3code-068f45de/livekit-agents/livekit/agents/utils/log.py\", line 17, in async_fn_logs\n    return await fn(*args, **kwargs)\n  File \"/Users/chenghao/.t3/worktrees/agents/t3code-068f45de/livekit-agents/livekit/agents/voice/agent_session.py\", line 1819, in _update_activity_task\n    await self._update_activity(agent, wait_on_enter=False)\n  File \"/Users/chenghao/.t3/worktrees/agents/t3code-068f45de/livekit-agents/livekit/agents/voice/agent_session.py\", line 1799, in _update_activity\n    await self._activity.start(reuse_resources=reuse_resources)\n  File \"/Users/chenghao/.t3/worktrees/agents/t3code-068f45de/livekit-agents/livekit/agents/voice/agent_activity.py\", line 896, in start\n    await self._start_session(reuse_resources=reuse_resources)\n  File \"/Users/chenghao/.t3/worktrees/agents/t3code-068f45de/livekit-agents/livekit/agents/voice/agent_activity.py\", line 1183, in _start_session\n    self._audio_recognition._start(\n  File \"/Users/chenghao/.t3/worktrees/agents/t3code-068f45de/livekit-agents/livekit/agents/voice/audio_recognition.py\", line 408, in _start\n    self._update_turn_detector(self._turn_detector, stream=turn_detector_stream)\n  File \"/Users/chenghao/.t3/worktrees/agents/t3code-068f45de/livekit-agents/livekit/agents/voice/audio_recognition.py\", line 968, in _update_turn_detector\n    stream = detector.stream() if isinstance(detector, _StreamingTurnDetector) else None\n  File \"/Users/chenghao/.t3/worktrees/agents/t3code-068f45de/livekit-agents/livekit/agents/inference/eot/detector.py\", line 201, in stream\n    transport = _LocalTransport(opts=self._opts)\n  File \"/Users/chenghao/.t3/worktrees/agents/t3code-068f45de/livekit-agents/livekit/agents/inference/eot/transports.py\", line 392, in __init__\n    self._eot = _EOT()", "room": "console"}

maybe we can ignore certain internal calls with a different PR.