diff --git a/backend/crates/gateway-admin/src/model/observability.rs b/backend/crates/gateway-admin/src/model/observability.rs index 3744672fb..8752629e8 100644 --- a/backend/crates/gateway-admin/src/model/observability.rs +++ b/backend/crates/gateway-admin/src/model/observability.rs @@ -646,7 +646,7 @@ pub struct DashboardObservation { } /// 使用记录表格的窄读模型 -#[derive(Debug, Clone, PartialEq, Eq)] +#[derive(Debug, Clone, PartialEq)] pub struct UsageListRecord { pub client_api_key_name: Option, pub id: String, @@ -687,6 +687,13 @@ pub struct UsageListRecord { pub first_text_ms: Option, pub first_token_ms: Option, pub provider_processing_ms: Option, + pub upstream_response_ms: Option, + pub upstream_api_overhead_ms: Option, + pub upstream_engine_ms: Option, + pub upstream_engine_iapi_ttft_ms: Option, + pub upstream_engine_service_ttft_ms: Option, + pub upstream_engine_iapi_tbt_ms: Option, + pub upstream_engine_service_tbt_ms: Option, pub latency_ms: Option, pub admission_decision_ms: Option, pub account_selection_wait_ms: Option, @@ -702,7 +709,7 @@ pub struct UsageListRecord { } /// 一次完整模型请求的公共观测记录 -#[derive(Debug, Clone, PartialEq, Eq)] +#[derive(Debug, Clone, PartialEq)] pub struct UsageRecord { pub id: String, pub client_api_key_ref: String, @@ -761,6 +768,13 @@ pub struct UsageRecord { pub first_text_ms: Option, pub first_token_ms: Option, pub provider_processing_ms: Option, + pub upstream_response_ms: Option, + pub upstream_api_overhead_ms: Option, + pub upstream_engine_ms: Option, + pub upstream_engine_iapi_ttft_ms: Option, + pub upstream_engine_service_ttft_ms: Option, + pub upstream_engine_iapi_tbt_ms: Option, + pub upstream_engine_service_tbt_ms: Option, pub latency_ms: Option, pub admission_decision_ms: Option, pub account_selection_wait_ms: Option, @@ -781,7 +795,7 @@ pub struct UsageRecord { } /// 用量分页结果 -#[derive(Debug, Clone, PartialEq, Eq)] +#[derive(Debug, Clone, PartialEq)] pub struct UsagePage { pub items: Vec, pub current_page: u32, @@ -827,7 +841,7 @@ pub struct UsageAttempt { } /// 一条请求及其全部尝试 -#[derive(Debug, Clone, PartialEq, Eq)] +#[derive(Debug, Clone, PartialEq)] pub struct UsageDetail { pub trace: Option, pub related_requests: Vec, diff --git a/backend/crates/gateway-admin/tests/use_case/observability.rs b/backend/crates/gateway-admin/tests/use_case/observability.rs index 249263768..29b6150dd 100644 --- a/backend/crates/gateway-admin/tests/use_case/observability.rs +++ b/backend/crates/gateway-admin/tests/use_case/observability.rs @@ -1138,6 +1138,13 @@ fn total_record( first_text_ms: None, first_token_ms: None, provider_processing_ms: None, + 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, diff --git a/backend/crates/gateway-api/src/admin/observability/presenter.rs b/backend/crates/gateway-api/src/admin/observability/presenter.rs index a33855d27..1528e268c 100644 --- a/backend/crates/gateway-api/src/admin/observability/presenter.rs +++ b/backend/crates/gateway-api/src/admin/observability/presenter.rs @@ -307,8 +307,14 @@ pub(crate) fn usage_list_record_view( first_event_ms: record.first_event_ms, first_reasoning_ms: record.first_reasoning_ms, first_text_ms: record.first_text_ms, - first_token_ms: record.first_token_ms, openai_processing_ms: record.provider_processing_ms, + 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, @@ -345,7 +351,6 @@ pub(crate) fn usage_record_view( .error_message .clone() .unwrap_or_else(|| outcome.clone()); - let first_token_display = display_duration(record.first_token_ms); let latency_display = display_duration(record.latency_ms); let cost_coverage = match record.cost_source.as_str() { "provider_reported" | "calculated" => CostCoverageView { @@ -409,15 +414,20 @@ pub(crate) fn usage_record_view( first_event_ms: record.first_event_ms, first_reasoning_ms: record.first_reasoning_ms, first_text_ms: record.first_text_ms, - first_token_ms: record.first_token_ms, openai_processing_ms: record.provider_processing_ms, + 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), response_id: record.client_response_id, upstream_request_id: record.upstream_request_id, latency_ms: record.latency_ms, - first_token_ms: record.first_token_ms, input_tokens: record.input_tokens, output_tokens: record.output_tokens, cached_tokens: record.cached_tokens, @@ -441,7 +451,6 @@ pub(crate) fn usage_record_view( costs, cost_coverage, first_token_latency_ms: record.first_token_ms, - first_token_latency_ms_display: first_token_display, latency_ms_display: latency_display, logical_outcome: outcome, } @@ -756,7 +765,7 @@ pub(crate) fn trend_summary_view( ratio: None, }, TrendSummaryView { - label: "吞吐 P50".to_owned(), + label: "速率 P50".to_owned(), value: summary .minimum_output_throughput_p50 .map_or_else(|| "—".to_owned(), |value| format!("{value} tok/s")), diff --git a/backend/crates/gateway-api/src/admin/observability/wire.rs b/backend/crates/gateway-api/src/admin/observability/wire.rs index ab95a494b..c32ad1edc 100644 --- a/backend/crates/gateway-api/src/admin/observability/wire.rs +++ b/backend/crates/gateway-api/src/admin/observability/wire.rs @@ -160,7 +160,6 @@ pub struct UsageRecordView { pub response_id: Option, pub upstream_request_id: Option, pub latency_ms: Option, - pub first_token_ms: Option, pub input_tokens: Option, pub output_tokens: Option, pub cached_tokens: Option, @@ -185,7 +184,6 @@ pub struct UsageRecordView { pub costs: Vec, pub cost_coverage: CostCoverageView, pub first_token_latency_ms: Option, - pub first_token_latency_ms_display: String, pub latency_ms_display: String, pub logical_outcome: String, } @@ -222,9 +220,21 @@ pub struct UsageLatencyDetailsView { #[serde(skip_serializing_if = "Option::is_none")] pub first_text_ms: Option, #[serde(skip_serializing_if = "Option::is_none")] - pub first_token_ms: Option, - #[serde(skip_serializing_if = "Option::is_none")] pub openai_processing_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + pub upstream_response_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + pub upstream_api_overhead_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + pub upstream_engine_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + pub upstream_engine_iapi_ttft_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + pub upstream_engine_service_ttft_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + pub upstream_engine_iapi_tbt_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + pub upstream_engine_service_tbt_ms: Option, } /// 单次上游尝试展示 diff --git a/backend/crates/gateway-api/src/key_usage/presenter.rs b/backend/crates/gateway-api/src/key_usage/presenter.rs index 89f867555..1b44d3c4e 100644 --- a/backend/crates/gateway-api/src/key_usage/presenter.rs +++ b/backend/crates/gateway-api/src/key_usage/presenter.rs @@ -201,6 +201,20 @@ pub(super) struct RecordView { #[derive(Default, Serialize)] #[serde(rename_all = "camelCase")] struct OutputTimingView { + #[serde(skip_serializing_if = "Option::is_none")] + upstream_response_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + upstream_api_overhead_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + upstream_engine_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + upstream_engine_iapi_ttft_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + upstream_engine_service_ttft_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + upstream_engine_iapi_tbt_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + upstream_engine_service_tbt_ms: Option, #[serde(skip_serializing_if = "Option::is_none")] first_event_ms: Option, #[serde(skip_serializing_if = "Option::is_none")] @@ -226,6 +240,13 @@ fn success_record(value: UsageListRecord, time: crate::time::TimePresenter) -> R latency_ms: value.latency_ms, first_token_latency_ms: value.first_token_ms, latency_details: OutputTimingView { + 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, diff --git a/backend/crates/gateway-api/tests/admin/observability/response.rs b/backend/crates/gateway-api/tests/admin/observability/response.rs index 5c431aad6..2e4af8753 100644 --- a/backend/crates/gateway-api/tests/admin/observability/response.rs +++ b/backend/crates/gateway-api/tests/admin/observability/response.rs @@ -233,6 +233,22 @@ async fn usage_detail_should_keep_attempt_snapshot_contract() { let fixture = AdminTestFixture::new().await; fixture.auth.insert_session("valid-session"); let now = Utc::now(); + let mut record = usage_record_with_account( + "req_detail", + "acct_snap_a", + "Snapshot Alpha", + "alpha@example.invalid", + "oauth", + now, + ); + record.first_token_ms = Some(20); + 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() @@ -240,14 +256,7 @@ async fn usage_detail_should_keep_attempt_snapshot_contract() { .replace(UsageDetail { trace: None, related_requests: Vec::new(), - request: usage_record_with_account( - "req_detail", - "acct_snap_a", - "Snapshot Alpha", - "alpha@example.invalid", - "oauth", - now, - ), + request: record, attempts: vec![UsageAttempt { source: "ops_event".to_owned(), id: "ops_detail".to_owned(), @@ -300,6 +309,39 @@ async fn usage_detail_should_keep_attempt_snapshot_contract() { .await .expect("usage detail body"); let value: serde_json::Value = serde_json::from_slice(&body).expect("usage detail JSON"); + assert_eq!(value["data"]["firstTokenLatencyMs"], 20); + assert_eq!(value["data"]["latencyDetails"]["upstreamResponseMs"], 1_000); + assert_eq!( + value["data"]["latencyDetails"]["upstreamApiOverheadMs"], + json!(120.25) + ); + assert_eq!( + 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!( + value["data"]["latencyDetails"] + .get("firstTokenMs") + .is_none() + ); assert_eq!( serde_json::json!({ "accountId": value["data"]["accountId"], @@ -702,6 +744,13 @@ fn usage_record_with_account( first_text_ms: None, first_token_ms: None, provider_processing_ms: None, + 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, @@ -834,6 +883,13 @@ async fn usage_route_should_expose_table_facts_without_detail_payload() { first_text_ms: Some(19), first_token_ms: Some(20), provider_processing_ms: Some(21), + 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), @@ -970,8 +1026,8 @@ async fn usage_route_should_expose_table_facts_without_detail_payload() { "firstEventMs": 17, "firstReasoningMs": 18, "firstTextMs": 19, - "firstTokenMs": 20, "openaiProcessingMs": 21, + "upstreamResponseMs": 2000, }, "firstTokenLatencyMs": 20, "latencyMs": 31, diff --git a/backend/crates/gateway-api/tests/key_usage/fixtures.rs b/backend/crates/gateway-api/tests/key_usage/fixtures.rs index 4d3a046d4..a555db33e 100644 --- a/backend/crates/gateway-api/tests/key_usage/fixtures.rs +++ b/backend/crates/gateway-api/tests/key_usage/fixtures.rs @@ -135,6 +135,13 @@ fn usage_record() -> UsageListRecord { first_text_ms: Some(600), first_token_ms: Some(210), 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, latency_ms: Some(1250), admission_decision_ms: None, account_selection_wait_ms: None, diff --git a/backend/crates/gateway-api/tests/key_usage/mod.rs b/backend/crates/gateway-api/tests/key_usage/mod.rs index 691e6f07f..2e1622a8a 100644 --- a/backend/crates/gateway-api/tests/key_usage/mod.rs +++ b/backend/crates/gateway-api/tests/key_usage/mod.rs @@ -305,9 +305,20 @@ async fn records_keep_pagination_and_hide_admin_and_upstream_data() { assert_eq!(record["firstTokenLatencyMs"], 210); assert_fields( &record["latencyDetails"], - &["firstEventMs", "firstReasoningMs", "firstTextMs"], + &[ + "upstreamResponseMs", + "upstreamEngineIapiTbtMs", + "firstEventMs", + "firstReasoningMs", + "firstTextMs", + ], ); assert_eq!(record["latencyDetails"]["firstEventMs"], 100); + assert_eq!(record["latencyDetails"]["upstreamResponseMs"], 1000); + assert_eq!( + record["latencyDetails"]["upstreamEngineIapiTbtMs"], + 2.450638 + ); assert!(record["statusCode"].is_null()); } else { assert_eq!(record["statusCode"], 502); diff --git a/backend/crates/gateway-core/src/engine/mod.rs b/backend/crates/gateway-core/src/engine/mod.rs index 34893182b..64636af8f 100644 --- a/backend/crates/gateway-core/src/engine/mod.rs +++ b/backend/crates/gateway-core/src/engine/mod.rs @@ -878,8 +878,8 @@ pub struct ProbeFailure { pub latency: Duration, } -/// `model_requests` 可用的毫秒级阶段耗时 -#[derive(Debug, Clone, Default, PartialEq, Eq)] +/// 请求与上游响应的耗时事实，统一以毫秒保存但不提高来源精度 +#[derive(Debug, Clone, Default, PartialEq)] pub struct ModelRequestTimings { pub transport_decision_wait_ms: Option, pub connect_ms: Option, @@ -889,6 +889,13 @@ pub struct ModelRequestTimings { pub first_text_ms: Option, pub first_token_ms: Option, pub provider_processing_ms: Option, + pub upstream_response_ms: Option, + pub upstream_api_overhead_ms: Option, + pub upstream_engine_ms: Option, + pub upstream_engine_iapi_ttft_ms: Option, + pub upstream_engine_service_ttft_ms: Option, + pub upstream_engine_iapi_tbt_ms: Option, + pub upstream_engine_service_tbt_ms: Option, pub latency_ms: Option, } diff --git a/backend/crates/gateway-core/src/engine/observation.rs b/backend/crates/gateway-core/src/engine/observation.rs index 700b81e4d..3a2e34cc2 100644 --- a/backend/crates/gateway-core/src/engine/observation.rs +++ b/backend/crates/gateway-core/src/engine/observation.rs @@ -237,7 +237,7 @@ pub enum RequestObservationOutcome { } /// Core 在业务结果确定后产生的一次最终观察，不包含原始正文或凭据 -#[derive(Debug, Clone, PartialEq, Eq)] +#[derive(Debug, Clone, PartialEq)] pub struct RequestObservation { event_id: String, request_id: ModelRequestId, @@ -768,8 +768,6 @@ impl ResponseObservation { } pub(super) fn observe_event(&mut self, event: &GatewayEvent) { - let elapsed = self.elapsed_ms(); - observe_event_timing(&mut self.timings, event, elapsed); if let GatewayEvent::Usage(observed) = event { self.usage.merge(observed); } @@ -806,6 +804,13 @@ impl ResponseObservation { self.timings.first_text_ms = None; self.timings.first_token_ms = None; self.timings.provider_processing_ms = None; + 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) { @@ -834,26 +839,26 @@ impl ResponseObservation { if let Some(value) = observed.provider_processing_ms { self.timings.provider_processing_ms = Some(value); } - } -} - -fn observe_event_timing(timings: &mut ModelRequestTimings, event: &GatewayEvent, elapsed_ms: u64) { - timings.first_event_ms.get_or_insert(elapsed_ms); - match event { - GatewayEvent::ReasoningDelta(delta) if !delta.text.is_empty() => { - timings.first_reasoning_ms.get_or_insert(elapsed_ms); - timings.first_token_ms.get_or_insert(elapsed_ms); + if let Some(value) = observed.upstream_response_ms { + self.timings.upstream_response_ms = Some(value); } - GatewayEvent::TextDelta(delta) if !delta.text.is_empty() => { - timings.first_text_ms.get_or_insert(elapsed_ms); - timings.first_token_ms.get_or_insert(elapsed_ms); + if let Some(value) = observed.upstream_api_overhead_ms { + self.timings.upstream_api_overhead_ms = Some(value); } - // `response.output_item.added` 会先投影一个空参数的 tool delta；它只是结构帧， - // 不能抢在真实工具参数之前成为首个可消费 token - GatewayEvent::ToolCallDelta(delta) if !delta.arguments_delta.is_empty() => { - timings.first_token_ms.get_or_insert(elapsed_ms); + 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); } - GatewayEvent::CalculatedCost(_) | GatewayEvent::ProviderCost(_) => {} - _ => {} } } diff --git a/backend/crates/gateway-core/src/event.rs b/backend/crates/gateway-core/src/event.rs index 2e43deac5..099dc87e6 100644 --- a/backend/crates/gateway-core/src/event.rs +++ b/backend/crates/gateway-core/src/event.rs @@ -479,12 +479,14 @@ impl UpstreamHttpVersion { } } -/// Provider transport 边界测得的时间 +/// Provider transport 观测与上游返回的响应耗时 /// /// `first_*_ms` 是相对 `AttemptContext::timing_started_at()` 的请求级偏移， -/// 与 Core 总耗时使用同一起点并包含选号与重试等待；其余字段是各阶段独立耗时 +/// 与 Core 总耗时使用同一起点并包含选号与重试等待 +/// `upstream_response_ms` 使用上游的响应计时边界，其余字段是各阶段独立耗时 +/// 首事件与输出阶段时间由 Provider 独占采集，Core 不从 canonical 事件补记 /// 首字边界由 Provider 协议定义，缺失时保留 `None`，不使用首包代替 -#[derive(Debug, Clone, Copy, Default, PartialEq, Eq)] +#[derive(Debug, Clone, Copy, Default, PartialEq)] pub struct ProviderResponseTimings { pub transport_decision_wait_ms: Option, pub connect_ms: Option, @@ -494,6 +496,16 @@ pub struct ProviderResponseTimings { pub first_text_ms: Option, pub first_token_ms: Option, pub provider_processing_ms: Option, + /// 上游返回的单次响应创建到完成耗时，不使用本地时钟补齐 + pub upstream_response_ms: Option, + /// 上游排除引擎与客户端工具时间后的 API 耗时 + pub upstream_api_overhead_ms: Option, + /// 上游引擎服务总耗时；以下专项指标保留毫秒小数及各自内部计量层级 + pub upstream_engine_ms: Option, + pub upstream_engine_iapi_ttft_ms: Option, + pub upstream_engine_service_ttft_ms: Option, + pub upstream_engine_iapi_tbt_ms: Option, + pub upstream_engine_service_tbt_ms: Option, } /// Provider 已筛选的响应观测 JSON @@ -572,7 +584,7 @@ impl fmt::Debug for ProviderResponseHeader { } /// Core 消费的 Provider 执行观测，不会原样进入客户端响应 -#[derive(Debug, Clone, PartialEq, Eq)] +#[derive(Debug, Clone, PartialEq)] pub struct ProviderResponseObservation { transport: UpstreamTransport, http_version: Option, diff --git a/backend/crates/gateway-core/tests/engine/coordinator.rs b/backend/crates/gateway-core/tests/engine/coordinator.rs index c6eed28ef..7b41085e4 100644 --- a/backend/crates/gateway-core/tests/engine/coordinator.rs +++ b/backend/crates/gateway-core/tests/engine/coordinator.rs @@ -51,7 +51,7 @@ use gateway_core::routing::{ use gateway_core::upstream::{UpstreamSendState, UpstreamTransport}; use serde_json::{Map, Value, json}; -#[derive(Debug, Clone, PartialEq, Eq)] +#[derive(Debug, Clone, PartialEq)] struct FinalState { error_kind: Option, diagnostic_trace_json: Option, @@ -85,6 +85,13 @@ struct FinalState { first_text_ms: Option, first_token_ms: Option, provider_processing_ms: Option, + upstream_response_ms: Option, + upstream_api_overhead_ms: Option, + upstream_engine_ms: Option, + upstream_engine_iapi_ttft_ms: Option, + upstream_engine_service_ttft_ms: Option, + upstream_engine_iapi_tbt_ms: Option, + upstream_engine_service_tbt_ms: Option, provider_metadata_json: Option, cost_source: CostSource, cost_ticks: Option, @@ -253,6 +260,15 @@ impl ExecutionStore for FakeStore { first_text_ms: finalization.timings.first_text_ms, first_token_ms: finalization.timings.first_token_ms, provider_processing_ms: finalization.timings.provider_processing_ms, + 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 @@ -1510,7 +1526,7 @@ fn empty_tool_call_delta_should_not_preempt_provider_first_token_timing() { } #[test] -fn empty_content_deltas_do_not_create_first_token_timings() { +fn canonical_output_does_not_invent_missing_provider_timings() { let operation = generate_operation(); let route_plan = plan(&operation); let mut items = complete_stream(None); @@ -1523,7 +1539,7 @@ fn empty_content_deltas_do_not_create_first_token_timings() { ))), Ok(GatewayEvent::TextDelta(gateway_core::event::TextDelta { content_index: 0, - text: String::new(), + text: "real content".to_owned(), })), Ok(GatewayEvent::ContentAdded(ContentItem::new( 1, @@ -1532,7 +1548,7 @@ fn empty_content_deltas_do_not_create_first_token_timings() { Ok(GatewayEvent::ReasoningDelta( gateway_core::event::ReasoningDelta { content_index: 1, - text: String::new(), + text: "real content".to_owned(), }, )), ], @@ -1555,7 +1571,7 @@ fn empty_content_deltas_do_not_create_first_token_timings() { let state = store.state.lock().unwrap(); let timings = &state.finalizations[0]; - assert!(timings.first_event_ms.is_some()); + assert_eq!(timings.first_event_ms, None); assert_eq!( ( timings.first_token_ms, @@ -1629,6 +1645,13 @@ fn discarded_attempt_observation_does_not_leak_into_retry_result() { headers_ms: Some(13), first_event_ms: Some(987_654), provider_processing_ms: Some(41), + 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( @@ -1719,17 +1742,20 @@ fn discarded_attempt_observation_does_not_leak_into_retry_result() { assert_eq!(finalization.connect_ms, None); assert_eq!(finalization.headers_ms, None); assert_eq!(finalization.provider_processing_ms, None); + 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!( contexts[0].timing_started_at(), contexts[1].timing_started_at() ); - assert!( - finalization - .first_event_ms - .is_some_and(|elapsed| elapsed < 987_654) - ); + assert_eq!(finalization.first_event_ms, None); assert_eq!(state.intermediate_status_codes, vec![Some(504)]); assert_eq!( state.intermediate_request_ids, diff --git a/backend/crates/gateway-plugin/runtime/src/adapter/observer.rs b/backend/crates/gateway-plugin/runtime/src/adapter/observer.rs index 782006158..31a7a0549 100644 --- a/backend/crates/gateway-plugin/runtime/src/adapter/observer.rs +++ b/backend/crates/gateway-plugin/runtime/src/adapter/observer.rs @@ -553,6 +553,13 @@ fn wire_timings(observation: &RequestObservation) -> RequestTimings { first_text_ms: timings.first_text_ms, first_token_ms: timings.first_token_ms, provider_processing_ms: timings.provider_processing_ms, + 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, } } diff --git a/backend/crates/gateway-plugin/runtime/src/callback/facts.rs b/backend/crates/gateway-plugin/runtime/src/callback/facts.rs index 91cf267fe..5cfa803cf 100644 --- a/backend/crates/gateway-plugin/runtime/src/callback/facts.rs +++ b/backend/crates/gateway-plugin/runtime/src/callback/facts.rs @@ -129,6 +129,13 @@ fn observation(value: &ProviderResponseObservation) -> facts::ResponseObservatio first_text_ms: timings.first_text_ms, first_token_ms: timings.first_token_ms, provider_processing_ms: timings.provider_processing_ms, + 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 diff --git a/backend/crates/gateway-plugin/runtime/tests/generation/observer.rs b/backend/crates/gateway-plugin/runtime/tests/generation/observer.rs index 1537fa9f4..43ef9f4a6 100644 --- a/backend/crates/gateway-plugin/runtime/tests/generation/observer.rs +++ b/backend/crates/gateway-plugin/runtime/tests/generation/observer.rs @@ -790,6 +790,8 @@ 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), latency_ms: Some(34), ..ModelRequestTimings::default() }), @@ -802,6 +804,11 @@ async fn completed_observation_contains_terminal_cost_timings_and_failure() { assert_eq!(observed["usage"]["cost"]["total"]["amount"], "0.0123"); 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"]["latency_ms"], 34); assert_eq!(observed["usage"]["failure"]["outcome"], "failed"); assert_eq!(observed["usage"]["failure"]["attempt_count"], 2); diff --git a/backend/crates/gateway-plugin/runtime/tests/generation/policy/facts/mod.rs b/backend/crates/gateway-plugin/runtime/tests/generation/policy/facts/mod.rs index 31d74a8da..f497c01c3 100644 --- a/backend/crates/gateway-plugin/runtime/tests/generation/policy/facts/mod.rs +++ b/backend/crates/gateway-plugin/runtime/tests/generation/policy/facts/mod.rs @@ -99,6 +99,8 @@ 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), ..Default::default() }), ); @@ -184,6 +186,14 @@ async fn facts_are_readable_without_replacing_or_duplicating_the_original_execut "{\"private_field\":\"kept\"}" ); assert_eq!(facts["observation"]["timings"]["headers_ms"], 19); + assert_eq!( + facts["observation"]["timings"]["upstream_engine_iapi_tbt_ms"], + 2.450638 + ); + assert_eq!( + facts["observation"]["timings"]["upstream_response_ms"], + 7_000 + ); assert_eq!( facts["session_update"]["payload"]["cursor"], "private-cursor" diff --git a/backend/crates/gateway-plugin/runtime/tests/support/environment.rs b/backend/crates/gateway-plugin/runtime/tests/support/environment.rs index c61b1b789..389325ee1 100644 --- a/backend/crates/gateway-plugin/runtime/tests/support/environment.rs +++ b/backend/crates/gateway-plugin/runtime/tests/support/environment.rs @@ -746,7 +746,7 @@ impl Environment { pub async fn bound_model_requests(&self, client_key_id: &str) -> Vec<(String, String)> { sqlx::query_as(sqlx::AssertSqlSafe(format!( - "select request_kind, subagent_kind from {}.model_requests + "select request_kind, subagent_kind from {}.model_request_observations where client_api_key_ref = $1 order by started_at, id", self.schema ))) diff --git a/backend/crates/gateway-plugin/sdk/src/call/model/facts.rs b/backend/crates/gateway-plugin/sdk/src/call/model/facts.rs index 3eaad56d5..8957f8b9b 100644 --- a/backend/crates/gateway-plugin/sdk/src/call/model/facts.rs +++ b/backend/crates/gateway-plugin/sdk/src/call/model/facts.rs @@ -66,7 +66,7 @@ pub struct ImageCostBreakdown { pub cache_read_price_per_million: RequestMoney, } -#[derive(Clone, PartialEq, Eq, Serialize, Deserialize)] +#[derive(Clone, PartialEq, Serialize, Deserialize)] #[serde(deny_unknown_fields)] pub struct ResponseObservation { pub transport: String, diff --git a/backend/crates/gateway-plugin/sdk/src/call/observation.rs b/backend/crates/gateway-plugin/sdk/src/call/observation.rs index 9b7a8a2c8..ae7b43424 100644 --- a/backend/crates/gateway-plugin/sdk/src/call/observation.rs +++ b/backend/crates/gateway-plugin/sdk/src/call/observation.rs @@ -14,7 +14,7 @@ pub enum EventKind { } /// 元数据在 RPC 参数中传递；WebSocket 原始帧独立放在二进制载荷中 -#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)] +#[derive(Debug, Clone, PartialEq, Serialize, Deserialize)] #[serde( tag = "event", content = "data", @@ -83,8 +83,8 @@ pub struct RequestCost { pub total: Option, } -/// 用量观察取得的毫秒级阶段耗时；缺失字段表示宿主没有该项事实 -#[derive(Debug, Clone, Default, PartialEq, Eq, Serialize, Deserialize)] +/// 用量观察取得的请求与上游响应耗时，毫秒单位不代表来源精度 +#[derive(Debug, Clone, Default, PartialEq, Serialize, Deserialize)] #[serde(deny_unknown_fields)] pub struct RequestTimings { #[serde(default, skip_serializing_if = "Option::is_none")] @@ -104,6 +104,20 @@ pub struct RequestTimings { #[serde(default, skip_serializing_if = "Option::is_none")] pub provider_processing_ms: Option, #[serde(default, skip_serializing_if = "Option::is_none")] + pub upstream_response_ms: Option, + #[serde(default, skip_serializing_if = "Option::is_none")] + pub upstream_api_overhead_ms: Option, + #[serde(default, skip_serializing_if = "Option::is_none")] + pub upstream_engine_ms: Option, + #[serde(default, skip_serializing_if = "Option::is_none")] + pub upstream_engine_iapi_ttft_ms: Option, + #[serde(default, skip_serializing_if = "Option::is_none")] + pub upstream_engine_service_ttft_ms: Option, + #[serde(default, skip_serializing_if = "Option::is_none")] + pub upstream_engine_iapi_tbt_ms: Option, + #[serde(default, skip_serializing_if = "Option::is_none")] + pub upstream_engine_service_tbt_ms: Option, + #[serde(default, skip_serializing_if = "Option::is_none")] pub latency_ms: Option, } @@ -138,7 +152,7 @@ pub struct RequestTerminal { } /// 用量观察取得的最终标准化用量；缺失字段表示宿主没有该项事实 -#[derive(Debug, Clone, Default, PartialEq, Eq, Serialize, Deserialize)] +#[derive(Debug, Clone, Default, PartialEq, Serialize, Deserialize)] #[serde(deny_unknown_fields)] pub struct RequestUsage { #[serde(default, skip_serializing_if = "Option::is_none")] @@ -166,7 +180,7 @@ pub struct RequestUsage { } /// 一次完成事件包含宿主已确认的全部终态、用量、费用与耗时 -#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)] +#[derive(Debug, Clone, PartialEq, Serialize, Deserialize)] #[serde(deny_unknown_fields)] pub struct RequestCompleted { /// 不重投时仍保持稳定，供插件自行去重和关联日志 diff --git a/backend/crates/gateway-plugin/sdk/tests/call/observation.rs b/backend/crates/gateway-plugin/sdk/tests/call/observation.rs index 11f6224f7..592c06c85 100644 --- a/backend/crates/gateway-plugin/sdk/tests/call/observation.rs +++ b/backend/crates/gateway-plugin/sdk/tests/call/observation.rs @@ -203,12 +203,14 @@ 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), latency_ms: Some(34), ..RequestTimings::default() }; assert_eq!( serde_json::to_value(&timings).unwrap(), - json!({"first_text_ms":12,"latency_ms":34}) + json!({"first_text_ms":12,"upstream_response_ms":7000,"upstream_engine_iapi_tbt_ms":2.450638,"latency_ms":34}) ); let failure = RequestFailure { diff --git a/backend/crates/gateway-store/src/postgres/execution.rs b/backend/crates/gateway-store/src/postgres/execution/mod.rs similarity index 85% rename from backend/crates/gateway-store/src/postgres/execution.rs rename to backend/crates/gateway-store/src/postgres/execution/mod.rs index dbc0a5f36..870085771 100644 --- a/backend/crates/gateway-store/src/postgres/execution.rs +++ b/backend/crates/gateway-store/src/postgres/execution/mod.rs @@ -24,6 +24,10 @@ use crate::{ ConflictKind, DecimalAmount, StoreError, StoreResult, postgres_unavailable, require_nonempty, }; +mod request_observation; + +use request_observation::RequestObservation; + const ENTITY: &str = "model request"; #[derive(Debug, Clone, Copy, PartialEq, Eq)] @@ -234,7 +238,6 @@ fn validate_timings(timings: &ModelRequestTimings) -> StoreResult<()> { timings.first_reasoning_ms, timings.first_text_ms, timings.first_token_ms, - timings.provider_processing_ms, ]; if phases.into_iter().flatten().any(|phase| phase > total) { return Err(invalid("timing phase exceeds total latency")); @@ -243,7 +246,7 @@ fn validate_timings(timings: &ModelRequestTimings) -> StoreResult<()> { Ok(()) } -#[derive(Debug, Clone, PartialEq, Eq)] +#[derive(Debug, Clone, PartialEq)] pub struct ModelRequestFinalization { pub billing_snapshot_json: Option, pub model_request_id: String, @@ -422,51 +425,27 @@ impl PgExecutionStore { impl ModelRequestRepository for PgExecutionStore { async fn insert_model_request(&self, request: NewModelRequest) -> StoreResult<()> { request.validate()?; + let observation = RequestObservation::initial(&request)?; sqlx::query( "insert into model_requests ( - id, client_api_key_id, client_api_key_ref, config_revision, protocol, - routing_scope, routing_group_refs, routing_group_names_snapshot, - operation, endpoint, client_transport, requested_model_id, - client_ip, user_agent, reasoning_effort, - reasoning_preset, request_kind, subagent_kind, compact, - image_generation_requested, admission_decision_ms, started_at, deadline_at, - continuation_affinity_hash, continuation_previous_response_id_hash, - continuation_requested - ) values ( - $1, $2, $3, $4, $5, $6, $7, $8, - $9, $10, $11, $12, $13::inet, $14, $15, - $16, $17, $18, $19, $20, $21, $22, $23, $24, $25, $26 - )", + id, client_api_key_id, client_api_key_ref, operation, client_transport, + requested_model_id, image_generation_requested, started_at, deadline_at, + continuation_affinity_hash, continuation_requested, request_kind, request_observation_json + ) values ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13)", ) .bind(request.id) .bind(request.client_api_key_id) .bind(request.client_api_key_ref) - .bind(to_i64(request.config_revision, "config_revision")?) - .bind(request.protocol) - .bind(request.routing_scope) - .bind(request.routing_group_refs) - .bind(sqlx::types::Json(request.routing_group_names_snapshot)) .bind(request.operation) - .bind(request.endpoint) .bind(request.client_transport) .bind(request.requested_model_id) - .bind(request.client_ip) - .bind(request.user_agent) - .bind(request.reasoning_effort) - .bind(request.reasoning_preset) - .bind(request.request_kind) - .bind(request.subagent_kind) - .bind(request.compact) .bind(request.image_generation_requested) - .bind(optional_i64( - request.admission_decision_ms, - "admission_decision_ms", - )?) .bind(request.started_at) .bind(request.deadline_at) .bind(request.continuation.affinity_hash) - .bind(request.continuation.previous_response_id_hash) .bind(request.continuation.requested) + .bind(request.request_kind) + .bind(observation) .execute(&self.pool) .await .map_err(|source| postgres_unavailable("insert model request", source))?; @@ -483,58 +462,40 @@ impl ModelRequestRepository for PgExecutionStore { if attempt.attempt_count != 1 || attempt.model_request_id != request.id { return Err(invalid("first attempt must target the inserted request")); } + let observation = RequestObservation::initial(&request)?; sqlx::query( "insert into model_requests ( - id, client_api_key_id, client_api_key_ref, config_revision, protocol, - routing_scope, routing_group_refs, routing_group_names_snapshot, - operation, endpoint, client_transport, requested_model_id, - client_ip, user_agent, reasoning_effort, - reasoning_preset, request_kind, subagent_kind, compact, - image_generation_requested, admission_decision_ms, started_at, deadline_at, - provider_kind, provider_account_id, provider_account_ref, - provider_account_name_snapshot, provider_account_email_snapshot, - provider_account_authentication_kind_snapshot, - upstream_model_id, upstream_transport, http_version, - attempt_count, upstream_send_state, account_selection_wait_ms, - capacity_used_slots, capacity_total_slots - , continuation_affinity_hash, continuation_previous_response_id_hash, - continuation_requested - ) select - $1, $2, $3, $4, $5, $6, $7, $8, - $9, $10, $11, $12, $13::inet, $14, $15, - $16, $17, $18, $19, $20, $21, $22, $23, - $24, $25, $26, - account.name, account.email, account.authentication_kind, - $27, $28, $29, 1, 'not_sent', $30, $31, $32, $33, $34, $35 + id, client_api_key_id, client_api_key_ref, operation, client_transport, + requested_model_id, image_generation_requested, started_at, deadline_at, + continuation_affinity_hash, continuation_requested, request_kind, request_observation_json, + provider_kind, provider_account_id, provider_account_ref, upstream_model_id, + upstream_transport, attempt_count, upstream_send_state + ) select $1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, + $13::jsonb || jsonb_build_object( + 'account', jsonb_strip_nulls(jsonb_build_object( + 'name', account.name, 'email', account.email, + 'authenticationKind', account.authentication_kind)), + 'transport', jsonb_strip_nulls(jsonb_build_object('httpVersion', $19::text)), + 'scheduling', ($13::jsonb -> 'scheduling') || jsonb_strip_nulls(jsonb_build_object( + 'accountSelectionWaitMs', $20::bigint, + 'capacityUsedSlots', $21::bigint, 'capacityTotalSlots', $22::bigint))), + $14, $15, $16, $17, $18, 1, 'not_sent' from (values (true)) as seed(present) - left join provider_accounts account on account.id = $25", + left join provider_accounts account on account.id = $15", ) .bind(request.id) .bind(request.client_api_key_id) .bind(request.client_api_key_ref) - .bind(to_i64(request.config_revision, "config_revision")?) - .bind(request.protocol) - .bind(request.routing_scope) - .bind(request.routing_group_refs) - .bind(sqlx::types::Json(request.routing_group_names_snapshot)) .bind(request.operation) - .bind(request.endpoint) .bind(request.client_transport) .bind(request.requested_model_id) - .bind(request.client_ip) - .bind(request.user_agent) - .bind(request.reasoning_effort) - .bind(request.reasoning_preset) - .bind(request.request_kind) - .bind(request.subagent_kind) - .bind(request.compact) .bind(request.image_generation_requested) - .bind(optional_i64( - request.admission_decision_ms, - "admission_decision_ms", - )?) .bind(request.started_at) .bind(request.deadline_at) + .bind(request.continuation.affinity_hash) + .bind(request.continuation.requested) + .bind(request.request_kind) + .bind(observation) .bind(attempt.provider_kind) .bind(attempt.provider_account_id) .bind(attempt.provider_account_ref) @@ -553,9 +514,6 @@ impl ModelRequestRepository for PgExecutionStore { attempt.capacity_total_slots, "capacity_total_slots", )?) - .bind(request.continuation.affinity_hash) - .bind(request.continuation.previous_response_id_hash) - .bind(request.continuation.requested) .execute(&self.pool) .await .map_err(|source| { @@ -577,22 +535,20 @@ impl ModelRequestRepository for PgExecutionStore { set provider_kind = $2, provider_account_id = $3, provider_account_ref = $4, - (provider_account_name_snapshot, - provider_account_email_snapshot, - provider_account_authentication_kind_snapshot) = ( - select name, email, authentication_kind - from provider_accounts where id = $3 - ), upstream_model_id = $5, upstream_transport = $6, - http_version = $7, attempt_count = $8, - account_selection_wait_ms = case - when $9::bigint is null then account_selection_wait_ms - else coalesce(account_selection_wait_ms, 0) + $9 - end, - capacity_used_slots = coalesce($10, capacity_used_slots), - capacity_total_slots = coalesce($11, capacity_total_slots) + request_observation_json = request_observation_json || jsonb_build_object( + 'account', coalesce((select jsonb_strip_nulls(jsonb_build_object( + 'name', name, 'email', email, 'authenticationKind', authentication_kind)) + from provider_accounts where id = $3), '{}'::jsonb), + 'transport', jsonb_strip_nulls(jsonb_build_object('httpVersion', $7::text)), + 'scheduling', coalesce(request_observation_json -> 'scheduling', '{}'::jsonb) || jsonb_strip_nulls(jsonb_build_object( + 'accountSelectionWaitMs', case when $9::bigint is null + then (request_observation_json #>> '{scheduling,accountSelectionWaitMs}')::bigint + else coalesce((request_observation_json #>> '{scheduling,accountSelectionWaitMs}')::bigint, 0) + $9 end, + 'capacityUsedSlots', coalesce($10::bigint, (request_observation_json #>> '{scheduling,capacityUsedSlots}')::bigint), + 'capacityTotalSlots', coalesce($11::bigint, (request_observation_json #>> '{scheduling,capacityTotalSlots}')::bigint)))) where id = $1 and outcome = 'running' and downstream_committed_at is null and $8 = attempt_count + 1 returning attempt_count", @@ -698,35 +654,29 @@ impl ModelRequestRepository for PgExecutionStore { finalization: ModelRequestFinalization, ) -> StoreResult { finalization.validate()?; + let observation = RequestObservation::finalized(&finalization)?; // 墙上时间可能回拨；终态必须可落盘，实际耗时仍保留 Core 的单调时钟观测 let finalized = sqlx::query_scalar::<_, i64>( "with finalized as ( update model_requests set outcome = $2, upstream_send_state = $3, attempt_count = $4, downstream_committed_at = $5, - client_status_code = coalesce(client_status_code, $6), - upstream_status_code = $7, + client_status_code = coalesce(client_status_code, $6), upstream_status_code = $7, client_response_id = $8, upstream_request_id = $9, upstream_response_id = $10, - error_kind = $11, provider_error_code = $12, error_message = $13, - retry_after_ms = $14, input_tokens = $15, output_tokens = $16, - cached_tokens = $17, cache_write_tokens = $18, reasoning_tokens = $19, - image_input_tokens = $20, image_output_tokens = $21, total_tokens = $22, - image_generation_succeeded = $23, cost_source = $24, - cost_amount = $25::numeric, cost_currency = $26, - transport_decision_wait_ms = $27, connect_ms = $28, - headers_ms = $29, first_event_ms = $30, first_reasoning_ms = $31, - first_text_ms = $32, first_token_ms = $33, provider_processing_ms = $34, - latency_ms = $35, completed_at = greatest($36, started_at), - upstream_transport = coalesce($37, upstream_transport), - http_version = coalesce($38, http_version), websocket_pool = $39, - service_tier = $40, provider_observation_json = $41, - error_details = $42, - continuation_unavailable_reason = $43, - upstream_connection_id = $44, - upstream_connection_exit_reason = $45, - upstream_connection_age_ms = $46, - upstream_connection_idle_ms = $47, diagnostic_trace_json = $48, - upstream_response_model = $49, billing_snapshot_json = $50 + error_kind = $11, input_tokens = $12, output_tokens = $13, + cached_tokens = $14, cache_write_tokens = $15, reasoning_tokens = $16, + image_input_tokens = $17, image_output_tokens = $18, total_tokens = $19, + image_generation_succeeded = $20, cost_source = $21, + cost_amount = $22::numeric, cost_currency = $23, + completed_at = greatest($24, started_at), + upstream_transport = coalesce($25, upstream_transport), service_tier = $26, + provider_observation_json = $27, error_details = $28, + diagnostic_trace_json = $29, billing_snapshot_json = $30, + request_observation_json = request_observation_json || $31::jsonb || jsonb_build_object( + 'transport', ($31::jsonb -> 'transport') || jsonb_strip_nulls(jsonb_build_object( + 'httpVersion', coalesce($31::jsonb #>> '{transport,httpVersion}', request_observation_json #>> '{transport,httpVersion}'))), + 'continuation', coalesce(request_observation_json -> 'continuation', '{}'::jsonb) + || ($31::jsonb -> 'continuation')) where id = $1 and outcome = 'running' returning id, client_api_key_ref, continuation_affinity_hash, continuation_requested, provider_kind, upstream_transport, @@ -758,20 +708,11 @@ impl ModelRequestRepository for PgExecutionStore { when current.outcome = 'succeeded' then current.completed_at else prior.recovered_at end, - recovery_retry_delay_ms = case - when current.outcome = 'succeeded' then greatest( - 0, - floor(extract(epoch from (current.started_at - prior.completed_at)) * 1000) - )::bigint - else prior.recovery_retry_delay_ms - end, - recovery_total_latency_ms = case - when current.outcome = 'succeeded' then greatest( - 0, - floor(extract(epoch from (current.completed_at - prior.completed_at)) * 1000) - )::bigint - else prior.recovery_total_latency_ms - end + request_observation_json = case when current.outcome = 'succeeded' then + prior.request_observation_json || jsonb_build_object('recovery', jsonb_build_object( + 'retryDelayMs', greatest(0, floor(extract(epoch from (current.started_at - prior.completed_at)) * 1000))::bigint, + 'totalLatencyMs', greatest(0, floor(extract(epoch from (current.completed_at - prior.completed_at)) * 1000))::bigint)) + else prior.request_observation_json end from finalized current join recovery_target target on true where prior.id = target.id @@ -801,14 +742,9 @@ impl ModelRequestRepository for PgExecutionStore { set recovery_attempt_count = prior.recovery_attempt_count + 1, recovery_request_id = current.id, recovered_at = current.completed_at, - recovery_retry_delay_ms = greatest( - 0, - floor(extract(epoch from (current.started_at - prior.completed_at)) * 1000) - )::bigint, - recovery_total_latency_ms = greatest( - 0, - floor(extract(epoch from (current.completed_at - prior.completed_at)) * 1000) - )::bigint + request_observation_json = prior.request_observation_json || jsonb_build_object('recovery', jsonb_build_object( + 'retryDelayMs', greatest(0, floor(extract(epoch from (current.started_at - prior.completed_at)) * 1000))::bigint, + 'totalLatencyMs', greatest(0, floor(extract(epoch from (current.completed_at - prior.completed_at)) * 1000))::bigint)) from finalized current join session_transport_recovery_target target on true where prior.id = target.id @@ -833,93 +769,26 @@ impl ModelRequestRepository for PgExecutionStore { .bind(finalization.upstream_request_id) .bind(finalization.upstream_response_id.map(String::into_bytes)) .bind(finalization.error_kind) - .bind(finalization.provider_error_code) - .bind(finalization.error_message) - .bind(optional_i64(finalization.retry_after_ms, "retry_after_ms")?) - .bind(optional_i64( - finalization.usage.input_tokens, - "input_tokens", - )?) - .bind(optional_i64( - finalization.usage.output_tokens, - "output_tokens", - )?) - .bind(optional_i64( - finalization.usage.cached_tokens, - "cached_tokens", - )?) - .bind(optional_i64( - finalization.usage.cache_write_tokens, - "cache_write_tokens", - )?) - .bind(optional_i64( - finalization.usage.reasoning_tokens, - "reasoning_tokens", - )?) - .bind(optional_i64( - finalization.usage.image_input_tokens, - "image_input_tokens", - )?) - .bind(optional_i64( - finalization.usage.image_output_tokens, - "image_output_tokens", - )?) - .bind(optional_i64( - finalization.usage.total_tokens, - "total_tokens", - )?) + .bind(optional_i64(finalization.usage.input_tokens, "input_tokens")?) + .bind(optional_i64(finalization.usage.output_tokens, "output_tokens")?) + .bind(optional_i64(finalization.usage.cached_tokens, "cached_tokens")?) + .bind(optional_i64(finalization.usage.cache_write_tokens, "cache_write_tokens")?) + .bind(optional_i64(finalization.usage.reasoning_tokens, "reasoning_tokens")?) + .bind(optional_i64(finalization.usage.image_input_tokens, "image_input_tokens")?) + .bind(optional_i64(finalization.usage.image_output_tokens, "image_output_tokens")?) + .bind(optional_i64(finalization.usage.total_tokens, "total_tokens")?) .bind(finalization.image_generation_succeeded) .bind(finalization.cost_source.as_str()) .bind(finalization.cost_amount.map(|amount| amount.to_string())) .bind(finalization.cost_currency) - .bind(optional_i64( - finalization.timings.transport_decision_wait_ms, - "transport_decision_wait_ms", - )?) - .bind(optional_i64(finalization.timings.connect_ms, "connect_ms")?) - .bind(optional_i64(finalization.timings.headers_ms, "headers_ms")?) - .bind(optional_i64( - finalization.timings.first_event_ms, - "first_event_ms", - )?) - .bind(optional_i64( - finalization.timings.first_reasoning_ms, - "first_reasoning_ms", - )?) - .bind(optional_i64( - finalization.timings.first_text_ms, - "first_text_ms", - )?) - .bind(optional_i64( - finalization.timings.first_token_ms, - "first_token_ms", - )?) - .bind(optional_i64( - finalization.timings.provider_processing_ms, - "provider_processing_ms", - )?) - .bind(optional_i64(finalization.timings.latency_ms, "latency_ms")?) .bind(finalization.completed_at) .bind(finalization.upstream_transport) - .bind(finalization.http_version) - .bind(finalization.websocket_pool) .bind(finalization.service_tier) .bind(finalization.provider_metadata_json.map(sqlx::types::Json)) .bind(finalization.error_details) - .bind(finalization.continuation_unavailable_reason) - .bind(finalization.upstream_connection_id) - .bind(finalization.upstream_connection_exit_reason) - .bind(optional_i64( - finalization.upstream_connection_age_ms, - "upstream_connection_age_ms", - )?) - .bind(optional_i64( - finalization.upstream_connection_idle_ms, - "upstream_connection_idle_ms", - )?) .bind(finalization.diagnostic_trace_json.map(sqlx::types::Json)) - .bind(finalization.upstream_response_model) .bind(finalization.billing_snapshot_json.map(sqlx::types::Json)) + .bind(observation) .fetch_one(&self.pool) .await .map_err(|source| postgres_unavailable("finalize model request", source))?; @@ -933,7 +802,8 @@ impl ModelRequestRepository for PgExecutionStore { let result = sqlx::query( "update model_requests set outcome = 'incomplete', error_kind = 'process_interrupted', - error_message = 'request did not reach a terminal state', + request_observation_json = request_observation_json || jsonb_build_object('error', + jsonb_build_object('message', 'request did not reach a terminal state')), image_generation_succeeded = case when image_generation_requested then false else null end, diff --git a/backend/crates/gateway-store/src/postgres/execution/request_observation.rs b/backend/crates/gateway-store/src/postgres/execution/request_observation.rs new file mode 100644 index 000000000..2fb001e26 --- /dev/null +++ b/backend/crates/gateway-store/src/postgres/execution/request_observation.rs @@ -0,0 +1,321 @@ +//! 请求观测 JSON 的类型化编码，只拥有持久化分组，不决定业务状态 + +use serde::Serialize; +use serde_json::Value; + +use super::{ModelRequestFinalization, NewModelRequest, StoreResult, invalid}; + +#[derive(Default, Serialize)] +#[serde(rename_all = "camelCase")] +pub(super) struct RequestObservation { + #[serde(skip_serializing_if = "Option::is_none")] + request: Option, + #[serde(skip_serializing_if = "Option::is_none")] + routing: Option, + #[serde(skip_serializing_if = "Option::is_none")] + error: Option, + #[serde(skip_serializing_if = "Option::is_none")] + timings: Option, + #[serde(skip_serializing_if = "Option::is_none")] + scheduling: Option, + #[serde(skip_serializing_if = "Option::is_none")] + transport: Option, + #[serde(skip_serializing_if = "Option::is_none")] + response: Option, + #[serde(skip_serializing_if = "Option::is_none")] + continuation: Option, +} + +#[derive(Default, Serialize)] +#[serde(rename_all = "camelCase")] +struct RequestContext { + config_revision: u64, + protocol: String, + endpoint: String, + #[serde(skip_serializing_if = "Option::is_none")] + client_ip: Option, + #[serde(skip_serializing_if = "Option::is_none")] + user_agent: Option, + #[serde(skip_serializing_if = "Option::is_none")] + reasoning_effort: Option, + #[serde(skip_serializing_if = "Option::is_none")] + reasoning_preset: Option, + #[serde(skip_serializing_if = "Option::is_none")] + subagent_kind: Option, + compact: bool, +} + +#[derive(Default, Serialize)] +#[serde(rename_all = "camelCase")] +struct RoutingSnapshot { + scope: String, + group_refs: Vec, + group_names_snapshot: Vec, +} + +#[derive(Default, Serialize)] +#[serde(rename_all = "camelCase")] +struct ErrorObservation { + #[serde(skip_serializing_if = "Option::is_none")] + provider_error_code: Option, + #[serde(skip_serializing_if = "Option::is_none")] + message: Option, + #[serde(skip_serializing_if = "Option::is_none")] + retry_after_ms: Option, +} + +#[derive(Default, Serialize)] +#[serde(rename_all = "camelCase")] +struct RequestTimings { + #[serde(skip_serializing_if = "Option::is_none")] + local: Option, + #[serde(skip_serializing_if = "Option::is_none")] + upstream: Option, +} + +#[derive(Default, Serialize)] +#[serde(rename_all = "camelCase")] +struct LocalTimings { + #[serde(skip_serializing_if = "Option::is_none")] + transport_decision_wait_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + connect_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + headers_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + first_event_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + first_reasoning_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + first_text_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + first_token_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + latency_ms: Option, +} + +#[derive(Default, Serialize)] +#[serde(rename_all = "camelCase")] +struct UpstreamTimings { + #[serde(skip_serializing_if = "Option::is_none")] + processing_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + response_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + api_overhead_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + engine_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + engine_iapi_ttft_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + engine_service_ttft_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + engine_iapi_tbt_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + engine_service_tbt_ms: Option, +} + +#[derive(Default, Serialize)] +#[serde(rename_all = "camelCase")] +struct SchedulingObservation { + #[serde(skip_serializing_if = "Option::is_none")] + admission_decision_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + account_selection_wait_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + capacity_used_slots: Option, + #[serde(skip_serializing_if = "Option::is_none")] + capacity_total_slots: Option, +} + +#[derive(Default, Serialize)] +#[serde(rename_all = "camelCase")] +struct TransportObservation { + #[serde(skip_serializing_if = "Option::is_none")] + http_version: Option, + #[serde(skip_serializing_if = "Option::is_none")] + websocket_pool: Option, + #[serde(skip_serializing_if = "Option::is_none")] + connection: Option, +} + +#[derive(Default, Serialize)] +#[serde(rename_all = "camelCase")] +struct ConnectionObservation { + #[serde(skip_serializing_if = "Option::is_none")] + id: Option, + #[serde(skip_serializing_if = "Option::is_none")] + exit_reason: Option, + #[serde(skip_serializing_if = "Option::is_none")] + age_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + idle_ms: Option, +} + +#[derive(Default, Serialize)] +#[serde(rename_all = "camelCase")] +struct ResponseObservation { + #[serde(skip_serializing_if = "Option::is_none")] + response_model: Option, +} + +#[derive(Default, Serialize)] +#[serde(rename_all = "camelCase")] +struct ContinuationObservation { + #[serde(skip_serializing_if = "Option::is_none")] + previous_response_id_hash: Option, + #[serde(skip_serializing_if = "Option::is_none")] + unavailable_reason: Option, +} + +impl RequestObservation { + pub(super) fn initial(request: &NewModelRequest) -> StoreResult> { + let observation = Self { + request: Some(RequestContext { + config_revision: request.config_revision, + protocol: request.protocol.clone(), + endpoint: request.endpoint.clone(), + client_ip: request.client_ip.clone(), + user_agent: request.user_agent.clone(), + reasoning_effort: request.reasoning_effort.clone(), + reasoning_preset: request.reasoning_preset.clone(), + subagent_kind: request.subagent_kind.clone(), + compact: request.compact, + }), + routing: Some(RoutingSnapshot { + scope: request.routing_scope.clone(), + group_refs: request.routing_group_refs.clone(), + group_names_snapshot: serde_json::from_value( + request.routing_group_names_snapshot.clone(), + ) + .map_err(|source| invalid("invalid routing group names").with_source(source))?, + }), + scheduling: Some(SchedulingObservation { + admission_decision_ms: request.admission_decision_ms, + ..Default::default() + }), + continuation: Some(ContinuationObservation { + previous_response_id_hash: request.continuation.previous_response_id_hash.clone(), + ..Default::default() + }), + ..Default::default() + }; + observation.encode() + } + + pub(super) fn finalized( + value: &ModelRequestFinalization, + ) -> StoreResult> { + let timings = &value.timings; + // 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() + { + if !value.is_finite() || value < 0.0 || value >= i64::MAX as f64 { + return Err(invalid( + "upstream timing is outside the supported millisecond range", + )); + } + } + let observation = Self { + timings: Some(RequestTimings { + local: Some(LocalTimings { + transport_decision_wait_ms: timings.transport_decision_wait_ms, + connect_ms: timings.connect_ms, + headers_ms: timings.headers_ms, + first_event_ms: timings.first_event_ms, + first_reasoning_ms: timings.first_reasoning_ms, + first_text_ms: timings.first_text_ms, + first_token_ms: timings.first_token_ms, + latency_ms: timings.latency_ms, + }), + upstream: Some(UpstreamTimings { + processing_ms: timings.provider_processing_ms, + 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 { + http_version: value.http_version.clone(), + websocket_pool: value.websocket_pool.clone(), + connection: value + .upstream_connection_id + .as_ref() + .map(|id| ConnectionObservation { + id: Some(id.clone()), + exit_reason: value.upstream_connection_exit_reason.clone(), + age_ms: value.upstream_connection_age_ms, + idle_ms: value.upstream_connection_idle_ms, + }), + }), + response: Some(ResponseObservation { + response_model: value.upstream_response_model.clone(), + }), + error: Some(ErrorObservation { + provider_error_code: value.provider_error_code.clone(), + message: value.error_message.clone(), + retry_after_ms: value.retry_after_ms, + }), + continuation: Some(ContinuationObservation { + unavailable_reason: value.continuation_unavailable_reason.clone(), + ..Default::default() + }), + ..Default::default() + }; + observation.encode() + } + + fn encode(self) -> StoreResult> { + let value = serde_json::to_value(self) + .map_err(|source| invalid("encode request observation").with_source(source))?; + validate_numbers(&value)?; + if value.to_string().len() > 1024 * 1024 { + return Err(invalid("request observation exceed 1 MiB")); + } + Ok(sqlx::types::Json(value)) + } +} + +// 整数指标保持 bigint 边界，官方专项计时允许毫秒小数 +fn validate_numbers(value: &Value) -> StoreResult<()> { + match value { + Value::Number(value) => { + let valid = match value.as_u64() { + Some(integer) => integer <= i64::MAX as u64, + None => value + .as_f64() + .is_some_and(|value| value >= 0.0 && value < i64::MAX as f64), + }; + if !valid { + return Err(invalid( + "request observation number exceeds supported range", + )); + } + } + Value::Object(values) => { + for value in values.values() { + validate_numbers(value)?; + } + } + Value::Array(values) => { + for value in values { + validate_numbers(value)?; + } + } + _ => {} + } + Ok(()) +} diff --git a/backend/crates/gateway-store/src/postgres/observability/mapping.rs b/backend/crates/gateway-store/src/postgres/observability/mapping.rs index 538079868..43b4526e7 100644 --- a/backend/crates/gateway-store/src/postgres/observability/mapping.rs +++ b/backend/crates/gateway-store/src/postgres/observability/mapping.rs @@ -335,6 +335,13 @@ pub(crate) fn usage_list_record_from_row( first_text_ms: optional_unsigned(row, "first_text_ms")?, first_token_ms: optional_unsigned(row, "first_token_ms")?, provider_processing_ms: optional_unsigned(row, "provider_processing_ms")?, + 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")?, @@ -424,6 +431,13 @@ pub(crate) fn usage_record_from_row(row: &sqlx::postgres::PgRow) -> StoreResult< first_text_ms: optional_unsigned(row, "first_text_ms")?, first_token_ms: optional_unsigned(row, "first_token_ms")?, provider_processing_ms: optional_unsigned(row, "provider_processing_ms")?, + 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")?, diff --git a/backend/crates/gateway-store/src/postgres/observability/model.rs b/backend/crates/gateway-store/src/postgres/observability/model.rs index dacd459f2..a2e21fd18 100644 --- a/backend/crates/gateway-store/src/postgres/observability/model.rs +++ b/backend/crates/gateway-store/src/postgres/observability/model.rs @@ -309,7 +309,7 @@ impl ProviderAccountUsageQuery { pub use gateway_admin::model::observability::DashboardTotals; -#[derive(Debug, Clone, PartialEq, Eq)] +#[derive(Debug, Clone, PartialEq)] pub struct DashboardObservation { pub range: ObservabilityRange, pub totals: DashboardTotals, diff --git a/backend/crates/gateway-store/src/postgres/observability/queries/dashboard.rs b/backend/crates/gateway-store/src/postgres/observability/queries/dashboard.rs index 1db7fb20d..e5408b324 100644 --- a/backend/crates/gateway-store/src/postgres/observability/queries/dashboard.rs +++ b/backend/crates/gateway-store/src/postgres/observability/queries/dashboard.rs @@ -67,19 +67,19 @@ pub(crate) async fn request_metrics( as account_selection_wait_p99_ms, round((percentile_cont(0.10) within group ( order by output_tokens::double precision * 1000.0 - / nullif(latency_ms, 0) + / nullif(upstream_response_ms, 0) ) filter (where {fact} and output_tokens > 0 - and latency_ms > 0)))::bigint as output_throughput_p10, + and upstream_response_ms > 0)))::bigint as output_throughput_p10, round((percentile_cont(0.50) within group ( order by output_tokens::double precision * 1000.0 - / nullif(latency_ms, 0) + / nullif(upstream_response_ms, 0) ) filter (where {fact} and output_tokens > 0 - and latency_ms > 0)))::bigint as output_throughput_p50, + and upstream_response_ms > 0)))::bigint as output_throughput_p50, round((percentile_cont(0.90) within group ( order by output_tokens::double precision * 1000.0 - / nullif(latency_ms, 0) + / nullif(upstream_response_ms, 0) ) filter (where {fact} and output_tokens > 0 - and latency_ms > 0)))::bigint as output_throughput_p90, + and upstream_response_ms > 0)))::bigint as output_throughput_p90, count(capacity_total_slots)::bigint as capacity_sample_count, round(avg(capacity_used_slots::double precision / nullif(capacity_total_slots, 0)) * 10000)::bigint @@ -88,7 +88,7 @@ pub(crate) async fn request_metrics( order by capacity_used_slots::double precision / nullif(capacity_total_slots, 0) ) * 10000)::bigint as capacity_utilization_p95_basis_points - from model_requests mr where mr.started_at >= " + from model_request_observations mr where mr.started_at >= " )); query.push_bind(range.start); query.push(" and mr.started_at < "); @@ -114,7 +114,7 @@ pub(crate) async fn dashboard_totals(pool: &PgPool) -> StoreResult 0 - and latency_ms > 0)))::bigint as output_throughput_p10, + and upstream_response_ms > 0)))::bigint as output_throughput_p10, round((percentile_cont(0.50) within group ( order by output_tokens::double precision * 1000.0 - / nullif(latency_ms, 0) + / nullif(upstream_response_ms, 0) ) filter (where {fact} and output_tokens > 0 - and latency_ms > 0)))::bigint as output_throughput_p50, + and upstream_response_ms > 0)))::bigint as output_throughput_p50, round((percentile_cont(0.90) within group ( order by output_tokens::double precision * 1000.0 - / nullif(latency_ms, 0) + / nullif(upstream_response_ms, 0) ) filter (where {fact} and output_tokens > 0 - and latency_ms > 0)))::bigint as output_throughput_p90, + and upstream_response_ms > 0)))::bigint as output_throughput_p90, count(capacity_total_slots)::bigint as capacity_sample_count, round(avg(capacity_used_slots::double precision / nullif(capacity_total_slots, 0)) * 10000)::bigint @@ -249,7 +249,7 @@ async fn request_metric_series_inner( as calculated_count, count(*) filter (where {fact} and cost_source = 'unavailable')::bigint as unavailable_count - from model_requests mr where mr.started_at >= " + from model_request_observations mr where mr.started_at >= " )); query.push_bind(range.start); query.push(" and mr.started_at < "); @@ -307,7 +307,7 @@ pub(crate) fn calculated_usage_billing_facts( mr.provider_kind, mr.upstream_model_id, mr.service_tier, mr.input_tokens, mr.output_tokens, mr.cached_tokens, mr.cache_write_tokens, mr.billing_snapshot_json, mr.cost_currency, mr.cost_amount::text as amount - from model_requests mr where mr.started_at >= ", + from model_request_observations mr where mr.started_at >= ", ); query.push_bind(range.start); query.push(" and mr.started_at < "); @@ -342,7 +342,7 @@ pub(crate) async fn request_costs_by_bucket( query.push( " as bucket_start, mr.cost_currency, sum(mr.cost_amount)::text as amount - from model_requests mr + from model_request_observations mr where mr.started_at >= ", ); query.push_bind(range.start); @@ -382,7 +382,7 @@ pub(crate) async fn attempt_metrics( select mr.id, mr.attempt_count, mr.outcome, mr.error_kind, mr.upstream_status_code, mr.client_status_code, mr.cost_source, ({completed_usage}) as is_completed_usage - from model_requests mr where mr.started_at >= " + from model_request_observations mr where mr.started_at >= " )); query.push_bind(range.start); query.push(" and mr.started_at < "); @@ -494,7 +494,7 @@ pub(crate) async fn request_costs( ) -> StoreResult> { let mut query = QueryBuilder::::new( "select mr.cost_currency, sum(mr.cost_amount)::text as amount - from model_requests mr where mr.started_at >= ", + from model_request_observations mr where mr.started_at >= ", ); query.push_bind(range.start); query.push(" and mr.started_at < "); @@ -527,7 +527,7 @@ pub(crate) async fn provider_observations( count(*) filter (where mr.outcome = 'failed')::bigint as failure_count, coalesce(sum(mr.total_tokens) filter (where {fact}), 0)::bigint as total_tokens - from model_requests mr where mr.started_at >= " + from model_request_observations mr where mr.started_at >= " )); query.push_bind(range.start); query.push(" and mr.started_at < "); diff --git a/backend/crates/gateway-store/src/postgres/observability/queries/ops.rs b/backend/crates/gateway-store/src/postgres/observability/queries/ops.rs index 26a8c9b03..b9c1b2cd4 100644 --- a/backend/crates/gateway-store/src/postgres/observability/queries/ops.rs +++ b/backend/crates/gateway-store/src/postgres/observability/queries/ops.rs @@ -32,7 +32,7 @@ const REQUEST_ERROR_SELECT: &str = "select 'model_request'::text as source, mr.recovery_retry_delay_ms, mr.recovery_total_latency_ms, mr.completed_at as occurred_at, 'model_request:' || mr.id as stable_sort_id -from model_requests mr +from model_request_observations mr left join client_api_keys client_key on client_key.id = mr.client_api_key_ref left join provider_accounts account on account.id = mr.provider_account_ref where true"; @@ -67,7 +67,7 @@ const OPS_EVENT_SELECT: &str = "select 'ops_event'::text as source, oe.created_at as occurred_at, 'ops_event:' || oe.id as stable_sort_id from ops_events oe -left join model_requests mr on mr.id = oe.model_request_id +left join model_request_observations mr on mr.id = oe.model_request_id left join client_api_keys client_key on client_key.id = mr.client_api_key_ref left join provider_accounts account on account.id = oe.provider_account_ref where true"; @@ -112,11 +112,11 @@ pub(crate) async fn count_ops_errors( filter: &OpsErrorFilter, ) -> StoreResult { let mut statement = QueryBuilder::::new( - "select coalesce(sum(source_count), 0)::bigint from (select count(*)::bigint as source_count from model_requests mr where true", + "select coalesce(sum(source_count), 0)::bigint from (select count(*)::bigint as source_count from model_request_observations mr where true", ); push_request_error_predicates(&mut statement, range, filter); statement.push( - " union all select count(*)::bigint as source_count from ops_events oe left join model_requests mr on mr.id = oe.model_request_id where true", + " union all select count(*)::bigint as source_count from ops_events oe left join model_request_observations mr on mr.id = oe.model_request_id where true", ); push_ops_event_predicates(&mut statement, range, filter); statement.push(") counts"); diff --git a/backend/crates/gateway-store/src/postgres/observability/queries/usage.rs b/backend/crates/gateway-store/src/postgres/observability/queries/usage.rs index ffdc11dea..56a85ef6d 100644 --- a/backend/crates/gateway-store/src/postgres/observability/queries/usage.rs +++ b/backend/crates/gateway-store/src/postgres/observability/queries/usage.rs @@ -138,12 +138,13 @@ pub(crate) const USAGE_LIST_RECORD_SELECT: &str = mr.total_tokens, mr.billing_snapshot_json, mr.cost_source, mr.cost_amount::text, 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.latency_ms, mr.admission_decision_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.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, mr.started_at - from model_requests mr + from model_request_observations mr left join client_api_keys client_key on client_key.id = mr.client_api_key_ref left join provider_accounts account on account.id = mr.provider_account_ref"; @@ -168,13 +169,14 @@ pub(crate) const USAGE_RECORD_DETAIL_SELECT: &str = mr.total_tokens, mr.billing_snapshot_json, mr.cost_source, mr.cost_amount::text, 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.latency_ms, mr.admission_decision_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.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, mr.subagent_kind, mr.compact, mr.image_generation_requested, mr.image_generation_succeeded, mr.started_at, mr.deadline_at, mr.completed_at - from model_requests mr"; + from model_request_observations mr"; pub(crate) async fn list_usage_records( pool: &PgPool, @@ -226,7 +228,7 @@ pub(crate) async fn count_usage_records( filter: &UsageRecordFilter, ) -> StoreResult { let mut statement = QueryBuilder::::new( - "select count(*)::bigint from model_requests mr where mr.started_at >= ", + "select count(*)::bigint from model_request_observations mr where mr.started_at >= ", ); statement.push_bind(range.start); statement.push(" and mr.started_at < "); @@ -292,7 +294,7 @@ pub(crate) async fn usage_record_detail( "select jsonb_build_object('requestId', related.id, 'outcome', related.outcome, 'relation', case when related.id = current.recovery_request_id then 'recovered_by' else 'recovers' end, 'completedAt', related.completed_at) - from model_requests current join model_requests related + from model_request_observations current join model_request_observations related on related.id = current.recovery_request_id or related.recovery_request_id = current.id where current.id = $1 order by related.started_at limit 20" ).bind(request_id).fetch_all(pool).await @@ -401,7 +403,7 @@ pub(crate) async fn usage_diagnostics( mr.latency_ms, mr.first_token_ms, mr.cost_source, mr.cost_amount, mr.cost_currency, mr.downstream_committed_at, mr.client_transport, mr.client_status_code, ({completed_usage}) as is_completed_usage - from model_requests mr where mr.started_at >= ", + from model_request_observations mr where mr.started_at >= ", )); statement.push_bind(range.start); statement.push(" and mr.started_at < "); @@ -567,7 +569,7 @@ pub(crate) async fn diagnostic_account_display_names( coalesce( ( select request.provider_account_email_snapshot - from model_requests request + from model_request_observations request where request.provider_account_ref = requested.account_id and request.provider_account_email_snapshot is not null order by request.started_at desc, request.id desc @@ -575,7 +577,7 @@ pub(crate) async fn diagnostic_account_display_names( ), ( select request.provider_account_name_snapshot - from model_requests request + from model_request_observations request where request.provider_account_ref = requested.account_id and request.provider_account_name_snapshot is not null order by request.started_at desc, request.id desc diff --git a/backend/crates/gateway-store/tests/postgres/account_groups.rs b/backend/crates/gateway-store/tests/postgres/account_groups.rs index d54dfd3de..59343dad3 100644 --- a/backend/crates/gateway-store/tests/postgres/account_groups.rs +++ b/backend/crates/gateway-store/tests/postgres/account_groups.rs @@ -446,20 +446,19 @@ async fn seed_group_cost_snapshot( .collect(); sqlx::query( "insert into model_requests ( - id, client_api_key_ref, config_revision, protocol, operation, endpoint, - client_transport, requested_model_id, provider_kind, provider_account_id, - provider_account_ref, upstream_model_id, upstream_transport, attempt_count, - upstream_send_state, downstream_committed_at, outcome, client_status_code, - upstream_status_code, total_tokens, cost_source, cost_amount, cost_currency, - started_at, deadline_at, completed_at, - routing_scope, routing_group_refs, routing_group_names_snapshot + id, client_api_key_ref, operation, client_transport, requested_model_id, provider_kind, provider_account_id, provider_account_ref, upstream_model_id, upstream_transport, attempt_count, upstream_send_state, downstream_committed_at, outcome, client_status_code, upstream_status_code, total_tokens, cost_source, cost_amount, cost_currency, started_at, deadline_at, completed_at, request_observation_json ) values ( - $1, 'key-group-history', 1, 'openai', 'responses', '/v1/responses', - 'http_sse', 'gpt-group', 'openai', $2, $2, 'gpt-group', 'http_sse', 1, - 'sent', now(), 'succeeded', 200, 200, 10, - 'provider_reported', $4::numeric, 'USD', now() - interval '1 minute', - now() + interval '5 minutes', now(), - 'groups', $3::text[], to_jsonb($3::text[]) + $1, 'key-group-history', 'responses', 'http_sse', 'gpt-group', 'openai', $2, $2, 'gpt-group', 'http_sse', 1, 'sent', now(), 'succeeded', 200, 200, 10, 'provider_reported', $4::numeric, 'USD', now() - interval '1 minute', now() + interval '5 minutes', now(), + jsonb_strip_nulls(jsonb_build_object( + 'request', jsonb_build_object( + 'configRevision', 1, + 'protocol', 'openai', + 'endpoint', '/v1/responses', + 'compact', false), + 'routing', jsonb_build_object( + 'scope', 'groups', + 'groupRefs', $3::text[], + 'groupNamesSnapshot', to_jsonb($3::text[])))) )", ) .bind(request_id) diff --git a/backend/crates/gateway-store/tests/postgres/admission_recovery.rs b/backend/crates/gateway-store/tests/postgres/admission_recovery.rs index fc0d9b794..3adb4d73e 100644 --- a/backend/crates/gateway-store/tests/postgres/admission_recovery.rs +++ b/backend/crates/gateway-store/tests/postgres/admission_recovery.rs @@ -93,14 +93,19 @@ async fn seed_request( let completed_at = (outcome != "running").then_some(started_at + Duration::seconds(1)); sqlx::query( "insert into model_requests ( - id, client_api_key_ref, config_revision, protocol, operation, endpoint, - client_transport, requested_model_id, outcome, - started_at, deadline_at, completed_at, - routing_scope, routing_group_refs, routing_group_names_snapshot + id, client_api_key_ref, operation, client_transport, requested_model_id, outcome, started_at, deadline_at, completed_at, request_observation_json ) values ( - $1, 'key-recovery', 1, 'openai', 'responses', '/v1/responses', - 'http_sse', 'coding', $2, $3, $4, $5, - 'all', '{}'::text[], '[]'::jsonb + $1, 'key-recovery', 'responses', 'http_sse', 'coding', $2, $3, $4, $5, + jsonb_strip_nulls(jsonb_build_object( + 'request', jsonb_build_object( + 'configRevision', 1, + 'protocol', 'openai', + 'endpoint', '/v1/responses', + 'compact', false), + 'routing', jsonb_build_object( + 'scope', 'all', + 'groupRefs', '{}'::text[], + 'groupNamesSnapshot', '[]'::jsonb))) )", ) .bind(id) diff --git a/backend/crates/gateway-store/tests/postgres/connection.rs b/backend/crates/gateway-store/tests/postgres/connection.rs index 3ef4a780c..1b3a77e30 100644 --- a/backend/crates/gateway-store/tests/postgres/connection.rs +++ b/backend/crates/gateway-store/tests/postgres/connection.rs @@ -159,6 +159,7 @@ async fn connect_and_migrate_should_apply_all_migrations_once_and_reopen_cleanly "client_api_keys", "client_key_budget_windows", "client_key_charge_events", + "model_request_observations", "model_requests", "ops_events", "outbound_proxies", @@ -187,14 +188,7 @@ async fn connect_and_migrate_should_apply_all_migrations_once_and_reopen_cleanly assert_eq!(response_id_types, ["bytea", "bytea"]); assert!(!raw_response_id_index_exists); assert!(!legacy_key_provider_column_exists); - assert_eq!( - routing_history_columns, - [ - "routing_group_names_snapshot", - "routing_group_refs", - "routing_scope", - ] - ); + assert!(routing_history_columns.is_empty()); } #[test] diff --git a/backend/crates/gateway-store/tests/postgres/execution.rs b/backend/crates/gateway-store/tests/postgres/execution/mod.rs similarity index 90% rename from backend/crates/gateway-store/tests/postgres/execution.rs rename to backend/crates/gateway-store/tests/postgres/execution/mod.rs index 2c115e23e..25eb4c612 100644 --- a/backend/crates/gateway-store/tests/postgres/execution.rs +++ b/backend/crates/gateway-store/tests/postgres/execution/mod.rs @@ -286,7 +286,7 @@ async fn model_request_persists_group_routing_snapshot_without_live_group_foreig let stored: (String, Vec, serde_json::Value) = sqlx::query_as( "select routing_scope, routing_group_refs, routing_group_names_snapshot - from model_requests where id = 'req_group_history'", + from model_request_observations where id = 'req_group_history'", ) .fetch_one(&database.pool) .await @@ -423,7 +423,7 @@ async fn core_adapter_should_persist_calculated_cost_exactly() { ) = sqlx::query_as( "select cost_source, cost_amount::text, cost_currency, upstream_transport, http_version, websocket_pool, service_tier - from model_requests where id = 'req_calculated_cost'", + from model_request_observations where id = 'req_calculated_cost'", ) .fetch_one(&database.pool) .await @@ -600,7 +600,7 @@ async fn core_adapter_should_persist_image_result_and_new_websocket_pool() { let persisted: (bool, Option, Option, Option, Option) = sqlx::query_as( "select image_generation_requested, image_input_tokens, image_output_tokens, image_generation_succeeded, websocket_pool - from model_requests where id = 'req_image_usage'", + from model_request_observations where id = 'req_image_usage'", ) .fetch_one(&database.pool) .await @@ -958,7 +958,7 @@ async fn core_adapter_persists_continuation_connection_failure_observation() { "select error_kind, continuation_unavailable_reason, upstream_connection_id, upstream_connection_exit_reason, upstream_connection_age_ms, upstream_connection_idle_ms - from model_requests where id = 'req_continuation_observation'", + from model_request_observations where id = 'req_continuation_observation'", ) .fetch_one(&database.pool) .await @@ -1016,7 +1016,7 @@ async fn successful_new_chain_should_mark_recent_continuation_failure_recovered( let recovered: PersistedRecoveryObservation = sqlx::query_as( "select recovery_request_id, recovered_at, recovery_attempt_count, recovery_retry_delay_ms, recovery_total_latency_ms - from model_requests where id = 'req_continuation_failed'", + from model_request_observations where id = 'req_continuation_failed'", ) .fetch_one(&database.pool) .await @@ -1096,7 +1096,7 @@ async fn successful_http_downgrade_should_mark_pending_websocket_failures_recove let recovered: Vec = sqlx::query_as( "select id, recovery_request_id, recovered_at, recovery_attempt_count, recovery_retry_delay_ms, recovery_total_latency_ms - from model_requests + from model_request_observations where id like 'req_websocket_failed_%' order by id", ) @@ -1293,14 +1293,19 @@ async fn seed_continuation_failure( .expect("seed continuation failure request"); sqlx::query( "update model_requests - set client_api_key_ref = 'key_continuation', client_transport = 'websocket', - continuation_affinity_hash = $2, - continuation_previous_response_id_hash = $3, - continuation_requested = true, - outcome = 'failed', error_kind = 'continuation_recovery_required', - continuation_unavailable_reason = 'reused_connection_lost', - started_at = $4 - interval '1 second', deadline_at = $4, - completed_at = $4 + set client_api_key_ref = 'key_continuation', + client_transport = 'websocket', + continuation_affinity_hash = $2, + continuation_requested = true, + outcome = 'failed', + error_kind = 'continuation_recovery_required', + started_at = $4 - interval '1 second', + deadline_at = $4, + completed_at = $4, + request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'continuation', coalesce(request_observation_json #> '{continuation}', '{}'::jsonb) || jsonb_build_object( + 'previousResponseIdHash', $3::text, + 'unavailableReason', 'reused_connection_lost'))) where id = $1", ) .bind(id) @@ -1348,14 +1353,19 @@ async fn seed_websocket_transport_failure( sqlx::query( "update model_requests set client_api_key_ref = 'key_transport_recovery', - client_transport = 'http_sse', - continuation_affinity_hash = $2, - attempt_count = 1, upstream_send_state = 'ambiguous', - upstream_transport = 'websocket', outcome = 'failed', - error_kind = 'upstream_unavailable', - provider_error_code = 'websocket_close_1000', - started_at = $3 - interval '1 second', deadline_at = $3, - completed_at = $3 + client_transport = 'http_sse', + continuation_affinity_hash = $2, + attempt_count = 1, + upstream_send_state = 'ambiguous', + upstream_transport = 'websocket', + outcome = 'failed', + error_kind = 'upstream_unavailable', + started_at = $3 - interval '1 second', + deadline_at = $3, + completed_at = $3, + request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'error', coalesce(request_observation_json #> '{error}', '{}'::jsonb) || jsonb_build_object( + 'providerErrorCode', 'websocket_close_1000'))) where id = $1", ) .bind(id) @@ -1394,13 +1404,20 @@ async fn seed_transport_recovery_request( async fn seed_running_request(pool: &sqlx::PgPool, id: &str) -> Result<(), sqlx::Error> { sqlx::query( "insert into model_requests ( - id, client_api_key_ref, config_revision, protocol, operation, endpoint, - client_transport, requested_model_id, provider_kind, provider_account_ref, cost_source, - started_at, deadline_at, - routing_scope, routing_group_refs, routing_group_names_snapshot - ) values ($1, 'key_status', 1, 'openai_responses', 'generate', '/v1/responses', - 'http_json', 'status-model', 'openai', 'acct_status', 'unavailable', now(), now() + interval '1 minute', - 'all', '{}'::text[], '[]'::jsonb)", + id, client_api_key_ref, operation, client_transport, requested_model_id, provider_kind, provider_account_ref, cost_source, started_at, deadline_at, request_observation_json + ) values ( + $1, 'key_status', 'generate', 'http_json', 'status-model', 'openai', 'acct_status', 'unavailable', now(), now() + interval '1 minute', + jsonb_strip_nulls(jsonb_build_object( + 'request', jsonb_build_object( + 'configRevision', 1, + 'protocol', 'openai_responses', + 'endpoint', '/v1/responses', + 'compact', false), + 'routing', jsonb_build_object( + 'scope', 'all', + 'groupRefs', '{}'::text[], + 'groupNamesSnapshot', '[]'::jsonb))) + )", ) .bind(id) .execute(pool) @@ -1440,7 +1457,7 @@ async fn diagnostic_trace_is_finalized_atomically_and_available_for_failed_reque .await .unwrap(); let persisted: (String, serde_json::Value, String) = sqlx::query_as( - "select outcome, diagnostic_trace_json, error_message from model_requests where id = 'req_diagnostic_failed'" + "select outcome, diagnostic_trace_json, error_message from model_request_observations where id = 'req_diagnostic_failed'" ).fetch_one(&database.pool).await.unwrap(); assert_eq!( persisted, @@ -1547,7 +1564,7 @@ pub(super) fn early_failure(request: &CoreNewModelRequest) -> CoreModelRequestFi } async fn stored_row(pool: &PgPool, request_id: &str) -> Value { - sqlx::query_scalar("select to_jsonb(mr) from model_requests mr where id = $1") + sqlx::query_scalar("select to_jsonb(mr) from model_request_observations mr where id = $1") .bind(request_id) .fetch_one(pool) .await @@ -2123,6 +2140,13 @@ async fn shared_core_usage_and_timings_preserve_fields_and_reject_invalid_phases first_text_ms: Some(6), first_token_ms: Some(7), provider_processing_ms: Some(8), + 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) @@ -2146,10 +2170,29 @@ async fn shared_core_usage_and_timings_preserve_fields_and_reject_invalid_phases ("first_text_ms", 6), ("first_token_ms", 7), ("provider_processing_ms", 8), + ("upstream_response_ms", 1_000), ("latency_ms", 9), ] { assert_eq!(persisted[field], json!(expected), "{field}"); } + 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 @@ -2163,5 +2206,100 @@ async fn shared_core_usage_and_timings_preserve_fields_and_reject_invalid_phases .unwrap_err(); assert_eq!(error.kind(), StoreErrorKind::InvalidData); 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); + let error = ExecutionStore::finalize_model_request(&store, invalid) + .await + .expect_err("invalid official timing must not silently become missing"); + assert_eq!(error.kind(), StoreErrorKind::InvalidData); + assert_eq!(stored_row(&database.pool, invalid_id).await, before); + } + database.close().await; +} + +#[tokio::test] +async fn concurrent_retry_updates_keep_request_context_and_clear_previous_transport() { + let Some(database) = TestDatabase::create("observation_retry_cas").await else { + return; + }; + let store = PgExecutionStore::new(database.pool.clone()); + let request = accepted_request("req_observation_retry"); + store.create_model_request(request.clone()).await.unwrap(); + let before = stored_row(&database.pool, request.id.as_str()).await; + let mut attempt = ModelRequestAttemptStart { + model_request_id: request.id.as_str().to_owned(), + attempt_count: 1, + provider_kind: "openai".to_owned(), + provider_account_id: None, + provider_account_ref: Some("deleted_account".to_owned()), + upstream_model_id: Some("model".to_owned()), + upstream_transport: "http_sse".to_owned(), + http_version: Some("HTTP/1.1".to_owned()), + account_selection_wait_ms: Some(5), + capacity_used_slots: Some(1), + capacity_total_slots: Some(10), + }; + store + .begin_model_request_attempt(attempt.clone()) + .await + .unwrap(); + sqlx::query("update model_requests set request_observation_json = request_observation_json || $1::jsonb where id = $2") + .bind(sqlx::types::Json( + json!({"transport": {"httpVersion":"HTTP/1.1", "connection": { + "id":"previous", "exitReason":"peer_closed", "ageMs":10, "idleMs":0 + }}}), + )) + .bind(request.id.as_str()) + .execute(&database.pool) + .await + .unwrap(); + attempt.attempt_count = 2; + attempt.http_version = Some("HTTP/2".to_owned()); + attempt.account_selection_wait_ms = Some(7); + attempt.capacity_used_slots = Some(2); + let (first, second) = tokio::join!( + store.begin_model_request_attempt(attempt.clone()), + store.begin_model_request_attempt(attempt), + ); + assert_eq!(usize::from(first.is_ok()) + usize::from(second.is_ok()), 1); + let retried = stored_row(&database.pool, request.id.as_str()).await; + let observation = &retried["request_observation_json"]; + assert_eq!( + observation["request"], + before["request_observation_json"]["request"] + ); + assert_eq!( + observation["routing"], + before["request_observation_json"]["routing"] + ); + assert_eq!(observation["scheduling"]["admissionDecisionMs"], 2); + assert_eq!(observation["scheduling"]["accountSelectionWaitMs"], 12); + assert_eq!(observation["scheduling"]["capacityUsedSlots"], 2); + assert_eq!(observation["transport"], json!({"httpVersion":"HTTP/2"})); + let mut finalization = successful_core_finalization(request.id.as_str()); + finalization.attempt_count = 2; + finalization.http_version = None; + finalization.timings.upstream_response_ms = Some(1_000); + ExecutionStore::finalize_model_request(&store, finalization) + .await + .unwrap(); + let terminal = stored_row(&database.pool, request.id.as_str()).await; + assert_eq!( + terminal["request_observation_json"]["scheduling"], + observation["scheduling"] + ); + assert_eq!( + terminal["request_observation_json"]["request"], + observation["request"] + ); + assert_eq!( + terminal["request_observation_json"]["transport"]["httpVersion"], + "HTTP/2" + ); + assert_eq!( + terminal["request_observation_json"]["timings"]["upstream"]["responseMs"], + 1_000 + ); database.close().await; } diff --git a/backend/crates/gateway-store/tests/postgres/observability/mod.rs b/backend/crates/gateway-store/tests/postgres/observability/mod.rs index 0671b16a7..b77d5a1d5 100644 --- a/backend/crates/gateway-store/tests/postgres/observability/mod.rs +++ b/backend/crates/gateway-store/tests/postgres/observability/mod.rs @@ -67,8 +67,8 @@ fn usage_outcome_filter_should_accept_bounded_unknown_values() { } #[tokio::test] -async fn output_throughput_uses_full_duration_independently_of_first_token() { - let Some(database) = TestDatabase::create("output_throughput_full_duration").await else { +async fn output_throughput_uses_official_response_duration_without_local_fallback() { + let Some(database) = TestDatabase::create("output_throughput_official_duration").await else { return; }; let now = Utc::now(); @@ -79,30 +79,74 @@ async fn output_throughput_uses_full_duration_independently_of_first_token() { let store = admin_observability_store(&database.pool); let admin_range = admin_observability::TimeRange::new(range.start, range.end).unwrap(); - // 输出包含首字前的推理量；首字缺失或仅剩 1 ms 都不应改变整次请求速率 - for (first_token, latency, output, expected) in [ - (Some(17_799_i64), Some(19_216_i64), Some(605_i64), Some(31)), - (None, Some(19_216), Some(605), Some(31)), - (Some(19_215), Some(19_216), Some(605), Some(31)), - (Some(19_216), Some(19_216), Some(605), Some(31)), - (None, Some(0), Some(605), None), - (None, None, Some(605), None), - (None, Some(19_216), Some(0), None), - (None, Some(19_216), None, None), + // 官方输出已包含推理量；本地总耗时和首字不能改变速率，也不能补齐上游耗时 + for (first_token, latency, upstream, output, expected) in [ + ( + Some(14_238_i64), + Some(15_604_i64), + Some(7_000_i64), + Some(112_i64), + Some(16), + ), + (None, Some(15_604), Some(7_000), Some(112), Some(16)), + (Some(15_603), Some(15_604), Some(7_000), Some(112), Some(16)), + (None, None, Some(7_000), Some(112), Some(16)), + (None, Some(0), Some(7_000), Some(112), Some(16)), + (Some(10_196), Some(11_186), Some(3_000), Some(46), Some(15)), + (None, Some(15_604), None, Some(112), None), + (None, Some(15_604), Some(7_000), Some(0), None), + (None, Some(15_604), Some(7_000), None, None), ] { sqlx::query( "update model_requests - set output_tokens = $1, reasoning_tokens = 500, - first_token_ms = $2, latency_ms = $3 + set output_tokens = $1, + reasoning_tokens = case when $1 > 0 then 20 else null end, + request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'timings', coalesce(request_observation_json #> '{timings}', '{}'::jsonb) || jsonb_build_object( + 'local', coalesce(request_observation_json #> '{timings,local}', '{}'::jsonb) || jsonb_build_object( + 'firstTokenMs', $2::bigint, + 'latencyMs', $3::bigint), + 'upstream', coalesce(request_observation_json #> '{timings,upstream}', '{}'::jsonb) || jsonb_build_object( + 'responseMs', $4::bigint, 'engineIapiTbtMs', 2.450638)))) where id = 'req_observe_success'", ) .bind(output) .bind(first_token) .bind(latency) + .bind(upstream) .execute(&database.pool) .await .unwrap(); + let records = repository + .list_usage_records(UsageRecordQuery { + range, + filter: UsageRecordFilter::default(), + current_page: 1, + page_size: ObservabilityPageSize::new(10).unwrap(), + }) + .await + .expect("official duration in usage list"); + let record = records + .items + .iter() + .find(|record| record.id == "req_observe_success") + .unwrap(); + assert_eq!( + record.upstream_response_ms, + upstream.map(|value| value as u64) + ); + let detail = repository + .usage_record_detail("req_observe_success") + .await + .expect("official duration in usage detail"); + assert_eq!( + 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)); + let summary = repository .usage_summary(range, UsageRecordFilter::default()) .await @@ -453,14 +497,18 @@ async fn usage_search_should_match_account_email_and_name_prefixes() { assert_usage_search_ids(&database.pool, range, search, &[]).await; } - sqlx::query("update model_requests set provider_account_email_snapshot = null") + sqlx::query("update model_requests set request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'account', coalesce(request_observation_json #> '{account}', '{}'::jsonb) || jsonb_build_object( + 'email', null)))") .execute(&database.pool) .await .expect("clear account email snapshots"); assert_usage_search_ids(&database.pool, range, "primary", &["req_observe_success"]).await; assert_usage_search_ids(&database.pool, range, "account@", &[]).await; - sqlx::query("update model_requests set provider_account_name_snapshot = null") + sqlx::query("update model_requests set request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'account', coalesce(request_observation_json #> '{account}', '{}'::jsonb) || jsonb_build_object( + 'name', null)))") .execute(&database.pool) .await .expect("clear account name snapshots"); @@ -517,7 +565,10 @@ async fn usage_search_should_treat_account_snapshot_wildcards_as_literals() { .expect("seed observability facts"); sqlx::query( "update model_requests - set provider_account_email_snapshot = $1, provider_account_name_snapshot = $2", + set request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'account', coalesce(request_observation_json #> '{account}', '{}'::jsonb) || jsonb_build_object( + 'email', $1::text, + 'name', $2::text)))", ) .bind("account_team%tag@example.invalid") .bind(r"primary\ops_100%") @@ -848,11 +899,17 @@ async fn ops_should_include_incomplete_upstream_errors() { let raw_error = r#"{"type":"error","status":400,"error":{"type":"invalid_request_error","message":"Invalid `previous_response_id`."}}"#; sqlx::query( "update model_requests - set outcome = 'incomplete', error_kind = 'invalid_request', - client_transport = 'websocket', upstream_transport = 'websocket', - downstream_committed_at = completed_at, - client_status_code = null, upstream_status_code = 400, - provider_error_code = null, error_details = $1 + set outcome = 'incomplete', + error_kind = 'invalid_request', + client_transport = 'websocket', + upstream_transport = 'websocket', + downstream_committed_at = completed_at, + client_status_code = null, + upstream_status_code = 400, + error_details = $1, + request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'error', coalesce(request_observation_json #> '{error}', '{}'::jsonb) || jsonb_build_object( + 'providerErrorCode', null))) where id = 'req_observe_failed'", ) .bind(raw_error) @@ -964,13 +1021,18 @@ async fn recovered_continuation_failure_should_be_visible_in_ops_but_hidden_from sqlx::query( "update model_requests set error_kind = 'continuation_recovery_required', - continuation_affinity_hash = $2, - continuation_previous_response_id_hash = $3, - continuation_requested = true, - continuation_unavailable_reason = 'reused_connection_lost', - recovery_request_id = 'req_observe_success', recovered_at = $1, - recovery_attempt_count = 1, recovery_retry_delay_ms = 4000, - recovery_total_latency_ms = 8000 + continuation_affinity_hash = $2, + continuation_requested = true, + recovery_request_id = 'req_observe_success', + recovered_at = $1, + recovery_attempt_count = 1, + request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'continuation', coalesce(request_observation_json #> '{continuation}', '{}'::jsonb) || jsonb_build_object( + 'previousResponseIdHash', $3::text, + 'unavailableReason', 'reused_connection_lost'), + 'recovery', coalesce(request_observation_json #> '{recovery}', '{}'::jsonb) || jsonb_build_object( + 'retryDelayMs', 4000, + 'totalLatencyMs', 8000))) where id = 'req_observe_failed'", ) .bind(now) @@ -2149,25 +2211,26 @@ async fn seed_observability_facts( .await?; sqlx::query( "insert into model_requests ( - id, client_api_key_ref, config_revision, protocol, operation, endpoint, - client_transport, requested_model_id, - provider_kind, provider_account_id, - provider_account_ref, upstream_model_id, upstream_transport, - provider_account_name_snapshot, provider_account_email_snapshot, - provider_account_authentication_kind_snapshot, - attempt_count, upstream_send_state, outcome, client_status_code, - input_tokens, output_tokens, total_tokens, cost_source, latency_ms, - started_at, deadline_at, completed_at, - routing_scope, routing_group_refs, routing_group_names_snapshot + id, client_api_key_ref, operation, client_transport, requested_model_id, provider_kind, provider_account_id, provider_account_ref, upstream_model_id, upstream_transport, attempt_count, upstream_send_state, outcome, client_status_code, input_tokens, output_tokens, total_tokens, cost_source, started_at, deadline_at, completed_at, request_observation_json ) values ( - 'req_observe_uncommitted', 'key_observe', 1, 'openai', 'responses', '/v1/responses', - 'http_sse', 'public-model', 'openai', 'acct_observe', - 'acct_observe', 'upstream-model', 'http_sse', - 'primary', 'account@example.invalid', 'oauth', - 1, 'sent', 'succeeded', 200, - 900, 900, 1800, 'unavailable', 650, - $1 - interval '15 minutes', $1 + interval '10 minutes', $1 - interval '14 minutes', - 'all', '{}'::text[], '[]'::jsonb + 'req_observe_uncommitted', 'key_observe', 'responses', 'http_sse', 'public-model', 'openai', 'acct_observe', 'acct_observe', 'upstream-model', 'http_sse', 1, 'sent', 'succeeded', 200, 900, 900, 1800, 'unavailable', $1 - interval '15 minutes', $1 + interval '10 minutes', $1 - interval '14 minutes', + jsonb_strip_nulls(jsonb_build_object( + 'request', jsonb_build_object( + 'configRevision', 1, + 'protocol', 'openai', + 'endpoint', '/v1/responses', + 'compact', false), + 'account', jsonb_build_object( + 'name', 'primary', + 'email', 'account@example.invalid', + 'authenticationKind', 'oauth'), + 'timings', jsonb_build_object( + 'local', jsonb_build_object( + 'latencyMs', 650)), + 'routing', jsonb_build_object( + 'scope', 'all', + 'groupRefs', '{}'::text[], + 'groupNamesSnapshot', '[]'::jsonb))) )", ) .bind(now) @@ -2175,34 +2238,29 @@ async fn seed_observability_facts( .await?; sqlx::query( "insert into model_requests ( - id, client_api_key_ref, config_revision, protocol, operation, endpoint, - client_transport, requested_model_id, - provider_kind, provider_account_id, - provider_account_ref, upstream_model_id, upstream_transport, websocket_pool, - service_tier, - provider_account_name_snapshot, provider_account_email_snapshot, - provider_account_authentication_kind_snapshot, - attempt_count, - upstream_send_state, downstream_committed_at, outcome, client_status_code, - upstream_status_code, client_response_id, upstream_request_id, upstream_response_id, - input_tokens, output_tokens, cached_tokens, cache_write_tokens, reasoning_tokens, - image_input_tokens, image_output_tokens, total_tokens, - image_generation_requested, image_generation_succeeded, - cost_source, cost_amount, cost_currency, first_token_ms, latency_ms, - started_at, deadline_at, completed_at, - routing_scope, routing_group_refs, routing_group_names_snapshot + id, client_api_key_ref, operation, client_transport, requested_model_id, provider_kind, provider_account_id, provider_account_ref, upstream_model_id, upstream_transport, service_tier, attempt_count, upstream_send_state, downstream_committed_at, outcome, client_status_code, upstream_status_code, client_response_id, upstream_request_id, upstream_response_id, input_tokens, output_tokens, cached_tokens, cache_write_tokens, reasoning_tokens, image_input_tokens, image_output_tokens, total_tokens, image_generation_requested, image_generation_succeeded, cost_source, cost_amount, cost_currency, started_at, deadline_at, completed_at, request_observation_json ) values ( - 'req_observe_success', 'key_observe', 1, 'openai', 'responses', '/v1/responses', - 'http_sse', 'public-model', 'openai', 'acct_observe', - 'acct_observe', 'upstream-model', - 'http_sse', 'reuse', 'priority', - 'primary', 'account@example.invalid', 'oauth', - 1, 'sent', $1 - interval '19 minutes', 'succeeded', 200, 200, - 'resp_observe_success', 'upstream_req_success', 'upstream_resp_success', - 100, 20, 40, 3, 5, 31, 9, 120, true, true, - 'provider_reported', 1.25, 'USD', 120, 900, - $1 - interval '20 minutes', $1 + interval '10 minutes', $1 - interval '19 minutes', - 'groups', array['grp_history'], jsonb_build_array('Historical group') + 'req_observe_success', 'key_observe', 'responses', 'http_sse', 'public-model', 'openai', 'acct_observe', 'acct_observe', 'upstream-model', 'http_sse', 'priority', 1, 'sent', $1 - interval '19 minutes', 'succeeded', 200, 200, 'resp_observe_success', 'upstream_req_success', 'upstream_resp_success', 100, 20, 40, 3, 5, 31, 9, 120, true, true, 'provider_reported', 1.25, 'USD', $1 - interval '20 minutes', $1 + interval '10 minutes', $1 - interval '19 minutes', + jsonb_strip_nulls(jsonb_build_object( + 'request', jsonb_build_object( + 'configRevision', 1, + 'protocol', 'openai', + 'endpoint', '/v1/responses', + 'compact', false), + 'transport', jsonb_build_object( + 'websocketPool', 'reuse'), + 'account', jsonb_build_object( + 'name', 'primary', + 'email', 'account@example.invalid', + 'authenticationKind', 'oauth'), + 'timings', jsonb_build_object( + 'local', jsonb_build_object( + 'firstTokenMs', 120, + 'latencyMs', 900)), + 'routing', jsonb_build_object( + 'scope', 'groups', + 'groupRefs', array['grp_history'], + 'groupNamesSnapshot', jsonb_build_array('Historical group')))) )", ) .bind(now) @@ -2210,32 +2268,35 @@ async fn seed_observability_facts( .await?; sqlx::query( "insert into model_requests ( - id, client_api_key_ref, config_revision, protocol, operation, endpoint, - client_transport, requested_model_id, service_tier, - provider_kind, provider_account_id, - provider_account_ref, upstream_model_id, upstream_transport, attempt_count, - provider_account_name_snapshot, provider_account_email_snapshot, - provider_account_authentication_kind_snapshot, - upstream_send_state, outcome, client_status_code, upstream_status_code, - error_kind, provider_error_code, error_message, retry_after_ms, - input_tokens, cached_tokens, image_generation_requested, - image_generation_succeeded, cost_source, latency_ms, - client_ip, user_agent, reasoning_effort, reasoning_preset, - request_kind, subagent_kind, compact, - started_at, deadline_at, completed_at, - routing_scope, routing_group_refs, routing_group_names_snapshot + id, client_api_key_ref, operation, client_transport, requested_model_id, service_tier, provider_kind, provider_account_id, provider_account_ref, upstream_model_id, upstream_transport, attempt_count, upstream_send_state, outcome, client_status_code, upstream_status_code, error_kind, input_tokens, cached_tokens, image_generation_requested, image_generation_succeeded, cost_source, request_kind, started_at, deadline_at, completed_at, request_observation_json ) values ( - 'req_observe_failed', 'key_observe', 1, 'openai', 'responses', '/v1/responses', - 'http_sse', 'public-model', 'priority', 'openai', 'acct_observe', - 'acct_observe', 'upstream-model', - 'http_sse', 2, - 'primary', 'account@example.invalid', 'oauth', - 'sent', 'failed', 502, 429, 'rate_limited', 'rate_limit', - 'upstream limited', 1000, 0, 0, true, false, 'unavailable', 700, - '203.0.113.9', 'codex-cli/0.144.0', 'medium', null, - 'root', null, false, - $1 - interval '10 minutes', $1 + interval '20 minutes', $1 - interval '9 minutes', - 'all', '{}'::text[], '[]'::jsonb + 'req_observe_failed', 'key_observe', 'responses', 'http_sse', 'public-model', 'priority', 'openai', 'acct_observe', 'acct_observe', 'upstream-model', 'http_sse', 2, 'sent', 'failed', 502, 429, 'rate_limited', 0, 0, true, false, 'unavailable', 'root', $1 - interval '10 minutes', $1 + interval '20 minutes', $1 - interval '9 minutes', + jsonb_strip_nulls(jsonb_build_object( + 'request', jsonb_build_object( + 'configRevision', 1, + 'protocol', 'openai', + 'endpoint', '/v1/responses', + 'clientIp', '203.0.113.9', + 'userAgent', 'codex-cli/0.144.0', + 'reasoningEffort', 'medium', + 'reasoningPreset', null, + 'subagentKind', null, + 'compact', false), + 'account', jsonb_build_object( + 'name', 'primary', + 'email', 'account@example.invalid', + 'authenticationKind', 'oauth'), + 'error', jsonb_build_object( + 'providerErrorCode', 'rate_limit', + 'message', 'upstream limited', + 'retryAfterMs', 1000), + 'timings', jsonb_build_object( + 'local', jsonb_build_object( + 'latencyMs', 700)), + 'routing', jsonb_build_object( + 'scope', 'all', + 'groupRefs', '{}'::text[], + 'groupNamesSnapshot', '[]'::jsonb))) )", ) .bind(now) @@ -2270,24 +2331,23 @@ async fn seed_calculated_billing_facts( ) -> Result<(), sqlx::Error> { sqlx::query( "insert into model_requests ( - id, client_api_key_ref, config_revision, protocol, operation, endpoint, - client_transport, requested_model_id, provider_kind, provider_account_id, - provider_account_ref, upstream_model_id, upstream_transport, attempt_count, - provider_account_name_snapshot, provider_account_email_snapshot, - provider_account_authentication_kind_snapshot, - upstream_send_state, downstream_committed_at, outcome, client_status_code, - input_tokens, output_tokens, cached_tokens, cache_write_tokens, total_tokens, service_tier, - cost_source, cost_amount, cost_currency, started_at, deadline_at, completed_at, - routing_scope, routing_group_refs, routing_group_names_snapshot + id, client_api_key_ref, operation, client_transport, requested_model_id, provider_kind, provider_account_id, provider_account_ref, upstream_model_id, upstream_transport, attempt_count, upstream_send_state, downstream_committed_at, outcome, client_status_code, input_tokens, output_tokens, cached_tokens, cache_write_tokens, total_tokens, service_tier, cost_source, cost_amount, cost_currency, started_at, deadline_at, completed_at, request_observation_json ) values ( - 'req_observe_calculated', 'key_observe', 1, 'openai', 'responses', '/v1/responses', - 'http_sse', 'public-model', 'openai', 'acct_observe', 'acct_observe', 'gpt-5.5', - 'http_sse', 1, - 'primary', 'account@example.invalid', 'oauth', - 'sent', $1 - interval '29 minutes', 'succeeded', 200, - 800, 200, 0, 0, 1000, 'priority', 'calculated', 1.25, 'USD', - $1 - interval '30 minutes', $1 + interval '10 minutes', $1 - interval '29 minutes', - 'all', '{}'::text[], '[]'::jsonb + 'req_observe_calculated', 'key_observe', 'responses', 'http_sse', 'public-model', 'openai', 'acct_observe', 'acct_observe', 'gpt-5.5', 'http_sse', 1, 'sent', $1 - interval '29 minutes', 'succeeded', 200, 800, 200, 0, 0, 1000, 'priority', 'calculated', 1.25, 'USD', $1 - interval '30 minutes', $1 + interval '10 minutes', $1 - interval '29 minutes', + jsonb_strip_nulls(jsonb_build_object( + 'request', jsonb_build_object( + 'configRevision', 1, + 'protocol', 'openai', + 'endpoint', '/v1/responses', + 'compact', false), + 'account', jsonb_build_object( + 'name', 'primary', + 'email', 'account@example.invalid', + 'authenticationKind', 'oauth'), + 'routing', jsonb_build_object( + 'scope', 'all', + 'groupRefs', '{}'::text[], + 'groupNamesSnapshot', '[]'::jsonb))) )", ) .bind(now) @@ -2295,23 +2355,23 @@ async fn seed_calculated_billing_facts( .await?; sqlx::query( "insert into model_requests ( - id, client_api_key_ref, config_revision, protocol, operation, endpoint, - client_transport, requested_model_id, provider_kind, provider_account_id, - provider_account_ref, upstream_model_id, upstream_transport, attempt_count, - provider_account_name_snapshot, provider_account_email_snapshot, - provider_account_authentication_kind_snapshot, - upstream_send_state, outcome, client_status_code, input_tokens, output_tokens, - total_tokens, cost_source, cost_amount, cost_currency, started_at, deadline_at, - completed_at, routing_scope, routing_group_refs, routing_group_names_snapshot + id, client_api_key_ref, operation, client_transport, requested_model_id, provider_kind, provider_account_id, provider_account_ref, upstream_model_id, upstream_transport, attempt_count, upstream_send_state, outcome, client_status_code, input_tokens, output_tokens, total_tokens, cost_source, cost_amount, cost_currency, started_at, deadline_at, completed_at, request_observation_json ) values ( - 'req_observe_calculated_uncommitted', 'key_observe', 1, 'openai', 'responses', - '/v1/responses', 'http_sse', 'public-model', 'openai', 'acct_observe', - 'acct_observe', 'gpt-5.5', 'http_sse', 1, - 'primary', 'account@example.invalid', 'oauth', - 'sent', 'succeeded', 200, 800, 200, - 1000, 'calculated', 1.25, 'USD', - $1 - interval '40 minutes', $1 + interval '10 minutes', $1 - interval '39 minutes', - 'all', '{}'::text[], '[]'::jsonb + 'req_observe_calculated_uncommitted', 'key_observe', 'responses', 'http_sse', 'public-model', 'openai', 'acct_observe', 'acct_observe', 'gpt-5.5', 'http_sse', 1, 'sent', 'succeeded', 200, 800, 200, 1000, 'calculated', 1.25, 'USD', $1 - interval '40 minutes', $1 + interval '10 minutes', $1 - interval '39 minutes', + jsonb_strip_nulls(jsonb_build_object( + 'request', jsonb_build_object( + 'configRevision', 1, + 'protocol', 'openai', + 'endpoint', '/v1/responses', + 'compact', false), + 'account', jsonb_build_object( + 'name', 'primary', + 'email', 'account@example.invalid', + 'authenticationKind', 'oauth'), + 'routing', jsonb_build_object( + 'scope', 'all', + 'groupRefs', '{}'::text[], + 'groupNamesSnapshot', '[]'::jsonb))) )", ) .bind(now) diff --git a/backend/crates/gateway-store/tests/postgres/provider_accounts/mod.rs b/backend/crates/gateway-store/tests/postgres/provider_accounts/mod.rs index a1c4aadd2..f88c00135 100644 --- a/backend/crates/gateway-store/tests/postgres/provider_accounts/mod.rs +++ b/backend/crates/gateway-store/tests/postgres/provider_accounts/mod.rs @@ -3184,23 +3184,19 @@ async fn seed_model_request( ) -> Result<(), sqlx::Error> { sqlx::query( "insert into model_requests ( - id, client_api_key_ref, config_revision, protocol, operation, endpoint, - client_transport, requested_model_id, - provider_kind, provider_account_id, - provider_account_ref, upstream_model_id, upstream_transport, attempt_count, - upstream_send_state, downstream_committed_at, outcome, client_status_code, - upstream_status_code, - input_tokens, output_tokens, cached_tokens, cache_write_tokens, reasoning_tokens, - total_tokens, cost_source, cost_amount, cost_currency, - started_at, deadline_at, completed_at, - routing_scope, routing_group_refs, routing_group_names_snapshot + id, client_api_key_ref, operation, client_transport, requested_model_id, provider_kind, provider_account_id, provider_account_ref, upstream_model_id, upstream_transport, attempt_count, upstream_send_state, downstream_committed_at, outcome, client_status_code, upstream_status_code, input_tokens, output_tokens, cached_tokens, cache_write_tokens, reasoning_tokens, total_tokens, cost_source, cost_amount, cost_currency, started_at, deadline_at, completed_at, request_observation_json ) values ( - $1, 'key-provider-account-test', 1, 'openai', 'responses', '/v1/responses', - 'http_sse', $4, $3, $2, $2, $4, 'http_sse', 1, - 'sent', $7 + interval '1 second', 'succeeded', 200, 200, $5, 0, 0, 0, 0, - $5, 'provider_reported', $6::numeric, 'USD', $7, - $7 + interval '5 minutes', $7 + interval '1 second', - 'all', '{}'::text[], '[]'::jsonb + $1, 'key-provider-account-test', 'responses', 'http_sse', $4, $3, $2, $2, $4, 'http_sse', 1, 'sent', $7 + interval '1 second', 'succeeded', 200, 200, $5, 0, 0, 0, 0, $5, 'provider_reported', $6::numeric, 'USD', $7, $7 + interval '5 minutes', $7 + interval '1 second', + jsonb_strip_nulls(jsonb_build_object( + 'request', jsonb_build_object( + 'configRevision', 1, + 'protocol', 'openai', + 'endpoint', '/v1/responses', + 'compact', false), + 'routing', jsonb_build_object( + 'scope', 'all', + 'groupRefs', '{}'::text[], + 'groupNamesSnapshot', '[]'::jsonb))) )", ) .bind(seed.request_id) diff --git a/backend/crates/gateway-store/tests/postgres/schema_integrity.rs b/backend/crates/gateway-store/tests/postgres/schema_integrity.rs index be6952b66..ca3239f22 100644 --- a/backend/crates/gateway-store/tests/postgres/schema_integrity.rs +++ b/backend/crates/gateway-store/tests/postgres/schema_integrity.rs @@ -7,7 +7,7 @@ async fn error_details_migration_preserves_existing_request_and_event_text() { let Some(db) = TestDatabase::create_through("error_details_upgrade", 22).await else { return; }; - seed_request(&db.pool).await; + seed_legacy_request(&db.pool).await; let raw = "{ \"error\": {\"code\":\"Vendor.Unknown\",\"message\":\"原始错误\"} }"; sqlx::query("update model_requests set raw_upstream_error = $1 where id = 'req_integrity'") .bind(raw) @@ -40,7 +40,7 @@ async fn error_details_migration_preserves_existing_request_and_event_text() { db.close().await; } -async fn seed_request(pool: &sqlx::PgPool) { +async fn seed_legacy_request(pool: &sqlx::PgPool) { sqlx::query( "insert into model_requests ( id, client_api_key_ref, config_revision, protocol, operation, endpoint, @@ -55,6 +55,29 @@ async fn seed_request(pool: &sqlx::PgPool) { .expect("seed request without optional facts"); } +async fn seed_request(pool: &sqlx::PgPool) { + sqlx::query( + "insert into model_requests ( + id, client_api_key_ref, operation, client_transport, started_at, deadline_at, outcome, completed_at, request_observation_json + ) values ( + 'req_integrity', 'deleted_key', 'responses', 'http_sse', now(), now() + interval '1 hour', 'failed', now(), + jsonb_strip_nulls(jsonb_build_object( + 'request', jsonb_build_object( + 'configRevision', 1, + 'protocol', 'openai', + 'endpoint', '/v1/responses', + 'compact', false), + 'routing', jsonb_build_object( + 'scope', 'all', + 'groupRefs', '{}'::text[], + 'groupNamesSnapshot', '[]'::jsonb))) + )", + ) + .execute(pool) + .await + .expect("seed request without optional facts"); +} + fn assert_check_rejected(error: &sqlx::Error) { assert_eq!( error @@ -73,13 +96,38 @@ async fn request_fact_groups_reject_partial_writes_and_accept_complete_observati seed_request(&db.pool).await; for assignments in [ "cost_source = 'calculated', cost_amount = 1", - "capacity_used_slots = 1", - "capacity_total_slots = 2", - "upstream_connection_id = 'connection'", - "upstream_connection_id = 'connection', upstream_connection_exit_reason = 'peer_closed', upstream_connection_age_ms = 10", + "request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'scheduling', coalesce(request_observation_json #> '{scheduling}', '{}'::jsonb) || jsonb_build_object( + 'capacityUsedSlots', 1)))", + "request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'scheduling', coalesce(request_observation_json #> '{scheduling}', '{}'::jsonb) || jsonb_build_object( + 'capacityTotalSlots', 2)))", + "request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'transport', coalesce(request_observation_json #> '{transport}', '{}'::jsonb) || jsonb_build_object( + 'connection', coalesce(request_observation_json #> '{transport,connection}', '{}'::jsonb) || jsonb_build_object( + 'id', 'connection'))))", + "request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'transport', coalesce(request_observation_json #> '{transport}', '{}'::jsonb) || jsonb_build_object( + 'connection', coalesce(request_observation_json #> '{transport,connection}', '{}'::jsonb) || jsonb_build_object( + 'id', 'connection', + 'exitReason', 'peer_closed', + 'ageMs', 10))))", "recovery_request_id = 'req_recovery', recovered_at = completed_at, recovery_attempt_count = 1", - "recovery_request_id = 'req_recovery', recovered_at = completed_at, recovery_attempt_count = 1, recovery_retry_delay_ms = 0", - "outcome = 'running', completed_at = null, recovered_at = now(), recovery_request_id = 'req_recovery', recovery_attempt_count = 1, recovery_retry_delay_ms = 0, recovery_total_latency_ms = 1", + "recovery_request_id = 'req_recovery', + recovered_at = completed_at, + recovery_attempt_count = 1, + request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'recovery', coalesce(request_observation_json #> '{recovery}', '{}'::jsonb) || jsonb_build_object( + 'retryDelayMs', 0)))", + "outcome = 'running', + completed_at = null, + recovered_at = now(), + recovery_request_id = 'req_recovery', + recovery_attempt_count = 1, + request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'recovery', coalesce(request_observation_json #> '{recovery}', '{}'::jsonb) || jsonb_build_object( + 'retryDelayMs', 0, + 'totalLatencyMs', 1)))", ] { let error = sqlx::query(sqlx::AssertSqlSafe(format!( "update model_requests set {assignments} where id = 'req_integrity'" @@ -90,12 +138,25 @@ async fn request_fact_groups_reject_partial_writes_and_accept_complete_observati assert_check_rejected(&error); } sqlx::query( - "update model_requests set cost_source = 'calculated', cost_amount = 1, - cost_currency = 'USD', capacity_used_slots = 1, capacity_total_slots = 2, - upstream_connection_id = 'connection', upstream_connection_exit_reason = 'peer_closed', - upstream_connection_age_ms = 10, upstream_connection_idle_ms = 2, - recovery_request_id = 'req_recovery', recovered_at = completed_at, - recovery_attempt_count = 1, recovery_retry_delay_ms = 0, recovery_total_latency_ms = 1 + "update model_requests set cost_source = 'calculated', + cost_amount = 1, + cost_currency = 'USD', + recovery_request_id = 'req_recovery', + recovered_at = completed_at, + recovery_attempt_count = 1, + request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'scheduling', coalesce(request_observation_json #> '{scheduling}', '{}'::jsonb) || jsonb_build_object( + 'capacityUsedSlots', 1, + 'capacityTotalSlots', 2), + 'transport', coalesce(request_observation_json #> '{transport}', '{}'::jsonb) || jsonb_build_object( + 'connection', coalesce(request_observation_json #> '{transport,connection}', '{}'::jsonb) || jsonb_build_object( + 'id', 'connection', + 'exitReason', 'peer_closed', + 'ageMs', 10, + 'idleMs', 2)), + 'recovery', coalesce(request_observation_json #> '{recovery}', '{}'::jsonb) || jsonb_build_object( + 'retryDelayMs', 0, + 'totalLatencyMs', 1))) where id = 'req_integrity'", ) .execute(&db.pool) @@ -192,3 +253,158 @@ async fn backup_completion_cannot_precede_its_start() { assert_check_rejected(&error); db.close().await; } + +#[tokio::test] +async fn request_observation_migration_preserves_every_historical_field() { + let Some(db) = TestDatabase::create_through("request_observation_upgrade", 24).await else { + return; + }; + seed_legacy_request(&db.pool).await; + sqlx::raw_sql( + "insert into model_requests + select (jsonb_populate_record(null::model_requests, + to_jsonb(mr) || jsonb_build_object('id', 'req_empty'))).* + from model_requests mr; + update model_requests set config_revision = 7, + provider_account_name_snapshot = 'historical account', + provider_account_email_snapshot = 'history@example.invalid', + provider_account_authentication_kind_snapshot = 'oauth', + routing_scope = 'groups', routing_group_refs = array['deleted_group'], + routing_group_names_snapshot = '[\"历史组\"]', + provider_error_code = 'rate_limit', error_message = 'safe error', retry_after_ms = 0, + client_ip = '192.0.2.10/24', user_agent = 'fixture', reasoning_effort = 'high', + reasoning_preset = 'balanced', subagent_kind = 'review', compact = true, + transport_decision_wait_ms = 0, connect_ms = 2, headers_ms = 3, + first_event_ms = 4, first_reasoning_ms = 5, first_text_ms = 6, + first_token_ms = 5, latency_ms = 1000, provider_processing_ms = 7, + admission_decision_ms = 0, account_selection_wait_ms = 8, + capacity_used_slots = 0, capacity_total_slots = 20, + http_version = 'HTTP/2', websocket_pool = 'reuse', + upstream_connection_id = 'connection', upstream_connection_exit_reason = 'peer_closed', + upstream_connection_age_ms = 10, upstream_connection_idle_ms = 0, + upstream_response_model = 'response-model', continuation_requested = true, + continuation_previous_response_id_hash = repeat('a', 64), + continuation_unavailable_reason = 'missing_response', + recovery_request_id = 'recovery', recovered_at = completed_at + interval '1 second', + recovery_attempt_count = 1, recovery_retry_delay_ms = 0, recovery_total_latency_ms = 1000, + input_tokens = 10, output_tokens = 20, total_tokens = 30, + cost_source = 'provider_reported', cost_amount = 0.0123456789, cost_currency = 'USD', + error_details = '{ \"opaque\": true }', provider_observation_json = '{\"vendor\":true}', + diagnostic_trace_json = '{\"attempts\":[]}' + where id = 'req_integrity'", + ).execute(&db.pool).await.expect("populate all moved fields in the released schema"); + let before: Vec = + sqlx::query_scalar("select to_jsonb(mr) from model_requests mr order by id") + .fetch_all(&db.pool) + .await + .unwrap(); + super::TEST_MIGRATOR.run(&db.pool).await.unwrap(); + let after: Vec = sqlx::query_scalar( + "select to_jsonb(mr) - 'request_observation_json' - 'upstream_response_ms' - 'upstream_api_overhead_ms' - 'upstream_engine_ms' - 'upstream_engine_iapi_ttft_ms' - 'upstream_engine_service_ttft_ms' - 'upstream_engine_iapi_tbt_ms' - 'upstream_engine_service_tbt_ms' + from model_request_observations mr order by id", + ) + .fetch_all(&db.pool) + .await + .unwrap(); + assert_eq!( + after, before, + "all 90 historical facts survive the migration" + ); + let columns: i64 = sqlx::query_scalar( + "select count(*) from information_schema.columns + where table_schema = current_schema() and table_name = 'model_requests'", + ) + .fetch_one(&db.pool) + .await + .unwrap(); + assert_eq!(columns, 49); + let observation: serde_json::Value = sqlx::query_scalar( + "select request_observation_json from model_requests where id = 'req_integrity'", + ) + .fetch_one(&db.pool) + .await + .unwrap(); + assert_eq!( + observation["timings"]["local"]["transportDecisionWaitMs"], + 0 + ); + assert_eq!(observation["scheduling"]["capacityUsedSlots"], 0); + assert!( + observation["timings"]["upstream"] + .get("responseMs") + .is_none() + ); + db.close().await; +} + +#[tokio::test] +async fn request_observation_reject_malformed_documents_and_keep_upstream_clock_independent() { + use serde_json::json; + + let Some(db) = TestDatabase::create("request_observation_shape").await else { + return; + }; + seed_request(&db.pool).await; + let original: serde_json::Value = + sqlx::query_scalar("select request_observation_json from model_requests") + .fetch_one(&db.pool) + .await + .unwrap(); + for patch in [ + json!({"unknown": {}}), + json!({"timings": []}), + json!({"request": {}}), + json!({"request": null}), + json!({"routing": {"scope": "all", "groupRefs": [null], "groupNamesSnapshot": []}}), + json!({"timings": {"local": {"latencyMs": -1}}}), + json!({"timings": {"local": {"latencyMs": 1.0}}}), + json!({"timings": {"local": {"latencyMs": "1"}}}), + json!({"timings": {"local": {"latencyMs": u64::MAX}}}), + json!({"timings": {"upstream": {"responseMs": 0}}}), + json!({"timings": {"upstream": {"engineMs": -0.5}}}), + json!({"timings": {"upstream": {"engineIapiTbtMs": "1.5"}}}), + json!({"timings": {"upstream": {"engineServiceTbtMs": 1e99}}}), + json!({"transport": {"websocketPool": "invalid"}}), + json!({"continuation": {"unavailableReason": "invalid reason"}}), + json!({"error": {"message": "x".repeat(1024 * 1024)}}), + ] { + let mut document = original.clone(); + document + .as_object_mut() + .unwrap() + .extend(patch.as_object().unwrap().clone()); + sqlx::query("update model_requests set request_observation_json = $1") + .bind(sqlx::types::Json(document)) + .execute(&db.pool) + .await + .expect_err("invalid JSON must not enter the query projection"); + } + let mut invalid_ip = original.clone(); + invalid_ip["request"]["clientIp"] = json!("not an IP address"); + sqlx::query("update model_requests set request_observation_json = $1") + .bind(sqlx::types::Json(invalid_ip)) + .execute(&db.pool) + .await + .expect_err("invalid IP"); + sqlx::query("update model_requests set request_observation_json = request_observation_json || $1::jsonb") + .bind(sqlx::types::Json(json!({"timings": { + "local": {"latencyMs": 1, "firstTokenMs": 0}, + "upstream": {"processingMs": 500, "responseMs": 1000, "engineIapiTbtMs": 2.450638, "apiOverheadMs": 0.0} + }}))) + .execute(&db.pool) + .await + .expect("upstream has an independent clock"); + let timing: (i64, i64, i64, Option) = sqlx::query_as( + "select first_token_ms, provider_processing_ms, upstream_response_ms, connect_ms + from model_request_observations", + ) + .fetch_one(&db.pool) + .await + .unwrap(); + assert_eq!(timing, (0, 500, 1000, None)); + let metrics: (f64, f64, Option) = sqlx::query_as( + "select upstream_engine_iapi_tbt_ms, upstream_api_overhead_ms, upstream_engine_ms from model_request_observations", + ).fetch_one(&db.pool).await.unwrap(); + assert_eq!(metrics, (2.450638, 0.0, None)); + db.close().await; +} diff --git a/backend/crates/gateway-store/tests/postgres/snapshots.rs b/backend/crates/gateway-store/tests/postgres/snapshots.rs index 6cc808363..6a0ecd97c 100644 --- a/backend/crates/gateway-store/tests/postgres/snapshots.rs +++ b/backend/crates/gateway-store/tests/postgres/snapshots.rs @@ -365,10 +365,15 @@ async fn ops_errors_should_keep_request_and_event_snapshots_after_account_deleti .expect("insert failed request"); sqlx::query( "update model_requests - set outcome = 'failed', error_kind = 'upstream_error', - error_message = 'snapshot failure', client_status_code = 502, - upstream_status_code = 502, completed_at = $1, - error_details = $2 + set outcome = 'failed', + error_kind = 'upstream_error', + client_status_code = 502, + upstream_status_code = 502, + completed_at = $1, + error_details = $2, + request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'error', coalesce(request_observation_json #> '{error}', '{}'::jsonb) || jsonb_build_object( + 'message', 'snapshot failure'))) where id = 'req_snap_error'", ) .bind(started_at + chrono::Duration::seconds(2)) @@ -707,9 +712,14 @@ async fn failure_diagnostics_should_only_include_errored_requests() { .expect("insert errored request"); sqlx::query( "update model_requests - set outcome = 'failed', error_kind = 'rate_limited', - error_message = 'upstream limited', client_status_code = 429, - upstream_status_code = 429, completed_at = $2 + set outcome = 'failed', + error_kind = 'rate_limited', + client_status_code = 429, + upstream_status_code = 429, + completed_at = $2, + request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'error', coalesce(request_observation_json #> '{error}', '{}'::jsonb) || jsonb_build_object( + 'message', 'upstream limited'))) where id = $1", ) .bind("req_snap_err") @@ -1021,11 +1031,17 @@ async fn api_key_diagnostics_should_display_key_name_and_fallback_to_ref() { .expect("insert api key request"); finalize_request(&database.pool, id, started_at).await; } - sqlx::query("update model_requests set latency_ms = 1000 where id = 'req_key_a'") + sqlx::query("update model_requests set request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'timings', coalesce(request_observation_json #> '{timings}', '{}'::jsonb) || jsonb_build_object( + 'local', coalesce(request_observation_json #> '{timings,local}', '{}'::jsonb) || jsonb_build_object( + 'latencyMs', 1000)))) where id = 'req_key_a'") .execute(&database.pool) .await .expect("set request a latency"); - sqlx::query("update model_requests set latency_ms = 2000 where id = 'req_key_b'") + sqlx::query("update model_requests set request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'timings', coalesce(request_observation_json #> '{timings}', '{}'::jsonb) || jsonb_build_object( + 'local', coalesce(request_observation_json #> '{timings,local}', '{}'::jsonb) || jsonb_build_object( + 'latencyMs', 2000)))) where id = 'req_key_b'") .execute(&database.pool) .await .expect("set request b latency"); @@ -1236,13 +1252,23 @@ async fn finalize_request_without_client_status( ) { sqlx::query( "update model_requests - set outcome = 'succeeded', upstream_send_state = 'sent', - client_status_code = null, upstream_status_code = 200, - input_tokens = 7, output_tokens = 3, total_tokens = 10, - first_token_ms = 100, latency_ms = 500, - cost_source = 'provider_reported', cost_amount = 1.25, - cost_currency = 'USD', - downstream_committed_at = $2, completed_at = $2 + set outcome = 'succeeded', + upstream_send_state = 'sent', + client_status_code = null, + upstream_status_code = 200, + input_tokens = 7, + output_tokens = 3, + total_tokens = 10, + cost_source = 'provider_reported', + cost_amount = 1.25, + cost_currency = 'USD', + downstream_committed_at = $2, + completed_at = $2, + request_observation_json = jsonb_strip_nulls(request_observation_json || jsonb_build_object( + 'timings', coalesce(request_observation_json #> '{timings}', '{}'::jsonb) || jsonb_build_object( + 'local', coalesce(request_observation_json #> '{timings,local}', '{}'::jsonb) || jsonb_build_object( + 'firstTokenMs', 100, + 'latencyMs', 500)))) where id = $1", ) .bind(id) diff --git a/backend/crates/providers/openai/src/provider/execution.rs b/backend/crates/providers/openai/src/provider/execution.rs index aa05fa48d..0115dbc51 100644 --- a/backend/crates/providers/openai/src/provider/execution.rs +++ b/backend/crates/providers/openai/src/provider/execution.rs @@ -1093,7 +1093,14 @@ pub(super) fn cold_response_stream(response: ColdResponse) -> EventStream { let timing_signals = decoder.take_timing_signals(); let output_timing_changed = observation_state .observe_timing_signals(timing_signals, context.timing_started_at()); - let timing_changed = first_event_changed || output_timing_changed; + let upstream_timing_changed = observation_state + .observe_upstream_response_ms(decoder.upstream_response_ms()); + let upstream_metrics_changed = observation_state + .observe_upstream_timing_metrics(decoder.upstream_timing_metrics()); + let timing_changed = first_event_changed + || output_timing_changed + || upstream_timing_changed + || upstream_metrics_changed; let completed = events .iter() .flat_map(ProviderEvent::canonical_facts) @@ -1204,8 +1211,15 @@ pub(super) fn cold_response_stream(response: ColdResponse) -> EventStream { .observe_upstream_response_model(decoder.response_model()); let service_tier_changed = observation_state .observe_upstream_service_tier(decoder.response_service_tier()); - let timing_changed = observation_state + let output_timing_changed = observation_state .observe_timing_signals(timing_signals, context.timing_started_at()); + let upstream_timing_changed = observation_state + .observe_upstream_response_ms(decoder.upstream_response_ms()); + let upstream_metrics_changed = observation_state + .observe_upstream_timing_metrics(decoder.upstream_timing_metrics()); + let timing_changed = output_timing_changed + || upstream_timing_changed + || upstream_metrics_changed; let updates = take_rate_limit_updates(rate_limit_updates.as_ref()).await; let rate_limits_changed = if updates.is_empty() { false diff --git a/backend/crates/providers/openai/src/provider/observation.rs b/backend/crates/providers/openai/src/provider/observation.rs index 6a0d26950..bdd400179 100644 --- a/backend/crates/providers/openai/src/provider/observation.rs +++ b/backend/crates/providers/openai/src/provider/observation.rs @@ -153,7 +153,7 @@ impl OpenAiResponseObservationState { started_at: Instant, ) -> bool { let mut changed = false; - // 首字观测包含非前导结构事件，真实推理与正文仍分别计时 + // 首字采用官方输出项边界，真实推理与正文仍分别计时 if signals.output_start { changed |= insert_first_timing(&mut self.timings.first_token_ms, started_at); } @@ -177,6 +177,43 @@ impl OpenAiResponseObservationState { true } + pub(super) fn observe_upstream_response_ms(&mut self, duration_ms: Option) -> bool { + let Some(duration_ms) = duration_ms else { + return false; + }; + if self.timings.upstream_response_ms == Some(duration_ms) { + return false; + } + self.timings.upstream_response_ms = Some(duration_ms); + true + } + + pub(super) fn observe_upstream_timing_metrics( + &mut self, + metrics: crate::transport::protocol::responses::ResponseTimingMetrics, + ) -> bool { + let previous = self.timings; + if metrics.upstream_api_overhead_ms.is_some() { + self.timings.upstream_api_overhead_ms = metrics.upstream_api_overhead_ms; + } + 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 + } + pub(super) fn merge_rate_limit_headers(&mut self, updates: &[(String, String)]) -> bool { let mut changed = false; for (name, value) in selected_observation_headers(updates) { diff --git a/backend/crates/providers/openai/src/transport/canonical.rs b/backend/crates/providers/openai/src/transport/canonical.rs index 6a24d7db9..4e0cd8d2e 100644 --- a/backend/crates/providers/openai/src/transport/canonical.rs +++ b/backend/crates/providers/openai/src/transport/canonical.rs @@ -22,7 +22,8 @@ use serde_json::Value; use thiserror::Error; use super::protocol::responses::{ - ResponseEventSignals, ResponsesSseFailure, response_event_signals, + ResponseEventSignals, ResponseTimingMetrics, ResponsesSseFailure, response_duration_ms, + response_event_signals, }; use super::usage::{ OpenAiBillingUsage, WebSearchPricing, normalize_service_tier, web_search_pricing, @@ -49,6 +50,8 @@ pub struct CodexCanonicalDecoder { semantic_output_seen: bool, requested_service_tier: Option, response_service_tier: Option, + upstream_response_ms: Option, + upstream_timing_metrics: ResponseTimingMetrics, response_model: ResponseModelObservation, reported_model: Option, web_search_pricing: Option, @@ -158,6 +161,8 @@ impl CodexCanonicalDecoder { semantic_output_seen: false, requested_service_tier: None, response_service_tier: None, + upstream_response_ms: None, + upstream_timing_metrics: ResponseTimingMetrics::default(), response_model: ResponseModelObservation::default(), reported_model: None, web_search_pricing: None, @@ -241,6 +246,16 @@ impl CodexCanonicalDecoder { self.response_service_tier.as_deref() } + /// 返回当前 attempt 的官方响应耗时，缺少完成响应时间戳时保留未知 + #[must_use] + pub const fn upstream_response_ms(&self) -> Option { + self.upstream_response_ms + } + + pub(crate) const fn upstream_timing_metrics(&self) -> ResponseTimingMetrics { + self.upstream_timing_metrics + } + /// 真实 HTTP 响应头提供初始报告；流内请求级报告可覆盖它 #[must_use] pub fn with_reported_model(mut self, model: Option<&str>) -> Self { @@ -327,6 +342,16 @@ impl CodexCanonicalDecoder { // 此帧不能成为客户端输出，也不能启动首个输出计时 return Ok(()); } + if event_type == Some("responsesapi.websocket_timing") && self.started && !self.completed { + // 无 ID 的官方计时帧仅属于当前已开始的响应，复用连接的尾帧不能跨边界归属 + let response_id = value + .get("response_id") + .or_else(|| value.pointer("/response/id")); + if response_id.is_none_or(|id| id.as_str() == self.response_id.as_deref()) { + self.upstream_timing_metrics + .merge(ResponseTimingMetrics::from_event(&value)); + } + } self.observe_response_service_tier(&value); self.response_model.observe(event_type, &value); if let Some(model) = super::response_meta::reported_model_from_event(&value) { @@ -886,6 +911,9 @@ impl CodexCanonicalDecoder { self.completed = true; return Ok(()); } + if event_type == "response.completed" { + self.upstream_response_ms = response_duration_ms(value); + } if let Some(items) = response.get("output").and_then(Value::as_array) { for (output_index, item) in items.iter().enumerate() { let output_index = diff --git a/backend/crates/providers/openai/src/transport/headers.rs b/backend/crates/providers/openai/src/transport/headers.rs index 171d46d5d..605e082ab 100644 --- a/backend/crates/providers/openai/src/transport/headers.rs +++ b/backend/crates/providers/openai/src/transport/headers.rs @@ -163,6 +163,12 @@ impl CodexBackendClient { context: CodexRequestContext<'_>, ) -> CodexClientResult { let mut headers = self.response_headers(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"), @@ -321,6 +327,7 @@ fn websocket_header_order(name: &str) -> usize { "x-codex-turn-metadata", "x-codex-routing-hint", "openai-beta", + "x-responsesapi-include-timing-metrics", "originator", "user-agent", "authorization", diff --git a/backend/crates/providers/openai/src/transport/protocol/responses.rs b/backend/crates/providers/openai/src/transport/protocol/responses.rs index 6d9a5ac79..ab6c86b6a 100644 --- a/backend/crates/providers/openai/src/transport/protocol/responses.rs +++ b/backend/crates/providers/openai/src/transport/protocol/responses.rs @@ -1,6 +1,6 @@ //! Codex Responses 请求、传输要求、事件信号与流式错误的协议解析 -use std::fmt; +use std::{fmt, time::Duration}; use gateway_core::account::FastMode; use gateway_protocol::openai::{ @@ -212,7 +212,7 @@ pub fn transport_requirement(request: &CodexResponsesRequest) -> TransportRequir /// 单个 Responses 事件对计时系统提供的稳定语义信号 /// -/// `output_start` 用于首字观测，包含非前导结构事件；`semantic_output` 仍要求 +/// `output_start` 只表示官方输出项开始事件；`semantic_output` 仍要求 /// 实际内容，供重试与交付边界使用，不能与首字观测互换 #[derive(Debug, Clone, Copy, Default, PartialEq, Eq)] pub struct ResponseEventSignals { @@ -223,24 +223,85 @@ pub struct ResponseEventSignals { pub text_output: bool, } +/// 仅使用同一条完成响应的官方时间戳计算响应耗时 +/// +/// 整数秒时间戳可能得到零跨度，缺失、倒序或无法落盘的时间均保留未知 +pub(crate) fn response_duration_ms(value: &Value) -> Option { + let response = value.get("response")?; + let created_at = response.get("created_at")?.as_f64()?; + let completed_at = response.get("completed_at")?.as_f64()?; + if created_at < 0.0 || completed_at <= created_at { + return None; + } + let duration = Duration::try_from_secs_f64(completed_at - created_at).ok()?; + let millis = i64::try_from(duration.as_millis()).ok()?; + (millis > 0).then_some(millis as u64) +} + +/// 官方专项计时快照，毫秒小数按原始值保存，各层级不可混算 +#[derive(Debug, Clone, Copy, Default, PartialEq)] +pub(crate) struct ResponseTimingMetrics { + pub upstream_api_overhead_ms: Option, + pub upstream_engine_ms: Option, + pub upstream_engine_iapi_ttft_ms: Option, + pub upstream_engine_service_ttft_ms: Option, + pub upstream_engine_iapi_tbt_ms: Option, + pub upstream_engine_service_tbt_ms: Option, +} + +impl ResponseTimingMetrics { + pub(crate) fn from_event(value: &Value) -> Self { + let metrics = value.get("timing_metrics"); + let milliseconds = |key: &str| { + metrics? + .get(key)? + .as_f64() + .filter(|value| value.is_finite() && *value >= 0.0 && *value < i64::MAX as f64) + }; + Self { + upstream_api_overhead_ms: milliseconds( + "responses_duration_excl_engine_and_client_tool_time_ms", + ), + upstream_engine_ms: milliseconds("engine_service_total_ms"), + upstream_engine_iapi_ttft_ms: milliseconds("engine_iapi_ttft_total_ms"), + upstream_engine_service_ttft_ms: milliseconds("engine_service_ttft_total_ms"), + upstream_engine_iapi_tbt_ms: milliseconds("engine_iapi_tbt_across_engine_calls_ms"), + upstream_engine_service_tbt_ms: milliseconds( + "engine_service_tbt_across_engine_calls_ms", + ), + } + } + + pub(crate) fn merge(&mut self, incoming: Self) { + if incoming.upstream_api_overhead_ms.is_some() { + self.upstream_api_overhead_ms = incoming.upstream_api_overhead_ms; + } + 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; + } + } +} + /// 从已解析的 Responses 事件提取计时语义 /// -/// 首字采用首个非前导、非心跳、非失败事件，包含结构事件 +/// 首字采用官方 Codex 的首个 output_item.added 边界 /// 语义输出仍要求文本、推理、工具参数、图片结果或工具执行 pub fn response_event_signals(event_type: Option<&str>, value: &Value) -> ResponseEventSignals { let mut signals = ResponseEventSignals { protocol_progress: !matches!(event_type, Some("response.failed" | "error")), - output_start: event_type.is_some_and(|event_type| { - !matches!( - event_type, - "response.created" - | "response.in_progress" - | "keepalive" - | "codex.rate_limits" - | "response.failed" - | "error" - ) - }), + output_start: event_type == Some("response.output_item.added"), ..ResponseEventSignals::default() }; match event_type { diff --git a/backend/crates/providers/openai/tests/provider/contract/timing.rs b/backend/crates/providers/openai/tests/provider/contract/timing.rs index c8f9381e3..2fecd417e 100644 --- a/backend/crates/providers/openai/tests/provider/contract/timing.rs +++ b/backend/crates/providers/openai/tests/provider/contract/timing.rs @@ -1,4 +1,4 @@ -//! 验证 SSE 与 WebSocket 的首字边界、首块计时和请求级计时原点 +//! 验证 SSE 与 WebSocket 的首字边界、请求级计时原点与独立上游耗时 use std::time::Instant; @@ -56,7 +56,140 @@ async fn finish_timings( } #[tokio::test] -async fn first_sse_chunk_records_content_on_the_request_clock_for_every_attempt() { +async fn official_response_duration_is_observed_independently_of_the_request_clock() { + for websocket in [false, true] { + let store = Arc::new(MemoryAccountStore::default()); + create_account(&store, "acct_provider_contract").await; + let created = json!({"type":"response.created","response":{"id":"resp_official_time","created_at":100}}); + let completed = json!({"type":"response.completed","response":{"id":"resp_official_time","status":"completed","created_at":100,"completed_at":107,"output":[],"usage":{"input_tokens":1,"output_tokens":112,"total_tokens":113}}}); + 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]; + let (base_url, server) = if websocket { + let listener = TcpListener::bind("127.0.0.1:0").await.unwrap(); + let base_url = format!("http://{}", listener.local_addr().unwrap()); + let server = tokio::spawn(async move { + let (socket, _) = listener.accept().await.unwrap(); + 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" + ); + response.headers_mut().insert( + "sec-websocket-extensions", + "permessage-deflate".parse().unwrap(), + ); + }, + ) + .await; + ws.next().await.unwrap().unwrap(); + for event in events { + ws.send(Message::Text(event.to_string().into())) + .await + .unwrap(); + } + }); + (base_url, server) + } else { + let (base_url, release, _, server) = paused_chunked_sse_server( + events[..3] + .iter() + .map(|event| format!("data: {event}\n\n")) + .collect(), + events[3..] + .iter() + .map(|event| format!("data: {event}\n\n")) + .collect(), + ) + .await; + release.send(()).unwrap(); + (base_url, server) + }; + let operation = if websocket { + generate_operation() + } else { + http_generate_operation() + }; + let mut stream = provider_with_base_url(&store, base_url) + .execute( + planned_request("openai", operation), + timed_context(Instant::now() - Duration::from_secs(20), 2), + ) + .await + .unwrap(); + let timings = finish_timings(&mut stream, ProviderResponseTimings::default()).await; + 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)); + server.await.unwrap(); + } +} + +#[tokio::test] +async fn timing_frames_outside_the_active_response_do_not_enter_request_metrics() { + let store = Arc::new(MemoryAccountStore::default()); + create_account(&store, "acct_provider_contract").await; + 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}}}); + let (base_url, release, _, server) = paused_chunked_sse_server( + format!("data: {timing}\n\ndata: {created}\n\n"), + format!("data: {completed}\n\ndata: {timing}\n\n"), + ) + .await; + release.send(()).unwrap(); + let mut stream = provider_with_base_url(&store, base_url) + .execute( + planned_request("openai", http_generate_operation()), + timed_context(Instant::now(), 1), + ) + .await + .unwrap(); + 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(); +} + +#[tokio::test] +async fn content_without_output_item_start_keeps_ttft_unknown_on_every_attempt() { for attempt in [1, 2] { let store = Arc::new(MemoryAccountStore::default()); create_account(&store, "acct_provider_contract").await; @@ -80,12 +213,8 @@ async fn first_sse_chunk_records_content_on_the_request_clock_for_every_attempt( .unwrap(); let first = first_upstream_timings(&mut stream).await; assert!(first.first_event_ms.is_some_and(|value| value >= 3_000)); - assert!(first.first_token_ms.is_some_and(|value| value >= 3_000)); - assert!( - first - .first_text_ms - .is_some_and(|text| text >= first.first_token_ms.unwrap()) - ); + assert_eq!(first.first_token_ms, None); + assert!(first.first_text_ms.is_some_and(|value| value >= 3_000)); release.send(()).unwrap(); let final_timings = finish_timings(&mut stream, first).await; assert_eq!(final_timings.first_token_ms, first.first_token_ms); @@ -131,7 +260,21 @@ async fn structural_frames_start_ttft_before_content_on_http_and_websocket() { let (release, released) = oneshot::channel(); let server = tokio::spawn(async move { let (socket, _) = listener.accept().await.unwrap(); - let mut ws = accept_codex_test_websocket(socket).await; + 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" + ); + response.headers_mut().insert( + "sec-websocket-extensions", + "permessage-deflate".parse().unwrap(), + ); + }, + ) + .await; ws.next().await.unwrap().unwrap(); for event in [created, added] { ws.send(Message::Text(event.to_string().into())) diff --git a/backend/crates/providers/openai/tests/transport/canonical.rs b/backend/crates/providers/openai/tests/transport/canonical.rs index 8594375b1..d05f14019 100644 --- a/backend/crates/providers/openai/tests/transport/canonical.rs +++ b/backend/crates/providers/openai/tests/transport/canonical.rs @@ -60,6 +60,95 @@ fn response_model_observation_uses_explicit_body_and_never_request_fallback() { const METADATA_PREFIX_FIXTURE: &str = include_str!("fixtures/metadata_only_prefix.sse"); +#[test] +fn official_response_duration_uses_only_the_completed_response_on_both_transports() { + for websocket in [false, true] { + for (created_at, completed_at, expected) in [ + (json!(1_791_441_115), json!(1_791_441_122), Some(7_000)), + (json!(100.25), json!(101.5), Some(1_250)), + (json!(100), json!(100), None), + (json!(101), json!(100), None), + (json!(-1), json!(100), None), + (json!(null), json!(100), None), + (json!(100), json!(null), None), + (json!("100"), json!(101), None), + (json!(0), json!(1e30), None), + ] { + let mut decoder = CodexCanonicalDecoder::new("gpt-5.4").with_raw_sse_passthrough(); + // 前导响应的时间不能用于补齐完成响应缺失的时间 + decoder.push(b"data: {\"type\":\"response.created\",\"response\":{\"id\":\"resp_time\",\"created_at\":1}}\n\n").expect("created response"); + assert_eq!(decoder.upstream_response_ms(), None); + let completed = json!({ + "type": "response.completed", + "response": { + "id": "resp_time", "status": "completed", "output": [], + "created_at": created_at, "completed_at": completed_at, + "usage": { "input_tokens": 1, "output_tokens": 112, "total_tokens": 113 }, + }, + }); + let raw = completed.to_string(); + let frame = if websocket { + websocket_event_to_sse_frame(&raw).expect("WS completion") + } else { + format!("data: {raw}\n\n") + }; + let split = frame.len() / 2; + decoder + .push(&frame.as_bytes()[..split]) + .expect("first chunk"); + let events = decoder + .push(&frame.as_bytes()[split..]) + .expect("completion"); + assert_eq!(decoder.upstream_response_ms(), expected); + assert!(events.iter().any(|event| { + event + .wire_event() + .is_some_and(|wire| wire.data() == &completed) + })); + assert!(canonical_facts(&events).iter().any(|event| matches!(event, GatewayEvent::Usage(usage) if usage.output_tokens == Some(112)))); + } + } +} + +#[test] +fn official_response_duration_does_not_cross_response_identity_or_incomplete_boundary() { + for (event_type, response_id, created) in [ + ("response.completed", "resp_other", true), + ("response.completed", "resp_time", false), + ("response.incomplete", "resp_time", true), + ] { + let mut decoder = CodexCanonicalDecoder::new("gpt-5.4"); + if created { + decoder.push(b"data: {\"type\":\"response.created\",\"response\":{\"id\":\"resp_time\"}}\n\n").expect("created response"); + } + let completed = json!({ + "type": event_type, + "response": { + "id": response_id, "created_at": 100, "completed_at": 107, + "usage": { "input_tokens": 1, "output_tokens": 112, "total_tokens": 113 }, + }, + }); + let events = decoder + .push(format!("data: {completed}\n\n").as_bytes()) + .expect("terminal response"); + assert_eq!(decoder.upstream_response_ms(), None); + assert!(events.iter().any(|event| { + event + .wire_event() + .is_some_and(|wire| wire.data() == &completed) + })); + } +} + +#[test] +fn official_timing_frames_do_not_start_first_output_wait() { + let mut decoder = CodexCanonicalDecoder::new("gpt-5.4"); + let events = decoder.push(b"data: {\"type\":\"responsesapi.websocket_timing\",\"timing_metrics\":{\"total_turn_time_s\":20}}\n\n").expect("timing frame"); + assert!(!events.is_empty()); + assert!(!decoder.take_timing_signals().output_start); + assert_eq!(decoder.upstream_response_ms(), None); +} + #[test] fn decoder_should_not_forward_codex_rate_limit_metadata_fixture_as_openai_wire() { let events = CodexCanonicalDecoder::new("fallback") @@ -551,7 +640,7 @@ fn decoder_should_restore_done_only_reasoning_and_text_as_canonical_facts() { } #[test] -fn decoder_timing_signals_should_count_tool_arguments_as_first_token() { +fn decoder_timing_signals_distinguish_tool_item_start_from_argument_output() { let body = concat!( "event: response.created\n", "data: {\"type\":\"response.created\",\"response\":{\"id\":\"resp_tool_timing\",\"model\":\"gpt-test\"}}\n\n", diff --git a/backend/crates/providers/openai/tests/transport/protocol/responses.rs b/backend/crates/providers/openai/tests/transport/protocol/responses.rs index d88e046b1..22c0a82ce 100644 --- a/backend/crates/providers/openai/tests/transport/protocol/responses.rs +++ b/backend/crates/providers/openai/tests/transport/protocol/responses.rs @@ -101,29 +101,32 @@ fn response_signals_should_count_structural_start_without_semantic_output() { } #[test] -fn first_token_should_follow_non_preamble_events_without_reclassifying_content() { +fn first_token_should_use_only_the_official_output_item_added_boundary() { for event in [ "response.created", "response.in_progress", "keepalive", "codex.rate_limits", + "codex.response.metadata", + "response.metadata", + "responsesapi.websocket_timing", + "response.content_part.added", + "response.reasoning_summary_part.added", + "response.output_text.delta", + "response.output_item.done", + "response.completed", "response.failed", "error", ] { let signals = response_event_signals(Some(event), &json!({"type": event})); - assert!(!signals.output_start, "not a first token: {event}"); - } - for event in [ - "response.output_item.added", - "response.content_part.added", - "response.reasoning_summary_part.added", - "response.output_text.delta", - "response.completed", - ] { - let signals = response_event_signals(Some(event), &json!({"type": event})); - assert!(signals.output_start, "first non-preamble event: {event}"); - assert!(!signals.semantic_output, "no content: {event}"); + assert!(!signals.output_start, "not an output item start: {event}"); } + let signals = response_event_signals( + Some("response.output_item.added"), + &json!({"type": "response.output_item.added", "item": {"type": "message", "content": []}}), + ); + assert!(signals.output_start); + assert!(!signals.semantic_output); } #[test] diff --git a/backend/crates/providers/openai/tests/transport/websocket/fingerprint.rs b/backend/crates/providers/openai/tests/transport/websocket/fingerprint.rs index 160af1252..95308c596 100644 --- a/backend/crates/providers/openai/tests/transport/websocket/fingerprint.rs +++ b/backend/crates/providers/openai/tests/transport/websocket/fingerprint.rs @@ -110,7 +110,8 @@ async fn official_websocket_wire_fingerprint_should_remain_aligned() { opening.lines().next(), Some("GET /backend-api/codex/responses HTTP/1.1") ); - // 官方 Codex Core 0.154.0（Desktop 26.908.40834）的原始 opening 抓包顺序 + // 固定身份字段沿用官方画像，专项计时头按官方客户端在 openai-beta 后插入 + // HeaderMap 序列化会随新增头调整迭代顺序，锁定启用计时后的完整 opening assert_eq!( read_header_names(&opening), vec![ @@ -123,7 +124,7 @@ async fn official_websocket_wire_fingerprint_should_remain_aligned() { "authorization", "user-agent", "originator", - "openai-beta", + "x-responsesapi-include-timing-metrics", "version", "x-codex-beta-features", "x-client-request-id", @@ -132,9 +133,14 @@ 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"), + ); assert_eq!( read_header_value(&opening, "sec-websocket-extensions"), Some("permessage-deflate; client_max_window_bits") diff --git a/backend/crates/providers/xai/src/provider/stream.rs b/backend/crates/providers/xai/src/provider/stream.rs index c473c175b..125b48cc9 100644 --- a/backend/crates/providers/xai/src/provider/stream.rs +++ b/backend/crates/providers/xai/src/provider/stream.rs @@ -32,6 +32,42 @@ pub(super) struct GrokCompactionStreamAttempt { pub(super) reasoning_replay_key: Option, } +// xAI 的首字要求真实语义输出，结构事件只记首事件时间 +fn observe_output_timings( + observation: &mut ProviderResponseObservation, + events: &[ProviderEvent], + started_at: Instant, +) -> bool { + if events.is_empty() { + return false; + } + let previous = observation.timings(); + let mut timings = previous; + let elapsed_ms = u64::try_from(started_at.elapsed().as_millis()).unwrap_or(u64::MAX); + timings.first_event_ms.get_or_insert(elapsed_ms); + for event in events.iter().flat_map(ProviderEvent::canonical_facts) { + match event { + GatewayEvent::ReasoningDelta(delta) if !delta.text.is_empty() => { + timings.first_reasoning_ms.get_or_insert(elapsed_ms); + timings.first_token_ms.get_or_insert(elapsed_ms); + } + GatewayEvent::TextDelta(delta) if !delta.text.is_empty() => { + timings.first_text_ms.get_or_insert(elapsed_ms); + timings.first_token_ms.get_or_insert(elapsed_ms); + } + GatewayEvent::ToolCallDelta(delta) if !delta.arguments_delta.is_empty() => { + timings.first_token_ms.get_or_insert(elapsed_ms); + } + _ => {} + } + } + if timings == previous { + return false; + } + *observation = observation.clone().with_timings(timings); + true +} + fn append_middleware_grok_headers( target: &mut Vec, headers: &[MiddlewareHeader], @@ -243,6 +279,9 @@ pub(super) fn cold_compaction_http_sse_stream( return; } }; + if observe_output_timings(&mut observation, &events, context.timing_started_at()) { + yield ProviderEvent::observation(observation.clone()); + } for event in events { summary.observe(&event).map_err(map_compaction_decode_error)?; facts.observe(&event); @@ -268,6 +307,9 @@ pub(super) fn cold_compaction_http_sse_stream( return; } }; + if observe_output_timings(&mut observation, &events, context.timing_started_at()) { + yield ProviderEvent::observation(observation.clone()); + } for event in events { summary.observe(&event).map_err(map_compaction_decode_error)?; facts.observe(&event); @@ -555,6 +597,9 @@ pub(super) fn cold_http_sse_stream( return; } }; + if observe_output_timings(&mut observation, &events, context.timing_started_at()) { + yield ProviderEvent::observation(observation.clone()); + } if let Some(model) = decoder.response_model() && observation.upstream_response_model() != Some(model) { @@ -609,6 +654,9 @@ pub(super) fn cold_http_sse_stream( return; } }; + if observe_output_timings(&mut observation, &final_events, context.timing_started_at()) { + yield ProviderEvent::observation(observation.clone()); + } let completed = final_events .iter() .flat_map(ProviderEvent::canonical_facts) diff --git a/backend/crates/providers/xai/tests/provider/contract/mod.rs b/backend/crates/providers/xai/tests/provider/contract/mod.rs index effeec37c..f72bf0e64 100644 --- a/backend/crates/providers/xai/tests/provider/contract/mod.rs +++ b/backend/crates/providers/xai/tests/provider/contract/mod.rs @@ -1,6 +1,7 @@ //! 验证 xAI 原生执行的协议转换、账号选择与交付状态隔离 mod replay_tool_names; +mod timing; use std::collections::{BTreeMap, BTreeSet, VecDeque}; use std::num::NonZeroU32; diff --git a/backend/crates/providers/xai/tests/provider/contract/timing.rs b/backend/crates/providers/xai/tests/provider/contract/timing.rs new file mode 100644 index 000000000..522e73524 --- /dev/null +++ b/backend/crates/providers/xai/tests/provider/contract/timing.rs @@ -0,0 +1,102 @@ +//! 验证 xAI Provider 独立采集输出时间，结构帧与空增量不启动首字 + +use std::time::Instant; + +use super::*; + +#[tokio::test] +async fn provider_observes_semantic_output_on_the_request_clock() { + for (event_type, item_type, delta, has_text, has_reasoning) in [ + ( + "response.output_text.delta", + "message", + "hello", + true, + false, + ), + ("response.output_text.delta", "message", "", false, false), + ( + "response.reasoning_summary_text.delta", + "reasoning", + "plan", + false, + true, + ), + ( + "response.reasoning_summary_text.delta", + "reasoning", + "", + false, + false, + ), + ( + "response.function_call_arguments.delta", + "function_call", + "{}", + false, + false, + ), + ( + "response.function_call_arguments.delta", + "function_call", + "", + false, + false, + ), + ] { + let body = [ + json!({"type":"response.created","response":{"id":"resp_timing","model":MODEL}}), + json!({"type":"response.output_item.added","output_index":0,"item":{"id":"item_timing","type":item_type,"call_id":"call_timing","name":"lookup","content":[]}}), + json!({"type":event_type,"item_id":"item_timing","call_id":"call_timing","output_index":0,"content_index":0,"summary_index":0,"delta":delta}), + json!({"type":"response.completed","response":{"id":"resp_timing","status":"completed","output":[],"usage":{"input_tokens":1,"output_tokens":1,"total_tokens":2}}}), + ] + .into_iter() + .map(|event| format!("data: {event}\n\n")) + .collect::() + .into_bytes(); + let transport = StubInferenceTransport::sequence([InferenceMode::SuccessBody(body)]); + let provider = provider(StubSelector::success(), transport).await; + let context = AttemptContext::new( + gateway_core::engine::RequestAttemptContext::new( + ModelRequestId::new("req_xai_timing").unwrap(), + ClientApiKeyId::new("key_xai_timing").unwrap(), + ) + .with_timing_started_at(Instant::now() - Duration::from_secs(3)), + NonZeroU32::new(2).unwrap(), + SystemTime::now() + Duration::from_secs(30), + selection_policy(), + AccountAttemptContext::new(BTreeSet::new(), None, None), + None, + CancellationToken::new(), + ); + let mut stream = provider + .execute(provider_request("xai"), context) + .await + .unwrap(); + let mut timings = gateway_core::event::ProviderResponseTimings::default(); + let mut completed = false; + while let Some(event) = stream.next().await { + let event = event.unwrap(); + if let Some(observation) = event.response_observation() { + timings = observation.timings(); + } + completed |= event + .canonical_facts() + .iter() + .any(|fact| matches!(fact, GatewayEvent::Completed(_))); + } + assert!(completed); + assert!(timings.first_event_ms.is_some_and(|value| value >= 3_000)); + assert_eq!( + timings.first_token_ms.is_some(), + !delta.is_empty(), + "{event_type}" + ); + assert_eq!(timings.first_text_ms.is_some(), has_text); + assert_eq!(timings.first_reasoning_ms.is_some(), has_reasoning); + if let Some(first_token_ms) = timings.first_token_ms { + assert!(first_token_ms >= 3_000); + } + assert_eq!(timings.upstream_response_ms, None); + } +} diff --git a/backend/migrations/.frozen-sha256 b/backend/migrations/.frozen-sha256 index 639071c0a..925142d9f 100644 --- a/backend/migrations/.frozen-sha256 +++ b/backend/migrations/.frozen-sha256 @@ -22,3 +22,4 @@ e8c1339166ac02fb2d4a077424ee5f64f6dc20eb4d3f8ec4fcb09c0f2a0e61f6 0020_plugin_tr 77a140ddfb9dfae9b7d7349e5bfc9c8a7e7927bae6e77c1a627b34fcbb714bdb 0022_refresh_margin_and_group_fast_mode.sql d431ebf24669451da06bb6671136bf58cddcc713b43a1a705eb33f9cb4f9b577 0023_error_details_and_account_affinity.sql fa99dde0fe0b3d7da6693d76b2735629dde0dc255ea8c53f0354857a4e80669b 0024_preferred_account_affinity.sql +299d347add09b1e6f086732c0db8269efb640db4ecccb948e17c067b572afc43 0025_request_observation.sql diff --git a/backend/migrations/0025_request_observation.sql b/backend/migrations/0025_request_observation.sql new file mode 100644 index 000000000..4abd566e5 --- /dev/null +++ b/backend/migrations/0025_request_observation.sql @@ -0,0 +1,443 @@ +-- 请求观测以类型化 JSON 保存，业务状态保留列，查询通过只读投影取值 +create function model_request_observation_valid(document jsonb) returns boolean +language plpgsql immutable parallel safe as $$ +declare + spec record; + item jsonb; + number numeric; +begin + if document is null or jsonb_typeof(document) <> 'object' + or octet_length(document::text) > 1048576 then + return false; + end if; + for spec in select * from (values + ('{}'::text[], array['account','continuation','error','recovery','request','response','routing','scheduling','timings','transport']::text[]), + ('{request}'::text[], array['clientIp','compact','configRevision','endpoint','protocol','reasoningEffort','reasoningPreset','subagentKind','userAgent']::text[]), + ('{account}'::text[], array['authenticationKind','email','name']::text[]), + ('{routing}'::text[], array['groupNamesSnapshot','groupRefs','scope']::text[]), + ('{error}'::text[], array['message','providerErrorCode','retryAfterMs']::text[]), + ('{timings}'::text[], array['local','upstream']::text[]), + ('{timings,local}'::text[], array['connectMs','firstEventMs','firstReasoningMs','firstTextMs','firstTokenMs','headersMs','latencyMs','transportDecisionWaitMs']::text[]), + ('{timings,upstream}'::text[], array['processingMs','responseMs','apiOverheadMs','engineMs','engineIapiTtftMs','engineServiceTtftMs','engineIapiTbtMs','engineServiceTbtMs']::text[]), + ('{scheduling}'::text[], array['accountSelectionWaitMs','admissionDecisionMs','capacityTotalSlots','capacityUsedSlots']::text[]), + ('{transport}'::text[], array['connection','httpVersion','websocketPool']::text[]), + ('{transport,connection}'::text[], array['ageMs','exitReason','id','idleMs']::text[]), + ('{response}'::text[], array['responseModel']::text[]), + ('{continuation}'::text[], array['previousResponseIdHash','unavailableReason']::text[]), + ('{recovery}'::text[], array['retryDelayMs','totalLatencyMs']::text[])) as groups(path, allowed_keys) loop + item := document #> spec.path; + if item is not null and (jsonb_typeof(item) <> 'object' or item - spec.allowed_keys <> '{}'::jsonb) then + return false; + end if; + end loop; + for spec in select * from (values + ('{request,configRevision}'::text[], 'number'), + ('{request,protocol}'::text[], 'string'), + ('{request,endpoint}'::text[], 'string'), + ('{account,name}'::text[], 'string'), + ('{account,email}'::text[], 'string'), + ('{account,authenticationKind}'::text[], 'string'), + ('{routing,scope}'::text[], 'string'), + ('{routing,groupRefs}'::text[], 'array'), + ('{routing,groupNamesSnapshot}'::text[], 'array'), + ('{error,providerErrorCode}'::text[], 'string'), + ('{error,message}'::text[], 'string'), + ('{error,retryAfterMs}'::text[], 'number'), + ('{request,clientIp}'::text[], 'string'), + ('{request,userAgent}'::text[], 'string'), + ('{request,reasoningEffort}'::text[], 'string'), + ('{request,reasoningPreset}'::text[], 'string'), + ('{request,subagentKind}'::text[], 'string'), + ('{request,compact}'::text[], 'boolean'), + ('{timings,local,transportDecisionWaitMs}'::text[], 'number'), + ('{timings,local,connectMs}'::text[], 'number'), + ('{timings,local,headersMs}'::text[], 'number'), + ('{timings,local,firstEventMs}'::text[], 'number'), + ('{timings,local,firstReasoningMs}'::text[], 'number'), + ('{timings,local,firstTextMs}'::text[], 'number'), + ('{timings,local,firstTokenMs}'::text[], 'number'), + ('{timings,local,latencyMs}'::text[], 'number'), + ('{timings,upstream,processingMs}'::text[], 'number'), + ('{timings,upstream,apiOverheadMs}'::text[], 'milliseconds'), + ('{timings,upstream,engineMs}'::text[], 'milliseconds'), + ('{timings,upstream,engineIapiTtftMs}'::text[], 'milliseconds'), + ('{timings,upstream,engineServiceTtftMs}'::text[], 'milliseconds'), + ('{timings,upstream,engineIapiTbtMs}'::text[], 'milliseconds'), + ('{timings,upstream,engineServiceTbtMs}'::text[], 'milliseconds'), + ('{scheduling,admissionDecisionMs}'::text[], 'number'), + ('{scheduling,accountSelectionWaitMs}'::text[], 'number'), + ('{scheduling,capacityUsedSlots}'::text[], 'number'), + ('{scheduling,capacityTotalSlots}'::text[], 'number'), + ('{transport,httpVersion}'::text[], 'string'), + ('{transport,websocketPool}'::text[], 'string'), + ('{transport,connection,id}'::text[], 'string'), + ('{transport,connection,exitReason}'::text[], 'string'), + ('{transport,connection,ageMs}'::text[], 'number'), + ('{transport,connection,idleMs}'::text[], 'number'), + ('{response,responseModel}'::text[], 'string'), + ('{continuation,previousResponseIdHash}'::text[], 'string'), + ('{continuation,unavailableReason}'::text[], 'string'), + ('{recovery,retryDelayMs}'::text[], 'number'), + ('{recovery,totalLatencyMs}'::text[], 'number'), + ('{timings,upstream,responseMs}'::text[], 'number')) as fields(path, kind) loop + item := document #> spec.path; + if item is null or item = 'null'::jsonb then continue; end if; + if spec.kind = 'milliseconds' then + if jsonb_typeof(item) <> 'number' then return false; end if; + number := (item #>> '{}')::numeric; + if number < 0 or number > 9223372036854775807 then return false; end if; + continue; + end if; + if jsonb_typeof(item) <> spec.kind then return false; end if; + if spec.kind = 'number' then + number := (item #>> '{}')::numeric; + if item #>> '{}' !~ '^[0-9]+$' or number > 9223372036854775807 then return false; end if; + elsif spec.kind = 'array' then + if exists (select 1 from jsonb_array_elements(item) member where jsonb_typeof(member) <> 'string') then return false; end if; + end if; + end loop; + if (document #> '{request,configRevision}' is not null + and document #> '{request,configRevision}' <> 'null'::jsonb + and document #> '{request,compact}' in ('true'::jsonb, 'false'::jsonb) + and coalesce(length(document #>> '{request,protocol}'), 0) > 0 + and coalesce(length(document #>> '{request,endpoint}'), 0) > 0 + and document #>> '{routing,scope}' in ('legacy_provider', 'all', 'groups') + and jsonb_typeof(document #> '{routing,groupRefs}') = 'array' + and jsonb_typeof(document #> '{routing,groupNamesSnapshot}') = 'array') is not true then + return false; + end if; + if document #>> '{request,clientIp}' is not null then + perform (document #>> '{request,clientIp}')::inet; + end if; + return true; +exception when invalid_text_representation or numeric_value_out_of_range then + return false; +end; +$$; + +alter table model_requests add column request_observation_json jsonb; + +update model_requests set request_observation_json = jsonb_strip_nulls(jsonb_build_object( + 'request', jsonb_build_object( + 'configRevision', config_revision, + 'protocol', protocol, + 'endpoint', endpoint, + 'clientIp', client_ip::text, + 'userAgent', user_agent, + 'reasoningEffort', reasoning_effort, + 'reasoningPreset', reasoning_preset, + 'subagentKind', subagent_kind, + 'compact', compact), + 'account', jsonb_build_object( + 'name', provider_account_name_snapshot, + 'email', provider_account_email_snapshot, + 'authenticationKind', provider_account_authentication_kind_snapshot), + 'routing', jsonb_build_object( + 'scope', routing_scope, + 'groupRefs', routing_group_refs, + 'groupNamesSnapshot', routing_group_names_snapshot), + 'error', jsonb_build_object( + 'providerErrorCode', provider_error_code, + 'message', error_message, + 'retryAfterMs', retry_after_ms), + 'timings', jsonb_build_object( + 'local', jsonb_build_object( + 'transportDecisionWaitMs', transport_decision_wait_ms, + 'connectMs', connect_ms, + 'headersMs', headers_ms, + 'firstEventMs', first_event_ms, + 'firstReasoningMs', first_reasoning_ms, + 'firstTextMs', first_text_ms, + 'firstTokenMs', first_token_ms, + 'latencyMs', latency_ms), + 'upstream', jsonb_build_object( + 'processingMs', provider_processing_ms)), + 'scheduling', jsonb_build_object( + 'admissionDecisionMs', admission_decision_ms, + 'accountSelectionWaitMs', account_selection_wait_ms, + 'capacityUsedSlots', capacity_used_slots, + 'capacityTotalSlots', capacity_total_slots), + 'transport', jsonb_build_object( + 'httpVersion', http_version, + 'websocketPool', websocket_pool, + 'connection', jsonb_build_object( + 'id', upstream_connection_id, + 'exitReason', upstream_connection_exit_reason, + 'ageMs', upstream_connection_age_ms, + 'idleMs', upstream_connection_idle_ms)), + 'response', jsonb_build_object( + 'responseModel', upstream_response_model), + 'continuation', jsonb_build_object( + 'previousResponseIdHash', continuation_previous_response_id_hash, + 'unavailableReason', continuation_unavailable_reason), + 'recovery', jsonb_build_object( + 'retryDelayMs', recovery_retry_delay_ms, + 'totalLatencyMs', recovery_total_latency_ms))); + +alter table model_requests + alter column request_observation_json set not null, + drop constraint model_requests_revision_attempt_ck, + drop constraint model_requests_status_ck, + drop constraint model_requests_websocket_pool_ck, + drop constraint model_requests_routing_scope_ck, + drop constraint model_requests_routing_group_names_ck, + drop constraint model_requests_latency_ck, + drop constraint model_requests_runtime_pressure_ck, + drop constraint model_requests_continuation_hashes_ck, + drop constraint model_requests_continuation_reason_ck, + drop constraint model_requests_upstream_connection_ck, + drop constraint model_requests_recovery_ck, + drop constraint model_requests_fact_completeness_ck, + drop column config_revision, + drop column protocol, + drop column endpoint, + drop column provider_account_name_snapshot, + drop column provider_account_email_snapshot, + drop column provider_account_authentication_kind_snapshot, + drop column routing_scope, + drop column routing_group_refs, + drop column routing_group_names_snapshot, + drop column provider_error_code, + drop column error_message, + drop column retry_after_ms, + drop column client_ip, + drop column user_agent, + drop column reasoning_effort, + drop column reasoning_preset, + drop column subagent_kind, + drop column compact, + drop column transport_decision_wait_ms, + drop column connect_ms, + drop column headers_ms, + drop column first_event_ms, + drop column first_reasoning_ms, + drop column first_text_ms, + drop column first_token_ms, + drop column latency_ms, + drop column provider_processing_ms, + drop column admission_decision_ms, + drop column account_selection_wait_ms, + drop column capacity_used_slots, + drop column capacity_total_slots, + drop column http_version, + drop column websocket_pool, + drop column upstream_connection_id, + drop column upstream_connection_exit_reason, + drop column upstream_connection_age_ms, + drop column upstream_connection_idle_ms, + drop column upstream_response_model, + drop column continuation_previous_response_id_hash, + drop column continuation_unavailable_reason, + drop column recovery_retry_delay_ms, + drop column recovery_total_latency_ms; + +alter table model_requests + add constraint model_requests_observation_shape_ck check (model_request_observation_valid(request_observation_json) is true), + add constraint model_requests_upstream_duration_ck check ((request_observation_json #>> '{timings,upstream,responseMs}')::bigint > 0), + add constraint model_requests_revision_attempt_ck check ( + (request_observation_json #>> '{request,configRevision}')::bigint > 0 and attempt_count >= 0 + ), + add constraint model_requests_status_ck check ( + (client_status_code is null or client_status_code between 100 and 599) + and (upstream_status_code is null or upstream_status_code between 100 and 599) + and ((request_observation_json #>> '{error,retryAfterMs}')::bigint is null or (request_observation_json #>> '{error,retryAfterMs}')::bigint >= 0) + ), + add constraint model_requests_websocket_pool_ck check ( + (request_observation_json #>> '{transport,websocketPool}') is null or (request_observation_json #>> '{transport,websocketPool}') in ('new', 'reuse') + ), + add constraint model_requests_routing_scope_ck check ( + (request_observation_json #>> '{routing,scope}') in ('legacy_provider', 'all', 'groups') + ), + add constraint model_requests_routing_group_names_ck check ( + jsonb_typeof((request_observation_json #> '{routing,groupNamesSnapshot}')) = 'array' + and ( + ( + (request_observation_json #>> '{routing,scope}') in ('legacy_provider', 'all') + and jsonb_array_length(request_observation_json #> '{routing,groupRefs}') = 0 + and jsonb_array_length((request_observation_json #> '{routing,groupNamesSnapshot}')) = 0 + ) + or ( + (request_observation_json #>> '{routing,scope}') = 'groups' + and jsonb_array_length(request_observation_json #> '{routing,groupRefs}') > 0 + and not jsonb_path_exists(request_observation_json, '$.routing.groupRefs[*] ? (@ == null)') + and jsonb_array_length((request_observation_json #> '{routing,groupNamesSnapshot}')) + = jsonb_array_length(request_observation_json #> '{routing,groupRefs}') + ) + ) + ), + add constraint model_requests_latency_ck check ( + ((request_observation_json #>> '{timings,local,transportDecisionWaitMs}')::bigint is null or (request_observation_json #>> '{timings,local,transportDecisionWaitMs}')::bigint >= 0) + and ((request_observation_json #>> '{timings,local,connectMs}')::bigint is null or (request_observation_json #>> '{timings,local,connectMs}')::bigint >= 0) + and ((request_observation_json #>> '{timings,local,headersMs}')::bigint is null or (request_observation_json #>> '{timings,local,headersMs}')::bigint >= 0) + and ((request_observation_json #>> '{timings,local,firstEventMs}')::bigint is null or (request_observation_json #>> '{timings,local,firstEventMs}')::bigint >= 0) + and ((request_observation_json #>> '{timings,local,firstReasoningMs}')::bigint is null or (request_observation_json #>> '{timings,local,firstReasoningMs}')::bigint >= 0) + and ((request_observation_json #>> '{timings,local,firstTextMs}')::bigint is null or (request_observation_json #>> '{timings,local,firstTextMs}')::bigint >= 0) + and ((request_observation_json #>> '{timings,local,firstTokenMs}')::bigint is null or (request_observation_json #>> '{timings,local,firstTokenMs}')::bigint >= 0) + and ((request_observation_json #>> '{timings,upstream,processingMs}')::bigint is null or (request_observation_json #>> '{timings,upstream,processingMs}')::bigint >= 0) + and ((request_observation_json #>> '{timings,local,latencyMs}')::bigint is null or (request_observation_json #>> '{timings,local,latencyMs}')::bigint >= 0) + and ( + (request_observation_json #>> '{timings,local,latencyMs}')::bigint is null + or ( + ((request_observation_json #>> '{timings,local,transportDecisionWaitMs}')::bigint is null or (request_observation_json #>> '{timings,local,transportDecisionWaitMs}')::bigint <= (request_observation_json #>> '{timings,local,latencyMs}')::bigint) + and ((request_observation_json #>> '{timings,local,connectMs}')::bigint is null or (request_observation_json #>> '{timings,local,connectMs}')::bigint <= (request_observation_json #>> '{timings,local,latencyMs}')::bigint) + and ((request_observation_json #>> '{timings,local,headersMs}')::bigint is null or (request_observation_json #>> '{timings,local,headersMs}')::bigint <= (request_observation_json #>> '{timings,local,latencyMs}')::bigint) + and ((request_observation_json #>> '{timings,local,firstEventMs}')::bigint is null or (request_observation_json #>> '{timings,local,firstEventMs}')::bigint <= (request_observation_json #>> '{timings,local,latencyMs}')::bigint) + and ((request_observation_json #>> '{timings,local,firstReasoningMs}')::bigint is null or (request_observation_json #>> '{timings,local,firstReasoningMs}')::bigint <= (request_observation_json #>> '{timings,local,latencyMs}')::bigint) + and ((request_observation_json #>> '{timings,local,firstTextMs}')::bigint is null or (request_observation_json #>> '{timings,local,firstTextMs}')::bigint <= (request_observation_json #>> '{timings,local,latencyMs}')::bigint) + and ((request_observation_json #>> '{timings,local,firstTokenMs}')::bigint is null or (request_observation_json #>> '{timings,local,firstTokenMs}')::bigint <= (request_observation_json #>> '{timings,local,latencyMs}')::bigint) + ) + ) + ), + add constraint model_requests_runtime_pressure_ck check ( + ((request_observation_json #>> '{scheduling,admissionDecisionMs}')::bigint is null or (request_observation_json #>> '{scheduling,admissionDecisionMs}')::bigint >= 0) + and ((request_observation_json #>> '{scheduling,accountSelectionWaitMs}')::bigint is null or (request_observation_json #>> '{scheduling,accountSelectionWaitMs}')::bigint >= 0) + and ( + ((request_observation_json #>> '{scheduling,capacityUsedSlots}')::bigint is null and (request_observation_json #>> '{scheduling,capacityTotalSlots}')::bigint is null) + or ( + (request_observation_json #>> '{scheduling,capacityUsedSlots}')::bigint >= 0 + and (request_observation_json #>> '{scheduling,capacityTotalSlots}')::bigint > 0 + and (request_observation_json #>> '{scheduling,capacityUsedSlots}')::bigint <= (request_observation_json #>> '{scheduling,capacityTotalSlots}')::bigint + ) + ) + ), + add constraint model_requests_continuation_hashes_ck check ( + (continuation_affinity_hash is null + or continuation_affinity_hash ~ '^[0-9a-f]{64}$') + and ((request_observation_json #>> '{continuation,previousResponseIdHash}') is null + or (request_observation_json #>> '{continuation,previousResponseIdHash}') ~ '^[0-9a-f]{64}$') + and (continuation_requested + or (request_observation_json #>> '{continuation,previousResponseIdHash}') is null) + ), + add constraint model_requests_continuation_reason_ck check ( + (request_observation_json #>> '{continuation,unavailableReason}') is null + or ( + octet_length((request_observation_json #>> '{continuation,unavailableReason}')) between 1 and 64 + and (request_observation_json #>> '{continuation,unavailableReason}') ~ '^[a-z][a-z0-9_]*$' + ) + ), + add constraint model_requests_upstream_connection_ck check ( + ( + (request_observation_json #>> '{transport,connection,id}') is null + and (request_observation_json #>> '{transport,connection,exitReason}') is null + and (request_observation_json #>> '{transport,connection,ageMs}')::bigint is null + and (request_observation_json #>> '{transport,connection,idleMs}')::bigint is null + ) + or ( + octet_length((request_observation_json #>> '{transport,connection,id}')) between 1 and 128 + and (request_observation_json #>> '{transport,connection,id}') !~ '[[:cntrl:]]' + and octet_length((request_observation_json #>> '{transport,connection,exitReason}')) between 1 and 64 + and (request_observation_json #>> '{transport,connection,exitReason}') ~ '^[a-z][a-z0-9_]*$' + and (request_observation_json #>> '{transport,connection,ageMs}')::bigint >= 0 + and (request_observation_json #>> '{transport,connection,idleMs}')::bigint between 0 and (request_observation_json #>> '{transport,connection,ageMs}')::bigint + ) + ), + add constraint model_requests_recovery_ck check ( + recovery_attempt_count >= 0 + and ( + ( + recovered_at is null + and recovery_request_id is null + and (request_observation_json #>> '{recovery,retryDelayMs}')::bigint is null + and (request_observation_json #>> '{recovery,totalLatencyMs}')::bigint is null + ) + or ( + recovered_at is not null + and recovered_at >= completed_at + and recovery_request_id is not null + and octet_length(recovery_request_id) between 1 and 128 + and recovery_attempt_count > 0 + and (request_observation_json #>> '{recovery,retryDelayMs}')::bigint >= 0 + and (request_observation_json #>> '{recovery,totalLatencyMs}')::bigint >= (request_observation_json #>> '{recovery,retryDelayMs}')::bigint + ) + ) + ), + add constraint model_requests_fact_completeness_ck check ( + (provider_account_id is null or provider_account_ref is not null) + and (cost_source = 'unavailable' or cost_currency is not null) + and num_nonnulls((request_observation_json #>> '{scheduling,capacityUsedSlots}')::bigint, (request_observation_json #>> '{scheduling,capacityTotalSlots}')::bigint) in (0, 2) + and num_nonnulls( + (request_observation_json #>> '{transport,connection,id}'), (request_observation_json #>> '{transport,connection,exitReason}'), + (request_observation_json #>> '{transport,connection,ageMs}')::bigint, (request_observation_json #>> '{transport,connection,idleMs}')::bigint + ) in (0, 4) + and ( + recovered_at is null + or ( + completed_at is not null + and (request_observation_json #>> '{recovery,retryDelayMs}')::bigint is not null + and (request_observation_json #>> '{recovery,totalLatencyMs}')::bigint is not null + ) + ) + ); + +-- 只读视图集中 JSON 路径与类型转换，不保存冗余事实 +-- 计时与调度投影逐行计算一次，避免聚合的多个分位数重复提取同一个 JSON 值 +-- 请求与账号筛选保留在主扫描上，分页后才计算所需观测 +create view model_request_observations as +select mr.*, + (mr.request_observation_json #>> '{request,configRevision}')::bigint as config_revision, + (mr.request_observation_json #>> '{request,protocol}') as protocol, + (mr.request_observation_json #>> '{request,endpoint}') as endpoint, + (mr.request_observation_json #>> '{account,name}') as provider_account_name_snapshot, + (mr.request_observation_json #>> '{account,email}') as provider_account_email_snapshot, + (mr.request_observation_json #>> '{account,authenticationKind}') as provider_account_authentication_kind_snapshot, + (mr.request_observation_json #>> '{routing,scope}') as routing_scope, + array(select jsonb_array_elements_text(mr.request_observation_json #> '{routing,groupRefs}')) as routing_group_refs, + (mr.request_observation_json #> '{routing,groupNamesSnapshot}') as routing_group_names_snapshot, + (mr.request_observation_json #>> '{error,providerErrorCode}') as provider_error_code, + (mr.request_observation_json #>> '{error,message}') as error_message, + (mr.request_observation_json #>> '{error,retryAfterMs}')::bigint as retry_after_ms, + (mr.request_observation_json #>> '{request,clientIp}')::inet as client_ip, + (mr.request_observation_json #>> '{request,userAgent}') as user_agent, + (mr.request_observation_json #>> '{request,reasoningEffort}') as reasoning_effort, + (mr.request_observation_json #>> '{request,reasoningPreset}') as reasoning_preset, + (mr.request_observation_json #>> '{request,subagentKind}') as subagent_kind, + (mr.request_observation_json #>> '{request,compact}')::boolean as compact, + measured.transport_decision_wait_ms as transport_decision_wait_ms, + measured.connect_ms as connect_ms, + measured.headers_ms as headers_ms, + measured.first_event_ms as first_event_ms, + measured.first_reasoning_ms as first_reasoning_ms, + measured.first_text_ms as first_text_ms, + measured.first_token_ms as first_token_ms, + measured.latency_ms as latency_ms, + measured.provider_processing_ms as provider_processing_ms, + measured.admission_decision_ms as admission_decision_ms, + measured.account_selection_wait_ms as account_selection_wait_ms, + measured.capacity_used_slots as capacity_used_slots, + measured.capacity_total_slots as capacity_total_slots, + (mr.request_observation_json #>> '{transport,httpVersion}') as http_version, + (mr.request_observation_json #>> '{transport,websocketPool}') as websocket_pool, + (mr.request_observation_json #>> '{transport,connection,id}') as upstream_connection_id, + (mr.request_observation_json #>> '{transport,connection,exitReason}') as upstream_connection_exit_reason, + (mr.request_observation_json #>> '{transport,connection,ageMs}')::bigint as upstream_connection_age_ms, + (mr.request_observation_json #>> '{transport,connection,idleMs}')::bigint as upstream_connection_idle_ms, + (mr.request_observation_json #>> '{response,responseModel}') as upstream_response_model, + (mr.request_observation_json #>> '{continuation,previousResponseIdHash}') as continuation_previous_response_id_hash, + (mr.request_observation_json #>> '{continuation,unavailableReason}') as continuation_unavailable_reason, + (mr.request_observation_json #>> '{recovery,retryDelayMs}')::bigint as recovery_retry_delay_ms, + (mr.request_observation_json #>> '{recovery,totalLatencyMs}')::bigint as recovery_total_latency_ms, + (mr.request_observation_json #>> '{timings,upstream,apiOverheadMs}')::double precision as upstream_api_overhead_ms, + (mr.request_observation_json #>> '{timings,upstream,engineMs}')::double precision as upstream_engine_ms, + (mr.request_observation_json #>> '{timings,upstream,engineIapiTtftMs}')::double precision as upstream_engine_iapi_ttft_ms, + (mr.request_observation_json #>> '{timings,upstream,engineServiceTtftMs}')::double precision as upstream_engine_service_ttft_ms, + (mr.request_observation_json #>> '{timings,upstream,engineIapiTbtMs}')::double precision as upstream_engine_iapi_tbt_ms, + (mr.request_observation_json #>> '{timings,upstream,engineServiceTbtMs}')::double precision as upstream_engine_service_tbt_ms, + measured.upstream_response_ms as upstream_response_ms +from model_requests mr +cross join lateral ( + select (mr.request_observation_json #>> '{timings,local,transportDecisionWaitMs}')::bigint as transport_decision_wait_ms, + (mr.request_observation_json #>> '{timings,local,connectMs}')::bigint as connect_ms, + (mr.request_observation_json #>> '{timings,local,headersMs}')::bigint as headers_ms, + (mr.request_observation_json #>> '{timings,local,firstEventMs}')::bigint as first_event_ms, + (mr.request_observation_json #>> '{timings,local,firstReasoningMs}')::bigint as first_reasoning_ms, + (mr.request_observation_json #>> '{timings,local,firstTextMs}')::bigint as first_text_ms, + (mr.request_observation_json #>> '{timings,local,firstTokenMs}')::bigint as first_token_ms, + (mr.request_observation_json #>> '{timings,local,latencyMs}')::bigint as latency_ms, + (mr.request_observation_json #>> '{timings,upstream,processingMs}')::bigint as provider_processing_ms, + (mr.request_observation_json #>> '{scheduling,admissionDecisionMs}')::bigint as admission_decision_ms, + (mr.request_observation_json #>> '{scheduling,accountSelectionWaitMs}')::bigint as account_selection_wait_ms, + (mr.request_observation_json #>> '{scheduling,capacityUsedSlots}')::bigint as capacity_used_slots, + (mr.request_observation_json #>> '{scheduling,capacityTotalSlots}')::bigint as capacity_total_slots, + (mr.request_observation_json #>> '{timings,upstream,responseMs}')::bigint as upstream_response_ms + offset 0 +) measured; diff --git a/docs/api.md b/docs/api.md index ad9de2b57..296c3a58d 100644 --- a/docs/api.md +++ b/docs/api.md @@ -594,7 +594,7 @@ overview 返回 `asOf`、`asOfDisplay`、`startTime`、`endTime`、`key`、`summ 日志只返回时间、公开请求模型、推理强度、接口、上下游传输方式、当前请求的 IP / User-Agent、 Token 明细、费用明细、用时/首字与状态。Token 和费用复用现有展示合同；延迟仅包含当前请求的首事件、 -首推理、首文本和总耗时，不含账号容量或调度诊断。 +首推理、首文本、总耗时与上游性能指标，口径见[记录范围与统计口径](#记录范围与统计口径)，不含账号容量或调度诊断。 成功记录的 `status` 为 `success`，不伪造未保存的 HTTP 状态；错误记录为 `error`，只返回客户端状态码， 缺失的 Token/费用明细为 null。不返回账号资料、Key ID、上游模型或请求标识、原始错误正文或诊断内容 @@ -1798,14 +1798,39 @@ OpenAI 优先采用服务端 `openai-model` / `x-openai-model` 报告（流内 `latencyMs` 从模型执行会话开始计到终结，包含账号选择、重试及流交付等待，不包含此前的入口解析、路由和准入。 `firstTokenLatencyMs` 与它使用同一计时起点，首字边界由 Provider 协议定义。 -OpenAI Responses 采用首个非前导输出事件，包含 `response.output_item.added` 等结构事件， -跳过 `response.created`、`response.in_progress`、心跳、额度控制和失败事件；xAI 采用首个语义输出。 +OpenAI Responses 采用官方 Codex 的首个 `response.output_item.added` 边界； +xAI 采用首个非空文本、推理或工具参数输出。对应事件缺失时保留未知，不用其他事件补齐首字。 +请求级首字统一通过 `firstTokenLatencyMs` 返回，由前端格式化。 `latencyDetails` 的首事件、首推理和首正文时间也使用请求级起点，首推理与首正文仍要求实际内容， 连接、响应头等传输阶段耗时独立计量，不能直接相加作为总耗时 -列表与性能统计的输出速率为 `outputTokens × 1000 / latencyMs`，只在输出 Token 和总耗时为正时计算， -不依赖首字是否采集。输出 Token 保留上游用量口径，OpenAI 的输出已包含推理 Token，不重复相加或扣除。 -该值表示完整请求期间的平均输出速率，包含选号、重试、推理与流交付等待，不表示模型内部的纯解码速度 +`latencyDetails.upstreamResponseMs` 是上游返回的本次响应耗时，与网关请求计时独立。 +OpenAI 仅使用同一条 `response.completed` 中的 `created_at` 与 `completed_at` 时间差， +将秒转换为毫秒保存，不拼接前导事件、会话累计计时或本地观测。 +字段缺失、时间倒序或时间跨度为零时保持缺失；未采集官方计时的记录不会用网关耗时补齐。 +返回整数秒时间戳时，短请求受秒级取整影响，不能用毫秒单位推断来源具有毫秒精度 + +`latencyDetails` 还可包含以下上游性能指标，单位为毫秒，保留上游返回的小数。 +OpenAI 从当前响应的 `responsesapi.websocket_timing.timing_metrics` 读取， +WebSocket 握手默认请求专项计时，客户端显式提供的开关保留原值。 +各字段独立可选；响应开始前、终态后的计时和明确属于其他响应的事件不写入当前请求，重试时清空 + +| 字段 | 上游口径 | +| --- | --- | +| `upstreamApiOverheadMs` | API 排除引擎与客户端工具时间后的耗时 | +| `upstreamEngineMs` | Engine Service 总耗时 | +| `upstreamEngineIapiTtftMs` | Engine IAPI TTFT 总计 | +| `upstreamEngineServiceTtftMs` | Engine Service TTFT 总计 | +| `upstreamEngineIapiTbtMs` | 跨引擎调用的 IAPI Token 间隔 | +| `upstreamEngineServiceTbtMs` | 跨引擎调用的 Service Token 间隔 | + +以上指标按上游内部口径展示，不相加重建总耗时，不替换请求级 `firstTokenLatencyMs`。 +它们仅补充性能诊断，不改变列表与聚合统计的速率分母 + +列表与性能统计的速率为 `outputTokens × 1000 / upstreamResponseMs`，只在两者为正时计算。 +输出 Token 保留上游用量口径，OpenAI 的输出已包含推理 Token，不重复相加或扣除。 +该值表示上游响应创建到完成期间的平均输出速率，按官方时间戳精度计算， +不表示模型内部的纯解码速度，也不用于替代网关观测的首个输出等待与请求总耗时 ### 诊断与恢复关联 diff --git a/docs/architecture.md b/docs/architecture.md index 18a97878b..a6e4dfd78 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -840,12 +840,23 @@ OpenAI 订阅周期属于按需个人信息，不是额度事实。Admin 账号 ### 请求记录与交付 +Provider 独占首事件、首字、首推理和首正文的观测，以及上游计时的协议解析，通过类型化响应观测交给 Core。 +Core 只接收这些事实并记录请求总耗时，不从 canonical 事件补记输出计时； +未观测到的时间保持未知，各 Provider 的首字边界见 [记录范围与统计口径](api.md#记录范围与统计口径) + 请求观测通过有界进程内队列异步投影到 PostgreSQL。普通额度之外预留四分之一容量给失败与请求生命周期记录， 进度更新不能消耗预留；同一请求仍按入队顺序写入。容量耗尽、Store 暂不可用或进程退出超时时， 观测记录可能丢失并累计指标，拥堵与写入失败告警按累计计数限频，不改变客户端响应。 Usage 详情中的 attempt 因此是 best-effort，并通过 `attemptsComplete: false` 明示不完整性 +`model_requests` 保留身份、生命周期、业务检索、用量和费用列；请求与账号快照、路由展示信息、 +计时、调度、传输、响应和恢复耗时存入受类型与完整性约束的 `request_observation_json`，不另存同义列。 +Store 按生命周期原子更新所属分组，保留其他阶段的事实；查询通过 `model_request_observations` +集中提取类型化字段，Admin 与 API 不依赖数据库 JSON 路径。官方计时与本地计时分别归入 +`timings.upstream` 和 `timings.local`，缺失保持未知；原始错误、Provider metadata、费用快照及 +诊断轨迹仍按各自合同独立保存 + `model_requests.deadline_at` 是异常回收租约的到期时间，运行会话持续刷新，且不超过显式执行截止。 进程退出后停止刷新，Worker 按过期租约收敛遗留的 running 记录；该观测续期失败不取消客户端执行 diff --git a/frontend/src/api/modules/usage.ts b/frontend/src/api/modules/usage.ts index b2a64bc28..fe4abb069 100644 --- a/frontend/src/api/modules/usage.ts +++ b/frontend/src/api/modules/usage.ts @@ -55,6 +55,13 @@ export interface UsageBilling { } export interface UsageLatencyDetails { + upstreamResponseMs?: number + upstreamApiOverheadMs?: number + upstreamEngineMs?: number + upstreamEngineIapiTtftMs?: number + upstreamEngineServiceTtftMs?: number + upstreamEngineIapiTbtMs?: number + upstreamEngineServiceTbtMs?: number admissionDecisionMs?: number accountSelectionWaitMs?: number capacityUsedSlots?: number @@ -65,7 +72,6 @@ export interface UsageLatencyDetails { firstEventMs?: number firstReasoningMs?: number firstTextMs?: number - firstTokenMs?: number openaiProcessingMs?: number } @@ -140,7 +146,6 @@ export interface UsageRecord { responseId: string | null upstreamRequestId: string | null latencyMs: number | null - firstTokenMs: number | null inputTokens: number | null outputTokens: number | null cachedTokens: number | null @@ -164,7 +169,6 @@ export interface UsageRecord { costs: UsageCost[] costCoverage: UsageCostCoverage firstTokenLatencyMs: number | null - firstTokenLatencyMsDisplay: string latencyMsDisplay: string logicalOutcome: string } diff --git a/frontend/src/components/usage/UsageDetailPopover.vue b/frontend/src/components/usage/UsageDetailPopover.vue index 90b15e111..579ad5294 100644 --- a/frontend/src/components/usage/UsageDetailPopover.vue +++ b/frontend/src/components/usage/UsageDetailPopover.vue @@ -5,7 +5,7 @@ import { Info } from '@lucide/vue' // 表格单元格的“信息点”悬浮明细：统一触发按钮与面板壳。 defineProps<{ - title: string + title?: string triggerLabel: string tone?: 'primary' | 'warning' }>() @@ -30,7 +30,7 @@ defineProps<{
-

