[codex-analytics] guardian review TTFT plumbing and emission

This commit is contained in:
rhan-oai
2026-04-14 14:51:54 -07:00
parent 15ca8c08c9
commit a22658d75f
18 changed files with 108 additions and 3 deletions
+3
View File
@@ -275,6 +275,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));
@@ -1225,6 +1226,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;
@@ -1311,6 +1313,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;
@@ -148,6 +148,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,
},
)),
];
@@ -215,6 +216,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(
@@ -242,6 +244,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(
@@ -311,6 +314,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(
@@ -400,6 +404,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(
@@ -426,6 +431,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(
@@ -443,6 +449,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(
@@ -515,6 +522,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(
@@ -534,6 +542,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(
@@ -601,6 +610,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(
@@ -650,6 +660,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.
@@ -667,6 +678,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(
@@ -720,6 +732,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(
@@ -876,6 +889,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,
},
)),
];
@@ -945,6 +959,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,
},
)),
];
@@ -1046,6 +1061,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(
@@ -1153,6 +1169,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(
@@ -1186,6 +1203,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,
},
)),
];
@@ -1268,6 +1286,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(
@@ -1418,6 +1437,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
@@ -1446,6 +1446,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,
},
)),
];
@@ -1631,6 +1632,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 {
@@ -1656,6 +1658,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;
@@ -1733,6 +1736,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 {
@@ -1751,6 +1755,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 {
@@ -1778,6 +1783,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;
@@ -1824,6 +1830,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 {
@@ -1847,6 +1854,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 {
@@ -1870,6 +1878,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;
@@ -4830,6 +4839,7 @@ async fn task_finish_emits_turn_item_lifecycle_for_leftover_pending_user_input()
turn_id,
last_agent_message: None,
..
time_to_first_token_ms: None,
}) if turn_id == tc.sub_id
));
}
+1 -1
View File
@@ -236,7 +236,7 @@ fn guardian_review_metadata_fields(
had_prior_review_context: Some(metadata.had_prior_review_context),
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,
},
None => GuardianReviewMetadataFields::default(),
}
+13 -2
View File
@@ -73,6 +73,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 {
@@ -619,6 +620,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;
@@ -691,8 +693,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(token_usage_at_review_start) = token_usage_at_review_start
@@ -736,6 +743,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);
@@ -761,6 +769,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
{
+5
View File
@@ -527,11 +527,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;
@@ -1154,6 +1154,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;
@@ -1631,6 +1632,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;
@@ -1659,6 +1661,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;
+10
View File
@@ -74,6 +74,16 @@ impl TurnTimingState {
(completed_at, duration_ms)
}
pub(crate) async fn time_to_first_token_ms(&self) -> Option<i64> {
let state = self.state.lock().await;
let started_at = state.started_at?;
let first_token_at = state.first_token_at?;
Some(
i64::try_from(first_token_at.duration_since(started_at).as_millis())
.unwrap_or(i64::MAX),
)
}
pub(crate) async fn record_ttft_for_response_event(
&self,
event: &ResponseEvent,
@@ -69,6 +69,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(),