From faf50c28ad8ff722e5c8e07304fa03544900b54f Mon Sep 17 00:00:00 2001 From: Zyy Date: Thu, 8 Oct 2026 17:30:33 +0800 Subject: [PATCH] feat(usage): unify request observations and upstream performance Consolidate request diagnostics into typed request_observation_json with migration 0025, preserving historical facts and query constraints. Use upstream response timestamps for output throughput, align TTFT event boundaries, and surface official timing metrics in the latency popover. Co-authored-by: Codex --- .../gateway-admin/src/model/observability.rs | 22 +- .../tests/use_case/observability.rs | 7 + .../src/admin/observability/presenter.rs | 21 +- .../src/admin/observability/wire.rs | 18 +- .../gateway-api/src/key_usage/presenter.rs | 21 + .../tests/admin/observability/response.rs | 74 ++- .../gateway-api/tests/key_usage/fixtures.rs | 7 + .../crates/gateway-api/tests/key_usage/mod.rs | 13 +- backend/crates/gateway-core/src/engine/mod.rs | 11 +- .../gateway-core/src/engine/observation.rs | 47 +- backend/crates/gateway-core/src/event.rs | 20 +- .../gateway-core/tests/engine/coordinator.rs | 46 +- .../runtime/src/adapter/observer.rs | 7 + .../runtime/src/callback/facts.rs | 7 + .../runtime/tests/generation/observer.rs | 7 + .../tests/generation/policy/facts/mod.rs | 10 + .../runtime/tests/support/environment.rs | 2 +- .../sdk/src/call/model/facts.rs | 2 +- .../sdk/src/call/observation.rs | 24 +- .../sdk/tests/call/observation.rs | 4 +- .../{execution.rs => execution/mod.rs} | 288 ++++-------- .../postgres/execution/request_observation.rs | 321 +++++++++++++ .../src/postgres/observability/mapping.rs | 14 + .../src/postgres/observability/model.rs | 2 +- .../observability/queries/dashboard.rs | 40 +- .../src/postgres/observability/queries/ops.rs | 8 +- .../postgres/observability/queries/usage.rs | 20 +- .../tests/postgres/account_groups.rs | 25 +- .../tests/postgres/admission_recovery.rs | 19 +- .../tests/postgres/connection.rs | 10 +- .../{execution.rs => execution/mod.rs} | 200 ++++++-- .../tests/postgres/observability/mod.rs | 324 +++++++------ .../tests/postgres/provider_accounts/mod.rs | 28 +- .../tests/postgres/schema_integrity.rs | 244 +++++++++- .../gateway-store/tests/postgres/snapshots.rs | 58 ++- .../openai/src/provider/execution.rs | 18 +- .../openai/src/provider/observation.rs | 39 +- .../openai/src/transport/canonical.rs | 30 +- .../providers/openai/src/transport/headers.rs | 7 + .../src/transport/protocol/responses.rs | 89 +++- .../openai/tests/provider/contract/timing.rs | 161 ++++++- .../openai/tests/transport/canonical.rs | 91 +++- .../tests/transport/protocol/responses.rs | 29 +- .../tests/transport/websocket/fingerprint.rs | 10 +- .../providers/xai/src/provider/stream.rs | 48 ++ .../xai/tests/provider/contract/mod.rs | 1 + .../xai/tests/provider/contract/timing.rs | 102 ++++ backend/migrations/.frozen-sha256 | 1 + .../migrations/0025_request_observation.sql | 443 ++++++++++++++++++ docs/api.md | 37 +- docs/architecture.md | 11 + frontend/src/api/modules/usage.ts | 10 +- .../components/usage/UsageDetailPopover.vue | 4 +- .../src/components/usage/UsageLatencyCell.vue | 64 +-- .../src/components/usage/shared/columns.ts | 2 +- .../src/components/usage/shared/presenter.ts | 105 ++++- frontend/src/views/accounts/index.vue | 4 +- .../composables/useRequestTrendChart.ts | 6 +- frontend/src/views/dashboard/presenter.ts | 4 +- .../key-usage/components/KeyUsageRecords.vue | 2 +- .../src/views/theme/fixtures/dashboard.ts | 15 +- .../usage/components/UsagePerformanceCard.vue | 6 +- .../components/UsageRecordDetailModal.vue | 3 +- 63 files changed, 2627 insertions(+), 686 deletions(-) rename backend/crates/gateway-store/src/postgres/{execution.rs => execution/mod.rs} (85%) create mode 100644 backend/crates/gateway-store/src/postgres/execution/request_observation.rs rename backend/crates/gateway-store/tests/postgres/{execution.rs => execution/mod.rs} (90%) create mode 100644 backend/crates/providers/xai/tests/provider/contract/timing.rs create mode 100644 backend/migrations/0025_request_observation.sql 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 {