From 2213359bd33f9ffc818e3aeb534faf47544293bc Mon Sep 17 00:00:00 2001 From: ioanbudea-OAI Date: Wed, 21 Oct 2026 09:44:44 +0000 Subject: [PATCH] Measure Guardian review latency once with a monotonic clock (#55846) ## Why Guardian review metrics derived duration from wall-clock timestamps, while analytics measured elapsed time when tracking the result. Clock changes and delayed tracking could produce inconsistent latencies. ## What changed Capture one monotonic duration at review completion and pass it to both metrics and analytics. Preserve wall-clock timestamps for event ordering, and saturate analytics latency conversion at `u64::MAX`. ## Testing Add a regression test covering skewed wall-clock timestamps and delayed tracking, verifying that the duration metric uses the captured interval and completion timestamps are preserved. GitOrigin-RevId: 19eafb8e1f1a3d13a751bdc72c218e4cafeae410 --- codex-rs/analytics/src/client.rs | 3 +- codex-rs/analytics/src/events.rs | 8 +- codex-rs/ext/guardian-reviewer/src/metrics.rs | 10 +- .../ext/guardian-reviewer/src/reporting.rs | 27 +++- .../guardian-reviewer/src/reporting_tests.rs | 122 ++++++++++++++++++ codex-rs/ext/guardian-reviewer/src/review.rs | 3 +- 6 files changed, 155 insertions(+), 18 deletions(-) create mode 100644 codex-rs/ext/guardian-reviewer/src/reporting_tests.rs diff --git a/codex-rs/analytics/src/client.rs b/codex-rs/analytics/src/client.rs index 26991de16d..aef8abef13 100644 --- a/codex-rs/analytics/src/client.rs +++ b/codex-rs/analytics/src/client.rs @@ -472,9 +472,10 @@ impl AnalyticsEventsClient { tracking: &GuardianReviewTrackContext, result: GuardianReviewAnalyticsResult, completed_at_ms: u64, + elapsed: Duration, ) { self.record_fact(AnalyticsFact::Custom(CustomAnalyticsFact::GuardianReview( - Box::new(tracking.event_params(result, completed_at_ms)), + Box::new(tracking.event_params(result, completed_at_ms, elapsed)), ))); } diff --git a/codex-rs/analytics/src/events.rs b/codex-rs/analytics/src/events.rs index f62516be9a..7ea459b0a3 100644 --- a/codex-rs/analytics/src/events.rs +++ b/codex-rs/analytics/src/events.rs @@ -1,5 +1,5 @@ use std::sync::LazyLock; -use std::time::Instant; +use std::time::Duration; use crate::facts::AppInvocation; use crate::facts::ArtifactOperation; @@ -448,7 +448,6 @@ pub struct GuardianReviewTrackContext { reviewed_action: GuardianReviewedAction, review_timeout_ms: u64, pub started_at_ms: u64, - started_instant: Instant, } impl GuardianReviewTrackContext { @@ -470,7 +469,6 @@ impl GuardianReviewTrackContext { reviewed_action, review_timeout_ms, started_at_ms: now_unix_millis(), - started_instant: Instant::now(), } } @@ -478,7 +476,9 @@ impl GuardianReviewTrackContext { &self, result: GuardianReviewAnalyticsResult, completed_at_ms: u64, + elapsed: Duration, ) -> GuardianReviewEventParams { + let completion_latency_ms = u64::try_from(elapsed.as_millis()).unwrap_or(u64::MAX); GuardianReviewEventParams { guardian_context_mode: result.guardian_context_mode, thread_id: self.thread_id.clone(), @@ -509,7 +509,7 @@ impl GuardianReviewTrackContext { // TODO(rhan-oai): plumb nested Guardian review session tool-call counts. tool_call_count: None, time_to_first_token_ms: result.time_to_first_token_ms, - completion_latency_ms: Some(self.started_instant.elapsed().as_millis() as u64), + completion_latency_ms: Some(completion_latency_ms), started_at: self.started_at_ms / 1_000, completed_at: Some(completed_at_ms / 1_000), input_tokens: result.token_usage.as_ref().map(|usage| usage.input_tokens), diff --git a/codex-rs/ext/guardian-reviewer/src/metrics.rs b/codex-rs/ext/guardian-reviewer/src/metrics.rs index e1f2a94237..fdb857508d 100644 --- a/codex-rs/ext/guardian-reviewer/src/metrics.rs +++ b/codex-rs/ext/guardian-reviewer/src/metrics.rs @@ -26,7 +26,7 @@ pub(crate) fn emit_guardian_review_metrics( result: &GuardianReviewAnalyticsResult, approval_request_source: GuardianApprovalRequestSource, reviewed_action: &GuardianReviewedAction, - completion_latency_ms: u64, + elapsed: Duration, ) { let tags = guardian_review_metric_tags(result, approval_request_source, reviewed_action); let tag_refs: Vec<(&str, &str)> = tags @@ -52,11 +52,7 @@ pub(crate) fn emit_guardian_review_metrics( /*inc*/ 1, &counter_tag_refs, ); - session_telemetry.record_duration( - GUARDIAN_REVIEW_DURATION_METRIC, - Duration::from_millis(completion_latency_ms), - &tag_refs, - ); + session_telemetry.record_duration(GUARDIAN_REVIEW_DURATION_METRIC, elapsed, &tag_refs); // Cached approvals may cancel an in-flight review: retain its attempt count, // but use the final review status to distinguish recovery from async release. @@ -452,7 +448,7 @@ mod tests { &result, GuardianApprovalRequestSource::DelegatedSubagent, &reviewed_action, - /*completion_latency_ms*/ 456, + Duration::from_millis(456), ); let snapshot = session_telemetry diff --git a/codex-rs/ext/guardian-reviewer/src/reporting.rs b/codex-rs/ext/guardian-reviewer/src/reporting.rs index 531d322247..30fc49c9ba 100644 --- a/codex-rs/ext/guardian-reviewer/src/reporting.rs +++ b/codex-rs/ext/guardian-reviewer/src/reporting.rs @@ -1,7 +1,11 @@ //! Owns review reporting and the per-thread denial window. The host publishes -//! events and enforces interruption only on the still-active owning turn. +//! events and enforces interruption only on the still-active owning turn. Review +//! completion captures one monotonic duration for latency reporting while retaining +//! the actual wall-clock completion timestamp for event ordering. use std::sync::Arc; +use std::time::Duration; +use std::time::Instant; use codex_analytics::AnalyticsEventsClient; use codex_analytics::GuardianApprovalRequestSource; @@ -42,6 +46,7 @@ pub struct ReviewMetadata { pub struct ReviewReport { started: GuardianAssessmentEvent, + started_instant: Instant, tracking: GuardianReviewTrackContext, approval_request_source: GuardianApprovalRequestSource, reviewed_action: GuardianReviewedAction, @@ -49,6 +54,7 @@ pub struct ReviewReport { impl ReviewReport { pub fn new(metadata: ReviewMetadata) -> Self { + let started_instant = Instant::now(); let tracking = GuardianReviewTrackContext::new( metadata.thread_id, metadata.turn_id.clone(), @@ -77,6 +83,7 @@ impl ReviewReport { }; Self { started, + started_instant, tracking, approval_request_source: metadata.approval_request_source, reviewed_action: metadata.reviewed_action, @@ -91,6 +98,7 @@ impl ReviewReport { self.started.clone() } + /// Completes the report and captures the elapsed duration to use when tracking it. pub fn complete( &self, outcome: GuardianReviewOutcome, @@ -98,11 +106,15 @@ impl ReviewReport { require_guardian: bool, analytics: GuardianReviewAnalyticsResult, completed_at_ms: i64, - ) -> ReviewCompletion { + ) -> (ReviewCompletion, Duration) { + let elapsed = self.started_instant.elapsed(); let mut event = self.started.clone(); event.completed_at_ms = Some(completed_at_ms); event.decision_source = Some(GuardianAssessmentDecisionSource::Agent); - crate::complete_review(outcome, model, require_guardian, event, analytics) + ( + crate::complete_review(outcome, model, require_guardian, event, analytics), + elapsed, + ) } pub fn track( @@ -111,15 +123,16 @@ impl ReviewReport { analytics: &AnalyticsEventsClient, result: GuardianReviewAnalyticsResult, completed_at_ms: u64, + elapsed: Duration, ) { crate::metrics::emit_guardian_review_metrics( telemetry, &result, self.approval_request_source, &self.reviewed_action, - completed_at_ms.saturating_sub(self.tracking.started_at_ms), + elapsed, ); - analytics.track_guardian_review(&self.tracking, result, completed_at_ms); + analytics.track_guardian_review(&self.tracking, result, completed_at_ms, elapsed); } } @@ -163,3 +176,7 @@ impl ReviewDenials { } } } + +#[cfg(test)] +#[path = "reporting_tests.rs"] +mod tests; diff --git a/codex-rs/ext/guardian-reviewer/src/reporting_tests.rs b/codex-rs/ext/guardian-reviewer/src/reporting_tests.rs new file mode 100644 index 0000000000..5bb364eab3 --- /dev/null +++ b/codex-rs/ext/guardian-reviewer/src/reporting_tests.rs @@ -0,0 +1,122 @@ +//! Regression coverage for capturing one review interval despite wall-clock skew. + +use super::*; +use codex_otel::GUARDIAN_REVIEW_DURATION_METRIC; +use codex_otel::MetricsClient; +use codex_otel::MetricsConfig; +use codex_protocol::ThreadId; +use codex_protocol::approvals::NetworkApprovalProtocol; +use codex_protocol::protocol::SessionSource; +use opentelemetry_sdk::metrics::InMemoryMetricExporter; +use opentelemetry_sdk::metrics::data::AggregatedMetrics; +use opentelemetry_sdk::metrics::data::MetricData; +use opentelemetry_sdk::metrics::data::ScopeMetrics; +use pretty_assertions::assert_eq; +use serde_json::json; +use std::time::Duration; + +#[test] +fn review_completion_uses_one_monotonic_duration() { + let exporter = InMemoryMetricExporter::default(); + let metrics = MetricsClient::new( + MetricsConfig::in_memory("test", "codex-core", env!("CARGO_PKG_VERSION"), exporter) + .with_runtime_reader(), + ) + .expect("in-memory metrics client"); + let telemetry = SessionTelemetry::new( + ThreadId::new(), + "test-model", + "test-model", + /*account_id*/ None, + /*account_email*/ None, + /*auth_mode*/ None, + "test_originator".to_string(), + /*log_user_prompts*/ false, + "tty".to_string(), + SessionSource::Cli, + ) + .with_metrics_without_metadata_tags(metrics); + let mut report = ReviewReport::new(ReviewMetadata { + thread_id: "thread".to_string(), + turn_id: "turn".to_string(), + review_id: "review".to_string(), + target_item_id: None, + plugin_id: None, + script_path: None, + approval_request_source: GuardianApprovalRequestSource::MainTurn, + reviewed_action: GuardianReviewedAction::NetworkAccess { + protocol: NetworkApprovalProtocol::Https, + port: 443, + }, + action: GuardianAssessmentAction::NetworkAccess { + target: "example.com".to_string(), + host: "example.com".to_string(), + protocol: NetworkApprovalProtocol::Https, + port: 443, + }, + review_reason: GuardianReviewReason::Policy, + model_context: ModelInvocationContext { + model_slug: "test-model".to_string(), + reasoning_effort: None, + }, + }); + report.tracking.started_at_ms = 1_654_073_807_000; + report.started.started_at_ms = + i64::try_from(report.tracking.started_at_ms).expect("start timestamp"); + report.started_instant = Instant::now() - Duration::from_millis(456); + let model: ModelInfo = serde_json::from_value(json!({ + "slug": "test-model", + "display_name": "Test model", + "supported_reasoning_levels": [], + "shell_type": "disabled", + "visibility": "none", + "supported_in_api": false, + "priority": 0, + "support_verbosity": false, + "truncation_policy": {"mode": "tokens", "limit": 1000}, + "experimental_supported_tools": [] + })) + .expect("test model"); + + let before = report.started_instant.elapsed(); + let (completed, elapsed) = report.complete( + GuardianReviewOutcome::CachedApproval, + &model, + /*require_guardian*/ true, + GuardianReviewAnalyticsResult::without_session(), + /*completed_at_ms*/ 1_792_141_011_000, + ); + let after = report.started_instant.elapsed(); + assert!((before..=after).contains(&elapsed)); + let elapsed_ms = u64::try_from(elapsed.as_millis()).expect("elapsed milliseconds"); + assert_eq!( + ( + completed.event.started_at_ms, + completed.event.completed_at_ms + ), + (1_654_073_807_000, Some(1_792_141_011_000),) + ); + + // Simulate tracking later: the captured interval must not be measured again. + report.started_instant -= Duration::from_secs(1); + report.track( + &telemetry, + &AnalyticsEventsClient::disabled(), + completed.analytics, + /*completed_at_ms*/ 1_792_141_011_000, + elapsed, + ); + + let snapshot = telemetry.snapshot_metrics().expect("metrics snapshot"); + let metric = snapshot + .scope_metrics() + .flat_map(ScopeMetrics::metrics) + .find(|metric| metric.name() == GUARDIAN_REVIEW_DURATION_METRIC) + .expect("review duration metric"); + let AggregatedMetrics::F64(MetricData::Histogram(histogram)) = metric.data() else { + panic!("expected a duration histogram"); + }; + let points: Vec<_> = histogram.data_points().collect(); + assert_eq!(points.len(), 1); + assert_eq!((points[0].count(), points[0].sum() as u64), (1, elapsed_ms)); +} diff --git a/codex-rs/ext/guardian-reviewer/src/review.rs b/codex-rs/ext/guardian-reviewer/src/review.rs index 4b336cc00b..7d7787cd6c 100644 --- a/codex-rs/ext/guardian-reviewer/src/review.rs +++ b/codex-rs/ext/guardian-reviewer/src/review.rs @@ -179,7 +179,7 @@ impl SynchronousApprovalReviewer for ReviewRequest<'_, H> { }; let completed_at_ms = codex_analytics::now_unix_millis(); let cached_approval = matches!(outcome, GuardianReviewOutcome::CachedApproval); - let completed = report.complete( + let (completed, elapsed) = report.complete( outcome, self.model, self.require_guardian, @@ -195,6 +195,7 @@ impl SynchronousApprovalReviewer for ReviewRequest<'_, H> { self.analytics, completed.analytics, completed_at_ms, + elapsed, ); if let Some(message) = completed.warning { self.host