diff --git a/crates/mise-cache-core/src/agent.rs b/crates/mise-cache-core/src/agent.rs index ac4e9c50850..9ed42593a64 100644 --- a/crates/mise-cache-core/src/agent.rs +++ b/crates/mise-cache-core/src/agent.rs @@ -12,6 +12,7 @@ use std::fs; use std::path::{Path, PathBuf}; use std::sync::atomic::{AtomicU64, Ordering}; use std::sync::{Arc, Mutex, Weak}; +use std::time::Instant; use tokio::io::{AsyncBufReadExt, AsyncRead, AsyncWrite, AsyncWriteExt, BufReader}; const MAX_EXECUTABLE_IDENTITIES: usize = 64; @@ -55,9 +56,11 @@ pub enum AgentRequest { }, RecordActionHit { action: CacheDigest, + restore: RestoreStats, }, RecordActionVerification { matched: bool, + restore: RestoreStats, }, StoreActionResult { result: RemoteActionResult, @@ -81,6 +84,18 @@ pub enum AgentRequest { }, } +/// Local output restoration work performed by one action-cache adapter hit. +#[derive(Debug, Clone, Copy, Default, PartialEq, Eq, Serialize, Deserialize)] +#[serde(deny_unknown_fields)] +pub struct RestoreStats { + /// Cumulative time spent materializing and validating output files. + pub duration_ns: u64, + /// Number of compiler output files restored. + pub output_files: u64, + /// Declared size of compiler output files restored. + pub output_bytes: u64, +} + /// A response returned by the task-scoped cache agent. #[derive(Debug, Serialize, Deserialize)] #[serde(tag = "type", rename_all = "snake_case")] @@ -119,6 +134,8 @@ pub enum AgentResponse { /// Aggregate cache activity for one task session. #[derive(Debug, Clone, Copy, Default, PartialEq, Eq)] pub struct AgentStats { + /// End-to-end lifetime of the task-scoped cache session. + pub session_duration_ns: u64, /// Number of action-result lookups. pub lookups: u64, /// Number of lookups that found a valid local action result. @@ -137,6 +154,30 @@ pub struct AgentStats { pub uploaded_bytes: u64, /// Complete actions staged before an adapter requested them. pub prefetched_actions: u64, + /// Number of task manifest requests made to the remote cache. + pub remote_manifest_lookups: u64, + /// Cumulative time spent requesting remote task manifests. + pub remote_manifest_lookup_duration_ns: u64, + /// Number of action-result requests made to the remote cache. + pub remote_action_lookups: u64, + /// Cumulative time spent requesting remote action results. + pub remote_action_lookup_duration_ns: u64, + /// Number of blob requests made to the remote cache. + pub remote_blob_requests: u64, + /// Cumulative time spent downloading and verifying remote blobs. + pub remote_blob_transfer_duration_ns: u64, + /// Cumulative time spent ingesting downloaded blobs into the local CAS. + pub local_cas_write_duration_ns: u64, + /// Number of speculative prefetch runs started for task manifests. + pub prefetch_runs: u64, + /// Cumulative wall time of speculative task-manifest prefetch runs. + pub prefetch_duration_ns: u64, + /// Cumulative time spent staging or materializing and validating cached outputs. + pub materialization_duration_ns: u64, + /// Number of compiler output files restored from action hits. + pub restored_output_files: u64, + /// Declared size of compiler output files restored from action hits. + pub restored_output_bytes: u64, } /// Adapter-owned data needed to reconstruct an action before fresh dependency @@ -161,6 +202,48 @@ struct AtomicAgentStats { downloaded_bytes: AtomicU64, uploaded_bytes: AtomicU64, prefetched_actions: AtomicU64, + remote_manifest_lookups: AtomicU64, + remote_manifest_lookup_duration_ns: AtomicU64, + remote_action_lookups: AtomicU64, + remote_action_lookup_duration_ns: AtomicU64, + remote_blob_requests: AtomicU64, + remote_blob_transfer_duration_ns: AtomicU64, + local_cas_write_duration_ns: AtomicU64, + prefetch_runs: AtomicU64, + prefetch_duration_ns: AtomicU64, + materialization_duration_ns: AtomicU64, + restored_output_files: AtomicU64, + restored_output_bytes: AtomicU64, +} + +struct AtomicDurationTimer<'a> { + started: Instant, + target: &'a AtomicU64, +} + +impl<'a> AtomicDurationTimer<'a> { + fn start(target: &'a AtomicU64) -> Self { + Self { + started: Instant::now(), + target, + } + } +} + +impl Drop for AtomicDurationTimer<'_> { + fn drop(&mut self) { + atomic_saturating_add(self.target, duration_ns(self.started)); + } +} + +fn duration_ns(started: Instant) -> u64 { + started.elapsed().as_nanos().try_into().unwrap_or(u64::MAX) +} + +fn atomic_saturating_add(target: &AtomicU64, value: u64) { + let _ = target.fetch_update(Ordering::Relaxed, Ordering::Relaxed, |current| { + Some(current.saturating_add(value)) + }); } /// Shared state for an agent hosted by the top-level `mise run` process. @@ -494,6 +577,10 @@ impl CacheAgent { }; let (_, selector) = Self::task_manifest_selector(task)?; let _permit = self.remote_transfers.acquire().await?; + self.stats + .remote_manifest_lookups + .fetch_add(1, Ordering::Relaxed); + let _timer = AtomicDurationTimer::start(&self.stats.remote_manifest_lookup_duration_ns); let Some(remote_manifest) = remote.get_action_manifest(&selector).await? else { return Ok(None); }; @@ -538,6 +625,7 @@ impl CacheAgent { /// Return a snapshot of this session's cache activity. pub fn stats(&self) -> AgentStats { AgentStats { + session_duration_ns: 0, lookups: self.stats.lookups.load(Ordering::Relaxed), hits: self.stats.hits.load(Ordering::Relaxed), stores: self.stats.stores.load(Ordering::Relaxed), @@ -547,6 +635,33 @@ impl CacheAgent { downloaded_bytes: self.stats.downloaded_bytes.load(Ordering::Relaxed), uploaded_bytes: self.stats.uploaded_bytes.load(Ordering::Relaxed), prefetched_actions: self.stats.prefetched_actions.load(Ordering::Relaxed), + remote_manifest_lookups: self.stats.remote_manifest_lookups.load(Ordering::Relaxed), + remote_manifest_lookup_duration_ns: self + .stats + .remote_manifest_lookup_duration_ns + .load(Ordering::Relaxed), + remote_action_lookups: self.stats.remote_action_lookups.load(Ordering::Relaxed), + remote_action_lookup_duration_ns: self + .stats + .remote_action_lookup_duration_ns + .load(Ordering::Relaxed), + remote_blob_requests: self.stats.remote_blob_requests.load(Ordering::Relaxed), + remote_blob_transfer_duration_ns: self + .stats + .remote_blob_transfer_duration_ns + .load(Ordering::Relaxed), + local_cas_write_duration_ns: self + .stats + .local_cas_write_duration_ns + .load(Ordering::Relaxed), + prefetch_runs: self.stats.prefetch_runs.load(Ordering::Relaxed), + prefetch_duration_ns: self.stats.prefetch_duration_ns.load(Ordering::Relaxed), + materialization_duration_ns: self + .stats + .materialization_duration_ns + .load(Ordering::Relaxed), + restored_output_files: self.stats.restored_output_files.load(Ordering::Relaxed), + restored_output_bytes: self.stats.restored_output_bytes.load(Ordering::Relaxed), } } @@ -590,6 +705,8 @@ impl CacheAgent { if !self.remote_mode.reads() || self.remote.is_none() { return; } + self.stats.prefetch_runs.fetch_add(1, Ordering::Relaxed); + let _timer = AtomicDurationTimer::start(&self.stats.prefetch_duration_ns); let mut actions = BTreeMap::new(); for prediction in predictions { actions @@ -641,7 +758,7 @@ impl CacheAgent { let _prefetch_permit = self.prefetch_transfers.acquire().await?; let result = { let _permit = self.remote_transfers.acquire().await?; - remote.get_action_result(&action).await? + self.get_remote_action_result(remote, &action).await? }; let Some(result) = result else { return Ok(()) }; self.pending_remote_actions @@ -754,9 +871,16 @@ impl CacheAgent { None => None, }; let _permit = self.remote_transfers.acquire().await?; + self.stats + .remote_blob_requests + .fetch_add(1, Ordering::Relaxed); + let transfer_timer = + AtomicDurationTimer::start(&self.stats.remote_blob_transfer_duration_ns); let temporary = remote .get_blob_file(digest, self.remote_staging_dir.as_path()) .await?; + drop(transfer_timer); + let _cas_timer = AtomicDurationTimer::start(&self.stats.local_cas_write_duration_ns); let path = self.cas.store_verified_file(digest, temporary.path())?; self.remember_verified_blob(digest, &path); self.stats.stores.fetch_add(1, Ordering::Relaxed); @@ -777,8 +901,11 @@ impl CacheAgent { self.stats.lookups.fetch_add(1, Ordering::Relaxed); self.find_action_result(&action).await } - AgentRequest::RecordActionHit { action } => self.record_action_hit(&action), - AgentRequest::RecordActionVerification { matched } => { + AgentRequest::RecordActionHit { action, restore } => { + self.record_action_hit(&action, restore) + } + AgentRequest::RecordActionVerification { matched, restore } => { + self.record_materialization(restore); self.stats.verifications.fetch_add(1, Ordering::Relaxed); if !matched { self.stats.divergences.fetch_add(1, Ordering::Relaxed); @@ -928,7 +1055,7 @@ impl CacheAgent { }); } let _permit = self.remote_transfers.acquire().await?; - match remote.get_action_result(action).await { + match self.get_remote_action_result(remote, action).await { Ok(Some(result)) => { self.pending_remote_actions .lock() @@ -965,7 +1092,23 @@ impl CacheAgent { Ok(AgentResponse::ActionStored { path }) } - fn record_action_hit(&self, action: &CacheDigest) -> Result { + async fn get_remote_action_result( + &self, + remote: &RemoteCacheClient, + action: &CacheDigest, + ) -> Result> { + self.stats + .remote_action_lookups + .fetch_add(1, Ordering::Relaxed); + let _timer = AtomicDurationTimer::start(&self.stats.remote_action_lookup_duration_ns); + remote.get_action_result(action).await + } + + fn record_action_hit( + &self, + action: &CacheDigest, + restore: RestoreStats, + ) -> Result { if self.actions.find(action)?.is_none() { let pending = self.pending_remote_actions.lock().unwrap().remove(action); if let Some(result) = pending { @@ -974,10 +1117,21 @@ impl CacheAgent { bail!("cannot record a hit for a missing action result"); } } + self.record_restore(restore); self.stats.hits.fetch_add(1, Ordering::Relaxed); Ok(AgentResponse::ActionHitRecorded) } + fn record_restore(&self, restore: RestoreStats) { + self.record_materialization(restore); + atomic_saturating_add(&self.stats.restored_output_files, restore.output_files); + atomic_saturating_add(&self.stats.restored_output_bytes, restore.output_bytes); + } + + fn record_materialization(&self, restore: RestoreStats) { + atomic_saturating_add(&self.stats.materialization_duration_ns, restore.duration_ns); + } + fn find_action_prediction( &self, task: &str, @@ -1362,7 +1516,12 @@ mod tests { assert!(matches!( agent .respond(AgentRequest::RecordActionHit { - action: action.clone() + action: action.clone(), + restore: RestoreStats { + duration_ns: 7, + output_files: 2, + output_bytes: 11, + }, }) .await, AgentResponse::ActionHitRecorded @@ -1372,6 +1531,9 @@ mod tests { AgentStats { lookups: 1, hits: 1, + materialization_duration_ns: 7, + restored_output_files: 2, + restored_output_bytes: 11, ..AgentStats::default() } ); @@ -1394,7 +1556,10 @@ mod tests { )); assert!(matches!( agent - .respond(AgentRequest::RecordActionHit { action }) + .respond(AgentRequest::RecordActionHit { + action, + restore: RestoreStats::default(), + }) .await, AgentResponse::Error { .. } )); @@ -1408,12 +1573,22 @@ mod tests { assert!(matches!( agent - .respond(AgentRequest::RecordActionVerification { matched: false }) + .respond(AgentRequest::RecordActionVerification { + matched: false, + restore: RestoreStats { + duration_ns: 7, + output_files: 2, + output_bytes: 11, + }, + }) .await, AgentResponse::ActionVerificationRecorded )); assert_eq!(agent.stats().verifications, 1); assert_eq!(agent.stats().divergences, 1); + assert_eq!(agent.stats().materialization_duration_ns, 7); + assert_eq!(agent.stats().restored_output_files, 0); + assert_eq!(agent.stats().restored_output_bytes, 0); } #[tokio::test] @@ -1769,13 +1944,27 @@ mod tests { } assert!(matches!( reader - .respond(AgentRequest::RecordActionHit { action }) + .respond(AgentRequest::RecordActionHit { + action, + restore: RestoreStats::default(), + }) .await, AgentResponse::ActionHitRecorded )); for mock in mocks { mock.assert_async().await; } + let stats = reader.stats(); + assert_eq!(stats.prefetch_runs, 1); + assert_eq!(stats.prefetched_actions, 1); + assert!(stats.remote_manifest_lookups > 0); + assert!(stats.remote_action_lookups > 0); + assert!(stats.remote_blob_requests > 0); + assert!(stats.remote_manifest_lookup_duration_ns > 0); + assert!(stats.remote_action_lookup_duration_ns > 0); + assert!(stats.remote_blob_transfer_duration_ns > 0); + assert!(stats.local_cas_write_duration_ns > 0); + assert!(stats.prefetch_duration_ns > 0); } #[tokio::test] diff --git a/crates/mise-cache-core/src/lib.rs b/crates/mise-cache-core/src/lib.rs index 35911dfaff8..1d073d8811e 100644 --- a/crates/mise-cache-core/src/lib.rs +++ b/crates/mise-cache-core/src/lib.rs @@ -20,7 +20,7 @@ mod local; pub use agent::{ AGENT_PROTOCOL_VERSION, ActionPrediction, AgentRemoteCache, AgentRequest, AgentResponse, - AgentStats, CacheAgent, + AgentStats, CacheAgent, RestoreStats, }; pub use local::{LocalActionCache, LocalCas}; diff --git a/e2e/tasks/test_task_rust_cache_restore b/e2e/tasks/test_task_rust_cache_restore index 2479c0f5c6c..6703bfb5225 100644 --- a/e2e/tasks/test_task_rust_cache_restore +++ b/e2e/tasks/test_task_rust_cache_restore @@ -111,4 +111,9 @@ chmod +x fake-rustc assert_contains "mise run restore 2>&1" "Action cache: 1 hits, 2 misses, 0 prefetched;" rm -rf out -assert_contains "mise run restore 2>&1" "Action cache: 1 hits, 0 misses, 0 prefetched;" +assert_contains \ + "MISE_TASK_CACHE_STATS_REPORT=cache-stats.json mise run restore 2>&1" \ + "Action cache: 1 hits, 0 misses, 0 prefetched;" +assert \ + "jq -c '{version, hits, misses, compiler_invocations_avoided, restored: (.restored_output_files > 0 and .restored_output_bytes > 0), timed: (.session_duration_ns > 0 and .materialization_duration_ns > 0)}' cache-stats.json" \ + '{"version":1,"hits":1,"misses":0,"compiler_invocations_avoided":1,"restored":true,"timed":true}' diff --git a/schema/mise.json b/schema/mise.json index ac9bc461b98..87dd23276c7 100644 --- a/schema/mise.json +++ b/schema/mise.json @@ -1835,6 +1835,10 @@ "remote_url": { "description": "[experimental] Base URL for the remote build-cache service.", "type": "string" + }, + "stats_report": { + "description": "[experimental] File to write action-cache session statistics to.", + "type": "string" } } }, diff --git a/settings.toml b/settings.toml index 58e7a026402..65a51b44637 100644 --- a/settings.toml +++ b/settings.toml @@ -2812,6 +2812,22 @@ env = "MISE_TASK_CACHE_REMOTE_URL" optional = true type = "Url" +[task.cache.stats_report] +description = "[experimental] File to write action-cache session statistics to." +docs = """ +Write a versioned JSON report describing Rust action-cache activity, transfer volume, restored +outputs, and phase timings. Timing values use nanoseconds. Concurrent phase timings are cumulative +work time and can exceed the end-to-end `session_duration_ns`; `prefetch_duration_ns` is the sum of +wall-clock durations for each task prefetch run. + +This is intended for CI qualification and benchmarking. Relative paths resolve against mise's +working directory. The report is replaced atomically after each `mise run` invocation that creates +an action-cache session. +""" +env = "MISE_TASK_CACHE_STATS_REPORT" +optional = true +type = "Path" + [task.cache_dir] description = "[experimental] Directory for task output cache artifacts." docs = """ diff --git a/src/cache/rustc.rs b/src/cache/rustc.rs index f6be75af8d7..ccb7c24e8e5 100644 --- a/src/cache/rustc.rs +++ b/src/cache/rustc.rs @@ -2,7 +2,7 @@ use super::session; use eyre::{Context, Result, bail}; use mise_cache_core::{ ActionPrediction, AgentRequest, AgentResponse, CacheDigest, CacheDirectory, CacheFileNode, - RemoteActionResult, RustcMetadata, canonical_json, + RemoteActionResult, RestoreStats, RustcMetadata, canonical_json, }; use mise_cache_rustc::{ ActionContext, CompilerIdentity, DiscoveredInputs, PathMapping, RustcAction, RustcDepInfo, @@ -15,12 +15,13 @@ use std::ffi::{OsStr, OsString}; use std::io::{Read as _, Write as _}; use std::path::{Path, PathBuf}; use std::process::{Command, ExitCode, ExitStatus, Output}; -use std::time::SystemTime; +use std::time::{Instant, SystemTime}; struct CachedCompilation { stdout: Vec, stderr: Vec, outputs: Vec, + restore: RestoreStats, } struct CachedOutput { @@ -89,7 +90,7 @@ pub(super) fn compile(rustc: &OsStr, arguments: &[OsString]) -> Result let _ = replay_output(&output); if let Some(cached) = verification { let matched = cached_matches(&cached, &output); - record_verification(matched); + record_verification(matched, cached.restore); if !matched { eprintln!("mise rustc cache warning: shadow verification diverged from cached output"); } @@ -315,6 +316,10 @@ fn restore_result( mode: node.mode, }) .collect(); + let restored_output_files = files.len().try_into().unwrap_or(u64::MAX); + let restored_output_bytes = files.iter().fold(0_u64, |total, (node, _)| { + total.saturating_add(node.digest.size) + }); let mut digests = vec![metadata.stdout.clone(), metadata.stderr.clone()]; digests.extend(files.iter().map(|(node, _)| node.digest.clone())); @@ -322,6 +327,7 @@ fn restore_result( let stdout = read_verified_blob(&blobs[0], &metadata.stdout, "stdout")?; let stderr = read_verified_blob(&blobs[1], &metadata.stderr, "stderr")?; + let materialization_started = Instant::now(); std::fs::create_dir_all(&outputs.directory)?; let staging = tempfile::tempdir_in(&outputs.directory)?; let mut staged = Vec::with_capacity(files.len()); @@ -337,13 +343,23 @@ fn restore_result( discovered.verify()?; verify_environment(&discovered.environment)?; finalize_restored_outputs(staged, restore_outputs)?; + let restore = RestoreStats { + duration_ns: materialization_started + .elapsed() + .as_nanos() + .try_into() + .unwrap_or(u64::MAX), + output_files: restored_output_files, + output_bytes: restored_output_bytes, + }; if restore_outputs { - record_action_hit(&action.digest); + record_action_hit(&action.digest, restore); } Ok(Some(CachedCompilation { stdout, stderr, outputs: cached_outputs, + restore, })) } @@ -394,8 +410,9 @@ fn cached_matches(cached: &CachedCompilation, output: &Output) -> bool { }) } -fn record_verification(matched: bool) { - let responses = session::request_agent(&[AgentRequest::RecordActionVerification { matched }]); +fn record_verification(matched: bool, restore: RestoreStats) { + let responses = + session::request_agent(&[AgentRequest::RecordActionVerification { matched, restore }]); match responses.map(|responses| responses.into_iter().next()) { Ok(Some(AgentResponse::ActionVerificationRecorded)) => {} Ok(Some(AgentResponse::Error { message })) => { @@ -439,9 +456,10 @@ fn persist_outputs(staged: StagedOutputs) -> Result<()> { Ok(()) } -fn record_action_hit(action: &CacheDigest) { +fn record_action_hit(action: &CacheDigest, restore: RestoreStats) { let responses = session::request_agent(&[AgentRequest::RecordActionHit { action: action.clone(), + restore, }]); match responses.map(|responses| responses.into_iter().next()) { Ok(Some(AgentResponse::ActionHitRecorded)) => {} diff --git a/src/cache/session.rs b/src/cache/session.rs index 55913ce80a6..f1081178782 100644 --- a/src/cache/session.rs +++ b/src/cache/session.rs @@ -16,6 +16,7 @@ use std::io::{BufRead, BufReader, Write}; use std::path::{Path, PathBuf}; use std::process::{Command, ExitCode}; use std::sync::Mutex; +use std::time::{Duration, Instant}; use tokio::sync::oneshot; use tokio::task::JoinHandle; @@ -134,6 +135,7 @@ fn task_action_identity(task: &Task) -> String { pub(crate) struct CacheSession { environment: CacheSessionEnvironment, agent: CacheAgent, + started: Instant, shutdown: Mutex>>, server: Mutex>>>, } @@ -158,6 +160,7 @@ impl CacheSession { agent: agent.clone(), }, agent, + started: Instant::now(), shutdown: Mutex::new(Some(shutdown_tx)), server: Mutex::new(Some(server)), }) @@ -176,7 +179,9 @@ impl CacheSession { server.await??; } self.agent.cancel_prefetches().await; - Ok(self.agent.stats()) + let mut stats = self.agent.stats(); + stats.session_duration_ns = duration_ns(self.started.elapsed()); + Ok(stats) } } @@ -229,7 +234,74 @@ impl Drop for CacheSession { } } +#[derive(Serialize)] +struct ActionCacheStatsReport { + version: u8, + session_duration_ns: u64, + lookups: u64, + hits: u64, + misses: u64, + compiler_invocations_avoided: u64, + verifications: u64, + divergences: u64, + prefetched_actions: u64, + prefetch_runs: u64, + downloaded_bytes: u64, + uploaded_bytes: u64, + stored_bytes: u64, + restored_output_files: u64, + restored_output_bytes: u64, + remote_manifest_lookups: u64, + remote_action_lookups: u64, + remote_blob_requests: u64, + remote_manifest_lookup_duration_ns: u64, + remote_action_lookup_duration_ns: u64, + remote_blob_transfer_duration_ns: u64, + local_cas_write_duration_ns: u64, + prefetch_duration_ns: u64, + materialization_duration_ns: u64, +} + +impl From<&AgentStats> for ActionCacheStatsReport { + fn from(stats: &AgentStats) -> Self { + Self { + version: 1, + session_duration_ns: stats.session_duration_ns, + lookups: stats.lookups, + hits: stats.hits, + misses: cache_misses(stats), + compiler_invocations_avoided: stats.hits, + verifications: stats.verifications, + divergences: stats.divergences, + prefetched_actions: stats.prefetched_actions, + prefetch_runs: stats.prefetch_runs, + downloaded_bytes: stats.downloaded_bytes, + uploaded_bytes: stats.uploaded_bytes, + stored_bytes: stats.stored_bytes, + restored_output_files: stats.restored_output_files, + restored_output_bytes: stats.restored_output_bytes, + remote_manifest_lookups: stats.remote_manifest_lookups, + remote_action_lookups: stats.remote_action_lookups, + remote_blob_requests: stats.remote_blob_requests, + remote_manifest_lookup_duration_ns: stats.remote_manifest_lookup_duration_ns, + remote_action_lookup_duration_ns: stats.remote_action_lookup_duration_ns, + remote_blob_transfer_duration_ns: stats.remote_blob_transfer_duration_ns, + local_cas_write_duration_ns: stats.local_cas_write_duration_ns, + prefetch_duration_ns: stats.prefetch_duration_ns, + materialization_duration_ns: stats.materialization_duration_ns, + } + } +} + pub(crate) fn display_stats(stats: AgentStats) { + if let Some(path) = &Settings::get().task.cache.stats_report + && let Err(error) = write_stats_report(path, &stats) + { + warn!( + "action cache could not write its statistics report to {}: {error}", + path.display() + ); + } if stats.lookups == 0 && stats.stores == 0 && stats.verifications == 0 @@ -247,6 +319,18 @@ pub(crate) fn display_stats(stats: AgentStats) { ByteSize::b(stats.uploaded_bytes).display().iec(), ByteSize::b(stats.stored_bytes).display().iec(), ); + let remote_lookup_duration_ns = stats + .remote_manifest_lookup_duration_ns + .saturating_add(stats.remote_action_lookup_duration_ns); + safe_eprintln!( + "Action cache timing: {} session, {} prefetch; cumulative {} remote lookup, {} blob transfer, {} CAS write, {} materialization", + format_duration(stats.session_duration_ns), + format_duration(stats.prefetch_duration_ns), + format_duration(remote_lookup_duration_ns), + format_duration(stats.remote_blob_transfer_duration_ns), + format_duration(stats.local_cas_write_duration_ns), + format_duration(stats.materialization_duration_ns), + ); if stats.verifications > 0 { safe_eprintln!( "Action cache qualification: {} verified, {} diverged", @@ -256,6 +340,26 @@ pub(crate) fn display_stats(stats: AgentStats) { } } +fn write_stats_report(path: &Path, stats: &AgentStats) -> Result<()> { + if let Some(parent) = path + .parent() + .filter(|parent| !parent.as_os_str().is_empty()) + { + crate::file::create_dir_all(parent)?; + } + let mut report = serde_json::to_vec_pretty(&ActionCacheStatsReport::from(stats))?; + report.push(b'\n'); + crate::file::write_atomic(path, report) +} + +fn duration_ns(duration: Duration) -> u64 { + duration.as_nanos().try_into().unwrap_or(u64::MAX) +} + +fn format_duration(nanoseconds: u64) -> String { + crate::ui::time::format_duration(Duration::from_nanos(nanoseconds)) +} + fn cache_misses(stats: &AgentStats) -> u64 { stats .lookups @@ -772,4 +876,39 @@ mod tests { }; assert_eq!(cache_misses(&stats), 1); } + + #[test] + fn writes_versioned_action_cache_stats_report() { + let directory = tempfile::tempdir().unwrap(); + let path = directory.path().join("nested").join("stats.json"); + let stats = AgentStats { + session_duration_ns: 42, + lookups: 5, + hits: 2, + verifications: 1, + prefetched_actions: 3, + downloaded_bytes: 1024, + restored_output_files: 7, + restored_output_bytes: 2048, + remote_blob_requests: 4, + materialization_duration_ns: 9, + ..AgentStats::default() + }; + + write_stats_report(&path, &stats).unwrap(); + let report: serde_json::Value = + serde_json::from_slice(&std::fs::read(path).unwrap()).unwrap(); + + assert_eq!(report["version"], 1); + assert_eq!(report["session_duration_ns"], 42); + assert_eq!(report["hits"], 2); + assert_eq!(report["misses"], 2); + assert_eq!(report["compiler_invocations_avoided"], 2); + assert_eq!(report["prefetched_actions"], 3); + assert_eq!(report["downloaded_bytes"], 1024); + assert_eq!(report["restored_output_files"], 7); + assert_eq!(report["restored_output_bytes"], 2048); + assert_eq!(report["remote_blob_requests"], 4); + assert_eq!(report["materialization_duration_ns"], 9); + } }