openai/codex
1
0
Fork 0
mirror of https://github.com/openai/codex.git synced 2026-10-21 17:48:44 +00:00
Code Issues Packages Projects Releases Wiki Activity

Report code mode host request durations (#41452)

Browse Source 
## Why

Code mode wall time should measure the host operation itself, without including
client-side response delays or idle time between requests.

## What changed

- Measure each execute, wait, and terminate request in the code mode host.
- Carry the duration through the stdio and gRPC protocols and use it for
  model-visible wall time.
- Emit a structured `codex.code_mode.host_timing` event correlated with the
  conversation, turn, tool call, and cell.

## Testing

- Cover successful and failed execution timing, delayed response reads,
  repeated waits, termination, and missing cells across stdio and gRPC.
- Verify timing survives protocol serialization and is reflected in app-server
  model output and structured telemetry.

GitOrigin-RevId: d24af30c3fc5820521b4beba1f9970714dad6482
This commit is contained in:
Adam Perry @ OpenAI
2026-08-29 02:52:58 +00:00
committed by copyberry
parent 75388bf321
commit 48e22a5fa0
34 changed files with 1398 additions and 259 deletions
Download Patch File Download Diff File Expand all files Collapse all files
codex-rs/code-mode/src/grpc_session/conversion.rs
+15 -8
View File
@@ -1,3 +1,5 @@
use std::time::Duration;
use codex_code_mode_protocol::CellId;
use codex_code_mode_protocol::CodeModeNestedToolCall;
use codex_code_mode_protocol::CodeModeToolKind;
@@ -89,6 +91,7 @@ pub(super) fn tool_call(call: grpc::ToolCall) -> Result<CodeModeNestedToolCall,
}
pub(super) fn runtime_response(outcome: grpc::ExecutionOutcome) -> Result<RuntimeResponse, String> {
let code_mode_host_duration = Some(Duration::from_nanos(outcome.code_mode_host_duration_ns));
super::validate_identifier(&outcome.cell_id, "cell ID")?;
let cell_id = CellId::new(outcome.cell_id);
let content_items = outcome
@@ -96,24 +99,28 @@ pub(super) fn runtime_response(outcome: grpc::ExecutionOutcome) -> Result<Runtim
.into_iter()
.map(content_item)
.collect::<Result<Vec<_>, _>>()?;
match outcome
let response = match outcome
.outcome
.ok_or_else(|| "code-mode execution omitted its outcome".to_string())?
{
grpc::execution_outcome::Outcome::Yielded(_) => Ok(RuntimeResponse::Yielded {
grpc::execution_outcome::Outcome::Yielded(_) => RuntimeResponse::Yielded {
cell_id,
content_items,
}),
grpc::execution_outcome::Outcome::Terminated(_) => Ok(RuntimeResponse::Terminated {
code_mode_host_duration,
},
grpc::execution_outcome::Outcome::Terminated(_) => RuntimeResponse::Terminated {
cell_id,
content_items,
}),
grpc::execution_outcome::Outcome::Completed(completed) => Ok(RuntimeResponse::Result {
code_mode_host_duration,
},
grpc::execution_outcome::Outcome::Completed(completed) => RuntimeResponse::Result {
cell_id,
content_items,
error_text: completed.error_text,
}),
}
code_mode_host_duration,
},
};
Ok(response)
}
pub(super) fn wait_outcome(response: grpc::WaitResponse) -> Result<WaitOutcome, String> {
codex-rs/code-mode/src/grpc_session/conversion_tests.rs
+35
View File
@@ -11,6 +11,7 @@ use codex_code_mode_protocol::grpc;
use codex_protocol::ToolName;
use pretty_assertions::assert_eq;
use serde_json::json;
use std::time::Duration;
use super::execute_request;
use super::runtime_response;
@@ -91,6 +92,7 @@ fn tool_call_decodes_structured_input_and_namespace() {
#[test]
fn runtime_response_decodes_mixed_content_items() {
let outcome = grpc::ExecutionOutcome {
code_mode_host_duration_ns: 0,
cell_id: "cell".to_string(),
content_items: vec![
grpc::ContentItem {
@@ -120,6 +122,7 @@ fn runtime_response_decodes_mixed_content_items() {
assert_eq!(
runtime_response(outcome),
Ok(RuntimeResponse::Result {
code_mode_host_duration: Some(Duration::ZERO),
cell_id: CellId::new("cell".to_string()),
content_items: vec![
FunctionCallOutputContentItem::InputText {
@@ -143,6 +146,7 @@ fn wait_outcome_preserves_missing_cell_state() {
let response = grpc::WaitResponse {
state: Some(grpc::wait_response::State::MissingCell(
grpc::ExecutionOutcome {
code_mode_host_duration_ns: 0,
cell_id: "missing".to_string(),
content_items: Vec::new(),
outcome: Some(grpc::execution_outcome::Outcome::Terminated(
@@ -155,6 +159,7 @@ fn wait_outcome_preserves_missing_cell_state() {
assert_eq!(
wait_outcome(response),
Ok(WaitOutcome::MissingCell(RuntimeResponse::Terminated {
code_mode_host_duration: Some(Duration::ZERO),
cell_id: CellId::new("missing".to_string()),
content_items: Vec::new(),
}))
@@ -164,6 +169,7 @@ fn wait_outcome_preserves_missing_cell_state() {
#[test]
fn oversized_response_cell_ids_are_rejected() {
let response = grpc::ExecutionOutcome {
code_mode_host_duration_ns: 0,
cell_id: "x".repeat(grpc::MAX_IDENTIFIER_BYTES + 1),
content_items: Vec::new(),
outcome: Some(grpc::execution_outcome::Outcome::Yielded(
@@ -183,6 +189,7 @@ fn oversized_response_cell_ids_are_rejected() {
#[test]
fn invalid_output_enums_and_missing_oneofs_are_rejected() {
let invalid_image = grpc::ExecutionOutcome {
code_mode_host_duration_ns: 0,
cell_id: "cell".to_string(),
content_items: vec![grpc::ContentItem {
item: Some(grpc::content_item::Item::Image(grpc::ImageContent {
@@ -198,3 +205,31 @@ fn invalid_output_enums_and_missing_oneofs_are_rejected() {
assert!(runtime_response(invalid_image).is_err());
assert!(wait_outcome(grpc::WaitResponse { state: None }).is_err());
}
/// Zero is a valid measurement, and decoding must not round nanoseconds to
/// milliseconds even at the limits of the wire representation.
#[test]
fn host_timing_preserves_zero_and_nanosecond_precision() {
for code_mode_host_duration_ns in [0, 1_234_567, u64::MAX] {
let outcome = grpc::ExecutionOutcome {
cell_id: "cell".to_string(),
content_items: Vec::new(),
code_mode_host_duration_ns,
outcome: Some(grpc::execution_outcome::Outcome::Yielded(
grpc::ExecutionYielded {},
)),
};
let expected = RuntimeResponse::Yielded {
cell_id: CellId::new("cell".to_string()),
content_items: Vec::new(),
code_mode_host_duration: Some(Duration::from_nanos(code_mode_host_duration_ns)),
};
assert_eq!(runtime_response(outcome.clone()).as_ref(), Ok(&expected));
assert_eq!(
wait_outcome(grpc::WaitResponse {
state: Some(grpc::wait_response::State::LiveCell(outcome)),
}),
Ok(WaitOutcome::LiveCell(expected))
);
}
}
codex-rs/code-mode/src/grpc_session/generation.rs
+6
View File
@@ -85,25 +85,31 @@ fn public_runtime_response(generation: u64, response: RuntimeResponse) -> Runtim
RuntimeResponse::Yielded {
cell_id,
content_items,
code_mode_host_duration,
} => RuntimeResponse::Yielded {
cell_id: public_cell_id(generation, &cell_id),
content_items,
code_mode_host_duration,
},
RuntimeResponse::Terminated {
cell_id,
content_items,
code_mode_host_duration,
} => RuntimeResponse::Terminated {
cell_id: public_cell_id(generation, &cell_id),
content_items,
code_mode_host_duration,
},
RuntimeResponse::Result {
cell_id,
content_items,
error_text,
code_mode_host_duration,
} => RuntimeResponse::Result {
cell_id: public_cell_id(generation, &cell_id),
content_items,
error_text,
code_mode_host_duration,
},
}
}
codex-rs/code-mode/src/grpc_session/generation_tests.rs
+38
View File
@@ -2,6 +2,7 @@ use std::sync::Arc;
use std::sync::Mutex;
use std::sync::atomic::AtomicBool;
use std::sync::atomic::Ordering;
use std::time::Duration;
use codex_code_mode_protocol::CellId;
use codex_code_mode_protocol::CodeModeNestedToolCall;
@@ -171,6 +172,7 @@ async fn reconnected_execution_maps_started_and_initial_response_ids() {
let claimed = Arc::new(AtomicBool::new(false));
let initial_response_claimed = Arc::clone(&claimed);
let response = RuntimeResponse::Result {
code_mode_host_duration: None,
cell_id: wire_id.clone(),
content_items: vec![FunctionCallOutputContentItem::InputText {
text: "result".to_string(),
@@ -192,6 +194,7 @@ async fn reconnected_execution_maps_started_and_initial_response_ids() {
assert_eq!(
started.initial_response().await,
Ok(RuntimeResponse::Result {
code_mode_host_duration: None,
cell_id: public_id,
content_items: vec![FunctionCallOutputContentItem::InputText {
text: "result".to_string(),
@@ -205,10 +208,12 @@ async fn reconnected_execution_maps_started_and_initial_response_ids() {
fn reconnected_wait_maps_live_and_missing_outcomes() {
let public_id = CellId::new("g2:42".to_string());
let yielded = RuntimeResponse::Yielded {
code_mode_host_duration: None,
cell_id: CellId::new("42".to_string()),
content_items: Vec::new(),
};
let terminated = RuntimeResponse::Terminated {
code_mode_host_duration: None,
cell_id: CellId::new("42".to_string()),
content_items: Vec::new(),
};
@@ -216,6 +221,7 @@ fn reconnected_wait_maps_live_and_missing_outcomes() {
assert_eq!(
public_wait_outcome(/*generation*/ 2, WaitOutcome::LiveCell(yielded)),
WaitOutcome::LiveCell(RuntimeResponse::Yielded {
code_mode_host_duration: None,
cell_id: public_id.clone(),
content_items: Vec::new(),
})
@@ -223,8 +229,40 @@ fn reconnected_wait_maps_live_and_missing_outcomes() {
assert_eq!(
public_wait_outcome(/*generation*/ 2, WaitOutcome::MissingCell(terminated)),
WaitOutcome::MissingCell(RuntimeResponse::Terminated {
code_mode_host_duration: None,
cell_id: public_id,
content_items: Vec::new(),
})
);
}
/// Replacing a host generation changes public cell IDs without losing the
/// operation's original duration on either the exec or wait path.
#[tokio::test]
async fn cell_id_remapping_preserves_code_mode_host_duration() {
let cell_id = CellId::new("42".to_string());
let code_mode_host_duration = Some(Duration::from_nanos(/*nanos*/ 1_234_567));
let response = RuntimeResponse::Yielded {
cell_id: cell_id.clone(),
content_items: Vec::new(),
code_mode_host_duration,
};
let initial = response.clone();
let started = StartedCell::from_future(cell_id, async move { Ok(initial) });
let expected = RuntimeResponse::Yielded {
cell_id: CellId::new("g2:42".to_string()),
content_items: Vec::new(),
code_mode_host_duration,
};
assert_eq!(
public_started_cell(/*generation*/ 2, started)
.initial_response()
.await
.as_ref(),
Ok(&expected),
);
assert_eq!(
public_wait_outcome(/*generation*/ 2, WaitOutcome::LiveCell(response)),
WaitOutcome::LiveCell(expected),
);
}
codex-rs/code-mode/src/remote_session/connection/driver/cell_ids.rs
+6
View File
@@ -60,25 +60,31 @@ pub(super) fn public_runtime_response(
RuntimeResponse::Yielded {
cell_id,
content_items,
code_mode_host_duration,
} => RuntimeResponse::Yielded {
cell_id: public_cell_id_from_protocol(generation, &cell_id),
content_items,
code_mode_host_duration,
},
RuntimeResponse::Terminated {
cell_id,
content_items,
code_mode_host_duration,
} => RuntimeResponse::Terminated {
cell_id: public_cell_id_from_protocol(generation, &cell_id),
content_items,
code_mode_host_duration,
},
RuntimeResponse::Result {
cell_id,
content_items,
error_text,
code_mode_host_duration,
} => RuntimeResponse::Result {
cell_id: public_cell_id_from_protocol(generation, &cell_id),
content_items,
error_text,
code_mode_host_duration,
},
}
}
codex-rs/code-mode/src/remote_session/connection/driver_tests.rs
+14
View File
@@ -773,6 +773,7 @@ async fn terminate_closes_cell_without_waiting_for_delegate_cleanup() {
result: WireResult::Ok {
value: HostResponse::WaitCompleted {
outcome: WireWaitOutcome::LiveCell(WireRuntimeResponse::Terminated {
code_mode_host_duration_ns: 0,
cell_id: CellId::new("1".to_string()).into(),
content_items: Vec::new(),
}),
@@ -792,6 +793,7 @@ async fn terminate_closes_cell_without_waiting_for_delegate_cleanup() {
response_rx.await.expect("terminate reply"),
Ok(codex_code_mode_protocol::WaitOutcome::LiveCell(
codex_code_mode_protocol::RuntimeResponse::Terminated {
code_mode_host_duration: Some(Duration::ZERO),
cell_id: CellId::new("1".to_string()),
content_items: Vec::new(),
}
@@ -1096,6 +1098,7 @@ async fn mismatched_initial_response_fails_connection_and_closes_cell_once() {
id: RequestId::new(/*value*/ 2),
result: WireResult::Ok {
value: WireRuntimeResponse::Yielded {
code_mode_host_duration_ns: 0,
cell_id: CellId::new("2".to_string()).into(),
content_items: Vec::new(),
},
@@ -1143,6 +1146,7 @@ async fn mismatched_wait_response_fails_connection() {
result: WireResult::Ok {
value: HostResponse::WaitCompleted {
outcome: WireWaitOutcome::LiveCell(WireRuntimeResponse::Yielded {
code_mode_host_duration_ns: 0,
cell_id: CellId::new("2".to_string()).into(),
content_items: Vec::new(),
}),
@@ -1187,6 +1191,7 @@ async fn mismatched_terminate_response_fails_connection() {
result: WireResult::Ok {
value: HostResponse::WaitCompleted {
outcome: WireWaitOutcome::MissingCell(WireRuntimeResponse::Terminated {
code_mode_host_duration_ns: 0,
cell_id: CellId::new("2".to_string()).into(),
content_items: Vec::new(),
}),
@@ -1239,6 +1244,7 @@ async fn remote_wait_accepts_durations_longer_than_five_minutes() {
result: WireResult::Ok {
value: HostResponse::WaitCompleted {
outcome: WireWaitOutcome::LiveCell(WireRuntimeResponse::Yielded {
code_mode_host_duration_ns: 0,
cell_id: CellId::new("1".to_string()).into(),
content_items: Vec::new(),
}),
@@ -1252,6 +1258,7 @@ async fn remote_wait_accepts_durations_longer_than_five_minutes() {
response_rx.await.expect("wait reply"),
Ok(codex_code_mode_protocol::WaitOutcome::LiveCell(
codex_code_mode_protocol::RuntimeResponse::Yielded {
code_mode_host_duration: Some(Duration::ZERO),
cell_id: CellId::new("1".to_string()),
content_items: Vec::new(),
}
@@ -1416,6 +1423,7 @@ async fn cancelled_wait_is_retired_before_next_wait_is_sent() {
result: WireResult::Ok {
value: HostResponse::WaitCompleted {
outcome: WireWaitOutcome::LiveCell(WireRuntimeResponse::Yielded {
code_mode_host_duration_ns: 0,
cell_id: CellId::new("1".to_string()).into(),
content_items: Vec::new(),
}),
@@ -1429,6 +1437,7 @@ async fn cancelled_wait_is_retired_before_next_wait_is_sent() {
second_rx.await.expect("second wait reply"),
Ok(codex_code_mode_protocol::WaitOutcome::LiveCell(
codex_code_mode_protocol::RuntimeResponse::Yielded {
code_mode_host_duration: Some(Duration::ZERO),
cell_id: CellId::new("1".to_string()),
content_items: Vec::new(),
}
@@ -1492,6 +1501,7 @@ async fn abandoned_execute_is_tracked_and_terminated_after_admission() {
id: RequestId::new(/*value*/ 2),
result: WireResult::Ok {
value: WireRuntimeResponse::Terminated {
code_mode_host_duration_ns: 0,
cell_id: CellId::new("1".to_string()).into(),
content_items: Vec::new(),
},
@@ -1506,6 +1516,7 @@ async fn abandoned_execute_is_tracked_and_terminated_after_admission() {
result: WireResult::Ok {
value: HostResponse::WaitCompleted {
outcome: WireWaitOutcome::LiveCell(WireRuntimeResponse::Terminated {
code_mode_host_duration_ns: 0,
cell_id: CellId::new("1".to_string()).into(),
content_items: Vec::new(),
}),
@@ -1591,6 +1602,7 @@ async fn delivered_but_unclaimed_execute_is_terminated_when_the_caller_is_cancel
id: RequestId::new(/*value*/ 2),
result: WireResult::Ok {
value: WireRuntimeResponse::Terminated {
code_mode_host_duration_ns: 0,
cell_id: CellId::new("1".to_string()).into(),
content_items: Vec::new(),
},
@@ -1606,6 +1618,7 @@ async fn delivered_but_unclaimed_execute_is_terminated_when_the_caller_is_cancel
result: WireResult::Ok {
value: HostResponse::WaitCompleted {
outcome: WireWaitOutcome::LiveCell(WireRuntimeResponse::Terminated {
code_mode_host_duration_ns: 0,
cell_id: CellId::new("1".to_string()).into(),
content_items: Vec::new(),
}),
@@ -1652,6 +1665,7 @@ async fn session_accepts_more_than_4096_cells_without_growing_a_tombstone_set()
id: RequestId::new(request_id),
result: WireResult::Ok {
value: WireRuntimeResponse::Yielded {
code_mode_host_duration_ns: 0,
cell_id: CellId::new(cell_id.clone()).into(),
content_items: Vec::new(),
},