Add exact tool timing metadata

codex-rs/core/src/lib.rs

@@ -145,6 +145,7 @@ pub(crate) mod state_db_bridge;
 pub use state_db_bridge::StateDbHandle;
 pub use state_db_bridge::init_state_db;
 mod thread_rollout_truncation;
+mod tool_timing;
 mod tools;
 pub(crate) mod turn_diff_tracker;
 mod turn_metadata;

codex-rs/core/src/responses_metadata.rs

@@ -22,6 +22,8 @@ use crate::client::X_CODEX_PARENT_THREAD_ID_HEADER;
 use crate::client::X_CODEX_TURN_METADATA_HEADER;
 use crate::client::X_CODEX_WINDOW_ID_HEADER;
 use crate::client::X_OPENAI_SUBAGENT_HEADER;
+use crate::tool_timing::TOOL_TIMING_KEY;
+use crate::tool_timing::ToolTimingReport;
 
 pub(crate) const INSTALLATION_ID_KEY: &str = "installation_id";
 pub(crate) const SESSION_ID_KEY: &str = "session_id";
@@ -61,6 +63,7 @@ const RESERVED_METADATA_KEYS: &[&str] = &[
     THREAD_SOURCE_KEY,
     SANDBOX_KEY,
     WORKSPACES_KEY,
+    TOOL_TIMING_KEY,
 ];
 
 /// Metadata attached to model requests whose purpose is conversation compaction.
@@ -150,6 +153,7 @@ pub struct CodexResponsesMetadata {
     pub(crate) sandbox: Option<String>,
     pub(crate) workspaces: BTreeMap<String, TurnMetadataWorkspace>,
     pub(crate) turn_started_at_unix_ms: Option<i64>,
+    pub(crate) tool_timing: Option<ToolTimingReport>,
     pub(crate) extra: BTreeMap<String, String>,
 }
 
@@ -175,6 +179,7 @@ impl CodexResponsesMetadata {
             sandbox: None,
             workspaces: BTreeMap::new(),
             turn_started_at_unix_ms: None,
+            tool_timing: None,
             extra: BTreeMap::new(),
         }
     }
