diff --git a/codex-rs/app-server-protocol/src/protocol/thread_history.rs b/codex-rs/app-server-protocol/src/protocol/thread_history.rs index 886d9c2557..4a421bec0d 100644 --- a/codex-rs/app-server-protocol/src/protocol/thread_history.rs +++ b/codex-rs/app-server-protocol/src/protocol/thread_history.rs @@ -1357,6 +1357,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), ]; @@ -1431,6 +1432,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })), ]; @@ -1754,6 +1756,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), ]; @@ -2264,6 +2267,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), EventMsg::TurnStarted(TurnStartedEvent { turn_id: "turn-b".into(), @@ -2301,6 +2305,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), ]; @@ -2353,6 +2358,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), EventMsg::TurnStarted(TurnStartedEvent { turn_id: "turn-b".into(), @@ -2390,6 +2396,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), ]; @@ -2564,6 +2571,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), EventMsg::TurnStarted(TurnStartedEvent { turn_id: "turn-b".into(), @@ -2582,6 +2590,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), EventMsg::AgentMessage(AgentMessageEvent { message: "still in b".into(), @@ -2593,6 +2602,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), ]; @@ -2627,6 +2637,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), EventMsg::TurnStarted(TurnStartedEvent { turn_id: "turn-b".into(), @@ -2683,6 +2694,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })), ]; @@ -2928,6 +2940,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), EventMsg::Error(ErrorEvent { message: "request-level failure".into(), @@ -2987,6 +3000,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), ]; @@ -3038,6 +3052,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })), ]; @@ -3086,6 +3101,7 @@ mod tests { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })), ]; diff --git a/codex-rs/app-server/src/bespoke_event_handling.rs b/codex-rs/app-server/src/bespoke_event_handling.rs index 6e215fe1c4..7f8eeb4c07 100644 --- a/codex-rs/app-server/src/bespoke_event_handling.rs +++ b/codex-rs/app-server/src/bespoke_event_handling.rs @@ -3074,6 +3074,7 @@ mod tests { last_agent_message: None, completed_at: Some(TEST_TURN_COMPLETED_AT), duration_ms: Some(TEST_TURN_DURATION_MS), + time_to_first_token_ms: None, } } diff --git a/codex-rs/core/src/agent/control_tests.rs b/codex-rs/core/src/agent/control_tests.rs index b444d8c67c..8ab9140b3d 100644 --- a/codex-rs/core/src/agent/control_tests.rs +++ b/codex-rs/core/src/agent/control_tests.rs @@ -279,6 +279,7 @@ async fn on_event_updates_status_from_task_complete() { last_agent_message: Some("done".to_string()), completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })); let expected = AgentStatus::Completed(Some("done".to_string())); assert_eq!(status, Some(expected)); @@ -1229,6 +1230,7 @@ async fn multi_agent_v2_completion_ignores_dead_direct_parent() { last_agent_message: Some("done".to_string()), completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), ) .await; @@ -1315,6 +1317,7 @@ async fn multi_agent_v2_completion_queues_message_for_direct_parent() { last_agent_message: Some("done".to_string()), completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), ) .await; diff --git a/codex-rs/core/src/guardian/analytics.rs b/codex-rs/core/src/guardian/analytics.rs index 3870f2f1b2..38e83f9c25 100644 --- a/codex-rs/core/src/guardian/analytics.rs +++ b/codex-rs/core/src/guardian/analytics.rs @@ -158,9 +158,9 @@ impl GuardianReviewAnalyticsResult { guardian_model: Some(metadata.guardian_model), guardian_reasoning_effort: metadata.guardian_reasoning_effort, had_prior_review_context: Some(metadata.had_prior_review_context), - reviewed_action_truncated: false, + reviewed_action_truncated: metadata.reviewed_action_truncated, token_usage: metadata.token_usage, - time_to_first_token_ms: None, + time_to_first_token_ms: metadata.time_to_first_token_ms, completed_at: metadata.completed_at, } } diff --git a/codex-rs/core/src/guardian/approval_request.rs b/codex-rs/core/src/guardian/approval_request.rs index 6d1d3f76af..72ec5fcccd 100644 --- a/codex-rs/core/src/guardian/approval_request.rs +++ b/codex-rs/core/src/guardian/approval_request.rs @@ -167,32 +167,49 @@ fn guardian_command_source_tool_name(source: GuardianCommandSource) -> &'static } } -fn truncate_guardian_action_value(value: Value) -> Value { +fn truncate_guardian_action_value(value: Value) -> (Value, bool) { match value { - Value::String(text) => Value::String(guardian_truncate_text( - &text, - GUARDIAN_MAX_ACTION_STRING_TOKENS, - )), - Value::Array(values) => Value::Array( - values + Value::String(text) => { + let (text, truncated) = + guardian_truncate_text(&text, GUARDIAN_MAX_ACTION_STRING_TOKENS); + (Value::String(text), truncated) + } + Value::Array(values) => { + let mut truncated = false; + let values = values .into_iter() - .map(truncate_guardian_action_value) - .collect::>(), - ), + .map(|value| { + let (value, value_truncated) = truncate_guardian_action_value(value); + truncated |= value_truncated; + value + }) + .collect::>(); + (Value::Array(values), truncated) + } Value::Object(values) => { let mut entries = values.into_iter().collect::>(); entries.sort_by(|(left, _), (right, _)| left.cmp(right)); - Value::Object( - entries - .into_iter() - .map(|(key, value)| (key, truncate_guardian_action_value(value))) - .collect(), - ) + let mut truncated = false; + let values = entries + .into_iter() + .map(|(key, value)| { + let (value, value_truncated) = truncate_guardian_action_value(value); + truncated |= value_truncated; + (key, value) + }) + .collect(); + (Value::Object(values), truncated) } - other => other, + other => (other, false), } } +#[derive(Debug, Clone, PartialEq, Eq)] +pub(crate) struct FormattedGuardianAction { + pub(crate) text: String, + pub(crate) truncated: bool, +} + pub(crate) fn guardian_approval_request_to_json( action: &GuardianApprovalRequest, ) -> serde_json::Result { @@ -382,10 +399,13 @@ pub(crate) fn guardian_request_turn_id<'a>( } } -pub(crate) fn format_guardian_action_pretty( +pub(crate) fn format_guardian_action_pretty_with_truncation( action: &GuardianApprovalRequest, -) -> serde_json::Result { - let mut value = guardian_approval_request_to_json(action)?; - value = truncate_guardian_action_value(value); - serde_json::to_string_pretty(&value) +) -> serde_json::Result { + let value = guardian_approval_request_to_json(action)?; + let (value, truncated) = truncate_guardian_action_value(value); + Ok(FormattedGuardianAction { + text: serde_json::to_string_pretty(&value)?, + truncated, + }) } diff --git a/codex-rs/core/src/guardian/mod.rs b/codex-rs/core/src/guardian/mod.rs index 5c8987cc2b..2eaca7da34 100644 --- a/codex-rs/core/src/guardian/mod.rs +++ b/codex-rs/core/src/guardian/mod.rs @@ -63,7 +63,7 @@ pub(crate) struct GuardianRejection { } #[cfg(test)] -use approval_request::format_guardian_action_pretty; +use approval_request::format_guardian_action_pretty_with_truncation; #[cfg(test)] use approval_request::guardian_assessment_action; #[cfg(test)] diff --git a/codex-rs/core/src/guardian/prompt.rs b/codex-rs/core/src/guardian/prompt.rs index 687b3e13a7..bc10f6d57d 100644 --- a/codex-rs/core/src/guardian/prompt.rs +++ b/codex-rs/core/src/guardian/prompt.rs @@ -19,7 +19,7 @@ use super::GUARDIAN_RECENT_ENTRY_LIMIT; use super::GuardianApprovalRequest; use super::GuardianAssessment; use super::TRUNCATION_TAG; -use super::approval_request::format_guardian_action_pretty; +use super::approval_request::format_guardian_action_pretty_with_truncation; /// Transcript entry retained for guardian review after filtering. #[derive(Debug, PartialEq, Eq)] @@ -56,6 +56,7 @@ impl GuardianTranscriptEntryKind { pub(crate) struct GuardianPromptItems { pub(crate) items: Vec, pub(crate) transcript_cursor: GuardianTranscriptCursor, + pub(crate) reviewed_action_truncated: bool, } /// Points to the end of the transcript that the guardian has already reviewed. @@ -91,7 +92,7 @@ pub(crate) async fn build_guardian_prompt_items( parent_history_version: history.history_version(), transcript_entry_count: transcript_entries.len(), }; - let planned_action_json = format_guardian_action_pretty(&request)?; + let planned_action = format_guardian_action_pretty_with_truncation(&request)?; let prompt_shape = match mode { GuardianPromptMode::Full => GuardianPromptShape::Full, @@ -176,11 +177,12 @@ pub(crate) async fn build_guardian_prompt_items( .to_string(), ); push_text("Planned action JSON:\n".to_string()); - push_text(format!("{planned_action_json}\n")); + push_text(format!("{}\n", planned_action.text)); push_text(">>> APPROVAL REQUEST END\n".to_string()); Ok(GuardianPromptItems { items, transcript_cursor, + reviewed_action_truncated: planned_action.truncated, }) } @@ -240,7 +242,7 @@ fn render_guardian_transcript_entries_with_offset( } else { GUARDIAN_MAX_MESSAGE_ENTRY_TOKENS }; - let text = guardian_truncate_text(&entry.text, token_cap); + let (text, _) = guardian_truncate_text(&entry.text, token_cap); let rendered = format!( "[{}] {}: {}", index + entry_number_offset + 1, @@ -420,20 +422,20 @@ pub(crate) fn collect_guardian_transcript_entries( entries } -pub(crate) fn guardian_truncate_text(content: &str, token_cap: usize) -> String { +pub(crate) fn guardian_truncate_text(content: &str, token_cap: usize) -> (String, bool) { if content.is_empty() { - return String::new(); + return (String::new(), false); } let max_bytes = approx_bytes_for_tokens(token_cap); if content.len() <= max_bytes { - return content.to_string(); + return (content.to_string(), false); } let omitted_tokens = approx_tokens_from_byte_count(content.len().saturating_sub(max_bytes)); let marker = format!("<{TRUNCATION_TAG} omitted_approx_tokens=\"{omitted_tokens}\" />"); if max_bytes <= marker.len() { - return marker; + return (marker, true); } let available_bytes = max_bytes.saturating_sub(marker.len()); @@ -441,7 +443,7 @@ pub(crate) fn guardian_truncate_text(content: &str, token_cap: usize) -> String let suffix_budget = available_bytes.saturating_sub(prefix_budget); let (prefix, suffix) = split_guardian_truncation_bounds(content, prefix_budget, suffix_budget); - format!("{prefix}{marker}{suffix}") + (format!("{prefix}{marker}{suffix}"), true) } fn split_guardian_truncation_bounds( diff --git a/codex-rs/core/src/guardian/review_session.rs b/codex-rs/core/src/guardian/review_session.rs index 4bbb3c56a2..d6ed75acf5 100644 --- a/codex-rs/core/src/guardian/review_session.rs +++ b/codex-rs/core/src/guardian/review_session.rs @@ -74,7 +74,9 @@ pub(crate) struct GuardianReviewSessionMetadata { pub(crate) guardian_reasoning_effort: Option, pub(crate) had_prior_review_context: bool, pub(crate) completed_at: u64, + pub(crate) reviewed_action_truncated: bool, pub(crate) token_usage: Option, + pub(crate) time_to_first_token_ms: Option, } pub(crate) struct GuardianReviewSessionParams { @@ -639,7 +641,9 @@ async fn run_review_on_session( guardian_reasoning_effort: guardian_reasoning_effort.map(|effort| effort.to_string()), had_prior_review_context: had_prior_review_context(&prompt_mode), completed_at: 0, + reviewed_action_truncated: false, token_usage: None, + time_to_first_token_ms: None, }; if send_followup_reminder { append_guardian_followup_reminder(review_session).await; @@ -665,6 +669,7 @@ async fn run_review_on_session( prompt_mode, ) .await?; + let reviewed_action_truncated = prompt_items.reviewed_action_truncated; // A fresh Guardian review session may not have token info yet. Treat that // as a zero baseline so the first review can still report usage. let token_usage_at_review_start = review_session @@ -692,8 +697,9 @@ async fn run_review_on_session( }) .await?; - Ok::<(GuardianTranscriptCursor, TokenUsage), anyhow::Error>(( + Ok::<(GuardianTranscriptCursor, bool, TokenUsage), anyhow::Error>(( prompt_items.transcript_cursor, + reviewed_action_truncated, token_usage_at_review_start, )) }), @@ -703,19 +709,26 @@ async fn run_review_on_session( Ok(submit_result) => submit_result, Err(outcome) => return (outcome, false, guardian_metadata), }; - let (transcript_cursor, token_usage_at_review_start) = match submit_result { - Ok(submit_result) => submit_result, - Err(err) => { - return ( - GuardianReviewSessionOutcome::PromptBuildFailed(err), - false, - guardian_metadata, - ); - } - }; + let (transcript_cursor, reviewed_action_truncated, token_usage_at_review_start) = + match submit_result { + Ok(submit_result) => submit_result, + Err(err) => { + return ( + GuardianReviewSessionOutcome::PromptBuildFailed(err), + false, + guardian_metadata, + ); + } + }; + guardian_metadata.reviewed_action_truncated = reviewed_action_truncated; - let outcome = - wait_for_guardian_review(review_session, deadline, params.external_cancel.as_ref()).await; + let outcome = wait_for_guardian_review( + review_session, + deadline, + params.external_cancel.as_ref(), + &mut guardian_metadata, + ) + .await; if matches!(outcome.0, GuardianReviewSessionOutcome::Completed(_)) { if outcome.2 && let Some(total_token_usage) = review_session.codex.session.total_token_usage().await @@ -758,6 +771,7 @@ async fn wait_for_guardian_review( review_session: &GuardianReviewSession, deadline: tokio::time::Instant, external_cancel: Option<&CancellationToken>, + metadata: &mut GuardianReviewSessionMetadata, ) -> (GuardianReviewSessionOutcome, bool, bool) { let timeout = tokio::time::sleep_until(deadline); tokio::pin!(timeout); @@ -783,6 +797,9 @@ async fn wait_for_guardian_review( match event { Ok(event) => match event.msg { EventMsg::TurnComplete(turn_complete) => { + metadata.time_to_first_token_ms = turn_complete + .time_to_first_token_ms + .and_then(|ms| u64::try_from(ms).ok()); if turn_complete.last_agent_message.is_none() && let Some(error_message) = last_error_message { diff --git a/codex-rs/core/src/guardian/tests.rs b/codex-rs/core/src/guardian/tests.rs index 37aec2c3bc..36e2174fe7 100644 --- a/codex-rs/core/src/guardian/tests.rs +++ b/codex-rs/core/src/guardian/tests.rs @@ -570,11 +570,12 @@ fn collect_guardian_transcript_entries_includes_recent_tool_calls_and_output() { fn guardian_truncate_text_keeps_prefix_suffix_and_xml_marker() { let content = "prefix ".repeat(200) + &" suffix".repeat(200); - let truncated = guardian_truncate_text(&content, /*token_cap*/ 20); + let (truncated, was_truncated) = guardian_truncate_text(&content, /*token_cap*/ 20); assert!(truncated.starts_with("prefix")); assert!(truncated.contains(" serde_json:: patch: patch.clone(), }; - let rendered = format_guardian_action_pretty(&action)?; + let rendered = format_guardian_action_pretty_with_truncation(&action)?; - assert!(rendered.contains("\"tool\": \"apply_patch\"")); - assert!(rendered.contains(" anyhow: let GuardianReviewSessionResult { outcome: GuardianReviewOutcome::Completed(first_assessment), - .. + metadata: first_metadata, } = first_outcome else { panic!("expected first guardian assessment"); }; + let first_metadata = first_metadata.expect("first guardian session metadata"); let GuardianReviewSessionResult { outcome: GuardianReviewOutcome::Completed(second_assessment), - .. + metadata: second_metadata, } = second_outcome else { panic!("expected second guardian assessment"); }; + let second_metadata = second_metadata.expect("second guardian session metadata"); let GuardianReviewSessionResult { outcome: GuardianReviewOutcome::Completed(third_assessment), - .. + metadata: third_metadata, } = third_outcome else { panic!("expected third guardian assessment"); }; + let third_metadata = third_metadata.expect("third guardian session metadata"); assert_eq!(first_assessment.outcome, GuardianAssessmentOutcome::Allow); assert_eq!(second_assessment.outcome, GuardianAssessmentOutcome::Allow); assert_eq!(third_assessment.outcome, GuardianAssessmentOutcome::Allow); + assert!(matches!( + first_metadata.guardian_session_kind, + codex_analytics::GuardianReviewSessionKind::TrunkNew + )); + assert!(matches!( + second_metadata.guardian_session_kind, + codex_analytics::GuardianReviewSessionKind::TrunkReused + )); + assert!(matches!( + third_metadata.guardian_session_kind, + codex_analytics::GuardianReviewSessionKind::TrunkReused + )); + ThreadId::from_string(&first_metadata.guardian_thread_id) + .expect("first guardian thread id should be a valid UUID"); + ThreadId::from_string(&second_metadata.guardian_thread_id) + .expect("second guardian thread id should be a valid UUID"); + ThreadId::from_string(&third_metadata.guardian_thread_id) + .expect("third guardian thread id should be a valid UUID"); + assert!(!first_metadata.had_prior_review_context); + assert!(second_metadata.had_prior_review_context); + assert!(third_metadata.had_prior_review_context); + assert_eq!( + first_metadata.guardian_thread_id, + second_metadata.guardian_thread_id + ); + assert_eq!( + second_metadata.guardian_thread_id, + third_metadata.guardian_thread_id + ); let requests = request_log.requests(); assert_eq!(requests.len(), 3); diff --git a/codex-rs/core/src/session/rollout_reconstruction_tests.rs b/codex-rs/core/src/session/rollout_reconstruction_tests.rs index 3dca7f0ce6..a3cb9a7353 100644 --- a/codex-rs/core/src/session/rollout_reconstruction_tests.rs +++ b/codex-rs/core/src/session/rollout_reconstruction_tests.rs @@ -151,6 +151,7 @@ async fn record_initial_history_resumed_hydrates_previous_turn_settings_from_lif last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), ]; @@ -218,6 +219,7 @@ async fn reconstruct_history_rollback_keeps_history_and_metadata_in_sync_for_com last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::TurnStarted( @@ -245,6 +247,7 @@ async fn reconstruct_history_rollback_keeps_history_and_metadata_in_sync_for_com last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::ThreadRolledBack( @@ -314,6 +317,7 @@ async fn reconstruct_history_rollback_keeps_history_and_metadata_in_sync_for_inc last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::TurnStarted( @@ -403,6 +407,7 @@ async fn reconstruct_history_rollback_skips_non_user_turns_for_history_and_metad last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::TurnStarted( @@ -429,6 +434,7 @@ async fn reconstruct_history_rollback_skips_non_user_turns_for_history_and_metad last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::TurnStarted( @@ -446,6 +452,7 @@ async fn reconstruct_history_rollback_skips_non_user_turns_for_history_and_metad last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::ThreadRolledBack( @@ -518,6 +525,7 @@ async fn reconstruct_history_rollback_counts_inter_agent_assistant_turns() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::TurnStarted( @@ -537,6 +545,7 @@ async fn reconstruct_history_rollback_counts_inter_agent_assistant_turns() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::ThreadRolledBack( @@ -604,6 +613,7 @@ async fn reconstruct_history_rollback_clears_history_and_metadata_when_exceeding last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::ThreadRolledBack( @@ -653,6 +663,7 @@ async fn record_initial_history_resumed_rollback_skips_only_user_turns() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), // Standalone task turn (no UserMessage) should not consume rollback skips. @@ -670,6 +681,7 @@ async fn record_initial_history_resumed_rollback_skips_only_user_turns() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::ThreadRolledBack( @@ -723,6 +735,7 @@ async fn record_initial_history_resumed_rollback_drops_incomplete_user_turn_comp last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::TurnStarted( @@ -879,6 +892,7 @@ async fn reconstruct_history_legacy_compaction_without_replacement_history_clear last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), ]; @@ -949,6 +963,7 @@ async fn record_initial_history_resumed_turn_context_after_compaction_reestablis last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), ]; @@ -1052,6 +1067,7 @@ async fn record_initial_history_resumed_aborted_turn_without_id_clears_active_tu last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::TurnStarted( @@ -1160,6 +1176,7 @@ async fn record_initial_history_resumed_unmatched_abort_preserves_active_turn_fo last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::TurnStarted( @@ -1193,6 +1210,7 @@ async fn record_initial_history_resumed_unmatched_abort_preserves_active_turn_fo last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), ]; @@ -1276,6 +1294,7 @@ async fn record_initial_history_resumed_trailing_incomplete_turn_compaction_clea last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::TurnStarted( @@ -1427,6 +1446,7 @@ async fn record_initial_history_resumed_replaced_incomplete_compacted_turn_clear last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), RolloutItem::EventMsg(EventMsg::TurnStarted( diff --git a/codex-rs/core/src/session/tests.rs b/codex-rs/core/src/session/tests.rs index bd41da9f20..c5401e1327 100644 --- a/codex-rs/core/src/session/tests.rs +++ b/codex-rs/core/src/session/tests.rs @@ -1776,6 +1776,7 @@ async fn record_initial_history_forked_hydrates_previous_turn_settings() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }, )), ]; @@ -1961,6 +1962,7 @@ async fn thread_rollback_recomputes_previous_turn_settings_and_reference_context last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })), RolloutItem::EventMsg(EventMsg::TurnStarted( codex_protocol::protocol::TurnStartedEvent { @@ -1986,6 +1988,7 @@ async fn thread_rollback_recomputes_previous_turn_settings_and_reference_context last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })), ]) .await; @@ -2063,6 +2066,7 @@ async fn thread_rollback_restores_cleared_reference_context_item_after_compactio last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })), RolloutItem::EventMsg(EventMsg::TurnStarted( codex_protocol::protocol::TurnStartedEvent { @@ -2081,6 +2085,7 @@ async fn thread_rollback_restores_cleared_reference_context_item_after_compactio last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })), RolloutItem::EventMsg(EventMsg::TurnStarted( codex_protocol::protocol::TurnStartedEvent { @@ -2108,6 +2113,7 @@ async fn thread_rollback_restores_cleared_reference_context_item_after_compactio last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })), ]) .await; @@ -2154,6 +2160,7 @@ async fn thread_rollback_persists_marker_and_replays_cumulatively() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })), RolloutItem::EventMsg(EventMsg::TurnStarted( codex_protocol::protocol::TurnStartedEvent { @@ -2177,6 +2184,7 @@ async fn thread_rollback_persists_marker_and_replays_cumulatively() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })), RolloutItem::EventMsg(EventMsg::TurnStarted( codex_protocol::protocol::TurnStartedEvent { @@ -2200,6 +2208,7 @@ async fn thread_rollback_persists_marker_and_replays_cumulatively() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })), ]) .await; @@ -5813,6 +5822,7 @@ async fn task_finish_emits_turn_item_lifecycle_for_leftover_pending_user_input() EventMsg::TurnComplete(TurnCompleteEvent { turn_id, last_agent_message: None, + time_to_first_token_ms: None, .. }) if turn_id == tc.sub_id )); diff --git a/codex-rs/core/src/tasks/mod.rs b/codex-rs/core/src/tasks/mod.rs index e7030d1d94..7874bae406 100644 --- a/codex-rs/core/src/tasks/mod.rs +++ b/codex-rs/core/src/tasks/mod.rs @@ -567,11 +567,16 @@ impl Session { .turn_timing_state .completed_at_and_duration_ms() .await; + let time_to_first_token_ms = turn_context + .turn_timing_state + .time_to_first_token_ms() + .await; let event = EventMsg::TurnComplete(TurnCompleteEvent { turn_id: turn_context.sub_id.clone(), last_agent_message, completed_at, duration_ms, + time_to_first_token_ms, }); self.send_event(turn_context.as_ref(), event).await; diff --git a/codex-rs/core/src/tools/handlers/multi_agents_tests.rs b/codex-rs/core/src/tools/handlers/multi_agents_tests.rs index 3a525e69eb..d5eaf233b2 100644 --- a/codex-rs/core/src/tools/handlers/multi_agents_tests.rs +++ b/codex-rs/core/src/tools/handlers/multi_agents_tests.rs @@ -1155,6 +1155,7 @@ async fn multi_agent_v2_list_agents_returns_completed_status_and_last_task_messa last_agent_message: Some("done".to_string()), completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), ) .await; @@ -1633,6 +1634,7 @@ async fn multi_agent_v2_followup_task_completion_notifies_parent_on_every_turn() last_agent_message: Some("first done".to_string()), completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), ) .await; @@ -1661,6 +1663,7 @@ async fn multi_agent_v2_followup_task_completion_notifies_parent_on_every_turn() last_agent_message: Some("second done".to_string()), completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), ) .await; diff --git a/codex-rs/core/src/turn_timing.rs b/codex-rs/core/src/turn_timing.rs index 8236ae53b7..76e52d6c36 100644 --- a/codex-rs/core/src/turn_timing.rs +++ b/codex-rs/core/src/turn_timing.rs @@ -74,6 +74,13 @@ impl TurnTimingState { (completed_at, duration_ms) } + pub(crate) async fn time_to_first_token_ms(&self) -> Option { + let state = self.state.lock().await; + state + .time_to_first_token() + .map(|duration| i64::try_from(duration.as_millis()).unwrap_or(i64::MAX)) + } + pub(crate) async fn record_ttft_for_response_event( &self, event: &ResponseEvent, @@ -102,14 +109,17 @@ fn now_unix_timestamp_secs() -> i64 { } impl TurnTimingStateInner { + fn time_to_first_token(&self) -> Option { + Some(self.first_token_at?.duration_since(self.started_at?)) + } + 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)) + self.started_at?; + self.first_token_at = Some(Instant::now()); + self.time_to_first_token() } fn record_turn_ttfm(&mut self) -> Option { diff --git a/codex-rs/core/tests/suite/resume_warning.rs b/codex-rs/core/tests/suite/resume_warning.rs index 8ea2be3147..0368d9baf6 100644 --- a/codex-rs/core/tests/suite/resume_warning.rs +++ b/codex-rs/core/tests/suite/resume_warning.rs @@ -70,6 +70,7 @@ fn resume_history( last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })), ], rollout_path: rollout_path.to_path_buf(), diff --git a/codex-rs/protocol/src/protocol.rs b/codex-rs/protocol/src/protocol.rs index 475d2941c3..b4fb138bbf 100644 --- a/codex-rs/protocol/src/protocol.rs +++ b/codex-rs/protocol/src/protocol.rs @@ -2091,6 +2091,10 @@ pub struct TurnCompleteEvent { #[serde(default, skip_serializing_if = "Option::is_none")] #[ts(type = "number | null", optional)] pub duration_ms: Option, + /// Duration between turn start and the first model token in milliseconds, if known. + #[serde(default, skip_serializing_if = "Option::is_none")] + #[ts(type = "number | null", optional)] + pub time_to_first_token_ms: Option, } #[derive(Debug, Clone, Deserialize, Serialize, JsonSchema, TS)] diff --git a/codex-rs/tui/src/app/app_server_adapter.rs b/codex-rs/tui/src/app/app_server_adapter.rs index c700e5e14f..db5aa1314d 100644 --- a/codex-rs/tui/src/app/app_server_adapter.rs +++ b/codex-rs/tui/src/app/app_server_adapter.rs @@ -785,6 +785,7 @@ fn append_terminal_turn_events(events: &mut Vec, turn: &Turn, include_fai last_agent_message: None, completed_at: turn.completed_at, duration_ms: turn.duration_ms, + time_to_first_token_ms: None, }), }), TurnStatus::Interrupted => events.push(Event { @@ -816,6 +817,7 @@ fn append_terminal_turn_events(events: &mut Vec, turn: &Turn, include_fai last_agent_message: None, completed_at: turn.completed_at, duration_ms: turn.duration_ms, + time_to_first_token_ms: None, }), }); } diff --git a/codex-rs/tui/src/chatwidget/tests/exec_flow.rs b/codex-rs/tui/src/chatwidget/tests/exec_flow.rs index 9f181d3d21..e343e4a5aa 100644 --- a/codex-rs/tui/src/chatwidget/tests/exec_flow.rs +++ b/codex-rs/tui/src/chatwidget/tests/exec_flow.rs @@ -654,6 +654,7 @@ async fn unified_exec_wait_after_final_agent_message_snapshot() { last_agent_message: Some("Final response.".into()), completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); @@ -699,6 +700,7 @@ async fn unified_exec_wait_before_streamed_agent_message_snapshot() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); @@ -766,6 +768,7 @@ async fn unified_exec_waiting_multiple_empty_snapshots() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); @@ -846,6 +849,7 @@ async fn unified_exec_non_empty_then_empty_snapshots() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); @@ -1359,6 +1363,7 @@ async fn turn_complete_keeps_unified_exec_processes() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); diff --git a/codex-rs/tui/src/chatwidget/tests/plan_mode.rs b/codex-rs/tui/src/chatwidget/tests/plan_mode.rs index 9f2c81010a..993d083842 100644 --- a/codex-rs/tui/src/chatwidget/tests/plan_mode.rs +++ b/codex-rs/tui/src/chatwidget/tests/plan_mode.rs @@ -648,6 +648,7 @@ async fn plan_implementation_popup_skips_replayed_turn_complete() { last_agent_message: Some("Plan details".to_string()), completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })]); let popup = render_bottom_popup(&chat, /*width*/ 80); @@ -674,6 +675,7 @@ async fn plan_implementation_popup_shows_once_when_replay_precedes_live_turn_com last_agent_message: Some("Plan details".to_string()), completed_at: None, duration_ms: None, + time_to_first_token_ms: None, })]); let replay_popup = render_bottom_popup(&chat, /*width*/ 80); assert!( @@ -688,6 +690,7 @@ async fn plan_implementation_popup_shows_once_when_replay_precedes_live_turn_com last_agent_message: Some("Plan details".to_string()), completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); @@ -711,6 +714,7 @@ async fn plan_implementation_popup_shows_once_when_replay_precedes_live_turn_com last_agent_message: Some("Plan details".to_string()), completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); let duplicate_popup = render_bottom_popup(&chat, /*width*/ 80); diff --git a/codex-rs/tui/src/chatwidget/tests/review_mode.rs b/codex-rs/tui/src/chatwidget/tests/review_mode.rs index 2de9c7eb98..86bd4a26bf 100644 --- a/codex-rs/tui/src/chatwidget/tests/review_mode.rs +++ b/codex-rs/tui/src/chatwidget/tests/review_mode.rs @@ -314,6 +314,7 @@ async fn steer_rejection_queues_review_follow_up_before_existing_queued_messages last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); @@ -335,6 +336,7 @@ async fn steer_rejection_queues_review_follow_up_before_existing_queued_messages last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); diff --git a/codex-rs/tui/src/chatwidget/tests/slash_commands.rs b/codex-rs/tui/src/chatwidget/tests/slash_commands.rs index 905ae98377..9d6309685d 100644 --- a/codex-rs/tui/src/chatwidget/tests/slash_commands.rs +++ b/codex-rs/tui/src/chatwidget/tests/slash_commands.rs @@ -807,6 +807,7 @@ async fn slash_copy_state_tracks_turn_complete_final_reply() { last_agent_message: Some("Final reply **markdown**".to_string()), completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); @@ -839,6 +840,7 @@ async fn slash_copy_state_tracks_plan_item_completion() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); @@ -925,6 +927,7 @@ async fn slash_copy_state_is_preserved_during_running_task() { last_agent_message: Some("Previous completed reply".to_string()), completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); chat.on_task_started(); @@ -955,6 +958,7 @@ async fn slash_copy_tracks_replayed_legacy_agent_message_when_turn_complete_omit last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); let _ = drain_insert_history(&mut rx); @@ -992,6 +996,7 @@ async fn slash_copy_uses_agent_message_item_when_turn_complete_omits_final_text( last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); let _ = drain_insert_history(&mut rx); diff --git a/codex-rs/tui/src/chatwidget/tests/status_and_layout.rs b/codex-rs/tui/src/chatwidget/tests/status_and_layout.rs index 39b72906b9..bda0729274 100644 --- a/codex-rs/tui/src/chatwidget/tests/status_and_layout.rs +++ b/codex-rs/tui/src/chatwidget/tests/status_and_layout.rs @@ -1315,6 +1315,7 @@ async fn status_line_branch_refreshes_after_turn_complete() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); @@ -1665,6 +1666,7 @@ async fn multiple_agent_messages_in_single_turn_emit_multiple_headers() { last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); @@ -2610,6 +2612,7 @@ printf 'fenced within fenced\n' last_agent_message: None, completed_at: None, duration_ms: None, + time_to_first_token_ms: None, }), }); for lines in drain_insert_history(&mut rx) {