Add per-operation timing instrumentation for historically slow/deadlocked operations

[all-hands-bot]

Problem

Recent perf/deadlock regressions in the agent server were each caught by direct code review or a production incident rather than by an automated signal that says "this operation is taking too long / is stuck." For the operations that have historically wedged or slowed down, we have no per-operation timing that would let us (a) alert when one degrades, or (b) distinguish "slow" from "deadlocked."

We already emit coarse, privacy-bucketed conversation telemetry (see openhands-agent-server/openhands/agent_server/telemetry/), but it only captures whole-conversation duration_bucket and has no per-operation latency, so it cannot produce p50/p95 for the hot paths below.

Desired Behavior

Add per-operation timing instrumentation to the agent-server/SDK hot paths with a numeric latency property that can be percentiled (p50/p95/p99) in PostHog and, ideally, also emitted as OpenTelemetry/OpenInference spans. Timing should be recorded as wall-clock duration, and a "still in-flight / stuck" signal (or an explicit timeout) should be emitted so a deadlock is distinguishable from a merely slow operation.

Note: this is a deliberate change from the current bucketized/privacy-constrained telemetry policy (models.py / sanitizer.py), so it needs an explicit decision on how raw numeric durations are allowed through the allowlist without reintroducing a re-identification vector. Reuse the existing telemetry subscriber/sink plumbing rather than adding a parallel path.

Acceptance Criteria

Each operation below has previously been shown to deadlock or be very slow. Instrumentation must cover all of them, with a named latency metric per operation, and each historical failure must be reproducible as a failed/budget-exceeded threshold against a cheap fake-LLM or controlled-delay harness.

