Add opt-in overhead timing to code-mode responses (#46288)

## Why Code-mode responses show host duration without exposing time spent outside the host, including app-server waiting. ## What changed - Add `features.code_mode.experimental_show_cell_overhead`, disabled by default, to show handler duration, host duration, and their difference in `exec` and `wait` response headers. - Reuse the completed handler measurement from tool-call logging, excluding dispatch waiting, and capture it even when logging is disabled. - Preserve the existing timing format when the option is disabled or host timing is unavailable, and preserve boolean feature toggles when merging nested code-mode configuration. ## Testing Add coverage for timing headers, zero and missing host measurements, negative rounding differences, content preservation, and configuration merging. Extend app-server tests across gRPC and stdio to verify timing includes post-host elicitation waiting, and add a response snapshot for successful execution and a failed wait. GitOrigin-RevId: 929b84784d9c6077cf2b5927a90bd2d5f3870078
2026-10-19 17:28:46 +00:00 · 2026-09-17 19:34:45 +00:00
parent 0a5b999169
commit 0fd1cd8d99
19 changed files with 619 additions and 116 deletions
@@ -34,17 +34,28 @@ const DEFAULT_READ_TIMEOUT: Duration = Duration::from_secs(/*secs*/ 60);
 #[cfg(not(any(target_os = "macos", windows)))]
 const DEFAULT_READ_TIMEOUT: Duration = Duration::from_secs(/*secs*/ 10);

-/// Model output and the structured timing consumed by Bridge describe the same
-/// host operation over either transport, including missing-cell responses.
-#[test_case("exec", "grpc"; "exec_grpc")]
-#[test_case("wait", "grpc"; "wait_grpc")]
-#[test_case("exec", "stdio"; "exec_stdio")]
-#[test_case("wait", "stdio"; "wait_stdio")]
+enum TimingOutput {
+    HostOnly,
+    WithOverhead,
+}
+
+/// Responses with overhead use the same host and handler measurements as Bridge,
+/// including app-server waiting. The default shows only host duration.
+#[test_case("exec", "grpc", TimingOutput::HostOnly; "exec_grpc_host_only")]
+#[test_case("wait", "grpc", TimingOutput::HostOnly; "wait_grpc_host_only")]
+#[test_case("exec", "stdio", TimingOutput::HostOnly; "exec_stdio_host_only")]
+#[test_case("wait", "stdio", TimingOutput::HostOnly; "wait_stdio_host_only")]
+#[test_case("exec", "grpc", TimingOutput::WithOverhead; "exec_grpc_with_overhead")]
+#[test_case("wait", "grpc", TimingOutput::WithOverhead; "wait_grpc_with_overhead")]
+#[test_case("exec", "stdio", TimingOutput::WithOverhead; "exec_stdio_with_overhead")]
+#[test_case("wait", "stdio", TimingOutput::WithOverhead; "wait_stdio_with_overhead")]
 #[tokio::test(flavor = "multi_thread", worker_threads = 2)]
 async fn code_mode_model_output_uses_structured_host_timing(
    tool_name: &str,
    transport: &str,
+    timing_output: TimingOutput,
 ) -> Result<()> {
+    let experimental_show_cell_overhead = matches!(timing_output, TimingOutput::WithOverhead);
    let mut host = match transport {
        "grpc" => Some(
            Command::new(codex_utils_cargo_bin::cargo_bin("codex-code-mode-host")?)
@@ -100,9 +111,13 @@ async fn code_mode_model_output_uses_structured_host_timing(
    )
    .await;
    let codex_home = TempDir::new()?;
-    MockResponsesConfig::new(&model_server.uri())
-        .enable_feature(Feature::CodeModeOnly)
-        .write(codex_home.path())?;
+    let mut config =
+        MockResponsesConfig::new(&model_server.uri()).enable_feature(Feature::CodeModeOnly);
+    if experimental_show_cell_overhead {
+        config = config
+            .with_extra_config("[features.code_mode]\nexperimental_show_cell_overhead = true");
+    }
+    config.write(codex_home.path())?;
    let mut builder = TestAppServer::builder()
        .with_codex_home(codex_home.path())
        .with_json_logging("codex_code_mode::timing=info,codex_core::tools::parallel=info");
@@ -133,12 +148,16 @@ async fn code_mode_model_output_uses_structured_host_timing(
        })
        .await?;
    let _: TurnStartResponse = app_server.read_response(start_id).await?;
-    let timing = app_server
+    let host_timing = app_server
        .wait_for_json_log_event("codex.code_mode.host_timing")
        .await?;
    // Hold only the app-server after the host outcome, so local elapsed time
    // cannot round to the same displayed duration as the host measurement.
    tokio::time::sleep(Duration::from_millis(/*millis*/ 300)).await;
+    assert!(
+        follow_up.requests().is_empty(),
+        "the model must not receive the result while elicitation is outstanding"
+    );
    let decrement_id = app_server
        .send_request(
            "thread/decrement_elicitation",
@@ -151,14 +170,45 @@ async fn code_mode_model_output_uses_structured_host_timing(
    let completed: TurnCompletedNotification =
        app_server.read_notification("turn/completed").await?;
    assert_eq!(completed.turn.status, TurnStatus::Completed);
-    let fields = &timing["fields"];
-    let code_mode_host_duration_ns = fields["code_mode_host_duration_ns"]
+    let host_fields = &host_timing["fields"];
+    let code_mode_host_duration_ns = host_fields["code_mode_host_duration_ns"]
        .as_u64()
        .context("missing host timing")?;
-    assert_eq!(fields["conversation_id"], thread.thread.id);
-    assert_eq!(fields["turn_id"], completed.turn.id);
-    assert_eq!(fields["call_id"], "timed-call");
-    assert_eq!(fields["tool_name"], tool_name);
+    assert_eq!(host_fields["conversation_id"], thread.thread.id);
+    assert_eq!(host_fields["turn_id"], completed.turn.id);
+    assert_eq!(host_fields["call_id"], "timed-call");
+    assert_eq!(host_fields["tool_name"], tool_name);
+    let handler_timing = app_server
+        .wait_for_json_log_event("codex.tool_call")
+        .await?;
+    let handler_fields = &handler_timing["fields"];
+    let handler_duration_ms = handler_fields["handler_duration_ms"]
+        .as_u64()
+        .context("missing handler timing")?;
+    assert_eq!(
+        [
+            &handler_fields["conversation.id"],
+            &handler_fields["turn_id"],
+            &handler_fields["call_id"],
+            &handler_fields["tool_name"],
+        ],
+        [
+            &host_fields["conversation_id"],
+            &host_fields["turn_id"],
+            &host_fields["call_id"],
+            &host_fields["tool_name"],
+        ]
+    );
+    assert_eq!(handler_fields["tool_source"], "direct");
+    assert_eq!(handler_fields["execution_started"], true);
+    // The host stopped its timer before the elicitation hold. The outer handler
+    // must include that hold, with some allowance for its millisecond precision.
+    let overhead_ns =
+        i128::from(handler_duration_ms) * 1_000_000 - i128::from(code_mode_host_duration_ns);
+    assert!(
+        overhead_ns >= 250_000_000,
+        "handler timing omitted the post-host elicitation hold: {overhead_ns}ns"
+    );
    let request = follow_up.single_request();
    let output = if tool_name == "exec" {
        request.custom_tool_call_output("timed-call")
@@ -170,12 +220,19 @@ async fn code_mode_model_output_uses_structured_host_timing(
    } else {
        "Script failed"
    };
-    let seconds = Duration::from_nanos(code_mode_host_duration_ns).as_secs_f32();
-    let seconds = (seconds * 10.0).round() / 10.0;
-    assert_eq!(
-        output["output"][0]["text"],
+    let expected_header = if experimental_show_cell_overhead {
+        let total_seconds = Duration::from_millis(handler_duration_ms).as_secs_f64();
+        let host_seconds = Duration::from_nanos(code_mode_host_duration_ns).as_secs_f64();
+        let overhead_seconds = overhead_ns as f64 / 1_000_000_000.0;
+        format!(
+            "{status}\nWall time {total_seconds:.3} seconds (code-mode {host_seconds:.3} seconds; overhead {overhead_seconds:.3} seconds)\nOutput:\n"
+        )
+    } else {
+        let seconds = Duration::from_nanos(code_mode_host_duration_ns).as_secs_f32();
+        let seconds = (seconds * 10.0).round() / 10.0;
        format!("{status}\nWall time {seconds:.1} seconds\nOutput:\n")
-    );
+    };
+    assert_eq!(output["output"][0]["text"], expected_header);
    Ok(())
 }

@@ -68,7 +68,7 @@ pub fn is_structured_feature_path<S: AsRef<str>>(path: &[S]) -> bool {
    features.as_ref() == "features"
        && matches!(
            feature.as_ref(),
-            "multi_agent_v2" | "network_proxy" | "sleep_tool"
+            "code_mode" | "multi_agent_v2" | "network_proxy" | "sleep_tool"
        )
 }

@@ -255,6 +255,45 @@ fn multi_agent_v2_cli_overrides_preserve_boolean_and_nested_configuration() {
    }
 }

+#[test]
+fn code_mode_overrides_preserve_enabled_state_and_cell_overhead() {
+    for feature_path in ["features", "profiles.work.features"] {
+        for enabled in [true, false] {
+            let toggle = (
+                format!("{feature_path}.code_mode"),
+                TomlValue::Boolean(enabled),
+            );
+            let overhead = (
+                format!("{feature_path}.code_mode.experimental_show_cell_overhead"),
+                TomlValue::Boolean(true),
+            );
+            let expected = parse_toml(&format!(
+                "[{feature_path}.code_mode]\nenabled = {enabled}\nexperimental_show_cell_overhead = true\n",
+            ));
+
+            // Adding a display option must preserve the toggle in either override order.
+            for overrides in [
+                vec![toggle.clone(), overhead.clone()],
+                vec![overhead, toggle],
+            ] {
+                assert_eq!(crate::build_cli_overrides_layer(&overrides), expected);
+            }
+
+            let boolean_layer = parse_toml(&format!("[{feature_path}]\ncode_mode = {enabled}\n"));
+            let table_layer = parse_toml(&format!(
+                "[{feature_path}.code_mode]\nexperimental_show_cell_overhead = true\n",
+            ));
+            for (mut base, overlay) in [
+                (boolean_layer.clone(), table_layer.clone()),
+                (table_layer, boolean_layer),
+            ] {
+                merge_toml_values(&mut base, &overlay);
+                assert_eq!(base, expected);
+            }
+        }
+    }
+}
+
 #[test]
 fn sleep_tool_overrides_preserve_disabled_state_and_mode() {
    for feature_path in ["features", "profiles.work.features"] {
@@ -530,6 +530,10 @@
            "type": "string"
          },
          "type": "array"
+        },
+        "experimental_show_cell_overhead": {
+          "description": "Show handler duration, code-mode host duration, and harness overhead in each code-mode cell response. Experimental: this option and the response format may change or be removed.",
+          "type": "boolean"
        }
      },
      "type": "object"
@@ -635,6 +635,7 @@ async fn load_config_resolves_code_mode_config() -> std::io::Result<()> {
 [features.code_mode]
 enabled = true
 default_exec_yield_time_ms = 10000
+experimental_show_cell_overhead = true
 excluded_tool_namespaces = ["mcp__codex_apps", "multi_agent_v1"]
 direct_only_tool_namespaces = ["mcp__history", "mcp__notes"]

@@ -652,6 +653,7 @@ disable_in_process_fallback = true
    .await?;

    assert_eq!(config.code_mode.default_exec_yield_time_ms, 10_000);
+    assert!(config.code_mode.experimental_show_cell_overhead);
    assert_eq!(
        config.code_mode.excluded_tool_namespaces,
        vec!["mcp__codex_apps".to_string(), "multi_agent_v1".to_string()]
@@ -1127,6 +1127,10 @@ const DEFAULT_CODE_MODE_EXEC_YIELD_TIME_MS: u64 = 30_000;
 #[derive(Debug, Clone, PartialEq, Eq, Serialize)]
 pub struct CodeModeConfig {
    pub default_exec_yield_time_ms: u64,
+    /// Show handler duration, code-mode host duration, and harness overhead
+    /// in each code-mode cell response.
+    /// Experimental: this option and the response format may change or be removed.
+    pub experimental_show_cell_overhead: bool,
    pub excluded_tool_namespaces: Vec<String>,
    pub direct_only_tool_namespaces: Vec<String>,
    /// Keep code mode fail-closed when the standalone host is unavailable.
@@ -1137,6 +1141,7 @@ impl Default for CodeModeConfig {
    fn default() -> Self {
        Self {
            default_exec_yield_time_ms: DEFAULT_CODE_MODE_EXEC_YIELD_TIME_MS,
+            experimental_show_cell_overhead: false,
            excluded_tool_namespaces: Vec::new(),
            direct_only_tool_namespaces: Vec::new(),
            disable_in_process_fallback: false,
@@ -2679,6 +2684,9 @@ fn resolve_code_mode_config(config_toml: &ConfigToml) -> CodeModeConfig {
        default_exec_yield_time_ms: base
            .and_then(|config| config.default_exec_yield_time_ms)
            .unwrap_or(DEFAULT_CODE_MODE_EXEC_YIELD_TIME_MS),
+        experimental_show_cell_overhead: base
+            .and_then(|config| config.experimental_show_cell_overhead)
+            .unwrap_or_default(),
        excluded_tool_namespaces: base
            .and_then(|config| config.excluded_tool_namespaces.as_ref())
            .cloned()
@@ -1,5 +1,4 @@
 use crate::function_tool::FunctionCallError;
-use crate::tools::context::FunctionToolOutput;
 use crate::tools::context::ToolInvocation;
 use crate::tools::context::ToolPayload;
 use crate::tools::context::boxed_tool_output;
@@ -13,6 +12,7 @@ use super::ExecContext;
 use super::PUBLIC_TOOL_NAME;
 use super::handle_runtime_response;
 use super::is_exec_tool_name;
+use super::output::CodeModeToolOutput;
 use super::telemetry::CodeModeToolCallGuard;
 use super::telemetry::trace_id;

@@ -39,7 +39,7 @@ impl CodeModeExecuteHandler {
        originating_call: Option<crate::tools::context::ToolCallOrigin>,
        code: String,
        telemetry: &mut CodeModeToolCallGuard,
-    ) -> Result<FunctionToolOutput, FunctionCallError> {
+    ) -> Result<CodeModeToolOutput, FunctionCallError> {
        let args =
            codex_code_mode::parse_exec_source(&code).map_err(FunctionCallError::RespondToModel)?;
        let exec = ExecContext {
@@ -146,14 +146,13 @@ impl CodeModeExecuteHandler {
        let wall_time = response
            .code_mode_host_duration()
            .unwrap_or_else(|| started_at.elapsed());
-        handle_runtime_response(
+        Ok(handle_runtime_response(
            &step_context.settings.model_info,
            response,
            args.max_output_tokens,
            wall_time,
-        )
-        .await
-        .map_err(FunctionCallError::RespondToModel)
+            exec.turn.config.code_mode.experimental_show_cell_overhead,
+        ))
    }
 }

@@ -1,6 +1,7 @@
 mod delegate;
 mod execute_handler;
 pub(crate) mod execute_spec;
+mod output;
 mod response_adapter;
 mod telemetry;
 mod wait_handler;
@@ -51,6 +52,7 @@ use delegate::CodeModeCellDelegate;
 use delegate::CodeModeDispatchBroker;
 use delegate::CodeModeDispatchWorker;
 pub(crate) use execute_handler::CodeModeExecuteHandler;
+use output::CodeModeToolOutput;
 use response_adapter::into_function_call_output_content_items;
 pub(crate) use wait_handler::CodeModeWaitHandler;

@@ -251,51 +253,43 @@ impl CodeModeService {
    }
 }

-pub(super) async fn handle_runtime_response(
+fn handle_runtime_response(
    model_info: &codex_protocol::openai_models::ModelInfo,
    response: RuntimeResponse,
    max_output_tokens: Option<usize>,
    wall_time: Duration,
-) -> Result<FunctionToolOutput, String> {
+    experimental_show_cell_overhead: bool,
+) -> CodeModeToolOutput {
    let script_status = format_script_status(&response);
    let supports_original = can_request_original_image_detail(model_info);
+    let host_duration = response
+        .code_mode_host_duration()
+        .filter(|_| experimental_show_cell_overhead);

-    match response {
-        RuntimeResponse::Yielded { content_items, .. } => {
-            let mut content_items = into_function_call_output_content_items(content_items);
-            sanitize_image_detail_items(supports_original, &mut content_items);
-            content_items = truncate_code_mode_result(content_items, max_output_tokens);
-            prepend_script_status(&mut content_items, &script_status, wall_time);
-            Ok(FunctionToolOutput::from_content(content_items, Some(true)))
-        }
-        RuntimeResponse::Terminated { content_items, .. } => {
-            let mut content_items = into_function_call_output_content_items(content_items);
-            sanitize_image_detail_items(supports_original, &mut content_items);
-            content_items = truncate_code_mode_result(content_items, max_output_tokens);
-            prepend_script_status(&mut content_items, &script_status, wall_time);
-            Ok(FunctionToolOutput::from_content(content_items, Some(true)))
-        }
+    let (content_items, error_text) = match response {
+        RuntimeResponse::Yielded { content_items, .. }
+        | RuntimeResponse::Terminated { content_items, .. } => (content_items, None),
        RuntimeResponse::Result {
            content_items,
            error_text,
            ..
-        } => {
-            let mut content_items = into_function_call_output_content_items(content_items);
-            sanitize_image_detail_items(supports_original, &mut content_items);
-            let success = error_text.is_none();
-            if let Some(error_text) = error_text {
-                content_items.push(FunctionCallOutputContentItem::InputText {
-                    text: format!("Script error:\n{error_text}"),
-                });
-            }
-            content_items = truncate_code_mode_result(content_items, max_output_tokens);
-            prepend_script_status(&mut content_items, &script_status, wall_time);
-            Ok(FunctionToolOutput::from_content(
-                content_items,
-                Some(success),
-            ))
-        }
+        } => (content_items, error_text),
+    };
+    let mut content_items = into_function_call_output_content_items(content_items);
+    sanitize_image_detail_items(supports_original, &mut content_items);
+    let success = error_text.is_none();
+    if let Some(error_text) = error_text {
+        content_items.push(FunctionCallOutputContentItem::InputText {
+            text: format!("Script error:\n{error_text}"),
+        });
    }
+    content_items = truncate_code_mode_result(content_items, max_output_tokens);
+    CodeModeToolOutput::new(
+        FunctionToolOutput::from_content(content_items, Some(success)),
+        script_status,
+        wall_time,
+        host_duration,
+    )
 }

 fn format_script_status(response: &RuntimeResponse) -> String {
@@ -314,16 +308,6 @@ fn format_script_status(response: &RuntimeResponse) -> String {
    }
 }

-fn prepend_script_status(
-    content_items: &mut Vec<FunctionCallOutputContentItem>,
-    status: &str,
-    wall_time: Duration,
-) {
-    let wall_time_seconds = ((wall_time.as_secs_f32()) * 10.0).round() / 10.0;
-    let header = format!("{status}\nWall time {wall_time_seconds:.1} seconds\nOutput:\n");
-    content_items.insert(0, FunctionCallOutputContentItem::InputText { text: header });
-}
-
 fn truncate_code_mode_result(
    items: Vec<FunctionCallOutputContentItem>,
    max_output_tokens: Option<usize>,
@@ -0,0 +1,76 @@
+//! Code-mode response headers use the host measurement and completed handler timing.
+//! Content is already truncated; only the bounded header changes at completion.
+
+use std::time::Duration;
+
+use codex_protocol::models::FunctionCallOutputContentItem;
+use codex_protocol::models::ResponseInputItem;
+
+use crate::tools::context::FunctionToolOutput;
+use crate::tools::context::ToolOutput;
+use crate::tools::context::ToolPayload;
+
+pub(super) struct CodeModeToolOutput {
+    output: FunctionToolOutput,
+    status: String,
+    host_duration: Option<Duration>,
+}
+
+impl CodeModeToolOutput {
+    pub(super) fn new(
+        mut output: FunctionToolOutput,
+        status: String,
+        wall_time: Duration,
+        host_duration: Option<Duration>,
+    ) -> Self {
+        // Use the host-only header when overhead is hidden or host timing is unavailable.
+        let wall_time_seconds = (wall_time.as_secs_f32() * 10.0).round() / 10.0;
+        output.body.insert(
+            /*index*/ 0,
+            FunctionCallOutputContentItem::InputText {
+                text: format!("{status}\nWall time {wall_time_seconds:.1} seconds\nOutput:\n"),
+            },
+        );
+        Self {
+            output,
+            status,
+            host_duration,
+        }
+    }
+}
+
+impl ToolOutput for CodeModeToolOutput {
+    fn log_output(&self) -> String {
+        self.output.log_output()
+    }
+
+    fn success_for_logging(&self) -> bool {
+        self.output.success_for_logging()
+    }
+
+    fn set_handler_duration_ms(&mut self, handler_duration_ms: u64) {
+        let Some(host_duration) = self.host_duration else {
+            return;
+        };
+        let total_seconds = handler_duration_ms as f64 / 1_000.0;
+        let host_seconds = host_duration.as_secs_f64();
+        // Match the logged measurements before rounding. Millisecond quantization of the
+        // outer measurement can legitimately produce a small negative difference.
+        let overhead_seconds = total_seconds - host_seconds;
+        let status = &self.status;
+        // The constructor owns this slot; script text and media stay untouched.
+        self.output.body[0] = FunctionCallOutputContentItem::InputText {
+            text: format!(
+                "{status}\nWall time {total_seconds:.3} seconds (code-mode {host_seconds:.3} seconds; overhead {overhead_seconds:.3} seconds)\nOutput:\n"
+            ),
+        };
+    }
+
+    fn to_response_item(&self, call_id: &str, payload: &ToolPayload) -> ResponseInputItem {
+        self.output.to_response_item(call_id, payload)
+    }
+}
+
+#[cfg(test)]
+#[path = "output_tests.rs"]
+mod tests;
@@ -0,0 +1,65 @@
+//! Checks code-mode timing headers, including absent and zero host measurements.
+
+use super::*;
+use codex_protocol::models::ImageReference;
+use pretty_assertions::assert_eq;
+
+#[test]
+fn completed_timing_preserves_content_and_distinguishes_zero_from_unavailable() {
+    let content = vec![
+        FunctionCallOutputContentItem::InputText {
+            text: "result".to_string(),
+        },
+        FunctionCallOutputContentItem::InputImage {
+            image: ImageReference::Inline {
+                image_url: "data:image/png;base64,image".to_string(),
+            },
+            detail: None,
+        },
+        FunctionCallOutputContentItem::InputAudio {
+            audio_url: "data:audio/wav;base64,audio".to_string(),
+        },
+    ];
+    for (host_duration, expected_timing) in [
+        (
+            Some(Duration::from_millis(/*millis*/ 750)),
+            "Wall time 1.250 seconds (code-mode 0.750 seconds; overhead 0.500 seconds)",
+        ),
+        (
+            Some(Duration::ZERO),
+            "Wall time 1.250 seconds (code-mode 0.000 seconds; overhead 1.250 seconds)",
+        ),
+        (
+            Some(Duration::from_micros(/*micros*/ 1_251_400)),
+            "Wall time 1.250 seconds (code-mode 1.251 seconds; overhead -0.001 seconds)",
+        ),
+        (None, "Wall time 0.8 seconds"),
+    ] {
+        let mut output = CodeModeToolOutput::new(
+            FunctionToolOutput::from_content(content.clone(), Some(false)),
+            "Script failed".to_string(),
+            Duration::from_millis(/*millis*/ 750),
+            host_duration,
+        );
+        output.set_handler_duration_ms(/*handler_duration_ms*/ 1_250);
+        let mut expected_content = vec![FunctionCallOutputContentItem::InputText {
+            text: format!("Script failed\n{expected_timing}\nOutput:\n"),
+        }];
+        expected_content.extend(content.clone());
+        let expected = FunctionToolOutput::from_content(expected_content, Some(false));
+        for payload in [
+            ToolPayload::Custom {
+                input: "text('result')".to_string(),
+            },
+            ToolPayload::Function {
+                arguments: r#"{"cell_id":"1"}"#.to_string(),
+            },
+        ] {
+            let response = output.to_response_item("call", &payload);
+            assert_eq!(response, expected.to_response_item("call", &payload));
+            // Serialization must reuse the completed value, including on retries.
+            assert_eq!(output.to_response_item("call", &payload), response);
+        }
+        assert_eq!(output.success_for_logging(), false);
+    }
+}
@@ -178,15 +178,13 @@ impl CodeModeWaitHandler {
                let wall_time = wait_response
                    .code_mode_host_duration()
                    .unwrap_or_else(|| started_at.elapsed());
-                handle_runtime_response(
+                Ok(boxed_tool_output(handle_runtime_response(
                    &step_context.settings.model_info,
                    wait_response.into(),
                    args.max_tokens,
                    wall_time,
-                )
-                .await
-                .map_err(FunctionCallError::RespondToModel)
-                .map(boxed_tool_output)
+                    exec.turn.config.code_mode.experimental_show_cell_overhead,
+                )))
            }
            _ => Err(FunctionCallError::RespondToModel(format!(
                "{WAIT_TOOL_NAME} expects JSON arguments"
@@ -32,7 +32,7 @@ use codex_protocol::models::ResponseInputItem;
 use codex_protocol::models::ToolResultMetadata;

 struct ToolCallTimingGuard {
-    started_at: Instant,
+    started_at: Option<Instant>,
    execution_started_at: Arc<OnceLock<Instant>>,
    conversation_id: String,
    turn_id: String,
@@ -130,8 +130,14 @@ impl ToolCallRuntime {
        let lock = Arc::clone(&self.parallel_execution);
        let invocation_cancellation_token = cancellation_token.clone();
        let started = Instant::now();
-        let tool_call_timing_guard =
-            ToolCallTimingGuard::capture(started, &session.thread_id, &turn.sub_id, &call, &source);
+        let tool_call_timing_guard = ToolCallTimingGuard::capture(
+            started,
+            &session.thread_id,
+            &turn.sub_id,
+            &call,
+            &source,
+            turn.config.code_mode.experimental_show_cell_overhead,
+        );
        let execution_started_at = tool_call_timing_guard
            .as_ref()
            .map(|timing| Arc::clone(&timing.execution_started_at));
@@ -213,8 +219,8 @@ impl ToolCallRuntime {
        ));

        async move {
-            let _tool_call_timing_guard = tool_call_timing_guard;
-            tokio::select! {
+            let mut tool_call_timing_guard = tool_call_timing_guard;
+            let mut result = tokio::select! {
                res = &mut dispatch_handle => res.map_err(Self::tool_task_join_error)?,
                _ = cancellation_token.cancelled() => {
                    if terminal_outcome_reached.load(Ordering::Acquire) || dispatch_handle.is_finished() {
@@ -224,30 +230,40 @@ impl ToolCallRuntime {
                        abort_dispatch_span.record("aborted", true);
                        dispatch_handle.abort();
                        match dispatch_handle.await {
-                            Ok(result) => return result,
-                            Err(err) if err.is_cancelled() => {}
-                            Err(err) => return Err(Self::tool_task_join_error(err)),
+                            Ok(result) => result,
+                            Err(err) if err.is_cancelled() => {
+                                let response = Self::aborted_response(&call, secs);
+                                call_trace::result_ready(
+                                    thread_id,
+                                    &abort_turn.sub_id,
+                                    &call.tool_name,
+                                    &call.call_id,
+                                    trace_source,
+                                );
+                                notify_tool_aborted(
+                                    abort_session.as_ref(),
+                                    abort_turn.as_ref(),
+                                    call.call_id.as_str(),
+                                    &call.tool_name,
+                                    abort_source,
+                                )
+                                .await;
+                                Ok(response)
+                            }
+                            Err(err) => Err(Self::tool_task_join_error(err)),
                        }
-                        let response = Self::aborted_response(&call, secs);
-                        call_trace::result_ready(
-                            thread_id,
-                            &abort_turn.sub_id,
-                            &call.tool_name,
-                            &call.call_id,
-                            trace_source,
-                        );
-                        notify_tool_aborted(
-                            abort_session.as_ref(),
-                            abort_turn.as_ref(),
-                            call.call_id.as_str(),
-                            &call.tool_name,
-                            abort_source,
-                        )
-                        .await;
-                        Ok(response)
                    }
                },
+            };
+            // Use one completion measurement for logging and response formatting.
+            // Measuring inside a handler would omit routing and output processing.
+            if let Some(timing) = tool_call_timing_guard.as_mut()
+                && let Some(handler_duration_ms) = timing.finish()
+                && let Ok(result) = &mut result
+            {
+                result.result.set_handler_duration_ms(handler_duration_ms);
            }
+            result
        }
        .in_current_span()
    }
@@ -312,6 +328,7 @@ impl ToolCallTimingGuard {
        turn_id: &str,
        call: &ToolCall,
        source: &ToolCallSource,
+        experimental_show_cell_overhead: bool,
    ) -> Option<Self> {
        // Code-mode calls are nested within a direct code-mode tool call whose
        // timing already includes them. Suppress nested guards so consumers do
@@ -319,13 +336,13 @@ impl ToolCallTimingGuard {
        if !matches!(
            source,
            ToolCallSource::Direct | ToolCallSource::DirectPlaintextMessage
-        ) || !tracing::enabled!(tracing::Level::INFO)
+        ) || (!experimental_show_cell_overhead && !tracing::enabled!(tracing::Level::INFO))
        {
            return None;
        }

        Some(Self {
-            started_at,
+            started_at: Some(started_at),
            execution_started_at: Arc::new(OnceLock::new()),
            conversation_id: conversation_id.to_string(),
            turn_id: turn_id.to_string(),
@@ -333,10 +350,11 @@ impl ToolCallTimingGuard {
            tool_name: call.tool_name.clone(),
        })
    }
-}

-impl Drop for ToolCallTimingGuard {
-    fn drop(&mut self) {
+    /// Log call timing once and return the handler duration in milliseconds.
+    fn finish(&mut self) -> Option<u64> {
+        // Taking the start instant keeps normal completion and Drop from logging twice.
+        let started_at = self.started_at.take()?;
        let completed_at = Instant::now();
        // Snapshot once so a concurrently-starting dispatch cannot make one
        // event internally inconsistent.
@@ -346,12 +364,10 @@ impl Drop for ToolCallTimingGuard {
            .copied()
            .filter(|execution_started_at| *execution_started_at <= completed_at);
        let duration_ms = |duration: std::time::Duration| u64::try_from(duration.as_millis()).ok();
-        let total_duration_ms = duration_ms(completed_at.duration_since(self.started_at));
+        let total_duration_ms = duration_ms(completed_at.duration_since(started_at));
        let dispatch_duration_ms = execution_started_at.map_or_else(
            || total_duration_ms,
-            |execution_started_at| {
-                duration_ms(execution_started_at.duration_since(self.started_at))
-            },
+            |execution_started_at| duration_ms(execution_started_at.duration_since(started_at)),
        );
        let handler_duration_ms = execution_started_at.map_or(Some(0), |execution_started_at| {
            duration_ms(completed_at.duration_since(execution_started_at))
@@ -388,6 +404,14 @@ impl Drop for ToolCallTimingGuard {
                );
            }
        }
+        handler_duration_ms
+    }
+}
+
+impl Drop for ToolCallTimingGuard {
+    fn drop(&mut self) {
+        // Cancellation can drop the outer future before its normal completion path runs.
+        let _ = self.finish();
    }
 }

@@ -434,6 +458,7 @@ mod tests {
                "turn-id",
                &call,
                &ToolCallSource::Direct,
+                /*experimental_show_cell_overhead*/ false,
            );
            assert!(
                direct_guard.is_some(),
@@ -450,6 +475,7 @@ mod tests {
                    cell_id: "cell-1".to_string(),
                    runtime_tool_call_id: "runtime-call-1".to_string(),
                },
+                /*experimental_show_cell_overhead*/ false,
            );
            assert!(
                code_mode_guard.is_none(),
@@ -458,6 +484,38 @@ mod tests {
        });
    }

+    #[test]
+    fn output_timing_works_without_logs_and_excludes_dispatch_waiting() {
+        tracing::subscriber::with_default(tracing::subscriber::NoSubscriber::default(), || {
+            let call = ToolCall {
+                tool_name: codex_tools::ToolName::plain("exec"),
+                call_id: "call-1".to_string(),
+                payload: ToolPayload::Custom {
+                    input: "text('ready')".to_string(),
+                },
+                encrypted_function_args: None,
+            };
+            let started_at = Instant::now() - Duration::from_secs(/*secs*/ 5);
+            let mut timing = ToolCallTimingGuard::capture(
+                started_at,
+                &"conversation-id",
+                "turn-id",
+                &call,
+                &ToolCallSource::Direct,
+                /*experimental_show_cell_overhead*/ true,
+            )
+            .expect("model-visible timing must not depend on INFO logging");
+            timing
+                .execution_started_at
+                .set(started_at + Duration::from_secs(/*secs*/ 4))
+                .expect("execution start is unset");
+            let handler_ms = timing.finish().expect("completed handler duration");
+            assert!(u128::from(handler_ms) <= started_at.elapsed().as_millis() - 4_000);
+            assert!(handler_ms >= 1_000);
+            assert_eq!(timing.finish(), None, "completion is consumed exactly once");
+        });
+    }
+
    #[tokio::test]
    async fn cancellation_before_dispatch_admission_logs_dispatch_only_timing() -> anyhow::Result<()>
    {
@@ -232,6 +232,10 @@ impl ToolOutput for PostToolUseFeedbackOutput {
        self.original.success_for_logging()
    }

+    fn set_handler_duration_ms(&mut self, handler_duration_ms: u64) {
+        self.original.set_handler_duration_ms(handler_duration_ms);
+    }
+
    fn fallback_token_limit_override(&self) -> Option<usize> {
        self.original.fallback_token_limit_override()
    }
@@ -76,6 +76,25 @@ fn lite_tool_catalog_and_code_calls_are_visible() {
    assert!(rendered.contains("04:function_call_output:Wall time: <DURATION> seconds"));
 }

+#[test]
+fn code_mode_timing_normalization_preserves_status_and_user_output() {
+    for status in ["Script completed", "Script failed", "Script terminated"] {
+        let text = format!(
+            "{status}\nWall time 1.000 seconds (code-mode 1.001 seconds; overhead -0.001 seconds)\nOutput:\nWall time 2.0 seconds"
+        );
+        assert_eq!(
+            Normalizer::default().text(
+                &text,
+                TextSource::Other,
+                &ContextSnapshotOptions::default(),
+            ),
+            format!(
+                "{status}\nWall time <DURATION> seconds (code-mode <DURATION> seconds; overhead <DURATION> seconds)\nOutput:\nWall time 2.0 seconds"
+            ),
+        );
+    }
+}
+
 #[test]
 fn tool_outputs_show_only_their_own_names_and_namespaces() {
    let items = [
@@ -109,17 +109,22 @@ impl Normalizer {
    }

    fn normalize_values(&mut self, text: &str) -> String {
-        // Tool calls report elapsed wall time in an otherwise stable output header.
-        let text = if text.starts_with("Script completed\nWall time ")
-            || text.starts_with("Wall time: ")
-        {
+        // Tool calls report elapsed times in an otherwise stable output header.
+        let text = if text.starts_with("Script ") || text.starts_with("Wall time: ") {
            static WALL_TIME: OnceLock<Regex> = OnceLock::new();
            WALL_TIME
                .get_or_init(|| {
-                    Regex::new(r"(?m)^(Wall time:?) [0-9]+(?:\.[0-9]+)? seconds$")
+                    Regex::new(r"(?m)^(Wall time:?) [0-9]+(?:\.[0-9]+)? seconds( \(code-mode [0-9]+(?:\.[0-9]+)? seconds; overhead -?[0-9]+(?:\.[0-9]+)? seconds\))?$")
                        .expect("tool wall time regex")
                })
-                .replace(text, "${1} <DURATION> seconds")
+                .replace(text, |captures: &regex_lite::Captures<'_>| {
+                    let prefix = &captures[1];
+                    if captures.get(2).is_some() {
+                        format!("{prefix} <DURATION> seconds (code-mode <DURATION> seconds; overhead <DURATION> seconds)")
+                    } else {
+                        format!("{prefix} <DURATION> seconds")
+                    }
+                })
                .into_owned()
        } else {
            text.to_string()
@@ -641,6 +641,70 @@ text(`MCP: ${ping.structuredContent?.echo ?? "missing"}`);"#,
    Ok(())
 }

+#[tokio::test(flavor = "multi_thread", worker_threads = 2)]
+async fn astra_reads_code_mode_call_timing() -> Result<()> {
+    skip_if_no_network!(Ok(()));
+    let server = start_mock_server().await;
+    let test = test_codex()
+        .with_model("gpt-6-astra")
+        .with_config(|config| {
+            configure_scenario_catalog(config);
+            // Use the selected cwd as the workspace root on local and remote executors.
+            config.workspace_roots = vec![config.cwd.clone()];
+            config.code_mode.experimental_show_cell_overhead = true;
+            config
+                .features
+                .enable(Feature::CodeMode)
+                .expect("enable code mode");
+            config
+                .features
+                .enable(Feature::CodeModeOnly)
+                .expect("enable code-mode-only tools");
+            config
+                .features
+                .enable(Feature::CodeModeHost)
+                .expect("enable the code-mode host");
+        })
+        .build_with_auto_env(&server)
+        .await?;
+    let mock = mount_sse_sequence(
+        &server,
+        vec![
+            sse(vec![
+                ev_response_created("exec-response"),
+                ev_custom_tool_call("exec-call", "exec", "text('ready');"),
+                ev_completed("exec-response"),
+            ]),
+            sse(vec![
+                ev_response_created("wait-response"),
+                ev_function_call_with_namespace(
+                    "wait-call",
+                    "functions",
+                    "wait",
+                    r#"{"cell_id":"missing"}"#,
+                ),
+                ev_completed("wait-response"),
+            ]),
+            sse(vec![
+                ev_assistant_message("final", "The call completed; the missing-cell wait failed."),
+                ev_completed("final-response"),
+            ]),
+        ],
+    )
+    .await;
+    test.submit_turn("Run a code cell, then inspect its timing and a failed wait.")
+        .await?;
+    insta::assert_snapshot!(
+        "astra_code_mode_call_timing",
+        context_snapshot::format_request_history_snapshot(
+            "Astra receives host and handler timings on completed and failed code-mode calls.",
+            &mock.requests(),
+            &ContextSnapshotOptions::default(),
+        )
+    );
+    Ok(())
+}
+
 #[tokio::test(flavor = "multi_thread", worker_threads = 2)]
 async fn astra_refreshes_plugin_tools_and_skills_in_an_existing_thread() -> Result<()> {
    skip_if_no_network!(Ok(()));
@@ -0,0 +1,108 @@
+---
+source: core/tests/suite/scenarios.rs
+expression: "context_snapshot::format_request_history_snapshot(\"Astra receives host and handler timings on completed and failed code-mode calls.\",\n&mock.requests(), &ContextSnapshotOptions::default(),)"
+---
+Scenario: Astra receives host and handler timings on completed and failed code-mode calls.
+
+## Window 1
+-- request 1 (turn) --
+00:additional_tools/developer (3; hash=9e8e744a3a55a2dd):
+        - namespace/functions; hash=e7db0a45c4ec3157
+          - custom/exec
+          - function/wait
+          - function/request_user_input
+          - function/request_user_input_async
+        - namespace/clock: Tools for reading and waiting on time.; hash=f402e8c5e9b5e317
+          - function/sleep
+        - namespace/collaboration: Tools for spawning and managing sub-agents.; hash=91f6de0e2773854f
+          - function/followup_task
+          - function/interrupt_agent
+          - function/list_agents
+          - function/send_message
+          - function/spawn_agent
+          - function/wait_agent
+01:message/developer:
+    You are Codex, an agent based on GPT-6. You and the user share one workspace, and your job is to collabo...them until their intended goal is completely handled. [hash=efa50f074efa5803]
+
+    # When to ask the user for permission
+
+    Use your best judgement given task context for when you really need user permission, like a competent co...ork without ending the turn to clarify with the user. [hash=ca7367e658b51388]
+
+    User authorization and preferences persist across turns. Do not request permission again when the user h... any guidelines provided in skills or external files. [hash=911f91c92c72882c]
+
+    <OMITTED 155 LINES; ~4895 TOKENS; hash=fd5ef18a80f62502>
+
+    - Skill naming: If a plugin contributes skills, those skill entries are prefixed with plugin_name: in the Skills list.
+    - MCP naming: Plugin-provided MCP tools keep standard MCP identifiers such as mcp__server__tool; use tool provenance to tell which plugin they come from.
+    - Trigger rules: If the user explicitly names a plugin, prefer capabilities associated with that plugin for that turn.
+    - Relationship to capabilities: Plugins are not invoked directly. Use their underlying skills, MCP tools, and app tools to help solve the task.
+    - Relevance: Determine what a plugin can help with from explicit user mention or from the plugin-associa..., MCP tools, and apps exposed elsewhere in this turn. [hash=620459a4e7b590f0]
+    - Missing/blocked: If the user requests a plugin that does not have relevant callable capabilities for t..., say so briefly and continue with the best fallback. [hash=746b0469a8f6cb3e]
+
+02:message/developer[2]:
+    [01] <permissions instructions>
+        Filesystem sandboxing defines which files can be read or written. `sandbox_mode` is `danger-full-access`...ll commands are permitted. Network access is enabled. [hash=c134061cebb94a1b]
+        Approval policy is currently never. Do not provide the `sandbox_permissions` for any reason, commands will be rejected.
+        </permissions instructions>
+    [02] <collaboration_mode># Collaboration Mode: Default
+
+        You are now in Default mode. Any previous instructions for other modes (e.g. Plan mode) are no longer active.
+
+        Your active mode changes only when new developer instructions with a different `<collaboration_mode>...<...by themselves. Known mode names are Default and Plan. [hash=e75f6b12fc52d812]
+
+        ## request_user_input availability
+
+        Use the `request_user_input` tool only when it is listed in the available tools for this turn.
+
+        In Default mode, strongly prefer making reasonable assumptions and executing the user's request rather than stopping to ask questions.
+
+        Use the `request_user_input` tool only for optional questions where the answer would materially improve the quality of the work.
+
+        If `request_user_input` returns no answers, continue with best judgment instead of asking again or treating the turn as blocked.
+
+        Never use the `request_user_input` tool for permission requests or permission-related escalations.
+
+        If explicit user input is required for another reason before progress can safely continue, do not use th... as a textual assistant message.</collaboration_mode> [hash=8213052bde4a62b2]
+03:message/developer:
+    <multi_agent_role>You are `/root`, the primary agent in a team of agents collaborating to fulfill the user's goals.
+
+    At the start of your turn, you are the active agent.
+    You can spawn sub-agents to handle subtasks, and those sub-agents can spawn their own sub-agents.
+    All agents in the team, including the agents that you can assign tasks to, are equally intelligent and capable, and have access to the same set of tools.
+
+    You can use `spawn_agent` to create a new agent, `followup_task` to give an existing agent a new task an...message to a running agent without triggering a turn. [hash=7d40ff8b58977202]
+    `send_message` calls may be read by a human, so ensure they are legible. Always put proper spaces between words and/or numbers.
+    <OMITTED 17 LINES; ~246 TOKENS; hash=780031e2df907944>
+    - All agents use the same current working directory.
+    - As a result, edits made by one agent are immediately visible to all other agents.
+
+    When calling `wait_agent`, prefer longer waits (minutes) to avoid busy polling.
+
+    There are 4 available concurrency slots, meaning that up to 4 agents can be active at once, including you.
+
+    Full-history forks (`fork_turns` omitted or `"all"`) inherit the parent model and reasoning effort and d...ne"` or a positive integer string.</multi_agent_role> [hash=c7f52e90688299ce]
+04:message/developer:
+    <multi_agent_mode>Any earlier instruction enabling proactive multi-agent delegation no longer applies. D...elegation, or parallel agent work.</multi_agent_mode> [hash=2b6e037067b4390c]
+05:message/user:
+    <environment_context>
+      <cwd><CWD></cwd>
+      <shell><HOST_SHELL></shell>
+      <current_date><CURRENT_DATE></current_date>
+      <timezone><HOST_TIMEZONE></timezone>
+      <filesystem><workspace_roots><root><CWD></root></workspace_roots><permission_profile type="disabled"><...e="unrestricted" /></permission_profile></filesystem> [hash=d40b2f45cb028888]
+    </environment_context>
+06:message/user:
+    Run a code cell, then inspect its timing and a failed wait.
+-- request 2 (turn) --
+07:custom_tool_call/exec:text('ready');
+08:custom_tool_call_output:Script completed
+    Wall time <DURATION> seconds (code-mode <DURATION> seconds; overhead <DURATION> seconds)
+    Output:
+     | ready
+-- request 3 (turn) --
+09:function_call/functions.wait:{"cell_id":"missing"}
+10:function_call_output:Script failed
+    Wall time <DURATION> seconds (code-mode <DURATION> seconds; overhead <DURATION> seconds)
+    Output:
+     | Script error:
+    exec cell missing not found
@@ -26,6 +26,11 @@ pub struct CodeModeConfigToml {
    /// Default yield timeout for code-mode exec calls, in milliseconds.
    #[serde(skip_serializing_if = "Option::is_none")]
    pub default_exec_yield_time_ms: Option<u64>,
+    /// Show handler duration, code-mode host duration, and harness overhead
+    /// in each code-mode cell response.
+    /// Experimental: this option and the response format may change or be removed.
+    #[serde(skip_serializing_if = "Option::is_none")]
+    pub experimental_show_cell_overhead: Option<bool>,
    /// Exact tool namespaces to omit from the code-mode nested tool surface.
    #[serde(skip_serializing_if = "Option::is_none")]
    pub excluded_tool_namespaces: Option<Vec<String>>,
@@ -18,6 +18,10 @@ pub trait ToolOutput: Send {

    fn success_for_logging(&self) -> bool;

+    /// Finalizes output using the same completed handler duration reported in tool-call logs.
+    /// Called before recording model-visible history; implementations must not measure time here.
+    fn set_handler_duration_ms(&mut self, _handler_duration_ms: u64) {}
+
    /// Whether this output contains external context that should disable memory generation when
    /// `memories.disable_on_external_context` is enabled.
    fn contains_external_context(&self) -> bool {
@@ -75,6 +79,10 @@ where
        (**self).success_for_logging()
    }

+    fn set_handler_duration_ms(&mut self, handler_duration_ms: u64) {
+        (**self).set_handler_duration_ms(handler_duration_ms);
+    }
+
    fn contains_external_context(&self) -> bool {
        (**self).contains_external_context()
    }