[codex-analytics] guardian review TTFT plumbing and emission

This commit is contained in:
rhan-oai
2026-04-17 12:31:53 -07:00
parent c6596ea2d7
commit cfb5b66b35
19 changed files with 116 additions and 6 deletions
@@ -1348,6 +1348,7 @@ mod tests {
last_agent_message: None,
completed_at: None,
duration_ms: None,
time_to_first_token_ms: None,
}),
];
@@ -1422,6 +1423,7 @@ mod tests {
last_agent_message: None,
completed_at: None,
duration_ms: None,
time_to_first_token_ms: None,
})),
];
@@ -1745,6 +1747,7 @@ mod tests {
last_agent_message: None,
completed_at: None,
duration_ms: None,
time_to_first_token_ms: None,
}),
];
@@ -2255,6 +2258,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(),
@@ -2292,6 +2296,7 @@ mod tests {
last_agent_message: None,
completed_at: None,
duration_ms: None,
time_to_first_token_ms: None,
}),
];
@@ -2344,6 +2349,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(),
@@ -2381,6 +2387,7 @@ mod tests {
last_agent_message: None,
completed_at: None,
duration_ms: None,
time_to_first_token_ms: None,
}),
];
@@ -2555,6 +2562,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(),
@@ -2573,6 +2581,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(),
@@ -2584,6 +2593,7 @@ mod tests {
last_agent_message: None,
completed_at: None,
duration_ms: None,
time_to_first_token_ms: None,
}),
];
@@ -2618,6 +2628,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(),
@@ -2674,6 +2685,7 @@ mod tests {
last_agent_message: None,
completed_at: None,
duration_ms: None,
time_to_first_token_ms: None,
})),
];
@@ -2919,6 +2931,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(),
@@ -2978,6 +2991,7 @@ mod tests {
last_agent_message: None,
completed_at: None,
duration_ms: None,
time_to_first_token_ms: None,
}),
];
@@ -3029,6 +3043,7 @@ mod tests {
last_agent_message: None,
completed_at: None,
duration_ms: None,
time_to_first_token_ms: None,
})),
];
@@ -3077,6 +3092,7 @@ mod tests {
last_agent_message: None,
completed_at: None,
duration_ms: None,
time_to_first_token_ms: None,
})),
];
@@ -3044,6 +3044,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,
}
}
+3
View File
@@ -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;
+1
View File
@@ -282,6 +282,7 @@ impl GuardianReviewAnalyticsResult {
result.had_prior_review_context = Some(metadata.had_prior_review_context);
result.reviewed_action_truncated = metadata.reviewed_action_truncated;
result.token_usage = metadata.token_usage;
result.time_to_first_token_ms = metadata.time_to_first_token_ms;
}
result
+13 -2
View File
@@ -74,6 +74,7 @@ pub(crate) struct GuardianReviewSessionMetadata {
pub(crate) had_prior_review_context: bool,
pub(crate) reviewed_action_truncated: bool,
pub(crate) token_usage: Option<TokenUsage>,
pub(crate) time_to_first_token_ms: Option<u64>,
}
pub(crate) struct GuardianReviewSessionParams {
@@ -623,6 +624,7 @@ async fn run_review_on_session(
had_prior_review_context: had_prior_review_context(&prompt_mode),
reviewed_action_truncated: false,
token_usage: None,
time_to_first_token_ms: None,
};
if send_followup_reminder {
append_guardian_followup_reminder(review_session).await;
@@ -701,8 +703,13 @@ async fn run_review_on_session(
};
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
@@ -745,6 +752,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);
@@ -770,6 +778,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
{
+4
View File
@@ -974,6 +974,10 @@ async fn guardian_review_request_layout_matches_model_visible_request_snapshot()
request_reasoning_effort
);
assert!(!metadata.had_prior_review_context);
assert!(
metadata.time_to_first_token_ms.is_some(),
"guardian review metadata should capture TTFT when the nested turn completes"
);
let mut settings = Settings::clone_current();
settings.set_snapshot_path("snapshots");
@@ -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(
+10
View File
@@ -1503,6 +1503,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,
},
)),
];
@@ -1688,6 +1689,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 {
@@ -1713,6 +1715,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;
@@ -1790,6 +1793,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 {
@@ -1808,6 +1812,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 {
@@ -1835,6 +1840,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;
@@ -1881,6 +1887,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 {
@@ -1904,6 +1911,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 {
@@ -1927,6 +1935,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;
@@ -5146,6 +5155,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
));
+5
View File
@@ -535,11 +535,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;
@@ -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;
+14 -4
View File
@@ -74,6 +74,13 @@ impl TurnTimingState {
(completed_at, duration_ms)
}
pub(crate) async fn time_to_first_token_ms(&self) -> Option<i64> {
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<Duration> {
Some(self.first_token_at?.duration_since(self.started_at?))
}
fn record_turn_ttft(&mut self) -> Option<Duration> {
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<Duration> {
@@ -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(),
+4
View File
@@ -2091,6 +2091,10 @@ pub struct TurnCompleteEvent {
#[serde(default, skip_serializing_if = "Option::is_none")]
#[ts(type = "number | null", optional)]
pub duration_ms: Option<i64>,
/// 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<i64>,
}
#[derive(Debug, Clone, Deserialize, Serialize, JsonSchema, TS)]
@@ -781,6 +781,7 @@ fn append_terminal_turn_events(events: &mut Vec<Event>, 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 {
@@ -812,6 +813,7 @@ fn append_terminal_turn_events(events: &mut Vec<Event>, turn: &Turn, include_fai
last_agent_message: None,
completed_at: turn.completed_at,
duration_ms: turn.duration_ms,
time_to_first_token_ms: None,
}),
});
}
@@ -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,
}),
});
@@ -1350,6 +1354,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,
}),
});
@@ -609,6 +609,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);
@@ -635,6 +636,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!(
@@ -649,6 +651,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,
}),
});
@@ -672,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 duplicate_popup = render_bottom_popup(&chat, /*width*/ 80);
@@ -234,6 +234,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,
}),
});
@@ -255,6 +256,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,
}),
});
@@ -267,6 +267,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,
}),
});
@@ -299,6 +300,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,
}),
});
@@ -385,6 +387,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();
@@ -415,6 +418,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);
@@ -452,6 +456,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);
@@ -943,6 +943,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,
}),
});
@@ -1293,6 +1294,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,
}),
});
@@ -2238,6 +2240,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) {