@@ -277,6 +282,7 @@ impl CodexResponsesMetadata {
             sandbox: self.sandbox.as_deref(),
             workspaces: non_empty_workspaces(&self.workspaces),
             turn_started_at_unix_ms: self.turn_started_at_unix_ms,
+            tool_timing: self.tool_timing.as_ref(),
             compaction,
             // responsesapi_client_metadata enriches the Codex turn metadata blob, not literal
             // top-level Responses client_metadata. Reserved Codex-owned keys are filtered when
@@ -368,6 +374,8 @@ struct CodexTurnMetadataPayload<'a> {
     #[serde(default, skip_serializing_if = "Option::is_none")]
     turn_started_at_unix_ms: Option<i64>,
     #[serde(default, skip_serializing_if = "Option::is_none")]
+    tool_timing: Option<&'a ToolTimingReport>,
+    #[serde(default, skip_serializing_if = "Option::is_none")]
     compaction: Option<CompactionTurnMetadata>,
     #[serde(flatten)]
     extra: &'a BTreeMap<String, String>,

codex-rs/core/src/tool_timing.rs

@@ -0,0 +1,268 @@
+//! Turn-local, model-visible tool latency exported through Responses client metadata.
+
+use std::mem;
+use std::sync::Arc;
+use std::sync::Mutex;
+use std::time::Instant;
+
+use serde::Serialize;
+
+const TOOL_TIMING_VERSION: u8 = 1;
+pub(crate) const TOOL_TIMING_KEY: &str = "tool_timing";
+
+#[derive(Clone, Debug)]
+pub(crate) enum ToolTimingSource {
+    Direct,
+    CodeMode {
+        cell_id: String,
+        runtime_tool_call_id: String,
+    },
+}
+
+#[derive(Clone, Debug)]
+pub(crate) struct ToolTimingCall {
+    pub(crate) call_id: String,
+    pub(crate) tool_name: String,
+    pub(crate) source: ToolTimingSource,
+}
+
+#[derive(Clone, Debug)]
+pub(crate) struct ToolTimingState {
+    inner: Arc<Mutex<ToolTimingStateInner>>,
+}
+
+#[derive(Debug)]
+struct ToolTimingStateInner {
+    origin: Instant,
+    next_entry_id: u64,
+    next_report_id: u64,
+    calls: Vec<ToolTimingCallState>,
+}
+
+#[derive(Debug)]
+struct ToolTimingCallState {
+    entry_id: u64,
+    call_id: String,
+    tool_name: String,
+    source: ToolTimingSource,
+    started_us: u64,
+    execution_started_us: Option<u64>,
+    completed_us: Option<u64>,
+}
+
+#[derive(Clone, Debug)]
+pub(crate) struct ToolTimingMarker {
+    state: ToolTimingState,
+    entry_id: u64,
+}
+
+#[derive(Debug)]
+pub(crate) struct ToolTimingGuard {
+    marker: ToolTimingMarker,
+}
+
+#[derive(Clone, Debug, Serialize)]
+pub(crate) struct ToolTimingReport {
+    version: u8,
+    report_id: u64,
+    tool_active_s: f64,
+    calls: Vec<ToolCallTimingReport>,
+}
+
+#[derive(Clone, Debug, Serialize)]
+struct ToolCallTimingReport {
+    call_id: String,
+    tool_name: String,
+    source: &'static str,
+    #[serde(skip_serializing_if = "Option::is_none")]
+    cell_id: Option<String>,
+    #[serde(skip_serializing_if = "Option::is_none")]
+    runtime_tool_call_id: Option<String>,
+    started_s: f64,
+    #[serde(skip_serializing_if = "Option::is_none")]
+    execution_started_s: Option<f64>,
+    completed_s: f64,
+    dispatch_s: f64,
+    handler_s: f64,
+    total_s: f64,
+}
+
+impl Default for ToolTimingState {
+    fn default() -> Self {
+        Self {
+            inner: Arc::new(Mutex::new(ToolTimingStateInner {
+                origin: Instant::now(),
+                next_entry_id: 0,
+                next_report_id: 0,
+                calls: Vec::new(),
+            })),
+        }
+    }
+}
+
+impl ToolTimingState {
+    pub(crate) fn start_call(&self, call: ToolTimingCall) -> ToolTimingGuard {
+        let mut state = self
+            .inner
+            .lock()
+            .unwrap_or_else(std::sync::PoisonError::into_inner);
+        let entry_id = state.next_entry_id;
+        state.next_entry_id += 1;
+        let started_us = state.elapsed_us();
+        state.calls.push(ToolTimingCallState {
+            entry_id,
+            call_id: call.call_id,
+            tool_name: call.tool_name,
+            source: call.source,
+            started_us,
+            execution_started_us: None,
+            completed_us: None,
+        });
+        ToolTimingGuard {
+            marker: ToolTimingMarker {
+                state: self.clone(),
+                entry_id,
+            },
+        }
+    }
+
+    pub(crate) fn take_report(&self) -> ToolTimingReport {
+        let mut state = self
+            .inner
+            .lock()
+            .unwrap_or_else(std::sync::PoisonError::into_inner);
+        let report_id = state.next_report_id;
+        state.next_report_id += 1;
+
+        let mut completed_calls = Vec::new();
+        let mut pending_calls = Vec::new();
+        for call in mem::take(&mut state.calls) {
+            match call.completed_us {
+                Some(completed_us) => completed_calls.push((call, completed_us)),
+                None => pending_calls.push(call),
+            }
+        }
+        state.calls = pending_calls;
+
+        // Nested code-mode calls are diagnostic; their enclosing direct call owns the latency.
+        let mut intervals = completed_calls
+            .iter()
+            .filter(|(call, _)| matches!(&call.source, ToolTimingSource::Direct))
+            .map(|(call, completed_us)| (call.started_us, *completed_us))
+            .collect::<Vec<_>>();
+        intervals.sort_unstable_by_key(|interval| interval.0);
+        let mut tool_active_us = 0_u64;
+        if let Some((mut current_start_us, mut current_end_us)) = intervals.first().copied() {
+            for (started_us, completed_us) in intervals.into_iter().skip(1) {
+                if started_us <= current_end_us {
+                    current_end_us = current_end_us.max(completed_us);
+                } else {
+                    tool_active_us += current_end_us - current_start_us;
+                    current_start_us = started_us;
+                    current_end_us = completed_us;
+                }
+            }
+            tool_active_us += current_end_us - current_start_us;
+        }
+
+        let mut calls = completed_calls
+            .into_iter()
+            .map(|(call, completed_us)| {
+                let execution_started_us = call.execution_started_us;
+                let dispatch_completed_us = execution_started_us.unwrap_or(completed_us);
+                let (source, cell_id, runtime_tool_call_id) = match call.source {
+                    ToolTimingSource::Direct => ("direct", None, None),
+                    ToolTimingSource::CodeMode {
+                        cell_id,
+                        runtime_tool_call_id,
+                    } => ("code_mode", Some(cell_id), Some(runtime_tool_call_id)),
+                };
+                ToolCallTimingReport {
+                    call_id: call.call_id,
+                    tool_name: call.tool_name,
+                    source,
+                    cell_id,
+                    runtime_tool_call_id,
+                    started_s: micros_to_seconds(call.started_us),
+                    execution_started_s: execution_started_us.map(micros_to_seconds),
+                    completed_s: micros_to_seconds(completed_us),
+                    dispatch_s: micros_to_seconds(dispatch_completed_us - call.started_us),
+                    handler_s: micros_to_seconds(completed_us - dispatch_completed_us),
+                    total_s: micros_to_seconds(completed_us - call.started_us),
+                }
+            })
+            .collect::<Vec<_>>();
+        calls.sort_by(|left, right| left.started_s.total_cmp(&right.started_s));
+
+        ToolTimingReport {
+            version: TOOL_TIMING_VERSION,
+            report_id,
+            tool_active_s: micros_to_seconds(tool_active_us),
+            calls,
+        }
+    }
+
+    fn mark_execution_started(&self, entry_id: u64) {
+        let mut state = self
+            .inner
+            .lock()
+            .unwrap_or_else(std::sync::PoisonError::into_inner);
+        let execution_started_us = state.elapsed_us();
+        if let Some(call) = state
+            .calls
+            .iter_mut()
+            .find(|call| call.entry_id == entry_id)
+            && call.completed_us.is_none()
+            && call.execution_started_us.is_none()
+        {
+            call.execution_started_us = Some(execution_started_us);
+        }
+    }
+
+    fn complete_call(&self, entry_id: u64) {
+        let mut state = self
+            .inner
+            .lock()
+            .unwrap_or_else(std::sync::PoisonError::into_inner);
+        let completed_us = state.elapsed_us();
+        if let Some(call) = state
+            .calls
+            .iter_mut()
+            .find(|call| call.entry_id == entry_id)
+        {
+            call.completed_us = Some(completed_us);
+        }
+    }
+}
+
+impl ToolTimingStateInner {
+    fn elapsed_us(&self) -> u64 {
+        u64::try_from(self.origin.elapsed().as_micros()).unwrap_or(u64::MAX)
+    }
+}
+
+impl ToolTimingGuard {
+    pub(crate) fn marker(&self) -> ToolTimingMarker {
+        self.marker.clone()
+    }
+}
+
+impl Drop for ToolTimingGuard {
+    fn drop(&mut self) {
+        self.marker.state.complete_call(self.marker.entry_id);
+    }
+}
+
+impl ToolTimingMarker {
+    pub(crate) fn mark_execution_started(&self) {
+        self.state.mark_execution_started(self.entry_id);
+    }
+}
+
+fn micros_to_seconds(micros: u64) -> f64 {
+    micros as f64 / 1_000_000.0
+}
+
+#[cfg(test)]
+#[path = "tool_timing_tests.rs"]
+mod tests;

codex-rs/core/src/tool_timing_tests.rs

@@ -0,0 +1,115 @@
+use std::sync::Arc;
+use std::sync::Mutex;
+use std::time::Instant;
+
+use pretty_assertions::assert_eq;
+use serde_json::json;
+
+use super::*;
+
+#[test]
+fn direct_calls_are_unioned_and_nested_calls_are_diagnostic() {
+    let state = ToolTimingState {
+        inner: Arc::new(Mutex::new(ToolTimingStateInner {
+            origin: Instant::now(),
+            next_entry_id: 3,
+            next_report_id: 4,
+            calls: vec![
+                ToolTimingCallState {
+                    entry_id: 0,
+                    call_id: "direct-a".to_string(),
+                    tool_name: "functions.exec".to_string(),
+                    source: ToolTimingSource::Direct,
+                    started_us: 0,
+                    execution_started_us: Some(500_000),
+                    completed_us: Some(2_000_000),
+                },
+                ToolTimingCallState {
+                    entry_id: 1,
+                    call_id: "nested".to_string(),
+                    tool_name: "mcp__example__read".to_string(),
+                    source: ToolTimingSource::CodeMode {
+                        cell_id: "cell-1".to_string(),
+                        runtime_tool_call_id: "runtime-call-1".to_string(),
+                    },
+                    started_us: 500_000,
+                    execution_started_us: Some(1_000_000),
+                    completed_us: Some(2_500_000),
+                },
+                ToolTimingCallState {
+                    entry_id: 2,
+                    call_id: "direct-b".to_string(),
+                    tool_name: "functions.wait".to_string(),
+                    source: ToolTimingSource::Direct,
+                    started_us: 1_000_000,
+                    execution_started_us: Some(1_250_000),
+                    completed_us: Some(3_000_000),
+                },
+            ],
+        })),
+    };
+
+    assert_eq!(
+        serde_json::to_value(state.take_report()).expect("serialize report"),
+        json!({
+            "version": 1,
+            "report_id": 4,
+            "tool_active_s": 3.0,
+            "calls": [
+                {
+                    "call_id": "direct-a",
+                    "tool_name": "functions.exec",
+                    "source": "direct",
+                    "started_s": 0.0,
+                    "execution_started_s": 0.5,
+                    "completed_s": 2.0,
+                    "dispatch_s": 0.5,
+                    "handler_s": 1.5,
+                    "total_s": 2.0,
+                },
+                {
+                    "call_id": "nested",
+                    "tool_name": "mcp__example__read",
+                    "source": "code_mode",
+                    "cell_id": "cell-1",
+                    "runtime_tool_call_id": "runtime-call-1",
+                    "started_s": 0.5,
+                    "execution_started_s": 1.0,
+                    "completed_s": 2.5,
+                    "dispatch_s": 0.5,
+                    "handler_s": 1.5,
+                    "total_s": 2.0,
+                },
+                {
+                    "call_id": "direct-b",
+                    "tool_name": "functions.wait",
+                    "source": "direct",
+                    "started_s": 1.0,
+                    "execution_started_s": 1.25,
+                    "completed_s": 3.0,
+                    "dispatch_s": 0.25,
+                    "handler_s": 1.75,
+                    "total_s": 2.0,
+                },
+            ],
+        })
+    );
+}
+
+#[test]
+fn execution_start_after_completion_is_ignored() {
+    let state = ToolTimingState::default();
+    let guard = state.start_call(ToolTimingCall {
+        call_id: "call-1".to_string(),
+        tool_name: "functions.exec".to_string(),
+        source: ToolTimingSource::Direct,
+    });
+    let marker = guard.marker();
+
+    drop(guard);
+    marker.mark_execution_started();
+
+    let report = serde_json::to_value(state.take_report()).expect("serialize report");
+    assert_eq!(report["calls"][0]["execution_started_s"], json!(null));
+    assert_eq!(report["calls"][0]["handler_s"], json!(0.0));
+}

codex-rs/core/src/tools/parallel.rs

@@ -15,6 +15,8 @@ use tracing::trace_span;
 use crate::function_tool::FunctionCallError;
 use crate::session::session::Session;
 use crate::session::step_context::StepContext;
+use crate::tool_timing::ToolTimingCall;
+use crate::tool_timing::ToolTimingSource;
 use crate::tools::context::AbortedToolOutput;
 use crate::tools::context::SharedTurnDiffTracker;
 use crate::tools::context::ToolPayload;
@@ -96,6 +98,22 @@ impl ToolCallRuntime {
         let invocation_cancellation_token = cancellation_token.clone();
         let wait_for_runtime_cancellation = self.router.tool_waits_for_runtime_cancellation(&call);
         let started = Instant::now();
+        let tool_timing_source = match &source {
+            ToolCallSource::Direct => ToolTimingSource::Direct,
+            ToolCallSource::CodeMode {
+                cell_id,
+                runtime_tool_call_id,
+            } => ToolTimingSource::CodeMode {
+                cell_id: cell_id.clone(),
+                runtime_tool_call_id: runtime_tool_call_id.clone(),
+            },
+        };
+        let tool_timing_guard = turn.turn_metadata_state.start_tool_timing(ToolTimingCall {
+            call_id: call.call_id.clone(),
+            tool_name: call.tool_name.to_string(),
+            source: tool_timing_source,
+        });
+        let tool_timing_marker = tool_timing_guard.marker();
         let abort_session = Arc::clone(&session);
         let abort_source = source.clone();
         let abort_turn = Arc::clone(&turn);
@@ -119,6 +137,7 @@ impl ToolCallRuntime {
                 } else {
                     Either::Right(lock.write().await)
                 };
+                tool_timing_marker.mark_execution_started();
 
                 router
                     .dispatch_tool_call_with_terminal_outcome(
@@ -135,6 +154,7 @@ impl ToolCallRuntime {
             }));
 
         async move {
+            let _tool_timing_guard = tool_timing_guard;
             tokio::select! {
                 res = &mut handle => res.map_err(Self::tool_task_join_error)?,
                 _ = cancellation_token.cancelled() => {

codex-rs/core/src/turn_metadata.rs

@@ -16,6 +16,9 @@ use crate::responses_metadata::filter_extra_metadata;
 use crate::responses_metadata::subagent_header_value;
 use crate::responses_metadata::subagent_metadata_kind;
 use crate::sandbox_tags::permission_profile_sandbox_tag;
+use crate::tool_timing::ToolTimingCall;
+use crate::tool_timing::ToolTimingGuard;
+use crate::tool_timing::ToolTimingState;
 use codex_git_utils::get_git_remote_urls_assume_git_repo;
 use codex_git_utils::get_git_repo_root;
 use codex_git_utils::get_has_changes;
@@ -98,6 +101,7 @@ pub(crate) struct TurnMetadataState {
     enriched_workspaces: Arc<RwLock<Option<BTreeMap<String, TurnMetadataWorkspace>>>>,
     turn_started_at_unix_ms: Arc<RwLock<Option<i64>>>,
     responsesapi_client_metadata: Arc<RwLock<BTreeMap<String, String>>>,
+    tool_timing_state: ToolTimingState,
     user_input_requested_during_turn: Arc<AtomicBool>,
     enrichment_task: Arc<Mutex<Option<JoinHandle<()>>>>,
 }
@@ -141,6 +145,7 @@ impl TurnMetadataState {
             enriched_workspaces: Arc::new(RwLock::new(None)),
             turn_started_at_unix_ms: Arc::new(RwLock::new(None)),
             responsesapi_client_metadata: Arc::new(RwLock::new(BTreeMap::new())),
+            tool_timing_state: ToolTimingState::default(),
             user_input_requested_during_turn: Arc::new(AtomicBool::new(false)),
             enrichment_task: Arc::new(Mutex::new(None)),
         }
@@ -190,14 +195,24 @@ impl TurnMetadataState {
         window_id: String,
         request_kind: CodexResponsesRequestKind,
     ) -> CodexResponsesMetadata {
+        let tool_timing = matches!(
+            request_kind,
+            CodexResponsesRequestKind::Turn | CodexResponsesRequestKind::Compaction(_)
+        )
+        .then(|| self.tool_timing_state.take_report());
         CodexResponsesMetadata {
             installation_id,
             window_id,
             request_kind: Some(request_kind),
+            tool_timing,
             ..self.responses_metadata_template()
         }
     }
 
+    pub(crate) fn start_tool_timing(&self, call: ToolTimingCall) -> ToolTimingGuard {
+        self.tool_timing_state.start_call(call)
+    }
+
     pub(crate) fn mark_user_input_requested_during_turn(&self) {
         self.user_input_requested_during_turn
             .store(true, Ordering::Relaxed);

codex-rs/core/src/turn_metadata_tests.rs

@@ -720,6 +720,15 @@ fn turn_metadata_state_overlays_compaction_only_on_compaction_requests() {
     assert_eq!(compact_json["request_kind"].as_str(), Some("compaction"));
     assert_eq!(compact_json["turn_id"].as_str(), Some("turn-a"));
     assert_eq!(compact_json[WINDOW_ID_KEY].as_str(), Some("thread-a:2"));
+    assert_eq!(
+        compact_json["tool_timing"],
+        serde_json::json!({
+            "version": 1,
+            "report_id": 0,
+            "tool_active_s": 0.0,
+            "calls": [],
+        })
+    );
     assert_eq!(
         compact_json["compaction"],
         serde_json::json!({
@@ -735,6 +744,15 @@ fn turn_metadata_state_overlays_compaction_only_on_compaction_requests() {
     let regular_json: Value = serde_json::from_str(&regular_header).expect("json");
     assert_eq!(regular_json["request_kind"].as_str(), Some("turn"));
     assert_eq!(regular_json[WINDOW_ID_KEY].as_str(), Some("thread-a:3"));
+    assert_eq!(
+        regular_json["tool_timing"],
+        serde_json::json!({
+            "version": 1,
+            "report_id": 1,
+            "tool_active_s": 0.0,
+            "calls": [],
+        })
+    );
     assert!(regular_json.get("compaction").is_none());
 }