[codex] Add turn profiling analytics (#26484)

## Summary Add flat profiling fields to `codex_turn_event` so analytics can explain where turn wall-clock time is spent without changing tool execution behavior. The profile reports: - time before the first sampling request - sampling time across all attempts and follow-ups - overhead between sampling requests - time blocked in the post-sampling tool drain - time after the final sampling request - sampling request and retry counts ## Implementation - Extend the existing turn timing state with constant-memory phase accounting and one RAII phase guard. - Observe sampling and the existing post-sampling drain only at turn orchestration boundaries. - Keep tool runtime, tool futures, response item handling, and turn lifecycle values unchanged. - Add the profiling fields directly to the existing analytics turn event without changing app-server protocol or rollout persistence. - Use the existing turn `status` to distinguish completed, failed, and interrupted profiles. Exact sampling/tool overlap is intentionally omitted because measuring tool completion accurately would require hooks in the tool execution path. ## Validation - Add app-server end-to-end coverage for a single-sampling turn with no blocking tool work. - Add app-server end-to-end coverage for `request_user_input` blocking followed by a second sampling request. - CI is running on the PR; tests were not executed locally per repository guidance.
2026-07-01 00:31:56 +08:00 · 2026-06-05 11:27:10 -07:00
parent 82b15b65e2
commit 8d72fb6de9
11 changed files with 530 additions and 101 deletions
@@ -1,8 +1,11 @@
+use std::sync::Arc;
+use std::sync::Mutex as StdMutex;
 use std::time::Duration;
 use std::time::Instant;
 use std::time::SystemTime;
 use std::time::UNIX_EPOCH;

+use codex_analytics::TurnProfile;
 use codex_otel::TURN_TTFM_DURATION_METRIC;
 use codex_protocol::items::TurnItem;
 use codex_protocol::models::ResponseItem;
@@ -39,6 +42,7 @@ pub(crate) async fn record_turn_ttfm_metric(turn_context: &TurnContext, item: &T
 #[derive(Debug, Default)]
 pub(crate) struct TurnTimingState {
    state: Mutex<TurnTimingStateInner>,
+    profile: StdMutex<TurnProfileState>,
 }

 #[derive(Debug, Default)]
@@ -49,6 +53,35 @@ struct TurnTimingStateInner {
    first_message_at: Option<Instant>,
 }

+#[derive(Debug, Default)]
+struct TurnProfileState {
+    started_at: Option<Instant>,
+    last_transition_at: Option<Instant>,
+    active_phase: Option<TurnProfilePhase>,
+    seen_sampling: bool,
+    before_first_sampling: Duration,
+    sampling: Duration,
+    between_sampling_overhead: Duration,
+    tool_blocking: Duration,
+    pending_idle_after_sampling: Duration,
+    sampling_request_count: u32,
+    sampling_retry_count: u32,
+    completed_profile: Option<TurnProfile>,
+}
+
+#[derive(Clone, Copy, Debug, PartialEq, Eq)]
+enum TurnProfilePhase {
+    Sampling,
+    ToolBlocking,
+}
+
+#[must_use]
+pub(crate) struct TurnProfileTimingGuard {
+    timing: Arc<TurnTimingState>,
+    phase: TurnProfilePhase,
+    active: bool,
+}
+
 impl TurnTimingState {
    pub(crate) async fn mark_turn_started(&self, started_at: Instant) -> i64 {
        let started_at_unix_ms = now_unix_timestamp_ms();
@@ -57,6 +90,7 @@ impl TurnTimingState {
        state.started_at_unix_secs = Some(started_at_unix_ms / 1000);
        state.first_token_at = None;
        state.first_message_at = None;
+        self.profile_state().start(started_at);
        started_at_unix_ms
    }

@@ -80,6 +114,32 @@ impl TurnTimingState {
            .map(|duration| i64::try_from(duration.as_millis()).unwrap_or(i64::MAX))
    }

+    pub(crate) fn complete_profile(&self) -> TurnProfile {
+        self.profile_state().complete(Instant::now())
+    }
+
+    pub(crate) fn begin_sampling(self: &Arc<Self>) -> TurnProfileTimingGuard {
+        let active = self.profile_state().begin_sampling(Instant::now());
+        TurnProfileTimingGuard {
+            timing: Arc::clone(self),
+            phase: TurnProfilePhase::Sampling,
+            active,
+        }
+    }
+
+    pub(crate) fn record_sampling_retry(&self) {
+        self.profile_state().record_sampling_retry();
+    }
+
+    pub(crate) fn begin_tool_blocking(self: &Arc<Self>) -> TurnProfileTimingGuard {
+        let active = self.profile_state().begin_tool_blocking(Instant::now());
+        TurnProfileTimingGuard {
+            timing: Arc::clone(self),
+            phase: TurnProfilePhase::ToolBlocking,
+            active,
+        }
+    }
+
    pub(crate) async fn record_ttft_for_response_event(
        &self,
        event: &ResponseEvent,
@@ -98,6 +158,22 @@ impl TurnTimingState {
        let mut state = self.state.lock().await;
        state.record_turn_ttfm()
    }
+
+    fn profile_state(&self) -> std::sync::MutexGuard<'_, TurnProfileState> {
+        self.profile
+            .lock()
+            .unwrap_or_else(std::sync::PoisonError::into_inner)
+    }
+}
+
+impl Drop for TurnProfileTimingGuard {
+    fn drop(&mut self) {
+        if self.active {
+            self.timing
+                .profile_state()
+                .end_phase(Instant::now(), self.phase);
+        }
+    }
 }

 fn now_unix_timestamp_secs() -> i64 {
@@ -111,6 +187,121 @@ pub(crate) fn now_unix_timestamp_ms() -> i64 {
    i64::try_from(duration.as_millis()).unwrap_or(i64::MAX)
 }

+fn duration_to_u64_ms(duration: Duration) -> u64 {
+    u64::try_from(duration.as_millis()).unwrap_or(u64::MAX)
+}
+
+impl TurnProfileState {
+    fn start(&mut self, started_at: Instant) {
+        *self = Self {
+            started_at: Some(started_at),
+            last_transition_at: Some(started_at),
+            ..Self::default()
+        };
+    }
+
+    fn begin_sampling(&mut self, now: Instant) -> bool {
+        if self.completed_profile.is_some()
+            || self.started_at.is_none()
+            || self.active_phase.is_some()
+        {
+            return false;
+        }
+        self.advance(now);
+        if self.seen_sampling {
+            self.between_sampling_overhead += std::mem::take(&mut self.pending_idle_after_sampling);
+        }
+        self.seen_sampling = true;
+        self.active_phase = Some(TurnProfilePhase::Sampling);
+        self.sampling_request_count = self.sampling_request_count.saturating_add(1);
+        true
+    }
+
+    fn record_sampling_retry(&mut self) {
+        if self.completed_profile.is_none() && self.started_at.is_some() {
+            self.sampling_retry_count = self.sampling_retry_count.saturating_add(1);
+        }
+    }
+
+    fn begin_tool_blocking(&mut self, now: Instant) -> bool {
+        if self.completed_profile.is_some()
+            || self.started_at.is_none()
+            || self.active_phase.is_some()
+        {
+            return false;
+        }
+        self.advance(now);
+        self.active_phase = Some(TurnProfilePhase::ToolBlocking);
+        true
+    }
+
+    fn end_phase(&mut self, now: Instant, phase: TurnProfilePhase) {
+        if self.completed_profile.is_some() || self.active_phase != Some(phase) {
+            return;
+        }
+        self.advance(now);
+        self.active_phase = None;
+    }
+
+    fn advance(&mut self, now: Instant) {
+        let Some(previous) = self.last_transition_at.replace(now) else {
+            return;
+        };
+        let elapsed = now.saturating_duration_since(previous);
+        match self.active_phase {
+            Some(TurnProfilePhase::Sampling) => self.sampling += elapsed,
+            Some(TurnProfilePhase::ToolBlocking) => self.tool_blocking += elapsed,
+            None if self.seen_sampling => self.pending_idle_after_sampling += elapsed,
+            None => self.before_first_sampling += elapsed,
+        }
+    }
+
+    fn complete(&mut self, now: Instant) -> TurnProfile {
+        if let Some(profile) = self.completed_profile.as_ref() {
+            return profile.clone();
+        }
+
+        let final_phase = self.active_phase;
+        self.advance(now);
+        let after_last_sampling = if self.seen_sampling {
+            std::mem::take(&mut self.pending_idle_after_sampling)
+        } else {
+            Duration::ZERO
+        };
+
+        let mut profile = TurnProfile {
+            before_first_sampling_ms: duration_to_u64_ms(self.before_first_sampling),
+            sampling_ms: duration_to_u64_ms(self.sampling),
+            between_sampling_overhead_ms: duration_to_u64_ms(self.between_sampling_overhead),
+            tool_blocking_ms: duration_to_u64_ms(self.tool_blocking),
+            after_last_sampling_ms: duration_to_u64_ms(after_last_sampling),
+            sampling_request_count: self.sampling_request_count,
+            sampling_retry_count: self.sampling_retry_count,
+        };
+        let total_ms = self
+            .started_at
+            .map(|started_at| duration_to_u64_ms(now.saturating_duration_since(started_at)))
+            .unwrap_or_default();
+        let classified_ms = profile
+            .before_first_sampling_ms
+            .saturating_add(profile.sampling_ms)
+            .saturating_add(profile.between_sampling_overhead_ms)
+            .saturating_add(profile.tool_blocking_ms)
+            .saturating_add(profile.after_last_sampling_ms);
+        let rounding_ms = total_ms.saturating_sub(classified_ms);
+        match final_phase {
+            Some(TurnProfilePhase::Sampling) => profile.sampling_ms += rounding_ms,
+            Some(TurnProfilePhase::ToolBlocking) => profile.tool_blocking_ms += rounding_ms,
+            None if self.seen_sampling => profile.after_last_sampling_ms += rounding_ms,
+            None => profile.before_first_sampling_ms += rounding_ms,
+        }
+
+        self.active_phase = None;
+        self.completed_profile = Some(profile.clone());
+        profile
+    }
+}
+
 impl TurnTimingStateInner {
    fn time_to_first_token(&self) -> Option<Duration> {
        Some(self.first_token_at?.duration_since(self.started_at?))