use std::time::Duration; use std::time::Instant; use codex_otel::metrics::names::TURN_TTFM_DURATION_METRIC; use codex_otel::metrics::names::TURN_TTFT_DURATION_METRIC; use codex_protocol::items::TurnItem; use codex_protocol::models::ResponseItem; use tokio::sync::Mutex; use crate::ResponseEvent; use crate::codex::TurnContext; use crate::stream_events_utils::raw_assistant_output_text_from_item; pub(crate) async fn record_turn_ttft_metric(turn_context: &TurnContext, event: &ResponseEvent) { let Some(duration) = turn_context .turn_timing_state .record_ttft_for_response_event(event) .await else { return; }; turn_context .session_telemetry .record_duration(TURN_TTFT_DURATION_METRIC, duration, &[]); } pub(crate) async fn record_turn_ttfm_metric(turn_context: &TurnContext, item: &TurnItem) { let Some(duration) = turn_context .turn_timing_state .record_ttfm_for_turn_item(item) .await else { return; }; turn_context .session_telemetry .record_duration(TURN_TTFM_DURATION_METRIC, duration, &[]); } #[derive(Debug, Default)] pub(crate) struct TurnTimingState { state: Mutex, } #[derive(Debug, Default)] struct TurnTimingStateInner { started_at: Option, first_token_at: Option, first_message_at: Option, } impl TurnTimingState { pub(crate) async fn mark_turn_started(&self, started_at: Instant) { let mut state = self.state.lock().await; state.started_at = Some(started_at); state.first_token_at = None; state.first_message_at = None; } pub(crate) async fn record_ttft_for_response_event( &self, event: &ResponseEvent, ) -> Option { if !response_event_records_turn_ttft(event) { return None; } let mut state = self.state.lock().await; state.record_turn_ttft() } pub(crate) async fn record_ttfm_for_turn_item(&self, item: &TurnItem) -> Option { if !matches!(item, TurnItem::AgentMessage(_)) { return None; } let mut state = self.state.lock().await; state.record_turn_ttfm() } } impl TurnTimingStateInner { fn record_turn_ttft(&mut self) -> Option { if self.first_token_at.is_some() { return None; } let started_at = self.started_at?; let first_token_at = Instant::now(); self.first_token_at = Some(first_token_at); Some(first_token_at.duration_since(started_at)) } fn record_turn_ttfm(&mut self) -> Option { if self.first_message_at.is_some() { return None; } let started_at = self.started_at?; let first_message_at = Instant::now(); self.first_message_at = Some(first_message_at); Some(first_message_at.duration_since(started_at)) } } fn response_event_records_turn_ttft(event: &ResponseEvent) -> bool { match event { ResponseEvent::OutputItemDone(item) | ResponseEvent::OutputItemAdded(item) => { response_item_records_turn_ttft(item) } ResponseEvent::OutputTextDelta(_) | ResponseEvent::ReasoningSummaryDelta { .. } | ResponseEvent::ReasoningContentDelta { .. } => true, ResponseEvent::Created | ResponseEvent::ServerModel(_) | ResponseEvent::ServerReasoningIncluded(_) | ResponseEvent::Completed { .. } | ResponseEvent::ReasoningSummaryPartAdded { .. } | ResponseEvent::RateLimits(_) | ResponseEvent::ModelsEtag(_) => false, } } fn response_item_records_turn_ttft(item: &ResponseItem) -> bool { match item { ResponseItem::Message { .. } => { raw_assistant_output_text_from_item(item).is_some_and(|text| !text.is_empty()) } ResponseItem::Reasoning { summary, content, .. } => { summary.iter().any(|entry| match entry { codex_protocol::models::ReasoningItemReasoningSummary::SummaryText { text } => { !text.is_empty() } }) || content.as_ref().is_some_and(|entries| { entries.iter().any(|entry| match entry { codex_protocol::models::ReasoningItemContent::ReasoningText { text } | codex_protocol::models::ReasoningItemContent::Text { text } => { !text.is_empty() } }) }) } ResponseItem::LocalShellCall { .. } | ResponseItem::FunctionCall { .. } | ResponseItem::CustomToolCall { .. } | ResponseItem::WebSearchCall { .. } | ResponseItem::ImageGenerationCall { .. } | ResponseItem::GhostSnapshot { .. } | ResponseItem::Compaction { .. } => true, ResponseItem::FunctionCallOutput { .. } | ResponseItem::CustomToolCallOutput { .. } | ResponseItem::Other => false, } } #[cfg(test)] mod tests { use codex_protocol::items::AgentMessageItem; use codex_protocol::items::TurnItem; use codex_protocol::models::ContentItem; use codex_protocol::models::FunctionCallOutputPayload; use codex_protocol::models::ResponseItem; use pretty_assertions::assert_eq; use std::time::Instant; use super::TurnTimingState; use super::response_item_records_turn_ttft; use crate::ResponseEvent; #[tokio::test] async fn turn_timing_state_records_ttft_only_once_per_turn() { let state = TurnTimingState::default(); assert_eq!( state .record_ttft_for_response_event(&ResponseEvent::OutputTextDelta("hi".to_string())) .await, None ); state.mark_turn_started(Instant::now()).await; assert_eq!( state .record_ttft_for_response_event(&ResponseEvent::Created) .await, None ); assert!( state .record_ttft_for_response_event(&ResponseEvent::OutputTextDelta("hi".to_string())) .await .is_some() ); assert_eq!( state .record_ttft_for_response_event(&ResponseEvent::OutputTextDelta( "again".to_string() )) .await, None ); } #[tokio::test] async fn turn_timing_state_records_ttfm_independently_of_ttft() { let state = TurnTimingState::default(); state.mark_turn_started(Instant::now()).await; assert!( state .record_ttft_for_response_event(&ResponseEvent::OutputTextDelta("hi".to_string())) .await .is_some() ); assert!( state .record_ttfm_for_turn_item(&TurnItem::AgentMessage(AgentMessageItem { id: "msg-1".to_string(), content: Vec::new(), phase: None, })) .await .is_some() ); assert_eq!( state .record_ttfm_for_turn_item(&TurnItem::AgentMessage(AgentMessageItem { id: "msg-2".to_string(), content: Vec::new(), phase: None, })) .await, None ); } #[test] fn response_item_records_turn_ttft_for_first_output_signals() { assert!(response_item_records_turn_ttft( &ResponseItem::FunctionCall { id: None, name: "shell".to_string(), arguments: "{}".to_string(), call_id: "call-1".to_string(), } )); assert!(response_item_records_turn_ttft( &ResponseItem::CustomToolCall { id: None, status: None, call_id: "call-2".to_string(), name: "custom".to_string(), input: "echo hi".to_string(), } )); assert!(response_item_records_turn_ttft(&ResponseItem::Message { id: None, role: "assistant".to_string(), content: vec![ContentItem::OutputText { text: "hello".to_string(), }], end_turn: None, phase: None, })); } #[test] fn response_item_records_turn_ttft_ignores_empty_non_output_items() { assert!(!response_item_records_turn_ttft(&ResponseItem::Message { id: None, role: "assistant".to_string(), content: vec![ContentItem::OutputText { text: String::new(), }], end_turn: None, phase: None, })); assert!(!response_item_records_turn_ttft( &ResponseItem::FunctionCallOutput { call_id: "call-1".to_string(), output: FunctionCallOutputPayload::from_text("ok".to_string()), } )); } }