diff --git a/codex-rs/codex-api/src/endpoint/responses_websocket.rs b/codex-rs/codex-api/src/endpoint/responses_websocket.rs index 88e7fbb9b4e0..2eeb91bd6667 100644 --- 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, + thread_id: Option, + turn_id: Option, + traceparent: Option, + previous_response_id: Option, + request_start_ms: Option, + warmup: bool, + connection_reused: bool, +} pub struct ResponsesWebsocketConnection { stream: Arc>>, @@ -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>, - connection_reused: bool, turn_state: Option<&OnceLock>, + timing_log_context: &ResponsesWebsocketTimingLogContext, ) -> Result<(), ApiError> { let mut last_server_model: Option = 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 index b993ec83cda3..114c24d2c1fc 100755 --- 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 index cd97349c4816..a8864690bde3 100644 --- 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 index c470f8dc7cc7..6d7afb72e319 100644 --- 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 { + let ms = f64_ms_value(value)?; + Some(Duration::from_millis(ms.round() as u64)) +} + +fn f64_ms_value(value: Option<&serde_json::Value>) -> Option { let value = value?; let ms = value .as_f64() @@ -1242,6 +1266,5 @@ fn duration_from_ms_value(value: Option<&serde_json::Value>) -> Option 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 index 251fc74d77c5..d3c7e0d70991 100644 --- 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 index 93f457a61cc6..a18e66d0bf1d 100644 --- 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 index b77e4557ae91..f4914fd98df1 100644 --- 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>, 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, }; diff --git a/codex-rs/otel/tests/suite/timing.rs b/codex-rs/otel/tests/suite/timing.rs index 72156b526990..02259b6c72b6 100644 --- a/codex-rs/otel/tests/suite/timing.rs +++ b/codex-rs/otel/tests/suite/timing.rs @@ -33,6 +33,21 @@ fn record_duration_records_histogram() -> Result<()> { Ok(()) } +#[test] +fn record_duration_keeps_whole_millisecond_behavior() -> Result<()> { + let (metrics, exporter) = build_metrics_with_defaults(&[])?; + + metrics.record_duration("codex.request_latency", Duration::from_micros(15_999), &[])?; + metrics.shutdown()?; + + let resource_metrics = latest_metrics(&exporter); + let (_, _, sum, count) = histogram_data(&resource_metrics, "codex.request_latency"); + assert_eq!(sum, 15.0); + assert_eq!(count, 1); + + Ok(()) +} + #[test] fn record_duration_seconds_uses_fractional_seconds_and_scaled_buckets() -> Result<()> { let (metrics, exporter) = build_metrics_with_defaults(&[])?; diff --git a/codex-rs/state/src/log_db.rs b/codex-rs/state/src/log_db.rs index 01c8ac395140..e24afb2b3e76 100644 --- a/codex-rs/state/src/log_db.rs +++ b/codex-rs/state/src/log_db.rs @@ -58,6 +58,7 @@ pub fn default_filter() -> Targets { .with_target("codex_otel.log_only", LevelFilter::OFF) .with_target("codex_otel.trace_safe", LevelFilter::OFF) .with_target("rmcp::service", LevelFilter::INFO) + .with_target("codex_api::responses_websocket_timing", LevelFilter::OFF) } #[derive(Clone, Copy, Debug, Eq, PartialEq)] diff --git a/codex-rs/state/src/log_db_filter_tests.rs b/codex-rs/state/src/log_db_filter_tests.rs index 36ee27aba8a1..6c6380d33472 100644 --- a/codex-rs/state/src/log_db_filter_tests.rs +++ b/codex-rs/state/src/log_db_filter_tests.rs @@ -1,5 +1,4 @@ use pretty_assertions::assert_eq; -use tracing_subscriber::filter::Targets; use tracing_subscriber::layer::SubscriberExt; use tracing_subscriber::util::SubscriberInitExt; use uuid::Uuid; @@ -16,17 +15,18 @@ async fn sqlite_sink_drops_low_level_opentelemetry_sdk_logs() { let layer = start(runtime.clone()); let guard = tracing_subscriber::registry() - .with( - layer - .clone() - .with_filter(Targets::new().with_default(tracing::Level::TRACE)), - ) + .with(layer.clone().with_filter(default_filter())) .set_default(); tracing::trace!(target: "opentelemetry_sdk", "dropped-trace"); tracing::debug!(target: "opentelemetry_sdk", "dropped-debug"); tracing::info!(target: "opentelemetry_sdk", "retained-info"); tracing::trace!(target: "codex_state", "retained-trace"); + tracing::trace!( + target: "codex_api::responses_websocket_timing", + payload = "complete timing payload", + "dropped-websocket-timing" + ); layer.flush().await; drop(guard); diff --git a/codex-rs/tui/src/chatwidget.rs b/codex-rs/tui/src/chatwidget.rs index 0775daa5d5a0..71d42b8fb25f 100644 --- a/codex-rs/tui/src/chatwidget.rs +++ b/codex-rs/tui/src/chatwidget.rs @@ -2013,8 +2013,8 @@ fn has_websocket_timing_metrics(summary: RuntimeMetricsSummary) -> bool { || summary.responses_api_inference_time_ms > 0 || summary.responses_api_engine_iapi_ttft_ms > 0 || summary.responses_api_engine_service_ttft_ms > 0 - || summary.responses_api_engine_iapi_tbt_ms > 0 - || summary.responses_api_engine_service_tbt_ms > 0 + || summary.responses_api_engine_iapi_tbt_ms > 0.0 + || summary.responses_api_engine_service_tbt_ms > 0.0 } impl Drop for ChatWidget { diff --git a/codex-rs/tui/src/chatwidget/tests/status_and_layout.rs b/codex-rs/tui/src/chatwidget/tests/status_and_layout.rs index 22f7c828a6db..fe17933f52ee 100644 --- a/codex-rs/tui/src/chatwidget/tests/status_and_layout.rs +++ b/codex-rs/tui/src/chatwidget/tests/status_and_layout.rs @@ -3156,7 +3156,7 @@ async fn runtime_metrics_websocket_timing_logs_and_final_separator_sums_totals() chat.on_task_started(); chat.apply_runtime_metrics_delta(RuntimeMetricsSummary { responses_api_engine_iapi_ttft_ms: 120, - responses_api_engine_service_tbt_ms: 50, + responses_api_engine_service_tbt_ms: 50.0, ..RuntimeMetricsSummary::default() }); diff --git a/codex-rs/tui/src/history_cell/separators.rs b/codex-rs/tui/src/history_cell/separators.rs index 0a746806387f..1eced782cea6 100644 --- a/codex-rs/tui/src/history_cell/separators.rs +++ b/codex-rs/tui/src/history_cell/separators.rs @@ -136,16 +136,18 @@ pub(crate) fn runtime_metrics_label(summary: RuntimeMetricsSummary) -> Option 0 - || summary.responses_api_engine_service_tbt_ms > 0 + if summary.responses_api_engine_iapi_tbt_ms > 0.0 + || summary.responses_api_engine_service_tbt_ms > 0.0 { let mut tbt_parts = Vec::new(); - if summary.responses_api_engine_iapi_tbt_ms > 0 { - let duration = format_duration_ms(summary.responses_api_engine_iapi_tbt_ms); + if summary.responses_api_engine_iapi_tbt_ms > 0.0 { + let duration = + format_duration_ms(summary.responses_api_engine_iapi_tbt_ms.round() as u64); tbt_parts.push(format!("{duration} (iapi)")); } - if summary.responses_api_engine_service_tbt_ms > 0 { - let duration = format_duration_ms(summary.responses_api_engine_service_tbt_ms); + if summary.responses_api_engine_service_tbt_ms > 0.0 { + let duration = + format_duration_ms(summary.responses_api_engine_service_tbt_ms.round() as u64); tbt_parts.push(format!("{duration} (service)")); } parts.push(format!("TBT: {}", tbt_parts.join(" "))); diff --git a/codex-rs/tui/src/history_cell/tests.rs b/codex-rs/tui/src/history_cell/tests.rs index e8e786fde1cb..c7a4ca801f05 100644 --- a/codex-rs/tui/src/history_cell/tests.rs +++ b/codex-rs/tui/src/history_cell/tests.rs @@ -564,8 +564,8 @@ fn final_message_separator_hides_short_worked_label_and_includes_runtime_metrics responses_api_inference_time_ms: 1_940, responses_api_engine_iapi_ttft_ms: 410, responses_api_engine_service_ttft_ms: 460, - responses_api_engine_iapi_tbt_ms: 1_180, - responses_api_engine_service_tbt_ms: 1_240, + responses_api_engine_iapi_tbt_ms: 1_180.0, + responses_api_engine_service_tbt_ms: 1_240.0, turn_ttft_ms: 0, turn_ttfm_ms: 0, }; @@ -585,6 +585,17 @@ fn final_message_separator_hides_short_worked_label_and_includes_runtime_metrics assert!(rendered[0].contains("TBT: 1.2s (iapi) 1.2s (service)")); } +#[test] +fn runtime_metrics_label_rounds_fractional_tbt_milliseconds() { + let summary = RuntimeMetricsSummary { + responses_api_engine_iapi_tbt_ms: 2.450638, + responses_api_engine_service_tbt_ms: 5.267279, + ..RuntimeMetricsSummary::default() + }; + + insta::assert_snapshot!(runtime_metrics_label(summary).expect("TBT label"), @"TBT: 2ms (iapi) 5ms (service)"); +} + #[test] fn final_message_separator_includes_worked_label_after_one_minute() { let cell = FinalMessageSeparator::new(Some(61), /*runtime_metrics*/ None);