feat(telemetry): request, stage, and delivery metrics with a local Collector (#340)

[Zheng-Lu]

Summary

Phase 3 of #279. Closes #340.

Rebuilt on main at 5473e02 (2026-10-09), then rebased on 2026-10-12 onto 079a9a3 (#432, #379). main reorganized most of the code this PR instruments: #384, #386, #407, #410 and #423 changed the inference loop, multi-agent execution, the WebSocket path and client delivery. So each hook was re-applied at its current owner rather than merged textually, and the paths that did not exist before are now covered too. See "Changes in the rebuild" below.

The rebase onto 079a9a3 needed two small changes. #432 wraps persist_if_needed in Box::pin at the two call sites where this PR passes &exec_ctx.metrics; both are kept. engine/multi_agent_tests.rs gets a file-size exception (limit 501) for this PR's two-line metrics module declaration, because #432 brought the file to 499 lines; the tests themselves live in multi_agent_tests/metrics.rs.

This adds operational metrics that stay correct without trace sampling, a backend-neutral local Collector setup, and measured overhead. All instruments are typed in agentic-server-core and are recorded by the same ExecutionSpan guard that already finalizes agentic.execute. They therefore share its exactly-once terminal paths: completion, in-band upstream failure, disconnect, and shutdown. They are also independent of the sampling decision.

Instrument	Type	Attributes
agentic.execution.count, agentic.execution.duration	counter, histogram (s)	agentic.api, agentic.route, agentic.stream, agentic.execution.outcome, error.type on failure
agentic.execution.active	up-down counter	agentic.api, agentic.route, agentic.stream
agentic.delivery.count	counter	agentic.api, agentic.route, agentic.stream, agentic.delivery.outcome
agentic.delivery.wait.duration	histogram (s)	agentic.api
agentic.stage.duration	histogram (s)	agentic.stage (rehydrate, inference, tool, compaction, persist), agentic.tool.type on tool samples, error.type
agentic.inference.rounds	histogram	agentic.api
gen_ai.client.token.usage	histogram	gen_ai.operation.name=chat, gen_ai.token.type, agentic.api
agentic.time_to_first_upstream_data, agentic.time_to_first_client_event, agentic.time_to_first_text	histogram (s)	agentic.api
agentic.websocket.connections.active	up-down counter	none
agentic.websocket.queue.wait.duration	histogram (s)	none

• ExecutorMetrics lives on ExecutionContext. It defaults to the global meter provider, and embedding applications pass their own with ExecutionContext::with_metrics. Without a provider every instrument is a no-op.
• Token usage is recorded once per upstream call from that call's own usage, including compaction summaries. Nothing is recorded when the upstream omits usage or a count, so no zeros are fabricated. For Messages, prompt tokens include cache reads and writes.
• The three first-data timings share an ExecutionClock measured from when the execution was accepted:
  • first upstream data: marked at the pipeline entry;
  • first client event and first text: marked where the client-facing stream yields to the transport.
• Multi-agent responses: each round runs on its own pipeline, which shares the execution's clock, and the response records one agentic.inference.rounds sample counting every agent's rounds.
• Retained (WebSocket) responses mark first client event and first text in the event stream that ResponseEventSink::stream returns, and measure delivery wait there.
• Local Collector: deploy/otel/docker-compose.yaml runs digest-pinned collector-contrib 0.161.0 with an OTLP/HTTP receiver, memory_limiter, batch, the debug exporter, and a Prometheus endpoint carrying service.name. --env-file deploy/otel/jaeger.env adds Jaeger 2.21.0. All ports bind to 127.0.0.1.
• scripts/tests/otel-smoke.sh sends streamed, blocking, proxied, and WebSocket requests through a scripted upstream. It stops the gateway so it flushes, then checks the Collector's debug output and Prometheus endpoint. The rust CI job now runs the smoke test and the checker's unit tests.
• Docs: docs/deploying/observability.md covers every instrument, attribute value, recording rule, timing anchor, histogram boundary, the cardinality contract, the local Collector, and the overhead table. ARCHITECTURE.md records which pipeline stage owns each telemetry mark, so the refactor: unify synchronous streaming ingestion and item lifecycle #243/refactor: extract StreamRelay and bound client delivery #244 refactors move marks instead of duplicating them.

Defaults restated from the #279 design table

These got no reply on #279, so this PR uses the proposed defaults:

• OTLP over HTTP/protobuf only.
• agentic.* namespace for project-specific metric and attribute names.
• No model label on metrics (see departures below).
• Cumulative temporality.
• Histogram boundaries as proposed, except delivery wait (see departures).

Design departures from the #279 plan

1. First text is marked where the client-facing stream yields, not at ingestion. Ingestion can run ahead of delivery by the bounded channel's capacity, so an ingestion-time mark can come before the first client event. Marking both at the same point guarantees first_upstream_data ≤ first_client_event ≤ first_text for a text response. It also measures what a client sees. Ingestion still owns the classification: StreamEvent carries a typed text flag set from SSEEventType::OutputTextDelta.
2. Delivery wait is one sum per streamed execution, not a sample per blocked send. InstrumentedStream measures the time between handing a frame to the transport and the transport polling for the next one. That covers HTTP and WebSocket at one boundary with one sample per execution. Boundaries therefore extend to 60 s. A WebSocket response finalizes on its own task, so frames the connection takes after that are not included.
3. No gen_ai.request.model, gen_ai.response.model, or gen_ai.provider.name. Per-request-model labels are a feat: request, stage, and delivery metrics with a local Collector example (#279 phase 3) #340 non-goal. The gateway cannot know which provider serves its upstream, so it records no provider name rather than a guessed one. This deviates from the semantic convention's required provider attribute, and the docs say so.
4. Gateway-executed built-in tools in the Messages loop are not timed. They have no stage span yet either (phase 2 traced only the Responses scheduler). The tool stage covers Responses gateway calls, one sample per tool call.
5. First-data timings cover streamed executor responses only. Blocking requests and the raw proxy have no client-visible first event.
6. A WebSocket execution starts at admission, matching its span. agentic.execution.active includes requests queued behind another on the same stream, and duration includes queue wait. agentic.websocket.queue.wait.duration isolates the wait.

Changes in the rebuild

• The inference stage timer and per-round usage now sit in AgentTurn::run_round, which both single-agent and multi-agent rounds use. The file moves the original PR made for size (engine/round.rs, gateway/input.rs, compaction/explicit.rs) are gone.
• The round count lives on SingleAgentRun and MultiAgentRun, one per execution. MultiAgentRun passes the execution clock to every round's pipeline.
• retained.rs gives the root pipeline the clock and wraps its event stream for delivery timing. persist_if_needed takes the metrics on all four call sites, including the retained one.
• The tool timer wraps GatewayScheduler::run_one, the same scope as its agentic.tool.execute span. Calls refused by max_tool_calls never run, so they are not timed. The two timing methods live in gateway/timing.rs to keep gateway.rs under the size limit.
• execute_and_emit_output_calls takes &ExecutionContext instead of a policy and the metrics (clippy::too_many_arguments).
• StreamFrame carries the typed text flag on both frame paths (HTTP and retained).
• messages_stream.rs: open_round replaces prime_messages_stream and the later-round branch, as before. MessagesStreamAccumulator gains a fourth flag, so it takes #[allow(clippy::struct_excessive_bools)] like the other such structs in the repository.
• The inner rehydrate future is boxed so the timing wrapper doesn't hold RequestPayload twice (clippy::large_futures).
• No size-policy baselines change. The rebase adds one exception, for engine/multi_agent_tests.rs (see the top).
• Public API change: ExecutionSpan::start and start_linked take &ExecutorMetrics.

Test Plan

cargo fmt -- --check
cargo clippy --workspace --all-targets -- -D warnings
cargo test --workspace --no-fail-fast        # 2341 passed, 0 failed, 18 ignored
uvx pre-commit run --all-files                # all hooks pass
docker compose -f deploy/otel/docker-compose.yaml up -d && scripts/tests/otel-smoke.sh
python3 -m unittest discover -s scripts/tests -p test_otel_fixtures.py
uvx --with-requirements docs/requirements.txt mkdocs build --strict

web_fetch::http::tests::the_deadline_bounds_a_slow_origin is timing-sensitive and fails intermittently on unmodified main under the full suite; after the rebase it failed in one of two full-suite runs and passes on its own. This PR doesn't touch web_fetch. Clippy also passes with --features embedded-code-interpreter for both crates, as in CI.

New tests. Every test builds its own in-memory meter provider, so they run in parallel. Every assertion passes through a shared allow-list, crates/agentic-server-core/tests/execution_metrics/harness.rs, which fails on any instrument, attribute key, or attribute value that isn't listed.

• agentic-server-core/tests/execution_metrics_test.rs (11 tests, no tracing subscriber installed):
  • Each terminal path counts exactly one execution and releases its active count, for Responses and Messages. The paths are:
    • blocking completion;
    • an in-band SSE failure under HTTP 200;
    • a failure before delivery;
    • a dropped stream;
    • a Messages rejection before headers.
  • A recorded text cassette (text_only/responses/resp-single-gpt-4o-streaming.yaml):
    • proves first_upstream_data ≤ first_client_event ≤ first_text;
    • reports the cassette's exact usage (14 in, 4 out);
    • records no token sample for usage: null.
  • The two-round web-search cassette records two rounds, two inference stages, one web_search tool stage, and one usage sample per upstream call.
  • Messages records prompt tokens including cache reads, and orders its three timings too.
  • Explicit /v1/responses/compact times rehydrate, compaction, and persist, and records usage, but no execution.
  • The allow-list rejects unlisted instruments, keys, and values.
• agentic-server/tests/execution_metrics_test.rs (4 tests, production router):
  • HTTP completed, in-band failure, blocking, proxied, and client disconnect: 5 executions, active back to 0.
  • Three response.create plus one failure on one WebSocket gives 4 executions, 4 queue-wait samples, and connections.active = 1 while open, 0 after close.
  • A WebSocket disconnect cancels both the active and the queued request exactly once.
  • Drain cancels the queued request once and lets the active one finish.
• agentic-server/tests/telemetry_metrics_e2e_test.rs runs the real binary, configured only through OTEL_*, with OTEL_TRACES_SAMPLER=parentbased_traceidratio and OTEL_TRACES_SAMPLER_ARG=0, exporting to an in-process OTLP stub. It sends HTTP and WebSocket requests, then SIGTERMs the gateway with one HTTP stream and one WebSocket request still in flight:
  • 0 spans exported;
  • all 15 instruments present, with service.name;
  • 6 executions: 4 completed and 2 cancelled;
  • active back to 0 and connections.active back to 0.
• Added in the rebuild:
  • multi_agent_execution_records_rounds_and_first_data_once (core unit test). A streamed multi-agent response, a root and two children, records one rounds sample. Its sum equals the number of inference stages across all agents, and first upstream data is recorded once.
  • The WebSocket test also checks first upstream data and first text once per completed response, and first client event for all four. Those come from the retained path.
• The mock upstreams and the smoke fixture give each response fresh item IDs, as a real upstream does. Stored history keys rows by item ID, so a repeated ID can't be stored twice (Resubmitting stored output items with store: true fails with 500 after #370 #385).
• scripts/tests/test_otel_fixtures.py (10 tests): the Collector-log checker reads the allow-list from the Rust harness and rejects unlisted keys, values, and instruments.
• The two new Rust test binaries ran 8 times in a row with no failures.

Mutation checks. For the code the rebuild re-placed, each new check fails when its wiring is removed:

Removed	Result
The clock on multi-agent round pipelines	the multi-agent test fails: first upstream data recorded 0 times, expected 1
Counting multi-agent rounds	the multi-agent test fails: no rounds sample
The retained path's clock (pipeline and event stream)	the WebSocket test fails: first upstream data recorded 0 times, expected 3

The original branch (9a9b052) had these checks. The tests behind them pass unchanged on the rebuild, but I did not repeat the mutations:

Mutation	Result
ExecutionSpan drop never records execution metrics	core: 9 of 10 fail (only the pure allow-list test passes)
Execution metrics recorded twice on drop	core: 9 of 10 fail; server: 4 of 4 fail
Pipeline never marks first upstream data	core: the Responses timing-order test fails
Missing upstream usage recorded as zero (unwrap_or_default)	core: fails with "the upstream sent usage: null; nothing is fabricated"
WebSocket guard never releases connections.active	server: both tests that wait for the connection to close fail
Control: e2e with OTEL_TRACES_SAMPLER_ARG=1	fails with 34 spans exported, so the 0-span assertion is not vacuous

Local Collector. scripts/tests/otel-smoke.sh passes against the compose stack after the rebase, on five cold Collector starts and a warm rerun: all 15 instruments and 29 data points are allow-listed, with the run's service.name. The very first run, which also created the Docker network, reported no metrics even though the Collector logged them a moment later; this did not reproduce. I did not rerun the Jaeger variant after the rebuild. This machine only has docker-compose v1, so the script falls back to it locally. CI runs docker compose v2.

Overhead

Measured on the 2026-10-09 rebuild and not re-measured after the rebase, which changed no instrumented code.

scripts/otel-overhead.py, release builds. Setup:

• SQLite storage, so every request is rehydrated, executed, and persisted.
• In-process scripted upstream.
• 2,000 sequential requests per scenario per round after 200 warm-up requests.
• 3 rounds alternating the two modes.
• Enabled traces every request (parentbased_always_on) and exports traces and metrics over OTLP/HTTP to the local Collector.
• Host: i9-13980HX, Linux 6.6 (WSL2).

Measured again after the rebuild, two runs per build in the same session (second run shown). This branch:

Scenario	Telemetry	p50 (ms)	p90 (ms)	p99 (ms)	Gateway CPU / request (ms)	Peak RSS (MiB)
Streaming	disabled	0.96	1.18	13.03	0.86	31.5
Streaming	enabled	1.08	1.34	13.39	1.06	36.2
Non-streaming	disabled	0.87	1.11	12.52	0.76	31.5
Non-streaming	enabled	0.97	1.18	12.76	0.90	36.2

main at 5473e02 (traces, no metrics), same benchmark:

Scenario	Telemetry	p50 (ms)	p90 (ms)	p99 (ms)	Gateway CPU / request (ms)	Peak RSS (MiB)
Streaming	disabled	0.90	1.10	12.45	0.80	31.5
Streaming	enabled	1.00	1.24	12.81	0.94	36.5
Non-streaming	disabled	0.81	1.00	12.17	0.71	31.5
Non-streaming	enabled	0.96	1.21	12.75	0.89	36.5

• Enabling telemetry on this branch added 0.04–0.13 ms at p50, 0.07–0.20 ms of gateway CPU per request, and about 5 MiB of peak RSS.
• Against main, this branch measured 0.01–0.13 ms higher at p50 and 0.01–0.14 ms more CPU per request, with telemetry enabled or disabled.
• Run-to-run variation for one build was up to 0.1 ms at p50, so each difference is within that variation. But every one pointed the same way, so the docs no longer say "no measurable cost". They say the metrics cost at most about 0.1 ms per request at this scale.

Known gaps and follow-ups

• Messages gateway tool timing (departure 4).
• Documented MSRV 1.85 does not build: Cargo.lock requires Rust 1.86–1.88 #377: fix: declare Rust 1.88 as the MSRV and check it in CI (#377) #379 merged and set the MSRV to Rust 1.98.1. This branch is rebased onto it and passes clippy at msrv = "1.98.1".