fix(openai): align request ordering and simplify timing metrics

Preserve response.create field order and align OAuth query ordering with
current official Codex sources.

Stop adding the timing-metrics request header by default and remove the
four unused engine TTFT and token interval fields throughout the backend,
plugin observation contracts, and frontend. Keep rate calculations unchanged.

Co-authored-by: Codex <noreply@openai.com>
This commit is contained in:
Zyy
2026-10-18 16:32:15 +08:00
co-authored by Codex
parent 2221f400da
commit 99ba5b1120
35 changed files with 55 additions and 303 deletions
@@ -722,10 +722,6 @@ pub struct UsageListRecord {
pub upstream_response_ms: Option<u64>,
pub upstream_api_overhead_ms: Option<f64>,
pub upstream_engine_ms: Option<f64>,
pub upstream_engine_iapi_ttft_ms: Option<f64>,
pub upstream_engine_service_ttft_ms: Option<f64>,
pub upstream_engine_iapi_tbt_ms: Option<f64>,
pub upstream_engine_service_tbt_ms: Option<f64>,
pub latency_ms: Option<u64>,
pub admission_decision_ms: Option<u64>,
pub account_selection_wait_ms: Option<u64>,
@@ -803,10 +799,6 @@ pub struct UsageRecord {
pub upstream_response_ms: Option<u64>,
pub upstream_api_overhead_ms: Option<f64>,
pub upstream_engine_ms: Option<f64>,
pub upstream_engine_iapi_ttft_ms: Option<f64>,
pub upstream_engine_service_ttft_ms: Option<f64>,
pub upstream_engine_iapi_tbt_ms: Option<f64>,
pub upstream_engine_service_tbt_ms: Option<f64>,
pub latency_ms: Option<u64>,
pub admission_decision_ms: Option<u64>,
pub account_selection_wait_ms: Option<u64>,
@@ -1390,10 +1390,6 @@ fn total_record(
upstream_response_ms: None,
upstream_api_overhead_ms: None,
upstream_engine_ms: None,
upstream_engine_iapi_ttft_ms: None,
upstream_engine_service_ttft_ms: None,
upstream_engine_iapi_tbt_ms: None,
upstream_engine_service_tbt_ms: None,
latency_ms: Some(100),
admission_decision_ms: None,
account_selection_wait_ms: None,
@@ -304,10 +304,6 @@ pub(crate) fn usage_list_record_view(
upstream_response_ms: record.upstream_response_ms,
upstream_api_overhead_ms: record.upstream_api_overhead_ms,
upstream_engine_ms: record.upstream_engine_ms,
upstream_engine_iapi_ttft_ms: record.upstream_engine_iapi_ttft_ms,
upstream_engine_service_ttft_ms: record.upstream_engine_service_ttft_ms,
upstream_engine_iapi_tbt_ms: record.upstream_engine_iapi_tbt_ms,
upstream_engine_service_tbt_ms: record.upstream_engine_service_tbt_ms,
},
first_token_latency_ms: record.first_token_ms,
latency_ms: record.latency_ms,
@@ -411,10 +407,6 @@ pub(crate) fn usage_record_view(
upstream_response_ms: record.upstream_response_ms,
upstream_api_overhead_ms: record.upstream_api_overhead_ms,
upstream_engine_ms: record.upstream_engine_ms,
upstream_engine_iapi_ttft_ms: record.upstream_engine_iapi_ttft_ms,
upstream_engine_service_ttft_ms: record.upstream_engine_service_ttft_ms,
upstream_engine_iapi_tbt_ms: record.upstream_engine_iapi_tbt_ms,
upstream_engine_service_tbt_ms: record.upstream_engine_service_tbt_ms,
},
attempt_index: None,
attempt_count: u64::from(record.attempt_count),
@@ -230,14 +230,6 @@ pub struct UsageLatencyDetailsView {
pub upstream_api_overhead_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
pub upstream_engine_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
pub upstream_engine_iapi_ttft_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
pub upstream_engine_service_ttft_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
pub upstream_engine_iapi_tbt_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
pub upstream_engine_service_tbt_ms: Option<f64>,
}
/// 单次上游尝试展示
@@ -213,14 +213,6 @@ struct OutputTimingView {
#[serde(skip_serializing_if = "Option::is_none")]
upstream_engine_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
upstream_engine_iapi_ttft_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
upstream_engine_service_ttft_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
upstream_engine_iapi_tbt_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
upstream_engine_service_tbt_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
first_event_ms: Option<u64>,
#[serde(skip_serializing_if = "Option::is_none")]
first_reasoning_ms: Option<u64>,
@@ -260,10 +252,6 @@ fn usage_record(value: UsageListRecord, time: crate::time::TimePresenter) -> Rec
upstream_response_ms: value.upstream_response_ms,
upstream_api_overhead_ms: value.upstream_api_overhead_ms,
upstream_engine_ms: value.upstream_engine_ms,
upstream_engine_iapi_ttft_ms: value.upstream_engine_iapi_ttft_ms,
upstream_engine_service_ttft_ms: value.upstream_engine_service_ttft_ms,
upstream_engine_iapi_tbt_ms: value.upstream_engine_iapi_tbt_ms,
upstream_engine_service_tbt_ms: value.upstream_engine_service_tbt_ms,
first_event_ms: value.first_event_ms,
first_reasoning_ms: value.first_reasoning_ms,
first_text_ms: value.first_text_ms,
@@ -58,7 +58,8 @@ fn decode_response_create_inner(
else {
return Err(ResponseCreateFrameError::ExpectedObject);
};
match body.remove("type") {
// 保持剩余字段顺序,避免末尾元数据交换到模型等路由字段之前
match body.shift_remove("type") {
Some(Value::String(message_type)) if message_type == "response.create" => {}
_ => return Err(ResponseCreateFrameError::UnsupportedType),
}
@@ -288,10 +288,6 @@ async fn usage_detail_should_keep_attempt_snapshot_contract() {
record.upstream_response_ms = Some(1_000);
record.upstream_api_overhead_ms = Some(120.25);
record.upstream_engine_ms = Some(6400.0);
record.upstream_engine_iapi_ttft_ms = Some(650.5);
record.upstream_engine_service_ttft_ms = Some(720.25);
record.upstream_engine_iapi_tbt_ms = Some(18.45);
record.upstream_engine_service_tbt_ms = Some(20.12);
fixture
.usage_detail
.lock()
@@ -362,22 +358,6 @@ async fn usage_detail_should_keep_attempt_snapshot_contract() {
value["data"]["latencyDetails"]["upstreamEngineMs"],
json!(6400.0)
);
assert_eq!(
value["data"]["latencyDetails"]["upstreamEngineIapiTtftMs"],
json!(650.5)
);
assert_eq!(
value["data"]["latencyDetails"]["upstreamEngineServiceTtftMs"],
json!(720.25)
);
assert_eq!(
value["data"]["latencyDetails"]["upstreamEngineIapiTbtMs"],
json!(18.45)
);
assert_eq!(
value["data"]["latencyDetails"]["upstreamEngineServiceTbtMs"],
json!(20.12)
);
assert!(value["data"].get("firstTokenMs").is_none());
assert!(value["data"].get("firstTokenLatencyMsDisplay").is_none());
assert!(
@@ -734,10 +714,6 @@ pub(super) fn usage_record_with_account(
upstream_response_ms: None,
upstream_api_overhead_ms: None,
upstream_engine_ms: None,
upstream_engine_iapi_ttft_ms: None,
upstream_engine_service_ttft_ms: None,
upstream_engine_iapi_tbt_ms: None,
upstream_engine_service_tbt_ms: None,
latency_ms: None,
admission_decision_ms: None,
account_selection_wait_ms: None,
@@ -877,10 +853,6 @@ async fn usage_route_should_expose_table_facts_without_detail_payload() {
upstream_response_ms: Some(2_000),
upstream_api_overhead_ms: None,
upstream_engine_ms: None,
upstream_engine_iapi_ttft_ms: None,
upstream_engine_service_ttft_ms: None,
upstream_engine_iapi_tbt_ms: None,
upstream_engine_service_tbt_ms: None,
latency_ms: Some(31),
admission_decision_ms: Some(1),
account_selection_wait_ms: Some(2),
@@ -140,11 +140,7 @@ fn usage_record() -> UsageListRecord {
provider_processing_ms: None,
upstream_response_ms: Some(1_000),
upstream_api_overhead_ms: None,
upstream_engine_ms: None,
upstream_engine_iapi_ttft_ms: None,
upstream_engine_service_ttft_ms: None,
upstream_engine_iapi_tbt_ms: Some(2.450638),
upstream_engine_service_tbt_ms: None,
upstream_engine_ms: Some(2.450638),
latency_ms: Some(1250),
admission_decision_ms: None,
account_selection_wait_ms: None,
@@ -320,7 +320,7 @@ async fn records_keep_pagination_and_hide_admin_and_upstream_data() {
&record["latencyDetails"],
&[
"upstreamResponseMs",
"upstreamEngineIapiTbtMs",
"upstreamEngineMs",
"firstEventMs",
"firstReasoningMs",
"firstTextMs",
@@ -328,10 +328,7 @@ async fn records_keep_pagination_and_hide_admin_and_upstream_data() {
);
assert_eq!(record["latencyDetails"]["firstEventMs"], 100);
assert_eq!(record["latencyDetails"]["upstreamResponseMs"], 1000);
assert_eq!(
record["latencyDetails"]["upstreamEngineIapiTbtMs"],
2.450638
);
assert_eq!(record["latencyDetails"]["upstreamEngineMs"], 2.450638);
assert!(record["statusCode"].is_null());
} else {
assert_eq!(record["statusCode"], 502);
@@ -8,6 +8,26 @@ use serde_json::json;
use super::decode_response_create;
#[test]
fn response_create_should_preserve_field_order_when_removing_frame_type() {
let expected = r#"{"model":"smart-code","stream":true,"input":"hello","future_field":{"z":1,"a":2},"client_metadata":{"thread_id":"thread","turn_id":"turn"}}"#;
for payload in [
r#"{"type":"response.create","model":"smart-code","stream":true,"input":"hello","future_field":{"z":1,"a":2},"client_metadata":{"thread_id":"thread","turn_id":"turn"}}"#,
r#"{"model":"smart-code","stream":true,"type":"response.create","input":"hello","future_field":{"z":1,"a":2},"client_metadata":{"thread_id":"thread","turn_id":"turn"}}"#,
r#"{"model":"smart-code","stream":true,"input":"hello","future_field":{"z":1,"a":2},"client_metadata":{"thread_id":"thread","turn_id":"turn"},"type":"response.create"}"#,
] {
let decoded = decode_response_create(payload).expect("decode response.create");
let body = decoded
.operation()
.middleware_body()
.expect("encode transparent body");
assert_eq!(
std::str::from_utf8(&body).expect("UTF-8 JSON body"),
expected,
);
}
}
#[test]
fn client_retry_identity_should_follow_each_frame_instead_of_handshake_metadata() {
let mut headers = HeaderMap::new();
@@ -955,10 +955,6 @@ pub struct ModelRequestTimings {
pub upstream_response_ms: Option<u64>,
pub upstream_api_overhead_ms: Option<f64>,
pub upstream_engine_ms: Option<f64>,
pub upstream_engine_iapi_ttft_ms: Option<f64>,
pub upstream_engine_service_ttft_ms: Option<f64>,
pub upstream_engine_iapi_tbt_ms: Option<f64>,
pub upstream_engine_service_tbt_ms: Option<f64>,
pub latency_ms: Option<u64>,
}
@@ -807,10 +807,6 @@ impl ResponseObservation {
self.timings.upstream_response_ms = None;
self.timings.upstream_api_overhead_ms = None;
self.timings.upstream_engine_ms = None;
self.timings.upstream_engine_iapi_ttft_ms = None;
self.timings.upstream_engine_service_ttft_ms = None;
self.timings.upstream_engine_iapi_tbt_ms = None;
self.timings.upstream_engine_service_tbt_ms = None;
}
pub(super) fn observe_response(&mut self, observation: &ProviderResponseObservation) {
@@ -848,17 +844,5 @@ impl ResponseObservation {
if let Some(value) = observed.upstream_engine_ms {
self.timings.upstream_engine_ms = Some(value);
}
if let Some(value) = observed.upstream_engine_iapi_ttft_ms {
self.timings.upstream_engine_iapi_ttft_ms = Some(value);
}
if let Some(value) = observed.upstream_engine_service_ttft_ms {
self.timings.upstream_engine_service_ttft_ms = Some(value);
}
if let Some(value) = observed.upstream_engine_iapi_tbt_ms {
self.timings.upstream_engine_iapi_tbt_ms = Some(value);
}
if let Some(value) = observed.upstream_engine_service_tbt_ms {
self.timings.upstream_engine_service_tbt_ms = Some(value);
}
}
}
+1 -5
View File
@@ -536,12 +536,8 @@ pub struct ProviderResponseTimings {
pub upstream_response_ms: Option<u64>,
/// 上游排除引擎与客户端工具时间后的 API 耗时
pub upstream_api_overhead_ms: Option<f64>,
/// 上游响应级引擎耗时;以下专项指标保留毫秒小数及各自内部计量层级
/// 上游响应级引擎耗时,保留毫秒小数
pub upstream_engine_ms: Option<f64>,
pub upstream_engine_iapi_ttft_ms: Option<f64>,
pub upstream_engine_service_ttft_ms: Option<f64>,
pub upstream_engine_iapi_tbt_ms: Option<f64>,
pub upstream_engine_service_tbt_ms: Option<f64>,
}
/// Provider 已筛选的响应观测 JSON
@@ -505,10 +505,6 @@ struct FinalState {
upstream_response_ms: Option<u64>,
upstream_api_overhead_ms: Option<f64>,
upstream_engine_ms: Option<f64>,
upstream_engine_iapi_ttft_ms: Option<f64>,
upstream_engine_service_ttft_ms: Option<f64>,
upstream_engine_iapi_tbt_ms: Option<f64>,
upstream_engine_service_tbt_ms: Option<f64>,
provider_metadata_json: Option<String>,
cost_source: CostSource,
cost_ticks: Option<u128>,
@@ -684,12 +680,6 @@ impl ExecutionStore for FakeStore {
upstream_response_ms: finalization.timings.upstream_response_ms,
upstream_api_overhead_ms: finalization.timings.upstream_api_overhead_ms,
upstream_engine_ms: finalization.timings.upstream_engine_ms,
upstream_engine_iapi_ttft_ms: finalization.timings.upstream_engine_iapi_ttft_ms,
upstream_engine_service_ttft_ms: finalization
.timings
.upstream_engine_service_ttft_ms,
upstream_engine_iapi_tbt_ms: finalization.timings.upstream_engine_iapi_tbt_ms,
upstream_engine_service_tbt_ms: finalization.timings.upstream_engine_service_tbt_ms,
provider_metadata_json: finalization.provider_metadata_json,
cost_source: finalization.cost.source(),
cost_ticks: finalization
@@ -2067,10 +2057,6 @@ fn discarded_attempt_observation_does_not_leak_into_retry_result() {
upstream_response_ms: Some(7_000),
upstream_api_overhead_ms: Some(120.25),
upstream_engine_ms: Some(6400.0),
upstream_engine_iapi_ttft_ms: Some(650.5),
upstream_engine_service_ttft_ms: Some(720.25),
upstream_engine_iapi_tbt_ms: Some(18.45),
upstream_engine_service_tbt_ms: Some(20.12),
..ProviderResponseTimings::default()
});
let second_observation = ProviderResponseObservation::new(
@@ -2164,10 +2150,6 @@ fn discarded_attempt_observation_does_not_leak_into_retry_result() {
assert_eq!(finalization.upstream_response_ms, None);
assert_eq!(finalization.upstream_api_overhead_ms, None);
assert_eq!(finalization.upstream_engine_ms, None);
assert_eq!(finalization.upstream_engine_iapi_ttft_ms, None);
assert_eq!(finalization.upstream_engine_service_ttft_ms, None);
assert_eq!(finalization.upstream_engine_iapi_tbt_ms, None);
assert_eq!(finalization.upstream_engine_service_tbt_ms, None);
let contexts = provider.contexts.lock().unwrap();
assert_eq!(contexts.len(), 2);
assert_eq!(
@@ -543,10 +543,6 @@ fn wire_timings(observation: &RequestObservation) -> RequestTimings {
upstream_response_ms: timings.upstream_response_ms,
upstream_api_overhead_ms: timings.upstream_api_overhead_ms,
upstream_engine_ms: timings.upstream_engine_ms,
upstream_engine_iapi_ttft_ms: timings.upstream_engine_iapi_ttft_ms,
upstream_engine_service_ttft_ms: timings.upstream_engine_service_ttft_ms,
upstream_engine_iapi_tbt_ms: timings.upstream_engine_iapi_tbt_ms,
upstream_engine_service_tbt_ms: timings.upstream_engine_service_tbt_ms,
latency_ms: timings.latency_ms,
}
}
@@ -132,10 +132,6 @@ fn observation(value: &ProviderResponseObservation) -> facts::ResponseObservatio
upstream_response_ms: timings.upstream_response_ms,
upstream_api_overhead_ms: timings.upstream_api_overhead_ms,
upstream_engine_ms: timings.upstream_engine_ms,
upstream_engine_iapi_ttft_ms: timings.upstream_engine_iapi_ttft_ms,
upstream_engine_service_ttft_ms: timings.upstream_engine_service_ttft_ms,
upstream_engine_iapi_tbt_ms: timings.upstream_engine_iapi_tbt_ms,
upstream_engine_service_tbt_ms: timings.upstream_engine_service_tbt_ms,
latency_ms: None,
},
client_headers: value
@@ -817,7 +817,7 @@ async fn completed_observation_contains_terminal_cost_timings_and_failure() {
.with_timings(ModelRequestTimings {
first_text_ms: Some(12),
upstream_response_ms: Some(7_000),
upstream_engine_iapi_tbt_ms: Some(2.450638),
upstream_engine_ms: Some(2.450638),
latency_ms: Some(34),
..ModelRequestTimings::default()
}),
@@ -831,10 +831,7 @@ async fn completed_observation_contains_terminal_cost_timings_and_failure() {
assert_eq!(observed["usage"]["cost"]["total"]["currency"], "USD");
assert_eq!(observed["usage"]["timings"]["first_text_ms"], 12);
assert_eq!(observed["usage"]["timings"]["upstream_response_ms"], 7_000);
assert_eq!(
observed["usage"]["timings"]["upstream_engine_iapi_tbt_ms"],
2.450638
);
assert_eq!(observed["usage"]["timings"]["upstream_engine_ms"], 2.450638);
assert_eq!(observed["usage"]["timings"]["latency_ms"], 34);
assert_eq!(observed["usage"]["failure"]["outcome"], "failed");
assert_eq!(observed["usage"]["failure"]["attempt_count"], 2);
@@ -186,7 +186,7 @@ async fn facts_are_readable_without_replacing_or_duplicating_the_original_execut
.with_timings(ProviderResponseTimings {
headers_ms: Some(19),
upstream_response_ms: Some(7_000),
upstream_engine_iapi_tbt_ms: Some(2.450638),
upstream_engine_ms: Some(2.450638),
..Default::default()
}),
);
@@ -273,7 +273,7 @@ async fn facts_are_readable_without_replacing_or_duplicating_the_original_execut
);
assert_eq!(facts["observation"]["timings"]["headers_ms"], 19);
assert_eq!(
facts["observation"]["timings"]["upstream_engine_iapi_tbt_ms"],
facts["observation"]["timings"]["upstream_engine_ms"],
2.450638
);
assert_eq!(
@@ -110,14 +110,6 @@ pub struct RequestTimings {
#[serde(default, skip_serializing_if = "Option::is_none")]
pub upstream_engine_ms: Option<f64>,
#[serde(default, skip_serializing_if = "Option::is_none")]
pub upstream_engine_iapi_ttft_ms: Option<f64>,
#[serde(default, skip_serializing_if = "Option::is_none")]
pub upstream_engine_service_ttft_ms: Option<f64>,
#[serde(default, skip_serializing_if = "Option::is_none")]
pub upstream_engine_iapi_tbt_ms: Option<f64>,
#[serde(default, skip_serializing_if = "Option::is_none")]
pub upstream_engine_service_tbt_ms: Option<f64>,
#[serde(default, skip_serializing_if = "Option::is_none")]
pub latency_ms: Option<u64>,
}
@@ -204,13 +204,13 @@ fn cost_timings_and_failure_keep_unknown_facts_explicit_and_safe() {
let timings = RequestTimings {
first_text_ms: Some(12),
upstream_response_ms: Some(7_000),
upstream_engine_iapi_tbt_ms: Some(2.450638),
upstream_engine_ms: Some(2.450638),
latency_ms: Some(34),
..RequestTimings::default()
};
assert_eq!(
serde_json::to_value(&timings).unwrap(),
json!({"first_text_ms":12,"upstream_response_ms":7000,"upstream_engine_iapi_tbt_ms":2.450638,"latency_ms":34})
json!({"first_text_ms":12,"upstream_response_ms":7000,"upstream_engine_ms":2.450638,"latency_ms":34})
);
let failure = RequestFailure {
@@ -107,14 +107,6 @@ struct UpstreamTimings {
api_overhead_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
engine_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
engine_iapi_ttft_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
engine_service_ttft_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
engine_iapi_tbt_ms: Option<f64>,
#[serde(skip_serializing_if = "Option::is_none")]
engine_service_tbt_ms: Option<f64>,
}
#[derive(Default, Serialize)]
@@ -229,16 +221,9 @@ impl RequestObservation {
value.retry_after_ms,
])?;
// serde_json 会把非有限浮点数写成 null,先拒绝以免把非法指标伪装成缺失
for value in [
timings.upstream_api_overhead_ms,
timings.upstream_engine_ms,
timings.upstream_engine_iapi_ttft_ms,
timings.upstream_engine_service_ttft_ms,
timings.upstream_engine_iapi_tbt_ms,
timings.upstream_engine_service_tbt_ms,
]
.into_iter()
.flatten()
for value in [timings.upstream_api_overhead_ms, timings.upstream_engine_ms]
.into_iter()
.flatten()
{
if !value.is_finite() || value < 0.0 || value >= i64::MAX as f64 {
return Err(invalid(
@@ -263,10 +248,6 @@ impl RequestObservation {
response_ms: timings.upstream_response_ms,
api_overhead_ms: timings.upstream_api_overhead_ms,
engine_ms: timings.upstream_engine_ms,
engine_iapi_ttft_ms: timings.upstream_engine_iapi_ttft_ms,
engine_service_ttft_ms: timings.upstream_engine_service_ttft_ms,
engine_iapi_tbt_ms: timings.upstream_engine_iapi_tbt_ms,
engine_service_tbt_ms: timings.upstream_engine_service_tbt_ms,
}),
}),
transport: Some(TransportObservation {
@@ -350,10 +350,6 @@ pub(crate) fn usage_list_record_from_row(
upstream_response_ms: optional_unsigned(row, "upstream_response_ms")?,
upstream_api_overhead_ms: get(row, "upstream_api_overhead_ms")?,
upstream_engine_ms: get(row, "upstream_engine_ms")?,
upstream_engine_iapi_ttft_ms: get(row, "upstream_engine_iapi_ttft_ms")?,
upstream_engine_service_ttft_ms: get(row, "upstream_engine_service_ttft_ms")?,
upstream_engine_iapi_tbt_ms: get(row, "upstream_engine_iapi_tbt_ms")?,
upstream_engine_service_tbt_ms: get(row, "upstream_engine_service_tbt_ms")?,
latency_ms: optional_unsigned(row, "latency_ms")?,
admission_decision_ms: optional_unsigned(row, "admission_decision_ms")?,
account_selection_wait_ms: optional_unsigned(row, "account_selection_wait_ms")?,
@@ -446,10 +442,6 @@ pub(crate) fn usage_record_from_row(row: &sqlx::postgres::PgRow) -> StoreResult<
upstream_response_ms: optional_unsigned(row, "upstream_response_ms")?,
upstream_api_overhead_ms: get(row, "upstream_api_overhead_ms")?,
upstream_engine_ms: get(row, "upstream_engine_ms")?,
upstream_engine_iapi_ttft_ms: get(row, "upstream_engine_iapi_ttft_ms")?,
upstream_engine_service_ttft_ms: get(row, "upstream_engine_service_ttft_ms")?,
upstream_engine_iapi_tbt_ms: get(row, "upstream_engine_iapi_tbt_ms")?,
upstream_engine_service_tbt_ms: get(row, "upstream_engine_service_tbt_ms")?,
latency_ms: optional_unsigned(row, "latency_ms")?,
admission_decision_ms: optional_unsigned(row, "admission_decision_ms")?,
account_selection_wait_ms: optional_unsigned(row, "account_selection_wait_ms")?,
@@ -128,7 +128,7 @@ pub(crate) const USAGE_LIST_RECORD_SELECT: &str =
mr.transport_decision_wait_ms, mr.connect_ms, mr.headers_ms,
mr.first_event_ms, mr.first_reasoning_ms, mr.first_text_ms, mr.first_token_ms,
mr.provider_processing_ms, mr.upstream_response_ms,
mr.upstream_api_overhead_ms, mr.upstream_engine_ms, mr.upstream_engine_iapi_ttft_ms, mr.upstream_engine_service_ttft_ms, mr.upstream_engine_iapi_tbt_ms, mr.upstream_engine_service_tbt_ms, mr.latency_ms, mr.admission_decision_ms,
mr.upstream_api_overhead_ms, mr.upstream_engine_ms, mr.latency_ms, mr.admission_decision_ms,
mr.account_selection_wait_ms, mr.capacity_used_slots, mr.capacity_total_slots,
host(mr.client_ip) as client_ip, mr.user_agent,
mr.reasoning_effort, mr.reasoning_preset, mr.subagent_kind, mr.compact,
@@ -157,7 +157,7 @@ pub(crate) const USAGE_RECORD_DETAIL_SELECT: &str =
mr.cost_currency, mr.transport_decision_wait_ms, mr.connect_ms, mr.headers_ms,
mr.first_event_ms, mr.first_reasoning_ms, mr.first_text_ms, mr.first_token_ms,
mr.provider_processing_ms, mr.upstream_response_ms,
mr.upstream_api_overhead_ms, mr.upstream_engine_ms, mr.upstream_engine_iapi_ttft_ms, mr.upstream_engine_service_ttft_ms, mr.upstream_engine_iapi_tbt_ms, mr.upstream_engine_service_tbt_ms, mr.latency_ms, mr.admission_decision_ms,
mr.upstream_api_overhead_ms, mr.upstream_engine_ms, mr.latency_ms, mr.admission_decision_ms,
mr.account_selection_wait_ms, mr.capacity_used_slots, mr.capacity_total_slots,
host(mr.client_ip) as client_ip,
mr.user_agent, mr.reasoning_effort, mr.reasoning_preset, mr.request_kind,
@@ -2168,10 +2168,6 @@ async fn shared_core_usage_and_timings_preserve_fields_and_reject_invalid_phases
upstream_response_ms: Some(1_000),
upstream_api_overhead_ms: Some(120.25),
upstream_engine_ms: Some(6400.0),
upstream_engine_iapi_ttft_ms: Some(650.5),
upstream_engine_service_ttft_ms: Some(720.25),
upstream_engine_iapi_tbt_ms: Some(18.45),
upstream_engine_service_tbt_ms: Some(20.12),
latency_ms: Some(9),
};
ExecutionStore::finalize_model_request(&store, finalization)
@@ -2202,22 +2198,6 @@ async fn shared_core_usage_and_timings_preserve_fields_and_reject_invalid_phases
}
assert_eq!(persisted["upstream_api_overhead_ms"].as_f64(), Some(120.25));
assert_eq!(persisted["upstream_engine_ms"].as_f64(), Some(6400.0));
assert_eq!(
persisted["upstream_engine_iapi_ttft_ms"].as_f64(),
Some(650.5)
);
assert_eq!(
persisted["upstream_engine_service_ttft_ms"].as_f64(),
Some(720.25)
);
assert_eq!(
persisted["upstream_engine_iapi_tbt_ms"].as_f64(),
Some(18.45)
);
assert_eq!(
persisted["upstream_engine_service_tbt_ms"].as_f64(),
Some(20.12)
);
let invalid_id = "req_invalid_phase";
seed_running_request(&database.pool, invalid_id)
.await
@@ -2233,7 +2213,7 @@ async fn shared_core_usage_and_timings_preserve_fields_and_reject_invalid_phases
assert_eq!(stored_row(&database.pool, invalid_id).await, before);
for invalid_ms in [-1.0, f64::NAN, f64::INFINITY, i64::MAX as f64] {
let mut invalid = successful_core_finalization(invalid_id);
invalid.timings.upstream_engine_iapi_tbt_ms = Some(invalid_ms);
invalid.timings.upstream_engine_ms = Some(invalid_ms);
let error = ExecutionStore::finalize_model_request(&store, invalid)
.await
.expect_err("invalid official timing must not silently become missing");
@@ -110,7 +110,7 @@ async fn output_throughput_uses_official_response_duration_without_local_fallbac
'firstTokenMs', $2::bigint,
'latencyMs', $3::bigint),
'upstream', coalesce(request_observation_json #> '{timings,upstream}', '{}'::jsonb) || jsonb_build_object(
'responseMs', $4::bigint, 'engineIapiTbtMs', 2.450638))))
'responseMs', $4::bigint, 'engineMs', 2.450638))))
where id = 'req_observe_success'",
)
.bind(output)
@@ -150,8 +150,6 @@ async fn output_throughput_uses_official_response_duration_without_local_fallbac
detail.request.upstream_response_ms,
record.upstream_response_ms
);
assert_eq!(record.upstream_engine_iapi_tbt_ms, Some(2.450638));
assert_eq!(detail.request.upstream_engine_iapi_tbt_ms, Some(2.450638));
super::drain_analytics(&database.pool).await;
let summary = repository
@@ -776,12 +776,12 @@ fn authorization_url(
.append_pair("response_type", "code")
.append_pair("client_id", oauth_client_id)
.append_pair("redirect_uri", OFFICIAL_CODEX_REDIRECT_URI)
.append_pair("scope", AUTHORIZATION_SCOPE)
.append_pair("code_challenge", challenge.as_str())
.append_pair("code_challenge_method", "S256")
.append_pair("state", pending.state.expose_secret())
.append_pair("scope", AUTHORIZATION_SCOPE)
.append_pair("id_token_add_organizations", "true")
.append_pair("codex_cli_simplified_flow", "true")
.append_pair("state", pending.state.expose_secret())
.append_pair("originator", AUTHORIZATION_ORIGINATOR)
.append_pair("codex_app_version", desktop_version)
.append_pair("source_surface_stable_id", &stable_id)
@@ -199,18 +199,6 @@ impl OpenAiResponseObservationState {
if metrics.upstream_engine_ms.is_some() {
self.timings.upstream_engine_ms = metrics.upstream_engine_ms;
}
if metrics.upstream_engine_iapi_ttft_ms.is_some() {
self.timings.upstream_engine_iapi_ttft_ms = metrics.upstream_engine_iapi_ttft_ms;
}
if metrics.upstream_engine_service_ttft_ms.is_some() {
self.timings.upstream_engine_service_ttft_ms = metrics.upstream_engine_service_ttft_ms;
}
if metrics.upstream_engine_iapi_tbt_ms.is_some() {
self.timings.upstream_engine_iapi_tbt_ms = metrics.upstream_engine_iapi_tbt_ms;
}
if metrics.upstream_engine_service_tbt_ms.is_some() {
self.timings.upstream_engine_service_tbt_ms = metrics.upstream_engine_service_tbt_ms;
}
self.timings != previous
}
@@ -165,12 +165,6 @@ impl CodexBackendClient {
context: CodexRequestContext<'_>,
) -> CodexClientResult<HeaderMap> {
let mut headers = self.response_headers(profile, request, context)?;
if !headers.contains_key("x-responsesapi-include-timing-metrics") {
headers.insert(
HeaderName::from_static("x-responsesapi-include-timing-metrics"),
HeaderValue::from_static("true"),
);
}
headers.insert(
HeaderName::from_static("openai-beta"),
HeaderValue::from_static("responses_websockets=2026-02-06"),
@@ -255,10 +255,6 @@ pub(crate) fn response_duration_ms(value: &Value) -> Option<u64> {
pub(crate) struct ResponseTimingMetrics {
pub upstream_api_overhead_ms: Option<f64>,
pub upstream_engine_ms: Option<f64>,
pub upstream_engine_iapi_ttft_ms: Option<f64>,
pub upstream_engine_service_ttft_ms: Option<f64>,
pub upstream_engine_iapi_tbt_ms: Option<f64>,
pub upstream_engine_service_tbt_ms: Option<f64>,
}
impl ResponseTimingMetrics {
@@ -287,7 +283,6 @@ impl ResponseTimingMetrics {
return Self {
upstream_api_overhead_ms: overhead,
upstream_engine_ms: milliseconds(path, "engine_wall_ms"),
..Self::default()
};
}
// 直接返回的专项指标保留原口径,明确标为整轮累计的值不能归入单次请求
@@ -303,16 +298,6 @@ impl ResponseTimingMetrics {
"responses_duration_excl_engine_and_client_tool_time_ms",
),
upstream_engine_ms: milliseconds(metrics, "engine_service_total_ms"),
upstream_engine_iapi_ttft_ms: milliseconds(metrics, "engine_iapi_ttft_total_ms"),
upstream_engine_service_ttft_ms: milliseconds(metrics, "engine_service_ttft_total_ms"),
upstream_engine_iapi_tbt_ms: milliseconds(
metrics,
"engine_iapi_tbt_across_engine_calls_ms",
),
upstream_engine_service_tbt_ms: milliseconds(
metrics,
"engine_service_tbt_across_engine_calls_ms",
),
}
}
@@ -323,18 +308,6 @@ impl ResponseTimingMetrics {
if incoming.upstream_engine_ms.is_some() {
self.upstream_engine_ms = incoming.upstream_engine_ms;
}
if incoming.upstream_engine_iapi_ttft_ms.is_some() {
self.upstream_engine_iapi_ttft_ms = incoming.upstream_engine_iapi_ttft_ms;
}
if incoming.upstream_engine_service_ttft_ms.is_some() {
self.upstream_engine_service_ttft_ms = incoming.upstream_engine_service_ttft_ms;
}
if incoming.upstream_engine_iapi_tbt_ms.is_some() {
self.upstream_engine_iapi_tbt_ms = incoming.upstream_engine_iapi_tbt_ms;
}
if incoming.upstream_engine_service_tbt_ms.is_some() {
self.upstream_engine_service_tbt_ms = incoming.upstream_engine_service_tbt_ms;
}
}
}
@@ -265,12 +265,12 @@ async fn authorize_url_matches_the_official_desktop_parameter_contract() {
"response_type",
"client_id",
"redirect_uri",
"scope",
"code_challenge",
"code_challenge_method",
"state",
"scope",
"id_token_add_organizations",
"codex_cli_simplified_flow",
"state",
"originator",
"codex_app_version",
"source_surface_stable_id",
@@ -66,9 +66,10 @@ async fn observe_timing_events(websocket: bool, events: Vec<Value>) -> ProviderR
let mut ws = crate::transport::accept_codex_test_websocket_with(
socket,
|request: &tokio_tungstenite::tungstenite::handshake::server::Request, response| {
assert_eq!(
request.headers()["x-responsesapi-include-timing-metrics"],
"true"
assert!(
!request
.headers()
.contains_key("x-responsesapi-include-timing-metrics")
);
response.headers_mut().insert(
"sec-websocket-extensions",
@@ -125,19 +126,11 @@ async fn official_response_duration_is_observed_independently_of_the_request_clo
let metrics = json!({"type":"responsesapi.websocket_timing","timing_metrics":{
"responses_duration_excl_engine_and_client_tool_time_ms":120.25,
"engine_service_total_ms":6400.0,
"engine_iapi_ttft_total_ms":650.5,
"engine_service_ttft_total_ms":720.25,
"engine_iapi_tbt_across_engine_calls_ms":18.45,
"engine_service_tbt_across_engine_calls_ms":20.12
}});
let wrong_id = json!({"type":"responsesapi.websocket_timing","response_id":"resp_other","timing_metrics":{"engine_service_total_ms":999.0}});
let invalid = json!({"type":"responsesapi.websocket_timing","timing_metrics":{
"responses_duration_excl_engine_and_client_tool_time_ms":null,
"engine_service_total_ms":"100",
"engine_iapi_ttft_total_ms":-1,
"engine_service_ttft_total_ms":1e99,
"engine_iapi_tbt_across_engine_calls_ms":{},
"engine_service_tbt_across_engine_calls_ms":[]
}});
let stale = json!({"type":"responsesapi.websocket_timing","timing_metrics":{"engine_service_total_ms":999.0}});
let events = [stale, created, metrics, wrong_id, invalid, completed];
@@ -145,10 +138,6 @@ async fn official_response_duration_is_observed_independently_of_the_request_clo
assert_eq!(timings.upstream_response_ms, Some(7_000));
assert_eq!(timings.upstream_api_overhead_ms, Some(120.25));
assert_eq!(timings.upstream_engine_ms, Some(6400.0));
assert_eq!(timings.upstream_engine_iapi_ttft_ms, Some(650.5));
assert_eq!(timings.upstream_engine_service_ttft_ms, Some(720.25));
assert_eq!(timings.upstream_engine_iapi_tbt_ms, Some(18.45));
assert_eq!(timings.upstream_engine_service_tbt_ms, Some(20.12));
assert_eq!(timings.first_token_ms, None);
assert!(timings.first_event_ms.is_some_and(|value| value >= 20_000));
}
@@ -197,7 +186,6 @@ async fn response_critical_path_is_observed_without_logical_turn_totals_on_both_
let mut metrics = response_critical_path_event();
// 同帧即使携带整轮专项值,也不能与响应级 critical path 混算
metrics["timing_metrics"]["engine_service_total_ms"] = json!(25_000);
metrics["timing_metrics"]["engine_iapi_ttft_total_ms"] = json!(500);
let mut events = critical_path_response_events(metrics);
let mut wrong_id = response_critical_path_event();
wrong_id["timing_metrics"]["response_id"] = json!("resp_other");
@@ -208,10 +196,6 @@ async fn response_critical_path_is_observed_without_logical_turn_totals_on_both_
assert!((timings.upstream_api_overhead_ms.unwrap() - 81.409594).abs() < 0.000001);
assert_eq!(timings.upstream_response_ms, Some(7000));
assert_eq!(timings.first_token_ms, None);
assert_eq!(timings.upstream_engine_iapi_ttft_ms, None);
assert_eq!(timings.upstream_engine_service_ttft_ms, None);
assert_eq!(timings.upstream_engine_iapi_tbt_ms, None);
assert_eq!(timings.upstream_engine_service_tbt_ms, None);
}
}
@@ -252,12 +236,10 @@ async fn critical_path_rejects_mismatched_identity_and_incomplete_or_cumulative_
"timing_scope":"logical_turn",
"engine_service_total_ms":25_000,
"responses_duration_excl_engine_and_client_tool_time_ms":500,
"engine_iapi_ttft_total_ms":200
}});
let timings = observe_timing_events(false, critical_path_response_events(metrics)).await;
assert_eq!(timings.upstream_engine_ms, None);
assert_eq!(timings.upstream_api_overhead_ms, None);
assert_eq!(timings.upstream_engine_iapi_ttft_ms, None);
}
#[tokio::test]
@@ -288,10 +270,6 @@ async fn timing_frames_outside_the_active_response_do_not_enter_request_metrics(
let timing = json!({"type":"responsesapi.websocket_timing","timing_metrics":{
"responses_duration_excl_engine_and_client_tool_time_ms":0,
"engine_service_total_ms":450,
"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
}});
let created = json!({"type":"response.created","response":{"id":"resp_boundary"}});
let completed = json!({"type":"response.completed","response":{"id":"resp_boundary","status":"completed","output":[],"usage":{"input_tokens":1,"output_tokens":1,"total_tokens":2}}});
@@ -311,10 +289,6 @@ async fn timing_frames_outside_the_active_response_do_not_enter_request_metrics(
let timings = finish_timings(&mut stream, ProviderResponseTimings::default()).await;
assert_eq!(timings.upstream_api_overhead_ms, None);
assert_eq!(timings.upstream_engine_ms, None);
assert_eq!(timings.upstream_engine_iapi_ttft_ms, None);
assert_eq!(timings.upstream_engine_service_ttft_ms, None);
assert_eq!(timings.upstream_engine_iapi_tbt_ms, None);
assert_eq!(timings.upstream_engine_service_tbt_ms, None);
assert_eq!(timings.first_token_ms, None);
server.await.unwrap();
}
@@ -395,9 +369,10 @@ async fn structural_frames_start_ttft_before_content_on_http_and_websocket() {
socket,
|request: &tokio_tungstenite::tungstenite::handshake::server::Request,
response| {
assert_eq!(
request.headers()["x-responsesapi-include-timing-metrics"],
"true"
assert!(
!request
.headers()
.contains_key("x-responsesapi-include-timing-metrics")
);
response.headers_mut().insert(
"sec-websocket-extensions",
@@ -110,8 +110,7 @@ async fn official_websocket_wire_fingerprint_should_remain_aligned() {
opening.lines().next(),
Some("GET /backend-api/codex/responses HTTP/1.1")
);
// 固定身份字段沿用官方画像,专项计时头按官方客户端在 openai-beta 后插入
// HeaderMap 序列化会随新增头调整迭代顺序,锁定启用计时后的完整 opening
// 固定身份字段沿用官方画像,锁定默认不请求专项计时的完整 opening
assert_eq!(
read_header_names(&opening),
vec![
@@ -124,7 +123,7 @@ async fn official_websocket_wire_fingerprint_should_remain_aligned() {
"authorization",
"user-agent",
"originator",
"x-responsesapi-include-timing-metrics",
"openai-beta",
"version",
"x-codex-beta-features",
"x-client-request-id",
@@ -133,13 +132,12 @@ async fn official_websocket_wire_fingerprint_should_remain_aligned() {
"x-codex-window-id",
"x-codex-turn-metadata",
"x-codex-routing-hint",
"openai-beta",
"sec-websocket-extensions",
]
);
assert_eq!(
read_header_value(&opening, "x-responsesapi-include-timing-metrics"),
Some("true"),
None,
);
assert_eq!(
read_header_value(&opening, "sec-websocket-extensions"),
+1 -5
View File
@@ -2055,7 +2055,7 @@ OpenAI 仅使用同一条 `response.completed` 中的 `created_at` 与 `complete
`latencyDetails` 还可包含以下上游性能指标,单位为毫秒,保留上游返回的小数。
OpenAI 从当前响应的 `responsesapi.websocket_timing.timing_metrics` 读取,
WebSocket 握手默认请求专项计时,客户端显式提供的开关保留原值。
WebSocket 握手不主动添加专项计时请求头,客户端显式提供的开关保留原值。
各字段独立可选;响应开始前、终态后的计时和明确属于其他响应的事件不写入当前请求,重试时清空
`critical_path` 仅采集 `scope=response`、`coverage=complete` 且边界为
@@ -2067,10 +2067,6 @@ WebSocket 握手默认请求专项计时,客户端显式提供的开关保留
| --- | --- |
| `upstreamApiOverheadMs` | API 排除引擎与客户端工具时间后的耗时 |
| `upstreamEngineMs` | 响应级引擎耗时,取完整 critical path 的墙钟时间或直接返回的 Engine Service 时间 |
| `upstreamEngineIapiTtftMs` | Engine IAPI TTFT 总计 |
| `upstreamEngineServiceTtftMs` | Engine Service TTFT 总计 |
| `upstreamEngineIapiTbtMs` | 跨引擎调用的 IAPI Token 间隔 |
| `upstreamEngineServiceTbtMs` | 跨引擎调用的 Service Token 间隔 |
以上指标按上游内部口径展示,不相加重建总耗时,不替换请求级 `firstTokenLatencyMs`。
它们仅补充性能诊断,不改变列表与聚合统计的速率分母
-4
View File
@@ -59,10 +59,6 @@ export interface UsageLatencyDetails {
upstreamResponseMs?: number
upstreamApiOverheadMs?: number
upstreamEngineMs?: number
upstreamEngineIapiTtftMs?: number
upstreamEngineServiceTtftMs?: number
upstreamEngineIapiTbtMs?: number
upstreamEngineServiceTbtMs?: number
admissionDecisionMs?: number
accountSelectionWaitMs?: number
capacityUsedSlots?: number
@@ -197,10 +197,6 @@ export function usageLatencyDetails(record: UsageLatencyRecord) {
const performanceItems = [
{ label: 'API 开销', value: durationValue(latencyDetails?.upstreamApiOverheadMs) },
{ label: '引擎耗时', value: durationValue(latencyDetails?.upstreamEngineMs) },
{ label: 'TTFT · IAPI', value: durationValue(latencyDetails?.upstreamEngineIapiTtftMs) },
{ label: 'TTFT · Service', value: durationValue(latencyDetails?.upstreamEngineServiceTtftMs) },
{ label: 'Token 间隔 · IAPI', value: durationValue(latencyDetails?.upstreamEngineIapiTbtMs) },
{ label: 'Token 间隔 · Service', value: durationValue(latencyDetails?.upstreamEngineServiceTbtMs) },
]
for (const item of performanceItems) {
if (item.value !== null)