openai · copyberry · Jul 10, 2026 · Jul 10, 2026
diff --git a/codex-rs/codex-api/src/endpoint/responses_websocket.rs b/codex-rs/codex-api/src/endpoint/responses_websocket.rs
@@ -3,6 +3,7 @@ use crate::common::ResponseEvent;
 use crate::common::ResponseStream;
 use crate::common::ResponsesWsRequest;
 use crate::common::SafetyBufferingTreatment;
+use crate::common::WS_REQUEST_HEADER_TRACEPARENT_CLIENT_METADATA_KEY;
 use crate::error::ApiError;
 use crate::provider::Provider;
 use crate::rate_limits::parse_rate_limit_event;
@@ -156,6 +157,24 @@ const X_REASONING_INCLUDED_HEADER: &str = "x-reasoning-included";
 const OPENAI_MODEL_HEADER: &str = "openai-model";
 const WEBSOCKET_CONNECTION_LIMIT_REACHED_CODE: &str = "websocket_connection_limit_reached";
 const WEBSOCKET_CONNECTION_LIMIT_REACHED_MESSAGE: &str = "Responses websocket connection limit reached (60 minutes). Create a new websocket connection to continue.";
+const RESPONSES_WEBSOCKET_TIMING_KIND: &str = "responsesapi.websocket_timing";
+const RESPONSES_WEBSOCKET_TIMING_EVENT_TARGET: &str = "codex_api::responses_websocket_timing";
+const SESSION_ID_CLIENT_METADATA_KEY: &str = "session_id";
+const THREAD_ID_CLIENT_METADATA_KEY: &str = "thread_id";
+const TURN_ID_CLIENT_METADATA_KEY: &str = "turn_id";
+const WS_STREAM_REQUEST_START_MS_CLIENT_METADATA_KEY: &str = "x-codex-ws-stream-request-start-ms";
+
+struct ResponsesWebsocketTimingLogContext {
+    model: String,
+    session_id: Option<String>,
+    thread_id: Option<String>,
+    turn_id: Option<String>,
+    traceparent: Option<String>,
+    previous_response_id: Option<String>,
+    request_start_ms: Option<String>,
+    warmup: bool,
+    connection_reused: bool,
+}
 
 pub struct ResponsesWebsocketConnection {
     stream: Arc<Mutex<Option<WsStream>>>,
@@ -223,6 +242,31 @@ impl ResponsesWebsocketConnection {
         let models_etag = self.models_etag.clone();
         let server_model = self.server_model.clone();
         let telemetry = self.telemetry.clone();
+        let ResponsesWsRequest::ResponseCreate(ws_request) = &request;
+        let client_metadata = ws_request.client_metadata.as_ref();
+        let timing_log_context = ResponsesWebsocketTimingLogContext {
+            model: ws_request.model.clone(),
+            session_id: client_metadata
+                .and_then(|metadata| metadata.get(SESSION_ID_CLIENT_METADATA_KEY))
+                .cloned(),
+            thread_id: client_metadata
+                .and_then(|metadata| metadata.get(THREAD_ID_CLIENT_METADATA_KEY))
+                .cloned(),
+            turn_id: client_metadata
+                .and_then(|metadata| metadata.get(TURN_ID_CLIENT_METADATA_KEY))
+                .cloned(),
+            traceparent: client_metadata
+                .and_then(|metadata| {
+                    metadata.get(WS_REQUEST_HEADER_TRACEPARENT_CLIENT_METADATA_KEY)
+                })
+                .cloned(),
+            previous_response_id: ws_request.previous_response_id.clone(),
+            request_start_ms: client_metadata
+                .and_then(|metadata| metadata.get(WS_STREAM_REQUEST_START_MS_CLIENT_METADATA_KEY))
+                .cloned(),
+            warmup: ws_request.generate == Some(false),
+            connection_reused,
+        };
         let request_text = serialize_websocket_request(&request)?;
 
         let current_span = Span::current();
@@ -260,8 +304,8 @@ impl ResponsesWebsocketConnection {
                         request_text,
                         idle_timeout,
                         telemetry,
-                        connection_reused,
                         turn_state.as_deref(),
+                        &timing_log_context,
                     )
                     .await
                 };
@@ -625,8 +669,8 @@ async fn run_websocket_response_stream(
     request_text: String,
     idle_timeout: Duration,
     telemetry: Option<Arc<dyn WebsocketTelemetry>>,
-    connection_reused: bool,
     turn_state: Option<&OnceLock<String>>,
+    timing_log_context: &ResponsesWebsocketTimingLogContext,
 ) -> Result<(), ApiError> {
     let mut last_server_model: Option<String> = None;
     let mut safety_buffering_treatment = SafetyBufferingTreatment::default();
@@ -635,7 +679,7 @@ async fn run_websocket_response_stream(
         request_text,
         idle_timeout,
         telemetry.as_ref(),
-        connection_reused,
+        timing_log_context.connection_reused,
     )
     .await?;
 
@@ -678,6 +722,11 @@ async fn run_websocket_response_stream(
                         continue;
                     }
                 };
+                emit_responses_websocket_timing_event(
+                    event.kind(),
+                    text.as_str(),
+                    timing_log_context,
+                );
                 if let Some(response_turn_state) = event.turn_state()
                     && let Some(turn_state) = turn_state
                 {
@@ -761,6 +810,35 @@ async fn run_websocket_response_stream(
     Ok(())
 }
 
+fn emit_responses_websocket_timing_event(
+    kind: &str,
+    payload: &str,
+    context: &ResponsesWebsocketTimingLogContext,
+) {
+    if kind != RESPONSES_WEBSOCKET_TIMING_KIND {
+        return;
+    }
+
+    // This full payload is excluded from always-on sinks. Opt in with
+    // `RUST_LOG='codex_api::responses_websocket_timing=trace'`.
+    tracing::event!(
+        name: RESPONSES_WEBSOCKET_TIMING_KIND,
+        target: RESPONSES_WEBSOCKET_TIMING_EVENT_TARGET,
+        tracing::Level::TRACE,
+        model = context.model.as_str(),
+        session_id = context.session_id.as_deref().unwrap_or_default(),
+        thread_id = context.thread_id.as_deref().unwrap_or_default(),
+        turn_id = context.turn_id.as_deref().unwrap_or_default(),
+        traceparent = context.traceparent.as_deref().unwrap_or_default(),
+        previous_response_id = context.previous_response_id.as_deref().unwrap_or_default(),
+        request_start_ms = context.request_start_ms.as_deref().unwrap_or_default(),
+        warmup = context.warmup,
+        connection_reused = context.connection_reused,
+        payload,
+        "responses websocket timing"
+    );
+}
+
 fn safety_buffering_for_event(
     event: &ResponsesStreamEvent,
     treatment: &mut SafetyBufferingTreatment,

diff --git a/codex-rs/core/tests/suite/client_websockets.rs b/codex-rs/core/tests/suite/client_websockets.rs
@@ -1236,8 +1236,8 @@ async fn responses_websocket_includes_timing_metrics_header_when_runtime_metrics
     assert_eq!(summary.responses_api_inference_time_ms, 450);
     assert_eq!(summary.responses_api_engine_iapi_ttft_ms, 310);
     assert_eq!(summary.responses_api_engine_service_ttft_ms, 340);
-    assert_eq!(summary.responses_api_engine_iapi_tbt_ms, 220);
-    assert_eq!(summary.responses_api_engine_service_tbt_ms, 260);
+    assert_eq!(summary.responses_api_engine_iapi_tbt_ms, 220.0);
+    assert_eq!(summary.responses_api_engine_service_tbt_ms, 260.0);
 
     server.shutdown().await;
 }

diff --git a/codex-rs/feedback/src/lib.rs b/codex-rs/feedback/src/lib.rs
@@ -18,6 +18,7 @@ use codex_protocol::protocol::SessionSource;
 use tracing::Event;
 use tracing::Level;
 use tracing::field::Visit;
+use tracing::level_filters::LevelFilter;
 use tracing_subscriber::Layer;
 use tracing_subscriber::filter::Targets;
 use tracing_subscriber::fmt::writer::MakeWriter;
@@ -205,7 +206,11 @@ impl CodexFeedback {
             .with_target(false)
             // Capture everything, regardless of the caller's `RUST_LOG`, so feedback includes the
             // full trace when the user uploads a report.
-            .with_filter(Targets::new().with_default(Level::TRACE))
+            .with_filter(
+                Targets::new()
+                    .with_default(Level::TRACE)
+                    .with_target("codex_api::responses_websocket_timing", LevelFilter::OFF),
+            )
     }
 
     /// Returns a [`tracing_subscriber`] layer that collects structured metadata for feedback.
@@ -722,6 +727,21 @@ mod tests {
         pretty_assertions::assert_eq!(std::str::from_utf8(snap.as_bytes()).unwrap(), "cdefghij");
     }
 
+    #[test]
+    fn logger_layer_excludes_responses_websocket_timing_payloads() {
+        let fb = CodexFeedback::new();
+        let _guard = tracing_subscriber::registry()
+            .with(fb.logger_layer())
+            .set_default();
+
+        tracing::trace!(target: "codex_api::responses_websocket_timing", payload = "secret");
+        tracing::trace!(target: "codex_feedback_test", "retained");
+
+        let logs = String::from_utf8(fb.snapshot(/*session_id*/ None).bytes).unwrap();
+        assert!(!logs.contains("secret"));
+        assert!(logs.contains("retained"));
+    }
+
     #[test]
     fn metadata_layer_records_tags_from_feedback_target() {
         let fb = CodexFeedback::new();

diff --git a/codex-rs/otel/src/events/session_telemetry.rs b/codex-rs/otel/src/events/session_telemetry.rs
@@ -205,6 +205,21 @@ impl SessionTelemetry {
         }
     }
 
+    fn record_duration_ms_f64(&self, name: &str, duration_ms: f64, tags: &[(&str, &str)]) {
+        let res: MetricsResult<()> = (|| {
+            let Some(metrics) = &self.metrics else {
+                return Ok(());
+            };
+
+            let tags = self.tags_with_metadata(tags)?;
+            metrics.record_duration_ms_f64(name, duration_ms, &tags)
+        })();
+
+        if let Err(e) = res {
+            tracing::warn!("metrics duration [{name}] failed: {e}");
+        }
+    }
+
     /// Records a coarse startup phase for production latency breakdowns.
     pub fn record_startup_phase(
         &self,
@@ -1170,16 +1185,20 @@ impl SessionTelemetry {
 
         let engine_iapi_tbt_value =
             timing_metrics.and_then(|value| value.get(RESPONSES_API_ENGINE_IAPI_TBT_FIELD));
-        if let Some(duration) = duration_from_ms_value(engine_iapi_tbt_value) {
-            self.record_duration(RESPONSES_API_ENGINE_IAPI_TBT_DURATION_METRIC, duration, &[]);
+        if let Some(duration_ms) = f64_ms_value(engine_iapi_tbt_value) {
+            self.record_duration_ms_f64(
+                RESPONSES_API_ENGINE_IAPI_TBT_DURATION_METRIC,
+                duration_ms,
+                &[],
+            );
         }
 
         let engine_service_tbt_value =
             timing_metrics.and_then(|value| value.get(RESPONSES_API_ENGINE_SERVICE_TBT_FIELD));
-        if let Some(duration) = duration_from_ms_value(engine_service_tbt_value) {
-            self.record_duration(
+        if let Some(duration_ms) = f64_ms_value(engine_service_tbt_value) {
+            self.record_duration_ms_f64(
                 RESPONSES_API_ENGINE_SERVICE_TBT_DURATION_METRIC,
-                duration,
+                duration_ms,
                 &[],
             );
         }
@@ -1234,6 +1253,11 @@ impl SessionTelemetry {
 }
 
 fn duration_from_ms_value(value: Option<&serde_json::Value>) -> Option<Duration> {
+    let ms = f64_ms_value(value)?;
+    Some(Duration::from_millis(ms.round() as u64))
+}
+
+fn f64_ms_value(value: Option<&serde_json::Value>) -> Option<f64> {
     let value = value?;
     let ms = value
         .as_f64()
@@ -1242,6 +1266,5 @@ fn duration_from_ms_value(value: Option<&serde_json::Value>) -> Option<Duration>
     if !ms.is_finite() || ms < 0.0 {
         return None;
     }
-    let clamped = ms.min(u64::MAX as f64);
-    Some(Duration::from_millis(clamped.round() as u64))
+    Some(ms.min(u64::MAX as f64))
 }
diff --git a/codex-rs/otel/src/metrics/client.rs b/codex-rs/otel/src/metrics/client.rs
@@ -401,6 +401,23 @@ impl MetricsClient {
         )
     }
 
+    /// Record a duration supplied as fractional milliseconds using a histogram.
+    pub(crate) fn record_duration_ms_f64(
+        &self,
+        name: &str,
+        duration_ms: f64,
+        tags: &[(&str, &str)],
+    ) -> Result<()> {
+        self.0.duration_histogram(
+            name,
+            duration_ms,
+            MILLISECOND_DURATION_UNIT,
+            MILLISECOND_DURATION_DESCRIPTION,
+            MILLISECOND_DURATION_BOUNDARIES,
+            tags,
+        )
+    }
+
     /// Record a duration in seconds using a histogram with an instrument description.
     pub fn record_duration_seconds_with_description(
         &self,

diff --git a/codex-rs/otel/src/metrics/runtime_metrics.rs b/codex-rs/otel/src/metrics/runtime_metrics.rs
@@ -38,7 +38,7 @@ impl RuntimeMetricTotals {
     }
 }
 
-#[derive(Debug, Clone, Copy, Default, PartialEq, Eq)]
+#[derive(Debug, Clone, Copy, Default, PartialEq)]
 pub struct RuntimeMetricsSummary {
     pub tool_calls: RuntimeMetricTotals,
     pub api_calls: RuntimeMetricTotals,
@@ -49,8 +49,8 @@ pub struct RuntimeMetricsSummary {
     pub responses_api_inference_time_ms: u64,
     pub responses_api_engine_iapi_ttft_ms: u64,
     pub responses_api_engine_service_ttft_ms: u64,
-    pub responses_api_engine_iapi_tbt_ms: u64,
-    pub responses_api_engine_service_tbt_ms: u64,
+    pub responses_api_engine_iapi_tbt_ms: f64,
+    pub responses_api_engine_service_tbt_ms: f64,
     pub turn_ttft_ms: u64,
     pub turn_ttfm_ms: u64,
 }
@@ -66,8 +66,8 @@ impl RuntimeMetricsSummary {
             && self.responses_api_inference_time_ms == 0
             && self.responses_api_engine_iapi_ttft_ms == 0
             && self.responses_api_engine_service_ttft_ms == 0
-            && self.responses_api_engine_iapi_tbt_ms == 0
-            && self.responses_api_engine_service_tbt_ms == 0
+            && self.responses_api_engine_iapi_tbt_ms == 0.0
+            && self.responses_api_engine_service_tbt_ms == 0.0
             && self.turn_ttft_ms == 0
             && self.turn_ttfm_ms == 0
     }
@@ -90,10 +90,10 @@ impl RuntimeMetricsSummary {
         if other.responses_api_engine_service_ttft_ms > 0 {
             self.responses_api_engine_service_ttft_ms = other.responses_api_engine_service_ttft_ms;
         }
-        if other.responses_api_engine_iapi_tbt_ms > 0 {
+        if other.responses_api_engine_iapi_tbt_ms > 0.0 {
             self.responses_api_engine_iapi_tbt_ms = other.responses_api_engine_iapi_tbt_ms;
         }
-        if other.responses_api_engine_service_tbt_ms > 0 {
+        if other.responses_api_engine_service_tbt_ms > 0.0 {
             self.responses_api_engine_service_tbt_ms = other.responses_api_engine_service_tbt_ms;
         }
         if other.turn_ttft_ms > 0 {
@@ -146,9 +146,9 @@ impl RuntimeMetricsSummary {
         let responses_api_engine_service_ttft_ms =
             sum_histogram_ms(snapshot, RESPONSES_API_ENGINE_SERVICE_TTFT_DURATION_METRIC);
         let responses_api_engine_iapi_tbt_ms =
-            sum_histogram_ms(snapshot, RESPONSES_API_ENGINE_IAPI_TBT_DURATION_METRIC);
+            sum_histogram_f64(snapshot, RESPONSES_API_ENGINE_IAPI_TBT_DURATION_METRIC);
         let responses_api_engine_service_tbt_ms =
-            sum_histogram_ms(snapshot, RESPONSES_API_ENGINE_SERVICE_TBT_DURATION_METRIC);
+            sum_histogram_f64(snapshot, RESPONSES_API_ENGINE_SERVICE_TBT_DURATION_METRIC);
         let turn_ttft_ms = sum_histogram_ms(snapshot, TURN_TTFT_DURATION_METRIC);
         let turn_ttfm_ms = sum_histogram_ms(snapshot, TURN_TTFM_DURATION_METRIC);
         Self {
@@ -189,21 +189,25 @@ fn sum_counter_metric(metric: &Metric) -> u64 {
 }
 
 fn sum_histogram_ms(snapshot: &ResourceMetrics, name: &str) -> u64 {
+    f64_to_u64(sum_histogram_f64(snapshot, name))
+}
+
+fn sum_histogram_f64(snapshot: &ResourceMetrics, name: &str) -> f64 {
     snapshot
         .scope_metrics()
         .flat_map(opentelemetry_sdk::metrics::data::ScopeMetrics::metrics)
         .filter(|metric| metric.name() == name)
-        .map(sum_histogram_metric_ms)
+        .map(sum_histogram_metric)
         .sum()
 }
 
-fn sum_histogram_metric_ms(metric: &Metric) -> u64 {
+fn sum_histogram_metric(metric: &Metric) -> f64 {
     match metric.data() {
         AggregatedMetrics::F64(MetricData::Histogram(histogram)) => histogram
             .data_points()
-            .map(|point| f64_to_u64(point.sum()))
+            .map(opentelemetry_sdk::metrics::data::HistogramDataPoint::sum)
             .sum(),
-        _ => 0,
+        _ => 0.0,
     }
 }
 

diff --git a/codex-rs/otel/tests/suite/runtime_summary.rs b/codex-rs/otel/tests/suite/runtime_summary.rs
@@ -90,7 +90,7 @@ fn runtime_metrics_summary_collects_tool_api_and_streaming_metrics() -> Result<(
         Option<std::result::Result<Message, tokio_tungstenite::tungstenite::Error>>,
         codex_api::ApiError,
     > = Ok(Some(Ok(Message::Text(
-        r#"{"type":"responsesapi.websocket_timing","timing_metrics":{"responses_duration_excl_engine_and_client_tool_time_ms":124,"engine_service_total_ms":457,"engine_iapi_ttft_total_ms":211,"engine_service_ttft_total_ms":233,"engine_iapi_tbt_across_engine_calls_ms":377,"engine_service_tbt_across_engine_calls_ms":399}}"#
+        r#"{"type":"responsesapi.websocket_timing","timing_metrics":{"responses_duration_excl_engine_and_client_tool_time_ms":124.25,"engine_service_total_ms":457,"engine_iapi_ttft_total_ms":211,"engine_service_ttft_total_ms":233,"engine_iapi_tbt_across_engine_calls_ms":2.450638,"engine_service_tbt_across_engine_calls_ms":5.267279}}"#
             .into(),
     ))));
     manager.record_websocket_event(&ws_timing_response, Duration::from_millis(20));
@@ -133,8 +133,8 @@ fn runtime_metrics_summary_collects_tool_api_and_streaming_metrics() -> Result<(
         responses_api_inference_time_ms: 457,
         responses_api_engine_iapi_ttft_ms: 211,
         responses_api_engine_service_ttft_ms: 233,
-        responses_api_engine_iapi_tbt_ms: 377,
-        responses_api_engine_service_tbt_ms: 399,
+        responses_api_engine_iapi_tbt_ms: 2.450638,
+        responses_api_engine_service_tbt_ms: 5.267279,
         turn_ttft_ms: 95,
         turn_ttfm_ms: 180,
     };