• Conversation lifecycle create/delete/close — global _lifecycle_lock wedge (Lifecycle lock deadlock: thread-pool exhaustion blocks all event loading #4514, fixed by fix(agent-server): replace global _lifecycle_lock with per-conversation locks #4570, tracked in perf: replace global _lifecycle_lock with per-conversation locks to eliminate cross-conversation wedges #4569). Emit conversation_create, conversation_delete, and conversation_close latencies; a blocked create/close on one conversation must be visible (slow + no completion) without blocking measurement site.

• Event service load / runtime hydration — _get_or_load_event_service / _prepare_persisted_runtime disk I/O + runtime prep under the lifecycle lock (Lifecycle lock deadlock: thread-pool exhaustion blocks all event loading #4514, test(agent-server): lifecycle lock deadlocks on thread-pool exhaustion #4513, fix(sdk): bound AsyncExecutor.close() so it cannot hang forever #4548). Emit event_service_load latency and a "blocked waiting for lifecycle lock" signal.

• Event search / bash event listing — event loop blocked by glob over an unbounded bash_events dir and scandir hot path ([Bug]: agent-server blocks event loop globbing unbounded bash_events dir; starves conversations/search #4480, fixed by fix(agent-server): move bash event search off event loop and replace glob with scandir #4481). Emit event_search / bash_event_search latency incl. events-read count and directory fanout.

• ConversationInfo composition — GC wedge composing ConversationInfo off the event loop (fix(agent-server): compose ConversationInfo off the event loop to avoid GC wedge #4417). Emit conversation_info_compose latency.

• LLM call concurrency / global config serialization — LLM requests unintentionally serialized through global config (fix(llm): stop serializing calls through global config #4473, Global threading.Lock serializes LLM calls across all conversations — wastes local model compute OpenHands#16459). Emit per-LLM llm_call latency, queue/acquire time, and a concurrency count; the overlap (not serial) ratio must be measurable.

• switch_llm on the state lock — run-loop-held state lock deadlock (switch_llm deadlocks the conversation runtime (regression in v1.23.0, async LLM completion #3284) #3485, fixed by fix(sdk): avoid switch_llm deadlock when the run loop holds the state lock #3486). Emit switch_llm latency incl. state-lock wait time.

• stats_callback state-lock re-acquisition / stats streaming — ACP conversations hanging after prompt() on the state lock (ACP conversations hang silently after prompt() returns — stats_callback deadlock on the state lock #3348, fixed by fix(agent-server): remove redundant with state: from stats_callback (deadlock) #3349). Emit stats_streaming latency and state-lock wait time.

• subscribe_to_events initial-state push — wedged WS subscriber blocking registration (agent-server: subscribe_to_events deadlocks on a wedged WS subscriber #3118, fixed by fix(agent-server): bound initial-state push in subscribe_to_events #3201). Emit subscribe_init_push latency (or timeout) and subscriber drain latency.

• ACP restart loopback secret lookup — async ACP restart loopback secret lookup deadlock (Fix async ACP restart loopback secret lookup deadlock #3737). Emit acp_restart_secret_lookup latency.

• Model-info discovery / LLM construction probe — synchronous timeout-less model-info discovery hanging on unreachable/loopback endpoints (fix(llm): bound model-info discovery with a timeout to prevent deadlocks #3912). Emit model_info_discovery latency (bounded) and report timeout as a distinct terminal value.

• Conversation summary caching — unchanged summary recomputation (perf(agent-server): cache unchanged conversation summaries #4483). Emit summary_render latency with a cache-hit vs cache-miss dimension.

• Idle conversation eviction — idle conversation memory eviction (perf(agent-server): evict idle conversations from memory after a configurable TTL #4202). Emit conversation_evict latency and count.

• Lease renewal / autosave / pub/sub dispatch / condensation — historical perf work (perf: centralize lease renewal into one background task #3168 lease renewal centralization, perf: batch ConversationState autosaves inside context manager #3165 autosave batching, perf: dispatch PubSub notifications concurrently #3162 concurrent pub/sub, perf: change Condensation.forgotten_event_ids from list to set #3156 condensation forgotten-id set, perf: bound InMemoryFileStore with LRU eviction #3163 file-store LRU, perf: dedicated thread pool for conversation execution #3169 dedicated execution thread pool). Provide latency/count metrics for each so a regression that reintroduces serialization or O(N²) behavior is detectable.

• Latency totals/metrics are emitted as raw numeric durations (or p50/p95-friendly values) suitable for PostHog percentile aggregation, with the privacy trade-off documented and allowlisted explicitly.

• A "stuck"/timeout dimension is emitted so a deadlock (no completion) is distinguishable from a slow operation, rather than both looking identical in a latency histogram.

• Instrumentation lives behind the existing telemetry consent/kill-switch path (telemetry/policy.py) and is cheap enough (constant overhead) not to perturb the measured operations.

• Each historical case has a corresponding failing threshold in the pre-release load-test gate (see Add pre-release load tests as a blocking release gate #4588) — i.e. the new metrics, not ad-hoc timing, are the assertion source where practical.

• Coverage of the operations above is verified by a test that forces each slow/deadlock scenario and asserts the metric is emitted with the expected terminal value (not just a happy-path duration).

References

• Deadlock/perf issues: Lifecycle lock deadlock: thread-pool exhaustion blocks all event loading #4514, perf: replace global _lifecycle_lock with per-conversation locks to eliminate cross-conversation wedges #4569, fix(agent-server): replace global _lifecycle_lock with per-conversation locks #4570, test(agent-server): lifecycle lock deadlocks on thread-pool exhaustion #4513, fix(sdk): bound AsyncExecutor.close() so it cannot hang forever #4548, [Bug]: agent-server blocks event loop globbing unbounded bash_events dir; starves conversations/search #4480, fix(agent-server): move bash event search off event loop and replace glob with scandir #4481, fix(agent-server): compose ConversationInfo off the event loop to avoid GC wedge #4417, fix(llm): stop serializing calls through global config #4473, switch_llm deadlocks the conversation runtime (regression in v1.23.0, async LLM completion #3284) #3485, fix(sdk): avoid switch_llm deadlock when the run loop holds the state lock #3486, ACP conversations hang silently after prompt() returns — stats_callback deadlock on the state lock #3348, fix(agent-server): remove redundant with state: from stats_callback (deadlock) #3349, agent-server: subscribe_to_events deadlocks on a wedged WS subscriber #3118, fix(agent-server): bound initial-state push in subscribe_to_events #3201, Fix async ACP restart loopback secret lookup deadlock #3737, fix(llm): bound model-info discovery with a timeout to prevent deadlocks #3912, perf(agent-server): cache unchanged conversation summaries #4483, perf(agent-server): evict idle conversations from memory after a configurable TTL #4202, perf: centralize lease renewal into one background task #3168, perf: batch ConversationState autosaves inside context manager #3165, perf: dispatch PubSub notifications concurrently #3162, perf: change Condensation.forgotten_event_ids from list to set #3156, perf: bound InMemoryFileStore with LRU eviction #3163, perf: dedicated thread pool for conversation execution #3169
• Existing telemetry plumbing: openhands-agent-server/openhands/agent_server/telemetry/ (models.py, sanitizer.py, subscriber.py, posthog_exporter.py, policy.py)
• Companion load-test gate: Add pre-release load tests as a blocking release gate #4588

This issue was created by an AI agent (OpenHands) on behalf of the requester.

[github-actions]

✅ ready-for-dev label applied

This issue meets the readiness criteria and is ready for contribution.
A contributor can now open a PR that links this issue (Fixes #<number>).

This is an automated check — no AI was used to generate this comment.

[jdlake]

Please can the following elements of this issue be placed in another issue?

• event_search / bash_event_search — sync executor scans; needs a sync-timer variant plus a decision on the count/fan-out magnitude (raw counts are re-identifying).
• llm_call / switch_llm config serialization — the SDK LLM has no telemetry tap today; needs a cross-package sink hook and a contention/lock-wait timer (wire time =/= lock-wait time).
• Lease renewal / autosave / pub/sub / condensation — background loops and cross-module fan-out; needs a defined per-iteration operation boundary and the same cross-package hook.

My PR addresses all others.

If you'd prefer me to update the PR with these addressed, and iron them out, let me know.