From ac6b27b187f8150e6e599a9f51b502255a846704 Mon Sep 17 00:00:00 2001 From: default <216188+jdx@users.noreply.github.com> Date: Sat, 1 Aug 2026 22:14:52 +0000 Subject: [PATCH] feat(task): report task cache statistics --- TASK_CACHE_PARITY.md | 2 +- docs/cli/run.md | 4 ++ docs/cli/tasks/run.md | 4 ++ docs/tasks/task-configuration.md | 6 +++ e2e/tasks/test_task_artifact_cache | 25 ++++++++-- man/man1/mise.1 | 6 +++ mise.usage.kdl | 2 + src/cli/bootstrap.rs | 1 + src/cli/mod.rs | 1 + src/cli/run.rs | 35 +++++++++++++- src/task/task_cache.rs | 76 +++++++++++++++++++++++------- src/task/task_executor.rs | 54 +++++++++++++++++++-- 12 files changed, 190 insertions(+), 26 deletions(-) diff --git a/TASK_CACHE_PARITY.md b/TASK_CACHE_PARITY.md index 232a435525c..4d308009f31 100644 --- a/TASK_CACHE_PARITY.md +++ b/TASK_CACHE_PARITY.md @@ -96,7 +96,7 @@ outside this tracker. - [x] Report the reason for each cache miss - [x] Show resolved cache inputs and outputs - [x] Add machine-readable cache details to dry-run or task-info output -- [ ] Report hit rate, bytes restored, and time saved +- [x] Report hit rate, bytes restored, and time saved - [ ] Add per-task cache inspection and deletion ## Integrity and portability diff --git a/docs/cli/run.md b/docs/cli/run.md index c60b52490e6..dd00b58090d 100644 --- a/docs/cli/run.md +++ b/docs/cli/run.md @@ -213,6 +213,10 @@ Explain the inputs that produced each task's output cache key Output cache-key input details as JSON Lines without running tasks +### `--task-cache-stats` + +Report task output cache hits, restored bytes, and time saved + ### `--timeout ` Timeout for the task to complete diff --git a/docs/cli/tasks/run.md b/docs/cli/tasks/run.md index 262ffb4be85..9bb8a3da174 100644 --- a/docs/cli/tasks/run.md +++ b/docs/cli/tasks/run.md @@ -227,6 +227,10 @@ Explain the inputs that produced each task's output cache key Output cache-key input details as JSON Lines without running tasks +### `--task-cache-stats` + +Report task output cache hits, restored bytes, and time saved + ### `--timeout ` Timeout for the task to complete diff --git a/docs/tasks/task-configuration.md b/docs/tasks/task-configuration.md index ccc063cbbab..1c37b0d4627 100644 --- a/docs/tasks/task-configuration.md +++ b/docs/tasks/task-configuration.md @@ -716,6 +716,12 @@ values. This JSON Lines format remains streamable when a pattern selects multipl command inputs still run so their presence can be reported accurately, but their output and hashes are not included. +Use `mise run --task-cache-stats ` to print a run summary with the number and percentage of +artifact cache hits, the uncompressed output and log bytes restored, and the execution time recorded +when each restored entry was created. Entries written before this metadata was added remain readable +and contribute zero bytes and time when restored. Freshness skips that do not perform a cache lookup +are not counted as hits or misses. + `task_config.global_env` adds ambient variable names to every enabled task cache in the config scope, including tasks with a task-local `cache` value. Unlike the default values under `task_config.cache`, these names always compose with task-local `cache.env`. diff --git a/e2e/tasks/test_task_artifact_cache b/e2e/tasks/test_task_artifact_cache index f8a1b715e5f..67863344635 100644 --- a/e2e/tasks/test_task_artifact_cache +++ b/e2e/tasks/test_task_artifact_cache @@ -21,6 +21,11 @@ outputs = ["dist", "dist/result.txt"] run = "true" sources = ["input.txt"] outputs = [] + +[tasks.fail] +run = "false" +sources = ["input.txt"] +outputs = [] EOF printf 'one\n' >input.txt @@ -64,12 +69,18 @@ assert_fail_contains \ assert "wc -l < runs.txt | tr -d ' '" "1" # Existing fresh outputs use the normal fast freshness path. -assert_contains "PROFILE=debug mise run build 2>&1" "sources up-to-date, skipping" +cache_stats="$(PROFILE=debug mise run --task-cache-stats build 2>&1)" +assert_contains "echo \"$cache_stats\"" "sources up-to-date, skipping" +assert_contains "echo \"$cache_stats\"" "Task cache: no lookups" assert "wc -l < runs.txt | tr -d ' '" "1" # Missing outputs are restored from the local artifact cache without executing. rm -rf dist -assert_contains "PROFILE=debug mise run build 2>&1" "restored outputs from cache" +cache_stats="$(PROFILE=debug mise run --task-cache-stats build 2>&1)" +assert_contains "echo \"$cache_stats\"" "restored outputs from cache" +assert_contains "echo \"$cache_stats\"" "Task cache: 1/1 hits (100%)" +assert_contains "echo \"$cache_stats\"" "10 B restored" +assert_not_contains "echo \"$cache_stats\"" "0ns saved" assert "wc -l < runs.txt | tr -d ' '" "1" assert "cat dist/result.txt" "debug:one" assert_succeed "test -d dist/empty" @@ -77,8 +88,13 @@ assert_succeed "test -d dist/empty" # Clearing the artifact cache invalidates the fast freshness skip even when # outputs remain, so the task executes once to repopulate the cache. mise cache clear -assert_not_contains "PROFILE=debug mise run build 2>&1" "sources up-to-date, skipping" +cache_stats="$(PROFILE=debug mise run --task-cache-stats build 2>&1)" +assert_not_contains "echo \"$cache_stats\"" "sources up-to-date, skipping" +assert_contains "echo \"$cache_stats\"" "Task cache: 0/1 hits (0%), 0 B restored, 0ns saved" assert "wc -l < runs.txt | tr -d ' '" "2" +assert_fail_contains \ + "mise run --task-cache-stats fail 2>&1" \ + "Task cache: 0/1 hits (0%), 0 B restored, 0ns saved" rm -rf dist assert_contains "PROFILE=debug mise run build 2>&1" "restored outputs from cache" assert "wc -l < runs.txt | tr -d ' '" "2" @@ -102,6 +118,9 @@ assert "cat dist/result.txt" "release:two" # Dry runs must not restore outputs or mutate artifact cache state. rm -rf dist +assert_fail_contains \ + "mise run --dry-run --task-cache-stats build 2>&1" \ + "cannot be used with" PROFILE=release mise run --dry-run build assert_fail "test -e dist" assert "wc -l < runs.txt | tr -d ' '" "4" diff --git a/man/man1/mise.1 b/man/man1/mise.1 index 551f6ac1ee0..3eebc04dfd5 100644 --- a/man/man1/mise.1 +++ b/man/man1/mise.1 @@ -3160,6 +3160,9 @@ Explain the inputs that produced each task's output cache key \fB\-\-task\-cache\-explain\-json\fR Output cache\-key input details as JSON Lines without running tasks .TP +\fB\-\-task\-cache\-stats\fR +Report task output cache hits, restored bytes, and time saved +.TP \fB\-\-timeout\fR \fI\fR Timeout for the task to complete e.g.: 30s, 5m @@ -3978,6 +3981,9 @@ Explain the inputs that produced each task's output cache key \fB\-\-task\-cache\-explain\-json\fR Output cache\-key input details as JSON Lines without running tasks .TP +\fB\-\-task\-cache\-stats\fR +Report task output cache hits, restored bytes, and time saved +.TP \fB\-\-timeout\fR \fI\fR Timeout for the task to complete e.g.: 30s, 5m diff --git a/mise.usage.kdl b/mise.usage.kdl index 15854d7fd46..c398a0a6607 100644 --- a/mise.usage.kdl +++ b/mise.usage.kdl @@ -3162,6 +3162,7 @@ Set task output cache access for this run } flag --task-cache-explain help="Explain the inputs that produced each task's output cache key" flag --task-cache-explain-json help="Output cache-key input details as JSON Lines without running tasks" + flag --task-cache-stats help="Report task output cache hits, restored bytes, and time saved" flag --timeout help=#""" Timeout for the task to complete e.g.: 30s, 5m @@ -4014,6 +4015,7 @@ Set task output cache access for this run } flag --task-cache-explain help="Explain the inputs that produced each task's output cache key" flag --task-cache-explain-json help="Output cache-key input details as JSON Lines without running tasks" + flag --task-cache-stats help="Report task output cache hits, restored bytes, and time saved" flag --timeout help=#""" Timeout for the task to complete e.g.: 30s, 5m diff --git a/src/cli/bootstrap.rs b/src/cli/bootstrap.rs index 801cbbff858..0f43926d281 100644 --- a/src/cli/bootstrap.rs +++ b/src/cli/bootstrap.rs @@ -926,6 +926,7 @@ impl Bootstrap { task_cache: crate::task::TaskCacheMode::from_env()?, task_cache_explain: false, task_cache_explain_json: false, + task_cache_stats: false, timeout: None, skip_deps: false, // a dry run must not auto-install tools before the (not actually diff --git a/src/cli/mod.rs b/src/cli/mod.rs index 9cc2afd079e..b8380e1fab6 100644 --- a/src/cli/mod.rs +++ b/src/cli/mod.rs @@ -802,6 +802,7 @@ impl Cli { task_cache: crate::task::TaskCacheMode::from_env()?, task_cache_explain: false, task_cache_explain_json: false, + task_cache_stats: false, timeout: None, skip_deps: false, skip_tools: false, diff --git a/src/cli/run.rs b/src/cli/run.rs index 6ea2b1e6a97..e912568fd8c 100644 --- a/src/cli/run.rs +++ b/src/cli/run.rs @@ -21,6 +21,7 @@ use crate::task::task_output_handler::OutputHandler; use crate::task::{Deps, Task, TaskCacheMode}; use crate::toolset::{InstallOptions, ResolveOptions, ToolVersion, ToolsetBuilder}; use crate::ui::{ctrlc, info, style}; +use bytesize::ByteSize; use clap::{CommandFactory, ValueHint}; use eyre::{Result, bail, eyre}; use futures_util::FutureExt; @@ -266,6 +267,10 @@ pub struct Run { )] pub task_cache_explain_json: bool, + /// Report task output cache hits, restored bytes, and time saved + #[clap(long, conflicts_with = "dry_run", verbatim_doc_comment)] + pub task_cache_stats: bool, + /// Timeout for the task to complete /// e.g.: 30s, 5m #[clap(long, verbatim_doc_comment)] @@ -907,7 +912,11 @@ impl Run { this.timings(), this.is_interrupted(), ); - results_display.display_results(num_tasks, timer)?; + let result = results_display.display_results(num_tasks, timer); + if this.task_cache_stats { + this.display_task_cache_stats(); + } + result?; time!("parallelize_tasks done"); Ok(()) @@ -1316,6 +1325,30 @@ impl Run { !self.quiet(None) && !self.no_timings } + fn display_task_cache_stats(&self) { + let stats = *self + .executor + .as_ref() + .expect("executor must be initialized before displaying cache stats") + .cache_stats + .lock() + .unwrap(); + let lookups = stats.hits.saturating_add(stats.misses); + if lookups == 0 { + safe_eprintln!("Task cache: no lookups"); + return; + } + let hit_rate = stats.hits.saturating_mul(100) / lookups; + safe_eprintln!( + "Task cache: {}/{} hits ({}%), {} restored, {} saved", + stats.hits, + lookups, + hit_rate, + ByteSize::b(stats.restored_bytes).display().iec(), + crate::ui::time::format_duration(stats.time_saved), + ); + } + fn quiet(&self, task: Option<&Task>) -> bool { self.output_handler.as_ref().unwrap().quiet(task) } diff --git a/src/task/task_cache.rs b/src/task/task_cache.rs index 852105d033d..bc0d75e96d5 100644 --- a/src/task/task_cache.rs +++ b/src/task/task_cache.rs @@ -112,6 +112,10 @@ struct CacheManifest { key: String, roots: Vec, output: Vec, + #[serde(default)] + restored_bytes: u64, + #[serde(default)] + execution_duration_ns: u64, } #[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)] @@ -122,10 +126,16 @@ pub(crate) enum TaskCacheOutput { } pub(crate) enum TaskCacheRestore { - Hit(Vec), + Hit(TaskCacheHit), Miss(TaskCacheMissReason), } +pub(crate) struct TaskCacheHit { + pub(crate) output: Vec, + pub(crate) restored_bytes: u64, + pub(crate) saved_duration: std::time::Duration, +} + pub(crate) enum TaskCacheMissReason { CorruptEntry, DependencyWithoutKey, @@ -365,7 +375,7 @@ impl TaskArtifactCache { if !manifest_path.is_file() { return Ok(TaskCacheRestore::Miss(TaskCacheMissReason::EntryNotFound)); } - let restore = || -> Result> { + let restore = || -> Result { let manifest = self.read_manifest()?; for root in &manifest.roots { ensure_safe_relative(root)?; @@ -377,7 +387,11 @@ impl TaskArtifactCache { if let Err(err) = file::touch_file(&manifest_path) { warn!("failed to update task cache manifest access time: {err}"); } - return Ok(manifest.output); + return Ok(TaskCacheHit { + output: manifest.output, + restored_bytes: manifest.restored_bytes, + saved_duration: std::time::Duration::from_nanos(manifest.execution_duration_ns), + }); } // Serialize restores targeting the same working directory across // mise processes so validation and renames form one cooperative @@ -431,7 +445,11 @@ impl TaskArtifactCache { if let Err(err) = file::touch_file(&manifest_path) { warn!("failed to update task cache manifest access time: {err}"); } - Ok(manifest.output) + Ok(TaskCacheHit { + output: manifest.output, + restored_bytes: manifest.restored_bytes, + saved_duration: std::time::Duration::from_nanos(manifest.execution_duration_ns), + }) }; match restore() { @@ -446,7 +464,12 @@ impl TaskArtifactCache { } /// Stores a successful task's declared outputs and captured logs. - pub(crate) fn store(&self, task: &Task, output: &[TaskCacheOutput]) -> Result<()> { + pub(crate) fn store( + &self, + task: &Task, + output: &[TaskCacheOutput], + execution_duration: std::time::Duration, + ) -> Result<()> { let roots = resolve_output_roots(task, &self.root, true)?; let roots = remove_nested_roots(roots); for root in &roots { @@ -463,21 +486,26 @@ impl TaskArtifactCache { .cache_dir .join(format!("{}.part-{nonce}.json", self.key)); + let output_bytes = output.iter().fold(0_u64, |total, line| { + let bytes = match line { + TaskCacheOutput::Stdout(line) | TaskCacheOutput::Stderr(line) => line.len() as u64, + }; + total.saturating_add(bytes) + }); + let archive_bytes = if !roots.is_empty() { + let output_matcher = build_output_matcher(&self.root, &task.outputs.patterns())?; + write_archive(&archive_partial, &self.root, &roots, &output_matcher)? + } else { + 0 + }; let manifest = CacheManifest { format: CACHE_FORMAT_VERSION, key: self.key.clone(), roots, output: output.to_vec(), + restored_bytes: archive_bytes.saturating_add(output_bytes), + execution_duration_ns: execution_duration.as_nanos().min(u64::MAX as u128) as u64, }; - if !manifest.roots.is_empty() { - let output_matcher = build_output_matcher(&self.root, &task.outputs.patterns())?; - write_archive( - &archive_partial, - &self.root, - &manifest.roots, - &output_matcher, - )?; - } fs::write(&manifest_partial, serde_json::to_vec(&manifest)?)?; if !manifest.roots.is_empty() { file::rename(&archive_partial, &archive_path)?; @@ -906,7 +934,7 @@ fn write_archive( root: &Path, roots: &[PathBuf], output_matcher: &Override, -) -> Result<()> { +) -> Result { let file = File::create(path)?; let encoder = zstd::Encoder::new(file, 0)?; let mut archive = Builder::new(encoder); @@ -924,6 +952,7 @@ fn write_archive( } } + let mut restored_bytes = 0_u64; for (rel, abs) in entries { let metadata = fs::symlink_metadata(&abs)?; let mut header = Header::new_gnu(if metadata.file_type().is_symlink() { @@ -951,13 +980,14 @@ fn write_archive( } else if metadata.is_file() { header.set_size(metadata.len()); archive.append_data(&mut header, &rel, File::open(&abs)?)?; + restored_bytes = restored_bytes.saturating_add(metadata.len()); } else { bail!("unsupported output file type: {}", rel.display()); } } let encoder = archive.into_inner()?; encoder.finish()?; - Ok(()) + Ok(restored_bytes) } #[cfg(unix)] @@ -991,6 +1021,20 @@ mod tests { assert!(toml::from_str::("remote = true").is_err()); } + #[test] + fn older_manifests_default_stats_metadata() { + let manifest: CacheManifest = serde_json::from_value(serde_json::json!({ + "format": 2, + "key": "cache-key", + "roots": [], + "output": [], + })) + .unwrap(); + + assert_eq!(manifest.restored_bytes, 0); + assert_eq!(manifest.execution_duration_ns, 0); + } + #[test] fn cache_explanation_omits_environment_and_variable_values() { let explanation = TaskCacheKeyExplanation { diff --git a/src/task/task_executor.rs b/src/task/task_executor.rs index 1fb1199a671..210c188417a 100644 --- a/src/task/task_executor.rs +++ b/src/task/task_executor.rs @@ -222,6 +222,7 @@ pub struct TaskExecutor { pub context_builder: TaskContextBuilder, pub output_handler: OutputHandler, pub failed_tasks: FailedTasks, + pub(crate) cache_stats: Arc>, interrupted: AtomicBool, // CLI flags @@ -245,6 +246,26 @@ pub struct TaskRunOutcome { pub cache_key: Option, } +#[derive(Debug, Clone, Copy, Default, PartialEq, Eq)] +pub(crate) struct TaskCacheStats { + pub(crate) hits: u64, + pub(crate) misses: u64, + pub(crate) restored_bytes: u64, + pub(crate) time_saved: Duration, +} + +impl TaskCacheStats { + fn record_hit(&mut self, restored_bytes: u64, time_saved: Duration) { + self.hits = self.hits.saturating_add(1); + self.restored_bytes = self.restored_bytes.saturating_add(restored_bytes); + self.time_saved = self.time_saved.saturating_add(time_saved); + } + + fn record_miss(&mut self) { + self.misses = self.misses.saturating_add(1); + } +} + impl TaskExecutor { pub fn new( context_builder: TaskContextBuilder, @@ -255,6 +276,7 @@ impl TaskExecutor { context_builder, output_handler, failed_tasks: Arc::new(StdMutex::new(Vec::new())), + cache_stats: Arc::new(StdMutex::new(TaskCacheStats::default())), interrupted: AtomicBool::new(false), force: config.force, cd: config.cd, @@ -699,7 +721,11 @@ impl TaskExecutor { } else { Self::check_interruption(allow_during_interruption)?; match cache.restore(task)? { - TaskCacheRestore::Hit(output) => { + TaskCacheRestore::Hit(hit) => { + self.cache_stats + .lock() + .unwrap() + .record_hit(hit.restored_bytes, hit.saved_duration); if !self.quiet(Some(task)) { let kind = if task.outputs.is_no_files() { "result" @@ -712,8 +738,11 @@ impl TaskExecutor { &format!("restored {kind} from cache {}", cache.key()), ); } - self.output_handler - .replay_cached_output(task, &prefix, &output); + self.output_handler.replay_cached_output( + task, + &prefix, + &hit.output, + ); if let Err(err) = save_checksum(task, config).await { warn!( "task {} artifact cache checksum update failed: {err}", @@ -736,6 +765,7 @@ impl TaskExecutor { TaskCacheRestore::Miss(reason) => reason, } }; + self.cache_stats.lock().unwrap().record_miss(); if !self.quiet(Some(task)) { self.eprint(task, &prefix, &format!("cache miss: {miss_reason}")); } @@ -809,13 +839,14 @@ impl TaskExecutor { ); } + let execution_duration = timer.elapsed(); if self.task_timings(Some(task)) && (task.file.as_ref().is_some() || !task.run_script_strings().is_empty()) { self.eprint( task, &prefix, - &format!("Finished in {}", time::format_duration(timer.elapsed())), + &format!("Finished in {}", time::format_duration(execution_duration)), ); } @@ -827,7 +858,7 @@ impl TaskExecutor { .as_ref() .map(|output| output.lock().unwrap().clone()) .unwrap_or_default(); - match cache.store(task, &output) { + match cache.store(task, &output, execution_duration) { Ok(()) => { if let Err(err) = cache.mark_current() { warn!( @@ -2052,6 +2083,19 @@ fn shell_from_shebang(path: &Path) -> Option> { mod tests { use super::*; + #[test] + fn task_cache_stats_saturate_and_accumulate() { + let mut stats = TaskCacheStats::default(); + stats.record_miss(); + stats.record_hit(512, Duration::from_millis(25)); + stats.record_hit(256, Duration::from_millis(15)); + + assert_eq!(stats.hits, 2); + assert_eq!(stats.misses, 1); + assert_eq!(stats.restored_bytes, 768); + assert_eq!(stats.time_saved, Duration::from_millis(40)); + } + fn env_with_path(path: &str) -> BTreeMap { let mut env = BTreeMap::new(); env.insert((*crate::env::PATH_KEY).to_string(), path.to_string());