diff --git a/codex-rs/analytics/src/analytics_client_tests.rs b/codex-rs/analytics/src/analytics_client_tests.rs index 7c634ce370..7347c5c236 100644 --- a/codex-rs/analytics/src/analytics_client_tests.rs +++ b/codex-rs/analytics/src/analytics_client_tests.rs @@ -594,6 +594,27 @@ async fn ingest_turn_prerequisites( include_resolved_config: bool, include_started: bool, include_token_usage: bool, +) { + ingest_turn_prerequisites_with_ttft( + reducer, + out, + include_initialize, + include_resolved_config, + include_started, + include_token_usage, + /*time_to_first_token_ms*/ Some(321), + ) + .await; +} + +async fn ingest_turn_prerequisites_with_ttft( + reducer: &mut AnalyticsReducer, + out: &mut Vec, + include_initialize: bool, + include_resolved_config: bool, + include_started: bool, + include_token_usage: bool, + time_to_first_token_ms: Option, ) { if include_initialize { ingest_initialize(reducer, out).await; @@ -672,6 +693,7 @@ async fn ingest_turn_prerequisites( TurnProfileFact { turn_id: "turn-2".to_string(), profile: sample_turn_profile(), + time_to_first_token_ms, }, ))), out, @@ -793,6 +815,7 @@ async fn ingest_complete_child_turn( TurnProfileFact { turn_id: turn_id.to_string(), profile: sample_turn_profile(), + time_to_first_token_ms: Some(321), }, ))), AnalyticsFact::Notification(Box::new(sample_turn_completed_notification( @@ -3474,6 +3497,7 @@ fn turn_event_serializes_expected_shape() { after_last_sampling_ms: 134, sampling_request_count: 2, sampling_retry_count: 1, + time_to_first_token_ms: Some(321), duration_ms: Some(1234), started_at: Some(455), completed_at: Some(456), @@ -3546,6 +3570,7 @@ fn turn_event_serializes_expected_shape() { "after_last_sampling_ms": 134, "sampling_request_count": 2, "sampling_retry_count": 1, + "time_to_first_token_ms": 321, "duration_ms": 1234, "started_at": 455, "completed_at": 456 @@ -3863,6 +3888,10 @@ async fn turn_lifecycle_emits_turn_event() { assert_eq!(payload["event_params"]["started_at"], json!(455)); assert_eq!(payload["event_params"]["completed_at"], json!(456)); assert_eq!(payload["event_params"]["duration_ms"], json!(1234)); + assert_eq!( + payload["event_params"]["time_to_first_token_ms"], + json!(321) + ); assert_eq!(payload["event_params"]["input_tokens"], json!(123)); assert_eq!(payload["event_params"]["cached_input_tokens"], json!(45)); assert_eq!(payload["event_params"]["output_tokens"], json!(140)); @@ -4262,6 +4291,10 @@ async fn turn_lifecycle_emits_failed_turn_event() { payload["event_params"]["codex_error_http_status_code"], json!(null) ); + assert_eq!( + payload["event_params"]["time_to_first_token_ms"], + json!(321) + ); } #[tokio::test] @@ -4295,6 +4328,48 @@ async fn turn_lifecycle_emits_interrupted_turn_event_without_error() { assert_eq!(payload["event_params"]["status"], json!("interrupted")); assert_eq!(payload["event_params"]["turn_error"], json!(null)); assert_eq!(payload["event_params"]["codex_error_kind"], json!(null)); + assert_eq!(payload["event_params"]["duration_ms"], json!(1234)); + assert_eq!( + payload["event_params"]["time_to_first_token_ms"], + json!(321) + ); +} + +#[tokio::test] +async fn turn_lifecycle_without_qualifying_output_emits_null_ttft() { + let mut reducer = AnalyticsReducer::default(); + let mut out = Vec::new(); + + ingest_turn_prerequisites_with_ttft( + &mut reducer, + &mut out, + /*include_initialize*/ true, + /*include_resolved_config*/ true, + /*include_started*/ true, + /*include_token_usage*/ false, + /*time_to_first_token_ms*/ None, + ) + .await; + reducer + .ingest( + AnalyticsFact::Notification(Box::new(sample_turn_completed_notification( + "thread-2", + "turn-2", + AppServerTurnStatus::Completed, + /*codex_error_info*/ None, + ))), + &mut out, + ) + .await; + + assert_eq!(out.len(), 1); + let payload = serde_json::to_value(&out[0]).expect("serialize turn event"); + assert_eq!(payload["event_params"]["status"], json!("completed")); + assert_eq!(payload["event_params"]["duration_ms"], json!(1234)); + assert_eq!( + payload["event_params"]["time_to_first_token_ms"], + json!(null) + ); } #[tokio::test] diff --git a/codex-rs/analytics/src/events.rs b/codex-rs/analytics/src/events.rs index eed972852a..004d4985ef 100644 --- a/codex-rs/analytics/src/events.rs +++ b/codex-rs/analytics/src/events.rs @@ -893,6 +893,7 @@ pub(crate) struct CodexTurnEventParams { pub(crate) after_last_sampling_ms: u64, pub(crate) sampling_request_count: u32, pub(crate) sampling_retry_count: u32, + pub(crate) time_to_first_token_ms: Option, pub(crate) duration_ms: Option, pub(crate) started_at: Option, pub(crate) completed_at: Option, diff --git a/codex-rs/analytics/src/facts.rs b/codex-rs/analytics/src/facts.rs index ab278e223c..fff8af6ac4 100644 --- a/codex-rs/analytics/src/facts.rs +++ b/codex-rs/analytics/src/facts.rs @@ -116,6 +116,7 @@ pub struct TurnProfile { pub struct TurnProfileFact { pub turn_id: String, pub profile: TurnProfile, + pub time_to_first_token_ms: Option, } #[derive(Clone)] diff --git a/codex-rs/analytics/src/reducer.rs b/codex-rs/analytics/src/reducer.rs index 89d6e57dc5..b3433351e4 100644 --- a/codex-rs/analytics/src/reducer.rs +++ b/codex-rs/analytics/src/reducer.rs @@ -340,6 +340,7 @@ struct TurnState { started_at: Option, token_usage: Option, profile: Option, + time_to_first_token_ms: Option, completed: Option, codex_error: Option, latest_diff: Option, @@ -654,9 +655,14 @@ impl AnalyticsReducer { input: TurnProfileFact, out: &mut Vec, ) { - let TurnProfileFact { turn_id, profile } = input; + let TurnProfileFact { + turn_id, + profile, + time_to_first_token_ms, + } = input; let turn_state = self.turns.entry(turn_id.clone()).or_default(); turn_state.profile = Some(profile); + turn_state.time_to_first_token_ms = time_to_first_token_ms; self.maybe_emit_turn_event(&turn_id, out).await; } @@ -2563,6 +2569,7 @@ fn codex_turn_event_params( after_last_sampling_ms, sampling_request_count, sampling_retry_count, + time_to_first_token_ms: turn_state.time_to_first_token_ms, duration_ms: completed.duration_ms, started_at, completed_at: Some(completed.completed_at), diff --git a/codex-rs/core/src/tasks/mod.rs b/codex-rs/core/src/tasks/mod.rs index b2f337ec42..26f145f3eb 100644 --- a/codex-rs/core/src/tasks/mod.rs +++ b/codex-rs/core/src/tasks/mod.rs @@ -739,6 +739,8 @@ impl Session { .track_turn_profile(TurnProfileFact { turn_id: turn_context.sub_id.clone(), profile: turn_context.turn_timing_state.complete_profile(), + time_to_first_token_ms: time_to_first_token_ms + .and_then(|duration_ms| u64::try_from(duration_ms).ok()), }); self.emit_turn_stop_lifecycle(turn_context.extension_data.as_ref()) .await; @@ -853,11 +855,18 @@ impl Session { .turn_timing_state .completed_at_and_duration_ms() .await; + let time_to_first_token_ms = task + .turn_context + .turn_timing_state + .time_to_first_token_ms() + .await; self.services .analytics_events_client .track_turn_profile(TurnProfileFact { turn_id: task.turn_context.sub_id.clone(), profile: task.turn_context.turn_timing_state.complete_profile(), + time_to_first_token_ms: time_to_first_token_ms + .and_then(|duration_ms| u64::try_from(duration_ms).ok()), }); let event = EventMsg::TurnAborted(TurnAbortedEvent { turn_id: Some(task.turn_context.sub_id.clone()),