From 05ee20dfa039bfa0b1cdea06566720e7458da509 Mon Sep 17 00:00:00 2001 From: Zheng Lu Date: Fri, 9 Oct 2026 15:29:14 +0100 Subject: [PATCH 1/4] feat(telemetry): record execution, stage, token, and timing metrics Phase 3 of #279 (#340). The ExecutionSpan guard now records the execution metrics from Drop, on the same paths that finalize the agentic.execute span, so every execution is counted exactly once and metrics do not depend on trace sampling. - ExecutorMetrics, on ExecutionContext (with_metrics for embedders), owns every instrument: execution count, duration and active executions; delivery outcome and wait; stage durations; inference rounds per execution; and per-call token usage. - ExecutionClock records first upstream data, first client event, and first output text. The pipeline marks upstream data; the client-facing stream marks client events and measures delivery wait through InstrumentedStream. - Stage timers wrap rehydration, each inference round, each executed gateway call, compaction summaries, and persistence, including explicit compaction persistence. - Retained (WebSocket) responses take the same timings in their event stream. A multi-agent response records one rounds sample covering every agent, and each round's pipeline shares the execution clock. - The Messages loop and stream record rounds, inference stages, and per-round token usage. - The server records WebSocket connections and queue wait. Signed-off-by: Zheng Lu --- .../src/executor/compaction.rs | 25 +- .../src/executor/engine.rs | 15 +- .../src/executor/engine/agent_turn.rs | 30 +- .../src/executor/engine/execute.rs | 14 +- .../src/executor/engine/multi_agent.rs | 10 + .../src/executor/engine/multi_agent/rounds.rs | 4 + .../src/executor/engine/retained.rs | 13 +- .../src/executor/engine/streaming.rs | 31 +- .../engine/streaming/producer/tests.rs | 1 + .../src/executor/gateway.rs | 28 +- .../src/executor/gateway/timing.rs | 41 ++ .../src/executor/gateway_accumulator.rs | 3 + .../src/executor/messages_loop.rs | 22 +- .../src/executor/messages_stream.rs | 140 ++--- .../src/executor/messages_stream/ingestion.rs | 2 + .../src/executor/messages_usage.rs | 12 + .../src/executor/persist.rs | 27 +- .../src/executor/pipeline.rs | 19 +- .../src/executor/rehydrate.rs | 13 + .../src/executor/request.rs | 14 + .../src/executor/response_events.rs | 17 +- .../src/executor/telemetry.rs | 123 ++++- .../src/executor/telemetry/metrics.rs | 483 ++++++++++++++++++ crates/agentic-server/src/app.rs | 36 +- .../src/handler/http/messages.rs | 2 +- .../src/handler/http/responses.rs | 3 +- .../src/handler/websocket/responses.rs | 2 +- .../websocket/responses/multiplexer.rs | 2 +- .../handler/websocket/responses/telemetry.rs | 23 +- crates/agentic-server/src/telemetry/mod.rs | 1 + crates/agentic-server/src/telemetry/proxy.rs | 10 +- .../agentic-server/src/telemetry/websocket.rs | 67 +++ 32 files changed, 1086 insertions(+), 147 deletions(-) create mode 100644 crates/agentic-server-core/src/executor/gateway/timing.rs create mode 100644 crates/agentic-server-core/src/executor/telemetry/metrics.rs create mode 100644 crates/agentic-server/src/telemetry/websocket.rs diff --git a/crates/agentic-server-core/src/executor/compaction.rs b/crates/agentic-server-core/src/executor/compaction.rs index 8f189756..c715edd9 100644 --- a/crates/agentic-server-core/src/executor/compaction.rs +++ b/crates/agentic-server-core/src/executor/compaction.rs @@ -4,6 +4,8 @@ pub(crate) use estimate::{estimate_history_tokens, estimate_input_tokens}; mod context; mod summary; +use super::telemetry::FailureCategory; +use super::telemetry::metrics::Stage; use super::telemetry::stages::CompactionTrigger; use context::item_has_meaningful_context; use summary::completed_summary_text; @@ -122,6 +124,18 @@ async fn compact_items_with_trigger( exec_ctx: &ExecutionContext, auth: Option<&str>, trigger: CompactionTrigger, +) -> ExecutorResult<(Vec, ResponseUsage, Option)> { + let timer = exec_ctx.metrics.stage(Stage::Compaction); + let summarized = summarize_items(request, input, exec_ctx, auth).await; + timer.finish_result(&summarized); + summarized +} + +async fn summarize_items( + request: &RequestPayload, + input: ResponsesInput, + exec_ctx: &ExecutionContext, + auth: Option<&str>, ) -> ExecutorResult<(Vec, ResponseUsage, Option)> { let original_items = Vec::from(input); if !original_items.iter().any(item_has_meaningful_context) { @@ -167,6 +181,7 @@ async fn compact_items_with_trigger( let mut agent = AgentPipeline::new(ctx, None, StreamRelay::detached()); let response = fetch_blocking_payload(&mut agent, exec_ctx, auth, &crate::tool::ToolRegistry::default(), None).await?; + exec_ctx.metrics.record_response_usage(response.usage.as_ref()); let summary = completed_summary_text(&response)?; Ok(( @@ -293,6 +308,7 @@ pub async fn compact_response( let response_id = ctx.response_id.clone(); ctx.new_input_items.clone_from(&output); + let timer = exec_ctx.metrics.stage(Stage::Persist); match persist_prepared_turn( ctx, tool_search_metadata, @@ -303,8 +319,13 @@ pub async fn compact_response( ) .await { - Ok(()) | Err(ExecutorError::Storage(crate::StorageError::NotConfigured)) => {} - Err(error) => return Err(error), + Ok(()) => timer.finish(None), + // Without storage nothing was written, so there is no stage to time. + Err(ExecutorError::Storage(crate::StorageError::NotConfigured)) => timer.discard(), + Err(error) => { + timer.finish(Some(FailureCategory::from(&error))); + return Err(error); + } } Ok(CompactedResponse { diff --git a/crates/agentic-server-core/src/executor/engine.rs b/crates/agentic-server-core/src/executor/engine.rs index 3e48d50d..11c945ae 100644 --- a/crates/agentic-server-core/src/executor/engine.rs +++ b/crates/agentic-server-core/src/executor/engine.rs @@ -32,6 +32,8 @@ use crate::executor::request::{ExecutionContext, RequestContext}; use crate::executor::response_budget::ExecutorResponseBudget; #[cfg(test)] use crate::executor::response_budget::MAX_EXECUTOR_RESPONSE_BYTES; +use crate::executor::telemetry::Api; +use crate::executor::telemetry::metrics::RoundCounter; use crate::tool::{ToolSearchMetadata, ToolSearchState}; use crate::types::io::{InputItem, OutputItem, ResponseUsage, ResponsesInput}; #[cfg(test)] @@ -127,6 +129,7 @@ struct SingleAgentRun<'a> { response_budget: ExecutorResponseBudget, output: Vec, usage: Option, + rounds: RoundCounter, } impl<'a> SingleAgentRun<'a> { @@ -139,6 +142,7 @@ impl<'a> SingleAgentRun<'a> { response_budget, output, usage: None, + rounds: exec_ctx.metrics.rounds(Api::Responses), }) } @@ -148,6 +152,7 @@ impl<'a> SingleAgentRun<'a> { stream_upstream: bool, ) -> ExecutorResult<(ResponsePayload, Option)> { loop { + self.rounds.begin_round(); let RoundResult { mut payload, decision } = self .root .run_round(self.output.len(), auth, stream_upstream, &self.response_budget) @@ -249,7 +254,15 @@ async fn run_blocking( let ch = exec_ctx.conv_handler.clone(); let rh = exec_ctx.resp_handler.clone(); - Box::pin(persist_if_needed(payload.clone(), ctx, tool_search_metadata, ch, rh)).await?; + Box::pin(persist_if_needed( + payload.clone(), + ctx, + tool_search_metadata, + ch, + rh, + &exec_ctx.metrics, + )) + .await?; Ok(payload) } diff --git a/crates/agentic-server-core/src/executor/engine/agent_turn.rs b/crates/agentic-server-core/src/executor/engine/agent_turn.rs index 64f2ed7b..68405b27 100644 --- a/crates/agentic-server-core/src/executor/engine/agent_turn.rs +++ b/crates/agentic-server-core/src/executor/engine/agent_turn.rs @@ -23,6 +23,7 @@ use crate::executor::rehydrate::prepare_reasoning_for_vllm; use crate::executor::relay::Release; use crate::executor::request::{ExecutionContext, RequestContext}; use crate::executor::response_budget::ExecutorResponseBudget; +use crate::executor::telemetry::metrics::Stage; use crate::executor::upstream::{fetch_blocking_payload, fetch_stream_payload}; use crate::tool::{ToolRegistry, mcp, record_discovered_mcp_tools, responses_declarations}; use crate::types::io::{InputItem, OutputItem, ResponsesInput, ToolChoice}; @@ -287,8 +288,9 @@ impl<'a> AgentTurn<'a> { compaction_usage.is_some(), )?; let round_span = crate::executor::telemetry::stages::inference_round(round); - let mut payload = if stream_upstream { - let payload = fetch_stream_payload( + let timer = self.exec_ctx.metrics.stage(Stage::Inference); + let fetched = if stream_upstream { + fetch_stream_payload( self.pipeline, self.exec_ctx, auth, @@ -297,11 +299,7 @@ impl<'a> AgentTurn<'a> { response_budget, ) .instrument(round_span) - .await?; - if round == 0 { - self.registry.clear_mcp_list_tool_items(); - } - payload + .await } else { fetch_blocking_payload( self.pipeline, @@ -311,8 +309,16 @@ impl<'a> AgentTurn<'a> { Some(response_budget), ) .instrument(round_span) - .await? + .await }; + timer.finish_result(&fetched); + let mut payload = fetched?; + if stream_upstream && round == 0 { + self.registry.clear_mcp_list_tool_items(); + } + // Only what this round's upstream response reported; an absent + // `usage` records nothing. + self.exec_ctx.metrics.record_response_usage(payload.usage.as_ref()); let mut round_usage = compaction_usage; accumulate_usage(&mut round_usage, payload.usage.take()); payload.usage = round_usage; @@ -404,14 +410,13 @@ impl<'a> AgentTurn<'a> { output_offset: usize, response_budget: &ExecutorResponseBudget, ) -> ExecutorResult> { - let policy = self.exec_ctx.gateway_scheduler_policy.clone(); let (ctx, relay) = self.pipeline.parts_mut(); if !relay.has_deferred() { return execute_and_emit_output_calls( output_items, &self.registry, output_offset, - policy, + self.exec_ctx, response_budget, &mut self.tool_call_budget, relay, @@ -423,9 +428,10 @@ impl<'a> AgentTurn<'a> { output_items, &self.registry, output_offset, - policy, + self.exec_ctx.gateway_scheduler_policy.clone(), &mut self.tool_call_budget, - ); + ) + .with_metrics(&self.exec_ctx.metrics); let initial_event_run_len = scheduler.initial_event_run_len(output_items, &self.registry); emit_gateway_start_events(scheduler.event_plans().take(initial_event_run_len), relay).await?; diff --git a/crates/agentic-server-core/src/executor/engine/execute.rs b/crates/agentic-server-core/src/executor/engine/execute.rs index 422a5b3c..1462c79f 100644 --- a/crates/agentic-server-core/src/executor/engine/execute.rs +++ b/crates/agentic-server-core/src/executor/engine/execute.rs @@ -119,7 +119,7 @@ impl ExecuteRequest { let mut execution = self .execution .take() - .unwrap_or_else(|| ExecutionSpan::start(Api::Responses, Route::Executor, true)); + .unwrap_or_else(|| ExecutionSpan::start(Api::Responses, Route::Executor, true, &self.exec_ctx.metrics)); let limit = self.effective_max_stream_event_bytes(); let prepared = if self.control.is_some() { Err(ExecutorError::InvalidRequest( @@ -155,10 +155,14 @@ impl ExecuteRequest { /// # Errors /// Returns [`ExecutorError`] if rehydration or (non-streaming) LLM inference fails. pub async fn run(mut self) -> ExecutorResult> { - let execution = self - .execution - .take() - .unwrap_or_else(|| ExecutionSpan::start(Api::Responses, Route::Executor, self.payload.stream)); + let execution = self.execution.take().unwrap_or_else(|| { + ExecutionSpan::start( + Api::Responses, + Route::Executor, + self.payload.stream, + &self.exec_ctx.metrics, + ) + }); let span = execution.span().clone(); Box::pin(self.run_traced(execution)).instrument(span).await } diff --git a/crates/agentic-server-core/src/executor/engine/multi_agent.rs b/crates/agentic-server-core/src/executor/engine/multi_agent.rs index 3cb22d80..cd14b81d 100644 --- a/crates/agentic-server-core/src/executor/engine/multi_agent.rs +++ b/crates/agentic-server-core/src/executor/engine/multi_agent.rs @@ -32,6 +32,10 @@ use crate::executor::{ relay::{AgentFrame, AgentRoundId}, request::ExecutionContext, response_budget::ExecutorResponseBudget, + telemetry::{ + Api, + metrics::{ExecutionClock, RoundCounter}, + }, }; use crate::tool::ToolSearchState; use crate::types::{ @@ -89,6 +93,10 @@ pub(super) struct MultiAgentRun { sealer: TranscriptSealer, payload: ResponsePayload, rounds: usize, + /// Every agent's upstream rounds, recorded once for the execution. + round_counter: RoundCounter, + /// The execution's timing state, shared with each round's pipeline. + clock: Option, max_retained_bytes: usize, frame_sender: mpsc::Sender, frames: mpsc::Receiver, @@ -173,6 +181,8 @@ impl MultiAgentRun { sealer: TranscriptSealer::new()?, payload, rounds: 0, + round_counter: exec.metrics.rounds(Api::Responses), + clock: pipeline.execution_clock().cloned(), max_retained_bytes: exec.responses_config.max_retained_bytes, }) } diff --git a/crates/agentic-server-core/src/executor/engine/multi_agent/rounds.rs b/crates/agentic-server-core/src/executor/engine/multi_agent/rounds.rs index a293c34d..77e990a9 100644 --- a/crates/agentic-server-core/src/executor/engine/multi_agent/rounds.rs +++ b/crates/agentic-server-core/src/executor/engine/multi_agent/rounds.rs @@ -149,6 +149,9 @@ impl MultiAgentRun { StreamRelay::detached() }; let mut agent = AgentPipeline::new(ctx, tool_search, relay); + if let Some(clock) = &self.clock { + agent.set_execution_clock(clock.clone()); + } agent.set_agent_guidance(self.round_guidance(turn)); let mut execution = context.execution.clone(); let source = AgentRoundId { @@ -181,6 +184,7 @@ impl MultiAgentRun { .set_phase(turn, AgentPhase::Inferring) .map_err(registry_error)?; self.rounds += 1; + self.round_counter.begin_round(); Ok(()) } diff --git a/crates/agentic-server-core/src/executor/engine/retained.rs b/crates/agentic-server-core/src/executor/engine/retained.rs index 122c04b8..e969a757 100644 --- a/crates/agentic-server-core/src/executor/engine/retained.rs +++ b/crates/agentic-server-core/src/executor/engine/retained.rs @@ -11,7 +11,7 @@ use crate::executor::{ relay::{RelayLimits, StreamRelay}, request::{ExecutionContext, RequestContext}, response_events::{ResponseCommitState, ResponseEventSink}, - telemetry::ExecutionSpan, + telemetry::{ExecutionSpan, InstrumentedStream}, }; use crate::tool::ToolSearchState; use std::{num::NonZeroUsize, sync::Arc}; @@ -90,6 +90,8 @@ pub(super) fn start( let sink = ResponseEventSink::new(sender, max_bytes); let relay = StreamRelay::response(sink.clone(), RelayLimits::with_event_bytes(max_bytes)); let mut pipeline = AgentPipeline::new(ctx, tools, relay); + let clock = execution.clock().clone(); + pipeline.set_execution_clock(clock.clone()); let control = if pipeline .request .enriched_request @@ -110,6 +112,7 @@ pub(super) fn start( let worker_cancel = cancellation.clone(); let worker_sink = sink.clone(); let span = execution.span().clone(); + let events_span = span.clone(); let task = tokio::spawn(async move { let result = Box::pin(async { // The multi-agent coordinator handles cancellation by joining its children. @@ -128,7 +131,7 @@ pub(super) fn start( tokio::select! { biased; () = worker_cancel.cancelled() => return Err(ExecutorError::StreamError("response cancelled before commit".into())), - result = persist_if_needed(payload, ctx, metadata, exec.conv_handler.clone(), exec.resp_handler.clone()) => result?, + result = persist_if_needed(payload, ctx, metadata, exec.conv_handler.clone(), exec.resp_handler.clone(), &exec.metrics) => result?, } tokio::select! { () = worker_cancel.cancelled() => return Err(ExecutorError::StreamError("response delivery cancelled".into())), @@ -168,7 +171,11 @@ pub(super) fn start( } result }.instrument(span)); - let events = ResponseEventSink::stream(receiver); + let events = Box::pin(InstrumentedStream::delivering( + ResponseEventSink::stream(receiver, Some(clock.clone())), + events_span, + clock, + )); let owner_sink = sink.clone(); RunningResponse { response_id, diff --git a/crates/agentic-server-core/src/executor/engine/streaming.rs b/crates/agentic-server-core/src/executor/engine/streaming.rs index a87c3e84..8a1a91fd 100644 --- a/crates/agentic-server-core/src/executor/engine/streaming.rs +++ b/crates/agentic-server-core/src/executor/engine/streaming.rs @@ -11,6 +11,7 @@ use crate::executor::persist::persist_if_needed; use crate::executor::pipeline::AgentPipeline; use crate::executor::relay::{RelayLimits, StreamRelay}; use crate::executor::request::{ExecutionContext, RequestContext}; +use crate::executor::telemetry::metrics::ExecutionClock; use crate::executor::telemetry::{ExecutionSpan, InstrumentedStream}; use crate::tool::{ToolSearchMetadata, ToolSearchState}; use crate::types::request_response::ResponsePayload; @@ -32,6 +33,10 @@ use tokio::sync::mpsc; /// into the stream so the span stays open, and is entered on every poll, /// until the terminal frame has been yielded or the stream is dropped. The /// stream owns and polls orchestration, so its stages run inside that span. +/// +/// The loop below is the client relay: every semantic event is handed to the +/// transport here, so this is where the first-event and first-text timings +/// are taken. The pipeline takes the first-upstream-data timing. /// Dropping the stream drops orchestration. For a multi-agent response that /// includes its `RunOwner`, which aborts round tasks without joining them. pub(super) fn run_stream( @@ -44,6 +49,8 @@ pub(super) fn run_stream( control: Option, ) -> BoxStream { let span = execution.span().clone(); + let clock = execution.clock().clone(); + let relay_clock = clock.clone(); let frames: BoxStream = Box::pin(stream! { let failure_context = StreamFailureContext::from(&ctx); let (event_tx, event_rx) = mpsc::channel(STREAM_EVENT_BUFFER); @@ -51,6 +58,7 @@ pub(super) fn run_stream( let relay = StreamRelay::client(event_tx, RelayLimits::with_event_bytes(max_stream_event_bytes)); let mut agent = AgentPipeline::new(ctx, tool_search_state, relay); agent.control = control; + agent.set_execution_clock(clock.clone()); let run = async move { let result = Box::pin(run_until_gateway_tools_complete( &mut agent, @@ -69,7 +77,7 @@ pub(super) fn run_stream( while let Some(event) = events.next().await { match event { ProducerEvent::Event(event) => { - if let Some(content) = consume_stream_event(event, &mut next_sequence_number) { + if let Some(content) = consume_stream_event(event, &mut next_sequence_number, &clock) { yield content; } } @@ -109,7 +117,7 @@ pub(super) fn run_stream( } } }); - Box::pin(InstrumentedStream::new(frames, span)) + Box::pin(InstrumentedStream::delivering(frames, span, relay_clock)) } fn failed_stream_chunk( @@ -154,7 +162,16 @@ async fn completed_stream_chunk( let status = payload.status.clone(); let ch = exec_ctx.conv_handler.clone(); let rh = exec_ctx.resp_handler.clone(); - match Box::pin(persist_if_needed(payload, ctx, tool_search_metadata, ch, rh)).await { + match Box::pin(persist_if_needed( + payload, + ctx, + tool_search_metadata, + ch, + rh, + &exec_ctx.metrics, + )) + .await + { Ok(()) => { execution.completed_with_status(&status); chunk @@ -222,9 +239,15 @@ impl StreamFailureContext { } } -pub(super) fn consume_stream_event(event: StreamEvent, next_sequence_number: &mut u64) -> Option { +/// Hand one relayed event to the transport. +pub(super) fn consume_stream_event( + event: StreamEvent, + next_sequence_number: &mut u64, + clock: &ExecutionClock, +) -> Option { match event { StreamEvent::Frame(frame) => { + clock.client_event(frame.text); *next_sequence_number = frame.sequence_number.saturating_add(1); Some(frame.content) } diff --git a/crates/agentic-server-core/src/executor/engine/streaming/producer/tests.rs b/crates/agentic-server-core/src/executor/engine/streaming/producer/tests.rs index ccdd3fc5..d6c0a835 100644 --- a/crates/agentic-server-core/src/executor/engine/streaming/producer/tests.rs +++ b/crates/agentic-server-core/src/executor/engine/streaming/producer/tests.rs @@ -18,6 +18,7 @@ fn event(sequence_number: u64) -> StreamEvent { StreamEvent::Frame(StreamFrame { content: "event".into(), sequence_number, + text: false, }) } diff --git a/crates/agentic-server-core/src/executor/gateway.rs b/crates/agentic-server-core/src/executor/gateway.rs index ca08b539..ebf56ec3 100644 --- a/crates/agentic-server-core/src/executor/gateway.rs +++ b/crates/agentic-server-core/src/executor/gateway.rs @@ -5,6 +5,7 @@ mod admission_tests; pub(super) mod history; mod lifecycle; mod policy; +mod timing; pub(crate) use admission::BuiltInToolCallBudget; pub(super) use history::{append_gateway_calls_to_new_input, append_output_items_to_input, append_tool_outputs}; @@ -23,7 +24,9 @@ use tokio::sync::Semaphore; use crate::executor::error::{ExecutorError, ExecutorResult}; use crate::executor::relay::StreamRelay; +use crate::executor::request::ExecutionContext; use crate::executor::response_budget::ExecutorResponseBudget; +use crate::executor::telemetry::metrics::ExecutorMetrics; use crate::tool::handler::MAX_GATEWAY_TOOL_OUTPUT_BYTES; use crate::tool::{GatewayBinding, ToolError, ToolOutput, ToolOwnership, ToolRegistry}; use crate::types::io::output::{FunctionToolCall, GatewayCallStatus}; @@ -107,6 +110,8 @@ pub(super) struct GatewayScheduler { omitted_items: Vec, policy: GatewaySchedulerPolicy, timeout: Duration, + /// Times each executed call as an `agentic.stage.duration` sample. + metrics: Option, } impl GatewayScheduler { @@ -206,6 +211,7 @@ impl GatewayScheduler { omitted_items, policy, timeout, + metrics: None, } } @@ -307,7 +313,7 @@ impl GatewayScheduler { response_budget: &ExecutorResponseBudget, ) -> ExecutorResult { let Some(limit) = plan.refused else { - return self.run_one(plan, execution_slots, response_budget).await; + return self.timed_run(plan, execution_slots, response_budget).await; }; let message = admission::limit_reached_message(limit); let omitted = plan.events.completed_output.is_none(); @@ -330,7 +336,7 @@ impl GatewayScheduler { plan: GatewayCallPlan, execution_slots: &Semaphore, response_budget: &ExecutorResponseBudget, - ) -> ExecutorResult { + ) -> ExecutorResult<(GatewayCallResult, GatewayCallStatus)> { let GatewayCallPlan { item_index, call, @@ -339,7 +345,8 @@ impl GatewayScheduler { } = plan; let GatewayExecutionPlan::Bound(binding) = execution else { let message = format!("gateway tool '{}' has no registered handler", call.name); - return unexecuted_result(item_index, &call, &message, None, false, response_budget); + return unexecuted_result(item_index, &call, &message, None, false, response_budget) + .map(|result| (result, GatewayCallStatus::Failed)); }; let _permit = match &binding.self_exclusion { @@ -379,12 +386,13 @@ impl GatewayScheduler { enforce_gateway_tool_output_size(output.output.len())?; response_budget.consume(output.output.len())?; let public_output = binding.public_output(&call, &output, status); - Ok(GatewayCallResult { + let result = GatewayCallResult { item_index, input_item: InputItem::FunctionCallOutput(output.into()), public_output, omitted: false, - }) + }; + Ok((result, status)) } } @@ -505,17 +513,21 @@ fn complete_gateway_event_plans(plans: &mut [Gatew } } +/// Plan, execute and relay one round's gateway calls under the execution +/// context's scheduler policy, timing each call with its metrics. pub(super) async fn execute_and_emit_output_calls( output_items: &[OutputItem], registry: &ToolRegistry, output_offset: usize, - policy: GatewaySchedulerPolicy, + exec_ctx: &ExecutionContext, response_budget: &ExecutorResponseBudget, tool_call_budget: &mut BuiltInToolCallBudget, relay: &mut StreamRelay, ) -> ExecutorResult> { + let policy = exec_ctx.gateway_scheduler_policy.clone(); let mut scheduler = - GatewayScheduler::plan_with_budget(output_items, registry, output_offset, policy, tool_call_budget); + GatewayScheduler::plan_with_budget(output_items, registry, output_offset, policy, tool_call_budget) + .with_metrics(&exec_ctx.metrics); emit_gateway_start_events(scheduler.event_plans(), relay).await?; let gateway_results = scheduler.execute_with_budget(response_budget).await?; emit_gateway_completed_events(&gateway_results, scheduler.event_plans(), relay).await?; @@ -1351,6 +1363,7 @@ mod tests { omitted_items: Vec::new(), policy: GatewaySchedulerPolicy::new(NonZeroUsize::new(2).expect("nonzero test limit")), timeout: std::time::Duration::ZERO, + metrics: None, }; let execution = tokio::spawn(async move { scheduler.execute().await }); @@ -1396,6 +1409,7 @@ mod tests { omitted_items: Vec::new(), policy: GatewaySchedulerPolicy::new(NonZeroUsize::new(2).expect("nonzero test limit")), timeout: std::time::Duration::ZERO, + metrics: None, }; let execution = tokio::spawn(async move { scheduler.execute().await }); diff --git a/crates/agentic-server-core/src/executor/gateway/timing.rs b/crates/agentic-server-core/src/executor/gateway/timing.rs new file mode 100644 index 00000000..eae2bf7a --- /dev/null +++ b/crates/agentic-server-core/src/executor/gateway/timing.rs @@ -0,0 +1,41 @@ +//! Stage timing for gateway-executed calls. + +use tokio::sync::Semaphore; + +use super::{GatewayCallPlan, GatewayCallResult, GatewayScheduler}; +use crate::executor::error::ExecutorResult; +use crate::executor::response_budget::ExecutorResponseBudget; +use crate::executor::telemetry::FailureCategory; +use crate::executor::telemetry::metrics::{ExecutorMetrics, Stage}; +use crate::types::io::output::GatewayCallStatus; + +impl GatewayScheduler { + /// Time each executed call as an `agentic.stage.duration` sample. + pub(in crate::executor) fn with_metrics(mut self, metrics: &ExecutorMetrics) -> Self { + self.metrics = Some(metrics.clone()); + self + } + + /// Time one executed call as a `tool` stage; a call that reports a failed + /// status is a failed stage even though the round continues. + pub(super) async fn timed_run( + &self, + plan: GatewayCallPlan, + execution_slots: &Semaphore, + response_budget: &ExecutorResponseBudget, + ) -> ExecutorResult { + let timer = self + .metrics + .as_ref() + .map(|metrics| metrics.stage(Stage::Tool(plan.tool_type))); + let result = self.run_one(plan, execution_slots, response_budget).await; + if let Some(timer) = timer { + timer.finish(match &result { + Ok((_, GatewayCallStatus::Failed)) => Some(FailureCategory::Tool), + Ok(_) => None, + Err(error) => Some(FailureCategory::from(error)), + }); + } + result.map(|(result, _)| result) + } +} diff --git a/crates/agentic-server-core/src/executor/gateway_accumulator.rs b/crates/agentic-server-core/src/executor/gateway_accumulator.rs index 685fa9d1..482ee524 100644 --- a/crates/agentic-server-core/src/executor/gateway_accumulator.rs +++ b/crates/agentic-server-core/src/executor/gateway_accumulator.rs @@ -24,6 +24,8 @@ pub(super) enum StreamEvent { pub(super) struct StreamFrame { pub(super) content: String, pub(super) sequence_number: u64, + /// An output-text delta, for the relay's first-text timing. + pub(super) text: bool, } #[cfg(test)] @@ -226,6 +228,7 @@ pub(super) async fn emit_sse_frame_limited( .send(StreamEvent::Frame(StreamFrame { content, sequence_number, + text: frame.event_type == SSEEventType::OutputTextDelta, })) .await .map_err(|_| ExecutorError::StreamError("stream receiver closed while emitting gateway event".to_owned())) diff --git a/crates/agentic-server-core/src/executor/messages_loop.rs b/crates/agentic-server-core/src/executor/messages_loop.rs index 85543a6b..da80c803 100644 --- a/crates/agentic-server-core/src/executor/messages_loop.rs +++ b/crates/agentic-server-core/src/executor/messages_loop.rs @@ -23,6 +23,7 @@ use crate::executor::messages_context::MessagesRequestContext; use crate::executor::messages_tools::{GatewayToolUse, execute_gateway_calls, request_gateway_map}; use crate::executor::messages_usage::MessagesUsageTotals; use crate::executor::request::ExecutionContext; +use crate::executor::telemetry::metrics::{ExecutorMetrics, Stage}; use crate::executor::telemetry::{Api, ExecutionSpan, FailureCategory, Route}; use crate::tool::ToolRegistry; use crate::types::messages::tool_seam; @@ -85,7 +86,7 @@ pub async fn run_messages_loop( exec_ctx: &ExecutionContext, upstream: &MessagesUpstream, ) -> ExecutorResult> { - let mut execution = ExecutionSpan::start(Api::Messages, Route::Executor, false); + let mut execution = ExecutionSpan::start(Api::Messages, Route::Executor, false, &exec_ctx.metrics); let span = execution.span().clone(); let result = run_messages_loop_traced(ctx, registry, exec_ctx, upstream, &mut execution) .instrument(span) @@ -117,10 +118,13 @@ async fn run_messages_loop_traced( // Gateway ownership is request-scoped: the operator aliases plus the // gateway tools this request's registry resolved. let gateway_map = request_gateway_map(&exec_ctx.messages_gateway_tools, registry); + let mut rounds = exec_ctx.metrics.rounds(Api::Messages); for round in 0..MAX_GATEWAY_TOOL_ROUNDS { let body = ctx.upstream_body()?; - let (resp_text, response_headers) = fetch_response_json_with_headers( + rounds.begin_round(); + let timer = exec_ctx.metrics.stage(Stage::Inference); + let fetched = fetch_response_json_with_headers( body, &upstream.url, &exec_ctx.client, @@ -128,8 +132,11 @@ async fn run_messages_loop_traced( exec_ctx.responses_config.max_upstream_json_bytes, ) .instrument(super::telemetry::stages::inference_round(round)) - .await?; + .await; + timer.finish_result(&fetched); + let (resp_text, response_headers) = fetched?; let message: Value = deserialize_from_str(&resp_text).map_err(ExecutorError::JsonError)?; + record_message_usage(&exec_ctx.metrics, message.get("usage")); // Any error body from upstream is surfaced verbatim (handler maps it to // the Anthropic error envelope). @@ -211,6 +218,15 @@ async fn run_messages_loop_traced( }) } +/// Record one upstream response's own `usage`, before any turn totals are +/// folded into it. +fn record_message_usage(metrics: &ExecutorMetrics, usage: Option<&Value>) { + let mut round = MessagesUsageTotals::default(); + round.observe(usage); + let (input, output) = round.round_tokens(); + metrics.record_token_usage(Api::Messages, input, output); +} + /// Return the terminal assistant message with the turn's complete `usage` and /// no gateway-owned `tool_use`. /// diff --git a/crates/agentic-server-core/src/executor/messages_stream.rs b/crates/agentic-server-core/src/executor/messages_stream.rs index 518fd4b5..c8e8f2bc 100644 --- a/crates/agentic-server-core/src/executor/messages_stream.rs +++ b/crates/agentic-server-core/src/executor/messages_stream.rs @@ -36,6 +36,7 @@ use crate::executor::messages_context::MessagesRequestContext; use crate::executor::messages_tools::request_gateway_map; use crate::executor::messages_usage::MessagesUsageTotals; use crate::executor::request::ExecutionContext; +use crate::executor::telemetry::metrics::{Stage, StageTimer}; use crate::executor::telemetry::{Api, ExecutionSpan, FailureCategory, InstrumentedStream, Route}; use crate::proxy::processed_response_headers; use crate::tool::ToolRegistry; @@ -58,52 +59,69 @@ pub async fn run_messages_stream( upstream: MessagesUpstream, ) -> ExecutorResult> { ctx.force_stream(true); - let mut execution = ExecutionSpan::start(Api::Messages, Route::Executor, true); + let mut execution = ExecutionSpan::start(Api::Messages, Route::Executor, true, &exec_ctx.metrics); let span = execution.span().clone(); - let first_round = span.in_scope(|| super::telemetry::stages::inference_round(0)); - let primed = prime_messages_stream(&ctx, &exec_ctx, &upstream) - .instrument(first_round.clone()) - .await; - let first_response = match primed { - Ok(first_response) => first_response, + // Send the first upstream request before the handler commits an HTTP 200, + // so initial vLLM errors retain their original status and body. + let opened = open_round(&ctx, &exec_ctx, &upstream, 0).instrument(span.clone()).await; + let first_round = match opened { + Ok(first_round) => first_round, Err(error) => { execution.failed(&error); execution.not_delivered(); return Err(error); } }; - let response_headers = processed_response_headers(first_response.headers()); - let body = messages_stream_body( - ctx, - registry, - exec_ctx, - upstream, - (first_response, first_round), - execution, - ); + let response_headers = processed_response_headers(first_round.response.headers()); + let clock = execution.clock().clone(); + let body = messages_stream_body(ctx, registry, exec_ctx, upstream, first_round, execution); Ok(MessagesResponse { - body: Box::pin(InstrumentedStream::new(body, span)), + body: Box::pin(InstrumentedStream::delivering(body, span, clock)), headers: response_headers, }) } /// Send the first upstream request before the handler commits an HTTP 200, so /// initial vLLM errors retain their original status and body. -async fn prime_messages_stream( +/// One upstream round whose response headers have arrived. +struct OpenRound { + response: reqwest::Response, + span: tracing::Span, + stage: StageTimer, +} + +/// Build and send one round's upstream request inside its +/// `agentic.inference_round` span; the round's stage timer keeps running +/// until its body has been read. +async fn open_round( ctx: &MessagesRequestContext, exec_ctx: &ExecutionContext, upstream: &MessagesUpstream, -) -> ExecutorResult { - let first_body = ctx.upstream_body()?; - send_request( - &exec_ctx.client, - upstream.url(), - first_body, - None, - Some(upstream.headers()), - exec_ctx.streaming_timeout, - ) - .await + round: usize, +) -> ExecutorResult { + let span = super::telemetry::stages::inference_round(round); + let stage = exec_ctx.metrics.stage(Stage::Inference); + let sent = async { + let body = ctx.upstream_body()?; + send_request( + &exec_ctx.client, + upstream.url(), + body, + None, + Some(upstream.headers()), + exec_ctx.streaming_timeout, + ) + .await + } + .instrument(span.clone()) + .await; + match sent { + Ok(response) => Ok(OpenRound { response, span, stage }), + Err(error) => { + stage.finish(Some(FailureCategory::from(&error))); + Err(error) + } + } } /// The client-facing frame stream. `execution` lives inside it: every exit @@ -114,7 +132,7 @@ fn messages_stream_body( registry: Arc, exec_ctx: Arc, upstream: MessagesUpstream, - first_response: (reqwest::Response, tracing::Span), + first_round: OpenRound, mut execution: ExecutionSpan, ) -> BoxStream { Box::pin(stream! { @@ -122,40 +140,23 @@ fn messages_stream_body( gateway_map: request_gateway_map(&exec_ctx.messages_gateway_tools, ®istry), ..Default::default() }; - let mut prepared_response = Some(first_response); + let mut prepared_response = Some(first_round); + let clock = execution.clock().clone(); + let mut rounds = exec_ctx.metrics.rounds(Api::Messages); for round in 0..MAX_GATEWAY_TOOL_ROUNDS { - let (response, round_span) = if let Some(response) = prepared_response.take() { - response - } else { - let round_span = super::telemetry::stages::inference_round(round); - let body = match ctx.upstream_body() { - Ok(b) => b, - Err(e) => { - execution.failed(&e); - execution.delivered(); - yield executor_error_sse(&e); - return; - } - }; - match send_request( - &exec_ctx.client, - upstream.url(), - body, - None, - Some(upstream.headers()), - exec_ctx.streaming_timeout, - ) - .instrument(round_span.clone()) - .await - { - Ok(response) => (response, round_span), - Err(e) => { - execution.failed(&e); - execution.delivered(); - yield executor_error_sse(&e); - return; - } + rounds.begin_round(); + let opened = match prepared_response.take() { + Some(opened) => Ok(opened), + None => open_round(&ctx, &exec_ctx, &upstream, round).await, + }; + let OpenRound { response, span: round_span, stage } = match opened { + Ok(opened) => opened, + Err(e) => { + execution.failed(&e); + execution.delivered(); + yield executor_error_sse(&e); + return; } }; let mut response_stream = InstrumentedStream::new(Box::pin(response_lines( @@ -169,16 +170,22 @@ fn messages_stream_body( let line = match line { Ok(l) => l, Err(e) => { + stage.finish(Some(FailureCategory::from(&e))); execution.failed(&e); execution.delivered(); yield error_sse(&e.to_string()); return; } }; - for out in acc.push(&line) { + clock.upstream_data(); + let frames = acc.push(&line); + let text = acc.pushed_text; + for out in frames { + clock.client_event(text); yield out; } if acc.has_error() { + stage.finish(Some(acc.failure_category())); execution.failed_with(acc.failure_category()); execution.delivered(); return; @@ -190,6 +197,9 @@ fn messages_stream_body( // Release an upstream body that can remain open after its terminal, // including before awaiting gateway tool execution for the next round. drop(response_stream); + stage.finish(None); + let (input_tokens, output_tokens) = acc.usage.round_tokens(); + exec_ctx.metrics.record_token_usage(Api::Messages, input_tokens, output_tokens); // Round finished. Continue only for a pure gateway-tool round; a // client-executed function tool makes the round terminal. @@ -239,6 +249,8 @@ enum RoundState { /// State machine that turns per-round Anthropic SSE into one client-visible /// message. Fed line-by-line via [`Self::push`]. +// Each flag is independent per-round or per-push state, not a mode. +#[allow(clippy::struct_excessive_bools)] #[derive(Default)] struct MessagesStreamAccumulator { message_started: bool, @@ -267,6 +279,8 @@ struct MessagesStreamAccumulator { round_state: RoundState, /// Every consumed round's terminal `usage`, reported once in the final `message_delta`. usage: MessagesUsageTotals, + /// The last pushed line was forwarded as an output-text delta. + pushed_text: bool, /// Operator-configured client-tool → gateway-executor aliases, so a client /// tool like Claude Code's `WebSearch` is classified gateway-owned (and /// suppressed) the same way the built-in `web_search` is. diff --git a/crates/agentic-server-core/src/executor/messages_stream/ingestion.rs b/crates/agentic-server-core/src/executor/messages_stream/ingestion.rs index 4c810c6c..910bba11 100644 --- a/crates/agentic-server-core/src/executor/messages_stream/ingestion.rs +++ b/crates/agentic-server-core/src/executor/messages_stream/ingestion.rs @@ -9,6 +9,7 @@ use crate::utils::common::deserialize_from_str; impl MessagesStreamAccumulator { /// Translate one upstream SSE line into zero or more client SSE lines. pub(super) fn push(&mut self, line: &str) -> Vec { + self.pushed_text = false; let ClassifiedSseLine::Data(data) = SseLine::parse(line) else { return Vec::new(); }; @@ -189,6 +190,7 @@ impl MessagesStreamAccumulator { return Vec::new(); }; event["index"] = Value::from(client_index); + self.pushed_text = event["delta"]["type"] == "text_delta"; vec![sse("content_block_delta", event)] } diff --git a/crates/agentic-server-core/src/executor/messages_usage.rs b/crates/agentic-server-core/src/executor/messages_usage.rs index 28086422..7d088ab3 100644 --- a/crates/agentic-server-core/src/executor/messages_usage.rs +++ b/crates/agentic-server-core/src/executor/messages_usage.rs @@ -55,6 +55,18 @@ impl MessagesUsageTotals { } } + /// The current round's prompt and completion token counts, for metrics. + /// The prompt count includes cache reads and writes, which Anthropic + /// reports apart from `input_tokens`; a count no counter reported is `None`. + pub(super) fn round_tokens(&self) -> (Option, Option) { + let [input, output, cache_creation, cache_read] = self.round; + let prompt = [input, cache_creation, cache_read] + .into_iter() + .flatten() + .reduce(u64::saturating_add); + (prompt, output) + } + /// Add the current round to the totals and start the next one. pub(super) fn commit(&mut self) { for (total, value) in self.committed.iter_mut().zip(std::mem::take(&mut self.round)) { diff --git a/crates/agentic-server-core/src/executor/persist.rs b/crates/agentic-server-core/src/executor/persist.rs index d5f30cbb..1067d9a1 100644 --- a/crates/agentic-server-core/src/executor/persist.rs +++ b/crates/agentic-server-core/src/executor/persist.rs @@ -9,6 +9,7 @@ use crate::executor::error::{ExecutorError, ExecutorResult}; use crate::executor::modes::{ConversationHandler, ResponseHandler}; use crate::executor::prepare::prepare_request_tools; use crate::executor::request::{ExecutionContext, RequestContext}; +use crate::executor::telemetry::metrics::{ExecutorMetrics, Stage}; use crate::storage::{InOutItem, ResponseMetadata}; use crate::tool::{ToolSearchMetadata, ToolSearchState}; use crate::types::event::ResponseStatus; @@ -28,24 +29,29 @@ pub(crate) fn should_persist(ctx: &RequestContext) -> bool { ctx.continuation.is_some() || ctx.original_request.store || ctx.original_request.conversation.is_some() } +/// Persist when the request asked for it; only an attempted write is timed +/// as a `persist` stage. pub(crate) async fn persist_if_needed( payload: ResponsePayload, ctx: RequestContext, tool_search_metadata: Option, conv_handler: ConversationHandler, resp_handler: ResponseHandler, + metrics: &ExecutorMetrics, ) -> ExecutorResult<()> { - if should_persist(&ctx) { - match persist_prepared_response(payload, ctx, tool_search_metadata, conv_handler, resp_handler).await { - Err(error @ (ExecutorError::Conflict(_) | ExecutorError::PayloadTooLarge(_))) => Err(error), - Err(source) => { - error!(error = ?source, "failed to persist response"); - Err(ExecutorError::Persistence(Box::new(source))) - } - Ok(()) => Ok(()), + if !should_persist(&ctx) { + return Ok(()); + } + let timer = metrics.stage(Stage::Persist); + let persisted = persist_prepared_response(payload, ctx, tool_search_metadata, conv_handler, resp_handler).await; + timer.finish_result(&persisted); + match persisted { + Err(error @ (ExecutorError::Conflict(_) | ExecutorError::PayloadTooLarge(_))) => Err(error), + Err(source) => { + error!(error = ?source, "failed to persist response"); + Err(ExecutorError::Persistence(Box::new(source))) } - } else { - Ok(()) + Ok(()) => Ok(()), } } @@ -222,6 +228,7 @@ pub async fn commit( None, exec_ctx.conv_handler.clone(), exec_ctx.resp_handler.clone(), + &exec_ctx.metrics, )) .await?; Ok(payload) diff --git a/crates/agentic-server-core/src/executor/pipeline.rs b/crates/agentic-server-core/src/executor/pipeline.rs index 5eb36857..a2bb376f 100644 --- a/crates/agentic-server-core/src/executor/pipeline.rs +++ b/crates/agentic-server-core/src/executor/pipeline.rs @@ -11,6 +11,7 @@ use crate::executor::multi_agent::RunControlReceiver; use crate::executor::relay::{AgentRoundId, StreamRelay}; use crate::executor::request::RequestContext; use crate::executor::response_budget::ExecutorResponseBudget; +use crate::executor::telemetry::metrics::ExecutionClock; use crate::executor::translate::{Translation, TranslationContext}; use crate::tool::{ToolRegistry, ToolSearchMetadata, ToolSearchState}; use crate::types::agent::AgentIdentity; @@ -30,9 +31,20 @@ pub(super) struct AgentPipeline { agent_guidance: Option, /// Set after a `max_tool_calls` refusal; later rounds omit gateway-executed tools. builtin_tools_withheld: bool, + /// Timing state of the execution this pipeline serves, when it streams. + clock: Option, } impl AgentPipeline { + /// Report the first upstream line of the execution's streamed bodies to `clock`. + pub(super) fn set_execution_clock(&mut self, clock: ExecutionClock) { + self.clock = Some(clock); + } + + pub(super) fn execution_clock(&self) -> Option<&ExecutionClock> { + self.clock.as_ref() + } + pub(super) fn set_agent_guidance(&mut self, guidance: InputMessage) { self.agent_guidance = Some(guidance); } @@ -84,6 +96,7 @@ impl AgentPipeline { agent_guidance: None, control: None, builtin_tools_withheld: false, + clock: None, } } @@ -171,7 +184,11 @@ impl AgentPipeline { self.begin_round(validation, context, budget)?; futures::pin_mut!(body); while let Some(line) = body.next().await { - let translation = self.push(SseLine::parse(&line?))?; + let line = line?; + if let Some(clock) = &self.clock { + clock.upstream_data(); + } + let translation = self.push(SseLine::parse(&line))?; self.relay.accept(translation, &self.request, registry).await?; } // Frames still deferred stay with the relay until the engine releases them diff --git a/crates/agentic-server-core/src/executor/rehydrate.rs b/crates/agentic-server-core/src/executor/rehydrate.rs index e424494e..6206b223 100644 --- a/crates/agentic-server-core/src/executor/rehydrate.rs +++ b/crates/agentic-server-core/src/executor/rehydrate.rs @@ -8,6 +8,7 @@ use crate::executor::error::{ExecutorError, ExecutorResult}; use crate::executor::multi_agent::{CheckpointLimits, ValidatedTreeCheckpoint}; use crate::executor::pending_calls::pending_calls; use crate::executor::request::{ExecutionContext, RequestContext}; +use crate::executor::telemetry::metrics::Stage; use crate::storage::{InOutItem, ResponseMetadata}; use crate::tool::ToolError; use crate::types::io::{ @@ -167,6 +168,18 @@ pub(crate) async fn rehydrate_with_continuation( request: RequestPayload, exec_ctx: &ExecutionContext, continuation: Option, +) -> ExecutorResult { + let timer = exec_ctx.metrics.stage(Stage::Rehydrate); + // Boxed so this wrapper does not hold the request payload twice. + let rehydrated = Box::pin(rehydrate_request(request, exec_ctx, continuation)).await; + timer.finish_result(&rehydrated); + rehydrated +} + +async fn rehydrate_request( + request: RequestPayload, + exec_ctx: &ExecutionContext, + continuation: Option, ) -> ExecutorResult { validate_multi_agent_request(&request)?; // Stored turns never supply `max_tool_calls`, so the request value is final here. diff --git a/crates/agentic-server-core/src/executor/request.rs b/crates/agentic-server-core/src/executor/request.rs index 8896d284..73f2c33b 100644 --- a/crates/agentic-server-core/src/executor/request.rs +++ b/crates/agentic-server-core/src/executor/request.rs @@ -7,6 +7,7 @@ use crate::error::Error; use crate::executor::gateway::GatewaySchedulerPolicy; use crate::executor::modes::{ConversationHandler, ResponseHandler}; use crate::executor::multi_agent::ValidatedTreeCheckpoint; +use crate::executor::telemetry::ExecutorMetrics; use crate::storage::backend::redact_database_urls; use crate::storage::{ ConversationStore, ConversationVersion, DatabaseBackend, ResponseStore, create_pool_with_schema_and_configs, @@ -92,6 +93,9 @@ pub struct ExecutionContext { /// Bounded-concurrency policy applied to gateway-owned calls in each round. pub(crate) gateway_scheduler_policy: GatewaySchedulerPolicy, pub responses_config: ResponsesConfig, + /// Execution, stage, token, and timing instruments. Defaults to the + /// globally registered meter provider at construction time. + pub metrics: ExecutorMetrics, storage_pool: Option>, } @@ -126,10 +130,19 @@ impl ExecutionContext { streaming_timeout: streaming_timeout_from_env(), gateway_scheduler_policy: GatewaySchedulerPolicy::default(), responses_config: ResponsesConfig::default(), + metrics: ExecutorMetrics::from_global(), storage_pool: None, } } + /// Record executor metrics with instruments from the embedding + /// application's meter instead of the global provider. + #[must_use] + pub fn with_metrics(mut self, metrics: ExecutorMetrics) -> Self { + self.metrics = metrics; + self + } + #[must_use] pub fn with_responses_config(mut self, responses_config: ResponsesConfig) -> Self { self.responses_config = responses_config; @@ -204,6 +217,7 @@ impl ExecutionContext { streaming_timeout: streaming_timeout_from_env(), gateway_scheduler_policy: GatewaySchedulerPolicy::new(cfg.tools.max_concurrent_gateway_calls), responses_config: cfg.responses, + metrics: ExecutorMetrics::from_global(), storage_pool: Some(pool), }) } diff --git a/crates/agentic-server-core/src/executor/response_events.rs b/crates/agentic-server-core/src/executor/response_events.rs index ac7fb3e3..1233440c 100644 --- a/crates/agentic-server-core/src/executor/response_events.rs +++ b/crates/agentic-server-core/src/executor/response_events.rs @@ -10,6 +10,7 @@ use crate::executor::gateway_accumulator::{ GatewayStreamAccumulator, StreamEvent, StreamFrame, checked_stream_event_limited, executor_error_frame, terminal_response_frame, }; +use crate::executor::telemetry::metrics::ExecutionClock; use crate::types::{injection::InjectionEvent, request_response::ResponsePayload}; use crate::utils::common::serialize_to_value; @@ -38,15 +39,22 @@ impl ResponseEventSink { pub fn channel(max_bytes: usize) -> (Self, BoxStream) { let (sender, receiver) = mpsc::channel(1); let sink = Self::new(sender, max_bytes); - let stream = Self::stream(receiver); + let stream = Self::stream(receiver, None); (sink, stream) } - pub(super) fn stream(receiver: mpsc::Receiver) -> BoxStream { - futures::stream::unfold(receiver, |mut receiver| async move { + /// Hand each frame to the adapter; with an execution `clock`, this is where + /// the first-event and first-text timings are taken. + pub(super) fn stream(receiver: mpsc::Receiver, clock: Option) -> BoxStream { + futures::stream::unfold((receiver, clock), |(mut receiver, clock)| async move { while let Some(event) = receiver.recv().await { match event { - StreamEvent::Frame(frame) => return Some((frame.content, receiver)), + StreamEvent::Frame(frame) => { + if let Some(clock) = &clock { + clock.client_event(frame.text); + } + return Some((frame.content, (receiver, clock))); + } StreamEvent::Flush(flushed) => { // A cancelled flush waiter does not cancel event delivery. let _ = flushed.send(()); @@ -137,6 +145,7 @@ impl ResponseEventSink { permit.send(StreamEvent::Frame(StreamFrame { content, sequence_number, + text: frame.event_type == SSEEventType::OutputTextDelta, })); *state = published; Ok(true) diff --git a/crates/agentic-server-core/src/executor/telemetry.rs b/crates/agentic-server-core/src/executor/telemetry.rs index b1117a8a..8111b755 100644 --- a/crates/agentic-server-core/src/executor/telemetry.rs +++ b/crates/agentic-server-core/src/executor/telemetry.rs @@ -18,24 +18,30 @@ //! Every attribute value is bounded: outcomes and failure categories are //! closed enums, and no request identifier, model name, prompt, or error //! message is recorded. +//! +//! The same guard records the execution metrics (see [`metrics`]), so they +//! are finalized exactly once on the same paths and do not depend on whether +//! the trace was sampled. use std::pin::Pin; use std::task::{Context, Poll}; +use std::time::Instant; use futures::Stream; use tracing::{Span, field, info_span}; use tracing_opentelemetry::OpenTelemetrySpanExt as _; use super::error::ExecutorError; +use metrics::{ATTR_DELIVERY_OUTCOME, ATTR_ERROR_TYPE, ATTR_EXECUTION_OUTCOME, ExecutionClock}; +pub mod metrics; pub(crate) mod stages; +pub use metrics::ExecutorMetrics; + /// Span name shared by every API and transport. pub const EXECUTE_SPAN_NAME: &str = "agentic.execute"; -const ATTR_EXECUTION_OUTCOME: &str = "agentic.execution.outcome"; -const ATTR_DELIVERY_OUTCOME: &str = "agentic.delivery.outcome"; -const ATTR_ERROR_TYPE: &str = "error.type"; const ATTR_OTEL_STATUS: &str = "otel.status_code"; /// Which public API the request arrived on. @@ -205,36 +211,53 @@ impl From<&ExecutorError> for FailureCategory { } } -/// The `agentic.execute` span plus the guard that finalizes its outcome. +/// The `agentic.execute` span plus the guard that finalizes its outcome and +/// records the execution metrics. /// /// Create it with [`ExecutionSpan::start`], run the request inside /// [`ExecutionSpan::span`] (via `Instrument`), state the outcome on the -/// paths that know it, and let `Drop` finalize the rest. +/// paths that know it, and let `Drop` finalize the rest. Creating the guard +/// counts the execution as active; dropping it records its count, duration, +/// and delivery outcome and releases the active count. #[derive(Debug)] pub struct ExecutionSpan { span: Span, execution: Option, + failure: Option, delivery: Option, + clock: ExecutionClock, } impl ExecutionSpan { /// Open the span as a child of whatever span is current. #[must_use] - pub fn start(api: Api, route: Route, stream: bool) -> Self { - Self::with_parent(api, route, stream, Span::current().id()) + pub fn start(api: Api, route: Route, stream: bool, metrics: &ExecutorMetrics) -> Self { + Self::with_parent(api, route, stream, metrics, Span::current().id()) } /// Start an independent execution trace linked to a long-lived session. #[must_use] - pub fn start_linked(api: Api, route: Route, stream: bool, link: opentelemetry::trace::SpanContext) -> Self { - let execution = Self::with_parent(api, route, stream, None); + pub fn start_linked( + api: Api, + route: Route, + stream: bool, + metrics: &ExecutorMetrics, + link: opentelemetry::trace::SpanContext, + ) -> Self { + let execution = Self::with_parent(api, route, stream, metrics, None); if link.is_valid() { execution.span.add_link(link); } execution } - fn with_parent(api: Api, route: Route, stream: bool, parent: Option) -> Self { + fn with_parent( + api: Api, + route: Route, + stream: bool, + metrics: &ExecutorMetrics, + parent: Option, + ) -> Self { // Field names must be literal here; the `ATTR_*` constants name the // same fields for `record` calls. let span = info_span!( @@ -252,7 +275,9 @@ impl ExecutionSpan { Self { span, execution: None, + failure: None, delivery: None, + clock: ExecutionClock::start(metrics.clone(), api, route, stream), } } @@ -262,6 +287,11 @@ impl ExecutionSpan { &self.span } + /// Timing state shared with the upstream reader and the client relay. + pub(crate) fn clock(&self) -> &ExecutionClock { + &self.clock + } + /// The execution reached a terminal state. pub fn completed(&mut self) { self.set_execution(ExecutionOutcome::Completed); @@ -301,6 +331,7 @@ impl ExecutionSpan { /// The execution failed for a reason that is not an [`ExecutorError`]. pub fn failed_with(&mut self, category: FailureCategory) { if self.set_execution(ExecutionOutcome::Failed) { + self.failure = Some(category); self.span.record(ATTR_ERROR_TYPE, category.as_str()); self.span.record(ATTR_OTEL_STATUS, "ERROR"); } @@ -351,14 +382,55 @@ impl ExecutionSpan { /// persistence after the last inference round, the outcome guard's `Drop` — /// is attributed to the request. `tracing`'s `Instrument` covers futures /// only; this is the stream equivalent. +/// +/// Built with [`InstrumentedStream::delivering`] it is also the client-facing +/// relay boundary: it measures how long the transport takes to ask for the +/// next frame after taking one, which is where a slow client's backpressure +/// shows up. pub struct InstrumentedStream { inner: S, span: Span, + delivery: Option, +} + +struct DeliveryTimer { + clock: ExecutionClock, + handed_at: Option, +} + +impl DeliveryTimer { + /// The transport asked for the next frame: add the wait since it took + /// the previous one. + fn resumed(&mut self) { + if let Some(handed_at) = self.handed_at.take() { + self.clock.transport_waited(handed_at.elapsed()); + } + } + + /// The transport took a frame. + fn handed(&mut self) { + self.clock.frame_handed(); + self.handed_at = Some(Instant::now()); + } } impl InstrumentedStream { pub fn new(inner: S, span: Span) -> Self { - Self { inner, span } + Self { + inner, + span, + delivery: None, + } + } + + /// The execution's client-facing frame stream, polled inside the + /// execution span. + pub(crate) fn delivering(inner: S, span: Span, clock: ExecutionClock) -> Self { + Self { + inner, + span, + delivery: Some(DeliveryTimer { clock, handed_at: None }), + } } } @@ -367,8 +439,17 @@ impl Stream for InstrumentedStream { fn poll_next(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll> { let this = self.get_mut(); + // Before polling: the outcome guard inside `inner` may finalize on + // this poll and must see the wait that led up to it. + if let Some(delivery) = &mut this.delivery { + delivery.resumed(); + } let _entered = this.span.enter(); - Pin::new(&mut this.inner).poll_next(cx) + let polled = Pin::new(&mut this.inner).poll_next(cx); + if let (Some(delivery), Poll::Ready(Some(_))) = (&mut this.delivery, &polled) { + delivery.handed(); + } + polled } fn size_hint(&self) -> (usize, Option) { @@ -392,6 +473,9 @@ impl Drop for ExecutionSpan { }; self.set_delivery(delivery); } + if let (Some(execution), Some(delivery)) = (self.execution, self.delivery) { + self.clock.finalize(execution, self.failure, delivery); + } } } @@ -476,7 +560,8 @@ mod tests { #[test] fn first_execution_outcome_wins() { - let mut execution = ExecutionSpan::start(Api::Responses, Route::Executor, true); + let mut execution = + ExecutionSpan::start(Api::Responses, Route::Executor, true, &ExecutorMetrics::from_global()); execution.failed_with(FailureCategory::Stream); execution.completed(); assert_eq!(execution.execution, Some(ExecutionOutcome::Failed)); @@ -484,7 +569,8 @@ mod tests { #[test] fn drop_defaults_to_cancelled_and_disconnected() { - let mut execution = ExecutionSpan::start(Api::Responses, Route::Executor, true); + let mut execution = + ExecutionSpan::start(Api::Responses, Route::Executor, true, &ExecutorMetrics::from_global()); assert_eq!(execution.execution, None); // Simulate `Drop` bookkeeping without consuming the value. execution.cancelled(); @@ -493,15 +579,18 @@ mod tests { #[test] fn incomplete_status_is_its_own_outcome() { - let mut execution = ExecutionSpan::start(Api::Responses, Route::Executor, false); + let mut execution = + ExecutionSpan::start(Api::Responses, Route::Executor, false, &ExecutorMetrics::from_global()); execution.completed_with_status("incomplete"); assert_eq!(execution.execution, Some(ExecutionOutcome::Incomplete)); - let mut execution = ExecutionSpan::start(Api::Messages, Route::Executor, false); + let mut execution = + ExecutionSpan::start(Api::Messages, Route::Executor, false, &ExecutorMetrics::from_global()); execution.completed_with_stop_reason(Some("max_tokens")); assert_eq!(execution.execution, Some(ExecutionOutcome::Incomplete)); - let mut execution = ExecutionSpan::start(Api::Messages, Route::Executor, false); + let mut execution = + ExecutionSpan::start(Api::Messages, Route::Executor, false, &ExecutorMetrics::from_global()); execution.completed_with_stop_reason(Some("end_turn")); assert_eq!(execution.execution, Some(ExecutionOutcome::Completed)); } diff --git a/crates/agentic-server-core/src/executor/telemetry/metrics.rs b/crates/agentic-server-core/src/executor/telemetry/metrics.rs new file mode 100644 index 00000000..7113c8ef --- /dev/null +++ b/crates/agentic-server-core/src/executor/telemetry/metrics.rs @@ -0,0 +1,483 @@ +//! Execution, stage, token, and timing metrics. +//! +//! Every instrument is created once, from a [`Meter`], and shared through +//! [`ExecutorMetrics`], which the [`ExecutionContext`] carries. The gateway +//! binary builds it from the globally registered meter provider after +//! telemetry is initialized; embedding applications pass their own meter with +//! [`ExecutionContext::with_metrics`], and without a provider every +//! instrument is a no-op. +//! +//! Metrics never depend on the trace sampling decision: they are recorded by +//! the same guards that finalize spans, not derived from exported spans. +//! Every attribute is a closed enum or a boolean; no request, response, +//! conversation, tool, model, or URL identifier becomes a metric dimension. +//! +//! [`ExecutionContext`]: crate::executor::ExecutionContext +//! [`ExecutionContext::with_metrics`]: crate::executor::ExecutionContext::with_metrics + +use std::sync::Arc; +use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; +use std::time::{Duration, Instant}; + +use opentelemetry::KeyValue; +use opentelemetry::global; +use opentelemetry::metrics::{Counter, Histogram, Meter, UpDownCounter}; + +use super::{Api, DeliveryOutcome, ExecutionOutcome, FailureCategory, Route}; +use crate::executor::error::ExecutorError; +use crate::tool::ToolType; +use crate::types::io::ResponseUsage; + +/// Instrumentation scope for every instrument this crate creates. +pub const INSTRUMENTATION_SCOPE: &str = "agentic_core"; + +pub(crate) const ATTR_API: &str = "agentic.api"; +pub(crate) const ATTR_ROUTE: &str = "agentic.route"; +pub(crate) const ATTR_STREAM: &str = "agentic.stream"; +pub(crate) const ATTR_EXECUTION_OUTCOME: &str = "agentic.execution.outcome"; +pub(crate) const ATTR_DELIVERY_OUTCOME: &str = "agentic.delivery.outcome"; +pub(crate) const ATTR_ERROR_TYPE: &str = "error.type"; +const ATTR_STAGE: &str = "agentic.stage"; +const ATTR_TOOL_TYPE: &str = "agentic.tool.type"; +const ATTR_OPERATION: &str = "gen_ai.operation.name"; +const ATTR_TOKEN_TYPE: &str = "gen_ai.token.type"; + +/// Every upstream call the executor makes is a chat-style inference. +const OPERATION_CHAT: &str = "chat"; +/// `error.type` for a stage whose future was dropped before it finished. +const ERROR_TYPE_CANCELLED: &str = "cancelled"; + +/// Execution, stage, and delivery durations: powers of two from 10 ms to +/// about 5.5 minutes, covering multi-round tool loops on slow models. +const DURATION_BOUNDARIES: &[f64] = &[ + 0.01, 0.02, 0.04, 0.08, 0.16, 0.32, 0.64, 1.28, 2.56, 5.12, 10.24, 20.48, 40.96, 81.92, 163.84, 327.68, +]; + +/// The `gen_ai.server.time_to_first_token` semantic-convention boundaries, +/// extended to 20 s for queued or cold upstreams. +const FIRST_DATA_BOUNDARIES: &[f64] = &[ + 0.001, 0.005, 0.01, 0.02, 0.04, 0.06, 0.08, 0.1, 0.25, 0.5, 0.75, 1.0, 2.5, 5.0, 7.5, 10.0, 20.0, +]; + +/// Total time a streamed execution waited on its transport. +const DELIVERY_WAIT_BOUNDARIES: &[f64] = &[ + 0.001, 0.0025, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0, 30.0, 60.0, +]; + +/// The `gen_ai.client.token.usage` semantic-convention boundaries. +const TOKEN_BOUNDARIES: &[f64] = &[ + 1.0, + 4.0, + 16.0, + 64.0, + 256.0, + 1024.0, + 4096.0, + 16384.0, + 65536.0, + 262_144.0, + 1_048_576.0, + 4_194_304.0, + 16_777_216.0, + 67_108_864.0, +]; + +/// One bucket per round up to the gateway's ten-round cap. +const ROUND_BOUNDARIES: &[f64] = &[1.0, 2.0, 3.0, 4.0, 5.0, 6.0, 7.0, 8.0, 9.0, 10.0]; + +/// A timed executor stage. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub(crate) enum Stage { + Rehydrate, + Inference, + Tool(ToolType), + Compaction, + Persist, +} + +impl Stage { + const fn as_str(self) -> &'static str { + match self { + Self::Rehydrate => "rehydrate", + Self::Inference => "inference", + Self::Tool(_) => "tool", + Self::Compaction => "compaction", + Self::Persist => "persist", + } + } +} + +/// The instruments the executor records, shared by every request. +/// +/// Cheap to clone. Build it once per [`Meter`]; creating instruments per +/// request would defeat the SDK's instrument cache. +#[derive(Debug, Clone)] +pub struct ExecutorMetrics { + instruments: Arc, +} + +#[derive(Debug)] +struct Instruments { + execution_count: Counter, + execution_active: UpDownCounter, + execution_duration: Histogram, + delivery_count: Counter, + delivery_wait: Histogram, + stage_duration: Histogram, + inference_rounds: Histogram, + token_usage: Histogram, + first_upstream_data: Histogram, + first_client_event: Histogram, + first_text: Histogram, +} + +impl ExecutorMetrics { + /// Create every instrument from `meter`. + #[must_use] + pub fn new(meter: &Meter) -> Self { + let seconds = |name: &'static str, description: &'static str, boundaries: &[f64]| { + meter + .f64_histogram(name) + .with_unit("s") + .with_description(description) + .with_boundaries(boundaries.to_vec()) + .build() + }; + let instruments = Instruments { + execution_count: meter + .u64_counter("agentic.execution.count") + .with_unit("{execution}") + .with_description("Finalized executions by API, route, and execution outcome.") + .build(), + execution_active: meter + .i64_up_down_counter("agentic.execution.active") + .with_unit("{execution}") + .with_description("Executions accepted and not yet finalized.") + .build(), + execution_duration: seconds( + "agentic.execution.duration", + "Time from accepting an execution until it is finalized.", + DURATION_BOUNDARIES, + ), + delivery_count: meter + .u64_counter("agentic.delivery.count") + .with_unit("{execution}") + .with_description("Finalized executions by delivery outcome.") + .build(), + delivery_wait: seconds( + "agentic.delivery.wait.duration", + "Total time a streamed execution waited for its transport to take the next frame.", + DELIVERY_WAIT_BOUNDARIES, + ), + stage_duration: seconds( + "agentic.stage.duration", + "Duration of one executor stage: rehydration, an inference round, a gateway-executed tool \ + call, compaction, or persistence.", + DURATION_BOUNDARIES, + ), + inference_rounds: meter + .u64_histogram("agentic.inference.rounds") + .with_unit("{round}") + .with_description("Upstream inference rounds per execution.") + .with_boundaries(ROUND_BOUNDARIES.to_vec()) + .build(), + token_usage: meter + .u64_histogram("gen_ai.client.token.usage") + .with_unit("{token}") + .with_description("Tokens reported by the upstream per inference call.") + .with_boundaries(TOKEN_BOUNDARIES.to_vec()) + .build(), + first_upstream_data: seconds( + "agentic.time_to_first_upstream_data", + "Time from accepting a streamed execution until its first upstream SSE line.", + FIRST_DATA_BOUNDARIES, + ), + first_client_event: seconds( + "agentic.time_to_first_client_event", + "Time from accepting a streamed execution until its first semantic event is handed to the \ + transport.", + FIRST_DATA_BOUNDARIES, + ), + first_text: seconds( + "agentic.time_to_first_text", + "Time from accepting a streamed execution until its first output-text delta is handed to the \ + transport.", + FIRST_DATA_BOUNDARIES, + ), + }; + Self { + instruments: Arc::new(instruments), + } + } + + /// Instruments bound to the globally registered meter provider. + /// + /// With no provider registered the instruments are no-ops, and they stay + /// no-ops: build this after the provider is installed. + #[must_use] + pub fn from_global() -> Self { + Self::new(&global::meter(INSTRUMENTATION_SCOPE)) + } + + /// Record the tokens one upstream inference call reported. Nothing is + /// recorded for a count the upstream did not send. + pub(crate) fn record_token_usage(&self, api: Api, input: Option, output: Option) { + for (token_type, count) in [("input", input), ("output", output)] { + if let Some(count) = count { + self.instruments.token_usage.record( + count, + &[ + KeyValue::new(ATTR_OPERATION, OPERATION_CHAT), + KeyValue::new(ATTR_TOKEN_TYPE, token_type), + KeyValue::new(ATTR_API, api.as_str()), + ], + ); + } + } + } + + /// Record the usage one Responses upstream call reported; `None` records + /// nothing. + pub(crate) fn record_response_usage(&self, usage: Option<&ResponseUsage>) { + if let Some(usage) = usage { + self.record_token_usage( + Api::Responses, + u64::try_from(usage.input_tokens).ok(), + u64::try_from(usage.output_tokens).ok(), + ); + } + } + + /// Start timing one stage; the returned timer records when it is + /// finished or dropped. + pub(crate) fn stage(&self, stage: Stage) -> StageTimer { + StageTimer { + metrics: self.clone(), + stage, + started: Instant::now(), + finished: false, + } + } + + /// Count the inference rounds of one execution; the count is recorded + /// when the returned counter is dropped. + pub(crate) fn rounds(&self, api: Api) -> RoundCounter { + RoundCounter { + metrics: self.clone(), + api, + rounds: 0, + } + } + + fn record_stage(&self, stage: Stage, elapsed: Duration, error_type: Option<&'static str>) { + let mut attributes = Vec::with_capacity(3); + attributes.push(KeyValue::new(ATTR_STAGE, stage.as_str())); + if let Stage::Tool(kind) = stage { + attributes.push(KeyValue::new(ATTR_TOOL_TYPE, super::stages::tool_type(kind))); + } + if let Some(error_type) = error_type { + attributes.push(KeyValue::new(ATTR_ERROR_TYPE, error_type)); + } + self.instruments + .stage_duration + .record(elapsed.as_secs_f64(), &attributes); + } +} + +/// Records one `agentic.stage.duration` sample exactly once: on +/// [`StageTimer::finish`], or as `cancelled` when dropped unfinished. +pub(crate) struct StageTimer { + metrics: ExecutorMetrics, + stage: Stage, + started: Instant, + finished: bool, +} + +impl StageTimer { + /// Record the stage, labelled with the error category when it failed. + pub(crate) fn finish_result(self, result: &Result) { + self.finish(result.as_ref().err().map(FailureCategory::from)); + } + + /// The stage turned out not to run; record nothing. + pub(crate) fn discard(mut self) { + self.finished = true; + } + + pub(crate) fn finish(mut self, failure: Option) { + self.finished = true; + self.metrics + .record_stage(self.stage, self.started.elapsed(), failure.map(FailureCategory::as_str)); + } +} + +impl Drop for StageTimer { + fn drop(&mut self) { + if !self.finished { + self.metrics + .record_stage(self.stage, self.started.elapsed(), Some(ERROR_TYPE_CANCELLED)); + } + } +} + +/// Counts one execution's upstream inference rounds and records the total +/// once, when dropped, however the loop ended. +pub(crate) struct RoundCounter { + metrics: ExecutorMetrics, + api: Api, + rounds: u64, +} + +impl RoundCounter { + pub(crate) fn begin_round(&mut self) { + self.rounds = self.rounds.saturating_add(1); + } +} + +impl Drop for RoundCounter { + fn drop(&mut self) { + if self.rounds > 0 { + self.metrics + .instruments + .inference_rounds + .record(self.rounds, &[KeyValue::new(ATTR_API, self.api.as_str())]); + } + } +} + +/// Per-execution timing state shared by the execution guard, the upstream +/// reader, and the client relay, which may run on different tasks. +/// +/// Each first-* timing is measured from the moment the execution was +/// accepted and recorded at most once. +#[derive(Debug, Clone)] +pub(crate) struct ExecutionClock { + inner: Arc, +} + +#[derive(Debug)] +struct ClockState { + metrics: ExecutorMetrics, + api: Api, + route: Route, + stream: bool, + started: Instant, + first_upstream_data: AtomicBool, + first_client_event: AtomicBool, + first_text: AtomicBool, + handed_frames: AtomicBool, + delivery_wait_nanos: AtomicU64, +} + +impl ExecutionClock { + /// Start the clock and count the execution as active. + pub(super) fn start(metrics: ExecutorMetrics, api: Api, route: Route, stream: bool) -> Self { + let clock = Self { + inner: Arc::new(ClockState { + metrics, + api, + route, + stream, + started: Instant::now(), + first_upstream_data: AtomicBool::new(false), + first_client_event: AtomicBool::new(false), + first_text: AtomicBool::new(false), + handed_frames: AtomicBool::new(false), + delivery_wait_nanos: AtomicU64::new(0), + }), + }; + clock + .inner + .metrics + .instruments + .execution_active + .add(1, &clock.base_attributes()); + clock + } + + fn base_attributes(&self) -> [KeyValue; 3] { + [ + KeyValue::new(ATTR_API, self.inner.api.as_str()), + KeyValue::new(ATTR_ROUTE, self.inner.route.as_str()), + KeyValue::new(ATTR_STREAM, self.inner.stream), + ] + } + + /// The first upstream SSE line reached the pipeline. + pub(crate) fn upstream_data(&self) { + self.first(&self.inner.first_upstream_data, |instruments| { + &instruments.first_upstream_data + }); + } + + /// A semantic event of the response is being handed to the transport. + /// `text` marks an output-text delta. + pub(crate) fn client_event(&self, text: bool) { + self.first(&self.inner.first_client_event, |instruments| { + &instruments.first_client_event + }); + if text { + self.first(&self.inner.first_text, |instruments| &instruments.first_text); + } + } + + fn first(&self, seen: &AtomicBool, histogram: impl FnOnce(&Instruments) -> &Histogram) { + // Every later event takes the load alone, without writing the flag. + if !seen.load(Ordering::Relaxed) && !seen.swap(true, Ordering::Relaxed) { + histogram(&self.inner.metrics.instruments).record( + self.inner.started.elapsed().as_secs_f64(), + &[KeyValue::new(ATTR_API, self.inner.api.as_str())], + ); + } + } + + /// A frame was handed to the transport. + pub(super) fn frame_handed(&self) { + if !self.inner.handed_frames.load(Ordering::Relaxed) { + self.inner.handed_frames.store(true, Ordering::Relaxed); + } + } + + /// The transport asked for the next frame `waited` after taking the + /// previous one. + pub(super) fn transport_waited(&self, waited: Duration) { + let nanos = u64::try_from(waited.as_nanos()).unwrap_or(u64::MAX); + self.inner.delivery_wait_nanos.fetch_add(nanos, Ordering::Relaxed); + } + + /// Record the execution's terminal metrics and release its active count. + /// The execution guard calls this exactly once, from `Drop`. + pub(super) fn finalize( + &self, + execution: ExecutionOutcome, + failure: Option, + delivery: DeliveryOutcome, + ) { + let instruments = &self.inner.metrics.instruments; + let base = self.base_attributes(); + instruments.execution_active.add(-1, &base); + + let mut attributes = Vec::with_capacity(5); + attributes.extend_from_slice(&base); + attributes.push(KeyValue::new(ATTR_EXECUTION_OUTCOME, execution.as_str())); + if let Some(failure) = failure { + attributes.push(KeyValue::new(ATTR_ERROR_TYPE, failure.as_str())); + } + instruments.execution_count.add(1, &attributes); + instruments + .execution_duration + .record(self.inner.started.elapsed().as_secs_f64(), &attributes); + + let mut attributes = base.to_vec(); + attributes.push(KeyValue::new(ATTR_DELIVERY_OUTCOME, delivery.as_str())); + instruments.delivery_count.add(1, &attributes); + + if self.inner.handed_frames.load(Ordering::Relaxed) { + let waited = Duration::from_nanos(self.inner.delivery_wait_nanos.load(Ordering::Relaxed)); + instruments.delivery_wait.record( + waited.as_secs_f64(), + &[KeyValue::new(ATTR_API, self.inner.api.as_str())], + ); + } + } +} diff --git a/crates/agentic-server/src/app.rs b/crates/agentic-server/src/app.rs index 90aca07a..cdc1a37b 100644 --- a/crates/agentic-server/src/app.rs +++ b/crates/agentic-server/src/app.rs @@ -28,6 +28,7 @@ use crate::handler::{ }; use crate::model_capabilities::ModelCapabilities; use crate::telemetry::http::{HttpMetrics, track_request}; +use crate::telemetry::websocket::WebSocketMetrics; /// Default ceiling on serialized inbound request bytes for HTTP bodies and /// WebSocket messages. @@ -39,10 +40,10 @@ pub struct WebSocketTracker { inner: Arc, } -#[derive(Default)] struct WebSocketTrackerInner { active: AtomicUsize, idle: Notify, + metrics: WebSocketMetrics, #[cfg(debug_assertions)] local_completion_barrier: std::sync::Mutex>, } @@ -116,13 +117,45 @@ struct LocalCompletionBarrier { release: oneshot::Receiver<()>, } +impl Default for WebSocketTrackerInner { + fn default() -> Self { + Self::with_metrics(WebSocketMetrics::from_global()) + } +} + +impl WebSocketTrackerInner { + fn with_metrics(metrics: WebSocketMetrics) -> Self { + Self { + active: AtomicUsize::new(0), + idle: Notify::new(), + metrics, + #[cfg(debug_assertions)] + local_completion_barrier: std::sync::Mutex::new(None), + } + } +} + pub(crate) struct WebSocketGuard { inner: Arc, } impl WebSocketTracker { + /// A tracker recording its connection and queue metrics with `metrics` + /// instead of the global meter provider's. + #[must_use] + pub fn with_metrics(metrics: WebSocketMetrics) -> Self { + Self { + inner: Arc::new(WebSocketTrackerInner::with_metrics(metrics)), + } + } + + pub(crate) fn metrics(&self) -> &WebSocketMetrics { + &self.inner.metrics + } + pub(crate) fn track(&self) -> WebSocketGuard { self.inner.active.fetch_add(1, Ordering::AcqRel); + self.inner.metrics.connection_opened(); WebSocketGuard { inner: Arc::clone(&self.inner), } @@ -178,6 +211,7 @@ impl WebSocketTracker { impl Drop for WebSocketGuard { fn drop(&mut self) { + self.inner.metrics.connection_closed(); if self.inner.active.fetch_sub(1, Ordering::AcqRel) == 1 { self.inner.idle.notify_waiters(); } diff --git a/crates/agentic-server/src/handler/http/messages.rs b/crates/agentic-server/src/handler/http/messages.rs index 8d636f46..8db065b6 100644 --- a/crates/agentic-server/src/handler/http/messages.rs +++ b/crates/agentic-server/src/handler/http/messages.rs @@ -34,7 +34,7 @@ async fn proxy_messages( query: parts.uri.query().map(str::to_owned), }, path, - &state.proxy_state, + state, ) .await, ) diff --git a/crates/agentic-server/src/handler/http/responses.rs b/crates/agentic-server/src/handler/http/responses.rs index 85f59c1b..e3972aa6 100644 --- a/crates/agentic-server/src/handler/http/responses.rs +++ b/crates/agentic-server/src/handler/http/responses.rs @@ -28,8 +28,7 @@ async fn proxy_responses(state: &AppState, parts: Parts, body: Bytes) -> Respons query: parts.uri.query().map(str::to_string), }; convert_response( - crate::telemetry::proxy::trace_proxy_request(Api::Responses, proxy_req, "/v1/responses", &state.proxy_state) - .await, + crate::telemetry::proxy::trace_proxy_request(Api::Responses, proxy_req, "/v1/responses", state).await, ) } diff --git a/crates/agentic-server/src/handler/websocket/responses.rs b/crates/agentic-server/src/handler/websocket/responses.rs index d7bff406..ecc2434c 100644 --- a/crates/agentic-server/src/handler/websocket/responses.rs +++ b/crates/agentic-server/src/handler/websocket/responses.rs @@ -232,7 +232,7 @@ async fn handle_ws_request(request: WsRequest, context: RequestExecution<'_>) -> generate, execution, } = request; - let mut execution = execution.unwrap_or_else(telemetry::QueuedExecution::new).dispatch(); + let mut execution = telemetry::dispatch(execution, state); if generate == Some(false) { debug!("handling non-generating websocket request locally"); diff --git a/crates/agentic-server/src/handler/websocket/responses/multiplexer.rs b/crates/agentic-server/src/handler/websocket/responses/multiplexer.rs index 87b1c72f..7580f0b6 100644 --- a/crates/agentic-server/src/handler/websocket/responses/multiplexer.rs +++ b/crates/agentic-server/src/handler/websocket/responses/multiplexer.rs @@ -166,7 +166,7 @@ impl WsMultiplexer { self.sessions.insert(lane.clone(), Arc::new(session)); } if let WsWorkItem::Execute { request, .. } = &mut work { - request.execution = Some(telemetry::QueuedExecution::new()); + request.execution = Some(telemetry::QueuedExecution::new(&self.state)); } self.byte_budget.reserve(work.input_bytes()); if let Some(queue) = self.lanes.get_mut(&lane) { diff --git a/crates/agentic-server/src/handler/websocket/responses/telemetry.rs b/crates/agentic-server/src/handler/websocket/responses/telemetry.rs index 4916e529..a3c891ae 100644 --- a/crates/agentic-server/src/handler/websocket/responses/telemetry.rs +++ b/crates/agentic-server/src/handler/websocket/responses/telemetry.rs @@ -2,6 +2,9 @@ use std::time::Instant; +use crate::app::AppState; +use crate::telemetry::websocket::WebSocketMetrics; + use agentic_core::executor::telemetry::{Api, ExecutionSpan, FailureCategory, Route}; use opentelemetry::trace::TraceContextExt as _; use tracing_opentelemetry::OpenTelemetrySpanExt as _; @@ -16,31 +19,41 @@ pub(super) struct QueuedExecution { struct QueueWait { span: tracing::Span, admitted: Instant, + metrics: WebSocketMetrics, } impl Drop for QueueWait { fn drop(&mut self) { - self.span - .record("agentic.queue.wait", self.admitted.elapsed().as_secs_f64()); + let waited = self.admitted.elapsed(); + self.span.record("agentic.queue.wait", waited.as_secs_f64()); + self.metrics.record_queue_wait(waited); } } impl QueuedExecution { - pub(super) fn new() -> Self { + pub(super) fn new(state: &AppState) -> Self { let session = tracing::Span::current().context().span().span_context().clone(); - let execution = ExecutionSpan::start_linked(Api::Responses, Route::Executor, true, session); + let metrics = &state.exec_ctx.metrics; + let execution = ExecutionSpan::start_linked(Api::Responses, Route::Executor, true, metrics, session); let wait = QueueWait { span: execution.span().clone(), admitted: Instant::now(), + metrics: state.websocket_tracker.metrics().clone(), }; Self { execution, _wait: wait } } - pub(super) fn dispatch(self) -> ExecutionSpan { + fn dispatch(self) -> ExecutionSpan { self.execution } } +/// Start executing an admitted request, ending its queue wait. Every admitted +/// request carries its execution; one that does not is traced from dispatch. +pub(super) fn dispatch(queued: Option, state: &AppState) -> ExecutionSpan { + queued.unwrap_or_else(|| QueuedExecution::new(state)).dispatch() +} + pub(super) fn finish_local(execution: &mut ExecutionSpan, result: &Result<(), WsError>) { match result { Ok(()) => { diff --git a/crates/agentic-server/src/telemetry/mod.rs b/crates/agentic-server/src/telemetry/mod.rs index 20ac202d..4daa978d 100644 --- a/crates/agentic-server/src/telemetry/mod.rs +++ b/crates/agentic-server/src/telemetry/mod.rs @@ -12,6 +12,7 @@ pub mod http; mod lifecycle; pub(crate) mod proxy; mod subscriber; +pub mod websocket; pub use config::{ExporterSelection, OtlpCompression, OtlpProtocol, TelemetryConfig, TelemetryConfigError}; pub use lifecycle::{DEFAULT_SHUTDOWN_TIMEOUT, InstrumentationHandles, Signal, TelemetryError, TelemetryGuard}; diff --git a/crates/agentic-server/src/telemetry/proxy.rs b/crates/agentic-server/src/telemetry/proxy.rs index f1daa29f..b9f605dd 100644 --- a/crates/agentic-server/src/telemetry/proxy.rs +++ b/crates/agentic-server/src/telemetry/proxy.rs @@ -4,23 +4,25 @@ use std::pin::Pin; use std::task::{Context, Poll}; use agentic_core::executor::telemetry::{Api, ExecutionSpan, FailureCategory, Route}; -use agentic_core::proxy::{ProxyAuth, ProxyBody, ProxyRequest, ProxyResponse, ProxyState, proxy_request_with_path}; +use agentic_core::proxy::{ProxyAuth, ProxyBody, ProxyRequest, ProxyResponse, proxy_request_with_path}; use bytes::Bytes; use futures::Stream; use tracing::Instrument as _; +use crate::app::AppState; + pub(crate) async fn trace_proxy_request( api: Api, request: ProxyRequest, path: &str, - state: &ProxyState, + state: &AppState, ) -> ProxyResponse { - let mut execution = ExecutionSpan::start(api, Route::Proxy, request.is_streaming()); + let mut execution = ExecutionSpan::start(api, Route::Proxy, request.is_streaming(), &state.exec_ctx.metrics); let auth = match api { Api::Responses => ProxyAuth::OpenAiBearer, Api::Messages => ProxyAuth::Anthropic, }; - let response = proxy_request_with_path(request, path, auth, state) + let response = proxy_request_with_path(request, path, auth, &state.proxy_state) .instrument(execution.span().clone()) .await; if !response.status.is_success() { diff --git a/crates/agentic-server/src/telemetry/websocket.rs b/crates/agentic-server/src/telemetry/websocket.rs new file mode 100644 index 00000000..02c29473 --- /dev/null +++ b/crates/agentic-server/src/telemetry/websocket.rs @@ -0,0 +1,67 @@ +//! WebSocket transport metrics: open connections and per-message queue wait. +//! +//! Each `response.create` on a connection is its own execution and is counted +//! by the core execution metrics; these instruments cover what only the +//! transport sees. Neither carries attributes, so a connection or stream +//! identifier can never become a dimension. + +use std::time::Duration; + +use opentelemetry::global; +use opentelemetry::metrics::{Histogram, Meter, UpDownCounter}; + +const INSTRUMENTATION_SCOPE: &str = "agentic_server"; + +/// A queued message can wait behind an entire earlier turn on its stream, so +/// the boundaries match the execution durations. +const QUEUE_WAIT_BOUNDARIES: &[f64] = &[ + 0.001, 0.01, 0.02, 0.04, 0.08, 0.16, 0.32, 0.64, 1.28, 2.56, 5.12, 10.24, 20.48, 40.96, 81.92, 163.84, 327.68, +]; + +/// Instruments shared by every WebSocket connection; cheap to clone. +#[derive(Debug, Clone)] +pub struct WebSocketMetrics { + connections: UpDownCounter, + queue_wait: Histogram, +} + +impl WebSocketMetrics { + #[must_use] + pub fn new(meter: &Meter) -> Self { + Self { + connections: meter + .i64_up_down_counter("agentic.websocket.connections.active") + .with_unit("{connection}") + .with_description("Responses WebSocket connections being upgraded or open.") + .build(), + queue_wait: meter + .f64_histogram("agentic.websocket.queue.wait.duration") + .with_unit("s") + .with_description( + "Time a response.create waited on its connection before execution started, including 0 for \ + messages dispatched immediately.", + ) + .with_boundaries(QUEUE_WAIT_BOUNDARIES.to_vec()) + .build(), + } + } + + /// Instruments bound to the globally registered meter provider; no-ops + /// when none is installed. + #[must_use] + pub fn from_global() -> Self { + Self::new(&global::meter(INSTRUMENTATION_SCOPE)) + } + + pub(crate) fn connection_opened(&self) { + self.connections.add(1, &[]); + } + + pub(crate) fn connection_closed(&self) { + self.connections.add(-1, &[]); + } + + pub(crate) fn record_queue_wait(&self, waited: Duration) { + self.queue_wait.record(waited.as_secs_f64(), &[]); + } +} From 92873945df4744bd8ca63ce53e6df84ef8b8f460 Mon Sep 17 00:00:00 2001 From: Zheng Lu Date: Fri, 9 Oct 2026 15:29:14 +0100 Subject: [PATCH 2/4] test(telemetry): prove execution metrics finalize once and stay bounded Cover every terminal path on both APIs: completion, upstream failure with and without a stream, a dropped stream, WebSocket requests, disconnects and drains, and a gateway tool round. Each execution is counted once, the first-* timings are ordered, token usage comes from each upstream call, and every exported metric stays within the cardinality allow-list. Also cover the paths added since: a multi-agent response records one rounds sample counting every agent's rounds, and retained WebSocket responses record the first-* timings. The mock upstreams give each response fresh item IDs, as a real upstream does: stored history keys rows by item ID (#385). Signed-off-by: Zheng Lu --- .rust-file-sizes.json | 4 + .../src/executor/engine/multi_agent_tests.rs | 2 + .../engine/multi_agent_tests/metrics.rs | 97 +++ .../tests/execution_metrics/harness.rs | 363 +++++++++++ .../tests/execution_metrics_test.rs | 605 ++++++++++++++++++ .../tests/execution_metrics_test.rs | 399 ++++++++++++ .../tests/telemetry_metrics_e2e_test.rs | 366 +++++++++++ 7 files changed, 1836 insertions(+) create mode 100644 crates/agentic-server-core/src/executor/engine/multi_agent_tests/metrics.rs create mode 100644 crates/agentic-server-core/tests/execution_metrics/harness.rs create mode 100644 crates/agentic-server-core/tests/execution_metrics_test.rs create mode 100644 crates/agentic-server/tests/execution_metrics_test.rs create mode 100644 crates/agentic-server/tests/telemetry_metrics_e2e_test.rs diff --git a/.rust-file-sizes.json b/.rust-file-sizes.json index f65f7df8..8d0f517c 100644 --- a/.rust-file-sizes.json +++ b/.rust-file-sizes.json @@ -28,6 +28,10 @@ "limit": 518, "reason": "Code-interpreter done-only ID backfill remains in the shared output-item slot validation path." }, + "crates/agentic-server-core/src/executor/engine/multi_agent_tests.rs": { + "limit": 501, + "reason": "Declares the multi-agent execution-metrics test module (multi_agent_tests/metrics.rs). The module tree reached the 500-line limit with #432; the tests themselves live in the child file." + }, "crates/agentic-server-core/src/tool/registry.rs": { "limit": 545, "reason": "The web_fetch executor binds through the existing registry validation and executor registration flow, like the code interpreter." diff --git a/crates/agentic-server-core/src/executor/engine/multi_agent_tests.rs b/crates/agentic-server-core/src/executor/engine/multi_agent_tests.rs index d696a291..380976f7 100644 --- a/crates/agentic-server-core/src/executor/engine/multi_agent_tests.rs +++ b/crates/agentic-server-core/src/executor/engine/multi_agent_tests.rs @@ -6,6 +6,8 @@ mod client_tools; mod explicit_compaction; #[path = "multi_agent_tests/live_control.rs"] mod live_control; +#[path = "multi_agent_tests/metrics.rs"] +mod metrics; #[path = "multi_agent_tests/root_completion.rs"] mod root_completion; #[path = "multi_agent_tests/service_tier.rs"] diff --git a/crates/agentic-server-core/src/executor/engine/multi_agent_tests/metrics.rs b/crates/agentic-server-core/src/executor/engine/multi_agent_tests/metrics.rs new file mode 100644 index 00000000..9e452ab8 --- /dev/null +++ b/crates/agentic-server-core/src/executor/engine/multi_agent_tests/metrics.rs @@ -0,0 +1,97 @@ +//! Execution metrics across a multi-agent response. +use super::*; +use opentelemetry::KeyValue; +use opentelemetry::metrics::MeterProvider as _; +use opentelemetry_sdk::metrics::data::{ + AggregatedMetrics, HistogramDataPoint, MetricData, ResourceMetrics, ScopeMetrics, +}; +use opentelemetry_sdk::metrics::{InMemoryMetricExporter, PeriodicReader, SdkMeterProvider}; + +fn has_attribute<'a>(mut attributes: impl Iterator, filter: Option<(&str, &str)>) -> bool { + filter.is_none_or(|(key, value)| attributes.any(|kv| kv.key.as_str() == key && kv.value.to_string() == value)) +} + +/// Number of samples a histogram recorded, optionally filtered by one attribute. +fn samples(export: &ResourceMetrics, name: &str, filter: Option<(&str, &str)>) -> u64 { + let mut count = 0; + for metric in export.scope_metrics().flat_map(ScopeMetrics::metrics) { + if metric.name() != name { + continue; + } + count += match metric.data() { + AggregatedMetrics::U64(MetricData::Histogram(data)) => data + .data_points() + .filter(|point| has_attribute(point.attributes(), filter)) + .map(HistogramDataPoint::count) + .sum::(), + AggregatedMetrics::F64(MetricData::Histogram(data)) => data + .data_points() + .filter(|point| has_attribute(point.attributes(), filter)) + .map(HistogramDataPoint::count) + .sum::(), + other => panic!("{name}: unexpected aggregation {other:?}"), + }; + } + count +} + +/// Sum of an integer histogram's samples. +fn int_sum(export: &ResourceMetrics, name: &str) -> u64 { + export + .scope_metrics() + .flat_map(ScopeMetrics::metrics) + .filter(|metric| metric.name() == name) + .map(|metric| match metric.data() { + AggregatedMetrics::U64(MetricData::Histogram(data)) => { + data.data_points().map(HistogramDataPoint::sum).sum::() + } + other => panic!("{name}: unexpected aggregation {other:?}"), + }) + .sum() +} + +/// One multi-agent execution records one `agentic.inference.rounds` sample +/// covering every agent's rounds, and times its first upstream data even +/// though each round runs on its own pipeline. +#[tokio::test] +async fn multi_agent_execution_records_rounds_and_first_data_once() { + let exporter = InMemoryMetricExporter::default(); + let provider = SdkMeterProvider::builder() + .with_reader(PeriodicReader::builder(exporter.clone()).build()) + .build(); + let (exec, server) = setup().await; + let metrics = crate::executor::telemetry::ExecutorMetrics::new(&provider.meter("agentic_core")); + let exec = Arc::new(ExecutionContext::clone(&exec).with_metrics(metrics)); + let request = RequestPayload { + model: "test".into(), + store: true, + stream: true, + input: ResponsesInput::Text("Compare proposals".into()), + multi_agent: Some(MultiAgentConfig { + enabled: true, + max_concurrent_subagents: Some(2), + }), + ..Default::default() + }; + let result = tokio::time::timeout(Duration::from_secs(15), response(request, exec)).await; + server.abort(); + assert_eq!(result.unwrap().status, "completed"); + + provider.force_flush().unwrap(); + let exports = exporter.get_finished_metrics().unwrap(); + let export = exports.last().expect("an export"); + let rounds = int_sum(export, "agentic.inference.rounds"); + assert_eq!( + samples(export, "agentic.inference.rounds", None), + 1, + "one rounds sample for the whole execution" + ); + assert_eq!( + rounds, + samples(export, "agentic.stage.duration", Some(("agentic.stage", "inference"))), + "every agent's rounds are counted" + ); + assert!(rounds >= 3, "the root and both children ran: {rounds}"); + assert_eq!(samples(export, "agentic.time_to_first_upstream_data", None), 1); + let _ = provider.shutdown(); +} diff --git a/crates/agentic-server-core/tests/execution_metrics/harness.rs b/crates/agentic-server-core/tests/execution_metrics/harness.rs new file mode 100644 index 00000000..14b19c2c --- /dev/null +++ b/crates/agentic-server-core/tests/execution_metrics/harness.rs @@ -0,0 +1,363 @@ +//! Metric capture and the metric cardinality contract, shared by the core +//! and server metric tests. +//! +//! Every test builds its own meter provider with an in-memory exporter, so +//! tests run in parallel without sharing instruments. [`assert_allowed`] is the +//! build-failing cardinality check: an instrument, attribute key, or attribute +//! value outside the tables below fails the test that recorded it. The tables +//! mirror `docs/deploying/observability.md`; change both together. + +#![allow(dead_code)] + +use std::collections::BTreeMap; +use std::time::Duration; + +use agentic_core::executor::telemetry::ExecutorMetrics; +use opentelemetry::metrics::{Meter, MeterProvider as _}; +use opentelemetry_sdk::metrics::data::{AggregatedMetrics, MetricData, ResourceMetrics, ScopeMetrics}; +use opentelemetry_sdk::metrics::{InMemoryMetricExporter, PeriodicReader, SdkMeterProvider}; + +/// Attribute keys each instrument may carry. +const INSTRUMENT_KEYS: &[(&str, &[&str])] = &[ + ( + "agentic.execution.count", + &[ + "agentic.api", + "agentic.route", + "agentic.stream", + "agentic.execution.outcome", + "error.type", + ], + ), + ( + "agentic.execution.active", + &["agentic.api", "agentic.route", "agentic.stream"], + ), + ( + "agentic.execution.duration", + &[ + "agentic.api", + "agentic.route", + "agentic.stream", + "agentic.execution.outcome", + "error.type", + ], + ), + ( + "agentic.delivery.count", + &[ + "agentic.api", + "agentic.route", + "agentic.stream", + "agentic.delivery.outcome", + ], + ), + ("agentic.delivery.wait.duration", &["agentic.api"]), + ( + "agentic.stage.duration", + &["agentic.stage", "agentic.tool.type", "error.type"], + ), + ("agentic.inference.rounds", &["agentic.api"]), + ( + "gen_ai.client.token.usage", + &["gen_ai.operation.name", "gen_ai.token.type", "agentic.api"], + ), + ("agentic.time_to_first_upstream_data", &["agentic.api"]), + ("agentic.time_to_first_client_event", &["agentic.api"]), + ("agentic.time_to_first_text", &["agentic.api"]), + ("agentic.websocket.connections.active", &[]), + ("agentic.websocket.queue.wait.duration", &[]), + ( + "http.server.request.duration", + &[ + "http.request.method", + "url.scheme", + "http.route", + "http.response.status_code", + ], + ), + ("http.server.active_requests", &["http.request.method", "url.scheme"]), +]; + +/// Values each attribute key may take. Keys absent here are checked by +/// [`value_allowed`]. +const KEY_VALUES: &[(&str, &[&str])] = &[ + ("agentic.api", &["responses", "messages"]), + ("agentic.route", &["executor", "proxy"]), + ("agentic.stream", &["true", "false"]), + ( + "agentic.execution.outcome", + &["completed", "incomplete", "failed", "cancelled"], + ), + ( + "agentic.delivery.outcome", + &["delivered", "disconnected", "not_started"], + ), + ( + "error.type", + &[ + "storage", + "persistence", + "conversation_locked", + "upstream_status", + "upstream_transport", + "network", + "parse", + "stream", + "not_found", + "invalid_request", + "payload_too_large", + "resource_limit", + "conflict", + "compaction", + "tool", + "upstream_error", + "round_budget", + "panic", + "cancelled", + ], + ), + ( + "agentic.stage", + &["rehydrate", "inference", "tool", "compaction", "persist"], + ), + ( + "agentic.tool.type", + &[ + "function", + "tool_search", + "custom", + "shell", + "codex_namespace", + "mcp", + "web_search", + "file_search", + "code_interpreter", + ], + ), + ("gen_ai.operation.name", &["chat"]), + ("gen_ai.token.type", &["input", "output"]), + ( + "http.request.method", + &[ + "CONNECT", "DELETE", "GET", "HEAD", "OPTIONS", "PATCH", "POST", "PUT", "TRACE", "_OTHER", + ], + ), + ("url.scheme", &["http"]), +]; + +/// One exported data point, flattened. +#[derive(Debug, Clone)] +pub struct Point { + pub name: String, + pub attributes: BTreeMap, + pub value: PointValue, +} + +#[derive(Debug, Clone, Copy)] +pub enum PointValue { + /// A counter or up-down counter value. + Sum(i64), + /// A histogram of seconds. + Histogram { count: u64, sum: f64 }, + /// A histogram of integers: tokens or rounds. + IntHistogram { count: u64, sum: u64 }, +} + +impl Point { + fn matches(&self, name: &str, filters: &[(&str, &str)]) -> bool { + self.name == name + && filters + .iter() + .all(|(key, value)| self.attributes.get(*key).is_some_and(|actual| actual == value)) + } +} + +/// A meter provider whose exports stay in memory for one test. +pub struct Metrics { + provider: SdkMeterProvider, + exporter: InMemoryMetricExporter, +} + +impl Metrics { + pub fn new() -> Self { + let exporter = InMemoryMetricExporter::default(); + let provider = SdkMeterProvider::builder() + .with_reader(PeriodicReader::builder(exporter.clone()).build()) + .build(); + Self { provider, exporter } + } + + pub fn meter(&self, scope: &'static str) -> Meter { + self.provider.meter(scope) + } + + /// Executor instruments bound to this provider. + pub fn executor(&self) -> ExecutorMetrics { + ExecutorMetrics::new(&self.meter("agentic_core")) + } + + /// Every data point of the latest (cumulative) export. + pub fn points(&self) -> Vec { + self.provider.force_flush().unwrap(); + let exports = self.exporter.get_finished_metrics().unwrap(); + exports.last().map(sdk_points).unwrap_or_default() + } + + /// Poll until `ready` holds, then check the cardinality contract. + /// + /// Executions finalize when their guard drops, which can land a few + /// milliseconds after the request future returns (a stream reaped on a + /// later tick, a `sqlx` worker releasing a span). + pub async fn wait_for(&self, what: &str, ready: impl Fn(&[Point]) -> bool) -> Vec { + let deadline = tokio::time::Instant::now() + Duration::from_secs(5); + loop { + let points = self.points(); + if ready(&points) { + assert_allowed(&points); + return points; + } + assert!( + tokio::time::Instant::now() < deadline, + "timed out waiting for {what}: {points:#?}" + ); + tokio::time::sleep(Duration::from_millis(5)).await; + } + } +} + +impl Drop for Metrics { + fn drop(&mut self) { + let _ = self.provider.shutdown(); + } +} + +fn sdk_points(export: &ResourceMetrics) -> Vec { + let mut points = Vec::new(); + for metric in export.scope_metrics().flat_map(ScopeMetrics::metrics) { + let name = metric.name().to_owned(); + let mut push = |attributes: BTreeMap, value| { + points.push(Point { + name: name.clone(), + attributes, + value, + }); + }; + match metric.data() { + AggregatedMetrics::U64(MetricData::Sum(sum)) => { + for p in sum.data_points() { + let value = PointValue::Sum(i64::try_from(p.value()).unwrap()); + push(attributes(p.attributes()), value); + } + } + AggregatedMetrics::I64(MetricData::Sum(sum)) => { + for p in sum.data_points() { + push(attributes(p.attributes()), PointValue::Sum(p.value())); + } + } + AggregatedMetrics::F64(MetricData::Histogram(histogram)) => { + for p in histogram.data_points() { + let value = PointValue::Histogram { + count: p.count(), + sum: p.sum(), + }; + push(attributes(p.attributes()), value); + } + } + AggregatedMetrics::U64(MetricData::Histogram(histogram)) => { + for p in histogram.data_points() { + let value = PointValue::IntHistogram { + count: p.count(), + sum: p.sum(), + }; + push(attributes(p.attributes()), value); + } + } + other => panic!("{name}: unexpected aggregation {other:?}"), + } + } + points +} + +fn attributes<'a>(kvs: impl Iterator) -> BTreeMap { + kvs.map(|kv| (kv.key.to_string(), kv.value.to_string())).collect() +} + +/// Sum of matching counter values, or number of matching histogram samples. +pub fn total(points: &[Point], name: &str, filters: &[(&str, &str)]) -> i64 { + points + .iter() + .filter(|point| point.matches(name, filters)) + .map(|point| match point.value { + PointValue::Sum(value) => value, + PointValue::Histogram { count, .. } | PointValue::IntHistogram { count, .. } => { + i64::try_from(count).unwrap() + } + }) + .sum() +} + +/// Sum of the seconds recorded into matching histogram points. +pub fn histogram_sum(points: &[Point], name: &str, filters: &[(&str, &str)]) -> f64 { + points + .iter() + .filter(|point| point.matches(name, filters)) + .map(|point| match point.value { + PointValue::Histogram { sum, .. } => sum, + _ => panic!("{name} is not a histogram of seconds"), + }) + .sum() +} + +/// Sum of the integers recorded into matching histogram points. +pub fn int_histogram_sum(points: &[Point], name: &str, filters: &[(&str, &str)]) -> u64 { + points + .iter() + .filter(|point| point.matches(name, filters)) + .map(|point| match point.value { + PointValue::IntHistogram { sum, .. } => sum, + _ => panic!("{name} is not an integer histogram"), + }) + .sum() +} + +/// Whether any point of `name` exists at all. +pub fn recorded(points: &[Point], name: &str) -> bool { + points.iter().any(|point| point.name == name) +} + +/// Fail on any instrument, attribute key, or attribute value outside the +/// cardinality contract. +pub fn assert_allowed(points: &[Point]) { + for point in points { + let keys = INSTRUMENT_KEYS + .iter() + .find(|(name, _)| *name == point.name) + .unwrap_or_else(|| panic!("instrument {} is not in the metric allow-list", point.name)) + .1; + for (key, value) in &point.attributes { + assert!( + keys.contains(&key.as_str()), + "{}: attribute {key} is not allowed on this instrument", + point.name + ); + assert!( + value_allowed(key, value), + "{}: {key}={value:?} is outside the allowed values", + point.name + ); + } + } +} + +fn value_allowed(key: &str, value: &str) -> bool { + if let Some((_, values)) = KEY_VALUES.iter().find(|(allowed, _)| *allowed == key) { + return values.contains(&value); + } + match key { + // Route templates come from the router, never the request target. + "http.route" => value.starts_with('/') && !value.contains('?'), + "http.response.status_code" => value.parse::().is_ok_and(|status| (100..=599).contains(&status)), + _ => false, + } +} diff --git a/crates/agentic-server-core/tests/execution_metrics_test.rs b/crates/agentic-server-core/tests/execution_metrics_test.rs new file mode 100644 index 00000000..0b80c0fa --- /dev/null +++ b/crates/agentic-server-core/tests/execution_metrics_test.rs @@ -0,0 +1,605 @@ +//! Execution metrics through the real executor against mock and recorded +//! upstreams, captured by a per-test in-memory meter provider. +//! +//! No `tracing` subscriber is installed in this binary: every assertion +//! here holds without a tracer, which is what makes the metrics independent +//! of the trace sampling decision. + +use std::fmt::Write as _; +use std::sync::Arc; + +use agentic_core::executor::{ + BoxStream, ExecuteRequest, ExecutionContext, ExecutorResult, MessagesRequestContext, MessagesUpstream, + run_messages_loop, run_messages_stream, +}; +use agentic_core::storage::{ConversationStore, ResponseStore}; +use agentic_core::tool::ToolRegistry; +use agentic_core::types::request_response::{RequestPayload, ResponsePayload}; +use either::Either; +use futures::StreamExt as _; +use serde_json::json; + +#[path = "execution_metrics/harness.rs"] +mod harness; +mod support; +use harness::{Metrics, histogram_sum, int_histogram_sum, recorded, total}; +use support::{MockResponse, MockServer, TestFixture, text_response}; + +const RESPONSES_EXECUTOR: &[(&str, &str)] = &[("agentic.api", "responses"), ("agentic.route", "executor")]; + +fn request(stream: bool) -> RequestPayload { + support::make_request("say one word", true, stream, None, None) +} + +/// The fixture's context, recording into `metrics`. +fn measured(exec_ctx: &Arc, metrics: &Metrics) -> Arc { + Arc::new(ExecutionContext::clone(exec_ctx).with_metrics(metrics.executor())) +} + +#[allow(clippy::result_large_err)] +async fn execute( + exec_ctx: Arc, + payload: RequestPayload, +) -> ExecutorResult> { + Box::pin(ExecuteRequest::new(payload, exec_ctx).run()).await +} + +async fn stream_of(exec_ctx: Arc, payload: RequestPayload) -> BoxStream { + match execute(exec_ctx, payload).await.unwrap() { + Either::Right(stream) => stream, + Either::Left(_) => panic!("streaming request returns a stream"), + } +} + +/// A minimal upstream stream: created, one text delta, completed without usage. +fn streaming_text_response(text: &str) -> MockResponse { + let message = json!({ + "id": "msg_upstream", "type": "message", "role": "assistant", "status": "completed", + "content": [{"type": "output_text", "text": text, "annotations": []}] + }); + let events = [ + json!({"type": "response.created", "sequence_number": 0, + "response": {"id": "resp_upstream", "status": "in_progress"}}), + json!({"type": "response.output_item.added", "sequence_number": 1, "output_index": 0, + "item": {"id": "msg_upstream", "type": "message", "role": "assistant", + "status": "in_progress", "content": []}}), + json!({"type": "response.output_text.delta", "sequence_number": 2, "output_index": 0, + "content_index": 0, "delta": text}), + json!({"type": "response.output_item.done", "sequence_number": 3, "output_index": 0, "item": message}), + json!({"type": "response.completed", "sequence_number": 4, + "response": {"id": "resp_upstream", "status": "completed", "usage": null, "output": [message]}}), + ]; + let mut body = String::new(); + for event in events { + writeln!(body, "data: {event}\n").unwrap(); + } + body.push_str("data: [DONE]\n\n"); + MockResponse::Sse(body) +} + +fn upstream_502() -> MockResponse { + MockResponse::Status( + 502, + r#"{"error":{"message":"upstream secret detail","type":"server_error"}}"#.to_owned(), + ) +} + +/// The execution was counted exactly once with `outcome`, and its active +/// count was released. +fn assert_finalized_once(points: &[harness::Point], stream: &str, outcome: &str, delivery: &str) { + let filters = [RESPONSES_EXECUTOR, &[("agentic.stream", stream)]].concat(); + assert_eq!( + total(points, "agentic.execution.count", &[]), + 1, + "one execution in total" + ); + let outcome_filter = [filters.as_slice(), &[("agentic.execution.outcome", outcome)]].concat(); + assert_eq!(total(points, "agentic.execution.count", &outcome_filter), 1); + assert_eq!(total(points, "agentic.execution.duration", &outcome_filter), 1); + let delivery_filter = [filters.as_slice(), &[("agentic.delivery.outcome", delivery)]].concat(); + assert_eq!(total(points, "agentic.delivery.count", &[]), 1); + assert_eq!(total(points, "agentic.delivery.count", &delivery_filter), 1); + assert!( + recorded(points, "agentic.execution.active"), + "the active count was taken" + ); + assert_eq!(total(points, "agentic.execution.active", &[]), 0, "and released"); +} + +fn finalized(points: &[harness::Point]) -> bool { + total(points, "agentic.execution.count", &[]) >= 1 +} + +#[tokio::test] +async fn blocking_completion_records_each_instrument_once() { + let metrics = Metrics::new(); + let fixture = TestFixture::new_with_responses(vec![text_response("hello")]).await; + + let result = execute(measured(&fixture.exec_ctx, &metrics), request(false)).await; + assert!(matches!(result, Ok(Either::Left(_)))); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_finalized_once(&points, "false", "completed", "delivered"); + assert_eq!( + total(&points, "agentic.execution.count", &[("error.type", "storage")]), + 0 + ); + for stage in ["rehydrate", "inference", "persist"] { + assert_eq!( + total(&points, "agentic.stage.duration", &[("agentic.stage", stage)]), + 1, + "{stage}" + ); + } + assert!( + points + .iter() + .filter(|point| point.name == "agentic.stage.duration") + .all(|point| !point.attributes.contains_key("error.type")), + "no stage failed" + ); + assert_eq!(total(&points, "agentic.inference.rounds", &[]), 1); + assert_eq!(int_histogram_sum(&points, "agentic.inference.rounds", &[]), 1); + assert!( + !recorded(&points, "gen_ai.client.token.usage"), + "the upstream sent `usage: null`; nothing is fabricated" + ); + for timing in [ + "agentic.time_to_first_upstream_data", + "agentic.time_to_first_client_event", + "agentic.time_to_first_text", + "agentic.delivery.wait.duration", + ] { + assert!(!recorded(&points, timing), "{timing} is only for streamed executions"); + } +} + +#[tokio::test] +async fn recorded_stream_orders_first_timings_and_reports_upstream_usage() { + let metrics = Metrics::new(); + let cassette = support::load_cassette(concat!( + env!("CARGO_MANIFEST_DIR"), + "/tests/cassettes/text_only/responses/resp-single-gpt-4o-streaming.yaml" + )); + let fixture = TestFixture::new(&support::responses_turns(&cassette)).await; + + let frames: Vec = stream_of(measured(&fixture.exec_ctx, &metrics), request(true)) + .await + .collect() + .await; + assert!(frames.iter().any(|frame| frame.contains("response.output_text.delta"))); + assert!(frames.iter().any(|frame| frame.contains("response.completed"))); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_finalized_once(&points, "true", "completed", "delivered"); + let api = [("agentic.api", "responses")]; + let first_upstream = histogram_sum(&points, "agentic.time_to_first_upstream_data", &api); + let first_event = histogram_sum(&points, "agentic.time_to_first_client_event", &api); + let first_text = histogram_sum(&points, "agentic.time_to_first_text", &api); + for timing in [ + "agentic.time_to_first_upstream_data", + "agentic.time_to_first_client_event", + "agentic.time_to_first_text", + ] { + assert_eq!(total(&points, timing, &api), 1, "{timing} is recorded once"); + } + assert!( + 0.0 < first_upstream && first_upstream <= first_event && first_event <= first_text, + "upstream {first_upstream} <= client event {first_event} <= text {first_text}" + ); + assert_eq!(total(&points, "agentic.delivery.wait.duration", &api), 1); + + // The cassette's `response.completed` reports 14 input and 4 output tokens. + let input = [("gen_ai.token.type", "input"), ("gen_ai.operation.name", "chat")]; + let output = [("gen_ai.token.type", "output"), ("gen_ai.operation.name", "chat")]; + assert_eq!(total(&points, "gen_ai.client.token.usage", &input), 1); + assert_eq!(int_histogram_sum(&points, "gen_ai.client.token.usage", &input), 14); + assert_eq!(int_histogram_sum(&points, "gen_ai.client.token.usage", &output), 4); +} + +#[tokio::test] +async fn upstream_failure_in_a_stream_is_one_delivered_failure() { + let metrics = Metrics::new(); + let fixture = TestFixture::new_with_responses(vec![upstream_502()]).await; + + let frames: Vec = stream_of(measured(&fixture.exec_ctx, &metrics), request(true)) + .await + .collect() + .await; + assert!( + frames.iter().any(|frame| frame.starts_with("event: error")), + "{frames:?}" + ); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_finalized_once(&points, "true", "failed", "delivered"); + assert_eq!( + total(&points, "agentic.execution.count", &[("error.type", "upstream_status")]), + 1 + ); + assert_eq!( + total( + &points, + "agentic.stage.duration", + &[("agentic.stage", "inference"), ("error.type", "upstream_status")] + ), + 1 + ); + assert!(!recorded(&points, "gen_ai.client.token.usage")); + // No upstream line arrived and an executor error frame is not a response + // event, so no first-* timing describes this execution. + for timing in [ + "agentic.time_to_first_upstream_data", + "agentic.time_to_first_client_event", + "agentic.time_to_first_text", + ] { + assert!(!recorded(&points, timing), "{timing}"); + } +} + +#[tokio::test] +async fn upstream_failure_without_a_stream_is_never_delivered() { + let metrics = Metrics::new(); + let fixture = TestFixture::new_with_responses(vec![upstream_502()]).await; + + assert!( + execute(measured(&fixture.exec_ctx, &metrics), request(false)) + .await + .is_err() + ); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_finalized_once(&points, "false", "failed", "not_started"); + assert_eq!(total(&points, "agentic.inference.rounds", &[]), 1); +} + +#[tokio::test] +async fn dropped_stream_is_one_cancelled_and_disconnected_execution() { + let metrics = Metrics::new(); + let fixture = TestFixture::new_with_responses(vec![streaming_text_response("hello")]).await; + + let mut stream = stream_of(measured(&fixture.exec_ctx, &metrics), request(true)).await; + let first = stream.next().await.expect("at least one frame"); + assert!(first.contains("response.created"), "{first}"); + // The client goes away before the terminal frame. + drop(stream); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_finalized_once(&points, "true", "cancelled", "disconnected"); + assert!( + points + .iter() + .filter(|point| point.name == "agentic.execution.count") + .all(|point| !point.attributes.contains_key("error.type")), + "cancellation is not a failure" + ); + assert_eq!( + total(&points, "agentic.time_to_first_client_event", &[]), + 1, + "the first event reached the transport" + ); +} + +#[tokio::test] +async fn gateway_tool_round_counts_rounds_and_times_the_tool() { + let metrics = Metrics::new(); + let cassette = support::load_cassette(concat!( + env!("CARGO_MANIFEST_DIR"), + "/tests/cassettes/codex/codex-openai-web-search-then-namespace-gpt-4o-streaming.yaml" + )); + let fixture = TestFixture::new(&support::responses_turns(&cassette)).await; + let search = search_server().await; + let exec_ctx = ExecutionContext::clone(&fixture.exec_ctx) + .with_gateway_executor(Arc::new(agentic_core::tool::WebSearchHandler::with_api_key( + Arc::new(reqwest::Client::new()), + "private-search-key".into(), + &search.0, + ))) + .with_metrics(metrics.executor()); + let mut payload = request(true); + payload.tools = Some( + serde_json::from_value(json!([ + {"type":"web_search_preview"}, + {"type":"namespace","name":"mcp__shell","tools":[{"type":"function","name":"run","parameters":{"type":"object"}}]} + ])) + .unwrap(), + ); + + let frames: Vec = stream_of(Arc::new(exec_ctx), payload).await.collect().await; + search.1.abort(); + assert!(frames.iter().any(|frame| frame.contains("response.completed"))); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_finalized_once(&points, "true", "completed", "delivered"); + assert_eq!(total(&points, "agentic.inference.rounds", &[]), 1); + assert_eq!(int_histogram_sum(&points, "agentic.inference.rounds", &[]), 2); + assert_eq!( + total(&points, "agentic.stage.duration", &[("agentic.stage", "inference")]), + 2 + ); + assert_eq!( + total( + &points, + "agentic.stage.duration", + &[("agentic.stage", "tool"), ("agentic.tool.type", "web_search")] + ), + 1 + ); + assert_eq!( + total(&points, "gen_ai.client.token.usage", &[("gen_ai.token.type", "input")]), + 2, + "one sample per upstream call, not per turn" + ); +} + +#[tokio::test] +async fn explicit_compaction_times_its_stages_and_usage_without_an_execution() { + let metrics = Metrics::new(); + let summary = MockResponse::Json( + json!({ + "id": "resp_upstream", "object": "response", "created_at": 0, "model": "test-model", + "status": "completed", + "output": [{"id": "msg_upstream", "type": "message", "role": "assistant", "status": "completed", + "content": [{"type": "output_text", "text": "summary", "annotations": []}]}], + "usage": {"input_tokens": 11, "input_tokens_details": {"cached_tokens": 0}, "output_tokens": 3, + "output_tokens_details": {"reasoning_tokens": 0}, "total_tokens": 14} + }) + .to_string(), + ); + let fixture = TestFixture::new_with_responses(vec![summary]).await; + let payload = serde_json::from_value(json!({"model": "test-model", "input": "compact me"})).unwrap(); + + Box::pin(agentic_core::executor::compact_response( + payload, + &measured(&fixture.exec_ctx, &metrics), + None, + )) + .await + .unwrap(); + + let points = metrics + .wait_for("persist stage", |points| { + total(points, "agentic.stage.duration", &[("agentic.stage", "persist")]) == 1 + }) + .await; + for stage in ["rehydrate", "compaction", "persist"] { + assert_eq!( + total(&points, "agentic.stage.duration", &[("agentic.stage", stage)]), + 1, + "{stage}" + ); + } + assert_eq!( + int_histogram_sum(&points, "gen_ai.client.token.usage", &[("gen_ai.token.type", "input")]), + 11 + ); + assert!( + !recorded(&points, "agentic.execution.count"), + "compaction has no agentic.execute span" + ); +} + +async fn search_server() -> (String, tokio::task::JoinHandle<()>) { + let listener = tokio::net::TcpListener::bind("127.0.0.1:0").await.unwrap(); + let url = format!("http://{}", listener.local_addr().unwrap()); + let router = axum::Router::new().route( + "/v1/search", + axum::routing::get(|| async { + axum::Json(json!({"results":{"web":[{"url":"https://example.com","title":"result"}],"news":[]}})) + }), + ); + let task = tokio::spawn(async move { axum::serve(listener, router).await.unwrap() }); + (url, task) +} + +struct MessagesFixture { + exec_ctx: Arc, + upstream: MessagesUpstream, + _server: MockServer, +} + +async fn messages_fixture(metrics: &Metrics, responses: Vec) -> MessagesFixture { + let server = MockServer::start_deque_on("/v1/messages", responses).await; + let pool = support::setup_pool().await; + let exec_ctx = ExecutionContext::new( + agentic_core::executor::ConversationHandler::new(ConversationStore::new(Arc::clone(&pool))), + agentic_core::executor::ResponseHandler::new(ResponseStore::new(pool)), + Arc::new(reqwest::Client::new()), + server.url().to_owned(), + ) + .with_metrics(metrics.executor()); + let upstream = MessagesUpstream::new(server.url(), None, reqwest::header::HeaderMap::new()); + MessagesFixture { + exec_ctx: Arc::new(exec_ctx), + upstream, + _server: server, + } +} + +fn messages_request(stream: bool) -> MessagesRequestContext { + MessagesRequestContext::from_value(json!({ + "model": "test-model", "max_tokens": 64, "stream": stream, + "messages": [{"role": "user", "content": "say one word"}] + })) + .unwrap() +} + +fn messages_sse_response() -> MockResponse { + let events = [ + json!({"type": "message_start", "message": { + "id": "msg_upstream", "type": "message", "role": "assistant", "model": "test-model", + "content": [], "stop_reason": null, "stop_sequence": null, + "usage": {"input_tokens": 3, "output_tokens": 0, "cache_read_input_tokens": 5}}}), + json!({"type": "content_block_start", "index": 0, "content_block": {"type": "text", "text": ""}}), + json!({"type": "content_block_delta", "index": 0, "delta": {"type": "text_delta", "text": "hello"}}), + json!({"type": "content_block_stop", "index": 0}), + json!({"type": "message_delta", "delta": {"stop_reason": "end_turn", "stop_sequence": null}, + "usage": {"output_tokens": 2}}), + json!({"type": "message_stop"}), + ]; + let mut body = String::new(); + for event in events { + writeln!(body, "event: {}\ndata: {event}\n", event["type"].as_str().unwrap()).unwrap(); + } + MockResponse::Sse(body) +} + +fn assert_messages_finalized_once(points: &[harness::Point], stream: &str, outcome: &str, delivery: &str) { + let filters = [ + ("agentic.api", "messages"), + ("agentic.route", "executor"), + ("agentic.stream", stream), + ]; + let outcome_filter = [filters.as_slice(), &[("agentic.execution.outcome", outcome)]].concat(); + let delivery_filter = [filters.as_slice(), &[("agentic.delivery.outcome", delivery)]].concat(); + assert_eq!(total(points, "agentic.execution.count", &[]), 1); + assert_eq!(total(points, "agentic.execution.count", &outcome_filter), 1); + assert_eq!(total(points, "agentic.delivery.count", &delivery_filter), 1); + assert_eq!(total(points, "agentic.execution.active", &[]), 0); +} + +#[tokio::test] +async fn messages_loop_reports_prompt_tokens_including_cache_reads() { + let metrics = Metrics::new(); + let response = MockResponse::Json( + json!({ + "id": "msg_upstream", "type": "message", "role": "assistant", "model": "test-model", + "content": [{"type": "text", "text": "hello"}], "stop_reason": "end_turn", "stop_sequence": null, + "usage": {"input_tokens": 3, "output_tokens": 1, "cache_read_input_tokens": 5} + }) + .to_string(), + ); + let fixture = messages_fixture(&metrics, vec![response]).await; + + run_messages_loop( + messages_request(false), + &ToolRegistry::default(), + &fixture.exec_ctx, + &fixture.upstream, + ) + .await + .unwrap(); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_messages_finalized_once(&points, "false", "completed", "delivered"); + let api = ("agentic.api", "messages"); + assert_eq!( + int_histogram_sum( + &points, + "gen_ai.client.token.usage", + &[api, ("gen_ai.token.type", "input")] + ), + 8, + "input_tokens plus cache reads" + ); + assert_eq!( + int_histogram_sum( + &points, + "gen_ai.client.token.usage", + &[api, ("gen_ai.token.type", "output")] + ), + 1 + ); + assert_eq!( + total(&points, "agentic.stage.duration", &[("agentic.stage", "inference")]), + 1 + ); + assert_eq!(total(&points, "agentic.inference.rounds", &[api]), 1); +} + +#[tokio::test] +async fn messages_stream_orders_first_timings_and_reports_final_round_usage() { + let metrics = Metrics::new(); + let fixture = messages_fixture(&metrics, vec![messages_sse_response()]).await; + + let response = run_messages_stream( + messages_request(true), + Arc::new(ToolRegistry::default()), + Arc::clone(&fixture.exec_ctx), + fixture.upstream.clone(), + ) + .await + .unwrap(); + let frames: Vec = response.body.collect().await; + assert!(frames.iter().any(|frame| frame.contains("text_delta")), "{frames:?}"); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_messages_finalized_once(&points, "true", "completed", "delivered"); + let api = [("agentic.api", "messages")]; + let first_upstream = histogram_sum(&points, "agentic.time_to_first_upstream_data", &api); + let first_event = histogram_sum(&points, "agentic.time_to_first_client_event", &api); + let first_text = histogram_sum(&points, "agentic.time_to_first_text", &api); + assert!( + 0.0 < first_upstream && first_upstream <= first_event && first_event <= first_text, + "upstream {first_upstream} <= client event {first_event} <= text {first_text}" + ); + // `message_start.usage` overlaid by the final `message_delta.usage`. + assert_eq!( + int_histogram_sum( + &points, + "gen_ai.client.token.usage", + &[api[0], ("gen_ai.token.type", "input")] + ), + 8 + ); + assert_eq!( + int_histogram_sum( + &points, + "gen_ai.client.token.usage", + &[api[0], ("gen_ai.token.type", "output")] + ), + 2 + ); + assert_eq!(total(&points, "agentic.delivery.wait.duration", &api), 1); +} + +#[tokio::test] +async fn messages_stream_rejected_before_headers_is_never_delivered() { + let metrics = Metrics::new(); + let fixture = messages_fixture(&metrics, vec![upstream_502()]).await; + + let rejected = run_messages_stream( + messages_request(true), + Arc::new(ToolRegistry::default()), + Arc::clone(&fixture.exec_ctx), + fixture.upstream.clone(), + ) + .await; + assert!(rejected.is_err()); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_messages_finalized_once(&points, "true", "failed", "not_started"); + assert_eq!( + total( + &points, + "agentic.stage.duration", + &[("agentic.stage", "inference"), ("error.type", "upstream_status")] + ), + 1 + ); +} + +/// The cardinality check is what fails the build on a new dimension, so it +/// must reject each kind of violation. +#[test] +fn cardinality_contract_rejects_unlisted_instruments_keys_and_values() { + fn violation(name: &str, key: &str, value: &str) -> bool { + let point = harness::Point { + name: name.to_owned(), + attributes: [(key.to_owned(), value.to_owned())].into(), + value: harness::PointValue::Sum(1), + }; + std::panic::catch_unwind(|| harness::assert_allowed(&[point])).is_err() + } + assert!(!violation("agentic.execution.count", "agentic.api", "responses")); + assert!(violation("agentic.execution.count", "response.id", "resp_123")); + assert!(violation("agentic.execution.count", "agentic.api", "gpt-4o")); + assert!(violation("agentic.stage.duration", "agentic.tool.name", "my_tool")); + assert!(violation("gen_ai.client.token.usage", "gen_ai.request.model", "gpt-4o")); + assert!(violation("agentic.unlisted.metric", "agentic.api", "responses")); + assert!(violation( + "http.server.request.duration", + "http.route", + "/v1/responses?x=1" + )); +} diff --git a/crates/agentic-server/tests/execution_metrics_test.rs b/crates/agentic-server/tests/execution_metrics_test.rs new file mode 100644 index 00000000..973a62fb --- /dev/null +++ b/crates/agentic-server/tests/execution_metrics_test.rs @@ -0,0 +1,399 @@ +//! Execution and transport metrics through the production router, over HTTP +//! and WebSocket, against a scripted upstream. +//! +//! Each test owns its meter provider, so tests run in parallel. Hard process +//! shutdown is covered by `telemetry_metrics_e2e_test.rs`; here shutdown is +//! the gateway's drain signal. + +use std::sync::Arc; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::time::Duration; + +use axum::body::{Body, Bytes}; +use axum::response::{IntoResponse as _, Response}; +use futures::{SinkExt as _, StreamExt as _}; +use serde_json::{Value, json}; +use tokio::sync::Notify; +use tokio_tungstenite::tungstenite::Message; + +use agentic_core::executor::{ConversationHandler, ExecutionContext, ResponseHandler}; +use agentic_core::storage::{ConversationStore, ResponseStore, create_pool_with_schema}; +use agentic_server::app::{AppState, ServerConfig, WebSocketTracker, build_router}; +use agentic_server::telemetry::websocket::WebSocketMetrics; + +#[allow(dead_code)] +mod common; +#[path = "../../agentic-server-core/tests/execution_metrics/harness.rs"] +mod harness; +use harness::{Metrics, Point, total}; + +static DATABASE: AtomicU64 = AtomicU64::new(0); +/// Like a real upstream, each response gets fresh item IDs: stored history +/// keys rows by public item ID, so a repeated ID cannot be stored twice (#385). +static ITEM: AtomicU64 = AtomicU64::new(0); + +fn fresh_item_id(template: &str) -> String { + template.replace("msg_up", &format!("msg_up_{}", ITEM.fetch_add(1, Ordering::Relaxed))) +} + +const USAGE: &str = r#"{"input_tokens":7,"input_tokens_details":{"cached_tokens":0},"output_tokens":2,"output_tokens_details":{"reasoning_tokens":0},"total_tokens":9}"#; + +fn sse_events(usage: &str) -> (String, String) { + let message = r#"{"id":"msg_up","type":"message","role":"assistant","status":"completed","content":[{"type":"output_text","text":"hi","annotations":[]}]}"#; + let head = r#"data: {"type":"response.created","sequence_number":0,"response":{"id":"resp_up","status":"in_progress","output":[]}} + +"# + .to_owned(); + let tail = format!( + "data: {{\"type\":\"response.output_item.added\",\"sequence_number\":1,\"output_index\":0,\"item\":{{\"id\":\"msg_up\",\"type\":\"message\",\"role\":\"assistant\",\"status\":\"in_progress\",\"content\":[]}}}}\n\n\ + data: {{\"type\":\"response.output_text.delta\",\"sequence_number\":2,\"output_index\":0,\"content_index\":0,\"delta\":\"hi\"}}\n\n\ + data: {{\"type\":\"response.output_item.done\",\"sequence_number\":3,\"output_index\":0,\"item\":{message}}}\n\n\ + data: {{\"type\":\"response.completed\",\"sequence_number\":4,\"response\":{{\"id\":\"resp_up\",\"status\":\"completed\",\"output\":[{message}],\"usage\":{usage}}}}}\n\n\ + data: [DONE]\n\n" + ); + (head, tail) +} + +fn json_body() -> String { + json!({ + "id": "resp_up", "object": "response", "created_at": 0, "model": "test-model", "status": "completed", + "output": [{"id": "msg_up", "type": "message", "role": "assistant", "status": "completed", + "content": [{"type": "output_text", "text": "hi", "annotations": []}]}], + "usage": serde_json::from_str::(USAGE).unwrap() + }) + .to_string() +} + +/// An upstream scripted by the prompt: `FAIL` answers 502, `HANG` streams +/// `response.created` and then waits for `release`, anything else completes. +async fn upstream(release: Arc) -> Server { + let router = axum::Router::new().route( + "/v1/responses", + axum::routing::post(move |body: Bytes| { + let release = Arc::clone(&release); + async move { scripted(&body, release) } + }), + ); + Server::start(router).await +} + +fn scripted(body: &[u8], release: Arc) -> Response { + let text = String::from_utf8_lossy(body); + if text.contains("FAIL") { + return ( + http::StatusCode::BAD_GATEWAY, + r#"{"error":{"message":"upstream secret","type":"server_error"}}"#, + ) + .into_response(); + } + let stream = serde_json::from_slice::(body).unwrap()["stream"] == true; + if !stream { + return ([("content-type", "application/json")], fresh_item_id(&json_body())).into_response(); + } + let (head, tail) = sse_events(USAGE); + let tail = fresh_item_id(&tail); + let hang = text.contains("HANG"); + let rest = futures::stream::once(async move { + if hang { + release.notified().await; + } + Ok::<_, std::io::Error>(Bytes::from(tail)) + }); + let body = futures::stream::once(std::future::ready(Ok(Bytes::from(head)))).chain(rest); + ([("content-type", "text/event-stream")], Body::from_stream(body)).into_response() +} + +struct Server { + url: String, + task: tokio::task::JoinHandle<()>, +} + +impl Server { + async fn start(router: axum::Router) -> Self { + let listener = tokio::net::TcpListener::bind("127.0.0.1:0").await.unwrap(); + let url = format!("http://{}", listener.local_addr().unwrap()); + let task = tokio::spawn(async move { axum::serve(listener, router).await.unwrap() }); + Self { url, task } + } +} + +impl Drop for Server { + fn drop(&mut self) { + self.task.abort(); + } +} + +async fn gateway_state(upstream: &str, metrics: &Metrics) -> AppState { + let id = DATABASE.fetch_add(1, Ordering::Relaxed); + let pool = create_pool_with_schema(Some(&format!("sqlite:file:metrics_{id}?mode=memory&cache=shared"))) + .await + .unwrap(); + let mut state = common::test_state(&common::test_config(upstream)); + state.exec_ctx = Arc::new( + ExecutionContext::new( + ConversationHandler::new(ConversationStore::new(pool.clone())), + ResponseHandler::new(ResponseStore::new(pool)), + Arc::new(reqwest::Client::new()), + upstream.to_owned(), + ) + .with_metrics(metrics.executor()), + ); + state.websocket_tracker = WebSocketTracker::with_metrics(WebSocketMetrics::new(&metrics.meter("agentic_server"))); + state +} + +async fn gateway(state: AppState) -> Server { + Server::start(build_router(state, &ServerConfig::from_env())).await +} + +fn request(prompt: &str, stream: bool, store: bool) -> Value { + json!({"model": "test-model", "input": prompt, "stream": stream, "store": store}) +} + +fn outcome(points: &[Point], outcome: &str) -> i64 { + total( + points, + "agentic.execution.count", + &[("agentic.execution.outcome", outcome)], + ) +} + +fn delivery(points: &[Point], delivery: &str) -> i64 { + total( + points, + "agentic.delivery.count", + &[("agentic.delivery.outcome", delivery)], + ) +} + +fn executions_total(points: &[Point]) -> i64 { + total(points, "agentic.execution.count", &[]) +} + +#[tokio::test] +async fn http_terminal_paths_each_finalize_once() { + let metrics = Metrics::new(); + let release = Arc::new(Notify::new()); + let upstream = upstream(Arc::clone(&release)).await; + let gateway = gateway(gateway_state(&upstream.url, &metrics).await).await; + let client = reqwest::Client::new(); + let url = format!("{}/v1/responses", gateway.url); + + let completed = client + .post(&url) + .json(&request("hello", true, true)) + .send() + .await + .unwrap(); + let body = completed.text().await.unwrap(); + assert!(body.contains("response.completed"), "{body}"); + + let failed = client + .post(&url) + .json(&request("FAIL", true, true)) + .send() + .await + .unwrap(); + assert_eq!(failed.status(), 200, "the failure is delivered in-band"); + assert!(failed.text().await.unwrap().contains("event: error")); + + let blocking = client + .post(&url) + .json(&request("hello", false, true)) + .send() + .await + .unwrap(); + assert_eq!(blocking.status(), 200); + blocking.bytes().await.unwrap(); + + let proxied = client + .post(&url) + .json(&request("hello", false, false)) + .send() + .await + .unwrap(); + assert_eq!(proxied.status(), 200); + proxied.bytes().await.unwrap(); + + let mut hanging = client + .post(&url) + .json(&request("HANG", true, true)) + .send() + .await + .unwrap() + .bytes_stream(); + let first = hanging.next().await.unwrap().unwrap(); + assert!(String::from_utf8_lossy(&first).contains("response.created")); + // The client disconnects mid-stream. + drop(hanging); + + let points = metrics + .wait_for("five executions", |points| executions_total(points) >= 5) + .await; + assert_eq!(executions_total(&points), 5, "{points:#?}"); + assert_eq!(total(&points, "agentic.delivery.count", &[]), 5); + assert_eq!(total(&points, "agentic.execution.active", &[]), 0); + assert_eq!(outcome(&points, "completed"), 3); + assert_eq!(outcome(&points, "failed"), 1); + assert_eq!(outcome(&points, "cancelled"), 1); + assert_eq!(delivery(&points, "delivered"), 4, "the in-band failure was delivered"); + assert_eq!(delivery(&points, "disconnected"), 1); + assert_eq!( + total( + &points, + "agentic.execution.count", + &[("agentic.route", "proxy"), ("agentic.execution.outcome", "completed")] + ), + 1 + ); + assert_eq!( + total( + &points, + "agentic.execution.count", + &[ + ("agentic.execution.outcome", "failed"), + ("error.type", "upstream_status") + ] + ), + 1 + ); +} + +async fn socket( + gateway: &Server, +) -> tokio_tungstenite::WebSocketStream> { + let url = format!("{}/v1/responses", gateway.url.replace("http:", "ws:")); + tokio_tungstenite::connect_async(url).await.unwrap().0 +} + +fn create(prompt: &str) -> Message { + let mut event = request(prompt, true, false); + event["type"] = json!("response.create"); + Message::Text(event.to_string().into()) +} + +/// Read events until `count` of them have type `event_type`. +async fn read_until( + socket: &mut tokio_tungstenite::WebSocketStream>, + event_type: &str, + count: usize, +) { + let mut seen = 0; + tokio::time::timeout(Duration::from_secs(5), async { + while seen < count { + if let Message::Text(text) = socket.next().await.unwrap().unwrap() { + let event: Value = serde_json::from_str(&text).unwrap(); + seen += usize::from(event["type"] == event_type); + } + } + }) + .await + .unwrap_or_else(|_| panic!("saw {seen} of {count} {event_type} events")); +} + +#[tokio::test] +async fn websocket_requests_count_once_each_on_one_connection() { + let metrics = Metrics::new(); + let upstream = upstream(Arc::new(Notify::new())).await; + let gateway = gateway(gateway_state(&upstream.url, &metrics).await).await; + let mut socket = socket(&gateway).await; + + for _ in 0..3 { + socket.send(create("hello")).await.unwrap(); + } + socket.send(create("FAIL")).await.unwrap(); + read_until(&mut socket, "response.completed", 3).await; + read_until(&mut socket, "error", 1).await; + + let open = metrics + .wait_for("four executions", |points| executions_total(points) >= 4) + .await; + assert_eq!(executions_total(&open), 4, "N requests, N executions"); + assert_eq!(outcome(&open, "completed"), 3); + assert_eq!(outcome(&open, "failed"), 1); + assert_eq!( + total(&open, "agentic.websocket.connections.active", &[]), + 1, + "one connection" + ); + assert_eq!(total(&open, "agentic.websocket.queue.wait.duration", &[]), 4); + assert_eq!(total(&open, "agentic.execution.active", &[]), 0); + // Retained WebSocket executions take the same first-* timings as HTTP + // streams: the upstream reader marks data, the event stream the rest. + assert_eq!(total(&open, "agentic.time_to_first_upstream_data", &[]), 3); + assert_eq!(total(&open, "agentic.time_to_first_text", &[]), 3); + assert_eq!(total(&open, "agentic.time_to_first_client_event", &[]), 4); + + socket.close(None).await.unwrap(); + let closed = metrics + .wait_for("closed connection", |points| { + total(points, "agentic.websocket.connections.active", &[]) == 0 + }) + .await; + assert_eq!(executions_total(&closed), 4, "closing counts nothing twice"); +} + +#[tokio::test] +async fn websocket_disconnect_cancels_active_and_queued_requests_once() { + let metrics = Metrics::new(); + let upstream = upstream(Arc::new(Notify::new())).await; + let gateway = gateway(gateway_state(&upstream.url, &metrics).await).await; + let mut socket = socket(&gateway).await; + + socket.send(create("HANG")).await.unwrap(); + read_until(&mut socket, "response.created", 1).await; + // Queued behind the hanging request on the default stream. + socket.send(create("hello")).await.unwrap(); + socket.send(Message::Ping("barrier".into())).await.unwrap(); + while !matches!(socket.next().await.unwrap().unwrap(), Message::Pong(_)) {} + drop(socket); + + let points = metrics + .wait_for("two executions", |points| executions_total(points) >= 2) + .await; + assert_eq!(outcome(&points, "cancelled"), 2); + assert_eq!(delivery(&points, "disconnected"), 2); + assert_eq!(total(&points, "agentic.execution.active", &[]), 0); + let closed = metrics + .wait_for("closed connection", |points| { + total(points, "agentic.websocket.connections.active", &[]) == 0 + }) + .await; + assert_eq!(executions_total(&closed), 2); +} + +#[tokio::test] +async fn websocket_drain_cancels_queued_requests_once_and_finishes_the_active_one() { + let metrics = Metrics::new(); + let release = Arc::new(Notify::new()); + let upstream = upstream(Arc::clone(&release)).await; + let state = gateway_state(&upstream.url, &metrics).await; + let shutdown = state.shutdown_token.clone(); + let gateway = gateway(state).await; + let mut socket = socket(&gateway).await; + + socket.send(create("HANG")).await.unwrap(); + read_until(&mut socket, "response.created", 1).await; + socket.send(create("hello")).await.unwrap(); + socket.send(Message::Ping("barrier".into())).await.unwrap(); + while !matches!(socket.next().await.unwrap().unwrap(), Message::Pong(_)) {} + + // Shutdown discards queued work; the active request may still finish. + shutdown.cancel(); + let points = metrics + .wait_for("queued execution", |points| executions_total(points) >= 1) + .await; + assert_eq!(outcome(&points, "cancelled"), 1); + assert_eq!(delivery(&points, "disconnected"), 1); + assert_eq!(total(&points, "agentic.execution.active", &[]), 1, "one still running"); + + release.notify_one(); + read_until(&mut socket, "response.completed", 1).await; + let points = metrics + .wait_for("both executions", |points| executions_total(points) >= 2) + .await; + assert_eq!(executions_total(&points), 2); + assert_eq!(outcome(&points, "completed"), 1); + assert_eq!(delivery(&points, "delivered"), 1); + assert_eq!(total(&points, "agentic.execution.active", &[]), 0); +} diff --git a/crates/agentic-server/tests/telemetry_metrics_e2e_test.rs b/crates/agentic-server/tests/telemetry_metrics_e2e_test.rs new file mode 100644 index 00000000..488efdbf --- /dev/null +++ b/crates/agentic-server/tests/telemetry_metrics_e2e_test.rs @@ -0,0 +1,366 @@ +//! The gateway binary, configured only through standard `OTEL_*` variables, +//! with trace sampling at zero, exporting to a local OTLP/HTTP stub. +//! +//! Metrics must not depend on sampling, carry the configured service name, +//! and finalize requests that are still in flight when the process receives +//! SIGTERM: the drain deadline abandons them, runtime shutdown drops them, +//! and the telemetry flush that follows exports their cancellation. + +#![cfg(unix)] + +use std::collections::BTreeMap; +use std::process::{Child, Command, Stdio}; +use std::sync::Arc; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::time::Duration; + +use axum::body::{Body, Bytes}; +use axum::response::{IntoResponse as _, Response}; +use futures::{SinkExt as _, StreamExt as _}; +use opentelemetry_proto::tonic::common::v1::KeyValue; +use opentelemetry_proto::tonic::common::v1::any_value::Value as AnyValue; +use opentelemetry_proto::tonic::metrics::v1::metric::Data; +use opentelemetry_proto::tonic::metrics::v1::number_data_point::Value as NumberValue; +use serde_json::{Value, json}; +use tokio::sync::Notify; +use tokio_tungstenite::tungstenite::Message; + +#[allow(dead_code)] +mod common; +#[path = "../../agentic-server-core/tests/execution_metrics/harness.rs"] +mod harness; +use common::otlp_stub::{OtlpStub, StubMode, service_name}; +use harness::{Point, PointValue, total}; + +const SERVICE: &str = "agentic-metrics-e2e"; +const USAGE: &str = r#"{"input_tokens":7,"input_tokens_details":{"cached_tokens":0},"output_tokens":2,"output_tokens_details":{"reasoning_tokens":0},"total_tokens":9}"#; + +/// Every instrument this scenario exercises. +const EXPECTED_INSTRUMENTS: &[&str] = &[ + "agentic.execution.count", + "agentic.execution.active", + "agentic.execution.duration", + "agentic.delivery.count", + "agentic.delivery.wait.duration", + "agentic.stage.duration", + "agentic.inference.rounds", + "gen_ai.client.token.usage", + "agentic.time_to_first_upstream_data", + "agentic.time_to_first_client_event", + "agentic.time_to_first_text", + "agentic.websocket.connections.active", + "agentic.websocket.queue.wait.duration", + "http.server.request.duration", + "http.server.active_requests", +]; + +/// Completes unless the prompt says `HANG`, which streams `response.created` +/// and then never finishes. +async fn upstream() -> (String, tokio::task::JoinHandle<()>) { + let never = Arc::new(Notify::new()); + let router = axum::Router::new().route( + "/v1/responses", + axum::routing::post(move |body: Bytes| { + let never = Arc::clone(&never); + async move { respond(&body, never) } + }), + ); + let listener = tokio::net::TcpListener::bind("127.0.0.1:0").await.unwrap(); + let url = format!("http://{}", listener.local_addr().unwrap()); + ( + url, + tokio::spawn(async move { axum::serve(listener, router).await.unwrap() }), + ) +} + +/// Like a real upstream, each response gets fresh item IDs: stored history +/// keys rows by public item ID, so a repeated ID cannot be stored twice (#385). +static ITEM: AtomicU64 = AtomicU64::new(0); + +fn respond(body: &[u8], never: Arc) -> Response { + let id = format!("msg_up_{}", ITEM.fetch_add(1, Ordering::Relaxed)); + let message = format!( + r#"{{"id":"{id}","type":"message","role":"assistant","status":"completed","content":[{{"type":"output_text","text":"hi","annotations":[]}}]}}"# + ); + let request: Value = serde_json::from_slice(body).unwrap(); + if request["stream"] != true { + let body = format!( + r#"{{"id":"resp_up","object":"response","created_at":0,"model":"m","status":"completed","output":[{message}],"usage":{USAGE}}}"# + ); + return ([("content-type", "application/json")], body).into_response(); + } + let head = "data: {\"type\":\"response.created\",\"sequence_number\":0,\"response\":{\"id\":\"resp_up\",\"status\":\"in_progress\",\"output\":[]}}\n\n"; + let tail = format!( + "data: {{\"type\":\"response.output_item.added\",\"sequence_number\":1,\"output_index\":0,\"item\":{{\"id\":\"{id}\",\"type\":\"message\",\"role\":\"assistant\",\"status\":\"in_progress\",\"content\":[]}}}}\n\n\ + data: {{\"type\":\"response.output_text.delta\",\"sequence_number\":2,\"output_index\":0,\"content_index\":0,\"delta\":\"hi\"}}\n\n\ + data: {{\"type\":\"response.output_item.done\",\"sequence_number\":3,\"output_index\":0,\"item\":{message}}}\n\n\ + data: {{\"type\":\"response.completed\",\"sequence_number\":4,\"response\":{{\"id\":\"resp_up\",\"status\":\"completed\",\"output\":[{message}],\"usage\":{USAGE}}}}}\n\n\ + data: [DONE]\n\n" + ); + let hang = String::from_utf8_lossy(body).contains("HANG"); + let rest = futures::stream::once(async move { + if hang { + never.notified().await; + } + Ok::<_, std::io::Error>(Bytes::from(tail)) + }); + let body = futures::stream::once(std::future::ready(Ok(Bytes::from_static(head.as_bytes())))).chain(rest); + ([("content-type", "text/event-stream")], Body::from_stream(body)).into_response() +} + +struct Gateway { + child: Child, + url: String, + home: tempfile::TempDir, +} + +impl Gateway { + fn spawn(llm: &str, otlp: &str) -> Self { + let home = tempfile::tempdir().unwrap(); + let port = std::net::TcpListener::bind("127.0.0.1:0") + .unwrap() + .local_addr() + .unwrap() + .port(); + let log = std::fs::File::create(home.path().join("server.log")).unwrap(); + let child = Command::new(env!("CARGO_BIN_EXE_agentic-server")) + .env_clear() + .env("HOME", home.path()) + .env("AGENTIC_API_HOME", home.path()) + .env("RUST_LOG", "info") + .env("OTEL_TRACES_EXPORTER", "otlp") + .env("OTEL_METRICS_EXPORTER", "otlp") + .env("OTEL_EXPORTER_OTLP_ENDPOINT", otlp) + .env("OTEL_SERVICE_NAME", SERVICE) + .env("OTEL_TRACES_SAMPLER", "parentbased_traceidratio") + .env("OTEL_TRACES_SAMPLER_ARG", "0") + .env("OTEL_BSP_SCHEDULE_DELAY", "50") + .args(["--llm-api-base", llm, "--skip-llm-ready-check"]) + .args(["--gateway-host", "127.0.0.1", "--gateway-port", &port.to_string()]) + .stdin(Stdio::null()) + .stdout(log.try_clone().unwrap()) + .stderr(log) + .spawn() + .expect("agentic-server starts"); + Self { + child, + url: format!("http://127.0.0.1:{port}"), + home, + } + } + + fn log(&self) -> String { + std::fs::read_to_string(self.home.path().join("server.log")).unwrap_or_default() + } + + async fn wait_ready(&self) { + let client = reqwest::Client::new(); + for _ in 0..500 { + if client.get(format!("{}/health", self.url)).send().await.is_ok() { + return; + } + tokio::time::sleep(Duration::from_millis(20)).await; + } + panic!("gateway did not start: {}", self.log()); + } + + async fn terminate(&mut self) { + let status = Command::new("kill") + .args(["-TERM", &self.child.id().to_string()]) + .status() + .unwrap(); + assert!(status.success()); + // Drain deadline (8 s), runtime shutdown (1 s), telemetry flush (3 s). + for _ in 0..1000 { + if let Some(status) = self.child.try_wait().unwrap() { + assert!(status.success(), "gateway exited with {status}: {}", self.log()); + return; + } + tokio::time::sleep(Duration::from_millis(20)).await; + } + panic!("gateway did not exit: {}", self.log()); + } +} + +impl Drop for Gateway { + fn drop(&mut self) { + let _ = self.child.kill(); + let _ = self.child.wait(); + } +} + +fn request(prompt: &str, stream: bool) -> Value { + json!({"model": "m", "input": prompt, "stream": stream, "store": true}) +} + +fn create(prompt: &str) -> Message { + let mut event = request(prompt, true); + event["store"] = json!(false); + event["type"] = json!("response.create"); + Message::Text(event.to_string().into()) +} + +type Socket = tokio_tungstenite::WebSocketStream>; + +async fn read_until(socket: &mut Socket, event_type: &str, count: usize) { + let mut seen = 0; + tokio::time::timeout(Duration::from_secs(10), async { + while seen < count { + if let Message::Text(text) = socket.next().await.unwrap().unwrap() { + let event: Value = serde_json::from_str(&text).unwrap(); + seen += usize::from(event["type"] == event_type); + } + } + }) + .await + .unwrap_or_else(|_| panic!("saw {seen} of {count} {event_type} events")); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn unsampled_gateway_exports_metrics_and_finalizes_shutdown_cancelled_requests() { + let (otlp, stub) = OtlpStub::spawn(StubMode::Accept).await; + let (llm, _llm) = upstream().await; + let mut gateway = Gateway::spawn(&llm, &otlp); + gateway.wait_ready().await; + let client = reqwest::Client::new(); + let url = format!("{}/v1/responses", gateway.url); + + // Completed over HTTP: streamed and blocking. + let streamed = client.post(&url).json(&request("hello", true)).send().await.unwrap(); + assert!(streamed.text().await.unwrap().contains("response.completed")); + let blocking = client.post(&url).json(&request("hello", false)).send().await.unwrap(); + assert_eq!(blocking.status(), 200, "{}", gateway.log()); + blocking.bytes().await.unwrap(); + + // Completed over WebSocket, twice on one connection. + let ws_url = format!("{}/v1/responses", gateway.url.replace("http:", "ws:")); + let (mut socket, _) = tokio_tungstenite::connect_async(&ws_url).await.unwrap(); + socket.send(create("hello")).await.unwrap(); + socket.send(create("hello")).await.unwrap(); + read_until(&mut socket, "response.completed", 2).await; + + // Still running at SIGTERM: one HTTP stream and one WebSocket request. + let mut in_flight = client + .post(&url) + .json(&request("HANG", true)) + .send() + .await + .unwrap() + .bytes_stream(); + assert!(String::from_utf8_lossy(&in_flight.next().await.unwrap().unwrap()).contains("response.created")); + socket.send(create("HANG")).await.unwrap(); + read_until(&mut socket, "response.created", 1).await; + + gateway.terminate().await; + drop((in_flight, socket)); + + let traces = stub.trace_exports().await; + let spans: usize = traces + .iter() + .flat_map(|export| &export.resource_spans) + .flat_map(|resource| &resource.scope_spans) + .map(|scope| scope.spans.len()) + .sum(); + assert_eq!(spans, 0, "OTEL_TRACES_SAMPLER_ARG=0 samples nothing"); + + let exports = stub.metric_exports().await; + let latest = exports.last().expect("metrics are flushed at shutdown"); + for resource in &latest.resource_metrics { + assert_eq!(service_name(resource.resource.as_ref()), Some(SERVICE)); + } + let points = otlp_points(latest); + harness::assert_allowed(&points); + for instrument in EXPECTED_INSTRUMENTS { + assert!( + points.iter().any(|point| point.name == *instrument), + "{instrument} was not exported" + ); + } + + let outcome = |outcome: &str| { + total( + &points, + "agentic.execution.count", + &[("agentic.execution.outcome", outcome)], + ) + }; + assert_eq!(total(&points, "agentic.execution.count", &[]), 6, "{points:#?}"); + assert_eq!(outcome("completed"), 4); + assert_eq!(outcome("cancelled"), 2, "both in-flight requests finalized at shutdown"); + assert_eq!( + total( + &points, + "agentic.delivery.count", + &[("agentic.delivery.outcome", "disconnected")] + ), + 2 + ); + assert_eq!( + total(&points, "agentic.execution.active", &[]), + 0, + "nothing left active" + ); + assert_eq!(total(&points, "agentic.websocket.connections.active", &[]), 0); + assert_eq!(total(&points, "agentic.websocket.queue.wait.duration", &[]), 3); + assert_eq!( + total(&points, "gen_ai.client.token.usage", &[("gen_ai.token.type", "input")]), + 4, + "one sample per completed upstream call" + ); + assert_eq!(total(&points, "http.server.active_requests", &[]), 0); +} + +fn otlp_points(export: &opentelemetry_proto::tonic::collector::metrics::v1::ExportMetricsServiceRequest) -> Vec { + let mut points = Vec::new(); + for metric in export + .resource_metrics + .iter() + .flat_map(|resource| &resource.scope_metrics) + .flat_map(|scope| &scope.metrics) + { + let mut push = |attributes: &[KeyValue], value| { + points.push(Point { + name: metric.name.clone(), + attributes: otlp_attributes(attributes), + value, + }); + }; + match &metric.data { + Some(Data::Sum(sum)) => { + for point in &sum.data_points { + let Some(NumberValue::AsInt(value)) = point.value else { + panic!("{}: every gateway sum is an integer", metric.name); + }; + push(&point.attributes, PointValue::Sum(value)); + } + } + Some(Data::Histogram(histogram)) => { + for point in &histogram.data_points { + let value = PointValue::Histogram { + count: point.count, + sum: point.sum.unwrap_or_default(), + }; + push(&point.attributes, value); + } + } + other => panic!("{}: unexpected data {other:?}", metric.name), + } + } + points +} + +fn otlp_attributes(attributes: &[KeyValue]) -> BTreeMap { + attributes + .iter() + .map(|attribute| { + let value = match attribute.value.as_ref().and_then(|value| value.value.as_ref()) { + Some(AnyValue::StringValue(value)) => value.clone(), + Some(AnyValue::BoolValue(value)) => value.to_string(), + Some(AnyValue::IntValue(value)) => value.to_string(), + Some(AnyValue::DoubleValue(value)) => value.to_string(), + other => panic!("{}: unexpected attribute value {other:?}", attribute.key), + }; + (attribute.key.clone(), value) + }) + .collect() +} From 89467221f3f7729e6e787a98eeb7ed16346b4fec Mon Sep 17 00:00:00 2001 From: Zheng Lu Date: Fri, 9 Oct 2026 15:29:14 +0100 Subject: [PATCH 3/4] feat(telemetry): add a local Collector setup and telemetry smoke test deploy/otel runs an OpenTelemetry Collector (and optional Jaeger) that exports metrics to Prometheus and logs every signal. The smoke test starts the gateway against a scripted upstream, sends streamed, blocking, proxied, and WebSocket requests, and checks the Collector's output against the same allow-list as the Rust tests. CI runs it after the CLI end-to-end test. scripts/otel-overhead.py measures the telemetry overhead. Signed-off-by: Zheng Lu --- .github/workflows/rust.yml | 8 + deploy/otel/collector.yaml | 48 ++++ deploy/otel/docker-compose.yaml | 30 +++ deploy/otel/jaeger.env | 4 + scripts/otel-overhead.py | 211 ++++++++++++++++++ scripts/tests/otel-smoke.sh | 102 +++++++++ scripts/tests/otel_fixtures.py | 335 ++++++++++++++++++++++++++++ scripts/tests/test_otel_fixtures.py | 110 +++++++++ 8 files changed, 848 insertions(+) create mode 100644 deploy/otel/collector.yaml create mode 100644 deploy/otel/docker-compose.yaml create mode 100644 deploy/otel/jaeger.env create mode 100755 scripts/otel-overhead.py create mode 100755 scripts/tests/otel-smoke.sh create mode 100755 scripts/tests/otel_fixtures.py create mode 100644 scripts/tests/test_otel_fixtures.py diff --git a/.github/workflows/rust.yml b/.github/workflows/rust.yml index e71c3e67..ec70cad7 100644 --- a/.github/workflows/rust.yml +++ b/.github/workflows/rust.yml @@ -84,6 +84,14 @@ jobs: - name: Test agentic CLI end to end run: python3 scripts/tests/agentic-cli-e2e-test.py + - name: Test the telemetry smoke checker + run: python3 -m unittest discover -s scripts/tests -p test_otel_fixtures.py + + - name: Smoke-test telemetry through the local Collector + run: | + docker compose -f deploy/otel/docker-compose.yaml up -d + scripts/tests/otel-smoke.sh + embedded-code-interpreter: name: Embedded code interpreter runs-on: ubuntu-latest diff --git a/deploy/otel/collector.yaml b/deploy/otel/collector.yaml new file mode 100644 index 00000000..d1b201c0 --- /dev/null +++ b/deploy/otel/collector.yaml @@ -0,0 +1,48 @@ +# Backend-neutral OpenTelemetry Collector for local gateway telemetry. +# +# Receives OTLP/HTTP from the gateway, prints every span and metric with the +# debug exporter, and serves metrics for Prometheus-compatible scrapers. +# Traces also go to Jaeger when started with `--profile jaeger`, which sets +# AGENTIC_OTEL_TRACE_EXPORTERS (see docker-compose.yaml). + +receivers: + otlp: + protocols: + http: + endpoint: 0.0.0.0:4318 + +processors: + memory_limiter: + check_interval: 1s + limit_mib: 400 + spike_limit_mib: 100 + batch: {} + +exporters: + debug: + verbosity: detailed + prometheus: + endpoint: 0.0.0.0:8889 + # Copies resource attributes such as service.name onto every series. + resource_to_telemetry_conversion: + enabled: true + otlp/jaeger: + endpoint: jaeger:4317 + tls: + insecure: true + +extensions: + health_check: + endpoint: 0.0.0.0:13133 + +service: + extensions: [health_check] + pipelines: + traces: + receivers: [otlp] + processors: [memory_limiter, batch] + exporters: ${env:AGENTIC_OTEL_TRACE_EXPORTERS} + metrics: + receivers: [otlp] + processors: [memory_limiter, batch] + exporters: [debug, prometheus] diff --git a/deploy/otel/docker-compose.yaml b/deploy/otel/docker-compose.yaml new file mode 100644 index 00000000..9a9785b4 --- /dev/null +++ b/deploy/otel/docker-compose.yaml @@ -0,0 +1,30 @@ +# Local, backend-neutral telemetry for the gateway. +# +# docker compose -f deploy/otel/docker-compose.yaml up -d +# docker compose -f deploy/otel/docker-compose.yaml --env-file deploy/otel/jaeger.env up -d # + Jaeger UI +# +# Then run the gateway with: +# OTEL_TRACES_EXPORTER=otlp OTEL_METRICS_EXPORTER=otlp \ +# OTEL_EXPORTER_OTLP_ENDPOINT=http://127.0.0.1:4318 agentic-server ... +# +# See docs/deploying/observability.md. + +services: + otel-collector: + image: otel/opentelemetry-collector-contrib:0.161.0@sha256:fd328de2552466ad78385e1b1289c3f2402b1c45f265b252aab1955b42845ac1 + command: ["--config=/etc/otelcol/collector.yaml"] + volumes: + - ./collector.yaml:/etc/otelcol/collector.yaml:ro + environment: + # `[debug]` by default; jaeger.env adds the Jaeger exporter. + AGENTIC_OTEL_TRACE_EXPORTERS: ${AGENTIC_OTEL_TRACE_EXPORTERS:-[debug]} + ports: + - "127.0.0.1:4318:4318" # OTLP/HTTP from the gateway + - "127.0.0.1:8889:8889" # Prometheus scrape endpoint + - "127.0.0.1:13133:13133" # health check + + jaeger: + profiles: [jaeger] + image: jaegertracing/jaeger:2.21.0@sha256:3d0ac795ff98aa04d1be04311d2dac6c25b4bfc8322dc02e53bc5b170c5018c3 + ports: + - "127.0.0.1:16686:16686" # UI diff --git a/deploy/otel/jaeger.env b/deploy/otel/jaeger.env new file mode 100644 index 00000000..98496771 --- /dev/null +++ b/deploy/otel/jaeger.env @@ -0,0 +1,4 @@ +# docker compose -f deploy/otel/docker-compose.yaml --env-file deploy/otel/jaeger.env up -d +# Starts Jaeger (UI on http://127.0.0.1:16686) and sends traces to it as well. +COMPOSE_PROFILES=jaeger +AGENTIC_OTEL_TRACE_EXPORTERS=[debug, otlp/jaeger] diff --git a/scripts/otel-overhead.py b/scripts/otel-overhead.py new file mode 100755 index 00000000..54ee0e15 --- /dev/null +++ b/scripts/otel-overhead.py @@ -0,0 +1,211 @@ +#!/usr/bin/env python3 +"""Measure gateway latency, CPU, and memory with telemetry disabled and enabled. + + cargo build --release -p agentic-server --bin agentic-server + docker compose -f deploy/otel/docker-compose.yaml up -d + scripts/otel-overhead.py --bin target/release/agentic-server + +Runs one gateway per mode against the same in-process scripted upstream, +alternating modes for --rounds rounds. Each round sends --requests sequential +streamed and blocking Responses requests (store=true, so every request is +rehydrated, executed, and persisted) after --warmup unmeasured ones. With +telemetry enabled the gateway exports traces (every request sampled) and +metrics over OTLP/HTTP to --otlp-endpoint. + +Reports per-request latency percentiles, gateway CPU time per request, and +the gateway's peak resident set size, as a Markdown table. + +The client re-arms TCP_QUICKACK after every read so that the gateway's +streamed writes never wait for a delayed ACK (the gateway does not set +TCP_NODELAY on accepted sockets); latency then reflects the gateway's own work. +Linux only. +""" + +from __future__ import annotations + +import argparse +import http.client +import json +import os +import signal +import socket +import statistics +import subprocess +import sys +import tempfile +import time +from pathlib import Path + +sys.path.insert(0, str(Path(__file__).resolve().parent / "tests")) + +import otel_fixtures # noqa: E402 + +TICKS = os.sysconf("SC_CLK_TCK") + + +def cpu_seconds(pid: int) -> float: + fields = Path(f"/proc/{pid}/stat").read_text().rsplit(")", 1)[1].split() + return (int(fields[11]) + int(fields[12])) / TICKS + + +def peak_rss_mib(pid: int) -> float: + for line in Path(f"/proc/{pid}/status").read_text().splitlines(): + if line.startswith("VmHWM:"): + return int(line.split()[1]) / 1024 + raise RuntimeError("no VmHWM") + + +def start_gateway(binary: str, upstream: int, enabled: bool, endpoint: str, home: str) -> tuple[subprocess.Popen, int]: + port = otel_fixtures.free_port() + env = {"PATH": os.environ["PATH"], "HOME": home, "AGENTIC_API_HOME": home, "RUST_LOG": "warn"} + if enabled: + env |= { + "OTEL_TRACES_EXPORTER": "otlp", + "OTEL_METRICS_EXPORTER": "otlp", + "OTEL_EXPORTER_OTLP_ENDPOINT": endpoint, + "OTEL_SERVICE_NAME": "agentic-overhead", + } + process = subprocess.Popen( + [ + binary, + "--llm-api-base", + f"http://127.0.0.1:{upstream}", + "--skip-llm-ready-check", + "--gateway-host", + "127.0.0.1", + "--gateway-port", + str(port), + ], + env=env, + stdout=subprocess.DEVNULL, + stderr=subprocess.DEVNULL, + ) + for _ in range(500): + try: + connection = http.client.HTTPConnection("127.0.0.1", port, timeout=1) + connection.request("GET", "/health") + if connection.getresponse().status == 200: + return process, port + except OSError: + time.sleep(0.02) + process.kill() + raise RuntimeError("gateway did not start") + + +class QuickAckClient: + """A keep-alive HTTP/1.1 client that acknowledges every segment at once.""" + + def __init__(self, port: int) -> None: + self.socket = socket.create_connection(("127.0.0.1", port), timeout=30) + self.socket.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1) + self.buffer = b"" + + def _receive(self) -> None: + self.socket.setsockopt(socket.IPPROTO_TCP, socket.TCP_QUICKACK, 1) + chunk = self.socket.recv(65536) + if not chunk: + raise RuntimeError("gateway closed the connection") + self.buffer += chunk + + def post(self, payload: dict) -> bytes: + body = json.dumps(payload).encode() + self.socket.sendall( + b"POST /v1/responses HTTP/1.1\r\nHost: gateway\r\nContent-Type: application/json\r\n" + + f"Content-Length: {len(body)}\r\n\r\n".encode() + + body + ) + while b"\r\n\r\n" not in self.buffer: + self._receive() + head, self.buffer = self.buffer.split(b"\r\n\r\n", 1) + status = head.split(b"\r\n", 1)[0] + if b" 200 " not in status: + raise RuntimeError(f"gateway answered {status!r}") + headers = dict(line.split(b": ", 1) for line in head.split(b"\r\n")[1:]) + headers = {key.lower(): value for key, value in headers.items()} + if b"content-length" in headers: + length = int(headers[b"content-length"]) + while len(self.buffer) < length: + self._receive() + response, self.buffer = self.buffer[:length], self.buffer[length:] + return response + # Chunked: every gateway response ends with the zero-length chunk. + while b"\r\n0\r\n\r\n" not in self.buffer: + self._receive() + response, self.buffer = self.buffer.split(b"\r\n0\r\n\r\n", 1) + return response + + def close(self) -> None: + self.socket.close() + + +def run_scenario(port: int, stream: bool, requests: int, warmup: int, pid: int) -> tuple[list[float], float]: + client = QuickAckClient(port) + payload = otel_fixtures.responses_request(stream=stream) + for _ in range(warmup): + client.post(payload) + latencies = [] + cpu_before = cpu_seconds(pid) + for _ in range(requests): + started = time.perf_counter() + client.post(payload) + latencies.append(time.perf_counter() - started) + cpu = (cpu_seconds(pid) - cpu_before) / requests + client.close() + return latencies, cpu + + +def percentile(values: list[float], fraction: float) -> float: + ordered = sorted(values) + return ordered[min(len(ordered) - 1, int(fraction * len(ordered)))] + + +def main() -> None: + parser = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter) + parser.add_argument("--bin", default="target/release/agentic-server") + parser.add_argument("--requests", type=int, default=1000) + parser.add_argument("--warmup", type=int, default=100) + parser.add_argument("--rounds", type=int, default=3) + parser.add_argument("--otlp-endpoint", default="http://127.0.0.1:4318") + args = parser.parse_args() + + upstream_port = otel_fixtures.free_port() + otel_fixtures.serve_upstream(upstream_port) + results: dict[tuple[str, str], dict] = {} + for round_ in range(args.rounds): + for enabled in (False, True): + mode = "enabled" if enabled else "disabled" + with tempfile.TemporaryDirectory() as home: + process, port = start_gateway(args.bin, upstream_port, enabled, args.otlp_endpoint, home) + try: + for stream in (True, False): + scenario = "streaming" if stream else "non-streaming" + latencies, cpu = run_scenario(port, stream, args.requests, args.warmup, process.pid) + entry = results.setdefault((scenario, mode), {"latencies": [], "cpu": [], "rss": []}) + entry["latencies"] += latencies + entry["cpu"].append(cpu) + results[("streaming", mode)]["rss"].append(peak_rss_mib(process.pid)) + finally: + process.send_signal(signal.SIGTERM) + process.wait(timeout=30) + print(f"round {round_ + 1}/{args.rounds}: {mode} done", file=sys.stderr) + + print("| Scenario | Telemetry | p50 (ms) | p90 (ms) | p99 (ms) | CPU / request (ms) | Peak RSS (MiB) |") + print("| --- | --- | ---: | ---: | ---: | ---: | ---: |") + for scenario in ("streaming", "non-streaming"): + for mode in ("disabled", "enabled"): + entry = results[(scenario, mode)] + latencies = entry["latencies"] + rss = results[("streaming", mode)]["rss"] + print( + f"| {scenario} | {mode} " + f"| {percentile(latencies, 0.5) * 1e3:.2f} " + f"| {percentile(latencies, 0.9) * 1e3:.2f} " + f"| {percentile(latencies, 0.99) * 1e3:.2f} " + f"| {statistics.median(entry['cpu']) * 1e3:.3f} " + f"| {statistics.median(rss):.1f} |" + ) + print(json.dumps({"requests": args.requests, "rounds": args.rounds}), file=sys.stderr) + + +if __name__ == "__main__": + main() diff --git a/scripts/tests/otel-smoke.sh b/scripts/tests/otel-smoke.sh new file mode 100755 index 00000000..f56816c4 --- /dev/null +++ b/scripts/tests/otel-smoke.sh @@ -0,0 +1,102 @@ +#!/usr/bin/env bash +# End-to-end check of gateway telemetry against the local Collector. +# +# docker compose -f deploy/otel/docker-compose.yaml up -d +# scripts/tests/otel-smoke.sh +# +# Starts a scripted upstream and the gateway exporting OTLP to the Collector, +# sends streamed, blocking, proxied, and WebSocket requests, stops the gateway +# so it flushes, then checks the Collector's debug output and Prometheus +# endpoint: every gateway instrument arrived with this run's service.name and +# only allow-listed attribute keys and values. +# +# AGENTIC_SERVER_BIN selects a prebuilt gateway; otherwise it is built with +# cargo. Requires docker, curl, and python3. +set -euo pipefail + +root=$(cd "$(dirname "${BASH_SOURCE[0]}")/../.." && pwd) +if docker compose version >/dev/null 2>&1; then + compose=(docker compose -f "$root/deploy/otel/docker-compose.yaml") +else + compose=(docker-compose -f "$root/deploy/otel/docker-compose.yaml") +fi +fixtures="$root/scripts/tests/otel_fixtures.py" +# Unique per run, so output left by earlier runs cannot satisfy the check. +service="agentic-otel-smoke-$$" +work=$(mktemp -d) +pids=() + +cleanup() { + for pid in "${pids[@]}"; do + kill "$pid" 2>/dev/null || true + done + rm -rf "$work" +} +trap cleanup EXIT + +wait_for() { + local what=$1 url=$2 + for _ in $(seq 1 150); do + if curl -fs -o /dev/null "$url"; then + return 0 + fi + sleep 0.2 + done + echo "timed out waiting for $what at $url" >&2 + return 1 +} + +wait_for "the Collector (docker compose -f deploy/otel/docker-compose.yaml up -d)" http://127.0.0.1:13133/ + +bin=${AGENTIC_SERVER_BIN:-} +if [[ -z "$bin" ]]; then + cargo build --quiet --manifest-path "$root/Cargo.toml" -p agentic-server --bin agentic-server + bin="$root/target/debug/agentic-server" +fi + +upstream_port=$(python3 -c 'import socket; s=socket.socket(); s.bind(("127.0.0.1", 0)); print(s.getsockname()[1])') +gateway_port=$(python3 -c 'import socket; s=socket.socket(); s.bind(("127.0.0.1", 0)); print(s.getsockname()[1])') + +python3 "$fixtures" upstream "$upstream_port" & +pids+=($!) +wait_for "the scripted upstream" "http://127.0.0.1:$upstream_port/health" + +env \ + AGENTIC_API_HOME="$work" \ + RUST_LOG=warn \ + OTEL_TRACES_EXPORTER=otlp \ + OTEL_METRICS_EXPORTER=otlp \ + OTEL_EXPORTER_OTLP_ENDPOINT=http://127.0.0.1:4318 \ + OTEL_SERVICE_NAME="$service" \ + "$bin" \ + --llm-api-base "http://127.0.0.1:$upstream_port" \ + --skip-llm-ready-check \ + --gateway-host 127.0.0.1 \ + --gateway-port "$gateway_port" \ + >"$work/gateway.log" 2>&1 & +gateway_pid=$! +pids+=("$gateway_pid") +wait_for "the gateway" "http://127.0.0.1:$gateway_port/health" + +python3 "$fixtures" requests "$gateway_port" + +# SIGTERM drains the gateway and flushes both signals before it exits. +kill -TERM "$gateway_pid" +if ! wait "$gateway_pid"; then + echo "gateway exited unsuccessfully:" >&2 + cat "$work/gateway.log" >&2 + exit 1 +fi + +# The Collector batches before exporting; poll until this run's metrics show up. +for _ in $(seq 1 50); do + "${compose[@]}" logs --no-color otel-collector >"$work/collector.log" 2>&1 + curl -fsS http://127.0.0.1:8889/metrics >"$work/prometheus.txt" + if grep -q "service.name: Str($service)" "$work/collector.log" && + grep -q "service_name=\"$service\"" "$work/prometheus.txt"; then + break + fi + sleep 0.2 +done + +python3 "$fixtures" check "$service" "$work/collector.log" "$work/prometheus.txt" diff --git a/scripts/tests/otel_fixtures.py b/scripts/tests/otel_fixtures.py new file mode 100755 index 00000000..2bf07adc --- /dev/null +++ b/scripts/tests/otel_fixtures.py @@ -0,0 +1,335 @@ +#!/usr/bin/env python3 +"""Fixtures for the gateway telemetry smoke test and overhead benchmark. + +Standard library only. Subcommands: + + upstream PORT serve a scripted OpenAI Responses upstream + requests GATEWAY_PORT send streamed, blocking, proxied, and WebSocket requests + check SERVICE LOG METRICS verify the Collector's debug log and Prometheus output + +The metric allow-list is read from the Rust test harness, so the smoke test +and `cargo test` enforce the same cardinality contract. +""" + +from __future__ import annotations + +import base64 +import http.client +import itertools +import json +import os +import re +import socket +import sys +import threading +from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer +from pathlib import Path + +ROOT = Path(__file__).resolve().parents[2] +HARNESS = ROOT / "crates/agentic-server-core/tests/execution_metrics/harness.rs" + +USAGE = { + "input_tokens": 7, + "input_tokens_details": {"cached_tokens": 0}, + "output_tokens": 2, + "output_tokens_details": {"reasoning_tokens": 0}, + "total_tokens": 9, +} +MESSAGE = { + "type": "message", + "role": "assistant", + "status": "completed", + "content": [{"type": "output_text", "text": "hi", "annotations": []}], +} + + +_ITEM_IDS = itertools.count() + + +def message() -> dict: + """An assistant message with a fresh item ID, as a real upstream sends. + + The gateway keys stored history rows by public item ID, so a repeated ID + cannot be stored twice (#385). + """ + return {**MESSAGE, "id": f"msg_up_{next(_ITEM_IDS)}"} + + +def sse_body() -> bytes: + item = message() + events = [ + {"type": "response.created", "response": {"id": "resp_up", "status": "in_progress", "output": []}}, + { + "type": "response.output_item.added", + "output_index": 0, + "item": {**item, "status": "in_progress", "content": []}, + }, + {"type": "response.output_text.delta", "output_index": 0, "content_index": 0, "delta": "hi"}, + {"type": "response.output_item.done", "output_index": 0, "item": item}, + { + "type": "response.completed", + "response": {"id": "resp_up", "status": "completed", "output": [item], "usage": USAGE}, + }, + ] + lines = [f"data: {json.dumps({**event, 'sequence_number': n})}\n\n" for n, event in enumerate(events)] + return ("".join(lines) + "data: [DONE]\n\n").encode() + + +def json_body() -> bytes: + body = { + "id": "resp_up", + "object": "response", + "created_at": 0, + "model": "test-model", + "status": "completed", + "output": [message()], + "usage": USAGE, + } + return json.dumps(body).encode() + + +class Upstream(BaseHTTPRequestHandler): + """Completes every Responses request; keeps connections alive.""" + + protocol_version = "HTTP/1.1" + + def setup(self) -> None: + super().setup() + # Headers and body are separate writes; without this, Nagle's algorithm + # and delayed ACKs add ~40 ms to every keep-alive response. + self.connection.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1) + + def do_GET(self) -> None: # noqa: N802 - http.server API + self._send(200, "application/json", b"{}") + + def do_POST(self) -> None: # noqa: N802 - http.server API + length = int(self.headers.get("content-length", "0")) + request = json.loads(self.rfile.read(length) or b"{}") + if request.get("stream"): + self._send(200, "text/event-stream", sse_body()) + else: + self._send(200, "application/json", json_body()) + + def _send(self, status: int, content_type: str, body: bytes) -> None: + self.send_response(status) + self.send_header("content-type", content_type) + self.send_header("content-length", str(len(body))) + self.end_headers() + self.wfile.write(body) + + def log_message(self, *_args: object) -> None: + pass + + +def serve_upstream(port: int) -> ThreadingHTTPServer: + server = ThreadingHTTPServer(("127.0.0.1", port), Upstream) + server.daemon_threads = True + threading.Thread(target=server.serve_forever, daemon=True).start() + return server + + +def free_port() -> int: + with socket.socket() as probe: + probe.bind(("127.0.0.1", 0)) + return probe.getsockname()[1] + + +def responses_request(stream: bool, store: bool = True) -> dict: + return {"model": "test-model", "input": "say hi", "stream": stream, "store": store} + + +def post(connection: http.client.HTTPConnection, payload: dict) -> bytes: + connection.request( + "POST", "/v1/responses", body=json.dumps(payload), headers={"content-type": "application/json"} + ) + response = connection.getresponse() + body = response.read() + if response.status != 200: + raise RuntimeError(f"gateway answered {response.status}: {body[:200]!r}") + return body + + +class WebSocket: + """A minimal RFC 6455 client: text frames out, frames in.""" + + def __init__(self, port: int, path: str = "/v1/responses") -> None: + self.socket = socket.create_connection(("127.0.0.1", port)) + self.reader = self.socket.makefile("rb") + key = base64.b64encode(os.urandom(16)).decode() + self.socket.sendall( + ( + f"GET {path} HTTP/1.1\r\nHost: 127.0.0.1:{port}\r\nUpgrade: websocket\r\n" + f"Connection: Upgrade\r\nSec-WebSocket-Key: {key}\r\nSec-WebSocket-Version: 13\r\n\r\n" + ).encode() + ) + status = self.reader.readline() + if b" 101 " not in status: + raise RuntimeError(f"websocket upgrade failed: {status!r}") + while self.reader.readline() not in (b"\r\n", b""): + pass + + def send_text(self, text: str) -> None: + self._send(0x1, text.encode()) + + def _send(self, opcode: int, payload: bytes) -> None: + mask = os.urandom(4) + header = bytes([0x80 | opcode]) + if len(payload) < 126: + header += bytes([0x80 | len(payload)]) + elif len(payload) < 1 << 16: + header += bytes([0x80 | 126]) + len(payload).to_bytes(2, "big") + else: + header += bytes([0x80 | 127]) + len(payload).to_bytes(8, "big") + masked = bytes(byte ^ mask[i % 4] for i, byte in enumerate(payload)) + self.socket.sendall(header + mask + masked) + + def receive_json(self) -> dict: + while True: + first, second = self.reader.read(2) + opcode, length = first & 0x0F, second & 0x7F + if length == 126: + length = int.from_bytes(self.reader.read(2), "big") + elif length == 127: + length = int.from_bytes(self.reader.read(8), "big") + payload = self.reader.read(length) + if opcode == 0x1: + return json.loads(payload) + if opcode == 0x9: + self._send(0xA, payload) + elif opcode == 0x8: + raise RuntimeError("websocket closed by the gateway") + + def complete(self) -> None: + """Send one response.create and read until it completes.""" + self.send_text(json.dumps({**responses_request(True, store=False), "type": "response.create"})) + while (event := self.receive_json())["type"] != "response.completed": + if event["type"] == "error": + raise RuntimeError(f"websocket request failed: {event}") + + def close(self) -> None: + self._send(0x8, b"") + self.socket.close() + + +def send_smoke_requests(gateway_port: int) -> None: + connection = http.client.HTTPConnection("127.0.0.1", gateway_port, timeout=30) + body = post(connection, responses_request(stream=True)) + assert b"response.completed" in body, body[-200:] + post(connection, responses_request(stream=False)) + post(connection, responses_request(stream=False, store=False)) # proxied + connection.close() + socket_ = WebSocket(gateway_port) + socket_.complete() + socket_.complete() + socket_.close() + + +# ---------------------------------------------------------------- checking + + +def _rust_string_list(text: str) -> list[str]: + return re.findall(r'"([^"]*)"', text) + + +def load_allow_list() -> tuple[dict[str, list[str]], dict[str, list[str]]]: + """Parse INSTRUMENT_KEYS and KEY_VALUES from the Rust test harness.""" + source = HARNESS.read_text() + tables = {} + for name in ("INSTRUMENT_KEYS", "KEY_VALUES"): + block = re.search(rf"const {name}: &\[\(&str, &\[&str\]\)\] = &\[(.*?)\n\];", source, re.S) + if block is None: + raise SystemExit(f"cannot find {name} in {HARNESS}") + entries = re.findall(r'\(\s*"([^"]+)",\s*&\[(.*?)\],?\s*\)', block.group(1), re.S) + tables[name] = {key: _rust_string_list(values) for key, values in entries} + return tables["INSTRUMENT_KEYS"], tables["KEY_VALUES"] + + +def value_allowed(key_values: dict[str, list[str]], key: str, value: str) -> bool: + if key in key_values: + return value in key_values[key] + if key == "http.route": + return value.startswith("/") and "?" not in value + if key == "http.response.status_code": + return value.isdigit() and 100 <= int(value) <= 599 + return False + + +_ATTRIBUTE = re.compile(r"^\s*-> ([^:]+): (?:Str|Bool|Int|Double)\((.*)\)$") +_DATA_POINT = re.compile(r"^\w*DataPoints #\d+$") + + +def parse_debug_metrics(log: str) -> list[tuple[str | None, str | None, dict[str, str]]]: + """(service.name, metric, attributes) for each data point in a detailed debug log. + + A data point's attribute block is printed only when it has attributes. + """ + points: list[tuple[str | None, str | None, dict[str, str]]] = [] + service = metric = None + section = None + attributes: dict[str, str] = {} + for raw in log.splitlines(): + line = raw.split("| ", 1)[1] if "| " in raw else raw + stripped = line.strip() + if stripped == "Resource attributes:": + section, service = "resource", None + elif stripped == "Descriptor:": + section = "descriptor" + elif _DATA_POINT.match(stripped): + section, attributes = None, {} + points.append((service, metric, attributes)) + elif stripped == "Data point attributes:": + section = "point" + elif match := _ATTRIBUTE.match(line): + if section == "resource" and match.group(1) == "service.name": + service = match.group(2) + elif section == "point": + attributes[match.group(1)] = match.group(2) + elif stripped.startswith("-> Name: ") and section == "descriptor": + metric = stripped.removeprefix("-> Name: ") + elif not stripped.startswith("->") and section == "point": + section = None + return points + + +def check(service: str, log_path: str, prometheus_path: str) -> None: + instrument_keys, key_values = load_allow_list() + points = [(metric, attrs) for svc, metric, attrs in parse_debug_metrics(Path(log_path).read_text()) if svc == service] + if not points: + raise SystemExit(f"the Collector printed no metrics for service.name={service}") + problems = [] + for metric, attributes in points: + if metric not in instrument_keys: + problems.append(f"unlisted instrument {metric}") + continue + for key, value in attributes.items(): + if key not in instrument_keys[metric]: + problems.append(f"{metric}: unlisted attribute {key}") + elif not value_allowed(key_values, key, value): + problems.append(f"{metric}: {key}={value!r} outside the allowed values") + seen = {metric for metric, _ in points} + missing = sorted(set(instrument_keys) - seen) + if missing: + problems.append(f"instruments missing from the Collector output: {missing}") + prometheus = Path(prometheus_path).read_text() + if not re.search(rf'^agentic_execution_count\w*\{{[^}}]*service_name="{re.escape(service)}"', prometheus, re.M): + problems.append("the Prometheus endpoint has no agentic_execution_count series for this service") + if problems: + raise SystemExit("telemetry smoke check failed:\n " + "\n ".join(problems)) + print(f"ok: {len(seen)} instruments, {len(points)} data points, all allow-listed, service.name={service}") + + +def main() -> None: + command, *args = sys.argv[1:] or ["help"] + if command == "upstream": + serve_upstream(int(args[0])) + threading.Event().wait() + elif command == "requests": + send_smoke_requests(int(args[0])) + elif command == "check": + check(*args) + else: + raise SystemExit(__doc__) + + +if __name__ == "__main__": + main() diff --git a/scripts/tests/test_otel_fixtures.py b/scripts/tests/test_otel_fixtures.py new file mode 100644 index 00000000..5859375c --- /dev/null +++ b/scripts/tests/test_otel_fixtures.py @@ -0,0 +1,110 @@ +"""Tests for the telemetry smoke checker in otel_fixtures.py.""" + +import sys +import tempfile +import unittest +from pathlib import Path + +sys.path.insert(0, str(Path(__file__).resolve().parent)) + +import otel_fixtures # noqa: E402 + +SERVICE = "agentic-test" + + +def resource(service: str) -> list[str]: + return [ + "info\tResourceMetrics #0", + "Resource attributes:", + f" -> service.name: Str({service})", + "ScopeMetrics #0", + "InstrumentationScope agentic_core ", + ] + + +def metric(name: str, attributes: dict[str, str] | None = None) -> list[str]: + lines = ["Metric #0", "Descriptor:", f" -> Name: {name}", " -> DataType: Sum", "NumberDataPoints #0"] + if attributes: + lines.append("Data point attributes:") + lines += [f" -> {key}: Str({value})" for key, value in attributes.items()] + return [*lines, "StartTimestamp: 2026-01-01 00:00:00 +0000 UTC", "Value: 1"] + + +def complete_log(extra: list[str] | None = None) -> str: + """One point for every allow-listed instrument, as the Collector prints them.""" + instruments, _ = otel_fixtures.load_allow_list() + lines = resource(SERVICE) + for name in instruments: + lines += metric(name) + lines += extra or [] + return "\n".join(f"otel-collector-1 | {line}" for line in lines) + + +PROMETHEUS = f'agentic_execution_count_total{{agentic_api="responses",service_name="{SERVICE}"}} 1\n' + + +def run_check(log: str, prometheus: str = PROMETHEUS) -> None: + with tempfile.TemporaryDirectory() as directory: + log_path, metrics_path = Path(directory, "collector.log"), Path(directory, "metrics.txt") + log_path.write_text(log) + metrics_path.write_text(prometheus) + otel_fixtures.check(SERVICE, str(log_path), str(metrics_path)) + + +class AllowListTest(unittest.TestCase): + def test_reads_the_rust_harness_tables(self) -> None: + instruments, values = otel_fixtures.load_allow_list() + self.assertIn("agentic.execution.count", instruments) + self.assertEqual(instruments["agentic.websocket.connections.active"], []) + self.assertEqual(values["agentic.api"], ["responses", "messages"]) + self.assertIn("cancelled", values["error.type"]) + + +class ParseTest(unittest.TestCase): + def test_points_without_attributes_are_still_points(self) -> None: + log = "\n".join(resource(SERVICE) + metric("agentic.execution.active") + metric("a", {"k": "v"})) + self.assertEqual( + otel_fixtures.parse_debug_metrics(log), + [(SERVICE, "agentic.execution.active", {}), (SERVICE, "a", {"k": "v"})], + ) + + def test_points_belong_to_their_resource(self) -> None: + log = "\n".join(resource("other") + metric("a") + resource(SERVICE) + metric("b")) + self.assertEqual( + [(service, name) for service, name, _ in otel_fixtures.parse_debug_metrics(log)], + [("other", "a"), (SERVICE, "b")], + ) + + +class CheckTest(unittest.TestCase): + def test_accepts_every_instrument_with_allowed_attributes(self) -> None: + run_check(complete_log(metric("agentic.execution.count", {"agentic.api": "responses"}))) + + def test_rejects_an_unlisted_attribute_key(self) -> None: + with self.assertRaisesRegex(SystemExit, "unlisted attribute response.id"): + run_check(complete_log(metric("agentic.execution.count", {"response.id": "resp_1"}))) + + def test_rejects_an_unlisted_attribute_value(self) -> None: + with self.assertRaisesRegex(SystemExit, "outside the allowed values"): + run_check(complete_log(metric("agentic.execution.count", {"agentic.api": "gpt-4o"}))) + + def test_rejects_an_unlisted_instrument(self) -> None: + with self.assertRaisesRegex(SystemExit, "unlisted instrument agentic.surprise"): + run_check(complete_log(metric("agentic.surprise"))) + + def test_rejects_missing_instruments(self) -> None: + log = "\n".join(resource(SERVICE) + metric("agentic.execution.count")) + with self.assertRaisesRegex(SystemExit, "instruments missing"): + run_check(log) + + def test_ignores_other_services(self) -> None: + log = complete_log() + "\n" + "\n".join(resource("other") + metric("agentic.surprise")) + run_check(log) + + def test_requires_the_prometheus_series(self) -> None: + with self.assertRaisesRegex(SystemExit, "Prometheus endpoint"): + run_check(complete_log(), prometheus="") + + +if __name__ == "__main__": + unittest.main() From e6dff9b6fae39cabe29ba2fcaa02124938cbc8cb Mon Sep 17 00:00:00 2001 From: Zheng Lu Date: Fri, 9 Oct 2026 15:29:14 +0100 Subject: [PATCH 4/4] docs(telemetry): document metrics, the local Collector, and overhead Describe every instrument, its attributes and boundaries, when each is recorded, the local Collector setup, and the measured overhead. Note that a multi-agent response's rounds sample counts every agent, and that a WebSocket response's delivery wait ends when it finalizes. Signed-off-by: Zheng Lu --- ARCHITECTURE.md | 12 ++ docs/deploying/observability.md | 202 +++++++++++++++++++++++++++++++- 2 files changed, 209 insertions(+), 5 deletions(-) diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index 6a88863b..104d2d05 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -828,6 +828,18 @@ The boundary contract is one owner and one path per concern: - Delivery consumes translated frames and provides ordered, awaited client emission across inference rounds. +Telemetry follows the same owners (`executor/telemetry/`; see +[Observability](docs/deploying/observability.md)). The `ExecutionSpan` guard finalizes +the `agentic.execute` span and the execution metrics together, exactly once, from `Drop`. +Instruments come from `ExecutorMetrics` on `ExecutionContext`. The first-data timings +share an `ExecutionClock`. The pipeline entry marks the first upstream line; multi-agent +rounds run on their own pipelines, which share the execution's clock. The client-facing +stream marks the first event and first output-text delta it yields to the transport, and +its `InstrumentedStream` wrapper measures delivery wait. For retained (WebSocket) +responses that stream is the event stream `ResponseEventSink::stream` returns. Stage timers wrap +the code that owns each stage. A refactor that moves one of these boundaries must move its +mark with it rather than add a second one. + #### `accumulator/` — typed response assembly `ResponseAccumulator` owns validation, response lifecycle, typed output slots, delta diff --git a/docs/deploying/observability.md b/docs/deploying/observability.md index c3958133..e05b3b15 100644 --- a/docs/deploying/observability.md +++ b/docs/deploying/observability.md @@ -6,9 +6,10 @@ selected the gateway creates no provider, exporter thread, or network connection, and only prints local logs as before. This page covers HTTP and execution traces, upstream context propagation, -standard HTTP request metrics, trace-correlated local logs, and the export -lifecycle from [#279](https://github.com/vllm-project/agentic-api/issues/279). -Gateway-specific metrics remain a later phase. +HTTP, execution, stage, token, timing, delivery, and WebSocket metrics, +trace-correlated local logs, the export lifecycle, a local Collector setup, +and measured overhead, from +[#279](https://github.com/vllm-project/agentic-api/issues/279). ## Enable export @@ -220,6 +221,16 @@ trace context are separate from this application-attribute contract. ### Metrics +Metrics are recorded by the same guards that finalize the spans above, so each +is recorded exactly once on every terminal path — completion, upstream failure, +client disconnect, and requests abandoned at shutdown — and **regardless of +the trace sampling decision**: an unsampled request is still counted. Every +attribute is one of the enumerated values below or a boolean. Instruments come +from two instrumentation scopes: `agentic_server` (HTTP and WebSocket +transport) and `agentic_core` (execution). + +#### HTTP + | Instrument | Type | Attributes | | --- | --- | --- | | `http.server.request.duration` (seconds) | histogram | `http.request.method`, `http.route`, `http.response.status_code`, `url.scheme` | @@ -229,8 +240,115 @@ Duration boundaries are the semantic-convention set extended with `30`, `60`, `120`, and `300` seconds because streamed inference responses routinely run for minutes. Both instruments are recorded exactly once per request from a guard attached to the response body, so a disconnecting client cannot leave -the active-request count drifting. Metrics are recorded regardless of the -trace sampling decision. +the active-request count drifting. + +#### Executions + +One execution is one `agentic.execute` span: an HTTP request the executor or +raw proxy handles, or one WebSocket `response.create`. + +| Instrument | Type | Unit | Attributes | +| --- | --- | --- | --- | +| `agentic.execution.count` | counter | `{execution}` | `agentic.api`, `agentic.route`, `agentic.stream`, `agentic.execution.outcome`, and `error.type` when the outcome is `failed` | +| `agentic.execution.duration` | histogram | `s` | Same as `agentic.execution.count` | +| `agentic.execution.active` | up-down counter | `{execution}` | `agentic.api`, `agentic.route`, `agentic.stream` | +| `agentic.delivery.count` | counter | `{execution}` | `agentic.api`, `agentic.route`, `agentic.stream`, `agentic.delivery.outcome` | + +Attribute values are the span's: see [Execution span](#execution-span). +An execution becomes active when the gateway accepts it — for WebSocket, when +the request is admitted to its connection's queue — and is finalized when its +span closes. At that moment the count, duration, and delivery outcome are +recorded once and the active count is released. Duration runs from acceptance +to finalization, so for a stream it includes client delivery. + +#### Stages, rounds, and tokens + +| Instrument | Type | Unit | Attributes | +| --- | --- | --- | --- | +| `agentic.stage.duration` | histogram | `s` | `agentic.stage`: `rehydrate`, `inference`, `tool`, `compaction`, or `persist`; `agentic.tool.type` on `tool` samples; `error.type` when the stage failed (a category from the list above) or `cancelled` when it was dropped unfinished | +| `agentic.inference.rounds` | histogram | `{round}` | `agentic.api` | +| `gen_ai.client.token.usage` | histogram | `{token}` | `gen_ai.operation.name`: `chat`; `gen_ai.token.type`: `input` or `output`; `agentic.api` | + +- An `inference` sample is one upstream round: sending the request and, for a + streamed round, reading its whole body. `persist` is recorded only when the + request asked for storage. `tool` covers gateway-executed built-in tools in + the Responses executor, one sample per tool call. Gateway-executed built-in + tools in the Messages loop are not timed yet. +- `agentic.inference.rounds` is recorded once per execution, however the loop + ended, when at least one round started. A multi-agent response records one + sample that counts every agent's rounds, so it can exceed the round cap. +- `gen_ai.client.token.usage` records one sample per token type for each + upstream call, from that call's own `usage` (compaction summaries + included), never from turn totals. When the upstream omits `usage` or a + count, nothing is recorded — the gateway never substitutes zero. For the + Messages API the input count adds `cache_creation_input_tokens` and + `cache_read_input_tokens` to `input_tokens`. +- `gen_ai.request.model`, `gen_ai.response.model`, and `gen_ai.provider.name` + are deliberately absent: model names are not a bounded dimension for a + gateway, and the gateway cannot know which provider serves its upstream. +- Explicit `/v1/responses/compact` requests record their stage and token + samples but no execution, as they have no `agentic.execute` span. + +#### First-data timings + +These describe streamed executor responses only; non-streaming requests and +the raw proxy route record none of them. Each is measured from the moment the +gateway accepted the execution, recorded at most once per execution, and +carries only `agentic.api`. None of them is labelled time to first token, +because they measure different boundaries: + +| Instrument (seconds, histogram) | Stops when | +| --- | --- | +| `agentic.time_to_first_upstream_data` | The first SSE line of the upstream response reaches the executor pipeline. | +| `agentic.time_to_first_client_event` | The executor's client-facing stream yields the first semantic event of the response, such as `response.created` or `message_start`, to the transport. An executor error frame is not a response event. | +| `agentic.time_to_first_text` | The executor's client-facing stream yields the first output-text delta (`response.output_text.delta`, or a Messages `text_delta`) to the transport. Reasoning and tool-call deltas do not count. | + +For a plain text response every client event derives from upstream data, so +`first_upstream_data ≤ first_client_event ≤ first_text`. Gateway-generated +events, such as MCP tool discovery, can reach the client before any upstream +data. + +#### Delivery and WebSocket + +| Instrument | Type | Unit | Recorded | +| --- | --- | --- | --- | +| `agentic.delivery.wait.duration` | histogram | `s` | Once per streamed execution that handed over at least one frame: the total time the transport took to ask for the next frame after taking one. This is how long a slow client — a full socket buffer or WebSocket send queue — held the execution back. A WebSocket response finalizes on its own task, so frames the connection takes after that are not included. Attribute: `agentic.api`. | +| `agentic.websocket.connections.active` | up-down counter | `{connection}` | Responses WebSocket connections being upgraded or open. No attributes. | +| `agentic.websocket.queue.wait.duration` | histogram | `s` | Once per admitted `response.create`: time until dispatch (near 0 when nothing was ahead of it) or until it was discarded. No attributes. | + +Each `response.create` is its own execution, so N requests on one connection +record N executions and one connection. + +#### Histogram boundaries + +| Instruments | Boundaries | +| --- | --- | +| Execution and stage durations | Powers of two from `0.01` to `327.68` s | +| First-data timings | The `gen_ai.server.time_to_first_token` semantic-convention set, plus `20` s | +| Delivery wait | `0.001` to `60` s | +| WebSocket queue wait | `0.001`, then the execution boundaries | +| Token usage | The `gen_ai.client.token.usage` semantic-convention set | +| Inference rounds | `1` to `10`, one agent's round cap | + +Temporality is cumulative. + +#### Cardinality contract + +Request, response, and conversation identifiers, tool names, model names, +URLs, and prompt or output text never become metric dimensions. The allow-list +of instruments, attribute keys, and attribute values in +[`crates/agentic-server-core/tests/execution_metrics/harness.rs`](https://github.com/vllm-project/agentic-api/blob/main/crates/agentic-server-core/tests/execution_metrics/harness.rs) +mirrors the tables on this page. Every metric test and the Collector smoke test +fail on anything outside it, so adding a dimension means updating the list and +this page together. + +#### Embedding applications + +`agentic-server-core` records through `ExecutorMetrics`, built from a `Meter`. +`ExecutionContext::new` and `ExecutionContext::from_config` bind it to the +global meter provider when they run, so register a provider first or pass +your own with `ExecutionContext::with_metrics(ExecutorMetrics::new(&meter))`. +Without a provider every instrument is a no-op. ## Sampling @@ -293,6 +411,80 @@ Correlated lines are written without ANSI colour. 12 s, well inside the 30 s termination grace period used by the Kubernetes manifests. Spans still buffered when the deadline passes are lost. +## Local Collector + +[`deploy/otel`](https://github.com/vllm-project/agentic-api/tree/main/deploy/otel) +runs a backend-neutral OpenTelemetry Collector (collector-contrib, pinned by +digest). It receives OTLP/HTTP, applies `memory_limiter` and `batch`, prints +every span and metric with the `debug` exporter, and serves the metrics in +Prometheus format with `service.name` on every series. All ports bind to +`127.0.0.1`. + +```bash +docker compose -f deploy/otel/docker-compose.yaml up -d + +OTEL_TRACES_EXPORTER=otlp OTEL_METRICS_EXPORTER=otlp \ +OTEL_EXPORTER_OTLP_ENDPOINT=http://127.0.0.1:4318 \ +OTEL_METRIC_EXPORT_INTERVAL=5000 \ +agentic-server --llm-api-base http://127.0.0.1:8000 + +docker compose -f deploy/otel/docker-compose.yaml logs -f otel-collector # every span and metric +curl -s http://127.0.0.1:8889/metrics | grep '^agentic_' # Prometheus format +``` + +The Prometheus exporter rewrites names in Prometheus style, for example +`agentic_execution_count_total` and `agentic_execution_duration_seconds_bucket`. + +To browse traces as well, add Jaeger (UI on ): + +```bash +docker compose -f deploy/otel/docker-compose.yaml --env-file deploy/otel/jaeger.env up -d +``` + +[`scripts/tests/otel-smoke.sh`](https://github.com/vllm-project/agentic-api/blob/main/scripts/tests/otel-smoke.sh) +checks the whole path against a running Collector. It sends streamed, +blocking, proxied, and WebSocket requests through a scripted upstream, stops +the gateway so it flushes, and verifies that every instrument arrived with the +run's `service.name` and only allow-listed attributes. CI runs it on every +change. + +## Overhead + +Measured with +[`scripts/otel-overhead.py`](https://github.com/vllm-project/agentic-api/blob/main/scripts/otel-overhead.py) +against a release build. The gateway used SQLite storage (every request is +rehydrated, executed, and persisted) and a local scripted upstream. Each +scenario ran 2,000 sequential requests per round after 200 warm-up requests, +over three rounds that alternated the two modes. *Enabled* exports traces for +every request (the default `parentbased_always_on` sampler) and all metrics +over OTLP/HTTP to the local Collector above. Host: 13th Gen Intel Core +i9-13980HX, Linux 6.6 (WSL2). + +| Scenario | Telemetry | p50 (ms) | p90 (ms) | p99 (ms) | Gateway CPU per 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 | + +Across two runs, enabling telemetry added 0.04–0.13 ms at p50 and +0.07–0.20 ms of gateway CPU per request, and about 5 MiB of peak RSS. +Run-to-run variation for one build was up to 0.1 ms at p50. The tail is +about 13 ms in both modes and does not change with telemetry. In the same +session, a build without these metrics (`main` at `5473e02`, execution traces +only) measured 0.01–0.13 ms lower at p50 and 0.01–0.14 ms less CPU per +request, with telemetry enabled or disabled. Each difference is within that +variation, but every one pointed the same way, so at this scale the metrics +cost at most about 0.1 ms per request. The streamed responses here are short +(five events). Longer streams add, per frame, one clock read and a few atomic +operations. + +```bash +cargo build --release -p agentic-server --bin agentic-server +docker compose -f deploy/otel/docker-compose.yaml up -d +scripts/otel-overhead.py --bin target/release/agentic-server --requests 2000 --warmup 200 --rounds 3 +``` + ## Kubernetes Add the variables to the gateway ConfigMap (see