+

{{ title }}

diff --git a/frontend/src/components/usage/UsageLatencyCell.vue b/frontend/src/components/usage/UsageLatencyCell.vue index 087b6264d..7024ea86d 100644 --- a/frontend/src/components/usage/UsageLatencyCell.vue +++ b/frontend/src/components/usage/UsageLatencyCell.vue @@ -17,60 +17,44 @@ const latencyDetails = computed(() => usageLatencyDetails(props.record))
- {{ latencyDetails.firstOutputLabel }} + 首字 {{ latencyDetails.firstOutputDisplay }} 总耗时 {{ latencyDetails.totalDisplay }}
- -
+
+

+ {{ section.title }} + + {{ section.source === 'official' ? '官方' : '本地' }} + +

{{ item.label }} - + {{ item.value }}
-
-

- 此记录未采集完整的阶段耗时 -

- -
- 总耗时 - - {{ latencyDetails.totalDisplay }} - -
- -
-

- 传输观测 -

-
- {{ item.label }} - - {{ item.value }} - -
-

- 与阶段耗时可能重叠，不参与总耗时相加 -

-
+
diff --git a/frontend/src/components/usage/shared/columns.ts b/frontend/src/components/usage/shared/columns.ts index 36f171302..6f33ff5df 100644 --- a/frontend/src/components/usage/shared/columns.ts +++ b/frontend/src/components/usage/shared/columns.ts @@ -28,7 +28,7 @@ export const usageRecordColumns = defineTableColumns([ { key: 'tokenDetails', label: 'TOKEN', kind: 'numeric', size: 'xl' }, { key: 'billing', label: '费用', kind: 'numeric', size: 'xl' }, { key: 'latency', label: '延迟', kind: 'numeric', size: 'xl' }, - { key: 'performance', label: '性能', kind: 'numeric', size: 'lg' }, + { key: 'performance', label: '速率', kind: 'numeric', size: 'lg' }, { key: 'createdAtDisplay', label: '时间', kind: 'datetime' }, { key: 'clientIp', label: 'IP', kind: 'custom', size: '3xl' }, { key: 'userAgent', label: 'User-Agent', kind: 'custom', size: '4xl' }, diff --git a/frontend/src/components/usage/shared/presenter.ts b/frontend/src/components/usage/shared/presenter.ts index 0b0c04b7d..9a6fa2511 100644 --- a/frontend/src/components/usage/shared/presenter.ts +++ b/frontend/src/components/usage/shared/presenter.ts @@ -5,10 +5,22 @@ import { formatCompactNumber, formatDuration, formatInteger } from '@/utils/form type UsageCommonRecord = UsageListRecord | UsageRecordDetail type UsageLatencyRecord = Pick -export type UsagePerformanceRecord = UsageLatencyRecord & { +export type UsagePerformanceRecord = Pick & { tokenDetails: Pick | null } +interface UsageTimingItem { + label: string + value: string + emphasized?: boolean +} + +interface UsageTimingSection { + title: string + source: 'official' | 'local' + items: UsageTimingItem[] +} + export function usageFreshInputTokens(input: number, cached: number, written: number) { // 输入总量包含缓存读写，普通输入与缓存明细分开展示 return Math.max(0, input - cached - written) @@ -101,52 +113,53 @@ export function usageModelDisplay(record: UsageCommonRecord) { } export function usagePerformanceDetails(record: UsagePerformanceRecord) { - const firstTokenMs = usageFirstTokenMs(record) - const totalMs = durationValue(record.latencyMs) + const upstreamMs = upstreamResponseMs(record.latencyDetails) const outputTokens = record.tokenDetails?.outputTokens - // 输出包含推理 Token，使用完整请求耗时，避免扣除推理等待后高估速率 + // 输出已包含推理 Token，分母只取同一完成响应的官方时间跨度 const throughput = typeof outputTokens === 'number' && Number.isFinite(outputTokens) && outputTokens > 0 - && totalMs !== null && totalMs > 0 - ? outputTokens * 1000 / totalMs + && upstreamMs !== null + ? outputTokens * 1000 / upstreamMs : null return { throughputDisplay: throughput === null ? '—' : `${formatCompactNumber(throughput)} tok/s`, - firstTokenDisplay: formatDuration(firstTokenMs), + firstTokenDisplay: formatDuration(durationValue(record.firstTokenLatencyMs)), } } export function usageLatencyDetails(record: UsageLatencyRecord) { const latencyDetails = record.latencyDetails - const firstTokenMs = usageFirstTokenMs(record) - const firstEventMs = durationValue(latencyDetails?.firstEventMs) + const firstTokenMs = durationValue(record.firstTokenLatencyMs) + const upstreamMs = upstreamResponseMs(latencyDetails) const totalMs = durationValue(record.latencyMs) const firstReasoningMs = durationValue(latencyDetails?.firstReasoningMs) const firstTextMs = durationValue(latencyDetails?.firstTextMs) - const breakdownItems = [] + const requestItems: UsageTimingItem[] = [] if (firstTokenMs !== null && totalMs !== null && firstTokenMs <= totalMs) { - breakdownItems.push({ label: '首字等待', value: formatDuration(firstTokenMs) }) + requestItems.push({ label: '首个输出等待', value: formatDuration(firstTokenMs) }) if (firstTextMs !== null && firstTextMs >= firstTokenMs && firstTextMs <= totalMs) { const beforeTextMs = firstTextMs - firstTokenMs if (beforeTextMs > 0) { - breakdownItems.push({ + requestItems.push({ label: firstReasoningMs === firstTokenMs ? '推理到正文' : '首个输出到正文', value: formatDuration(beforeTextMs), }) } - breakdownItems.push({ label: '正文生成', value: formatDuration(totalMs - firstTextMs) }) + requestItems.push({ label: '正文到完成', value: formatDuration(totalMs - firstTextMs) }) } else { - breakdownItems.push({ + requestItems.push({ label: '首个输出后完成', value: formatDuration(totalMs - firstTokenMs), }) } } - const transportItems = [ + requestItems.push({ label: '总耗时', value: formatDuration(totalMs), emphasized: true }) + + const transportItems: UsageTimingItem[] = [ { label: '准入判定', value: durationValue(latencyDetails?.admissionDecisionMs) }, { label: '账号选择等待', value: durationValue(latencyDetails?.accountSelectionWaitMs) }, { @@ -155,8 +168,7 @@ export function usageLatencyDetails(record: UsageLatencyRecord) { }, { label: 'WebSocket 连接', value: durationValue(latencyDetails?.wsConnectMs) }, { label: '上游响应头', value: durationValue(latencyDetails?.upstreamHeadersMs) }, - { label: '首个上游事件', value: firstEventMs }, - { label: '上游处理', value: durationValue(latencyDetails?.openaiProcessingMs) }, + { label: '首个上游事件', value: durationValue(latencyDetails?.firstEventMs) }, ] .filter(item => item.value !== null) .map(item => ({ ...item, value: formatDuration(item.value) })) @@ -171,13 +183,49 @@ export function usageLatencyDetails(record: UsageLatencyRecord) { }) } + const upstreamDisplay = formatDuration(upstreamMs) + const upstreamItems: UsageTimingItem[] = [] + if (upstreamMs !== null) + upstreamItems.push({ label: '响应耗时', value: upstreamDisplay }) + const processingMs = durationValue(latencyDetails?.openaiProcessingMs) + if (processingMs !== null) + upstreamItems.push({ label: '处理耗时', value: formatDuration(processingMs) }) + + 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) + upstreamItems.push({ label: item.label, value: formatUpstreamDuration(item.value) }) + } + + const sections: UsageTimingSection[] = [] + if (upstreamItems.length) { + sections.push({ + title: '上游性能', + source: 'official', + items: upstreamItems, + }) + } + sections.push({ title: '请求观测', source: 'local', items: requestItems }) + if (transportItems.length) { + sections.push({ + title: '传输观测', + source: 'local', + items: transportItems, + }) + } + return { - // SSE 可能先收到生命周期事件而没有文本或推理增量；这不是首字，须保留原始语义。 - firstOutputLabel: firstTokenMs === null && firstEventMs !== null ? '首事件' : '首字', - firstOutputDisplay: formatDuration(firstTokenMs ?? firstEventMs), + upstreamDisplay, + firstOutputDisplay: formatDuration(firstTokenMs), totalDisplay: formatDuration(totalMs), - breakdownItems, - transportItems, + sections, } } @@ -189,6 +237,15 @@ function durationValue(value: unknown) { return typeof value === 'number' && Number.isFinite(value) && value >= 0 ? value : null } -function usageFirstTokenMs(record: UsageLatencyRecord) { - return durationValue(record.firstTokenLatencyMs ?? record.latencyDetails?.firstTokenMs) +function formatUpstreamDuration(value: number) { + if (value >= 1000) + return formatDuration(value) + if (value > 0 && value < 0.001) + return '<0.001 ms' + return `${Number(value.toFixed(3))} ms` +} + +function upstreamResponseMs(details: UsageCommonRecord['latencyDetails']) { + const value = durationValue(details?.upstreamResponseMs) + return value !== null && value > 0 ? value : null } diff --git a/frontend/src/views/accounts/index.vue b/frontend/src/views/accounts/index.vue index 1bd70fd08..206802147 100644 --- a/frontend/src/views/accounts/index.vue +++ b/frontend/src/views/accounts/index.vue @@ -306,7 +306,9 @@ const {