diff --git a/src/agentsight/src/aggregator/http/mod.rs b/src/agentsight/src/aggregator/http/mod.rs index f0ba8f40e1..d6e2ce5136 100644 --- a/src/agentsight/src/aggregator/http/mod.rs +++ b/src/agentsight/src/aggregator/http/mod.rs @@ -12,6 +12,7 @@ pub use aggregator::{ConnectionId, HttpConnectionAggregator}; pub(crate) use aggregator::ConnectionState; pub use pair::HttpPair; pub use response::AggregatedResponse; +pub(crate) use response::event_has_meaningful_output; // Re-export ParsedRequest from parser (replaces AggregatedRequest) pub use crate::parser::http::ParsedRequest; diff --git a/src/agentsight/src/aggregator/http/response.rs b/src/agentsight/src/aggregator/http/response.rs index 20d67bdd8e..3a7a5bab0b 100644 --- a/src/agentsight/src/aggregator/http/response.rs +++ b/src/agentsight/src/aggregator/http/response.rs @@ -57,7 +57,7 @@ impl AggregatedResponse { /// Get JSON bodies from SSE events, aggregated into a Vec /// /// Parses each SSE event's payload as JSON and collects into a Vec, - /// skipping events that are not valid JSON (e.g., [DONE] markers). + /// skipping events that are not valid JSON (e.g., `[DONE]` markers). pub fn json_body(&self) -> Vec { self.sse_events .iter() @@ -80,6 +80,19 @@ impl AggregatedResponse { .unwrap_or_else(|| self.start_timestamp_ns()) } + /// Returns the timestamp of the first SSE event carrying model output. + /// + /// Lifecycle and usage events are skipped because they do not represent a + /// token becoming available to the caller. Text, reasoning, and tool-call + /// deltas all count as output because providers include them in output-token + /// accounting. + pub fn first_output_timestamp_ns(&self) -> Option { + self.sse_events + .iter() + .find(|event| event_has_meaningful_output(event.json_body().as_ref())) + .map(|event| event.source_event().timestamp_ns) + } + /// Get duration in nanoseconds pub fn duration_ns(&self) -> u64 { self.end_timestamp_ns() @@ -136,6 +149,74 @@ impl AggregatedResponse { } } +fn non_empty_string(value: Option<&serde_json::Value>) -> bool { + value + .and_then(serde_json::Value::as_str) + .is_some_and(|value| !value.is_empty()) +} + +pub(crate) fn event_has_meaningful_output(value: Option<&serde_json::Value>) -> bool { + let Some(value) = value else { + return false; + }; + + if let Some(event_type) = value.get("type").and_then(serde_json::Value::as_str) { + match event_type { + "response.output_text.delta" + | "response.reasoning_text.delta" + | "response.reasoning_summary_text.delta" + | "response.function_call_arguments.delta" => { + return non_empty_string(value.get("delta")); + } + "content_block_delta" => { + let delta = value.get("delta"); + return non_empty_string(delta.and_then(|item| item.get("text"))) + || non_empty_string(delta.and_then(|item| item.get("thinking"))) + || non_empty_string(delta.and_then(|item| item.get("partial_json"))); + } + "content_block_start" => { + let block = value.get("content_block"); + return non_empty_string(block.and_then(|item| item.get("text"))) + || non_empty_string(block.and_then(|item| item.get("thinking"))) + || (block.and_then(|item| item.get("type")) + == Some(&serde_json::Value::String("tool_use".to_string())) + && non_empty_string(block.and_then(|item| item.get("name")))); + } + "response.output_item.added" => { + let item = value.get("item"); + return item.and_then(|item| item.get("type")) + == Some(&serde_json::Value::String("function_call".to_string())) + && non_empty_string(item.and_then(|item| item.get("name"))); + } + _ => {} + } + } + + value + .get("choices") + .and_then(serde_json::Value::as_array) + .is_some_and(|choices| { + choices.iter().any(|choice| { + let delta = choice.get("delta"); + non_empty_string(choice.get("text")) + || non_empty_string(delta.and_then(|item| item.get("content"))) + || non_empty_string(delta.and_then(|item| item.get("reasoning_content"))) + || delta + .and_then(|item| item.get("tool_calls")) + .and_then(serde_json::Value::as_array) + .is_some_and(|calls| { + calls.iter().any(|call| { + let function = call.get("function"); + non_empty_string(function.and_then(|item| item.get("name"))) + || non_empty_string( + function.and_then(|item| item.get("arguments")), + ) + }) + }) + }) + }) +} + impl TraceArgs for AggregatedResponse { fn to_trace_args(&self) -> serde_json::Value { let mut args = serde_json::Map::new(); @@ -214,3 +295,123 @@ impl ToChromeTraceEvent for AggregatedResponse { vec![event] } } + +#[cfg(test)] +mod latency_tests { + use super::{AggregatedResponse, event_has_meaningful_output}; + use crate::parser::http::ParsedResponse; + use crate::parser::sse::ParsedSseEvent; + use crate::probes::sslsniff::SslEvent; + use std::collections::HashMap; + use std::rc::Rc; + + fn ssl_event(data: &str, timestamp_ns: u64) -> Rc { + Rc::new(SslEvent { + source: 0, + timestamp_ns, + delta_ns: 0, + pid: 1, + tid: 1, + uid: 0, + len: data.len() as u32, + rw: 0, + comm: String::new(), + buf: data.as_bytes().to_vec(), + is_handshake: false, + ssl_ptr: 0, + }) + } + + fn sse_event(data: &str, timestamp_ns: u64) -> ParsedSseEvent { + ParsedSseEvent::new( + None, + None, + None, + 0, + data.len(), + ssl_event(data, timestamp_ns), + ) + } + + fn response_with_sse_events(sse_events: Vec) -> AggregatedResponse { + AggregatedResponse { + parsed: ParsedResponse { + version: 1, + status_code: 200, + reason: "OK".to_string(), + headers: HashMap::new(), + body_offset: 0, + body_len: 0, + source_event: ssl_event("", 10), + }, + sse_events, + sse_continuation_bytes: None, + } + } + + #[test] + fn skips_openai_metadata_before_output_delta() { + let created = serde_json::json!({"type": "response.created"}); + let empty = serde_json::json!({"type": "response.output_text.delta", "delta": ""}); + let output = serde_json::json!({ + "type": "response.output_text.delta", + "delta": "hello" + }); + assert!(!event_has_meaningful_output(Some(&created))); + assert!(!event_has_meaningful_output(Some(&empty))); + assert!(event_has_meaningful_output(Some(&output))); + } + + #[test] + fn recognizes_anthropic_and_chat_completion_output() { + let anthropic = serde_json::json!({ + "type": "content_block_delta", + "delta": {"type": "text_delta", "text": "hello"} + }); + let chat = serde_json::json!({ + "choices": [{"delta": {"content": "hello"}}] + }); + assert!(event_has_meaningful_output(Some(&anthropic))); + assert!(event_has_meaningful_output(Some(&chat))); + } + + #[test] + fn first_output_timestamp_uses_first_nonempty_output_delta() { + let response = response_with_sse_events(vec![ + sse_event(r#"{"type":"response.created"}"#, 100), + sse_event(r#"{"type":"response.output_text.delta","delta":""}"#, 200), + sse_event( + r#"{"type":"response.output_text.delta","delta":"hello"}"#, + 300, + ), + sse_event( + r#"{"type":"response.output_text.done","text":"hello world"}"#, + 400, + ), + sse_event( + r#"{"type":"response.output_item.done","item":{"type":"message","content":[{"type":"output_text","text":"hello world"}]}}"#, + 500, + ), + sse_event(r#"{"type":"response.completed"}"#, 600), + ]); + + assert_eq!(response.first_output_timestamp_ns(), Some(300)); + } + + #[test] + fn first_output_timestamp_is_none_without_observable_delta() { + let response = response_with_sse_events(vec![ + sse_event( + r#"{"type":"response.output_text.done","text":"final text"}"#, + 500, + ), + sse_event( + r#"{"type":"response.output_item.done","item":{"type":"message","content":[{"type":"output_text","text":"final text"}]}}"#, + 600, + ), + sse_event(r#"{"type":"response.completed"}"#, 700), + ]); + + assert_eq!(response.first_output_timestamp_ns(), None); + } +} diff --git a/src/agentsight/src/aggregator/http2.rs b/src/agentsight/src/aggregator/http2.rs index 3714069a98..17ce35836b 100644 --- a/src/agentsight/src/aggregator/http2.rs +++ b/src/agentsight/src/aggregator/http2.rs @@ -5,6 +5,7 @@ //! to form complete HTTP/2 request/response pairs. use crate::aggregator::http::ConnectionId; +use crate::aggregator::http::event_has_meaningful_output; use crate::aggregator::result::AggregatedResult; use crate::chrome_trace::{ChromeTraceEvent, ToChromeTraceEvent, ns_to_us}; use crate::config::DEFAULT_CONNECTION_CAPACITY; @@ -305,6 +306,40 @@ impl Http2Stream { } } + /// Return the capture timestamp of the first observable meaningful SSE output. + /// + /// HTTP/2 keeps response DATA frames (and their source-event timestamps), so + /// parse the uncompressed stream incrementally and attribute each completed + /// SSE event to the DATA frame that made it observable. Compressed response + /// bodies cannot be mapped back to plaintext event boundaries safely. + pub fn first_output_timestamp_ns(&self) -> Option { + if self + .content_encoding() + .is_some_and(|encoding| !encoding.eq_ignore_ascii_case("identity")) + { + return None; + } + + let mut body = Vec::new(); + let mut parsed_event_count = 0usize; + for frame in &self.response_data_frames { + body.extend_from_slice(frame.payload()); + let Ok(body_str) = std::str::from_utf8(&body) else { + continue; + }; + let parsed = SSEParser::parse_stream(body_str); + + for event in parsed.events.iter().skip(parsed_event_count) { + let value = serde_json::from_str::(&event.data).ok(); + if event_has_meaningful_output(value.as_ref()) { + return Some(frame.source_event.timestamp_ns); + } + } + parsed_event_count = parsed.events.len(); + } + None + } + /// Try to parse request body as JSON (concatenates all data frames first) pub fn request_json_body(&self) -> Option { self.request_body_str() @@ -352,9 +387,26 @@ impl Http2Stream { Some(serde_json::Value::Array(json_array)) } } + /// Count complete SSE events in the response body. + /// + /// The count follows the HTTP/1 aggregator's event count semantics and + /// includes non-JSON events such as the [DONE] marker. + pub fn response_sse_event_count(&self) -> usize { + self.response_body_str() + .map(|body| SSEParser::parse_stream(&body).events.len()) + .unwrap_or(0) + } /// Check if response content-type indicates SSE stream pub fn is_response_sse(&self) -> bool { + if let Some(headers) = self.decoded_response_headers.as_ref() { + if let Some((_, value)) = headers + .iter() + .find(|(name, _)| name.eq_ignore_ascii_case("content-type")) + { + return value.contains("text/event-stream"); + } + } self.response_headers .as_ref() .map(|h| { @@ -1207,6 +1259,93 @@ mod tests { assert_eq!(StreamDirection::from_rw(0), StreamDirection::Response); } + #[test] + fn first_output_timestamp_uses_meaningful_data_frame_timestamp() { + let mut stream = + Http2Stream::new(StreamId::new(ConnectionId { pid: 1, ssl_ptr: 1 }, 1), 100); + let events = [ + (100, br#"data: {"type":"response.created"}"#.to_vec()), + ( + 200, + br#"data: {"type":"response.output_text.delta","delta":""}"#.to_vec(), + ), + ( + 300, + br#"data: {"type":"response.output_text.delta","delta":"hello"}"#.to_vec(), + ), + ( + 400, + br#"data: {"type":"response.output_text.done","text":"hello"}"#.to_vec(), + ), + ]; + for (timestamp_ns, mut payload) in events { + payload.extend_from_slice(&[10, 10]); + stream.response_data_frames.push(create_test_frame( + 1, + 0, + 0, + payload, + create_test_event(1234, 0x1000, 0, timestamp_ns), + )); + } + + assert_eq!(stream.first_output_timestamp_ns(), Some(300)); + } + + #[test] + fn first_output_timestamp_handles_meaningful_event_split_across_data_frames() { + let mut stream = + Http2Stream::new(StreamId::new(ConnectionId { pid: 1, ssl_ptr: 1 }, 1), 100); + let first_payload = b"data: {\"type\":\"response.created\"}\n\ndata: {\"type\":\"response.output_text.delta\",\"delta\":\"hel".to_vec(); + let second_payload = b"lo\"}\n\n".to_vec(); + + // The first DATA frame has a complete metadata event, but the + // meaningful event is still incomplete and must not be counted. + let first_body = std::str::from_utf8(&first_payload).unwrap(); + let first_parse = SSEParser::parse_stream(first_body); + assert_eq!(first_parse.events.len(), 1); + assert!(first_parse.events.iter().all(|event| { + let value = serde_json::from_str::(&event.data).ok(); + !event_has_meaningful_output(value.as_ref()) + })); + + stream.response_data_frames.push(create_test_frame( + 1, + 0, + 0, + first_payload, + create_test_event(1234, 0x1000, 0, 200), + )); + stream.response_data_frames.push(create_test_frame( + 1, + 0, + 0, + second_payload, + create_test_event(1234, 0x1000, 0, 400), + )); + + // Re-parsing the accumulated body after frame 2 must attribute the + // first complete meaningful event to frame 2, not the metadata frame. + assert_eq!(stream.first_output_timestamp_ns(), Some(400)); + } + + #[test] + fn first_output_timestamp_is_none_without_meaningful_data_frame() { + let mut stream = + Http2Stream::new(StreamId::new(ConnectionId { pid: 1, ssl_ptr: 1 }, 1), 100); + let mut payload = br#"data: {"type":"response.output_text.done","text":"final"}"#.to_vec(); + payload.extend_from_slice(&[10, 10]); + stream.response_data_frames.push(create_test_frame( + 1, + 0, + 0, + payload, + create_test_event(1234, 0x1000, 0, 500), + )); + + assert_eq!(stream.first_output_timestamp_ns(), None); + } + #[test] fn test_aggregator_process_request_response() { let mut aggregator = Http2StreamAggregator::new(); diff --git a/src/agentsight/src/analyzer/audit/analyzer.rs b/src/agentsight/src/analyzer/audit/analyzer.rs index b6e9fa5c3a..fab2133805 100644 --- a/src/agentsight/src/analyzer/audit/analyzer.rs +++ b/src/agentsight/src/analyzer/audit/analyzer.rs @@ -231,6 +231,7 @@ mod tests { response_headers: "{}".into(), response_body: response_body.map(|s| s.to_string()), duration_ns: 1000, + first_output_timestamp_ns: None, is_sse, sse_event_count: 0, } diff --git a/src/agentsight/src/analyzer/result.rs b/src/agentsight/src/analyzer/result.rs index 8ac6d83aad..ea47552b29 100644 --- a/src/agentsight/src/analyzer/result.rs +++ b/src/agentsight/src/analyzer/result.rs @@ -53,6 +53,8 @@ pub struct HttpRecord { pub response_body: Option, /// Duration in nanoseconds (response end - request start) pub duration_ns: u64, + /// First observable model-output timestamp for streaming responses. + pub first_output_timestamp_ns: Option, /// Whether this is an SSE streaming response pub is_sse: bool, /// Number of SSE events (0 for non-SSE) diff --git a/src/agentsight/src/analyzer/unified.rs b/src/agentsight/src/analyzer/unified.rs index 761a3133f8..2a3adf727f 100644 --- a/src/agentsight/src/analyzer/unified.rs +++ b/src/agentsight/src/analyzer/unified.rs @@ -995,6 +995,7 @@ impl Analyzer { duration_ns: resp .end_timestamp_ns() .saturating_sub(req.source_event.timestamp_ns), + first_output_timestamp_ns: None, is_sse: false, sse_event_count: 0, }) @@ -1038,6 +1039,7 @@ impl Analyzer { duration_ns: resp .end_timestamp_ns() .saturating_sub(req.source_event.timestamp_ns), + first_output_timestamp_ns: resp.first_output_timestamp_ns(), is_sse: true, sse_event_count: resp.sse_event_count(), }) @@ -1067,6 +1069,7 @@ impl Analyzer { response_headers: String::new(), response_body: None, duration_ns: 0, + first_output_timestamp_ns: None, is_sse: false, sse_event_count: 0, }) @@ -1076,22 +1079,20 @@ impl Analyzer { // Try SSE parsing first, fallback to regular text if it fails // This is more robust than checking content-type header (which may fail due to HPACK) - let (response_body, sse_event_count) = - if let Some(sse_json) = stream.response_sse_json_array() { - // Successfully parsed as SSE - let event_count = sse_json.as_array().map(|a| a.len()).unwrap_or(0); - ( - Some(serde_json::to_string(&sse_json).unwrap_or_default()), - event_count, - ) - } else { - // Not SSE, try regular JSON or raw text - let body = stream - .response_json_body() - .map(|v| serde_json::to_string(&v).unwrap_or_default()) - .or_else(|| stream.response_body_str()); - (body, 0) - }; + let parsed_sse_json = stream.response_sse_json_array(); + let sse_event_count = stream.response_sse_event_count(); + let response_body = if let Some(sse_json) = parsed_sse_json.as_ref() { + // Successfully parsed as SSE + Some(serde_json::to_string(sse_json).unwrap_or_default()) + } else { + // Not SSE, try regular JSON or raw text + let body = stream + .response_json_body() + .map(|v| serde_json::to_string(&v).unwrap_or_default()) + .or_else(|| stream.response_body_str()); + body + }; + let is_sse = stream.is_response_sse() || sse_event_count > 0; Some(HttpRecord { timestamp_ns: stream.start_timestamp_ns, @@ -1107,7 +1108,12 @@ impl Analyzer { duration_ns: stream .end_timestamp_ns .saturating_sub(stream.start_timestamp_ns), - is_sse: sse_event_count > 0, + first_output_timestamp_ns: if is_sse { + stream.first_output_timestamp_ns() + } else { + None + }, + is_sse, sse_event_count, }) } @@ -1487,16 +1493,31 @@ mod tests { fn build_sse_http2_stream( path: &str, request_body: &[u8], - sse_chunk: &serde_json::Value, + sse_chunk: Option<&serde_json::Value>, + ) -> crate::aggregator::Http2Stream { + let response_body = sse_chunk.map_or_else( + || "data: [DONE]\n\n".to_string(), + |chunk| format!("data: {}\n\ndata: [DONE]\n\n", chunk), + ); + build_http2_stream( + path, + request_body, + response_body.into_bytes(), + "text/event-stream", + ) + } + + fn build_http2_stream( + path: &str, + request_body: &[u8], + body_bytes: Vec, + content_type: &str, ) -> crate::aggregator::Http2Stream { use crate::aggregator::{ConnectionId, Http2Stream, StreamId}; use crate::parser::{Http2FrameType, ParsedHttp2Frame}; use crate::probes::sslsniff::SslEvent; use std::rc::Rc; - let response_body = format!("data: {}\n\ndata: [DONE]\n\n", sse_chunk); - let body_bytes = response_body.into_bytes(); - let ssl_event = Rc::new(SslEvent { source: 0, timestamp_ns: 1_000_000_000, @@ -1568,7 +1589,7 @@ mod tests { }); stream.decoded_response_headers = Some(vec![ (":status".to_string(), "200".to_string()), - ("content-type".to_string(), "text/event-stream".to_string()), + ("content-type".to_string(), content_type.to_string()), ]); stream.response_data_frames.push(ParsedHttp2Frame { frame_type: Http2FrameType::Data, @@ -1583,6 +1604,87 @@ mod tests { stream.end_timestamp_ns = 1_100_000_000; stream } + fn analyze_http2_record( + analyzer: &Analyzer, + stream: crate::aggregator::Http2Stream, + ) -> HttpRecord { + analyzer + .analyze_aggregated(&AggregatedResult::Http2StreamComplete(stream)) + .into_iter() + .find_map(|result| match result { + AnalysisResult::Http(record) => Some(record), + _ => None, + }) + .expect("Analyzer must emit HttpRecord") + } + + #[test] + fn first_output_timestamp_propagates_from_http2_to_latency_metrics() { + use crate::genai::{GenAIBuilder, GenAISemanticEvent}; + use crate::response_map::ResponseSessionMapper; + use std::collections::HashMap; + + let analyzer = Analyzer::new(); + let request_body = + br#"{"model":"gpt-4o","stream":true,"messages":[{"role":"user","content":"hi"}]}"#; + let chunk = serde_json::json!({ + "id": "chatcmpl-h2-propagation", + "model": "gpt-4o", + "choices": [{"delta": {"content": "hi"}, "finish_reason": "stop"}] + }); + let stream = build_sse_http2_stream("/v1/chat/completions", request_body, Some(&chunk)); + let results = analyzer.analyze_aggregated(&AggregatedResult::Http2StreamComplete(stream)); + + let http = results + .iter() + .find_map(|result| match result { + AnalysisResult::Http(record) => Some(record), + _ => None, + }) + .expect("Analyzer must emit HttpRecord"); + assert_eq!(http.first_output_timestamp_ns, Some(1_000_000_000)); + assert!(http.is_sse); + + let builder = GenAIBuilder::new(); + let mapper = ResponseSessionMapper::new(); + let cache = HashMap::::new(); + let (built, pending) = builder.build_with_pending(&results, &mapper, &cache); + let call = built + .events + .into_iter() + .find_map(|event| match event { + GenAISemanticEvent::LLMCall(call) => Some(call), + _ => None, + }) + .expect("GenAIBuilder must emit LLMCall"); + assert_eq!( + call.metadata.get("first_output_timestamp_ns"), + Some(&"1000000000".to_string()) + ); + + let event = GenAISemanticEvent::LLMCall(call); + let path = std::env::temp_dir().join(format!( + "agentsight_analyzer_latency_{}.db", + std::process::id() + )); + let _ = std::fs::remove_file(&path); + let store = crate::storage::sqlite::genai::GenAISqliteStore::new_with_path(&path).unwrap(); + if let Some(info) = pending.as_ref() { + store.insert_pending(info).unwrap(); + } + store.complete_pending(&event).unwrap(); + + let metrics = store.get_latency_metrics(0, 2_000_000_000, None).unwrap(); + assert_eq!(metrics.len(), 1); + assert_eq!(metrics[0].streaming_call_count, 1); + assert_eq!( + metrics[0].ttft_ms.as_ref().map(|metric| metric.p50), + Some(100.0) + ); + + drop(store); + let _ = std::fs::remove_file(path); + } #[test] fn test_extract_message_from_http_parses_openai_sse_request() { @@ -1597,7 +1699,7 @@ mod tests { "model": "gpt-4o", "choices": [{"delta": {"content": "hi"}, "finish_reason": "stop"}] }); - let stream = build_sse_http2_stream("/v1/chat/completions", request_body, &chunk); + let stream = build_sse_http2_stream("/v1/chat/completions", request_body, Some(&chunk)); let agg = AggregatedResult::Http2StreamComplete(stream); let result = analyzer.extract_message_from_http(&agg); @@ -1618,8 +1720,11 @@ mod tests { let chunk = serde_json::json!({ "choices": [{"message": {"content": "hi", "tool_use": null}}] }); - let stream = - build_sse_http2_stream("/api/v1/copilot/generate_copilot", &request_body, &chunk); + let stream = build_sse_http2_stream( + "/api/v1/copilot/generate_copilot", + &request_body, + Some(&chunk), + ); let agg = AggregatedResult::Http2StreamComplete(stream); let result = analyzer.extract_message_from_http(&agg); @@ -1647,7 +1752,7 @@ mod tests { let stream = build_sse_http2_stream( "/@modelcontextprotocol%2fserver-everything", request_body, - &chunk, + Some(&chunk), ); let agg = AggregatedResult::Http2StreamComplete(stream); @@ -1659,13 +1764,64 @@ mod tests { let llm_stream = build_sse_http2_stream( "/v1/chat/completions", br#"{"model":"gpt-4o","messages":[{"role":"user","content":"hi"}]}"#, - &serde_json::json!({"id": "chatcmpl-1"}), + Some(&serde_json::json!({"id": "chatcmpl-1"})), ); assert!(Analyzer::should_parse_message( &AggregatedResult::Http2StreamComplete(llm_stream) )); } + #[test] + fn http2_sse_without_observable_output_remains_streaming() { + let analyzer = Analyzer::new(); + let request_body = + br#"{"model":"gpt-4o","stream":true,"messages":[{"role":"user","content":"hi"}]}"#; + let stream = build_sse_http2_stream("/v1/chat/completions", request_body, None); + + let http = analyze_http2_record(&analyzer, stream); + + assert!(http.is_sse); + assert_eq!(http.first_output_timestamp_ns, None); + assert_eq!(http.sse_event_count, 1); + } + + #[test] + fn http2_metadata_only_sse_keeps_streaming_identity_without_first_output() { + let analyzer = Analyzer::new(); + let request_body = + br#"{"model":"gpt-4o","stream":true,"messages":[{"role":"user","content":"hi"}]}"#; + let stream = build_sse_http2_stream( + "/v1/chat/completions", + request_body, + Some(&serde_json::json!({"type": "response.created"})), + ); + + let http = analyze_http2_record(&analyzer, stream); + + assert!(http.is_sse); + assert_eq!(http.first_output_timestamp_ns, None); + assert_eq!(http.sse_event_count, 2); + } + + #[test] + fn http2_ordinary_json_response_is_not_streaming() { + let analyzer = Analyzer::new(); + let request_body = + br#"{"model":"gpt-4o","stream":false,"messages":[{"role":"user","content":"hi"}]}"#; + let stream = build_http2_stream( + "/v1/chat/completions", + request_body, + br#"{"id":"non-sse","choices":[]}"#.to_vec(), + "application/json", + ); + + let http = analyze_http2_record(&analyzer, stream); + + assert!(!http.is_sse); + assert_eq!(http.first_output_timestamp_ns, None); + assert_eq!(http.sse_event_count, 0); + } + #[test] fn test_extract_token_from_json_body_zero_tokens() { let analyzer = Analyzer::new(); diff --git a/src/agentsight/src/ffi.rs b/src/agentsight/src/ffi.rs index 89f9560f3f..5ecd2aa317 100644 --- a/src/agentsight/src/ffi.rs +++ b/src/agentsight/src/ffi.rs @@ -1660,6 +1660,7 @@ mod tests { response_headers: "{\"content-type\":\"application/octet-stream\"}".to_string(), response_body, duration_ns: 1, + first_output_timestamp_ns: None, is_sse: false, sse_event_count: 0, } diff --git a/src/agentsight/src/genai/call_builder.rs b/src/agentsight/src/genai/call_builder.rs index 1d3c658f54..ae7500c994 100644 --- a/src/agentsight/src/genai/call_builder.rs +++ b/src/agentsight/src/genai/call_builder.rs @@ -272,6 +272,12 @@ impl GenAIBuilder { meta.insert("path".to_string(), http.path.clone()); meta.insert("status_code".to_string(), http.status_code.to_string()); meta.insert("is_sse".to_string(), http.is_sse.to_string()); + if let Some(timestamp_ns) = http.first_output_timestamp_ns { + meta.insert( + "first_output_timestamp_ns".to_string(), + timestamp_ns.to_string(), + ); + } meta.insert( "sse_event_count".to_string(), http.sse_event_count.to_string(), @@ -804,6 +810,7 @@ mod tests { response_headers: "{}".to_string(), response_body, duration_ns: 1_000_000, + first_output_timestamp_ns: None, is_sse: false, sse_event_count: 0, } @@ -1693,6 +1700,53 @@ mod tests { assert!(!call.request.stream); } + #[test] + fn first_output_timestamp_reaches_latency_query() { + let mut http = make_http( + "/v1/chat/completions", + Some( + r#"{"model":"gpt-4o","messages":[{"role":"user","content":"hello"}]}"# + .to_string(), + ), + Some( + r#"{"id":"chatcmpl-test","object":"chat.completion","choices":[{"index":0,"message":{"role":"assistant","content":"world"},"finish_reason":"stop"}],"usage":{"prompt_tokens":1,"completion_tokens":1,"total_tokens":2}}"# + .to_string(), + ), + ); + http.duration_ns = 500_000_000; + http.first_output_timestamp_ns = Some(1_100_000_000); + http.is_sse = true; + http.sse_event_count = 4; + + let builder = GenAIBuilder::new(); + let call = build_call(&builder, &[AnalysisResult::Http(http)]).unwrap(); + assert_eq!( + call.metadata.get("first_output_timestamp_ns"), + Some(&"1100000000".to_string()) + ); + assert_eq!(call.metadata.get("is_sse"), Some(&"true".to_string())); + + let path = std::env::temp_dir().join(format!( + "agentsight_timing_pipeline_{}_{}.db", + std::process::id(), + 1_100_000_000u64 + )); + let _ = std::fs::remove_file(&path); + let store = crate::storage::sqlite::genai::GenAISqliteStore::new_with_path(&path).unwrap(); + let event = crate::genai::semantic::GenAISemanticEvent::LLMCall(call); + store.complete_pending(&event).unwrap(); + + let metrics = store.get_latency_metrics(0, 2_000_000_000, None).unwrap(); + assert_eq!(metrics.len(), 1); + assert_eq!(metrics[0].streaming_call_count, 1); + assert_eq!( + metrics[0].ttft_ms.as_ref().map(|metric| metric.p50), + Some(100.0) + ); + drop(store); + let _ = std::fs::remove_file(path); + } + #[test] fn test_build_llm_call_call_kind_main() { let builder = GenAIBuilder::new(); diff --git a/src/agentsight/src/server/handlers.rs b/src/agentsight/src/server/handlers.rs index 8db51ff01b..878f59a10d 100644 --- a/src/agentsight/src/server/handlers.rs +++ b/src/agentsight/src/server/handlers.rs @@ -417,6 +417,47 @@ pub struct TimeseriesQuery { pub buckets: Option, } +/// Query parameters for LLM latency percentile metrics. +#[derive(Debug, Deserialize)] +pub struct LatencyMetricsQuery { + pub start_ns: Option, + pub end_ns: Option, + pub agent_name: Option, +} + +/// GET /api/metrics/latency +#[get("/metrics/latency")] +pub async fn get_latency_metrics( + data: web::Data, + query: web::Query, +) -> impl Responder { + let end_ns = query.end_ns.unwrap_or_else(|| now_ns() as i64); + let start_ns = match query.start_ns { + Some(start_ns) => start_ns, + None => match end_ns.checked_sub(86_400_000_000_000i64) { + Some(start_ns) => start_ns, + None => { + return HttpResponse::BadRequest() + .json(serde_json::json!({"error": "default time range is out of bounds"})); + } + }, + }; + if start_ns > end_ns { + return HttpResponse::BadRequest() + .json(serde_json::json!({"error": "start_ns must not exceed end_ns"})); + } + match GenAISqliteStore::new_with_path(&data.storage_path) { + Ok(store) => match store.get_latency_metrics(start_ns, end_ns, query.agent_name.as_deref()) + { + Ok(summary) => HttpResponse::Ok().json(summary), + Err(error) => HttpResponse::InternalServerError() + .json(serde_json::json!({"error": error.to_string()})), + }, + Err(error) => HttpResponse::InternalServerError() + .json(serde_json::json!({"error": error.to_string()})), + } +} + /// GET /api/agent-names?start_ns=&end_ns= /// /// Returns a sorted list of distinct agent_name values. @@ -1985,7 +2026,8 @@ mod tests { .service(get_trace_detail) .service(get_conversation_events) .service(list_agent_names) - .service(get_timeseries), + .service(get_timeseries) + .service(get_latency_metrics), ) .await; @@ -2070,6 +2112,41 @@ mod tests { assert!(timeseries_body["token_series"].as_array().is_some()); assert!(timeseries_body["model_series"].as_array().is_some()); + let latency = awtest::call_service( + &app, + awtest::TestRequest::get() + .uri("/metrics/latency?start_ns=0&end_ns=9223372036854775807&agent_name=claude") + .to_request(), + ) + .await; + assert_eq!(latency.status(), StatusCode::OK); + let latency_body = service_response_json(latency).await; + assert_eq!(latency_body.as_array().map(Vec::len), Some(1)); + assert_eq!(latency_body[0]["agent_name"], "claude"); + assert!(latency_body[0]["e2e_latency_ms"]["p50"].is_number()); + assert!(latency_body[0]["ttft_ms"].is_null()); + + cleanup_db(&db_path); + } + + #[actix_web::test] + async fn latency_rejects_unrepresentable_default_start() { + let db_path = unique_handler_db("latency_overflow"); + let app = awtest::init_service( + App::new() + .app_data(test_app_state_with_storage(db_path.clone())) + .service(get_latency_metrics), + ) + .await; + + let response = awtest::call_service( + &app, + awtest::TestRequest::get() + .uri("/metrics/latency?end_ns=-9223372036854775808") + .to_request(), + ) + .await; + assert_eq!(response.status(), StatusCode::BAD_REQUEST); cleanup_db(&db_path); } diff --git a/src/agentsight/src/server/mod.rs b/src/agentsight/src/server/mod.rs index 3fd5cb2cfe..56174eae55 100644 --- a/src/agentsight/src/server/mod.rs +++ b/src/agentsight/src/server/mod.rs @@ -221,6 +221,7 @@ fn configure_routes(cfg: &mut web::ServiceConfig) { .service(handlers::latest_grader) .service(handlers::list_agent_names) .service(handlers::get_timeseries) + .service(handlers::get_latency_metrics) .service(handlers::export_atif_trace) .service(handlers::export_atif_session) .service(handlers::export_atif_conversation) diff --git a/src/agentsight/src/storage/sqlite/genai/events.rs b/src/agentsight/src/storage/sqlite/genai/events.rs index fb172bd230..0847855a2d 100644 --- a/src/agentsight/src/storage/sqlite/genai/events.rs +++ b/src/agentsight/src/storage/sqlite/genai/events.rs @@ -448,12 +448,13 @@ impl GenAISqliteStore { cache_creation_tokens, cache_read_tokens, system_instructions, input_messages, output_messages, user_query, http_method, http_path, status_code, - is_sse, sse_event_count, event_json, tool_call_ids, call_kind + is_sse, sse_event_count, event_json, tool_call_ids, call_kind, + first_output_timestamp_ns ) VALUES ( ?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8, ?9, ?10, ?11, ?12, ?13, ?14, ?15, ?16, ?17, ?18, ?19, ?20, ?21, ?22, ?23, ?24, ?25, ?26, ?27, ?28, ?29, ?30, ?31, ?32, - ?33, ?34, ?35, ?36, ?37, ?38, ?39, ?40, ?41 + ?33, ?34, ?35, ?36, ?37, ?38, ?39, ?40, ?41, ?42 )", params![ "llm_call", @@ -497,6 +498,9 @@ impl GenAISqliteStore { event_json, tool_call_ids, call.metadata.get("call_kind").map(|s| s.as_str()).unwrap_or("main"), + call.metadata + .get("first_output_timestamp_ns") + .and_then(|value| value.parse::().ok()), ], )?; } diff --git a/src/agentsight/src/storage/sqlite/genai/mod.rs b/src/agentsight/src/storage/sqlite/genai/mod.rs index 945c6886d8..73463d32a6 100644 --- a/src/agentsight/src/storage/sqlite/genai/mod.rs +++ b/src/agentsight/src/storage/sqlite/genai/mod.rs @@ -29,7 +29,10 @@ use crate::config::BatchConfig; pub use events::TraceEventDetail; pub use pending::{PendingCallInfo, PendingOrigin, SseEnrichment}; pub use session::{SavingsSessionSummary, SessionSummary, ToolCallTurnInfo, TraceSummary}; -pub use stats::{AgentTokenSummary, ModelTimeseriesBucket, TimeseriesBucket}; +pub use stats::{ + AgentTokenSummary, LatencyMetricsSummary, MetricPercentiles, ModelTimeseriesBucket, + TimeseriesBucket, +}; /// SQLite-backed GenAI event storage pub struct GenAISqliteStore { diff --git a/src/agentsight/src/storage/sqlite/genai/pending.rs b/src/agentsight/src/storage/sqlite/genai/pending.rs index 3f74132a50..a28227877e 100644 --- a/src/agentsight/src/storage/sqlite/genai/pending.rs +++ b/src/agentsight/src/storage/sqlite/genai/pending.rs @@ -266,8 +266,9 @@ impl GenAISqliteStore { sse_event_count = ?26, event_json = ?27, tool_call_ids = ?28, - call_kind = ?29 - WHERE call_id = ?30 AND status IN ('pending', 'interrupted')", + call_kind = ?29, + first_output_timestamp_ns = ?30 + WHERE call_id = ?31 AND status IN ('pending', 'interrupted')", params![ call.metadata.get("response_id"), call.metadata.get("conversation_id"), @@ -305,6 +306,9 @@ impl GenAISqliteStore { .get("call_kind") .map(|s| s.as_str()) .unwrap_or("main"), + call.metadata + .get("first_output_timestamp_ns") + .and_then(|value| value.parse::().ok()), call.call_id.as_str(), ], )?; @@ -367,13 +371,14 @@ impl GenAISqliteStore { event_json = ?27, tool_call_ids = ?28, call_kind = ?29, - call_id = ?30 + first_output_timestamp_ns = ?30, + call_id = ?31 WHERE id = ( SELECT id FROM genai_events WHERE event_type = 'llm_call' AND status IN ('pending', 'interrupted') AND pending_origin = 'idle_drain' - AND pending_match_key = ?31 + AND pending_match_key = ?32 ORDER BY start_timestamp_ns DESC LIMIT 1 )", @@ -414,6 +419,9 @@ impl GenAISqliteStore { .get("call_kind") .map(|s| s.as_str()) .unwrap_or("main"), + call.metadata + .get("first_output_timestamp_ns") + .and_then(|value| value.parse::().ok()), call.call_id.as_str(), match_key.as_str(), ], diff --git a/src/agentsight/src/storage/sqlite/genai/schema.rs b/src/agentsight/src/storage/sqlite/genai/schema.rs index 9351b87283..4b147cbdd7 100644 --- a/src/agentsight/src/storage/sqlite/genai/schema.rs +++ b/src/agentsight/src/storage/sqlite/genai/schema.rs @@ -51,6 +51,7 @@ impl GenAISqliteStore { start_timestamp_ns INTEGER NOT NULL, end_timestamp_ns INTEGER, duration_ns INTEGER, + first_output_timestamp_ns INTEGER, pid INTEGER, process_name TEXT, agent_name TEXT, @@ -198,6 +199,9 @@ impl GenAISqliteStore { // v8: stable key used to reconcile idle stream snapshots on completion ensure_col!("pending_match_key", "TEXT", "idx_genai_pending_match_key"); + // v9: first provider event that carries model output + ensure_col!("first_output_timestamp_ns", "INTEGER"); + Ok(()) } diff --git a/src/agentsight/src/storage/sqlite/genai/stats.rs b/src/agentsight/src/storage/sqlite/genai/stats.rs index 5cfab9243c..3331c2a5da 100644 --- a/src/agentsight/src/storage/sqlite/genai/stats.rs +++ b/src/agentsight/src/storage/sqlite/genai/stats.rs @@ -15,6 +15,152 @@ pub struct TimeseriesBucket { pub total_tokens: i64, } +#[cfg(test)] +mod latency_tests { + use super::{GenAISqliteStore, percentile, percentiles}; + use rusqlite::params; + + #[test] + fn interpolates_latency_percentiles() { + let values = vec![1.0, 2.0, 3.0, 4.0, 5.0]; + assert_eq!(percentile(&values, 50.0), Some(3.0)); + let summary = percentiles(vec![10.0, 20.0]).unwrap(); + assert_eq!(summary.p50, 15.0); + assert_eq!(summary.p95, 19.5); + assert!((summary.p99 - 19.9).abs() < 1e-12); + } + + #[test] + fn returns_none_for_empty_metric_samples() { + assert!(percentiles(Vec::new()).is_none()); + } + + #[test] + fn filters_latency_metrics_by_time_and_agent() { + let path = std::env::temp_dir().join(format!( + "agentsight_latency_metrics_{}.db", + std::process::id() + )); + let _ = std::fs::remove_file(&path); + let store = GenAISqliteStore::new_with_path(&path).unwrap(); + { + let conn = store.conn.lock().unwrap(); + for (call_id, agent, start) in [ + ("a1", "agent-a", 100_i64), + ("b1", "agent-b", 200), + ("a2", "agent-a", 300), + ] { + conn.execute( + "INSERT INTO genai_events + (event_type, status, call_id, start_timestamp_ns, end_timestamp_ns, + first_output_timestamp_ns, output_tokens, is_sse, agent_name, event_json) + VALUES ('llm_call', 'complete', ?1, ?2, ?3, ?4, 10, 1, ?5, '{}')", + params![call_id, start, start + 30, start + 10, agent], + ) + .unwrap(); + } + conn.execute( + "INSERT INTO genai_events + (event_type, status, call_id, start_timestamp_ns, end_timestamp_ns, + first_output_timestamp_ns, output_tokens, is_sse, agent_name, event_json) + VALUES ('llm_call', 'complete', 'zero', 400, 430, 410, 0, 1, 'agent-zero', '{}')", + [], + ) + .unwrap(); + conn.execute( + "INSERT INTO genai_events + (event_type, status, call_id, start_timestamp_ns, end_timestamp_ns, + first_output_timestamp_ns, output_tokens, is_sse, process_name, event_json) + VALUES ('llm_call', 'complete', 'fallback-agent-call', 500, 550, 520, 10, 1, + 'fallback-agent', '{}')", + [], + ) + .unwrap(); + conn.execute( + "INSERT INTO genai_events + (event_type, status, call_id, start_timestamp_ns, end_timestamp_ns, + first_output_timestamp_ns, output_tokens, is_sse, agent_name, event_json) + VALUES ('llm_call', 'complete', 'invalid-ttft', 700, 710, 720, 10, 1, + 'agent-invalid', '{}')", + [], + ) + .unwrap(); + } + let result = store.get_latency_metrics(50, 250, Some("agent-a")).unwrap(); + assert_eq!(result.len(), 1); + assert_eq!(result[0].agent_name.as_deref(), Some("agent-a")); + assert_eq!(result[0].call_count, 1); + assert_eq!( + result[0].ttft_ms.as_ref().map(|value| value.p50), + Some(0.00001) + ); + let zero = store + .get_latency_metrics(350, 450, Some("agent-zero")) + .unwrap(); + assert_eq!(zero[0].streaming_call_count, 1); + assert!(zero[0].tps_tokens_per_second.is_none()); + assert!(zero[0].tpot_ms_per_token.is_none()); + + let fallback = store + .get_latency_metrics(450, 600, Some("fallback-agent")) + .unwrap(); + assert_eq!(fallback.len(), 1); + assert_eq!(fallback[0].agent_name.as_deref(), Some("fallback-agent")); + assert_eq!( + fallback[0].ttft_ms.as_ref().map(|value| value.p50), + Some(0.00002) + ); + + let invalid = store + .get_latency_metrics(650, 750, Some("agent-invalid")) + .unwrap(); + assert_eq!(invalid.len(), 1); + assert!(invalid[0].ttft_ms.is_none()); + + drop(store); + let _ = std::fs::remove_file(path); + } + + #[test] + fn streaming_call_count_uses_is_sse_when_ttft_is_missing() { + let path = std::env::temp_dir().join(format!( + "agentsight_streaming_count_{}.db", + std::process::id() + )); + let _ = std::fs::remove_file(&path); + let store = GenAISqliteStore::new_with_path(&path).unwrap(); + { + let conn = store.conn.lock().unwrap(); + conn.execute( + "INSERT INTO genai_events + (event_type, status, call_id, start_timestamp_ns, end_timestamp_ns, + first_output_timestamp_ns, output_tokens, is_sse, agent_name, event_json) + VALUES ('llm_call', 'complete', 'sse-null', 100, 200, NULL, NULL, 1, + 'agent-count', '{}')", + [], + ) + .unwrap(); + conn.execute( + "INSERT INTO genai_events + (event_type, status, call_id, start_timestamp_ns, end_timestamp_ns, + first_output_timestamp_ns, output_tokens, is_sse, agent_name, event_json) + VALUES ('llm_call', 'complete', 'non-sse', 100, 200, NULL, NULL, 0, + 'agent-count', '{}')", + [], + ) + .unwrap(); + } + + let summary = store + .get_latency_metrics(0, 300, Some("agent-count")) + .unwrap(); + assert_eq!(summary[0].call_count, 2); + assert_eq!(summary[0].streaming_call_count, 1); + drop(store); + let _ = std::fs::remove_file(path); + } +} + /// One data-point in a per-model token time-series response #[derive(Debug, serde::Serialize)] pub struct ModelTimeseriesBucket { @@ -33,7 +179,152 @@ pub struct AgentTokenSummary { pub request_count: i64, } +/// Percentiles for one latency or throughput metric. +#[derive(Debug, serde::Serialize)] +pub struct MetricPercentiles { + pub p50: f64, + pub p95: f64, + pub p99: f64, +} + +/// Aggregated LLM latency metrics for one agent or the requested filter. +#[derive(Debug, serde::Serialize)] +pub struct LatencyMetricsSummary { + pub agent_name: Option, + pub call_count: usize, + pub streaming_call_count: usize, + pub ttft_ms: Option, + pub tps_tokens_per_second: Option, + pub tpot_ms_per_token: Option, + pub e2e_latency_ms: Option, +} + +#[derive(Debug)] +struct CallMetrics { + agent_name: Option, + is_sse: bool, + ttft_ms: Option, + tps_tokens_per_second: Option, + tpot_ms_per_token: Option, + e2e_latency_ms: Option, +} + +fn percentile(sorted: &[f64], pct: f64) -> Option { + if sorted.is_empty() { + return None; + } + let position = (pct / 100.0) * (sorted.len() - 1) as f64; + let lower = position.floor() as usize; + let upper = position.ceil() as usize; + let fraction = position - lower as f64; + Some(sorted[lower] * (1.0 - fraction) + sorted[upper] * fraction) +} + +fn percentiles(mut values: Vec) -> Option { + values.sort_by(f64::total_cmp); + Some(MetricPercentiles { + p50: percentile(&values, 50.0)?, + p95: percentile(&values, 95.0)?, + p99: percentile(&values, 99.0)?, + }) +} + impl GenAISqliteStore { + /// Returns percentile latency metrics grouped by agent. + pub fn get_latency_metrics( + &self, + start_ns: i64, + end_ns: i64, + agent_name: Option<&str>, + ) -> Result, Box> { + let conn = self.conn.lock().unwrap_or_else(|e| e.into_inner()); + let sql = if agent_name.is_some() { + "SELECT COALESCE(agent_name, process_name) AS agent_name, + start_timestamp_ns, end_timestamp_ns, + first_output_timestamp_ns, output_tokens, is_sse + FROM genai_events + WHERE event_type = 'llm_call' AND status = 'complete' + AND start_timestamp_ns BETWEEN ?1 AND ?2 + AND COALESCE(agent_name, process_name) = ?3" + } else { + "SELECT COALESCE(agent_name, process_name) AS agent_name, + start_timestamp_ns, end_timestamp_ns, + first_output_timestamp_ns, output_tokens, is_sse + FROM genai_events + WHERE event_type = 'llm_call' AND status = 'complete' + AND start_timestamp_ns BETWEEN ?1 AND ?2" + }; + let mut stmt = conn.prepare(sql)?; + let map_row = |row: &rusqlite::Row<'_>| -> rusqlite::Result { + let start: i64 = row.get(1)?; + let end: Option = row.get(2)?; + let first: Option = row.get(3)?; + let output_tokens: Option = row.get(4)?; + let e2e_ns = end.filter(|end| *end > start).map(|end| end - start); + let is_sse: Option = row.get(5)?; + let stream_ns = match (first, end) { + (Some(first), Some(end)) if first >= start && end > first => Some(end - first), + _ => None, + }; + let tokens = output_tokens.filter(|tokens| *tokens > 0); + Ok(CallMetrics { + agent_name: row.get(0)?, + ttft_ms: first + .filter(|first| *first >= start && end.map_or(true, |end| *first <= end)) + .map(|first| (first - start) as f64 / 1_000_000.0), + is_sse: is_sse == Some(1), + tps_tokens_per_second: stream_ns + .zip(tokens) + .map(|(duration, tokens)| tokens as f64 * 1_000_000_000.0 / duration as f64), + tpot_ms_per_token: stream_ns + .zip(tokens) + .map(|(duration, tokens)| duration as f64 / 1_000_000.0 / tokens as f64), + e2e_latency_ms: e2e_ns.map(|duration| duration as f64 / 1_000_000.0), + }) + }; + let calls = if let Some(name) = agent_name { + stmt.query_map(params![start_ns, end_ns, name], map_row)? + .collect::, _>>()? + } else { + stmt.query_map(params![start_ns, end_ns], map_row)? + .collect::, _>>()? + }; + + let mut grouped = std::collections::BTreeMap::, Vec>::new(); + for call in calls { + grouped + .entry(call.agent_name.clone()) + .or_default() + .push(call); + } + Ok(grouped + .into_iter() + .map(|(agent_name, calls)| LatencyMetricsSummary { + agent_name, + call_count: calls.len(), + streaming_call_count: calls.iter().filter(|call| call.is_sse).count(), + ttft_ms: percentiles(calls.iter().filter_map(|call| call.ttft_ms).collect()), + tps_tokens_per_second: percentiles( + calls + .iter() + .filter_map(|call| call.tps_tokens_per_second) + .collect(), + ), + tpot_ms_per_token: percentiles( + calls + .iter() + .filter_map(|call| call.tpot_ms_per_token) + .collect(), + ), + e2e_latency_ms: percentiles( + calls + .iter() + .filter_map(|call| call.e2e_latency_ms) + .collect(), + ), + }) + .collect()) + } /// One bucket in a token time-series query. pub fn get_token_timeseries( &self, diff --git a/src/agentsight/src/storage/sqlite/genai/tests.rs b/src/agentsight/src/storage/sqlite/genai/tests.rs index fe42b503e5..f1384e0a8d 100644 --- a/src/agentsight/src/storage/sqlite/genai/tests.rs +++ b/src/agentsight/src/storage/sqlite/genai/tests.rs @@ -807,6 +807,10 @@ fn test_complete_pending_promotes_idle_snapshot_by_match_key() { .insert("sse_event_count".to_string(), "2".to_string()); call.metadata .insert("call_kind".to_string(), "main".to_string()); + call.metadata.insert( + "first_output_timestamp_ns".to_string(), + (BASE_NS + STEP_NS / 2).to_string(), + ); store .complete_pending(&GenAISemanticEvent::LLMCall(call)) @@ -818,17 +822,25 @@ fn test_complete_pending_promotes_idle_snapshot_by_match_key() { .unwrap(); assert_eq!(total, 1, "complete must update the idle snapshot row"); - let (status, call_id, trace_id, origin): (String, String, String, String) = conn + let (status, call_id, trace_id, origin, first_output): ( + String, + String, + String, + String, + Option, + ) = conn .query_row( - "SELECT status, call_id, trace_id, pending_origin FROM genai_events", + "SELECT status, call_id, trace_id, pending_origin, first_output_timestamp_ns + FROM genai_events", [], - |r| Ok((r.get(0)?, r.get(1)?, r.get(2)?, r.get(3)?)), + |r| Ok((r.get(0)?, r.get(1)?, r.get(2)?, r.get(3)?, r.get(4)?)), ) .unwrap(); assert_eq!(status, "complete"); assert_eq!(call_id, "real-response-id"); assert_eq!(trace_id, "real-response-id"); assert_eq!(origin, "idle_drain"); + assert_eq!(first_output, Some(BASE_NS + STEP_NS / 2)); drop(conn); cleanup_db(&path); } diff --git a/src/agentsight/src/storage/sqlite/http.rs b/src/agentsight/src/storage/sqlite/http.rs index 3e46c61791..bf2d5fac7a 100644 --- a/src/agentsight/src/storage/sqlite/http.rs +++ b/src/agentsight/src/storage/sqlite/http.rs @@ -213,6 +213,7 @@ fn row_to_record(row: &rusqlite::Row) -> Result { response_headers, response_body, duration_ns: duration_ns as u64, + first_output_timestamp_ns: None, is_sse: is_sse_int != 0, sse_event_count: sse_event_count as usize, }) @@ -247,6 +248,7 @@ mod tests { response_headers: r#"{"content-type":"application/json"}"#.to_string(), response_body: Some(r#"{"choices":[]}"#.to_string()), duration_ns: 500000000, + first_output_timestamp_ns: None, is_sse: false, sse_event_count: 0, }; @@ -286,6 +288,7 @@ mod tests { response_headers: "{}".to_string(), response_body: None, duration_ns: 0, + first_output_timestamp_ns: None, is_sse: true, sse_event_count: 10, }; @@ -323,6 +326,7 @@ mod tests { response_headers: "{}".to_string(), response_body: None, duration_ns: 0, + first_output_timestamp_ns: None, is_sse: false, sse_event_count: 0, };