From 3dfac3a35206a51de41dd26f20655aad18a89e74 Mon Sep 17 00:00:00 2001 From: Will Date: Thu, 15 Oct 2026 13:45:23 -0700 Subject: [PATCH 1/8] Per-worker time tracking and the run report MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Every run now returns a RunReport (daisy.last_report(), Server.last_report, daisy_run_report on partial-run errors) with one TaskReport per task: block aggregates as mean ± std (wall, CPU, peak RSS, IO, overhead, trend) and a workers section with startup / idle / compute / teardown per task and per worker. Worker phases are stamped by the server from the lifecycle events it already handles (spawn, first acquire, each dispatch and return, the shutdown reply, the spawn thread's exit), so there is no protocol change; collection is always on and O(workers) in memory. With resource_tracking=True the tracking group gains worker_id, sent_at and returned_at arrays and a runs.jsonl with the report appended once per run. TaskReport.block(...) reads one block back through Task.block_record. Removed: Server.last_tracking_summary and the {"per_task": ...} dict; daisy_run_stats on the KeyboardInterrupt / abandonment errors. Co-Authored-By: Claude Fable 5.1 --- CHANGELOG.md | 23 ++ MIGRATION.md | 3 +- daisy-core/src/block_bookkeeper.rs | 15 +- daisy-core/src/block_tracking.rs | 268 ++++++++++++-- daisy-core/src/lib.rs | 2 + daisy-core/src/run_report.rs | 147 ++++++++ daisy-core/src/run_stats.rs | 220 +++++++++++ daisy-core/src/scheduler.rs | 46 ++- daisy-core/src/serial.rs | 29 +- daisy-core/src/server.rs | 121 ++++-- daisy-core/src/worker_timeline.rs | 549 +++++++++++++++++++++++++++ daisy-py/python/daisy/__init__.py | 6 + daisy-py/python/daisy/_daisy.pyi | 8 +- daisy-py/python/daisy/_progress.py | 117 ++---- daisy-py/python/daisy/_report.py | 575 +++++++++++++++++++++++++++++ daisy-py/python/daisy/_runner.py | 44 ++- daisy-py/python/daisy/v1_compat.py | 6 + daisy-py/python/daisy/v2.py | 4 + daisy-py/src/py_server.rs | 68 ++-- daisy-py/src/py_task.rs | 97 +++-- docs/source/api.md | 27 ++ docs/source/design/DONE_MARKERS.md | 13 +- docs/source/design/RUN_STATS.md | 128 +++++-- tests/test_block_profiling.py | 30 +- tests/test_run_stats.py | 217 ++++++++--- tests/test_worker_timeline.py | 267 ++++++++++++++ 26 files changed, 2675 insertions(+), 355 deletions(-) create mode 100644 daisy-core/src/run_report.rs create mode 100644 daisy-core/src/worker_timeline.rs create mode 100644 daisy-py/python/daisy/_report.py create mode 100644 tests/test_worker_timeline.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 0d684948..b726f192 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -65,6 +65,29 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added +- **Per-worker time tracking and the run report.** Every run now returns a + `daisy.RunReport` (`daisy.last_report()`, `Server.last_report`, and + `daisy_run_report` on the `KeyboardInterrupt` / abandonment error) with + one `TaskReport` per task: `blocks` (count, failures, and `mean ± std` + for wall, CPU, peak RSS, IO, plus the per-block `overhead` — server round + trip minus the worker's own wall time — and the wall-time trend) and + `workers` (count, `startup`, `idle`, `compute`, `teardown` as + distributions, exit kinds, and a row per worker under `by_id`). + `TaskReport.worker(id)` and `TaskReport.block(block | grid coord | id)` + drill down; the latter reads the tracking store (`Task.block_record`). + Worker timing is stamped by the server from the lifecycle events it + already sees — spawn, first acquire, each dispatch and return, the + shutdown reply, the spawn thread's exit — so it needs no protocol change, + is always collected (O(workers) memory), and covers startup and teardown, + which a worker cannot report about itself. The "Resource Utilization" + panel now prints `± ` figures, the worker line and a per-worker table + (ten rows, then a pointer) for tasks with `resource_tracking=True`. + With `resource_tracking=True` the tracking store gains `worker_id`, + `sent_at` and `returned_at` arrays (who ran each block and when, scheduler + clock) and a `runs.jsonl` with the task's report appended once per run. + **Removed**: `Server.last_tracking_summary` and the `{"per_task": {...}}` + dict it held; `daisy_run_stats` on the partial-run errors (now + `daisy_run_report`). - `Task(skip_mask=...)`: a caller-provided mask over the block grid (a uint8 or bool array at `Task.block_grid_shape`, nonzero = skip). Masked blocks are reported as skipped and release their downstream dependencies, diff --git a/MIGRATION.md b/MIGRATION.md index 1d49733b..dfdb0cf6 100644 --- a/MIGRATION.md +++ b/MIGRATION.md @@ -45,7 +45,8 @@ A few things v2 added that have no 1.x equivalent: - **Block tracking as a built-in** (`Task(tracking_path=…)` or via `set_tracking_basedir(…)`; `done_marker_path` / `set_done_marker_basedir` are deprecated aliases). A per-task Zarr v3 group recording which blocks completed (used to skip already-done work on resume) and how many times each failed. `Task.reset()` clears it for an explicit re-run. Tracking is **opt-in**: without an explicit path or a basedir set, nothing is tracked or skipped. The recommended pattern is one `set_tracking_basedir("")` call at pipeline start. Note that tracking is keyed by task_id + block geometry, *not* by your code — rerunning changed code against existing tracking resumes silently, so use distinct task_ids per pipeline version or `Task.reset()` after code changes. It is also bound to the exact task layout: changing any ROI (including growing `total_roi` for a dataset that acquired more data) invalidates it entirely; in-place migration for grown volumes is a planned enhancement (see `docs/source/design/DONE_MARKERS.md`). - **Skip masks** (`Task(skip_mask=…)`): a uint8 or bool array with one cell per block (`Task.block_grid_shape`; cell `(0, 0, …)` is the first block), nonzero = skip. Masked blocks count as skipped and release their dependents, but are not recorded as done, so the mask is a per-run input: a later run with a different mask (or none) runs them. Composes with tracking: done blocks stay done, masked blocks stay undone. Use it for blocks you know carry no work (far from a predicted surface, outside an acquired region) instead of a `check_function`, which runs a Python callable per block and cannot be seeded ahead of a run. -- **Per-block resource tracking** (`Task(resource_tracking=True)`, needs a tracking path). Each block reports its wall time, CPU time, peak RSS and IO bytes, measured inside whoever ran it — so thread, subprocess and external cluster workers all report the same numbers. Values land in the tracking group as sibling arrays indexed the same way as `done`, readable with plain `zarr.open_group(...)`, and the run prints an agglomerated **Resource Utilization** summary. daisy measures the whole block body automatically; `with daisy.profile_block(block):` narrows the scope if you want to exclude your own setup. Programmatic access: `daisy.Server().last_tracking_summary`. 1.x had no equivalent. +- **Per-block resource tracking** (`Task(resource_tracking=True)`, needs a tracking path). Each block reports its wall time, CPU time, peak RSS and IO bytes, measured inside whoever ran it — so thread, subprocess and external cluster workers all report the same numbers. Values land in the tracking group as sibling arrays indexed the same way as `done`, readable with plain `zarr.open_group(...)`, and the run prints an agglomerated **Resource Utilization** summary. daisy measures the whole block body automatically; `with daisy.profile_block(block):` narrows the scope if you want to exclude your own setup. Programmatic access: `daisy.last_report()` (a `RunReport` with `mean ± std` per metric). 1.x had no equivalent. +- **Per-worker time tracking** (always on). The scheduler stamps every worker's lifecycle — spawn → first acquire (**startup**, including cluster queue time), the gap before each block (**idle**), each round trip (**compute**), and shutdown reply → exit (**teardown**) — and the run report carries them per task (`report.tasks[t].workers`, distributions over workers and blocks) and per worker (`.workers.by_id[i]`, or `.worker(i)`). Shown in the Resource Utilization panel for tasks with `resource_tracking=True`, which also persists `worker_id` / `sent_at` / `returned_at` per block in the tracking group and appends the report to `runs.jsonl` there. `report.tasks[t].block(block)` reads one block's record back. 1.x had no equivalent. - **`block_tracking` flag on `run_blockwise`** to disable done-marker tracking entirely for a run. - **`JsonProgressObserver`** — line-delimited JSON progress events, useful for piping into log aggregators or external dashboards. - **Per-task resource budgets** (`requires` per task + global `resources` dict) — coordinate worker concurrency across tasks competing for shared resources (CPU, GPU, etc.). diff --git a/daisy-core/src/block_bookkeeper.rs b/daisy-core/src/block_bookkeeper.rs index a043a816..7e50a9af 100644 --- a/daisy-core/src/block_bookkeeper.rs +++ b/daisy-core/src/block_bookkeeper.rs @@ -43,6 +43,7 @@ impl BlockBookkeeper { client_addr: SocketAddr, timeout: Option, worker_id: Option, + sent_at: Instant, ) { debug!(block_id = %block.block_id, %client_addr, "block sent to client"); self.sent_blocks.insert( @@ -50,26 +51,26 @@ impl BlockBookkeeper { BlockLog { block, client_addr, - time_sent: Instant::now(), + time_sent: sent_at, timeout, worker_id, }, ); } - /// Record that a block was returned by a client. Returns the time - /// the block spent in the worker (`Instant::now() - time_sent`) - /// when the return is valid, otherwise `None`. + /// Record that a block was returned by a client. Returns the instant + /// the block was sent and the id of the worker that held it when the + /// return is valid, otherwise `None`. pub fn notify_block_returned( &mut self, block: &Block, client_addr: SocketAddr, - ) -> Option { + ) -> Option<(Instant, Option)> { if let Some(log) = self.sent_blocks.get(&block.block_id) { if log.client_addr == client_addr { - let elapsed = log.time_sent.elapsed(); + let sent = (log.time_sent, log.worker_id); self.sent_blocks.remove(&block.block_id); - return Some(elapsed); + return Some(sent); } debug!( block_id = %block.block_id, diff --git a/daisy-core/src/block_tracking.rs b/daisy-core/src/block_tracking.rs index e3a073b5..27bcb6ac 100644 --- a/daisy-core/src/block_tracking.rs +++ b/daisy-core/src/block_tracking.rs @@ -16,9 +16,19 @@ //! io_read_bytes/ uint64 | //! io_write_bytes/ uint64 | //! gpu_util_pct/ float32 | reserved (NaN) -//! gpu_mem_bytes/ uint64 / reserved (0) +//! gpu_mem_bytes/ uint64 | reserved (0) +//! worker_id/ uint32 | worker that completed the block (u32::MAX = none) +//! sent_at/ float64 | dispatch time, seconds since the UNIX epoch +//! returned_at/ float64 / return time, seconds since the UNIX epoch +//! runs.jsonl one JSON line per run: the task's run report //! ``` //! +//! `worker_id`, `sent_at` and `returned_at` are stamped by the server, so a +//! full per-worker timeline (who ran what, when, with what gaps) can be +//! reconstructed from the store after the fact. Worker ids restart at 0 +//! every run, so the value is "the worker, in the run that completed this +//! block". `runs.jsonl` is append-only and ignored by zarr readers. +//! //! Each array's layout is what `zarr.create(..., codecs=[BytesCodec()])` //! emits in zarr-python 3, so the whole group opens in any zarr v3 reader //! (`zarr.open_group(...)`, napari, neuroglancer) for inspection while a run @@ -52,15 +62,16 @@ //! ## This is the only place that counts blocks //! //! The tracking object also carries the run's *running aggregates* — blocks -//! recorded, Σcpu, Σio, max peak-RSS, and the per-block wall times used for -//! the end-of-run trend fit. The end-of-run summary is an agglomeration of -//! exactly what was written here, so there is one counter in the codebase -//! rather than a scheduler count and a stats count that can disagree. +//! recorded and one `Welford` (mean / std / min / max / sum) per resource +//! metric, plus the running slope of per-block wall time. The end-of-run +//! report is an agglomeration of exactly what was written here, so there is +//! one counter in the codebase rather than a scheduler count and a stats +//! count that can disagree. use crate::block::Block; use crate::block_profile::BlockStats; use crate::roi::Roi; -use crate::run_stats::linear_trend; +use crate::run_stats::{Trend, Welford}; use crate::task::Fit; use memmap2::MmapMut; use serde_json::json; @@ -115,6 +126,7 @@ enum Dtype { U32, U64, F32, + F64, } impl Dtype { @@ -124,6 +136,7 @@ impl Dtype { Dtype::U32 => 4, Dtype::U64 => 8, Dtype::F32 => 4, + Dtype::F64 => 8, } } @@ -133,6 +146,7 @@ impl Dtype { Dtype::U32 => "uint32", Dtype::U64 => "uint64", Dtype::F32 => "float32", + Dtype::F64 => "float64", } } } @@ -148,6 +162,15 @@ pub const ARRAY_IO_READ: &str = "io_read_bytes"; pub const ARRAY_IO_WRITE: &str = "io_write_bytes"; pub const ARRAY_GPU_UTIL: &str = "gpu_util_pct"; pub const ARRAY_GPU_MEM: &str = "gpu_mem_bytes"; +pub const ARRAY_WORKER_ID: &str = "worker_id"; +pub const ARRAY_SENT_AT: &str = "sent_at"; +pub const ARRAY_RETURNED_AT: &str = "returned_at"; + +/// `worker_id` value for a block no managed worker completed. +pub const NO_WORKER: u32 = u32::MAX; + +/// Per-run report lines, appended at the end of every run. +pub const RUNS_FILE: &str = "runs.jsonl"; /// Arrays present whenever tracking is on at all. const BASE_ARRAYS: &[(&str, Dtype)] = &[(ARRAY_DONE, Dtype::U8), (ARRAY_FAILURES, Dtype::U32)]; @@ -161,8 +184,33 @@ const STAT_ARRAYS: &[(&str, Dtype)] = &[ (ARRAY_IO_WRITE, Dtype::U64), (ARRAY_GPU_UTIL, Dtype::F32), (ARRAY_GPU_MEM, Dtype::U64), + (ARRAY_WORKER_ID, Dtype::U32), + (ARRAY_SENT_AT, Dtype::F64), + (ARRAY_RETURNED_AT, Dtype::F64), ]; +/// Who ran a block and when, as the server saw it. Rides with the block +/// into `record` and lands in the `worker_id` / `sent_at` / `returned_at` +/// arrays. Times are seconds since the UNIX epoch on the server clock. +#[derive(Clone, Copy, Debug, Default, PartialEq)] +pub struct BlockDispatch { + pub worker_id: Option, + pub sent_at: f64, + pub returned_at: f64, +} + +/// Everything the store holds for one block (diagnostics / `Task.block_record`). +#[derive(Clone, Debug, Default, PartialEq)] +pub struct BlockRecord { + pub done: bool, + pub failures: u32, + /// `None` when the store has no stat arrays. + pub stats: Option, + /// `None` when the store has no stat arrays or the block has no + /// recorded dispatch. + pub dispatch: Option, +} + /// Hash a task's layout into a stable hex string. Anything that changes /// the block grid (total/read/write ROIs, fit mode) must change this. pub fn compute_task_hash(total_roi: &Roi, read_roi: &Roi, write_roi: &Roi, fit: &Fit) -> String { @@ -263,20 +311,22 @@ pub struct TaskSummary { pub failures_recorded: u64, /// True once any recorded block carried resource stats. pub has_stats: bool, - pub total_cpu_seconds: f64, - pub total_wall_seconds: f64, - pub max_peak_rss_bytes: u64, - pub total_io_read_bytes: u64, - pub total_io_write_bytes: u64, - /// Per-block wall times in milliseconds, in completion order, for the - /// mean/slope trend fit. - pub block_ms: Vec, + /// Seconds in the block, per block. + pub wall: Welford, + /// CPU seconds, per block. + pub cpu: Welford, + /// Peak RSS bytes, per block. + pub peak_rss: Welford, + pub io_read: Welford, + pub io_write: Welford, + /// Per-block wall time in milliseconds against completion order. + pub wall_trend: Trend, } impl TaskSummary { /// Mean and slope of per-block wall time in milliseconds. pub fn block_ms_trend(&self) -> (f64, f64) { - linear_trend(&self.block_ms) + (self.wall_trend.mean(), self.wall_trend.slope()) } } @@ -433,8 +483,9 @@ impl TaskTracking { } /// Record a completed block: mark it done, persist any resource stats - /// it carried, and fold both into this run's aggregates. - pub fn record(&mut self, block: &Block) { + /// it carried and the dispatch the server stamped, and fold the stats + /// into this run's aggregates. + pub fn record(&mut self, block: &Block, dispatch: Option<&BlockDispatch>) { let Some(idx) = self.index_of(block) else { // Not addressable (boundary block); still counts as work done // so the summary's block count matches the scheduler's. @@ -450,6 +501,66 @@ impl TaskTracking { self.write_stats(idx, stats); self.fold_stats(stats); } + if let Some(d) = dispatch { + self.write_dispatch(idx, d); + } + } + + /// Append one line to the store's `runs.jsonl`: the task's report for + /// a run that just ended. + pub fn append_run_record(&self, json_line: &str) -> io::Result<()> { + let mut f = OpenOptions::new() + .create(true) + .append(true) + .open(self.path.join(RUNS_FILE))?; + f.write_all(json_line.as_bytes())?; + f.write_all(b"\n")?; + Ok(()) + } + + /// Everything recorded for one block (diagnostics / `Task.block_record`). + pub fn record_of(&self, block: &Block) -> Option { + let idx = self.index_of(block)?; + let done = self + .arrays + .get(ARRAY_DONE) + .map(|m| m[idx] != 0) + .unwrap_or(false); + let failures = self + .arrays + .get(ARRAY_FAILURES) + .map(|m| read_u32(m, idx)) + .unwrap_or(0); + Some(BlockRecord { + done, + failures, + stats: self.stats_of(block), + dispatch: self.dispatch_of(block), + }) + } + + /// The dispatch stamped for a block, if the stat arrays exist and the + /// block was ever recorded with one. + pub fn dispatch_of(&self, block: &Block) -> Option { + if !self.with_stats { + return None; + } + let idx = self.index_of(block)?; + let sent_at = self.read_f64(ARRAY_SENT_AT, idx); + let returned_at = self.read_f64(ARRAY_RETURNED_AT, idx); + if sent_at == 0.0 && returned_at == 0.0 { + return None; + } + let wid = self + .arrays + .get(ARRAY_WORKER_ID) + .map(|m| read_u32(m, idx)) + .unwrap_or(NO_WORKER); + Some(BlockDispatch { + worker_id: (wid != NO_WORKER).then_some(wid as u64), + sent_at, + returned_at, + }) } /// Note one failed attempt for this block (a worker-reported failure @@ -522,21 +633,45 @@ impl TaskTracking { } } + fn write_dispatch(&mut self, idx: usize, d: &BlockDispatch) { + if !self.with_stats { + return; + } + let wid = d + .worker_id + .and_then(|w| u32::try_from(w).ok()) + .filter(|w| *w != NO_WORKER) + .unwrap_or(NO_WORKER); + if let Some(m) = self.arrays.get_mut(ARRAY_WORKER_ID) { + write_u32(m, idx, wid); + } + if let Some(m) = self.arrays.get_mut(ARRAY_SENT_AT) { + write_f64(m, idx, d.sent_at); + } + if let Some(m) = self.arrays.get_mut(ARRAY_RETURNED_AT) { + write_f64(m, idx, d.returned_at); + } + } + fn fold_stats(&mut self, stats: &BlockStats) { let s = &mut self.summary; s.has_stats = true; - s.total_cpu_seconds += stats.cpu_seconds; - s.total_wall_seconds += stats.wall_seconds; - s.max_peak_rss_bytes = s.max_peak_rss_bytes.max(stats.peak_rss_bytes); - s.total_io_read_bytes = s.total_io_read_bytes.saturating_add(stats.io_read_bytes); - s.total_io_write_bytes = s.total_io_write_bytes.saturating_add(stats.io_write_bytes); - s.block_ms.push(stats.wall_seconds * 1000.0); + s.wall.push(stats.wall_seconds); + s.cpu.push(stats.cpu_seconds); + s.peak_rss.push(stats.peak_rss_bytes as f64); + s.io_read.push(stats.io_read_bytes as f64); + s.io_write.push(stats.io_write_bytes as f64); + s.wall_trend.push(stats.wall_seconds * 1000.0); } fn read_f32(&self, name: &'static str, idx: usize) -> f32 { self.arrays.get(name).map(|m| read_f32(m, idx)).unwrap_or(0.0) } + fn read_f64(&self, name: &'static str, idx: usize) -> f64 { + self.arrays.get(name).map(|m| read_f64(m, idx)).unwrap_or(0.0) + } + fn read_u64(&self, name: &'static str, idx: usize) -> u64 { self.arrays.get(name).map(|m| read_u64(m, idx)).unwrap_or(0) } @@ -607,6 +742,18 @@ fn write_f32(m: &mut MmapMut, idx: usize, v: f32) { m[o..o + 4].copy_from_slice(&v.to_le_bytes()); } +fn read_f64(m: &MmapMut, idx: usize) -> f64 { + let o = idx * 8; + let mut buf = [0u8; 8]; + buf.copy_from_slice(&m[o..o + 8]); + f64::from_le_bytes(buf) +} + +fn write_f64(m: &mut MmapMut, idx: usize, v: f64) { + let o = idx * 8; + m[o..o + 8].copy_from_slice(&v.to_le_bytes()); +} + fn write_json(path: &Path, value: &serde_json::Value) -> io::Result<()> { let mut f = OpenOptions::new() .create(true) @@ -641,7 +788,7 @@ fn open_or_create_array( let n_bytes = n_cells * dtype.width(); let shape_json: Vec = grid_shape.iter().map(|&v| v as u64).collect(); let fill: serde_json::Value = match dtype { - Dtype::F32 => json!(0.0), + Dtype::F32 | Dtype::F64 => json!(0.0), _ => json!(0), }; let layout = json!({ @@ -1042,17 +1189,22 @@ mod tests { gpu_util_pct: f32::NAN, gpu_mem_bytes: 0, }); - m.record(&b); + let dispatch = BlockDispatch { + worker_id: Some(3), + sent_at: 1_700_000_000.25, + returned_at: 1_700_000_000.75, + }; + m.record(&b, Some(&dispatch)); let summary = m.summary(); assert_eq!(summary.blocks_recorded, 1); assert!(summary.has_stats); - assert!((summary.total_cpu_seconds - 0.25).abs() < 1e-6); - assert_eq!(summary.max_peak_rss_bytes, 4096); - assert_eq!(summary.total_io_read_bytes, 128); - assert_eq!(summary.total_io_write_bytes, 256); - assert_eq!(summary.block_ms.len(), 1); - assert!((summary.block_ms[0] - 500.0).abs() < 1e-3); + assert!((summary.cpu.sum() - 0.25).abs() < 1e-6); + assert_eq!(summary.peak_rss.max(), 4096.0); + assert_eq!(summary.io_read.sum(), 128.0); + assert_eq!(summary.io_write.sum(), 256.0); + assert_eq!(summary.wall.n(), 1); + assert!((summary.wall_trend.mean() - 500.0).abs() < 1e-3); drop(m); let m2 = open(&dir, &total, &block_shape, true); @@ -1064,6 +1216,52 @@ mod tests { assert_eq!(back.io_write_bytes, 256); assert!(back.gpu_util_pct.is_nan(), "gpu slot should stay NaN"); assert!(m2.is_done(&b), "record must also mark done"); + assert_eq!(m2.dispatch_of(&b), Some(dispatch)); + let rec = m2.record_of(&b).unwrap(); + assert!(rec.done); + assert_eq!(rec.failures, 0); + assert_eq!(rec.dispatch, Some(dispatch)); + assert!(rec.stats.is_some()); + + // A block never dispatched reads back without one. + let other = block_at(&total, &[30], &[10]); + assert_eq!(m2.dispatch_of(&other), None); + assert_eq!(m2.record_of(&other).unwrap().done, false); + } + + #[test] + fn dispatch_without_a_managed_worker_reads_back_as_none_worker() { + let dir = tempdir(); + let total = make_roi(&[0], &[100]); + let block_shape = make_roi(&[0], &[10]); + let mut m = open(&dir, &total, &block_shape, true); + let b = block_at(&total, &[0], &[10]); + m.record( + &b, + Some(&BlockDispatch { + worker_id: None, + sent_at: 1.0, + returned_at: 2.0, + }), + ); + let d = m.dispatch_of(&b).unwrap(); + assert_eq!(d.worker_id, None); + assert_eq!((d.sent_at, d.returned_at), (1.0, 2.0)); + } + + #[test] + fn run_records_append_one_line_each() { + let dir = tempdir(); + let total = make_roi(&[0], &[100]); + let block_shape = make_roi(&[0], &[10]); + let m = open(&dir, &total, &block_shape, false); + m.append_run_record("{\"run\": 1}").unwrap(); + m.append_run_record("{\"run\": 2}").unwrap(); + let text = std::fs::read_to_string(dir.join(RUNS_FILE)).unwrap(); + assert_eq!(text, "{\"run\": 1}\n{\"run\": 2}\n"); + // Still a valid group: the stray file does not disturb reopening. + drop(m); + let _ = open(&dir, &total, &block_shape, false); } #[test] @@ -1075,10 +1273,12 @@ mod tests { let mut b = block_at(&total, &[20], &[10]); b.stats = Some(BlockStats::default()); - m.record(&b); + m.record(&b, Some(&BlockDispatch::default())); assert!(!m.with_stats()); assert!(m.stats_of(&b).is_none()); + assert!(m.dispatch_of(&b).is_none()); + assert!(!dir.join("worker_id").exists()); assert!(dir.join("done").is_dir()); assert!(dir.join("failures").is_dir()); assert!(!dir.join("cpu_seconds").exists()); @@ -1101,7 +1301,7 @@ mod tests { wall_seconds: ms / 1000.0, ..BlockStats::default() }); - m.record(&b); + m.record(&b, None); } let (mean, slope) = m.summary().block_ms_trend(); assert!((mean - 20.0).abs() < 1e-3, "mean={mean}"); @@ -1127,6 +1327,8 @@ mod tests { (ARRAY_FAILURES, "uint32"), (ARRAY_CPU_SECONDS, "float32"), (ARRAY_PEAK_RSS, "uint64"), + (ARRAY_WORKER_ID, "uint32"), + (ARRAY_SENT_AT, "float64"), ] { let meta: serde_json::Value = serde_json::from_slice(&std::fs::read(dir.join(name).join("zarr.json")).unwrap()) diff --git a/daisy-core/src/lib.rs b/daisy-core/src/lib.rs index bdb6f9fc..3e06942e 100644 --- a/daisy-core/src/lib.rs +++ b/daisy-core/src/lib.rs @@ -14,6 +14,7 @@ pub mod protocol; pub mod ready_surface; pub mod resource_allocator; pub mod roi; +pub mod run_report; pub mod run_stats; pub mod scheduler; pub mod serial; @@ -23,6 +24,7 @@ pub mod task; pub mod task_state; pub mod worker_context; pub mod worker_pool; +pub mod worker_timeline; pub use block::{Block, BlockStatus}; pub use client::Client; diff --git a/daisy-core/src/run_report.rs b/daisy-core/src/run_report.rs new file mode 100644 index 00000000..760aaba5 --- /dev/null +++ b/daisy-core/src/run_report.rs @@ -0,0 +1,147 @@ +//! The per-task run report: block aggregates from the tracking layer plus +//! the worker timeline, one `TaskReport` per task in the pipeline. +//! +//! This is what a run returns, what the end-of-run panel renders, and +//! (serialized as one JSON line) what is appended to the task's +//! `runs.jsonl`. Every figure is a fold over events the scheduler already +//! counts — there is no second block counter. + +use std::collections::HashMap; + +use serde::Serialize; + +use crate::block_tracking::TaskSummary; +use crate::run_stats::Welford; +use crate::task_state::TaskCounters; +use crate::worker_timeline::{RunTimeline, WorkerReport}; + +/// Per-block aggregates for one task over this run. +#[derive(Clone, Debug, Default, Serialize)] +pub struct BlockReport { + /// Blocks completed this run (from the tracking layer when the task + /// has a store, else the scheduler's completed count). + pub count: u64, + /// Failed attempts this run. + pub failures: u64, + /// True once any block carried resource measurements. + pub has_stats: bool, + pub wall: Welford, + pub cpu: Welford, + pub peak_rss: Welford, + pub io_read: Welford, + pub io_write: Welford, + /// Server round trip minus the worker's `wall_seconds`, per measured + /// block: daisy's own per-block cost. + pub overhead: Welford, + /// Least-squares slope of per-block wall time, ms per block in + /// completion order. + pub trend_slope_ms: f64, +} + +impl BlockReport { + fn from_summary(s: &TaskSummary, overhead: Welford) -> Self { + Self { + count: s.blocks_recorded, + failures: s.failures_recorded, + has_stats: s.has_stats, + wall: s.wall.clone(), + cpu: s.cpu.clone(), + peak_rss: s.peak_rss.clone(), + io_read: s.io_read.clone(), + io_write: s.io_write.clone(), + overhead, + trend_slope_ms: s.wall_trend.slope(), + } + } +} + +#[derive(Clone, Debug, Serialize)] +pub struct TaskReport { + pub task_id: String, + /// Run start, seconds since the UNIX epoch (server clock). + pub started_at: f64, + /// Report build time, seconds since the UNIX epoch. + pub finished_at: f64, + /// Whether the task had a tracking store this run (and therefore a + /// `runs.jsonl` line). + pub tracked: bool, + pub blocks: BlockReport, + pub workers: WorkerReport, +} + +impl TaskReport { + pub fn to_json(&self) -> String { + serde_json::to_string(self).unwrap_or_else(|_| "{}".to_string()) + } +} + +/// Build one report per task. `summaries` covers tasks with a tracking +/// store; the rest get their block count from the counters and no +/// resource figures. +pub fn build_reports( + counters: &HashMap, + summaries: &HashMap, + timeline: &RunTimeline, +) -> HashMap { + let finished_at = timeline.epoch_seconds(std::time::Instant::now()); + counters + .iter() + .map(|(task_id, c)| { + let overhead = timeline.overhead(task_id); + let (tracked, blocks) = match summaries.get(task_id) { + Some(s) => (true, BlockReport::from_summary(s, overhead)), + None => ( + false, + BlockReport { + count: c.completed_count.max(0) as u64, + overhead, + ..BlockReport::default() + }, + ), + }; + let report = TaskReport { + task_id: task_id.clone(), + started_at: timeline.started_at(), + finished_at, + tracked, + blocks, + workers: timeline.report_for(task_id), + }; + (task_id.clone(), report) + }) + .collect() +} + +/// Serialize a map of reports to JSON (`{task_id: report}`), the form the +/// Python layer consumes. +pub fn reports_to_json(reports: &HashMap) -> String { + serde_json::to_string(reports).unwrap_or_else(|_| "{}".to_string()) +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn untracked_task_reports_its_counters_and_no_stats() { + let mut counters = HashMap::new(); + counters.insert( + "t".to_string(), + TaskCounters { + completed_count: 7, + ..TaskCounters::default() + }, + ); + let timeline = RunTimeline::new(); + let reports = build_reports(&counters, &HashMap::new(), &timeline); + let r = &reports["t"]; + assert!(!r.tracked); + assert_eq!(r.blocks.count, 7); + assert!(!r.blocks.has_stats); + assert_eq!(r.workers.count, 0); + let json: serde_json::Value = serde_json::from_str(&r.to_json()).unwrap(); + assert_eq!(json["blocks"]["count"], 7); + assert_eq!(json["workers"]["exits"]["clean"], 0); + assert!(json["blocks"]["wall"]["std"].is_number()); + } +} diff --git a/daisy-core/src/run_stats.rs b/daisy-core/src/run_stats.rs index 426f294c..189c8a00 100644 --- a/daisy-core/src/run_stats.rs +++ b/daisy-core/src/run_stats.rs @@ -7,6 +7,8 @@ //! //! - `thread_cpu_time` — per-OS-thread CPU accounting, so concurrent //! thread workers don't contaminate each other's numbers. +//! - `Welford` / `Trend` — the O(1)-memory accumulators behind every +//! `x ± y` figure and the per-block wall-time slope in the run report. //! - `linear_trend` — the least-squares fit behind "blocks started at 2 ms //! and ended at 12 ms", applied to the per-block wall times collected by //! `block_tracking::TaskSummary`. @@ -184,3 +186,221 @@ mod tests { } } } + +/// Running mean / sample standard deviation / min / max / sum, by +/// Welford's method. One of these backs every `x ± y` figure in the run +/// report, so the report costs O(1) memory per metric however many blocks +/// or workers feed it. +#[derive(Clone, Debug, Default, PartialEq)] +pub struct Welford { + n: u64, + mean: f64, + m2: f64, + min: f64, + max: f64, + sum: f64, +} + +impl Welford { + pub fn push(&mut self, x: f64) { + if !x.is_finite() { + return; + } + if self.n == 0 { + self.min = x; + self.max = x; + } else { + self.min = self.min.min(x); + self.max = self.max.max(x); + } + self.n += 1; + self.sum += x; + let delta = x - self.mean; + self.mean += delta / self.n as f64; + self.m2 += delta * (x - self.mean); + } + + pub fn n(&self) -> u64 { + self.n + } + + pub fn is_empty(&self) -> bool { + self.n == 0 + } + + pub fn mean(&self) -> f64 { + self.mean + } + + /// Sample standard deviation; 0 for fewer than two samples. + pub fn std(&self) -> f64 { + if self.n < 2 { + 0.0 + } else { + (self.m2 / (self.n - 1) as f64).sqrt() + } + } + + pub fn min(&self) -> f64 { + self.min + } + + pub fn max(&self) -> f64 { + self.max + } + + pub fn sum(&self) -> f64 { + self.sum + } + + /// Fold another accumulator into this one (Chan et al.), so per-worker + /// samples can be pooled into a per-task figure without re-walking them. + pub fn merge(&mut self, other: &Welford) { + if other.n == 0 { + return; + } + if self.n == 0 { + *self = other.clone(); + return; + } + let n = (self.n + other.n) as f64; + let delta = other.mean - self.mean; + self.mean += delta * other.n as f64 / n; + self.m2 += other.m2 + delta * delta * self.n as f64 * other.n as f64 / n; + self.min = self.min.min(other.min); + self.max = self.max.max(other.max); + self.sum += other.sum; + self.n += other.n; + } +} + +impl serde::Serialize for Welford { + fn serialize(&self, s: S) -> Result { + use serde::ser::SerializeStruct; + let mut st = s.serialize_struct("Welford", 6)?; + st.serialize_field("n", &self.n)?; + st.serialize_field("mean", &self.mean)?; + st.serialize_field("std", &self.std())?; + st.serialize_field("min", &self.min)?; + st.serialize_field("max", &self.max)?; + st.serialize_field("sum", &self.sum)?; + st.end() + } +} + +/// Running least-squares slope of y against sample index, equivalent to +/// `linear_trend` over the full series but in O(1) memory. +#[derive(Clone, Debug, Default, PartialEq)] +pub struct Trend { + n: u64, + sum_x: f64, + sum_y: f64, + sum_xy: f64, + sum_xx: f64, +} + +impl Trend { + pub fn push(&mut self, y: f64) { + if !y.is_finite() { + return; + } + let x = self.n as f64; + self.n += 1; + self.sum_x += x; + self.sum_y += y; + self.sum_xy += x * y; + self.sum_xx += x * x; + } + + pub fn n(&self) -> u64 { + self.n + } + + pub fn mean(&self) -> f64 { + if self.n == 0 { + 0.0 + } else { + self.sum_y / self.n as f64 + } + } + + /// Slope per sample; 0 for fewer than two samples. + pub fn slope(&self) -> f64 { + if self.n < 2 { + return 0.0; + } + let n = self.n as f64; + let den = n * self.sum_xx - self.sum_x * self.sum_x; + if den == 0.0 { + 0.0 + } else { + (n * self.sum_xy - self.sum_x * self.sum_y) / den + } + } +} + +#[cfg(test)] +mod accumulator_tests { + use super::*; + + #[test] + fn welford_matches_hand_computed_moments() { + let mut w = Welford::default(); + for x in [2.0, 4.0, 4.0, 4.0, 5.0, 5.0, 7.0, 9.0] { + w.push(x); + } + assert_eq!(w.n(), 8); + assert!((w.mean() - 5.0).abs() < 1e-12); + // Sample std of that series is sqrt(32/7). + assert!((w.std() - (32.0f64 / 7.0).sqrt()).abs() < 1e-12, "{}", w.std()); + assert_eq!(w.min(), 2.0); + assert_eq!(w.max(), 9.0); + assert_eq!(w.sum(), 40.0); + } + + #[test] + fn welford_handles_short_inputs_and_non_finite() { + let mut w = Welford::default(); + assert_eq!(w.std(), 0.0); + w.push(f64::NAN); + assert!(w.is_empty()); + w.push(3.0); + assert_eq!(w.std(), 0.0); + assert_eq!(w.mean(), 3.0); + } + + #[test] + fn welford_merge_equals_pushing_everything_into_one() { + let xs: Vec = (0..50).map(|i| (i as f64 * 0.37).sin() * 10.0).collect(); + let mut all = Welford::default(); + let mut a = Welford::default(); + let mut b = Welford::default(); + for (i, &x) in xs.iter().enumerate() { + all.push(x); + if i % 3 == 0 { + a.push(x); + } else { + b.push(x); + } + } + a.merge(&b); + assert_eq!(a.n(), all.n()); + assert!((a.mean() - all.mean()).abs() < 1e-9); + assert!((a.std() - all.std()).abs() < 1e-9); + assert_eq!(a.min(), all.min()); + assert_eq!(a.max(), all.max()); + } + + #[test] + fn trend_matches_linear_trend() { + let y: Vec = (0..40).map(|i| 3.0 + 0.25 * i as f64 + ((i * 7) % 5) as f64).collect(); + let mut t = Trend::default(); + for &v in &y { + t.push(v); + } + let (mean, slope) = linear_trend(&y); + assert!((t.mean() - mean).abs() < 1e-9); + assert!((t.slope() - slope).abs() < 1e-9, "{} vs {}", t.slope(), slope); + assert_eq!(Trend::default().slope(), 0.0); + } +} diff --git a/daisy-core/src/scheduler.rs b/daisy-core/src/scheduler.rs index b4d3d670..576ce2fe 100644 --- a/daisy-core/src/scheduler.rs +++ b/daisy-core/src/scheduler.rs @@ -1,6 +1,7 @@ use crate::block::{Block, BlockStatus}; use crate::dependency_graph::DependencyGraph; -use crate::block_tracking::{TaskSummary, TaskTracking}; +use crate::block_tracking::{BlockDispatch, TaskSummary, TaskTracking}; +use crate::run_report::TaskReport; use crate::error::DaisyError; use crate::processing_queue::ProcessingQueue; use crate::ready_surface::ReadySurface; @@ -210,6 +211,25 @@ impl Scheduler { .collect() } + /// Append each tracked task's report to its store's `runs.jsonl`. + /// Tasks without a store are skipped; a write failure is logged, not + /// raised — the report itself is still returned to the caller. + pub fn append_run_records(&self, reports: &HashMap) { + for (task_id, tracking) in &self.task_tracking { + let Some(report) = reports.get(task_id) else { + continue; + }; + if let Err(e) = tracking.append_run_record(&report.to_json()) { + warn!( + task_id = %task_id, + path = %tracking.path().display(), + error = %e, + "could not append the run report to runs.jsonl", + ); + } + } + } + /// Whether any task expects blocks to come back carrying resource /// stats — used to police workers that return unmeasured blocks. pub fn expects_block_stats(&self, task_id: &str) -> bool { @@ -285,7 +305,7 @@ impl Scheduler { // be recorded as done: the mask is an input to this run, // not persisted state. Done-marker and check-function // skips are recorded as before. - self.release_block_impl(block, skip == Precheck::SkipDone); + self.release_block_impl(block, skip == Precheck::SkipDone, None); continue; } @@ -304,12 +324,28 @@ impl Scheduler { /// run loop uses for opportunistic rebalancing. The caller still /// inspects `task_states` directly when it needs more. pub fn release_block(&mut self, block: Block) -> Vec { - self.release_block_impl(block, true) + self.release_block_impl(block, true, None) + } + + /// `release_block` carrying the server's dispatch stamp (who ran the + /// block, when it was sent and returned), persisted next to the + /// block's resource stats. + pub fn release_block_with( + &mut self, + block: Block, + dispatch: Option, + ) -> Vec { + self.release_block_impl(block, true, dispatch) } /// `release_block` with control over whether a successful block is /// recorded in the tracking store (`false` only for skip-mask skips). - fn release_block_impl(&mut self, block: Block, record_done: bool) -> Vec { + fn release_block_impl( + &mut self, + block: Block, + record_done: bool, + dispatch: Option, + ) -> Vec { let task_id = block.task_id().to_string(); // Strip from in-flight tracking unconditionally — even for @@ -340,7 +376,7 @@ impl Scheduler { if let Some(tracking) = self.task_tracking.get_mut(&task_id) { // Records done + any resource stats the block carried, // and folds both into this run's aggregates. - tracking.record(&block); + tracking.record(&block, dispatch.as_ref()); } } let newly_ready = self.update_ready_queue(new_blocks); diff --git a/daisy-core/src/serial.rs b/daisy-core/src/serial.rs index 3b2f22ac..87cfa753 100644 --- a/daisy-core/src/serial.rs +++ b/daisy-core/src/serial.rs @@ -1,6 +1,7 @@ use crate::block::BlockStatus; use crate::block_profile::BlockProfiler; -use crate::block_tracking::TaskSummary; +use crate::run_report::{build_reports, TaskReport}; +use crate::worker_timeline::RunTimeline; use crate::error::DaisyError; use crate::scheduler::Scheduler; use crate::task::Task; @@ -25,7 +26,7 @@ impl SerialRunner { pub fn run( pipeline: &crate::pipeline::Pipeline, block_tracking: bool, - ) -> Result<(HashMap, HashMap), DaisyError> { + ) -> Result<(HashMap, HashMap), DaisyError> { crate::scheduler::validate_pipeline(pipeline)?; let mut scheduler = Scheduler::new(pipeline, true); if block_tracking { @@ -119,13 +120,17 @@ impl SerialRunner { } } + // Serial mode has no workers, so the report's worker section is + // empty; blocks are measured the same way as everywhere else. let summaries = scheduler.tracking_summaries(); - let counters = scheduler + let counters: HashMap = scheduler .task_states - .into_iter() - .map(|(k, v)| (k, v.counters())) + .iter() + .map(|(k, v)| (k.clone(), v.counters())) .collect(); - Ok((counters, summaries)) + let reports = build_reports(&counters, &summaries, &RunTimeline::new()); + scheduler.append_run_records(&reports); + Ok((counters, reports)) } } @@ -173,9 +178,15 @@ mod tests { ); let pipeline = crate::pipeline::Pipeline::from_task(task.clone()); - let (states, summaries) = SerialRunner::run(&pipeline, true).unwrap(); - // No tracking_path configured, so nothing to summarise. - assert!(summaries.is_empty()); + let (states, reports) = SerialRunner::run(&pipeline, true).unwrap(); + // No tracking_path configured: the report still exists (every task + // gets one), with the scheduler's count, no resource figures and + // no workers. + let report = &reports["test"]; + assert!(!report.tracked); + assert!(!report.blocks.has_stats); + assert_eq!(report.blocks.count, 4); + assert_eq!(report.workers.count, 0); let state = &states["test"]; assert!(state.balanced()); assert_eq!(state.total_block_count, 4); diff --git a/daisy-core/src/server.rs b/daisy-core/src/server.rs index 6449571b..77e9704d 100644 --- a/daisy-core/src/server.rs +++ b/daisy-core/src/server.rs @@ -2,16 +2,19 @@ use crate::block::BlockStatus; use crate::block_bookkeeper::BlockBookkeeper; use crate::protocol::{read_message, write_message, Message}; use crate::resource_allocator::{ResourceAllocator, ResourceBudget}; -use crate::block_tracking::TaskSummary; +use crate::block_tracking::BlockDispatch; +use crate::run_report::{build_reports, TaskReport}; use crate::scheduler::Scheduler; use crate::task::Task; use crate::task_state::{AbandonReason, TaskCounters, TaskState}; use crate::worker_context::encode_value; use crate::worker_pool::WorkerPool; +use crate::worker_timeline::{RunTimeline, WorkerExitKind}; use std::collections::{HashMap, VecDeque}; use std::net::SocketAddr; use std::sync::Arc; use std::thread::JoinHandle; +use std::time::Instant; use tokio::net::tcp::OwnedWriteHalf; use tokio::net::TcpListener; use tokio::sync::mpsc; @@ -60,9 +63,12 @@ struct ClientMessage { #[derive(Debug, Default)] struct WorkerExit { task_id: String, - #[allow(dead_code)] worker_id: u64, last_error: Option, + /// Stamped by the spawn thread as it returns, so the worker timeline's + /// teardown does not include however long the main loop took to + /// notice. + exited_at: Option, } pub struct Server { @@ -71,11 +77,11 @@ pub struct Server { } /// Payload of the `Interrupted` error `run_blockwise` returns when the run -/// was aborted (SIGINT): the task counters and tracking summaries at the -/// moment of shutdown, so a partial summary can still be printed. +/// was aborted (SIGINT): the task counters and run reports at the moment +/// of shutdown, so a partial summary can still be printed. pub struct AbortedRun { pub states: HashMap, - pub summaries: HashMap, + pub reports: HashMap, } impl std::fmt::Debug for AbortedRun { @@ -191,7 +197,7 @@ impl Server { progress: Option>, abort_check: Option bool + Send + Sync>>, block_tracking: bool, - ) -> std::io::Result<(HashMap, HashMap)> { + ) -> std::io::Result<(HashMap, HashMap)> { if let Err(e) = crate::scheduler::validate_pipeline(pipeline) { return Err(std::io::Error::new(std::io::ErrorKind::InvalidInput, e.to_string())); } @@ -282,6 +288,9 @@ impl Server { } let mut workers: Vec = Vec::new(); let mut registry = WorkerRegistry::default(); + // Per-worker lifecycle stamps (startup / idle / compute / teardown) + // and per-block dispatch stamps, all taken here in the main loop. + let mut timeline = RunTimeline::new(); let mut next_worker_id: u64 = 0; // Channel each worker thread signals on just before it exits, so // the main loop can rebalance immediately rather than waiting for @@ -308,6 +317,7 @@ impl Server { &mut workers, &mut next_worker_id, &worker_exit_tx, + &mut timeline, ); self.recruit_workers(&scheduler, worker_pools)?; @@ -340,7 +350,7 @@ impl Server { Some(cm) = msg_rx.recv() => { let updated = match self.handle_message( cm, &mut scheduler, &mut bookkeeper, &mut registry, - &mut pending, worker_pools, + &mut pending, worker_pools, &mut timeline, ) { Ok(updated) => updated, Err(e) => { @@ -374,11 +384,15 @@ impl Server { &mut workers, &mut next_worker_id, &worker_exit_tx, + &mut timeline, ); } } Some(exit) = worker_exit_rx.recv() => { + if let Some(at) = exit.exited_at { + timeline.note_exit_time(exit.worker_id, at); + } // A worker thread just signalled it's exiting. Attach // its error (if any) to the task state so abandonment // can report the cause, then reap the thread (frees @@ -393,7 +407,7 @@ impl Server { } } Self::check_thread_health( - &mut workers, &mut scheduler, &mut allocator, &mut registry, + &mut workers, &mut scheduler, &mut allocator, &mut registry, &mut timeline, ); Self::rebalance_workers( &self.host, @@ -404,6 +418,7 @@ impl Server { &mut workers, &mut next_worker_id, &worker_exit_tx, + &mut timeline, ); Self::abandon_exhausted_tasks(tasks, &mut scheduler, &allocator); } @@ -439,7 +454,7 @@ impl Server { // remote job system. if let Some(wid) = holder { Self::retire_worker_slot( - &mut workers, &mut allocator, wid, + &mut workers, &mut allocator, &mut timeline, wid, ); } } @@ -461,7 +476,7 @@ impl Server { // worker that died without sending a notification // (e.g. a panic that didn't unwind through `Drop`). Self::check_thread_health( - &mut workers, &mut scheduler, &mut allocator, &mut registry, + &mut workers, &mut scheduler, &mut allocator, &mut registry, &mut timeline, ); Self::rebalance_workers( &self.host, @@ -472,6 +487,7 @@ impl Server { &mut workers, &mut next_worker_id, &worker_exit_tx, + &mut timeline, ); Self::abandon_exhausted_tasks(tasks, &mut scheduler, &allocator); @@ -480,7 +496,7 @@ impl Server { if !pending.is_empty() { self.retry_pending( &mut scheduler, &mut bookkeeper, &mut registry, - &mut pending, worker_pools, + &mut pending, worker_pools, &mut timeline, )?; } } @@ -505,14 +521,21 @@ impl Server { } else { info!("all tasks completed"); } + timeline.shutdown_started(); // Shutdown. for cm in pending.drain(..) { + if let Message::AcquireBlock { worker_id: Some(wid), .. } = &cm.message { + timeline.shutdown_sent(*wid); + } let _ = cm.reply_tx.try_send(Message::RequestShutdown); } msg_rx.close(); while let Ok(cm) = msg_rx.try_recv() { - if let Message::AcquireBlock { .. } = &cm.message { + if let Message::AcquireBlock { worker_id, .. } = &cm.message { + if let Some(wid) = worker_id { + timeline.shutdown_sent(*wid); + } let _ = cm.reply_tx.try_send(Message::RequestShutdown); } } @@ -528,7 +551,11 @@ impl Server { if let WorkerThread::Running(handle) = std::mem::replace(&mut entry.thread, WorkerThread::Finished) { - let _ = handle.join(); + let kind = match handle.join() { + Ok(true) => WorkerExitKind::Clean, + Ok(false) | Err(_) => WorkerExitKind::Error, + }; + timeline.exited(entry.spec.worker_id, kind); } } // Drain any worker-exit notifications still in flight, so a @@ -543,9 +570,15 @@ impl Server { } } - // The summary is an agglomeration of what the tracking layer - // actually wrote — no separate accumulator to disagree with it. + // Workers still open at this point were cut off by the abort. + timeline.close_remaining(WorkerExitKind::Interrupted); + // The report is an agglomeration of what the tracking layer + // actually wrote plus the lifecycle stamps taken above — no + // separate accumulator to disagree with either. let summaries = scheduler.tracking_summaries(); + let counters = snapshot_counters(&scheduler.task_states); + let reports = build_reports(&counters, &summaries, &timeline); + scheduler.append_run_records(&reports); if let Some(ref obs) = progress { if progress_dirty { obs.on_progress(&snapshot_counters(&scheduler.task_states)); @@ -561,12 +594,12 @@ impl Server { return Err(std::io::Error::new( std::io::ErrorKind::Interrupted, AbortedRun { - states: snapshot_counters(&scheduler.task_states), - summaries, + states: counters, + reports, }, )); } - Ok((snapshot_counters(&scheduler.task_states), summaries)) + Ok((counters, reports)) } /// Spawn a worker for a task. Every worker is a spawn function: the @@ -603,6 +636,7 @@ impl Server { } impl Drop for ExitNotifier { fn drop(&mut self) { + self.exit.exited_at = Some(Instant::now()); let _ = self.tx.send(std::mem::take(&mut self.exit)); } } @@ -613,6 +647,7 @@ impl Server { task_id: task_id.clone(), worker_id, last_error: None, + exited_at: None, }, }; @@ -672,6 +707,7 @@ impl Server { scheduler: &mut Scheduler, allocator: &mut ResourceAllocator, registry: &mut WorkerRegistry, + timeline: &mut RunTimeline, ) { for entry in workers.iter_mut() { let spec = &entry.spec; @@ -683,6 +719,7 @@ impl Server { registry.exited.insert(spec.worker_id); match handle.join() { Ok(true) => { + timeline.exited(spec.worker_id, WorkerExitKind::Clean); debug!( worker_id = spec.worker_id, task_id = %spec.task_id, @@ -720,6 +757,7 @@ impl Server { } } Ok(false) | Err(_) => { + timeline.exited(spec.worker_id, WorkerExitKind::Error); warn!( worker_id = spec.worker_id, task_id = %spec.task_id, @@ -759,6 +797,7 @@ impl Server { fn retire_worker_slot( workers: &mut [WorkerEntry], allocator: &mut ResourceAllocator, + timeline: &mut RunTimeline, worker_id: u64, ) { for entry in workers.iter_mut() { @@ -777,6 +816,7 @@ impl Server { ); allocator.release(&entry.spec.task); entry.slot_retired = true; + timeline.exited(worker_id, WorkerExitKind::Timeout); return; } } @@ -903,6 +943,7 @@ impl Server { workers: &mut Vec, next_id: &mut u64, exit_tx: &mpsc::UnboundedSender, + timeline: &mut RunTimeline, ) { // Round-robin grow: at each pass, give *one* more worker to // every eligible task. Repeat until no task can grow. This @@ -984,6 +1025,7 @@ impl Server { port, }; let handle = Self::spawn_worker(&spec, exit_tx.clone()); + timeline.spawned(spec.worker_id, &spec.task_id); workers.push(WorkerEntry { spec, thread: WorkerThread::Running(handle), @@ -1013,12 +1055,13 @@ impl Server { registry: &mut WorkerRegistry, pending: &mut VecDeque, worker_pools: &mut HashMap, + timeline: &mut RunTimeline, ) -> std::io::Result<()> { let count = pending.len(); for _ in 0..count { if let Some(cm) = pending.pop_front() { let _ = self.handle_message( - cm, scheduler, bookkeeper, registry, pending, worker_pools, + cm, scheduler, bookkeeper, registry, pending, worker_pools, timeline, )?; } } @@ -1039,11 +1082,12 @@ impl Server { registry: &mut WorkerRegistry, pending: &mut VecDeque, worker_pools: &mut HashMap, + timeline: &mut RunTimeline, ) -> std::io::Result> { let mut updated: Vec = Vec::new(); match cm.message { Message::AcquireBlock { .. } => { - self.handle_acquire(cm, scheduler, bookkeeper, registry, pending, worker_pools)?; + self.handle_acquire(cm, scheduler, bookkeeper, registry, pending, worker_pools, timeline)?; } Message::ReleaseBlock { block } => { if bookkeeper.is_valid_return(&block, cm.addr) { @@ -1051,7 +1095,22 @@ impl Server { // deadline; per-block *durations* now come from the // worker's own measurement on `block.stats`, which is // the same number in every execution mode. - let _ = bookkeeper.notify_block_returned(&block, cm.addr); + let dispatch = bookkeeper + .notify_block_returned(&block, cm.addr) + .map(|(sent_at, wid)| { + let returned_at = timeline.block_returned( + wid, + block.task_id(), + sent_at, + true, + block.stats.map(|st| st.wall_seconds), + ); + BlockDispatch { + worker_id: wid, + sent_at: timeline.epoch_seconds(sent_at), + returned_at: timeline.epoch_seconds(returned_at), + } + }); if scheduler.expects_block_stats(block.task_id()) && block.stats.is_none() { return Err(std::io::Error::new( std::io::ErrorKind::InvalidData, @@ -1067,11 +1126,11 @@ impl Server { ), )); } - updated = scheduler.release_block(block); + updated = scheduler.release_block_with(block, dispatch); self.recruit_workers(scheduler, worker_pools)?; if !pending.is_empty() { self.retry_pending( - scheduler, bookkeeper, registry, pending, worker_pools, + scheduler, bookkeeper, registry, pending, worker_pools, timeline, )?; } } else { @@ -1089,13 +1148,17 @@ impl Server { // A failed block's measurement is not folded into the // trend (noisy outlier), but the failure itself is // counted by the scheduler's release path. - let _ = bookkeeper.notify_block_returned(&block, cm.addr); + if let Some((sent_at, wid)) = + bookkeeper.notify_block_returned(&block, cm.addr) + { + timeline.block_returned(wid, block.task_id(), sent_at, false, None); + } block.status = BlockStatus::Failed; updated = scheduler.release_block(block); self.recruit_workers(scheduler, worker_pools)?; if !pending.is_empty() { self.retry_pending( - scheduler, bookkeeper, registry, pending, worker_pools, + scheduler, bookkeeper, registry, pending, worker_pools, timeline, )?; } } @@ -1119,6 +1182,7 @@ impl Server { registry: &mut WorkerRegistry, pending: &mut VecDeque, worker_pools: &mut HashMap, + timeline: &mut RunTimeline, ) -> std::io::Result<()> { let (task_id, worker_id) = match &cm.message { Message::AcquireBlock { task_id, worker_id } => (task_id.clone(), *worker_id), @@ -1152,6 +1216,7 @@ impl Server { )); } registry.connected.insert(wid); + timeline.acquired(wid); } match scheduler.acquire_block(&task_id) { @@ -1161,7 +1226,8 @@ impl Server { .task_map .get(&task_id) .and_then(|t| t.timeout); - bookkeeper.notify_block_sent(block.clone(), cm.addr, timeout, worker_id); + let sent_at = timeline.block_sent(worker_id, &task_id, cm.addr); + bookkeeper.notify_block_sent(block.clone(), cm.addr, timeout, worker_id, sent_at); let _ = cm.reply_tx.try_send(Message::SendBlock { block, timeout_secs: timeout.map(|d| d.as_secs_f64()), @@ -1183,6 +1249,9 @@ impl Server { let terminal = !scheduler.task_states[&task_id].is_running(); if terminal || counters.pending_count() <= 0 { debug!(task_id = %task_id, "no more blocks"); + if let Some(wid) = worker_id { + timeline.shutdown_sent(wid); + } let _ = cm.reply_tx.try_send(Message::RequestShutdown); self.recruit_workers(scheduler, worker_pools)?; } else { diff --git a/daisy-core/src/worker_timeline.rs b/daisy-core/src/worker_timeline.rs new file mode 100644 index 00000000..0b3e82ae --- /dev/null +++ b/daisy-core/src/worker_timeline.rs @@ -0,0 +1,549 @@ +//! Per-worker lifecycle timing, observed from the server. +//! +//! Every worker-lifecycle event already crosses the server's main loop with +//! the worker's server-assigned id attached — the spawn call, the first +//! `AcquireBlock`, every `SendBlock`, every `ReleaseBlock`/`BlockFailed`, +//! the `RequestShutdown` reply, and the spawn thread's return. Stamping +//! those events is enough to split a worker's life into four phases: +//! +//! ```text +//! spawn ──startup──▶ connect ──idle──▶ block ──compute──▶ return ──idle──▶ block … ──final wait──▶ shutdown ──teardown──▶ exit +//! ``` +//! +//! - **startup**: spawn call → first `AcquireBlock`. Process launch, +//! imports, the user's own setup (model loading), the TCP connect — and, +//! for a cluster spawn function (`sbatch --wait`, `srun`), the queue wait. +//! - **idle**: returning one block → being handed the next (for the first +//! block: connect → first block). Waiting on the scheduler, which includes +//! dependency gating and read/write conflicts. +//! - **compute**: block handed out → block returned. The server round trip, +//! so it includes transport and the worker's own per-block wrapper; the +//! block's `wall_seconds` is the worker's narrower measurement of the +//! user function, and the difference is reported as `overhead`. +//! - **teardown**: `RequestShutdown` sent → spawn call returned. A worker +//! whose last acquire reached the server after the run had ended never +//! gets a reply (it sees the socket close instead); for it teardown is +//! counted from the moment the server began shutting down. +//! - **final wait**: last return → `RequestShutdown`; kept per worker but +//! not an "idle before a block", so it stays out of the idle aggregate. +//! +//! The server is the only vantage point that can see startup and teardown +//! at all (a worker cannot report time before its interpreter started or +//! after its process exited), and timing here needs no wire change: the +//! protocol is untouched. The cost is one network hop inside idle and +//! compute. Clients that connect without a server-assigned id (hand-rolled +//! workers outside daisy's management) are counted, not timed. +//! +//! Collection is always on: a handful of `Instant`s per worker, two +//! `Welford` accumulators per worker, O(workers) memory in total. + +use std::collections::{BTreeMap, HashMap, HashSet}; +use std::net::SocketAddr; +use std::time::{Instant, SystemTime, UNIX_EPOCH}; + +use serde::Serialize; + +use crate::run_stats::Welford; + +/// How a worker's life ended. +#[derive(Clone, Copy, Debug, PartialEq, Eq, Serialize)] +#[serde(rename_all = "lowercase")] +pub enum WorkerExitKind { + /// Spawn function returned cleanly. + Clean, + /// Spawn function returned an error, or its thread panicked. + Error, + /// Its block exceeded the task timeout and the slot was retired. + Timeout, + /// Still alive when the run was aborted. + Interrupted, +} + +/// One worker's stamped lifecycle. All arithmetic is on `Instant`s; the +/// `now` is passed in so the transitions are unit-testable. +#[derive(Clone, Debug)] +pub struct WorkerTimeline { + pub worker_id: u64, + pub task_id: String, + spawned_at: Instant, + connected_at: Option, + last_return_at: Option, + in_flight: Option, + shutdown_sent_at: Option, + exited_at: Option, + exit: Option, + blocks_ok: u64, + blocks_failed: u64, + idle: Welford, + compute: Welford, + final_wait: Option, +} + +impl WorkerTimeline { + pub fn new(worker_id: u64, task_id: &str, now: Instant) -> Self { + Self { + worker_id, + task_id: task_id.to_string(), + spawned_at: now, + connected_at: None, + last_return_at: None, + in_flight: None, + shutdown_sent_at: None, + exited_at: None, + exit: None, + blocks_ok: 0, + blocks_failed: 0, + idle: Welford::default(), + compute: Welford::default(), + final_wait: None, + } + } + + /// First (and every) `AcquireBlock`; only the first one is a stamp. + pub fn acquired(&mut self, now: Instant) { + if self.connected_at.is_none() { + self.connected_at = Some(now); + } + } + + /// A block was handed to this worker: close the idle gap since the + /// previous return (or since connecting). + pub fn block_sent(&mut self, now: Instant) { + let since = self.last_return_at.or(self.connected_at); + if let Some(t) = since { + self.idle.push(now.duration_since(t).as_secs_f64()); + } + self.in_flight = Some(now); + } + + /// The block came back (ok or failed); `sent_at` is the bookkeeper's + /// send stamp for that block. Returns the round-trip seconds. + pub fn block_returned(&mut self, now: Instant, sent_at: Instant, ok: bool) -> f64 { + let elapsed = now.duration_since(sent_at).as_secs_f64(); + self.compute.push(elapsed); + if ok { + self.blocks_ok += 1; + } else { + self.blocks_failed += 1; + } + self.in_flight = None; + self.last_return_at = Some(now); + elapsed + } + + pub fn shutdown_sent(&mut self, now: Instant) { + if self.shutdown_sent_at.is_some() { + return; + } + self.shutdown_sent_at = Some(now); + if let Some(t) = self.last_return_at.or(self.connected_at) { + self.final_wait = Some(now.duration_since(t).as_secs_f64()); + } + } + + /// The first exit wins: a timeout-retired worker that later exits on + /// its own keeps `Timeout`. + pub fn exited(&mut self, now: Instant, kind: WorkerExitKind) { + if self.exit.is_some() { + return; + } + self.exit = Some(kind); + self.exited_at = Some(now); + } + + pub fn has_exited(&self) -> bool { + self.exit.is_some() + } + + pub fn startup(&self) -> Option { + self.connected_at + .map(|c| c.duration_since(self.spawned_at).as_secs_f64()) + } + + /// `run_shutdown` is when the server began shutting down, the fallback + /// start of teardown for a clean exit that never received + /// `RequestShutdown` (its last acquire lost the end-of-run race). + pub fn teardown(&self, run_shutdown: Option) -> Option { + if self.exit != Some(WorkerExitKind::Clean) { + return None; + } + let exited = self.exited_at?; + let from = match self.shutdown_sent_at { + Some(s) => s, + None => run_shutdown.filter(|s| *s <= exited)?, + }; + Some(exited.saturating_duration_since(from).as_secs_f64()) + } + + pub fn record(&self, run_shutdown: Option) -> WorkerRecord { + WorkerRecord { + worker_id: self.worker_id, + startup: self.startup(), + blocks_ok: self.blocks_ok, + blocks_failed: self.blocks_failed, + idle: self.idle.clone(), + compute: self.compute.clone(), + final_wait: self.final_wait, + teardown: self.teardown(run_shutdown), + exit: self.exit, + } + } +} + +/// One worker's row in the report. +#[derive(Clone, Debug, Serialize)] +pub struct WorkerRecord { + pub worker_id: u64, + /// `None` if the worker never connected. + pub startup: Option, + pub blocks_ok: u64, + pub blocks_failed: u64, + /// Seconds between blocks, one sample per block handed out. + pub idle: Welford, + /// Round-trip seconds per block, one sample per block returned. + pub compute: Welford, + /// Last return → `RequestShutdown`. + pub final_wait: Option, + /// `RequestShutdown` → spawn call returned; only for clean exits. + pub teardown: Option, + /// `None` if the worker was still running when the report was built. + pub exit: Option, +} + +#[derive(Clone, Debug, Default, Serialize)] +pub struct ExitCounts { + pub clean: u64, + pub error: u64, + pub timeout: u64, + pub interrupted: u64, + pub running: u64, +} + +/// The per-task workers section of the report. +#[derive(Clone, Debug, Default, Serialize)] +pub struct WorkerReport { + /// Workers daisy spawned for this task. + pub count: u64, + /// Distinct clients that took blocks without a server-assigned id. + pub unmanaged_clients: u64, + /// One sample per worker that connected. + pub startup: Welford, + /// Per-block idle gaps pooled across workers. + pub idle: Welford, + /// Per-block round trips pooled across workers. + pub compute: Welford, + /// One sample per worker that exited cleanly after a shutdown request. + pub teardown: Welford, + pub exits: ExitCounts, + pub by_id: Vec, +} + +#[derive(Debug, Default)] +struct TaskSide { + /// Round trip minus the worker's own `wall_seconds`, per measured block. + overhead: Welford, + unmanaged: HashSet, +} + +/// Everything the server stamps during one run. +#[derive(Debug)] +pub struct RunTimeline { + origin: Instant, + origin_epoch: f64, + /// When the run loop exited and shutdown began. + shutdown_at: Option, + workers: BTreeMap, + tasks: HashMap, + /// Exit instants reported by the spawn threads themselves, consumed + /// when the thread is reaped so a busy main loop does not inflate + /// teardown. + exit_times: HashMap, +} + +impl Default for RunTimeline { + fn default() -> Self { + Self::new() + } +} + +impl RunTimeline { + pub fn new() -> Self { + let origin = Instant::now(); + let origin_epoch = SystemTime::now() + .duration_since(UNIX_EPOCH) + .map(|d| d.as_secs_f64()) + .unwrap_or(0.0); + Self { + origin, + origin_epoch, + shutdown_at: None, + workers: BTreeMap::new(), + tasks: HashMap::new(), + exit_times: HashMap::new(), + } + } + + /// Seconds since the UNIX epoch at `at`, on the server's clock. + pub fn epoch_seconds(&self, at: Instant) -> f64 { + self.origin_epoch + at.saturating_duration_since(self.origin).as_secs_f64() + } + + pub fn started_at(&self) -> f64 { + self.origin_epoch + } + + pub fn spawned(&mut self, worker_id: u64, task_id: &str) { + self.workers + .insert(worker_id, WorkerTimeline::new(worker_id, task_id, Instant::now())); + } + + pub fn acquired(&mut self, worker_id: u64) { + if let Some(w) = self.workers.get_mut(&worker_id) { + w.acquired(Instant::now()); + } + } + + /// Stamp a dispatch. Returns the send instant for the bookkeeper. + pub fn block_sent(&mut self, worker_id: Option, task_id: &str, addr: SocketAddr) -> Instant { + let now = Instant::now(); + match worker_id.and_then(|id| self.workers.get_mut(&id)) { + Some(w) => w.block_sent(now), + None => { + self.tasks.entry(task_id.to_string()).or_default().unmanaged.insert(addr); + } + } + now + } + + /// Stamp a return. `wall_seconds` is the worker's own measurement when + /// the block carried one; the difference to the round trip is the + /// per-block overhead. Returns the return instant. + pub fn block_returned( + &mut self, + worker_id: Option, + task_id: &str, + sent_at: Instant, + ok: bool, + wall_seconds: Option, + ) -> Instant { + let now = Instant::now(); + let elapsed = match worker_id.and_then(|id| self.workers.get_mut(&id)) { + Some(w) => w.block_returned(now, sent_at, ok), + None => now.duration_since(sent_at).as_secs_f64(), + }; + if let Some(wall) = wall_seconds { + self.tasks + .entry(task_id.to_string()) + .or_default() + .overhead + .push((elapsed - wall).max(0.0)); + } + now + } + + /// The run loop has exited; every clean exit from here on is a + /// teardown even if the worker never got an explicit reply. + pub fn shutdown_started(&mut self) { + if self.shutdown_at.is_none() { + self.shutdown_at = Some(Instant::now()); + } + } + + pub fn shutdown_sent(&mut self, worker_id: u64) { + if let Some(w) = self.workers.get_mut(&worker_id) { + w.shutdown_sent(Instant::now()); + } + } + + /// The spawn thread stamped its own exit; used by the next `exited`. + pub fn note_exit_time(&mut self, worker_id: u64, at: Instant) { + self.exit_times.entry(worker_id).or_insert(at); + } + + pub fn exited(&mut self, worker_id: u64, kind: WorkerExitKind) { + let at = self.exit_times.remove(&worker_id).unwrap_or_else(Instant::now); + if let Some(w) = self.workers.get_mut(&worker_id) { + w.exited(at, kind); + } + } + + /// Close every worker that has not exited yet (run aborted). + pub fn close_remaining(&mut self, kind: WorkerExitKind) { + let now = Instant::now(); + for w in self.workers.values_mut() { + if !w.has_exited() { + w.exited(now, kind); + } + } + } + + pub fn overhead(&self, task_id: &str) -> Welford { + self.tasks + .get(task_id) + .map(|t| t.overhead.clone()) + .unwrap_or_default() + } + + /// Fold this task's workers into the report section. + pub fn report_for(&self, task_id: &str) -> WorkerReport { + let mut r = WorkerReport { + unmanaged_clients: self + .tasks + .get(task_id) + .map(|t| t.unmanaged.len() as u64) + .unwrap_or(0), + ..WorkerReport::default() + }; + for w in self.workers.values().filter(|w| w.task_id == task_id) { + let rec = w.record(self.shutdown_at); + r.count += 1; + if let Some(s) = rec.startup { + r.startup.push(s); + } + if let Some(t) = rec.teardown { + r.teardown.push(t); + } + r.idle.merge(&rec.idle); + r.compute.merge(&rec.compute); + match rec.exit { + Some(WorkerExitKind::Clean) => r.exits.clean += 1, + Some(WorkerExitKind::Error) => r.exits.error += 1, + Some(WorkerExitKind::Timeout) => r.exits.timeout += 1, + Some(WorkerExitKind::Interrupted) => r.exits.interrupted += 1, + None => r.exits.running += 1, + } + r.by_id.push(rec); + } + r + } + + pub fn task_ids(&self) -> impl Iterator { + self.workers.values().map(|w| w.task_id.as_str()) + } +} + +#[cfg(test)] +mod tests { + use super::*; + use std::time::Duration; + + fn at(origin: Instant, ms: u64) -> Instant { + origin + Duration::from_millis(ms) + } + + #[test] + fn phases_are_cut_at_the_right_events() { + let o = Instant::now(); + let mut w = WorkerTimeline::new(0, "t", o); + w.acquired(at(o, 2000)); // startup 2.0 s + w.block_sent(at(o, 2100)); // idle 0.1 s (connect → first block) + w.block_returned(at(o, 3100), at(o, 2100), true); // compute 1.0 s + w.acquired(at(o, 3100)); // second acquire is not a stamp + w.block_sent(at(o, 3300)); // idle 0.2 s + w.block_returned(at(o, 4300), at(o, 3300), false); // compute 1.0 s, failed + w.shutdown_sent(at(o, 4350)); // final wait 0.05 s + w.exited(at(o, 4550), WorkerExitKind::Clean); // teardown 0.2 s + + let r = w.record(None); + assert!((r.startup.unwrap() - 2.0).abs() < 1e-9); + assert_eq!(r.idle.n(), 2); + assert!((r.idle.mean() - 0.15).abs() < 1e-9); + assert_eq!(r.compute.n(), 2); + assert!((r.compute.mean() - 1.0).abs() < 1e-9); + assert_eq!((r.blocks_ok, r.blocks_failed), (1, 1)); + assert!((r.final_wait.unwrap() - 0.05).abs() < 1e-9); + assert!((r.teardown.unwrap() - 0.2).abs() < 1e-9); + assert_eq!(r.exit, Some(WorkerExitKind::Clean)); + } + + #[test] + fn a_worker_that_never_connected_has_no_startup_or_teardown() { + let o = Instant::now(); + let mut w = WorkerTimeline::new(3, "t", o); + w.exited(at(o, 10), WorkerExitKind::Error); + let r = w.record(Some(at(o, 5))); + assert_eq!(r.startup, None); + assert_eq!(r.teardown, None); + assert_eq!(r.exit, Some(WorkerExitKind::Error)); + assert!(r.idle.is_empty() && r.compute.is_empty()); + } + + #[test] + fn first_exit_wins_and_dirty_exits_have_no_teardown() { + let o = Instant::now(); + let mut w = WorkerTimeline::new(1, "t", o); + w.acquired(at(o, 1)); + w.shutdown_sent(at(o, 5)); + w.exited(at(o, 7), WorkerExitKind::Timeout); + w.exited(at(o, 9), WorkerExitKind::Clean); + let r = w.record(None); + assert_eq!(r.exit, Some(WorkerExitKind::Timeout)); + assert_eq!(r.teardown, None); + } + + #[test] + fn teardown_falls_back_to_the_run_shutdown_for_unanswered_workers() { + let o = Instant::now(); + let mut w = WorkerTimeline::new(1, "t", o); + w.acquired(at(o, 1)); + w.exited(at(o, 500), WorkerExitKind::Clean); + // No RequestShutdown ever went out: without a run shutdown stamp + // there is nothing to measure from... + assert_eq!(w.record(None).teardown, None); + // ...with one, teardown runs from it. + let r = w.record(Some(at(o, 300))); + assert!((r.teardown.unwrap() - 0.2).abs() < 1e-9); + // A shutdown that began after the exit is not a teardown. + assert_eq!(w.record(Some(at(o, 900))).teardown, None); + } + + #[test] + fn run_timeline_groups_by_task_and_pools_samples() { + let mut t = RunTimeline::new(); + let addr: SocketAddr = "127.0.0.1:1".parse().unwrap(); + t.spawned(0, "a"); + t.spawned(1, "a"); + t.spawned(2, "b"); + for id in 0..3 { + t.acquired(id); + } + let s0 = t.block_sent(Some(0), "a", addr); + let s1 = t.block_sent(Some(1), "a", addr); + t.block_sent(None, "a", addr); // unmanaged client + t.block_returned(Some(0), "a", s0, true, Some(0.0)); + t.block_returned(Some(1), "a", s1, true, None); + t.shutdown_sent(0); + t.exited(0, WorkerExitKind::Clean); + t.exited(1, WorkerExitKind::Error); + t.close_remaining(WorkerExitKind::Interrupted); + + let a = t.report_for("a"); + assert_eq!(a.count, 2); + assert_eq!(a.unmanaged_clients, 1); + assert_eq!(a.startup.n(), 2); + assert_eq!(a.idle.n(), 2); + assert_eq!(a.compute.n(), 2); + assert_eq!(a.teardown.n(), 1); + assert_eq!((a.exits.clean, a.exits.error), (1, 1)); + assert_eq!(a.by_id.len(), 2); + assert_eq!(t.overhead("a").n(), 1); + + let b = t.report_for("b"); + assert_eq!(b.count, 1); + assert_eq!(b.exits.interrupted, 1); + assert_eq!(b.exits.running, 0); + assert!(t.report_for("c").by_id.is_empty()); + } + + #[test] + fn epoch_seconds_tracks_the_wall_clock() { + let t = RunTimeline::new(); + let now = SystemTime::now() + .duration_since(UNIX_EPOCH) + .unwrap() + .as_secs_f64(); + let stamped = t.epoch_seconds(Instant::now()); + assert!((stamped - now).abs() < 1.0, "{stamped} vs {now}"); + assert!(t.started_at() <= stamped); + } +} diff --git a/daisy-py/python/daisy/__init__.py b/daisy-py/python/daisy/__init__.py index 30396781..6585b09a 100644 --- a/daisy-py/python/daisy/__init__.py +++ b/daisy-py/python/daisy/__init__.py @@ -25,14 +25,17 @@ JsonProgressObserver, Pipeline, Roi, + RunReport, Scheduler, SerialServer, Server, Task, + TaskReport, TaskState, __version__, get_done_marker_basedir, get_tracking_basedir, + last_report, profile_block, run_blockwise, set_done_marker_basedir, @@ -50,16 +53,19 @@ "JsonProgressObserver", "Pipeline", "Roi", + "RunReport", "Scheduler", "SerialServer", "Server", "Task", + "TaskReport", "TaskState", "__version__", "profile_block", "get_done_marker_basedir", "get_tracking_basedir", "get_worker_log_basename", + "last_report", "run_blockwise", "set_done_marker_basedir", "set_tracking_basedir", diff --git a/daisy-py/python/daisy/_daisy.pyi b/daisy-py/python/daisy/_daisy.pyi index 85bb18d7..871a6a71 100644 --- a/daisy-py/python/daisy/_daisy.pyi +++ b/daisy-py/python/daisy/_daisy.pyi @@ -241,6 +241,8 @@ class Task: check_function: Callable[..., Any] | None def reset(self) -> str | None: ... + def failed_blocks(self) -> list[Block]: ... + def block_record(self, block: Block) -> dict[str, Any] | None: ... def __copy__(self) -> Task: ... def __deepcopy__(self, memo: Any) -> Task: ... @@ -359,14 +361,14 @@ def get_done_marker_basedir() -> Path | None: ... def _run_serial( input: Pipeline | Task, block_tracking: bool = ..., -) -> dict[str, TaskState]: ... +) -> tuple[dict[str, TaskState], Any]: ... def _run_distributed_server( input: Pipeline | Task, resources: dict[str, int] | None = ..., progress_observer: object | None = ..., host: str | None = ..., block_tracking: bool = ..., -) -> tuple[dict[str, TaskState], dict[str, Any]]: ... +) -> tuple[dict[str, TaskState], Any]: ... def _run_blockwise_orchestrator( input: Pipeline | Task, multiprocessing: bool = ..., @@ -374,5 +376,5 @@ def _run_blockwise_orchestrator( progress: bool | object | None = ..., block_tracking: bool = ..., host: str | None = ..., -) -> dict[str, TaskState]: ... +) -> tuple[dict[str, TaskState], Any]: ... def _topo_order(input: Pipeline | Task) -> list[str]: ... diff --git a/daisy-py/python/daisy/_progress.py b/daisy-py/python/daisy/_progress.py index b4a553bc..83fd7692 100644 --- a/daisy-py/python/daisy/_progress.py +++ b/daisy-py/python/daisy/_progress.py @@ -1,5 +1,6 @@ -"""Progress display: tqdm bars, JSON observer, post-run summary, -resource report, and the topological ordering that drives them. +"""Progress display: tqdm bars, JSON observer, post-run summary, the +resource / worker report panel, and the topological ordering that drives +them. Imports nothing from `_runner.py`; both `_runner.py` and the public `__init__.py` import from here. @@ -10,6 +11,7 @@ import sys import time +from daisy import _report from daisy import logging as _worker_log logger = logging.getLogger(__name__) @@ -163,18 +165,19 @@ def p(s=""): class _SummaryRecorder: """What `execution_summary` prints on exit: the final states, the - display order and the tracking summaries, set by the entry point once - the run has returned.""" + display order and the run report, set by the entry point once the run + has returned.""" def __init__(self): self.states = None self.order = None - self.stats = None + self.report = None - def set(self, states, stats=None, order=None): + def set(self, states, report=None, order=None): self.states = states - if stats is not None: - self.stats = stats + if report is not None: + self.report = report + _report._set_last(report) if order is not None: self.order = order @@ -207,11 +210,13 @@ def __enter__(self): def __exit__(self, exc_type, exc, tb): if not self.enabled: return False - states, order, stats = self.rec.states, self.rec.order, self.rec.stats + states, order, report = self.rec.states, self.rec.order, self.rec.report if exc is not None: states = getattr(exc, "daisy_states", None) order = getattr(exc, "daisy_task_order", None) or order - stats = getattr(exc, "daisy_run_stats", None) + report = getattr(exc, "daisy_run_report", None) + if report is not None: + _report._set_last(report) if states is None: return False if isinstance(exc, KeyboardInterrupt): @@ -225,7 +230,7 @@ def __exit__(self, exc_type, exc, tb): return False _print_execution_summary(states, order) _log_resume_summary(states) - _print_resource_utilization(stats, order) + _print_resource_utilization(report, order) return False @@ -436,32 +441,25 @@ def on_finish(self, states): pass -def _format_bytes(n): - n = float(n) - for unit in ("B", "KB", "MB", "GB", "TB"): - if abs(n) < 1024.0: - return f"{n:.1f} {unit}" - n /= 1024.0 - return f"{n:.1f} PB" +_format_bytes = _report._format_bytes -def _print_resource_utilization(stats, task_order=None): - """Post-run resource report, agglomerated from per-block measurements. +def _print_resource_utilization(report, task_order=None): + """Post-run resource and worker panel, rendered from the `RunReport`. - Every figure here is a fold over what the tracking layer wrote as - blocks came back — `blocks` is the same count the scheduler completed, - because it is the same counter. Tasks that did not opt into - `resource_tracking` have no resource figures, so the panel is omitted - rather than printing a table of zeros. + Every figure is a fold over what the tracking layer wrote as blocks + came back and over the lifecycle events the server stamped — `blocks` + is the same count the scheduler completed, because it is the same + counter. Tasks that did not opt into `resource_tracking` have no + resource figures, so the panel is omitted rather than printing a table + of zeros; `report.tasks[...]` still carries their worker timing. """ - if stats is None: + if report is None: return - import sys - - per_task = (stats.get("per_task") or {}) if hasattr(stats, "get") else {} - measured = {k: v for k, v in per_task.items() if v.get("has_stats")} - if not measured: + text = report.render(task_order) + if not text: return + import sys # While the per-worker proxies are installed, write to the real stdout # they wrap; once they are uninstalled (the summary now prints after @@ -471,56 +469,7 @@ def _print_resource_utilization(stats, task_order=None): # object that has since been closed — never let the summary crash a run if getattr(out, "closed", False): out = sys.__stdout__ or sys.stdout - - def p(s=""): - try: - print(s, file=out) - except ValueError: # closed file raced us - pass - - total_cpu = sum(float(t.get("total_cpu_secs", 0.0)) for t in measured.values()) - total_block = sum(float(t.get("total_block_secs", 0.0)) for t in measured.values()) - peak_rss = max(int(t.get("max_peak_rss_bytes", 0)) for t in measured.values()) - io_r = sum(int(t.get("io_read_bytes", 0)) for t in measured.values()) - io_w = sum(int(t.get("io_write_bytes", 0)) for t in measured.values()) - n_blocks = sum(int(t.get("blocks", 0)) for t in measured.values()) - - p() - p("Resource Utilization") - p("--------------------") - p() - p(" Totals (summed over measured blocks):") - p(f" blocks measured : {n_blocks}") - p(f" CPU time : {total_cpu:.2f} s") - p(f" in-block time : {total_block:.2f} s") - if total_block > 0: - # How much CPU each second of block time consumed: ~1.0 means - # CPU-bound, well under 1.0 means the blocks were waiting on IO. - p( - f" CPU per block-s : {total_cpu / total_block:.2f}" - " (≈1.0 CPU-bound, «1.0 IO-bound)" - ) - p(f" peak RSS : {_format_bytes(peak_rss)} (largest single worker)") - p(f" IO read : {_format_bytes(io_r)}") - p(f" IO write : {_format_bytes(io_w)}") - - p() - p(" Per-task:") - p( - f" {'task':<14}{'blocks':>8}{'fails':>7}" - f" {'mean ms ∠ slope':<22}{'cpu s':>9}{'peak RSS':>11}" - ) - p(f" {'─' * 14}{'─' * 8}{'─' * 7} {'─' * 22}{'─' * 9}{'─' * 11}") - for task_id in _ordered_states(measured, task_order): - t = measured[task_id] - blocks = int(t.get("blocks", 0)) - fails = int(t.get("failures", 0)) - mean_ms = float(t.get("mean_block_ms", 0.0)) - slope = float(t.get("block_ms_slope", 0.0)) - cpu = float(t.get("total_cpu_secs", 0.0)) - rss = int(t.get("max_peak_rss_bytes", 0)) - trend = f"{mean_ms:6.2f} ∠ {slope:+.4f}" - p( - f" {task_id:<14}{blocks:>8}{fails:>7}" - f" {trend:<22}{cpu:>8.2f}s{_format_bytes(rss):>11}" - ) + try: + print(text, file=out) + except ValueError: # closed file raced us + pass diff --git a/daisy-py/python/daisy/_report.py b/daisy-py/python/daisy/_report.py new file mode 100644 index 00000000..55bd712d --- /dev/null +++ b/daisy-py/python/daisy/_report.py @@ -0,0 +1,575 @@ +"""The run report: per-block and per-worker figures for every task of a run. + +Built from the JSON the Rust side emits (`daisy_core::run_report`) — the +same line it appends to each tracked task's ``runs.jsonl`` — so the object +you get back from a run and the record left on disk are one and the same +shape. + +Primary interface:: + + report = daisy.last_report() # or daisy.Server().last_report + t = report.tasks["segment"] + t.blocks.wall # Stat: n, mean, std, min, max, total + t.workers.startup # Stat over workers + t.workers.idle # Stat over per-block gaps, all workers + print(report) # the panel the run prints + +Drill-downs:: + + t.worker(1) # WorkerRecord + t.block(block) # BlockRecord from the tracking store + t.block((1, 2)) # ...by grid coordinate +""" + +from __future__ import annotations + +import json +from dataclasses import dataclass, field + +_last: list = [None] + + +def last_report(): + """The `RunReport` of the most recent run in this process (any entry + point), or None before the first run finishes.""" + return _last[0] + + +def _set_last(report) -> None: + _last[0] = report + + +# -- formatting --------------------------------------------------------------- + + +def _format_bytes(n) -> str: + n = float(n) + for unit in ("B", "KB", "MB", "GB", "TB"): + if abs(n) < 1024.0: + return f"{n:.1f} {unit}" + n /= 1024.0 + return f"{n:.1f} PB" + + +def _secs_unit(x: float) -> tuple[float, str]: + """Scale and unit that keep a duration readable.""" + x = abs(x) + if x >= 1.0 or x == 0.0: + return 1.0, "s" + if x >= 1e-3: + return 1e3, "ms" + return 1e6, "µs" + + +def _format_secs(x: float | None) -> str: + if x is None: + return "—" + scale, unit = _secs_unit(x) + v = x * scale + return f"{v:.2f} {unit}" if scale == 1.0 else f"{v:.1f} {unit}" + + +@dataclass(frozen=True) +class Stat: + """A measured distribution: sample count, mean, sample standard + deviation, min, max and total. Empty (``n == 0``) when nothing was + measured — it then formats as ``—``.""" + + n: int = 0 + mean: float = 0.0 + std: float = 0.0 + min: float = 0.0 + max: float = 0.0 + total: float = 0.0 + + @classmethod + def from_dict(cls, d) -> Stat: + if not d: + return cls() + return cls( + n=int(d.get("n", 0)), + mean=float(d.get("mean", 0.0)), + std=float(d.get("std", 0.0)), + min=float(d.get("min", 0.0)), + max=float(d.get("max", 0.0)), + total=float(d.get("sum", d.get("total", 0.0))), + ) + + def to_dict(self) -> dict: + return { + "n": self.n, + "mean": self.mean, + "std": self.std, + "min": self.min, + "max": self.max, + "sum": self.total, + } + + def __bool__(self) -> bool: + return self.n > 0 + + def format(self, unit: str = "s") -> str: + """``mean ± std`` in seconds (``unit="s"``) or bytes (``unit="B"``); + just the mean when there is a single sample.""" + if self.n == 0: + return "—" + if unit == "B": + m = _format_bytes(self.mean) + return m if self.n < 2 else f"{m} ± {_format_bytes(self.std)}" + scale, u = _secs_unit(self.mean) + prec = 2 if scale == 1.0 else 1 + m = f"{self.mean * scale:.{prec}f}" + if self.n < 2: + return f"{m} {u}" + return f"{m} {u} ± {self.std * scale:.{prec}f} {u}" + + def __str__(self) -> str: + return self.format() + + +# -- sections ----------------------------------------------------------------- + + +@dataclass(frozen=True) +class BlockSummary: + """Per-block figures for one task over this run. The ``Stat`` fields + are empty unless the task set ``resource_tracking=True``; ``overhead`` + (server round trip minus the block's own wall time) likewise.""" + + count: int = 0 + failures: int = 0 + has_stats: bool = False + wall: Stat = field(default_factory=Stat) + cpu: Stat = field(default_factory=Stat) + peak_rss: Stat = field(default_factory=Stat) + io_read: Stat = field(default_factory=Stat) + io_write: Stat = field(default_factory=Stat) + overhead: Stat = field(default_factory=Stat) + trend_slope_ms: float = 0.0 + + @classmethod + def from_dict(cls, d) -> BlockSummary: + d = d or {} + return cls( + count=int(d.get("count", 0)), + failures=int(d.get("failures", 0)), + has_stats=bool(d.get("has_stats", False)), + wall=Stat.from_dict(d.get("wall")), + cpu=Stat.from_dict(d.get("cpu")), + peak_rss=Stat.from_dict(d.get("peak_rss")), + io_read=Stat.from_dict(d.get("io_read")), + io_write=Stat.from_dict(d.get("io_write")), + overhead=Stat.from_dict(d.get("overhead")), + trend_slope_ms=float(d.get("trend_slope_ms", 0.0)), + ) + + def to_dict(self) -> dict: + return { + "count": self.count, + "failures": self.failures, + "has_stats": self.has_stats, + "wall": self.wall.to_dict(), + "cpu": self.cpu.to_dict(), + "peak_rss": self.peak_rss.to_dict(), + "io_read": self.io_read.to_dict(), + "io_write": self.io_write.to_dict(), + "overhead": self.overhead.to_dict(), + "trend_slope_ms": self.trend_slope_ms, + } + + +@dataclass(frozen=True) +class WorkerRecord: + """One worker's lifecycle. Durations in seconds; ``None`` where the + phase never happened (no ``startup`` for a worker that never connected, + no ``teardown`` for one that crashed or was cut off).""" + + worker_id: int + startup: float | None = None + blocks_ok: int = 0 + blocks_failed: int = 0 + idle: Stat = field(default_factory=Stat) + compute: Stat = field(default_factory=Stat) + final_wait: float | None = None + teardown: float | None = None + #: ``"clean"``, ``"error"``, ``"timeout"``, ``"interrupted"`` or None + #: if still running when the report was built. + exit: str | None = None + + @classmethod + def from_dict(cls, d) -> WorkerRecord: + return cls( + worker_id=int(d["worker_id"]), + startup=d.get("startup"), + blocks_ok=int(d.get("blocks_ok", 0)), + blocks_failed=int(d.get("blocks_failed", 0)), + idle=Stat.from_dict(d.get("idle")), + compute=Stat.from_dict(d.get("compute")), + final_wait=d.get("final_wait"), + teardown=d.get("teardown"), + exit=d.get("exit"), + ) + + def to_dict(self) -> dict: + return { + "worker_id": self.worker_id, + "startup": self.startup, + "blocks_ok": self.blocks_ok, + "blocks_failed": self.blocks_failed, + "idle": self.idle.to_dict(), + "compute": self.compute.to_dict(), + "final_wait": self.final_wait, + "teardown": self.teardown, + "exit": self.exit, + } + + @property + def blocks(self) -> int: + return self.blocks_ok + self.blocks_failed + + +@dataclass(frozen=True) +class WorkerSummary: + """The workers daisy spawned for one task. ``startup`` and ``teardown`` + have one sample per worker; ``idle`` and ``compute`` pool every + worker's per-block samples.""" + + count: int = 0 + unmanaged_clients: int = 0 + startup: Stat = field(default_factory=Stat) + idle: Stat = field(default_factory=Stat) + compute: Stat = field(default_factory=Stat) + teardown: Stat = field(default_factory=Stat) + exits: dict = field(default_factory=dict) + by_id: dict = field(default_factory=dict) + + @classmethod + def from_dict(cls, d) -> WorkerSummary: + d = d or {} + rows = [WorkerRecord.from_dict(r) for r in d.get("by_id", [])] + return cls( + count=int(d.get("count", 0)), + unmanaged_clients=int(d.get("unmanaged_clients", 0)), + startup=Stat.from_dict(d.get("startup")), + idle=Stat.from_dict(d.get("idle")), + compute=Stat.from_dict(d.get("compute")), + teardown=Stat.from_dict(d.get("teardown")), + exits={k: int(v) for k, v in (d.get("exits") or {}).items()}, + by_id={r.worker_id: r for r in rows}, + ) + + def to_dict(self) -> dict: + return { + "count": self.count, + "unmanaged_clients": self.unmanaged_clients, + "startup": self.startup.to_dict(), + "idle": self.idle.to_dict(), + "compute": self.compute.to_dict(), + "teardown": self.teardown.to_dict(), + "exits": dict(self.exits), + "by_id": [r.to_dict() for r in self.by_id.values()], + } + + +@dataclass(frozen=True) +class BlockRecord: + """What the tracking store holds for one block.""" + + block_id: tuple + done: bool + failures: int + #: ``daisy.BlockStats`` or None (no resource tracking, or never ran) + stats: object | None + #: worker that completed it, or None (unmanaged client / never ran) + worker_id: int | None + #: seconds since the UNIX epoch on the scheduler's clock, or None + sent_at: float | None + returned_at: float | None + + @property + def wall_seconds(self) -> float | None: + return None if self.stats is None else self.stats.wall_seconds + + @property + def peak_rss_bytes(self) -> int | None: + return None if self.stats is None else self.stats.peak_rss_bytes + + +class TaskReport: + """One task's report. ``blocks`` and ``workers`` are the summaries; + ``worker(id)`` and ``block(...)`` drill down.""" + + def __init__( + self, + task_id, + blocks, + workers, + started_at=0.0, + finished_at=0.0, + tracked=False, + ): + self.task_id = task_id + self.blocks = blocks + self.workers = workers + self.started_at = started_at + self.finished_at = finished_at + self.tracked = tracked + self._task = None + + @classmethod + def from_dict(cls, d) -> TaskReport: + return cls( + task_id=d["task_id"], + blocks=BlockSummary.from_dict(d.get("blocks")), + workers=WorkerSummary.from_dict(d.get("workers")), + started_at=float(d.get("started_at", 0.0)), + finished_at=float(d.get("finished_at", 0.0)), + tracked=bool(d.get("tracked", False)), + ) + + def to_dict(self) -> dict: + return { + "task_id": self.task_id, + "started_at": self.started_at, + "finished_at": self.finished_at, + "tracked": self.tracked, + "blocks": self.blocks.to_dict(), + "workers": self.workers.to_dict(), + } + + @property + def elapsed(self) -> float: + """Run wall time in seconds, start to report.""" + return max(0.0, self.finished_at - self.started_at) + + def worker(self, worker_id) -> WorkerRecord: + return self.workers.by_id[int(worker_id)] + + def block(self, block) -> BlockRecord | None: + """Look a block up in the task's tracking store. + + ``block`` is a `daisy.Block`, a grid coordinate (tuple of ints, + one per axis, anchored at ``total_roi``) or a spatial block id + (int; found by scanning the grid, so prefer the other two forms on + large tasks). None when the task has no store or the block is not + in it. Available on reports returned by a run in this process; + a report rebuilt from JSON has no task to read the store through. + """ + task = self._task + if task is None: + raise RuntimeError( + f"TaskReport({self.task_id!r}).block(): no task attached — " + "per-block lookup reads the tracking store through the Task " + "and is only available on the report a run returned" + ) + native = _resolve_block(task, block) + if native is None: + return None + rec = task.block_record(native) + if rec is None: + return None + return BlockRecord( + block_id=(task.task_id, native.block_id[1]), + done=rec["done"], + failures=rec["failures"], + stats=rec["stats"], + worker_id=rec["worker_id"], + sent_at=rec["sent_at"], + returned_at=rec["returned_at"], + ) + + def __repr__(self) -> str: + return ( + f"TaskReport({self.task_id!r}, blocks={self.blocks.count}, " + f"workers={self.workers.count})" + ) + + # -- rendering ------------------------------------------------------- + + def render(self, max_workers: int = 10) -> str: + """The task's section of the Resource Utilization panel.""" + b, w = self.blocks, self.workers + lines = [] + head = f" {self.task_id} {b.count} blocks" + if w.count: + head += f", {w.count} worker{'s' if w.count != 1 else ''}" + if self.elapsed > 0: + head += f", {_format_secs(self.elapsed)} wall" + lines.append(head) + if b.has_stats: + lines.append( + f" blocks wall {b.wall.format()} cpu {b.cpu.format()}" + f" peak RSS {b.peak_rss.format('B')}" + ) + second = ( + f" io read {_format_bytes(b.io_read.total)}" + f" write {_format_bytes(b.io_write.total)}" + ) + if b.overhead: + second += f" overhead {b.overhead.format()}" + second += f" trend ∠ {b.trend_slope_ms:+.4f} ms/block" + lines.append(second) + if b.failures: + lines.append(f" {b.failures} failed attempt(s)") + if w.count: + lines.append( + f" workers startup {w.startup.format()} idle {w.idle.format()}" + f" teardown {w.teardown.format()}" + ) + exits = " ".join(f"{n} {kind}" for kind, n in w.exits.items() if n) + extra = f" exits {exits or '—'}" + if w.unmanaged_clients: + extra += f" (+ {w.unmanaged_clients} unmanaged client(s))" + lines.append(extra) + lines.extend(self._worker_table(max_workers)) + return "\n".join(lines) + + def _worker_table(self, max_workers: int) -> list[str]: + rows = sorted(self.workers.by_id.values(), key=lambda r: r.worker_id) + if not rows: + return [] + cols = [ + ("id", 4), + ("startup", 9), + ("blocks", 6), + ("idle", 9), + ("idle / block", 19), + ("compute", 9), + ("compute / block", 19), + ("teardown", 9), + ] + out = [" " + " ".join(f"{name:>{w}}" for name, w in cols) + " exit"] + for r in rows[:max_workers]: + cells = [ + str(r.worker_id), + _format_secs(r.startup), + str(r.blocks), + _format_secs(r.idle.total) if r.idle else "—", + r.idle.format(), + _format_secs(r.compute.total) if r.compute else "—", + r.compute.format(), + _format_secs(r.teardown), + ] + out.append( + " " + + " ".join(f"{c:>{w}}" for c, (_, w) in zip(cells, cols)) + + f" {r.exit or 'running'}" + ) + if len(rows) > max_workers: + out.append( + f" … +{len(rows) - max_workers} more; see " + f'report.tasks["{self.task_id}"].workers.by_id' + ) + return out + + +class RunReport: + """Reports for every task of one run, keyed by task id.""" + + def __init__(self, tasks: dict): + self.tasks = tasks + + @classmethod + def from_dict(cls, d) -> RunReport: + return cls({tid: TaskReport.from_dict(t) for tid, t in (d or {}).items()}) + + @classmethod + def from_json(cls, s: str) -> RunReport: + return cls.from_dict(json.loads(s)) + + def to_dict(self) -> dict: + return {tid: t.to_dict() for tid, t in self.tasks.items()} + + def to_json(self) -> str: + return json.dumps(self.to_dict()) + + def __getitem__(self, task_id) -> TaskReport: + return self.tasks[task_id] + + def __iter__(self): + return iter(self.tasks) + + def __len__(self) -> int: + return len(self.tasks) + + def __repr__(self) -> str: + return f"RunReport({sorted(self.tasks)})" + + @property + def measured(self) -> dict: + """The tasks that measured their blocks (``resource_tracking=True``).""" + return {tid: t for tid, t in self.tasks.items() if t.blocks.has_stats} + + def _attach(self, tasks) -> None: + """Give each task report the `daisy.Task` it came from, for + `TaskReport.block`.""" + for task in tasks: + tid = getattr(task, "task_id", None) + if tid in self.tasks: + self.tasks[tid]._task = task + + def render(self, task_order=None, max_workers: int = 10) -> str: + """The Resource Utilization panel: one section per task that + measured its blocks, in ``task_order``. Empty when no task did — + a table of zeros is worse than no table.""" + measured = self.measured + if not measured: + return "" + if task_order is None: + order = sorted(measured) + else: + seen = set(task_order) + order = [t for t in task_order if t in measured] + sorted( + t for t in measured if t not in seen + ) + parts = ["", "Resource Utilization", "--------------------"] + for tid in order: + parts.append("") + parts.append(measured[tid].render(max_workers=max_workers)) + return "\n".join(parts) + + def __str__(self) -> str: + return self.render() + + +def _resolve_block(task, block): + """A `Block` (or anything carrying a ``_native`` block), a grid + coordinate tuple, or an int spatial id → the native block, or None.""" + from daisy.block import Block + + if isinstance(block, Block): + return block._native + native = getattr(block, "_native", None) + if native is not None: + return native + if hasattr(block, "block_id") and hasattr(block, "write_roi"): + return block # already native + from daisy._task import Roi + + total = task.total_roi + write = task.write_roi + if isinstance(block, tuple): + if len(block) != total.dims: + raise ValueError( + f"grid coordinate {block} has {len(block)} entries; " + f"task {task.task_id!r} has {total.dims} axes" + ) + offset = tuple( + int(o) + int(c) * int(s) + for o, c, s in zip(total.offset, block, write.shape) + ) + write_roi = Roi(offset, tuple(int(s) for s in write.shape)) + return Block(total, write_roi, write_roi, task_id=task.task_id)._native + if isinstance(block, int): + import itertools + + shape = task.block_grid_shape + for coord in itertools.product(*(range(int(n)) for n in shape)): + native = _resolve_block(task, tuple(coord)) + if native.block_id[1] == block: + return native + return None + raise TypeError( + f"block must be a daisy.Block, a grid coordinate tuple or an int " + f"spatial id, not {type(block).__name__}" + ) diff --git a/daisy-py/python/daisy/_runner.py b/daisy-py/python/daisy/_runner.py index 3cf7dffb..f2196874 100644 --- a/daisy-py/python/daisy/_runner.py +++ b/daisy-py/python/daisy/_runner.py @@ -49,18 +49,18 @@ class Server: wraps process functions with per-worker logging context first. Most users go through `daisy.run_blockwise(...)`. Instantiate this - class directly when you want access to `last_tracking_summary` or - `last_task_order` after the run.""" + class directly when you want access to `last_report` or + `last_task_order` after the run (`daisy.last_report()` returns the + same report for whichever entry point ran last).""" def __init__(self, stop_event=None): self._stop_event = stop_event self.hostname = None self.port = None - #: This run's per-task aggregates, agglomerated from the per-block - #: measurements the tracking layer wrote (``{"per_task": {...}}``). - #: Empty of resource figures unless a task set - #: ``resource_tracking=True``. - self.last_tracking_summary = None + #: This run's `daisy.RunReport`: per-task block aggregates (resource + #: figures only for tasks with ``resource_tracking=True``) and + #: per-worker startup / idle / compute / teardown timing. + self.last_report = None self.last_task_order = None def run_blockwise( @@ -76,14 +76,15 @@ def run_blockwise( abandoned tasks (inspect the states instead). The execution summary is printed on return and on KeyboardInterrupt; `summary=False` silences it.""" - pipeline = _prepare(_coerce_pipeline(pipeline)) + original = _coerce_pipeline(pipeline) + pipeline = _prepare(original) order = _rs._topo_order(pipeline) self.last_task_order = order observer = _resolve_observer(progress, order) with execution_summary(summary) as rec: rec.order = order try: - states, stats = _rs._run_distributed_server( + states, report = _rs._run_distributed_server( pipeline, resources, observer, @@ -92,23 +93,26 @@ def run_blockwise( ) finally: _worker_log.close_all_log_files() - self.last_tracking_summary = stats - rec.set(states, stats) + report._attach(original.tasks) + self.last_report = report + rec.set(states, report) return states def _run_serial(pipeline, block_tracking=True, summary=True): """Single-threaded execution path (no TCP, no workers). Runs the original process functions in-process — no subprocess wrapping.""" - pipeline = _prepare(_coerce_pipeline(pipeline), distributed=False) + original = _coerce_pipeline(pipeline) + pipeline = _prepare(original, distributed=False) order = _rs._topo_order(pipeline) with execution_summary(summary) as rec: rec.order = order try: - states, stats = _rs._run_serial(pipeline, block_tracking=block_tracking) + states, report = _rs._run_serial(pipeline, block_tracking=block_tracking) finally: _worker_log.close_all_log_files() - rec.set(states, stats) + report._attach(original.tasks) + rec.set(states, report) return states @@ -162,7 +166,9 @@ def run_blockwise( raises ``RuntimeError`` either way. ``summary=False`` silences the execution summary that is otherwise - printed on return, on KeyboardInterrupt and on abandonment. + printed on return, on KeyboardInterrupt and on abandonment. The run's + `daisy.RunReport` (per-block and per-worker timing) is available + afterwards from ``daisy.last_report()`` either way. ``host`` is the address workers are told to connect to. Leave it unset and daisy detects one — this host's resolved name, else the @@ -176,12 +182,13 @@ def run_blockwise( value from the environment, for pipeline libraries that don't thread the argument through. """ - pipeline = _prepare(_coerce_pipeline(pipeline), distributed=multiprocessing) + original = _coerce_pipeline(pipeline) + pipeline = _prepare(original, distributed=multiprocessing) order = _rs._topo_order(pipeline) with execution_summary(summary) as rec: rec.order = order try: - states, stats = _rs._run_blockwise_orchestrator( + states, report = _rs._run_blockwise_orchestrator( pipeline, multiprocessing=multiprocessing, resources=resources, @@ -191,7 +198,8 @@ def run_blockwise( ) finally: _worker_log.close_all_log_files() - rec.set(states, stats) + report._attach(original.tasks) + rec.set(states, report) if return_states: return states return _all_succeeded(states) diff --git a/daisy-py/python/daisy/v1_compat.py b/daisy-py/python/daisy/v1_compat.py index ec7efa08..cf755a70 100644 --- a/daisy-py/python/daisy/v1_compat.py +++ b/daisy-py/python/daisy/v1_compat.py @@ -44,11 +44,14 @@ JsonProgressObserver, Pipeline, Roi, + RunReport, Server, + TaskReport, TaskState, __version__, get_done_marker_basedir, get_tracking_basedir, + last_report, profile_block, set_done_marker_basedir, set_tracking_basedir, @@ -164,15 +167,18 @@ def run_blockwise(self, tasks, block_tracking=True): "JsonProgressObserver", "Pipeline", "Roi", + "RunReport", "Scheduler", "SerialServer", "Server", "Task", + "TaskReport", "TaskState", "__version__", "profile_block", "get_done_marker_basedir", "get_tracking_basedir", + "last_report", "run_blockwise", "set_done_marker_basedir", "set_tracking_basedir", diff --git a/daisy-py/python/daisy/v2.py b/daisy-py/python/daisy/v2.py index 606cda8b..7835574f 100644 --- a/daisy-py/python/daisy/v2.py +++ b/daisy-py/python/daisy/v2.py @@ -22,6 +22,7 @@ import daisy._daisy as _rs from daisy._progress import JsonProgressObserver +from daisy._report import RunReport, TaskReport, last_report from daisy._runner import Server, run_blockwise from daisy._task import ( Block, @@ -66,12 +67,15 @@ "JsonProgressObserver", "Pipeline", "Roi", + "RunReport", "Scheduler", "Server", "Task", + "TaskReport", "TaskState", "__version__", "BlockStats", + "last_report", "get_done_marker_basedir", "get_tracking_basedir", "run_blockwise", diff --git a/daisy-py/src/py_server.rs b/daisy-py/src/py_server.rs index 3f6bc5e4..6d1bc8ef 100644 --- a/daisy-py/src/py_server.rs +++ b/daisy-py/src/py_server.rs @@ -179,8 +179,8 @@ pub fn _run_blockwise_orchestrator( }; // Dispatch to the appropriate runner. Both paths return a - // `(task_id → PyTaskState, tracking summary)` tuple — serial mode - // measures blocks the same way, so it reports the same summary. + // `(task_id → PyTaskState, RunReport)` tuple — serial mode measures + // blocks the same way, so it reports the same shape (with no workers). let result: Py = if multiprocessing { _run_distributed_server( py, @@ -196,7 +196,7 @@ pub fn _run_blockwise_orchestrator( }; let tup = result.bind(py); let states_obj: Py = tup.get_item(0)?.into_pyobject(py)?.into_any().unbind(); - let run_stats_obj: Py = tup.get_item(1)?.into_pyobject(py)?.into_any().unbind(); + let run_report_obj: Py = tup.get_item(1)?.into_pyobject(py)?.into_any().unbind(); // The post-run report is printed by `daisy._progress.execution_summary`, // the context manager every Python entry point wraps its run in; it // prints on normal exit and on the exceptions below that carry states. @@ -282,12 +282,12 @@ pub fn _run_blockwise_orchestrator( // still printed before the error surfaces. let val = err.value(py); val.setattr("daisy_states", &states_obj)?; - val.setattr("daisy_run_stats", &run_stats_obj)?; + val.setattr("daisy_run_report", &run_report_obj)?; val.setattr("daisy_task_order", &order_py)?; return Err(err); } - let out = pyo3::types::PyTuple::new(py, &[states_obj.bind(py).clone(), run_stats_obj.bind(py).clone()])?; + let out = pyo3::types::PyTuple::new(py, &[states_obj.bind(py).clone(), run_report_obj.bind(py).clone()])?; Ok(out.into_any().unbind()) } @@ -322,15 +322,15 @@ pub fn _run_serial( }; } }; - let (states, summaries) = states; + let (states, reports) = states; let states_py: HashMap = states .into_iter() .map(|(k, v)| (k, PyTaskState { inner: v })) .collect(); - let summary_py = tracking_summary_to_py(py, &summaries)?; + let report_py = reports_to_py(py, &reports)?; let out = pyo3::types::PyTuple::new( py, - &[states_py.into_pyobject(py)?.into_any(), summary_py], + &[states_py.into_pyobject(py)?.into_any(), report_py], )?; Ok(out.into_any().unbind()) } @@ -339,8 +339,8 @@ pub fn _run_serial( /// Worker threads call back into Python via the GIL to execute /// process_function / spawn_function. /// -/// Returns a 2-tuple `(task_states, run_stats)` where `run_stats` is a -/// nested dict matching `daisy_core::run_stats::RunStats`. +/// Returns a 2-tuple `(task_states, run_report)` where `run_report` is a +/// `daisy._report.RunReport` built from `daisy_core::run_report`. /// /// `progress_observer`, if provided, must be a Python object exposing /// `on_start(states)`, `on_progress(states)`, and `on_finish(states)` @@ -414,7 +414,7 @@ pub fn _run_distributed_server( libc::signal(libc::SIGINT, prev as libc::sighandler_t); } - let (states, summaries) = match result { + let (states, reports) = match result { Ok(v) => v, Err(e) if e.kind() == std::io::ErrorKind::Interrupted => { let err = PyErr::new::( @@ -431,10 +431,10 @@ pub fn _run_distributed_server( .iter() .map(|(k, v)| (k.clone(), PyTaskState { inner: v.clone() })) .collect(); - let stats_py = tracking_summary_to_py(py, &ab.summaries)?; + let report_py = reports_to_py(py, &ab.reports)?; let val = err.value(py); val.setattr("daisy_states", states_py.into_pyobject(py)?)?; - val.setattr("daisy_run_stats", stats_py)?; + val.setattr("daisy_run_report", report_py)?; } return Err(err); } @@ -445,41 +445,23 @@ pub fn _run_distributed_server( .into_iter() .map(|(k, v)| (k, PyTaskState { inner: v })) .collect(); - let stats_py = tracking_summary_to_py(py, &summaries)?; + let report_py = reports_to_py(py, &reports)?; - let result = pyo3::types::PyTuple::new(py, &[states_py.into_pyobject(py)?.into_any(), stats_py])?; + let result = pyo3::types::PyTuple::new(py, &[states_py.into_pyobject(py)?.into_any(), report_py])?; Ok(result.unbind()) } -/// Convert this run's per-task tracking aggregates into the dict the -/// Python summary renderer consumes. +/// Hand this run's per-task reports to Python as a `daisy._report.RunReport`. /// -/// Everything here was measured per block inside the workers and folded by -/// `block_tracking::TaskTracking` as blocks were recorded — there is no -/// separate accumulator, so `blocks` cannot disagree with what the -/// scheduler saw. Tasks without tracking configured simply don't appear, -/// which is how the renderer knows to omit the resource panel. -fn tracking_summary_to_py<'py>( +/// The Rust side serializes the same JSON it appends to each task's +/// `runs.jsonl`; the Python side builds its dataclasses from it, so the +/// in-memory report and the persisted one cannot drift apart. +fn reports_to_py<'py>( py: Python<'py>, - summaries: &HashMap, + reports: &HashMap, ) -> PyResult> { - let per_task = PyDict::new(py); - for (task_id, s) in summaries { - let (mean_ms, slope_ms) = s.block_ms_trend(); - let d = PyDict::new(py); - d.set_item("blocks", s.blocks_recorded)?; - d.set_item("failures", s.failures_recorded)?; - d.set_item("has_stats", s.has_stats)?; - d.set_item("total_cpu_secs", s.total_cpu_seconds)?; - d.set_item("total_block_secs", s.total_wall_seconds)?; - d.set_item("max_peak_rss_bytes", s.max_peak_rss_bytes)?; - d.set_item("io_read_bytes", s.total_io_read_bytes)?; - d.set_item("io_write_bytes", s.total_io_write_bytes)?; - d.set_item("mean_block_ms", mean_ms)?; - d.set_item("block_ms_slope", slope_ms)?; - per_task.set_item(task_id, d)?; - } - let out = PyDict::new(py); - out.set_item("per_task", per_task)?; - Ok(out.into_any()) + let json = daisy_core::run_report::reports_to_json(reports); + py.import("daisy._report")? + .getattr("RunReport")? + .call_method1("from_json", (json,)) } diff --git a/daisy-py/src/py_task.rs b/daisy-py/src/py_task.rs index 7c201011..f65f65e0 100644 --- a/daisy-py/src/py_task.rs +++ b/daisy-py/src/py_task.rs @@ -517,33 +517,9 @@ impl PyTask { /// store: every block with a failure count above zero whose done flag /// is still unset. Empty when no store is configured or none exists. fn failed_blocks(&self, py: Python<'_>) -> PyResult> { - let Some(p) = self.done_marker_path.resolve(py, &self.task_id) else { + let Some((tracking, task)) = self.open_tracking(py)? else { return Ok(Vec::new()); }; - let path = Path::new(&p); - if !path.join("zarr.json").exists() { - return Ok(Vec::new()); - } - let task = Task::builder(&self.task_id) - .total_roi(self.total_roi.inner.clone()) - .read_roi(self.read_roi.inner.clone()) - .write_roi(self.write_roi.inner.clone()) - .read_write_conflict(self.read_write_conflict) - .fit(Fit::from_str(&self.fit)) - .build(); - let tracking = TaskTracking::open_or_create( - path, - &task.total_roi, - &task.read_roi, - &task.write_roi, - &task.fit, - false, - ) - .map_err(|e| { - PyErr::new::(format!( - "cannot open block tracking at {p}: {e}" - )) - })?; let graph = daisy_core::dependency_graph::BlockwiseDependencyGraph::from_task(&task); let mut out = Vec::new(); for level in 0..graph.num_levels() { @@ -556,6 +532,35 @@ impl PyTask { Ok(out) } + /// What the tracking store holds for one block, as a dict: `done`, + /// `failures`, `stats` (a `BlockStats` or None), `worker_id`, + /// `sent_at`, `returned_at` (None without a recorded dispatch). None + /// when no store is configured, none exists, or the block is not + /// addressable in it (a boundary block under overhang / shrink). + fn block_record<'py>( + &self, + py: Python<'py>, + block: &crate::py_block::PyBlock, + ) -> PyResult>> { + let Some((tracking, _task)) = self.open_tracking(py)? else { + return Ok(None); + }; + let Some(rec) = tracking.record_of(&block.inner) else { + return Ok(None); + }; + let d = PyDict::new(py); + d.set_item("done", rec.done)?; + d.set_item("failures", rec.failures)?; + d.set_item( + "stats", + rec.stats.map(|inner| crate::py_block::PyBlockStats { inner }), + )?; + d.set_item("worker_id", rec.dispatch.and_then(|x| x.worker_id))?; + d.set_item("sent_at", rec.dispatch.map(|x| x.sent_at))?; + d.set_item("returned_at", rec.dispatch.map(|x| x.returned_at))?; + Ok(Some(d)) + } + /// Property: return the user-facing 3-state value (None / False / /// str), matching what was passed at construction. #[getter(done_marker_path)] @@ -683,3 +688,45 @@ impl PyTask { Ok(arc) } } + +/// Store access shared by the read-only diagnostics above (not exposed +/// to Python). +impl PyTask { + /// Open this task's tracking store for reading, if one is configured + /// and exists. Maps the stat arrays only when the store already has + /// them, so a read never adds arrays to a store. + fn open_tracking(&self, py: Python<'_>) -> PyResult> { + let Some(p) = self.done_marker_path.resolve(py, &self.task_id) else { + return Ok(None); + }; + let path = Path::new(&p); + if !path.join("zarr.json").exists() { + return Ok(None); + } + let task = Task::builder(&self.task_id) + .total_roi(self.total_roi.inner.clone()) + .read_roi(self.read_roi.inner.clone()) + .write_roi(self.write_roi.inner.clone()) + .read_write_conflict(self.read_write_conflict) + .fit(Fit::from_str(&self.fit)) + .build(); + let with_stats = path + .join(daisy_core::block_tracking::ARRAY_WALL_SECONDS) + .join("zarr.json") + .exists(); + let tracking = TaskTracking::open_or_create( + path, + &task.total_roi, + &task.read_roi, + &task.write_roi, + &task.fit, + with_stats, + ) + .map_err(|e| { + PyErr::new::(format!( + "cannot open block tracking at {p}: {e}" + )) + })?; + Ok(Some((tracking, task))) + } +} diff --git a/docs/source/api.md b/docs/source/api.md index 3d915528..2989ac60 100644 --- a/docs/source/api.md +++ b/docs/source/api.md @@ -61,6 +61,33 @@ as in 1.x. Every daisy entry point accepts them (or anything with integer :members: ``` +## Run report + +```{eval-rst} +.. autofunction:: daisy.last_report + +.. autoclass:: daisy.RunReport + :members: + +.. autoclass:: daisy.TaskReport + :members: + +.. autoclass:: daisy._report.BlockSummary + :members: + +.. autoclass:: daisy._report.WorkerSummary + :members: + +.. autoclass:: daisy._report.WorkerRecord + :members: + +.. autoclass:: daisy._report.BlockRecord + :members: + +.. autoclass:: daisy._report.Stat + :members: +``` + ## Progress observers ```{eval-rst} diff --git a/docs/source/design/DONE_MARKERS.md b/docs/source/design/DONE_MARKERS.md index 1c0aa8fb..d4f395f5 100644 --- a/docs/source/design/DONE_MARKERS.md +++ b/docs/source/design/DONE_MARKERS.md @@ -27,8 +27,16 @@ element-per-block grid index, so they line up element-for-element: | `io_write_bytes` | uint64 | `resource_tracking` | bytes written via syscalls | | `gpu_util_pct` | float32 | `resource_tracking` | reserved (NaN) | | `gpu_mem_bytes` | uint64 | `resource_tracking` | reserved (0) | +| `worker_id` | uint32 | `resource_tracking` | worker that completed the block (`2**32-1` = none) | +| `sent_at` | float64 | `resource_tracking` | dispatch time, seconds since the UNIX epoch (scheduler clock) | +| `returned_at` | float64 | `resource_tracking` | return time, seconds since the UNIX epoch (scheduler clock) | -See `RUN_STATS.md` for what the resource figures mean and their caveats. +Next to the arrays, `runs.jsonl` holds one JSON line per run: the task's +run report (block aggregates and the per-worker timeline). It is +append-only and ignored by zarr readers. + +See `RUN_STATS.md` for what the resource figures mean and their caveats, +and for the worker timeline the last three arrays and `runs.jsonl` feed. The index is the **C-order grid coordinate**: `(block.write_roi.offset - total_roi.offset) / write_roi.shape`, flattened row-major. Boundary blocks @@ -46,7 +54,8 @@ are simply not addressable and are skipped. ├── failures/ │ ├── zarr.json ← array metadata (uint32) │ └── c/0/0/.../0 -└── … one directory per stat array, same shape +├── … one directory per stat array, same shape +└── runs.jsonl ← one line per run (resource_tracking only) ``` Chunk paths follow Zarr v3 conventions: `c///...`, all-zero diff --git a/docs/source/design/RUN_STATS.md b/docs/source/design/RUN_STATS.md index cee4fef1..5e090975 100644 --- a/docs/source/design/RUN_STATS.md +++ b/docs/source/design/RUN_STATS.md @@ -107,34 +107,109 @@ worker or reclaimed by the timeout. A block with a high failure count and Resource Utilization -------------------- - Totals (summed over measured blocks): - blocks measured : 12 - CPU time : 0.09 s - in-block time : 0.34 s - CPU per block-s : 0.27 (≈1.0 CPU-bound, «1.0 IO-bound) - peak RSS : 27.0 MB (largest single worker) - IO read : 198.3 KB - IO write : 937.5 KB - - Per-task: - task blocks fails mean ms ∠ slope cpu s peak RSS - ───────────────────────────── ────────────────────────────────────────── - segment 12 0 28.27 ∠ -0.1883 0.09s 27.0 MB + seg 12 blocks, 3 workers, 292.1 ms wall + blocks wall 50.2 ms ± 0.0 ms cpu 60.1 µs ± 13.6 µs peak RSS 25.5 MB ± 0.0 B + io read 1.1 KB write 0.0 B overhead 372.1 µs ± 43.3 µs trend ∠ +0.0027 ms/block + workers startup 60.8 ms ± 0.1 ms idle 25.9 µs ± 33.9 µs teardown 26.4 ms ± 3.7 ms + exits 3 clean + id startup blocks idle idle / block compute compute / block teardown exit + 0 60.6 ms 4 193.9 µs 48.5 µs ± 54.2 µs 202.2 ms 50.6 ms ± 0.0 ms 23.1 ms clean + 1 60.8 ms 4 75.3 µs 18.8 µs ± 12.7 µs 202.1 ms 50.5 ms ± 0.0 ms 23.8 ms clean + 2 60.9 ms 4 41.6 µs 10.4 µs ± 7.1 µs 202.0 ms 50.5 ms ± 0.1 ms 29.0 ms clean ``` -That run's blocks each slept 20 ms and then burned a little CPU, which is -why `CPU per block-s` reads 0.27 rather than ≈1.0. `blocks measured : 12` -agreeing with the execution summary's `completed 12` is the property this -redesign exists to guarantee — in subprocess mode (the default here) the old -code printed `blocks 0`. +That run's blocks each slept 50 ms, so `wall` is 50 ms with no spread, the +CPU figure is the few microseconds of Python around the sleep, and the three +workers each took four blocks. `12 blocks` agreeing with the execution +summary's `completed 12` is the property this design exists to guarantee — +the old code printed `blocks 0` in subprocess mode. + +Every `x ± y` is a mean and sample standard deviation over a `Welford` +accumulator (`run_stats.rs`), so the report costs O(1) memory per metric. +`trend` is the least-squares slope of per-block wall time in completion +order (`run_stats::Trend`, the running form of `linear_trend`): positive +means blocks got slower as the run progressed. The panel is **omitted +entirely** when no task opted into resource tracking — a table of zeros is +worse than no table — and the per-worker table stops at ten rows, then +points at the full table on the report object. + +Programmatic access: `daisy.last_report()` (also `Server.last_report`, and +`daisy_run_report` on the `KeyboardInterrupt` / abandonment error) is a +`RunReport` of `TaskReport`s: -`mean ms ∠ slope` is a least-squares fit over per-block wall times in -completion order (`run_stats::linear_trend`): a positive slope means blocks -got slower as the run progressed. The panel is **omitted entirely** when no -task opted into resource tracking — a table of zeros is worse than no table. +```python +t = daisy.last_report()["seg"] +t.blocks.wall # Stat(n, mean, std, min, max, total), seconds +t.blocks.peak_rss # bytes +t.blocks.overhead # round trip − wall, per block +t.workers.startup # Stat over workers +t.workers.idle # Stat over per-block gaps, pooled across workers +t.worker(1) # WorkerRecord: startup, idle, compute, teardown, exit +t.block((1, 2)) # BlockRecord from the store: stats, worker_id, sent_at, returned_at +``` -Programmatic access: `daisy.Server().last_tracking_summary`, keyed -`{"per_task": {task_id: {...}}}`. +## The worker timeline + +Per-block figures say what the blocks cost; they say nothing about the time +a run spends *around* them — bringing workers up, waiting for the scheduler, +tearing down. The server stamps those from events it already handles, with +the server-assigned `worker_id` that every message carries: + +| phase | from | to | where stamped | +|---|---|---|---| +| **startup** | spawn call | first `AcquireBlock` | `rebalance_workers`, `handle_acquire` | +| **idle** | previous return (or first acquire) | `SendBlock` | `handle_acquire` | +| **compute** | `SendBlock` | `ReleaseBlock` / `BlockFailed` | `handle_acquire`, `handle_message` | +| **final wait** | last return | `RequestShutdown` | `handle_acquire` | +| **teardown** | `RequestShutdown` (or run shutdown) | spawn call returned | spawn thread's exit notifier, `check_thread_health` | + +`worker_timeline.rs` holds one `WorkerTimeline` per worker (a few +`Instant`s and two `Welford`s) and folds them per task into the report's +`workers` section; collection is always on and needs no wire change. The +server is also the only vantage point that *can* see startup and teardown: +a worker cannot report the time before its interpreter started or after its +process exited, and for a cluster spawn function (`sbatch --wait`, `srun`) +startup honestly includes the queue wait. + +What this vantage point costs, stated plainly: + +- **compute is the server round trip**, including transport and the + worker's per-block wrapper, while the block's `wall_seconds` is the + worker's narrower measurement of the user function. The difference is + reported as `overhead` per block — daisy's own cost — and is usually a + few hundred microseconds. +- **idle includes one network hop**; on a LAN that is noise, on a slow + interconnect it is real idle time. +- a worker whose last acquire reaches the server after the run has ended + never gets a reply (it sees the socket close); its teardown is counted + from the moment the server began shutting down. +- the final wait before shutdown is not an "idle before a block": it is + kept per worker (`final_wait`) and excluded from the idle aggregate. +- a failed block's round trip counts in its worker's `compute` and + `blocks_failed`; it stays out of the block-level trend. +- a worker whose block times out is closed as `exit="timeout"` when its + slot is retired; a crash is `"error"`; a worker alive at an abort is + `"interrupted"`. Only clean exits have a teardown. +- clients that connect without a server-assigned id (hand-rolled workers + outside daisy's management) are counted as `unmanaged_clients`, not timed. +- serial mode has no workers: `workers.count == 0`. + +### What is persisted + +With `resource_tracking=True` the tracking group gains three more arrays, +indexed like every other (see `DONE_MARKERS.md`): `worker_id` (uint32, +`2**32-1` = no managed worker), `sent_at` and `returned_at` (float64 +seconds since the UNIX epoch on the scheduler's clock). From those a full +Gantt-style timeline — who ran what, when, with what gaps — can be rebuilt +from the store alone. Worker ids restart at 0 every run, so the value is +"the worker, in the run that completed this block". + +The run report itself is appended as one JSON line per run to `runs.jsonl` +in the same directory: append-only, human-readable, `jq`-able, keeps history +across resumes, and ignored by zarr readers. It is the same JSON the Python +`RunReport` is built from, so the object a run returns and the record left +on disk cannot drift apart. Tasks without a store persist nothing; the +report is still built in memory. ## Narrowing what gets measured @@ -181,5 +256,10 @@ Deleted along the way: `WorkerStats`, `TaskStats`, `ProcessStats`, - `daisy-core/src/block_tracking.rs` — the zarr group, per-block writes, aggregates - `daisy-py/src/py_profile.rs` — `daisy.profile_block` - `daisy-py/python/daisy/_task.py` — the `Client.acquire_block` seam +- `daisy-core/src/run_stats.rs` — `Welford`, `Trend` +- `daisy-core/src/worker_timeline.rs` — per-worker lifecycle stamps and the workers section +- `daisy-core/src/run_report.rs` — `TaskReport`, the JSON handed to Python and appended to `runs.jsonl` +- `daisy-py/python/daisy/_report.py` — `RunReport`, `TaskReport`, `Stat`, the panel renderer - `daisy-py/python/daisy/_progress.py` — `_print_resource_utilization` - `tests/test_block_profiling.py` — cross-mode equivalence, persistence, enforcement +- `tests/test_worker_timeline.py` — lifecycle phases, `worker_id` on disk, `runs.jsonl`, block lookup diff --git a/tests/test_block_profiling.py b/tests/test_block_profiling.py index 8ce72674..9645963a 100644 --- a/tests/test_block_profiling.py +++ b/tests/test_block_profiling.py @@ -50,7 +50,7 @@ def _task(task_id, tmp_path, **kw): def _summary(server, task_id): - return server.last_tracking_summary["per_task"][task_id] + return server.last_report[task_id].blocks def test_profile_block_attaches_measurements(): @@ -105,10 +105,10 @@ def test_blocks_are_counted_and_measured(tmp_path): s = _summary(server, task.task_id) assert states[task.task_id].completed_count == 4 - assert int(s["blocks"]) == 4, "block count must match what the scheduler completed" - assert s["has_stats"] - assert s["total_cpu_secs"] > 0 - assert s["mean_block_ms"] > 0 + assert s.count == 4, "block count must match what the scheduler completed" + assert s.has_stats + assert s.cpu.total > 0 + assert s.wall.mean > 0 def test_external_worker_is_measured_without_extra_code(tmp_path): @@ -139,8 +139,8 @@ def spawn(): s = _summary(server, "external") assert states["external"].completed_count == 4 - assert int(s["blocks"]) == 4 - assert s["has_stats"], "external workers must be measured too" + assert s.count == 4 + assert s.has_stats, "external workers must be measured too" def test_stats_are_readable_from_the_tracking_group(tmp_path): @@ -240,8 +240,8 @@ def test_tracking_without_resource_tracking_omits_stat_arrays(tmp_path): assert not (root / "cpu_seconds").exists() s = _summary(server, "plain") - assert int(s["blocks"]) == 4, "blocks are counted even without resource stats" - assert not s["has_stats"] + assert s.count == 4, "blocks are counted even without resource stats" + assert not s.has_stats def test_worker_context_advertises_resource_tracking(tmp_path): @@ -276,7 +276,7 @@ def run(flag, task_id): ) server = daisy.Server() server.run_blockwise([task], progress=False) - per = server.last_tracking_summary["per_task"][task_id] + per = server.last_report[task_id].blocks arrays = sorted( p.name for p in (tmp_path / "tr" / task_id).iterdir() if p.is_dir() ) @@ -286,10 +286,10 @@ def run(flag, task_id): off, off_arrays = run(False, "unmeasured") # both ran the same work - assert on["blocks"] == off["blocks"] == 4 + assert on.count == off.count == 4 # ...but only the opted-in task measured anything - assert on["has_stats"] and set(on_arrays) > {"done", "failures"} - assert not off["has_stats"] + assert on.has_stats and set(on_arrays) > {"done", "failures"} + assert not off.has_stats assert off_arrays == ["done", "failures"] - assert off["total_cpu_secs"] == 0 - assert off["io_read_bytes"] == 0 + assert off.cpu.total == 0 + assert off.io_read.total == 0 diff --git a/tests/test_run_stats.py b/tests/test_run_stats.py index 8dfa9545..8b9348a4 100644 --- a/tests/test_run_stats.py +++ b/tests/test_run_stats.py @@ -1,4 +1,4 @@ -"""The end-of-run summary, agglomerated from per-block measurements. +"""The end-of-run report, agglomerated from per-block measurements. These tests replace an older file that had to pin in-process workers to see any counts at all — that pin existed *because* only the in-process worker @@ -14,9 +14,8 @@ import time -import pytest - import daisy +import pytest def _tracked_task(task_id, tmp_path, process_function, **kw): @@ -38,7 +37,7 @@ def _tracked_task(task_id, tmp_path, process_function, **kw): def _run(task): server = daisy.Server() states = server.run_blockwise([task], progress=False) - return states, server.last_tracking_summary["per_task"][task.task_id] + return states, server.last_report[task.task_id].blocks def _busy(_block): @@ -49,21 +48,19 @@ def _busy(_block): def test_summary_shape(tmp_path): - """The keys the renderer and users rely on.""" + """The fields the renderer and users rely on, and the JSON they + round-trip through (the same line that lands in runs.jsonl).""" _, s = _run(_tracked_task("shape", tmp_path, _busy)) - for key in ( - "blocks", - "failures", - "has_stats", - "total_cpu_secs", - "total_block_secs", - "max_peak_rss_bytes", - "io_read_bytes", - "io_write_bytes", - "mean_block_ms", - "block_ms_slope", - ): - assert key in s, f"missing summary key {key}" + for key in ("count", "failures", "has_stats", "trend_slope_ms"): + assert hasattr(s, key), f"missing report field {key}" + for stat in (s.wall, s.cpu, s.peak_rss, s.io_read, s.io_write, s.overhead): + assert stat.n == 4, stat + assert stat.min <= stat.mean <= stat.max + assert stat.std >= 0 + report = daisy.last_report() + again = daisy.RunReport.from_json(report.to_json()) + assert again["shape"].blocks == s + assert again["shape"].workers.by_id.keys() == report["shape"].workers.by_id.keys() def _busy_worker(): @@ -95,21 +92,21 @@ def test_block_count_matches_the_scheduler_for_either_function_shape( task = _tracked_task(f"count_{shape}", tmp_path, fn) states, s = _run(task) assert states[task.task_id].completed_count == 4 - assert int(s["blocks"]) == 4 - assert s["has_stats"], f"{shape} blocks must arrive measured" + assert s.count == 4 + assert s.has_stats, f"{shape} blocks must arrive measured" def test_cpu_and_wall_are_plausible(tmp_path): """CPU-bound work should burn CPU comparable to its wall time; the numbers must be real measurements, not zeros or wild values.""" _, s = _run(_tracked_task("plausible", tmp_path, _busy)) - cpu = float(s["total_cpu_secs"]) - block = float(s["total_block_secs"]) + cpu = s.cpu.total + block = s.wall.total assert cpu > 0, "busy work must register CPU time" assert block > 0 # A tight arithmetic loop is on-CPU essentially all of its wall time. assert 0.4 < cpu / block < 1.6, f"cpu/wall ratio implausible: {cpu}/{block}" - assert int(s["max_peak_rss_bytes"]) > 0 + assert s.peak_rss.max > 0 def test_sleeping_blocks_burn_wall_but_not_cpu(tmp_path): @@ -120,8 +117,8 @@ def sleeper(_block): time.sleep(0.02) _, s = _run(_tracked_task("sleepy", tmp_path, sleeper)) - cpu = float(s["total_cpu_secs"]) - block = float(s["total_block_secs"]) + cpu = s.cpu.total + block = s.wall.total assert block > 0.05, f"4 blocks x 20ms should show up as wall time: {block}" assert cpu < block / 2, f"sleeping must not be counted as CPU: {cpu} vs {block}" @@ -130,10 +127,10 @@ def test_constant_workload_reports_near_zero_slope(tmp_path): """Uniform blocks → flat trend. Deliberately generous: this asserts the trend is fed real data, not that a loaded machine is quiet.""" _, s = _run(_tracked_task("flat", tmp_path, _busy, total=[200], max_workers=1)) - assert int(s["blocks"]) == 20 - assert float(s["mean_block_ms"]) > 0 - mean = float(s["mean_block_ms"]) - slope = float(s["block_ms_slope"]) + assert s.count == 20 + assert s.wall.mean > 0 + mean = s.wall.mean * 1000.0 + slope = s.trend_slope_ms # Slope is ms-per-block; scale-free comparison against the mean. assert abs(slope) < mean, f"expected a flat-ish trend: mean={mean} slope={slope}" @@ -161,12 +158,13 @@ def slowing(block): max_workers=1, ) ) - assert int(s["blocks"]) == 10 - assert float(s["block_ms_slope"]) > 1.0, f"expected a rising trend: {s}" + assert s.count == 10 + assert s.trend_slope_ms > 1.0, f"expected a rising trend: {s}" -def test_untracked_task_reports_no_summary(tmp_path): - """No tracking configured → nothing to summarise, and the renderer +def test_untracked_task_reports_no_measurements(tmp_path): + """No tracking configured → the report still exists (worker timing is + always collected) but carries no resource figures, and the renderer omits the panel rather than printing zeros.""" task = daisy.Task( task_id="untracked", @@ -180,11 +178,16 @@ def test_untracked_task_reports_no_summary(tmp_path): server = daisy.Server() states = server.run_blockwise([task], progress=False) assert states["untracked"].completed_count == 4 - assert server.last_tracking_summary["per_task"] == {} + t = server.last_report["untracked"] + assert not t.tracked + assert not t.blocks.has_stats + assert t.blocks.count == 4 + assert t.workers.count >= 1 + assert server.last_report.render() == "" -def _render(summary): - """Render a summary and return what it printed. +def _render(report): + """Render a report and return what it printed. The renderer writes to the *saved* real stdout on purpose, so that a worker-log stdout proxy can't swallow the report. Pointing that at a @@ -193,50 +196,144 @@ def _render(summary): """ import io - from daisy._progress import _print_resource_utilization - from daisy import logging as _worker_log + from daisy._progress import _print_resource_utilization buf = io.StringIO() previous = _worker_log._saved_stdout _worker_log._saved_stdout = buf try: - _print_resource_utilization(summary) + _print_resource_utilization(report) finally: _worker_log._saved_stdout = previous return buf.getvalue() +def _stat(n, mean, std=0.0, total=None): + return { + "n": n, + "mean": mean, + "std": std, + "min": mean, + "max": mean, + "sum": mean * n if total is None else total, + } + + +def _report(**tasks): + return daisy.RunReport.from_dict( + {tid: {"task_id": tid, **body} for tid, body in tasks.items()} + ) + + def test_renderer_omits_panel_without_measurements(): """Nothing at all when no task measured anything — a table of zeros is worse than no table.""" assert _render(None) == "" - assert _render({"per_task": {}}) == "" - assert _render({"per_task": {"t": {"has_stats": False, "blocks": 4}}}) == "" + assert _render(_report()) == "" + assert _render(_report(t={"blocks": {"has_stats": False, "count": 4}})) == "" -def test_renderer_prints_measured_totals(): - """And renders real figures when there are measurements.""" +def _is_worker_row(line): + """A per-worker table row: starts with an integer id, ends with the + exit kind (the `exits N clean` summary line does not start with an id).""" + parts = line.split() + return len(parts) > 2 and parts[0].isdigit() and parts[-1] == "clean" + + +def test_renderer_prints_measured_figures(): + """And renders real figures when there are measurements: the block + line with its ± figures, the worker line, and one row per worker.""" out = _render( - { - "per_task": { - "seg": { + _report( + seg={ + "started_at": 100.0, + "finished_at": 104.1, + "tracked": True, + "blocks": { "has_stats": True, - "blocks": 12, + "count": 12, "failures": 2, - "total_cpu_secs": 1.5, - "total_block_secs": 2.0, - "max_peak_rss_bytes": 1024 * 1024, - "io_read_bytes": 2048, - "io_write_bytes": 4096, - "mean_block_ms": 166.7, - "block_ms_slope": -0.5, - } + "wall": _stat(12, 1.0, 0.2), + "cpu": _stat(12, 0.9, 0.1), + "peak_rss": _stat(12, 1024 * 1024 * 1024, 20 * 1024 * 1024), + "io_read": _stat(12, 1024.0), + "io_write": _stat(12, 2048.0), + "overhead": _stat(12, 0.003, 0.001), + "trend_slope_ms": -0.5, + }, + "workers": { + "count": 2, + "startup": _stat(2, 2.0, 0.5), + "idle": _stat(12, 0.1, 0.02), + "compute": _stat(12, 1.0, 0.2), + "teardown": _stat(2, 0.2, 0.01), + "exits": {"clean": 2}, + "by_id": [ + { + "worker_id": 0, + "startup": 2.2, + "blocks_ok": 6, + "idle": _stat(6, 0.1), + "compute": _stat(6, 1.0), + "teardown": 0.1, + "exit": "clean", + }, + { + "worker_id": 1, + "startup": 1.8, + "blocks_ok": 6, + "idle": _stat(6, 0.1), + "compute": _stat(6, 1.0), + "teardown": 0.3, + "exit": "clean", + }, + ], + }, } - } + ) ) assert "Resource Utilization" in out - assert "blocks measured : 12" in out - assert "seg" in out - # CPU-per-block-second is the IO-vs-CPU-bound hint. - assert "0.75" in out + assert "seg 12 blocks, 2 workers, 4.10 s wall" in out + assert "wall 1.00 s ± 0.20 s" in out + assert "cpu 900.0 ms ± 100.0 ms" in out + assert "peak RSS 1.0 GB ± 20.0 MB" in out + assert "overhead 3.0 ms ± 1.0 ms" in out + assert "trend ∠ -0.5000 ms/block" in out + assert "2 failed attempt(s)" in out + assert "startup 2.00 s ± 0.50 s" in out + assert "idle 100.0 ms ± 20.0 ms" in out + assert "teardown 200.0 ms ± 10.0 ms" in out + assert "exits 2 clean" in out + rows = [line for line in out.splitlines() if _is_worker_row(line)] + assert len(rows) == 2, out + assert "2.20 s" in rows[0] and "1.80 s" in rows[1] + + +def test_renderer_caps_the_worker_table(): + """A 500-worker run must not scroll the terminal: ten rows, then a + pointer at the full table on the report object.""" + rows = [ + { + "worker_id": i, + "startup": 1.0, + "blocks_ok": 1, + "idle": _stat(1, 0.1), + "compute": _stat(1, 1.0), + "teardown": 0.1, + "exit": "clean", + } + for i in range(25) + ] + out = _render( + _report( + big={ + "tracked": True, + "blocks": {"has_stats": True, "count": 25, "wall": _stat(25, 1.0)}, + "workers": {"count": 25, "exits": {"clean": 25}, "by_id": rows}, + } + ) + ) + printed = [line for line in out.splitlines() if _is_worker_row(line)] + assert len(printed) == 10 + assert "… +15 more" in out diff --git a/tests/test_worker_timeline.py b/tests/test_worker_timeline.py new file mode 100644 index 00000000..ad668cca --- /dev/null +++ b/tests/test_worker_timeline.py @@ -0,0 +1,267 @@ +"""Per-worker lifecycle timing in the run report. + +The server stamps every worker-lifecycle event it already sees (spawn, +first acquire, each dispatch and return, the shutdown reply, the spawn +thread's exit) and folds them into startup / idle / compute / teardown per +worker. Nothing crosses the wire for this, so these tests drive real +subprocess workers and check the figures are plausible, consistent with +the block counts, and persisted (``worker_id`` / ``sent_at`` / +``returned_at`` arrays and ``runs.jsonl``). +""" + +import json +import time +from pathlib import Path + +import daisy +import pytest + + +def _sleepy(_block): + time.sleep(0.05) + + +def _task(task_id, tmp_path, fn=_sleepy, *, tracked=True, n=80, **kw): + kwargs = dict( + task_id=task_id, + total_roi=daisy.Roi([0], [n]), + read_roi=daisy.Roi([0], [10]), + write_roi=daisy.Roi([0], [10]), + process_function=fn, + read_write_conflict=False, + max_workers=kw.pop("max_workers", 2), + max_retries=0, + ) + if tracked: + kwargs["tracking_path"] = str(tmp_path / f"tracking_{task_id}") + kwargs["resource_tracking"] = True + kwargs.update(kw) + return daisy.Task(**kwargs) + + +def _run(task, **kw): + server = daisy.Server() + states = server.run_blockwise([task], progress=False, **kw) + return states, server.last_report[task.task_id] + + +def test_every_worker_gets_a_full_lifecycle(tmp_path): + """Two workers draining eight sleeping blocks: both connect (startup), + both take blocks, both exit cleanly after the shutdown reply + (teardown), and their block counts add up to the task's.""" + states, t = _run(_task("life", tmp_path)) + assert states["life"].completed_count == 8 + w = t.workers + assert w.count == 2 + assert w.exits == { + "clean": 2, + "error": 0, + "timeout": 0, + "interrupted": 0, + "running": 0, + } + assert w.unmanaged_clients == 0 + assert sorted(w.by_id) == [0, 1] + for rec in w.by_id.values(): + assert rec.exit == "clean" + assert rec.startup is not None and rec.startup > 0, rec + assert rec.teardown is not None and rec.teardown >= 0, rec + assert rec.blocks_failed == 0 + assert rec.idle.n == rec.compute.n == rec.blocks_ok, rec + assert sum(r.blocks_ok for r in w.by_id.values()) == 8 + assert w.startup.n == 2 and w.teardown.n == 2 + # Pooled per-block samples: one per block handed out / returned. + assert w.idle.n == 8 and w.compute.n == 8 + + +def test_compute_idle_and_overhead_are_plausible(tmp_path): + """Blocks that sleep 50 ms must show ≈50 ms of round-trip compute per + block, a per-block overhead (round trip minus the worker's own wall + measurement) far smaller than the block, and idle gaps that are small + because the scheduler always has a block ready.""" + _, t = _run(_task("plausible", tmp_path)) + w, b = t.workers, t.blocks + assert 0.045 < w.compute.mean < 0.5, w.compute + assert w.compute.min >= 0.045, w.compute + assert b.overhead.n == 8 + assert 0 <= b.overhead.mean < 0.05, b.overhead + # overhead = round trip − wall, so the round trip is the larger one + assert w.compute.mean >= b.wall.mean, (w.compute, b.wall) + assert w.idle.mean < 0.2, w.idle + assert w.startup.mean > 0.005, w.startup # an interpreter has to come up + + +def _crash_on_connect(): + """A 0-arg worker that dies before ever acquiring a block.""" + raise RuntimeError("simulated crash at startup") + + +def test_crashed_worker_has_an_error_exit_and_no_teardown(tmp_path): + """A worker that dies before connecting has no startup and no teardown, + and is counted under ``exits["error"]``; the report still covers it.""" + task = _task( + "crashy", + tmp_path, + fn=_crash_on_connect, + tracked=False, + max_workers=1, + max_worker_restarts=1, + ) + states, t = _run(task) + assert states["crashy"].abandoned + w = t.workers + assert w.count == 2 # the first worker and its one allowed restart + assert w.exits["error"] == 2, w.exits + for rec in w.by_id.values(): + assert rec.exit == "error" + assert rec.startup is None + assert rec.teardown is None + assert rec.blocks == 0 + assert w.startup.n == 0 and w.teardown.n == 0 + + +def _record_my_worker(block): + """Write this worker's id next to the block's spatial id so the test can + check the server's `worker_id` array against ground truth.""" + import os + + import daisy + + out = Path(os.environ["DAISY_TEST_OUT"]) + wid = daisy.Context.from_env()["worker_id"] + (out / f"block-{block.block_id[1]}").write_text(str(wid)) + time.sleep(0.01) + + +def test_worker_id_on_disk_matches_who_ran_each_block(tmp_path, monkeypatch): + out = tmp_path / "who" + out.mkdir() + monkeypatch.setenv("DAISY_TEST_OUT", str(out)) + task = _task("who", tmp_path, fn=_record_my_worker, max_workers=3) + _, t = _run(task) + + seen = set() + for i in range(8): + truth = int((out / f"block-{i}").read_text()) + rec = t.block((i,)) + assert rec is not None and rec.done + assert rec.worker_id == truth, (i, rec) + assert rec.sent_at is not None and rec.returned_at is not None + assert rec.returned_at - rec.sent_at >= 0.009, rec # the 10 ms sleep + assert t.started_at <= rec.sent_at <= rec.returned_at <= t.finished_at + seen.add(truth) + assert seen <= set(t.workers.by_id) + # ...and the per-worker rows agree with the per-block stamps. + counted = {wid: 0 for wid in t.workers.by_id} + for i in range(8): + counted[int((out / f"block-{i}").read_text())] += 1 + assert {wid: r.blocks_ok for wid, r in t.workers.by_id.items()} == counted + + # The arrays are plain zarr v3, readable without daisy. + zarr = pytest.importorskip("zarr") + if int(zarr.__version__.split(".")[0]) >= 3: + g = zarr.open_group(str(tmp_path / "tracking_who"), mode="r") + wids = g["worker_id"][:] + assert [int(w) for w in wids] == [ + int((out / f"block-{i}").read_text()) for i in range(8) + ] + assert (g["returned_at"][:] >= g["sent_at"][:]).all() + + +def test_block_lookup_forms_agree_and_degrade_honestly(tmp_path): + """`TaskReport.block` takes a Block, a grid coordinate or a spatial id; + an untracked task has nothing to look up; a report rebuilt from JSON + has no task to read through and says so.""" + _, t = _run(_task("forms", tmp_path, max_workers=1)) + block = daisy.Block( + daisy.Roi([0], [80]), daisy.Roi([30], [10]), daisy.Roi([30], [10]) + ) + by_block = t.block(block) + by_coord = t.block((3,)) + by_id = t.block(3) + + def key(rec): + # BlockStats compares by identity; compare what it holds instead + return ( + rec.block_id, + rec.done, + rec.failures, + rec.worker_id, + rec.sent_at, + rec.returned_at, + rec.wall_seconds, + rec.peak_rss_bytes, + ) + + assert key(by_block) == key(by_coord) == key(by_id) + assert by_block.block_id == ("forms", 3) + assert by_block.wall_seconds >= 0.045 + assert by_block.peak_rss_bytes > 0 + assert by_block.worker_id == 0 + with pytest.raises(ValueError, match="grid coordinate"): + t.block((1, 2)) + with pytest.raises(TypeError): + t.block("3") + + _, plain = _run(_task("plain", tmp_path, tracked=False, max_workers=1)) + assert plain.block((0,)) is None + + rebuilt = daisy.RunReport.from_json(daisy.last_report().to_json()) + with pytest.raises(RuntimeError, match="no task attached"): + rebuilt["plain"].block((0,)) + + +def test_runs_jsonl_gets_one_line_per_run_and_round_trips(tmp_path): + task = _task("history", tmp_path, max_workers=1) + _, first = _run(task) + _, second = _run(task) # resumed: every block skipped via done markers + path = tmp_path / "tracking_history" / "runs.jsonl" + lines = path.read_text().splitlines() + assert len(lines) == 2 + rows = [json.loads(line) for line in lines] + assert daisy.TaskReport.from_dict(rows[0]).to_dict() == first.to_dict() + assert daisy.TaskReport.from_dict(rows[1]).to_dict() == second.to_dict() + assert rows[0]["workers"]["count"] == 1 + assert rows[1]["started_at"] >= rows[0]["finished_at"] + # The whole report also round-trips as JSON. + rt = daisy.RunReport.from_json(daisy.last_report().to_json()) + assert rt.to_dict() == daisy.last_report().to_dict() + + +def test_serial_mode_has_no_workers(tmp_path): + task = _task("serial", tmp_path, max_workers=1) + ok = daisy.run_blockwise([task], multiprocessing=False, progress=False) + assert ok + t = daisy.last_report()["serial"] + assert t.tracked and t.blocks.has_stats and t.blocks.count == 8 + assert t.workers.count == 0 + assert t.workers.by_id == {} + assert not t.blocks.overhead # no round trip to subtract from + assert "workers" not in t.render() + + +def test_panel_prints_worker_timing_only_with_resource_tracking(tmp_path, capfd): + daisy.run_blockwise([_task("shown", tmp_path)], progress=False) + out = capfd.readouterr().out + assert "Resource Utilization" in out + assert "workers startup" in out + assert " exit" in out and "clean" in out + + daisy.run_blockwise([_task("hidden", tmp_path, tracked=False)], progress=False) + out = capfd.readouterr().out + assert "Execution Summary" in out + assert "Resource Utilization" not in out + # Collected regardless: the figures are on the report. + assert daisy.last_report()["hidden"].workers.count >= 1 + + +def test_last_report_is_set_by_every_entry_point(tmp_path): + daisy.run_blockwise([_task("a", tmp_path, tracked=False)], progress=False) + assert "a" in daisy.last_report() + daisy.Server().run_blockwise([_task("b", tmp_path, tracked=False)], progress=False) + assert "b" in daisy.last_report() + daisy.run_blockwise( + [_task("c", tmp_path, tracked=False)], multiprocessing=False, progress=False + ) + assert "c" in daisy.last_report() + assert daisy.last_report()["c"].workers.count == 0 From 240cf01c019ee72440555d352e0980468d80af30 Mon Sep 17 00:00:00 2001 From: Will Date: Thu, 15 Oct 2026 15:19:48 -0700 Subject: [PATCH 2/8] Print the store-free figures in every summary MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The scheduler times every block's round trip itself, so that per-block mean ± std and the per-worker startup / idle / compute / teardown need no tracking store and now print for every distributed task. The in-worker measurements (wall, CPU, peak RSS, IO, overhead, trend) still appear only for tasks with resource_tracking=True. BlockSummary gains `round_trip`. Co-Authored-By: Claude Fable 5.1 --- CHANGELOG.md | 7 +++-- MIGRATION.md | 2 +- daisy-core/src/run_report.rs | 10 +++++-- daisy-core/src/worker_timeline.rs | 23 ++++++++++---- daisy-py/python/daisy/_report.py | 48 ++++++++++++++++++++++------- docs/source/design/RUN_STATS.md | 22 ++++++++++---- tests/test_run_stats.py | 50 ++++++++++++++++++++++++++++--- tests/test_worker_timeline.py | 31 ++++++++++++++----- 8 files changed, 156 insertions(+), 37 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index b726f192..68e8871a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -80,8 +80,11 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 shutdown reply, the spawn thread's exit — so it needs no protocol change, is always collected (O(workers) memory), and covers startup and teardown, which a worker cannot report about itself. The "Resource Utilization" - panel now prints `± ` figures, the worker line and a per-worker table - (ten rows, then a pointer) for tasks with `resource_tracking=True`. + panel prints what needs no tracking store for every distributed task — + the scheduler's per-block `round trip` and the worker line plus a + per-worker table (ten rows, then a pointer) — and the in-worker + measurements (`wall`, `cpu`, `peak RSS`, IO, `overhead`, `trend`) only + for tasks with `resource_tracking=True`. With `resource_tracking=True` the tracking store gains `worker_id`, `sent_at` and `returned_at` arrays (who ran each block and when, scheduler clock) and a `runs.jsonl` with the task's report appended once per run. diff --git a/MIGRATION.md b/MIGRATION.md index dfdb0cf6..276d4242 100644 --- a/MIGRATION.md +++ b/MIGRATION.md @@ -46,7 +46,7 @@ A few things v2 added that have no 1.x equivalent: - **Block tracking as a built-in** (`Task(tracking_path=…)` or via `set_tracking_basedir(…)`; `done_marker_path` / `set_done_marker_basedir` are deprecated aliases). A per-task Zarr v3 group recording which blocks completed (used to skip already-done work on resume) and how many times each failed. `Task.reset()` clears it for an explicit re-run. Tracking is **opt-in**: without an explicit path or a basedir set, nothing is tracked or skipped. The recommended pattern is one `set_tracking_basedir("")` call at pipeline start. Note that tracking is keyed by task_id + block geometry, *not* by your code — rerunning changed code against existing tracking resumes silently, so use distinct task_ids per pipeline version or `Task.reset()` after code changes. It is also bound to the exact task layout: changing any ROI (including growing `total_roi` for a dataset that acquired more data) invalidates it entirely; in-place migration for grown volumes is a planned enhancement (see `docs/source/design/DONE_MARKERS.md`). - **Skip masks** (`Task(skip_mask=…)`): a uint8 or bool array with one cell per block (`Task.block_grid_shape`; cell `(0, 0, …)` is the first block), nonzero = skip. Masked blocks count as skipped and release their dependents, but are not recorded as done, so the mask is a per-run input: a later run with a different mask (or none) runs them. Composes with tracking: done blocks stay done, masked blocks stay undone. Use it for blocks you know carry no work (far from a predicted surface, outside an acquired region) instead of a `check_function`, which runs a Python callable per block and cannot be seeded ahead of a run. - **Per-block resource tracking** (`Task(resource_tracking=True)`, needs a tracking path). Each block reports its wall time, CPU time, peak RSS and IO bytes, measured inside whoever ran it — so thread, subprocess and external cluster workers all report the same numbers. Values land in the tracking group as sibling arrays indexed the same way as `done`, readable with plain `zarr.open_group(...)`, and the run prints an agglomerated **Resource Utilization** summary. daisy measures the whole block body automatically; `with daisy.profile_block(block):` narrows the scope if you want to exclude your own setup. Programmatic access: `daisy.last_report()` (a `RunReport` with `mean ± std` per metric). 1.x had no equivalent. -- **Per-worker time tracking** (always on). The scheduler stamps every worker's lifecycle — spawn → first acquire (**startup**, including cluster queue time), the gap before each block (**idle**), each round trip (**compute**), and shutdown reply → exit (**teardown**) — and the run report carries them per task (`report.tasks[t].workers`, distributions over workers and blocks) and per worker (`.workers.by_id[i]`, or `.worker(i)`). Shown in the Resource Utilization panel for tasks with `resource_tracking=True`, which also persists `worker_id` / `sent_at` / `returned_at` per block in the tracking group and appends the report to `runs.jsonl` there. `report.tasks[t].block(block)` reads one block's record back. 1.x had no equivalent. +- **Per-worker time tracking** (always on). The scheduler stamps every worker's lifecycle — spawn → first acquire (**startup**, including cluster queue time), the gap before each block (**idle**), each round trip (**compute**), and shutdown reply → exit (**teardown**) — and the run report carries them per task (`report.tasks[t].workers`, distributions over workers and blocks) and per worker (`.workers.by_id[i]`, or `.worker(i)`). Printed in every summary along with the scheduler's per-block round trip (neither needs a tracking store); `resource_tracking=True` adds the in-worker measurements to the panel and persists `worker_id` / `sent_at` / `returned_at` per block in the tracking group and appends the report to `runs.jsonl` there. `report.tasks[t].block(block)` reads one block's record back. 1.x had no equivalent. - **`block_tracking` flag on `run_blockwise`** to disable done-marker tracking entirely for a run. - **`JsonProgressObserver`** — line-delimited JSON progress events, useful for piping into log aggregators or external dashboards. - **Per-task resource budgets** (`requires` per task + global `resources` dict) — coordinate worker concurrency across tasks competing for shared resources (CPU, GPU, etc.). diff --git a/daisy-core/src/run_report.rs b/daisy-core/src/run_report.rs index 760aaba5..65735654 100644 --- a/daisy-core/src/run_report.rs +++ b/daisy-core/src/run_report.rs @@ -25,6 +25,9 @@ pub struct BlockReport { pub failures: u64, /// True once any block carried resource measurements. pub has_stats: bool, + /// Server round trip per completed block (dispatch → return). Needs + /// no tracking store, so it is reported for every distributed task. + pub round_trip: Welford, pub wall: Welford, pub cpu: Welford, pub peak_rss: Welford, @@ -39,11 +42,12 @@ pub struct BlockReport { } impl BlockReport { - fn from_summary(s: &TaskSummary, overhead: Welford) -> Self { + fn from_summary(s: &TaskSummary, round_trip: Welford, overhead: Welford) -> Self { Self { count: s.blocks_recorded, failures: s.failures_recorded, has_stats: s.has_stats, + round_trip, wall: s.wall.clone(), cpu: s.cpu.clone(), peak_rss: s.peak_rss.clone(), @@ -87,13 +91,15 @@ pub fn build_reports( counters .iter() .map(|(task_id, c)| { + let round_trip = timeline.round_trip(task_id); let overhead = timeline.overhead(task_id); let (tracked, blocks) = match summaries.get(task_id) { - Some(s) => (true, BlockReport::from_summary(s, overhead)), + Some(s) => (true, BlockReport::from_summary(s, round_trip, overhead)), None => ( false, BlockReport { count: c.completed_count.max(0) as u64, + round_trip, overhead, ..BlockReport::default() }, diff --git a/daisy-core/src/worker_timeline.rs b/daisy-core/src/worker_timeline.rs index 0b3e82ae..79f2c57f 100644 --- a/daisy-core/src/worker_timeline.rs +++ b/daisy-core/src/worker_timeline.rs @@ -240,6 +240,10 @@ pub struct WorkerReport { #[derive(Debug, Default)] struct TaskSide { + /// Server round trip per successfully returned block, managed and + /// unmanaged clients alike — the block-level time figure that needs + /// no tracking store. + round_trip: Welford, /// Round trip minus the worker's own `wall_seconds`, per measured block. overhead: Welford, unmanaged: HashSet, @@ -331,12 +335,12 @@ impl RunTimeline { Some(w) => w.block_returned(now, sent_at, ok), None => now.duration_since(sent_at).as_secs_f64(), }; + let side = self.tasks.entry(task_id.to_string()).or_default(); + if ok { + side.round_trip.push(elapsed); + } if let Some(wall) = wall_seconds { - self.tasks - .entry(task_id.to_string()) - .or_default() - .overhead - .push((elapsed - wall).max(0.0)); + side.overhead.push((elapsed - wall).max(0.0)); } now } @@ -377,6 +381,13 @@ impl RunTimeline { } } + pub fn round_trip(&self, task_id: &str) -> Welford { + self.tasks + .get(task_id) + .map(|t| t.round_trip.clone()) + .unwrap_or_default() + } + pub fn overhead(&self, task_id: &str) -> Welford { self.tasks .get(task_id) @@ -527,6 +538,8 @@ mod tests { assert_eq!((a.exits.clean, a.exits.error), (1, 1)); assert_eq!(a.by_id.len(), 2); assert_eq!(t.overhead("a").n(), 1); + assert_eq!(t.round_trip("a").n(), 2); + assert!(t.round_trip("b").is_empty()); let b = t.report_for("b"); assert_eq!(b.count, 1); diff --git a/daisy-py/python/daisy/_report.py b/daisy-py/python/daisy/_report.py index 55bd712d..0fa36249 100644 --- a/daisy-py/python/daisy/_report.py +++ b/daisy-py/python/daisy/_report.py @@ -132,13 +132,18 @@ def __str__(self) -> str: @dataclass(frozen=True) class BlockSummary: - """Per-block figures for one task over this run. The ``Stat`` fields - are empty unless the task set ``resource_tracking=True``; ``overhead`` - (server round trip minus the block's own wall time) likewise.""" + """Per-block figures for one task over this run. + + ``round_trip`` (dispatch → return, measured by the scheduler) needs no + tracking store and is there for every distributed task. The remaining + ``Stat`` fields are measured inside the worker and are empty unless the + task set ``resource_tracking=True``; ``overhead`` is the round trip + minus the block's own wall time.""" count: int = 0 failures: int = 0 has_stats: bool = False + round_trip: Stat = field(default_factory=Stat) wall: Stat = field(default_factory=Stat) cpu: Stat = field(default_factory=Stat) peak_rss: Stat = field(default_factory=Stat) @@ -154,6 +159,7 @@ def from_dict(cls, d) -> BlockSummary: count=int(d.get("count", 0)), failures=int(d.get("failures", 0)), has_stats=bool(d.get("has_stats", False)), + round_trip=Stat.from_dict(d.get("round_trip")), wall=Stat.from_dict(d.get("wall")), cpu=Stat.from_dict(d.get("cpu")), peak_rss=Stat.from_dict(d.get("peak_rss")), @@ -168,6 +174,7 @@ def to_dict(self) -> dict: "count": self.count, "failures": self.failures, "has_stats": self.has_stats, + "round_trip": self.round_trip.to_dict(), "wall": self.wall.to_dict(), "cpu": self.cpu.to_dict(), "peak_rss": self.peak_rss.to_dict(), @@ -396,9 +403,15 @@ def render(self, max_workers: int = 10) -> str: if self.elapsed > 0: head += f", {_format_secs(self.elapsed)} wall" lines.append(head) + # Always available: the scheduler's own per-block round trip. + label = " blocks " + if b.round_trip: + lines.append(f"{label} round trip {b.round_trip.format()}") + label = " " + # Measured inside the worker: only with resource_tracking=True. if b.has_stats: lines.append( - f" blocks wall {b.wall.format()} cpu {b.cpu.format()}" + f"{label} wall {b.wall.format()} cpu {b.cpu.format()}" f" peak RSS {b.peak_rss.format('B')}" ) second = ( @@ -409,8 +422,8 @@ def render(self, max_workers: int = 10) -> str: second += f" overhead {b.overhead.format()}" second += f" trend ∠ {b.trend_slope_ms:+.4f} ms/block" lines.append(second) - if b.failures: - lines.append(f" {b.failures} failed attempt(s)") + if b.failures: + lines.append(f" {b.failures} failed attempt(s)") if w.count: lines.append( f" workers startup {w.startup.format()} idle {w.idle.format()}" @@ -500,6 +513,17 @@ def measured(self) -> dict: """The tasks that measured their blocks (``resource_tracking=True``).""" return {tid: t for tid, t in self.tasks.items() if t.blocks.has_stats} + @property + def timed(self) -> dict: + """The tasks with anything to show: a worker timeline, a per-block + round trip, or resource measurements. A serial task without + resource tracking has none of these.""" + return { + tid: t + for tid, t in self.tasks.items() + if t.workers.count or t.blocks.round_trip or t.blocks.has_stats + } + def _attach(self, tasks) -> None: """Give each task report the `daisy.Task` it came from, for `TaskReport.block`.""" @@ -509,10 +533,14 @@ def _attach(self, tasks) -> None: self.tasks[tid]._task = task def render(self, task_order=None, max_workers: int = 10) -> str: - """The Resource Utilization panel: one section per task that - measured its blocks, in ``task_order``. Empty when no task did — - a table of zeros is worse than no table.""" - measured = self.measured + """The Resource Utilization panel, one section per task in + ``task_order``. What needs no tracking store — the per-block round + trip and the per-worker startup / idle / compute / teardown — is + always shown; the in-worker measurements (wall, CPU, RSS, IO, + overhead, trend) only for tasks with ``resource_tracking=True``. + Empty when there is nothing at all to show (a serial run without + resource tracking) — a table of zeros is worse than no table.""" + measured = self.timed if not measured: return "" if task_order is None: diff --git a/docs/source/design/RUN_STATS.md b/docs/source/design/RUN_STATS.md index 5e090975..49245e22 100644 --- a/docs/source/design/RUN_STATS.md +++ b/docs/source/design/RUN_STATS.md @@ -108,7 +108,8 @@ Resource Utilization -------------------- seg 12 blocks, 3 workers, 292.1 ms wall - blocks wall 50.2 ms ± 0.0 ms cpu 60.1 µs ± 13.6 µs peak RSS 25.5 MB ± 0.0 B + blocks round trip 50.5 ms ± 0.1 ms + wall 50.2 ms ± 0.0 ms cpu 60.1 µs ± 13.6 µs peak RSS 25.5 MB ± 0.0 B io read 1.1 KB write 0.0 B overhead 372.1 µs ± 43.3 µs trend ∠ +0.0027 ms/block workers startup 60.8 ms ± 0.1 ms idle 25.9 µs ± 33.9 µs teardown 26.4 ms ± 3.7 ms exits 3 clean @@ -128,10 +129,18 @@ Every `x ± y` is a mean and sample standard deviation over a `Welford` accumulator (`run_stats.rs`), so the report costs O(1) memory per metric. `trend` is the least-squares slope of per-block wall time in completion order (`run_stats::Trend`, the running form of `linear_trend`): positive -means blocks got slower as the run progressed. The panel is **omitted -entirely** when no task opted into resource tracking — a table of zeros is -worse than no table — and the per-worker table stops at ten rows, then -points at the full table on the report object. +means blocks got slower as the run progressed. + +What prints is decided by what it costs. The figures that need **no tracking +store** — the per-block `round trip` the scheduler times itself, and the +per-worker startup / idle / compute / teardown — are printed for every +distributed task, always. The figures measured **inside the worker** and +persisted to the store (`wall`, `cpu`, `peak RSS`, IO, `overhead`, `trend`) +appear only for tasks with `resource_tracking=True`. The panel is omitted +only when there is nothing at all to show (a serial run without resource +tracking) — a table of zeros is worse than no table — and the per-worker +table stops at ten rows, then points at the full table on the report +object. Programmatic access: `daisy.last_report()` (also `Server.last_report`, and `daisy_run_report` on the `KeyboardInterrupt` / abandonment error) is a @@ -139,7 +148,8 @@ Programmatic access: `daisy.last_report()` (also `Server.last_report`, and ```python t = daisy.last_report()["seg"] -t.blocks.wall # Stat(n, mean, std, min, max, total), seconds +t.blocks.round_trip # Stat(n, mean, std, min, max, total), seconds; always there +t.blocks.wall # the worker's own measurement; resource_tracking only t.blocks.peak_rss # bytes t.blocks.overhead # round trip − wall, per block t.workers.startup # Stat over workers diff --git a/tests/test_run_stats.py b/tests/test_run_stats.py index 8b9348a4..b1c267c6 100644 --- a/tests/test_run_stats.py +++ b/tests/test_run_stats.py @@ -183,7 +183,11 @@ def test_untracked_task_reports_no_measurements(tmp_path): assert not t.blocks.has_stats assert t.blocks.count == 4 assert t.workers.count >= 1 - assert server.last_report.render() == "" + # The store-free figures still print: round trip and worker timing... + out = server.last_report.render() + assert "round trip" in out and "workers startup" in out + # ...but nothing that needs the store. + assert "cpu" not in out and "peak RSS" not in out and "trend" not in out def _render(report): @@ -226,14 +230,50 @@ def _report(**tasks): ) -def test_renderer_omits_panel_without_measurements(): - """Nothing at all when no task measured anything — a table of zeros is - worse than no table.""" +def test_renderer_omits_panel_without_anything_to_show(): + """Nothing at all when no task has a round trip, a worker or a + measurement (a serial run without resource tracking) — a table of + zeros is worse than no table.""" assert _render(None) == "" assert _render(_report()) == "" assert _render(_report(t={"blocks": {"has_stats": False, "count": 4}})) == "" +def test_renderer_prints_store_free_figures_without_resource_tracking(): + """Round trip and worker timing need no tracking store, so they print + for every distributed task; the in-worker measurements do not.""" + out = _render( + _report( + plain={ + "blocks": {"count": 4, "round_trip": _stat(4, 0.05, 0.001)}, + "workers": { + "count": 1, + "startup": _stat(1, 0.1), + "idle": _stat(4, 0.001), + "compute": _stat(4, 0.05, 0.001), + "teardown": _stat(1, 0.02), + "exits": {"clean": 1}, + "by_id": [ + { + "worker_id": 0, + "startup": 0.1, + "blocks_ok": 4, + "idle": _stat(4, 0.001), + "compute": _stat(4, 0.05), + "teardown": 0.02, + "exit": "clean", + } + ], + }, + } + ) + ) + assert "plain 4 blocks, 1 worker" in out + assert "blocks round trip 50.0 ms ± 1.0 ms" in out + assert "workers startup 100.0 ms idle 1.0 ms" in out + assert "cpu" not in out and "peak RSS" not in out and "io read" not in out + + def _is_worker_row(line): """A per-worker table row: starts with an integer id, ends with the exit kind (the `exits N clean` summary line does not start with an id).""" @@ -254,6 +294,7 @@ def test_renderer_prints_measured_figures(): "has_stats": True, "count": 12, "failures": 2, + "round_trip": _stat(12, 1.003, 0.2), "wall": _stat(12, 1.0, 0.2), "cpu": _stat(12, 0.9, 0.1), "peak_rss": _stat(12, 1024 * 1024 * 1024, 20 * 1024 * 1024), @@ -295,6 +336,7 @@ def test_renderer_prints_measured_figures(): ) assert "Resource Utilization" in out assert "seg 12 blocks, 2 workers, 4.10 s wall" in out + assert "blocks round trip 1.00 s ± 0.20 s" in out assert "wall 1.00 s ± 0.20 s" in out assert "cpu 900.0 ms ± 100.0 ms" in out assert "peak RSS 1.0 GB ± 20.0 MB" in out diff --git a/tests/test_worker_timeline.py b/tests/test_worker_timeline.py index ad668cca..4df72362 100644 --- a/tests/test_worker_timeline.py +++ b/tests/test_worker_timeline.py @@ -236,23 +236,40 @@ def test_serial_mode_has_no_workers(tmp_path): assert t.tracked and t.blocks.has_stats and t.blocks.count == 8 assert t.workers.count == 0 assert t.workers.by_id == {} + assert not t.blocks.round_trip # nothing was dispatched over TCP assert not t.blocks.overhead # no round trip to subtract from - assert "workers" not in t.render() + assert "workers" not in t.render() and "round trip" not in t.render() + assert "wall" in t.render() + plain = _task("serial_plain", tmp_path, tracked=False, max_workers=1) + daisy.run_blockwise([plain], multiprocessing=False, progress=False) + assert daisy.last_report().render() == "" -def test_panel_prints_worker_timing_only_with_resource_tracking(tmp_path, capfd): - daisy.run_blockwise([_task("shown", tmp_path)], progress=False) + +def test_panel_always_prints_store_free_figures(tmp_path, capfd): + """Round trip and worker timing need no tracking store, so every + summary shows them; the in-worker measurements (wall, CPU, RSS, IO, + overhead, trend) appear only with resource_tracking=True.""" + daisy.run_blockwise([_task("measured", tmp_path)], progress=False) out = capfd.readouterr().out assert "Resource Utilization" in out + assert "blocks round trip" in out + assert "wall" in out and "cpu" in out and "peak RSS" in out assert "workers startup" in out assert " exit" in out and "clean" in out - daisy.run_blockwise([_task("hidden", tmp_path, tracked=False)], progress=False) + daisy.run_blockwise([_task("plain", tmp_path, tracked=False)], progress=False) out = capfd.readouterr().out assert "Execution Summary" in out - assert "Resource Utilization" not in out - # Collected regardless: the figures are on the report. - assert daisy.last_report()["hidden"].workers.count >= 1 + assert "Resource Utilization" in out + assert "blocks round trip" in out + assert "workers startup" in out and "clean" in out + for needs_store in ("cpu", "peak RSS", "io read", "overhead", "trend"): + assert needs_store not in out, needs_store + t = daisy.last_report()["plain"] + assert t.blocks.round_trip.n == 8 + assert 0.045 < t.blocks.round_trip.mean < 0.5 + assert not t.blocks.wall def test_last_report_is_set_by_every_entry_point(tmp_path): From 421f92da17eb24aae54da88119cc82694a5c5be5 Mon Sep 17 00:00:00 2001 From: Will Date: Mon, 19 Oct 2026 17:03:28 -0700 Subject: [PATCH 3/8] Task.run_blockwise() and Task.report() `task.run_blockwise(**kwargs)` runs a single task through daisy.run_blockwise; `task.report()` returns the task's TaskReport from the most recent run that included it. The report is wired to its tasks on the error paths too, so an interrupted or abandoned run still leaves its partial figures on the task. Co-Authored-By: Claude Fable 5.1 --- CHANGELOG.md | 3 +++ daisy-py/python/daisy/_report.py | 14 ++++++++++---- daisy-py/python/daisy/_runner.py | 25 ++++++++++++++++++++++--- daisy-py/python/daisy/_task.py | 17 +++++++++++++++++ docs/source/design/RUN_STATS.md | 7 +++++-- tests/test_worker_timeline.py | 27 +++++++++++++++++++++++++++ 6 files changed, 84 insertions(+), 9 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 68e8871a..334fc1e3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -75,6 +75,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 distributions, exit kinds, and a row per worker under `by_id`). `TaskReport.worker(id)` and `TaskReport.block(block | grid coord | id)` drill down; the latter reads the tracking store (`Task.block_record`). + `Task.run_blockwise(**kwargs)` runs a task on its own and `Task.report()` + returns its section of the most recent run's report, also after an + interrupted or abandoned run. Worker timing is stamped by the server from the lifecycle events it already sees — spawn, first acquire, each dispatch and return, the shutdown reply, the spawn thread's exit — so it needs no protocol change, diff --git a/daisy-py/python/daisy/_report.py b/daisy-py/python/daisy/_report.py index 0fa36249..ab8b8dea 100644 --- a/daisy-py/python/daisy/_report.py +++ b/daisy-py/python/daisy/_report.py @@ -525,12 +525,18 @@ def timed(self) -> dict: } def _attach(self, tasks) -> None: - """Give each task report the `daisy.Task` it came from, for - `TaskReport.block`.""" + """Give each task report the `daisy.Task` it came from (for + `TaskReport.block`) and each task its report (for `Task.report`).""" for task in tasks: tid = getattr(task, "task_id", None) - if tid in self.tasks: - self.tasks[tid]._task = task + if tid not in self.tasks: + continue + self.tasks[tid]._task = task + try: + task._last_report = self.tasks[tid] + except AttributeError: + # a bare native task (no instance dict) cannot carry it + pass def render(self, task_order=None, max_workers: int = 10) -> str: """The Resource Utilization panel, one section per task in diff --git a/daisy-py/python/daisy/_runner.py b/daisy-py/python/daisy/_runner.py index f2196874..ab995f51 100644 --- a/daisy-py/python/daisy/_runner.py +++ b/daisy-py/python/daisy/_runner.py @@ -44,6 +44,16 @@ def _prepare(pipeline, distributed=True): return _rs.Pipeline(wrapped, new_edges) +def _attach_report(report_or_exc, tasks): + """Wire the run's report to the tasks it covers — `TaskReport.block` + needs the task, `Task.report` needs the report. On the error paths + (KeyboardInterrupt, abandonment) the partial report rides on the + exception as ``daisy_run_report``.""" + report = getattr(report_or_exc, "daisy_run_report", report_or_exc) + if report is not None and hasattr(report, "_attach"): + report._attach(tasks) + + class Server: """Coordinator. Thin shim over `_rs._run_distributed_server` that wraps process functions with per-worker logging context first. @@ -91,9 +101,12 @@ def run_blockwise( host=host, block_tracking=block_tracking, ) + except BaseException as e: + _attach_report(e, original.tasks) + raise finally: _worker_log.close_all_log_files() - report._attach(original.tasks) + _attach_report(report, original.tasks) self.last_report = report rec.set(states, report) return states @@ -109,9 +122,12 @@ def _run_serial(pipeline, block_tracking=True, summary=True): rec.order = order try: states, report = _rs._run_serial(pipeline, block_tracking=block_tracking) + except BaseException as e: + _attach_report(e, original.tasks) + raise finally: _worker_log.close_all_log_files() - report._attach(original.tasks) + _attach_report(report, original.tasks) rec.set(states, report) return states @@ -196,9 +212,12 @@ def run_blockwise( block_tracking=block_tracking, host=host, ) + except BaseException as e: + _attach_report(e, original.tasks) + raise finally: _worker_log.close_all_log_files() - report._attach(original.tasks) + _attach_report(report, original.tasks) rec.set(states, report) if return_states: return states diff --git a/daisy-py/python/daisy/_task.py b/daisy-py/python/daisy/_task.py index fcc98c93..d4f92a1c 100644 --- a/daisy-py/python/daisy/_task.py +++ b/daisy-py/python/daisy/_task.py @@ -287,6 +287,23 @@ def failed_blocks(self): store, as `Block`s.""" return _blocks(super().failed_blocks()) + def run_blockwise(self, **kwargs): + """Run this task on its own: ``daisy.run_blockwise(task, **kwargs)``. + Returns what `daisy.run_blockwise` returns (a bool, or the states + dict with ``return_states=True``); the run's figures are on + `Task.report` afterwards.""" + from daisy._runner import run_blockwise + + return run_blockwise(self, **kwargs) + + def report(self): + """This task's `TaskReport` from the most recent run that included + it — per-block ``mean ± std`` and per-worker startup / idle / + compute / teardown — or None if it has not run in this process. + Set whether the run finished, was interrupted or was abandoned. + The same object is ``daisy.last_report()[task.task_id]``.""" + return getattr(self, "_last_report", None) + def _block_fn_arity(fn): """Positional arity of a process function: 0 means a worker function diff --git a/docs/source/design/RUN_STATS.md b/docs/source/design/RUN_STATS.md index 49245e22..fd051e83 100644 --- a/docs/source/design/RUN_STATS.md +++ b/docs/source/design/RUN_STATS.md @@ -144,10 +144,13 @@ object. Programmatic access: `daisy.last_report()` (also `Server.last_report`, and `daisy_run_report` on the `KeyboardInterrupt` / abandonment error) is a -`RunReport` of `TaskReport`s: +`RunReport` of `TaskReport`s, and each task that took part carries its own +section as `task.report()`: ```python -t = daisy.last_report()["seg"] +task = daisy.Task("seg", ...) +task.run_blockwise() +t = task.report() # the same object as daisy.last_report()["seg"] t.blocks.round_trip # Stat(n, mean, std, min, max, total), seconds; always there t.blocks.wall # the worker's own measurement; resource_tracking only t.blocks.peak_rss # bytes diff --git a/tests/test_worker_timeline.py b/tests/test_worker_timeline.py index 4df72362..c690b1b4 100644 --- a/tests/test_worker_timeline.py +++ b/tests/test_worker_timeline.py @@ -282,3 +282,30 @@ def test_last_report_is_set_by_every_entry_point(tmp_path): ) assert "c" in daisy.last_report() assert daisy.last_report()["c"].workers.count == 0 + + +def test_task_run_blockwise_and_report(tmp_path): + """The one-object form: build a task, run it, read its figures off it.""" + task = _task("solo", tmp_path, tracked=False) + assert task.report() is None + assert task.run_blockwise(progress=False) is True + t = task.report() + assert t is not None and t.task_id == "solo" + assert t is daisy.last_report()["solo"] + assert t.blocks.count == 8 and t.blocks.round_trip.n == 8 + assert t.workers.count >= 1 and t.workers.exits["clean"] == t.workers.count + assert t.worker(0).startup > 0 + + # Abandonment raises, but the partial report still lands on the task. + crashy = _task( + "crashy_solo", + tmp_path, + fn=_crash_on_connect, + tracked=False, + max_workers=1, + max_worker_restarts=0, + ) + with pytest.raises(RuntimeError, match="abandoned"): + crashy.run_blockwise(progress=False) + assert crashy.report().workers.exits["error"] == 1 + assert crashy.report().blocks.count == 0 From 220b4b38328c12cf3f4a63eb2fad9d6fcd2e6509 Mon Sep 17 00:00:00 2001 From: Will Date: Mon, 19 Oct 2026 17:12:02 -0700 Subject: [PATCH 4/8] Task.report() reads the persisted runs.jsonl; drop daisy.last_report() A task's report is now looked up on disk, not in memory: the last line of its runs.jsonl, in its tracking store when it has one, else under // next to its worker logs (written by the Python layer for tasks without a store, under the same condition as worker logs). So `task.report()` works in a later process and reflects whichever run of the task happened last; the in-memory copy is only the fallback when nothing could be persisted. `Task.tracking_path` exposes the resolved store directory. The module-level `daisy.last_report()` is gone; `Server.last_report` remains the whole-pipeline view of one server's run. Co-Authored-By: Claude Fable 5.1 --- CHANGELOG.md | 22 ++++---- MIGRATION.md | 4 +- daisy-py/python/daisy/__init__.py | 2 - daisy-py/python/daisy/_daisy.pyi | 2 + daisy-py/python/daisy/_progress.py | 3 -- daisy-py/python/daisy/_report.py | 80 +++++++++++++++++++++++------- daisy-py/python/daisy/_runner.py | 22 ++++---- daisy-py/python/daisy/_task.py | 24 +++++++-- daisy-py/python/daisy/v1_compat.py | 2 - daisy-py/python/daisy/v2.py | 3 +- daisy-py/src/py_task.rs | 9 ++++ docs/source/api.md | 2 - docs/source/design/RUN_STATS.md | 36 ++++++++++---- tests/test_run_stats.py | 8 +-- tests/test_worker_timeline.py | 75 ++++++++++++++++++++++------ 15 files changed, 210 insertions(+), 84 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 334fc1e3..c9c8fef1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -65,10 +65,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added -- **Per-worker time tracking and the run report.** Every run now returns a - `daisy.RunReport` (`daisy.last_report()`, `Server.last_report`, and - `daisy_run_report` on the `KeyboardInterrupt` / abandonment error) with - one `TaskReport` per task: `blocks` (count, failures, and `mean ± std` +- **Per-worker time tracking and the run report.** Every run now produces + a `daisy.RunReport` (`Server.last_report`, and `daisy_run_report` on the + `KeyboardInterrupt` / abandonment error) with one `TaskReport` per task, + read back per task with `task.report()`: `blocks` (count, failures, and `mean ± std` for wall, CPU, peak RSS, IO, plus the per-block `overhead` — server round trip minus the worker's own wall time — and the wall-time trend) and `workers` (count, `startup`, `idle`, `compute`, `teardown` as @@ -76,8 +76,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 `TaskReport.worker(id)` and `TaskReport.block(block | grid coord | id)` drill down; the latter reads the tracking store (`Task.block_record`). `Task.run_blockwise(**kwargs)` runs a task on its own and `Task.report()` - returns its section of the most recent run's report, also after an - interrupted or abandoned run. + returns its section of its most recent run's report, read from the + persisted `runs.jsonl`, so it works in a later process and after an + interrupted or abandoned run. `Task.tracking_path` is the resolved store + directory (None without a persistent store). Worker timing is stamped by the server from the lifecycle events it already sees — spawn, first acquire, each dispatch and return, the shutdown reply, the spawn thread's exit — so it needs no protocol change, @@ -88,9 +90,11 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 per-worker table (ten rows, then a pointer) — and the in-worker measurements (`wall`, `cpu`, `peak RSS`, IO, `overhead`, `trend`) only for tasks with `resource_tracking=True`. - With `resource_tracking=True` the tracking store gains `worker_id`, - `sent_at` and `returned_at` arrays (who ran each block and when, scheduler - clock) and a `runs.jsonl` with the task's report appended once per run. + Every task's report is appended once per run to a `runs.jsonl`: in its + tracking store when it has one, else under `//` + next to its worker logs. With `resource_tracking=True` the tracking store + also gains `worker_id`, `sent_at` and `returned_at` arrays (who ran each + block and when, scheduler clock). **Removed**: `Server.last_tracking_summary` and the `{"per_task": {...}}` dict it held; `daisy_run_stats` on the partial-run errors (now `daisy_run_report`). diff --git a/MIGRATION.md b/MIGRATION.md index 276d4242..2159dc2d 100644 --- a/MIGRATION.md +++ b/MIGRATION.md @@ -45,8 +45,8 @@ A few things v2 added that have no 1.x equivalent: - **Block tracking as a built-in** (`Task(tracking_path=…)` or via `set_tracking_basedir(…)`; `done_marker_path` / `set_done_marker_basedir` are deprecated aliases). A per-task Zarr v3 group recording which blocks completed (used to skip already-done work on resume) and how many times each failed. `Task.reset()` clears it for an explicit re-run. Tracking is **opt-in**: without an explicit path or a basedir set, nothing is tracked or skipped. The recommended pattern is one `set_tracking_basedir("")` call at pipeline start. Note that tracking is keyed by task_id + block geometry, *not* by your code — rerunning changed code against existing tracking resumes silently, so use distinct task_ids per pipeline version or `Task.reset()` after code changes. It is also bound to the exact task layout: changing any ROI (including growing `total_roi` for a dataset that acquired more data) invalidates it entirely; in-place migration for grown volumes is a planned enhancement (see `docs/source/design/DONE_MARKERS.md`). - **Skip masks** (`Task(skip_mask=…)`): a uint8 or bool array with one cell per block (`Task.block_grid_shape`; cell `(0, 0, …)` is the first block), nonzero = skip. Masked blocks count as skipped and release their dependents, but are not recorded as done, so the mask is a per-run input: a later run with a different mask (or none) runs them. Composes with tracking: done blocks stay done, masked blocks stay undone. Use it for blocks you know carry no work (far from a predicted surface, outside an acquired region) instead of a `check_function`, which runs a Python callable per block and cannot be seeded ahead of a run. -- **Per-block resource tracking** (`Task(resource_tracking=True)`, needs a tracking path). Each block reports its wall time, CPU time, peak RSS and IO bytes, measured inside whoever ran it — so thread, subprocess and external cluster workers all report the same numbers. Values land in the tracking group as sibling arrays indexed the same way as `done`, readable with plain `zarr.open_group(...)`, and the run prints an agglomerated **Resource Utilization** summary. daisy measures the whole block body automatically; `with daisy.profile_block(block):` narrows the scope if you want to exclude your own setup. Programmatic access: `daisy.last_report()` (a `RunReport` with `mean ± std` per metric). 1.x had no equivalent. -- **Per-worker time tracking** (always on). The scheduler stamps every worker's lifecycle — spawn → first acquire (**startup**, including cluster queue time), the gap before each block (**idle**), each round trip (**compute**), and shutdown reply → exit (**teardown**) — and the run report carries them per task (`report.tasks[t].workers`, distributions over workers and blocks) and per worker (`.workers.by_id[i]`, or `.worker(i)`). Printed in every summary along with the scheduler's per-block round trip (neither needs a tracking store); `resource_tracking=True` adds the in-worker measurements to the panel and persists `worker_id` / `sent_at` / `returned_at` per block in the tracking group and appends the report to `runs.jsonl` there. `report.tasks[t].block(block)` reads one block's record back. 1.x had no equivalent. +- **Per-block resource tracking** (`Task(resource_tracking=True)`, needs a tracking path). Each block reports its wall time, CPU time, peak RSS and IO bytes, measured inside whoever ran it — so thread, subprocess and external cluster workers all report the same numbers. Values land in the tracking group as sibling arrays indexed the same way as `done`, readable with plain `zarr.open_group(...)`, and the run prints an agglomerated **Resource Utilization** summary. daisy measures the whole block body automatically; `with daisy.profile_block(block):` narrows the scope if you want to exclude your own setup. Programmatic access: `task.report()` (a `TaskReport` with `mean ± std` per metric, read from the persisted `runs.jsonl`). 1.x had no equivalent. +- **Per-worker time tracking** (always on). The scheduler stamps every worker's lifecycle — spawn → first acquire (**startup**, including cluster queue time), the gap before each block (**idle**), each round trip (**compute**), and shutdown reply → exit (**teardown**) — and the run report carries them per task (`task.report().workers`, distributions over workers and blocks) and per worker (`.workers.by_id[i]`, or `.worker(i)`). Printed in every summary along with the scheduler's per-block round trip (neither needs a tracking store); `resource_tracking=True` adds the in-worker measurements to the panel and persists `worker_id` / `sent_at` / `returned_at` per block in the tracking group and the report is appended to `runs.jsonl` (in the tracking store, else next to the worker logs) so `task.report()` reads it back in any later process; `task.report().block(block)` reads one block's record back. 1.x had no equivalent. - **`block_tracking` flag on `run_blockwise`** to disable done-marker tracking entirely for a run. - **`JsonProgressObserver`** — line-delimited JSON progress events, useful for piping into log aggregators or external dashboards. - **Per-task resource budgets** (`requires` per task + global `resources` dict) — coordinate worker concurrency across tasks competing for shared resources (CPU, GPU, etc.). diff --git a/daisy-py/python/daisy/__init__.py b/daisy-py/python/daisy/__init__.py index 6585b09a..cc06a7e2 100644 --- a/daisy-py/python/daisy/__init__.py +++ b/daisy-py/python/daisy/__init__.py @@ -35,7 +35,6 @@ __version__, get_done_marker_basedir, get_tracking_basedir, - last_report, profile_block, run_blockwise, set_done_marker_basedir, @@ -65,7 +64,6 @@ "get_done_marker_basedir", "get_tracking_basedir", "get_worker_log_basename", - "last_report", "run_blockwise", "set_done_marker_basedir", "set_tracking_basedir", diff --git a/daisy-py/python/daisy/_daisy.pyi b/daisy-py/python/daisy/_daisy.pyi index 871a6a71..d84da2f5 100644 --- a/daisy-py/python/daisy/_daisy.pyi +++ b/daisy-py/python/daisy/_daisy.pyi @@ -229,6 +229,8 @@ class Task: @property def done_marker_path(self) -> str | bool | None: ... @property + def tracking_path(self) -> str | None: ... + @property def resource_tracking(self) -> bool: ... @property def block_grid_shape(self) -> list[int]: ... diff --git a/daisy-py/python/daisy/_progress.py b/daisy-py/python/daisy/_progress.py index 83fd7692..623af3d2 100644 --- a/daisy-py/python/daisy/_progress.py +++ b/daisy-py/python/daisy/_progress.py @@ -177,7 +177,6 @@ def set(self, states, report=None, order=None): self.states = states if report is not None: self.report = report - _report._set_last(report) if order is not None: self.order = order @@ -215,8 +214,6 @@ def __exit__(self, exc_type, exc, tb): states = getattr(exc, "daisy_states", None) order = getattr(exc, "daisy_task_order", None) or order report = getattr(exc, "daisy_run_report", None) - if report is not None: - _report._set_last(report) if states is None: return False if isinstance(exc, KeyboardInterrupt): diff --git a/daisy-py/python/daisy/_report.py b/daisy-py/python/daisy/_report.py index ab8b8dea..abee8bfa 100644 --- a/daisy-py/python/daisy/_report.py +++ b/daisy-py/python/daisy/_report.py @@ -1,42 +1,74 @@ """The run report: per-block and per-worker figures for every task of a run. Built from the JSON the Rust side emits (`daisy_core::run_report`) — the -same line it appends to each tracked task's ``runs.jsonl`` — so the object -you get back from a run and the record left on disk are one and the same -shape. +same line that is appended, once per run, to the task's ``runs.jsonl`` — +so the object a run returns and the record left on disk are one and the +same shape. ``runs.jsonl`` lives in the task's tracking store when it has +one, else under ``//`` next to the worker logs. -Primary interface:: +Primary interface, in the process that ran or any later one:: - report = daisy.last_report() # or daisy.Server().last_report - t = report.tasks["segment"] - t.blocks.wall # Stat: n, mean, std, min, max, total + t = task.report() # TaskReport, read from runs.jsonl + t.blocks.round_trip # Stat: n, mean, std, min, max, total t.workers.startup # Stat over workers t.workers.idle # Stat over per-block gaps, all workers - print(report) # the panel the run prints + print(t.render()) # the task's section of the panel Drill-downs:: t.worker(1) # WorkerRecord t.block(block) # BlockRecord from the tracking store t.block((1, 2)) # ...by grid coordinate + +`Server.last_report` is the whole-pipeline `RunReport` of a server's last +run. """ from __future__ import annotations import json from dataclasses import dataclass, field +from pathlib import Path + +RUNS_FILE = "runs.jsonl" -_last: list = [None] +def runs_file_for(task) -> Path | None: + """Where a task's run reports are appended: ``runs.jsonl`` in its + tracking store, else under the log basedir next to its worker logs, + else None (no store and file logging off).""" + store = task.tracking_path + if store: + return Path(store) / RUNS_FILE + from daisy.logging import get_log_basedir, get_log_mode + + base = get_log_basedir() + if base is None or get_log_mode() == "console": + return None + return Path(base) / task.task_id / RUNS_FILE -def last_report(): - """The `RunReport` of the most recent run in this process (any entry - point), or None before the first run finishes.""" - return _last[0] + +def read_last_run(path) -> TaskReport | None: + """The last report line of a ``runs.jsonl``, or None if absent/empty.""" + path = Path(path) + if not path.is_file(): + return None + last = None + with open(path, encoding="utf-8") as f: + for line in f: + if line.strip(): + last = line + if last is None: + return None + return TaskReport.from_dict(json.loads(last)) -def _set_last(report) -> None: - _last[0] = report +def append_run(path, task_report) -> None: + """Append one report line, creating the directory as needed.""" + path = Path(path) + path.parent.mkdir(parents=True, exist_ok=True) + with open(path, "a", encoding="utf-8") as f: + f.write(json.dumps(task_report.to_dict()) + "\n") # -- formatting --------------------------------------------------------------- @@ -526,17 +558,29 @@ def timed(self) -> dict: def _attach(self, tasks) -> None: """Give each task report the `daisy.Task` it came from (for - `TaskReport.block`) and each task its report (for `Task.report`).""" + `TaskReport.block`), keep an in-memory copy on the task (the + fallback for `Task.report` when nothing could be persisted), and + persist the report of every task without a tracking store next to + its worker logs — the Rust side already appended it to the store + of every task that has one.""" for task in tasks: tid = getattr(task, "task_id", None) if tid not in self.tasks: continue - self.tasks[tid]._task = task + report = self.tasks[tid] + report._task = task try: - task._last_report = self.tasks[tid] + task._last_report = report except AttributeError: # a bare native task (no instance dict) cannot carry it pass + if not report.tracked: + path = runs_file_for(task) + if path is not None: + try: + append_run(path, report) + except OSError: + pass # the report is still returned; never fail a run over it def render(self, task_order=None, max_workers: int = 10) -> str: """The Resource Utilization panel, one section per task in diff --git a/daisy-py/python/daisy/_runner.py b/daisy-py/python/daisy/_runner.py index ab995f51..f694d8e3 100644 --- a/daisy-py/python/daisy/_runner.py +++ b/daisy-py/python/daisy/_runner.py @@ -45,10 +45,10 @@ def _prepare(pipeline, distributed=True): def _attach_report(report_or_exc, tasks): - """Wire the run's report to the tasks it covers — `TaskReport.block` - needs the task, `Task.report` needs the report. On the error paths - (KeyboardInterrupt, abandonment) the partial report rides on the - exception as ``daisy_run_report``.""" + """Wire the run's report to the tasks it covers (`TaskReport.block` + needs the task) and persist it for the tasks without a tracking store. + On the error paths (KeyboardInterrupt, abandonment) the partial report + rides on the exception as ``daisy_run_report``.""" report = getattr(report_or_exc, "daisy_run_report", report_or_exc) if report is not None and hasattr(report, "_attach"): report._attach(tasks) @@ -58,10 +58,10 @@ class Server: """Coordinator. Thin shim over `_rs._run_distributed_server` that wraps process functions with per-worker logging context first. - Most users go through `daisy.run_blockwise(...)`. Instantiate this - class directly when you want access to `last_report` or - `last_task_order` after the run (`daisy.last_report()` returns the - same report for whichever entry point ran last).""" + Most users go through `daisy.run_blockwise(...)` and read a task's + figures back with `Task.report()`. Instantiate this class directly when + you want the whole pipeline's `last_report` or `last_task_order` after + the run.""" def __init__(self, stop_event=None): self._stop_event = stop_event @@ -182,9 +182,9 @@ def run_blockwise( raises ``RuntimeError`` either way. ``summary=False`` silences the execution summary that is otherwise - printed on return, on KeyboardInterrupt and on abandonment. The run's - `daisy.RunReport` (per-block and per-worker timing) is available - afterwards from ``daisy.last_report()`` either way. + printed on return, on KeyboardInterrupt and on abandonment. Each task's + figures (per-block and per-worker timing) are persisted and available + afterwards from ``task.report()`` either way. ``host`` is the address workers are told to connect to. Leave it unset and daisy detects one — this host's resolved name, else the diff --git a/daisy-py/python/daisy/_task.py b/daisy-py/python/daisy/_task.py index d4f92a1c..99c646ef 100644 --- a/daisy-py/python/daisy/_task.py +++ b/daisy-py/python/daisy/_task.py @@ -297,11 +297,25 @@ def run_blockwise(self, **kwargs): return run_blockwise(self, **kwargs) def report(self): - """This task's `TaskReport` from the most recent run that included - it — per-block ``mean ± std`` and per-worker startup / idle / - compute / teardown — or None if it has not run in this process. - Set whether the run finished, was interrupted or was abandoned. - The same object is ``daisy.last_report()[task.task_id]``.""" + """This task's `TaskReport` from its most recent run — per-block + ``mean ± std`` and per-worker startup / idle / compute / teardown — + or None if it has never run. + + Read from the last line of the task's ``runs.jsonl`` (in its + tracking store, else next to its worker logs under the log basedir), + so it works in a later process too and reflects whichever run of + this task happened last, finished, interrupted or abandoned. Only + when nothing could be persisted (no store and file logging off) does + it fall back to the report kept in memory by a run in this process. + """ + from daisy._report import read_last_run, runs_file_for + + path = runs_file_for(self) + if path is not None: + report = read_last_run(path) + if report is not None: + report._task = self + return report return getattr(self, "_last_report", None) diff --git a/daisy-py/python/daisy/v1_compat.py b/daisy-py/python/daisy/v1_compat.py index cf755a70..8f0a2189 100644 --- a/daisy-py/python/daisy/v1_compat.py +++ b/daisy-py/python/daisy/v1_compat.py @@ -51,7 +51,6 @@ __version__, get_done_marker_basedir, get_tracking_basedir, - last_report, profile_block, set_done_marker_basedir, set_tracking_basedir, @@ -178,7 +177,6 @@ def run_blockwise(self, tasks, block_tracking=True): "profile_block", "get_done_marker_basedir", "get_tracking_basedir", - "last_report", "run_blockwise", "set_done_marker_basedir", "set_tracking_basedir", diff --git a/daisy-py/python/daisy/v2.py b/daisy-py/python/daisy/v2.py index 7835574f..035d799f 100644 --- a/daisy-py/python/daisy/v2.py +++ b/daisy-py/python/daisy/v2.py @@ -22,7 +22,7 @@ import daisy._daisy as _rs from daisy._progress import JsonProgressObserver -from daisy._report import RunReport, TaskReport, last_report +from daisy._report import RunReport, TaskReport from daisy._runner import Server, run_blockwise from daisy._task import ( Block, @@ -75,7 +75,6 @@ "TaskState", "__version__", "BlockStats", - "last_report", "get_done_marker_basedir", "get_tracking_basedir", "run_blockwise", diff --git a/daisy-py/src/py_task.rs b/daisy-py/src/py_task.rs index f65f65e0..2176a19e 100644 --- a/daisy-py/src/py_task.rs +++ b/daisy-py/src/py_task.rs @@ -561,6 +561,15 @@ impl PyTask { Ok(Some(d)) } + /// The directory this task's tracking store resolves to — an explicit + /// `tracking_path`, or `/` when a basedir is + /// set — or None when the task has no persistent store (tracking off, + /// or the run-scoped store `resource_tracking=True` falls back to). + #[getter] + fn tracking_path(&self, py: Python<'_>) -> Option { + self.done_marker_path.resolve(py, &self.task_id) + } + /// Property: return the user-facing 3-state value (None / False / /// str), matching what was passed at construction. #[getter(done_marker_path)] diff --git a/docs/source/api.md b/docs/source/api.md index 2989ac60..c86ec3b3 100644 --- a/docs/source/api.md +++ b/docs/source/api.md @@ -64,8 +64,6 @@ as in 1.x. Every daisy entry point accepts them (or anything with integer ## Run report ```{eval-rst} -.. autofunction:: daisy.last_report - .. autoclass:: daisy.RunReport :members: diff --git a/docs/source/design/RUN_STATS.md b/docs/source/design/RUN_STATS.md index fd051e83..8c3f63ae 100644 --- a/docs/source/design/RUN_STATS.md +++ b/docs/source/design/RUN_STATS.md @@ -142,15 +142,17 @@ tracking) — a table of zeros is worse than no table — and the per-worker table stops at ten rows, then points at the full table on the report object. -Programmatic access: `daisy.last_report()` (also `Server.last_report`, and -`daisy_run_report` on the `KeyboardInterrupt` / abandonment error) is a -`RunReport` of `TaskReport`s, and each task that took part carries its own -section as `task.report()`: +Programmatic access goes through the task, and through the file, so it does +not depend on the state of an in-memory server: `task.report()` reads the +last line of the task's `runs.jsonl` and works in a later process just the +same. (`Server.last_report` is the whole pipeline's `RunReport` of that +server's last run; the partial report of an interrupted or abandoned run +also rides on the error as `daisy_run_report`.) ```python task = daisy.Task("seg", ...) task.run_blockwise() -t = task.report() # the same object as daisy.last_report()["seg"] +t = task.report() # TaskReport, from runs.jsonl t.blocks.round_trip # Stat(n, mean, std, min, max, total), seconds; always there t.blocks.wall # the worker's own measurement; resource_tracking only t.blocks.peak_rss # bytes @@ -217,12 +219,24 @@ Gantt-style timeline — who ran what, when, with what gaps — can be rebuilt from the store alone. Worker ids restart at 0 every run, so the value is "the worker, in the run that completed this block". -The run report itself is appended as one JSON line per run to `runs.jsonl` -in the same directory: append-only, human-readable, `jq`-able, keeps history -across resumes, and ignored by zarr readers. It is the same JSON the Python -`RunReport` is built from, so the object a run returns and the record left -on disk cannot drift apart. Tasks without a store persist nothing; the -report is still built in memory. +The run report itself is appended as one JSON line per run to `runs.jsonl`: +append-only, human-readable, `jq`-able, keeps history across resumes. It is +the same JSON the Python `RunReport` is built from, so the object a run +returns and the record left on disk cannot drift apart. Every task gets one, +whether or not it opted into resource tracking: + +- a task with a tracking store (an explicit `tracking_path`, or one resolved + from `set_tracking_basedir`) gets it inside that store — the Rust side + appends it as the run ends, on the normal, interrupted and abandoned paths + alike. zarr-python warns about the unrecognised entry when *listing* the + group's members; indexing arrays is silent; +- a task without one gets it under `//runs.jsonl`, + next to its worker logs, written by the Python layer when file logging is + on (the same condition under which worker logs are written). + +`task.report()` reads the last line from whichever applies; only when +neither exists (no store, file logging off) does it fall back to the copy a +run in this process kept in memory. ## Narrowing what gets measured diff --git a/tests/test_run_stats.py b/tests/test_run_stats.py index b1c267c6..abb276d6 100644 --- a/tests/test_run_stats.py +++ b/tests/test_run_stats.py @@ -57,10 +57,12 @@ def test_summary_shape(tmp_path): assert stat.n == 4, stat assert stat.min <= stat.mean <= stat.max assert stat.std >= 0 - report = daisy.last_report() + report = daisy.Server() + report.run_blockwise([_tracked_task("shape2", tmp_path, _busy)], progress=False) + report = report.last_report again = daisy.RunReport.from_json(report.to_json()) - assert again["shape"].blocks == s - assert again["shape"].workers.by_id.keys() == report["shape"].workers.by_id.keys() + assert again["shape2"].blocks == report["shape2"].blocks + assert again["shape2"].workers.by_id.keys() == report["shape2"].workers.by_id.keys() def _busy_worker(): diff --git a/tests/test_worker_timeline.py b/tests/test_worker_timeline.py index c690b1b4..2305d307 100644 --- a/tests/test_worker_timeline.py +++ b/tests/test_worker_timeline.py @@ -206,9 +206,9 @@ def key(rec): _, plain = _run(_task("plain", tmp_path, tracked=False, max_workers=1)) assert plain.block((0,)) is None - rebuilt = daisy.RunReport.from_json(daisy.last_report().to_json()) + rebuilt = daisy.TaskReport.from_dict(plain.to_dict()) with pytest.raises(RuntimeError, match="no task attached"): - rebuilt["plain"].block((0,)) + rebuilt.block((0,)) def test_runs_jsonl_gets_one_line_per_run_and_round_trips(tmp_path): @@ -223,16 +223,16 @@ def test_runs_jsonl_gets_one_line_per_run_and_round_trips(tmp_path): assert daisy.TaskReport.from_dict(rows[1]).to_dict() == second.to_dict() assert rows[0]["workers"]["count"] == 1 assert rows[1]["started_at"] >= rows[0]["finished_at"] - # The whole report also round-trips as JSON. - rt = daisy.RunReport.from_json(daisy.last_report().to_json()) - assert rt.to_dict() == daisy.last_report().to_dict() + # task.report() is the last line, read from the file. + assert task.report().to_dict() == second.to_dict() + assert task.tracking_path == str(tmp_path / "tracking_history") def test_serial_mode_has_no_workers(tmp_path): task = _task("serial", tmp_path, max_workers=1) ok = daisy.run_blockwise([task], multiprocessing=False, progress=False) assert ok - t = daisy.last_report()["serial"] + t = task.report() assert t.tracked and t.blocks.has_stats and t.blocks.count == 8 assert t.workers.count == 0 assert t.workers.by_id == {} @@ -243,7 +243,9 @@ def test_serial_mode_has_no_workers(tmp_path): plain = _task("serial_plain", tmp_path, tracked=False, max_workers=1) daisy.run_blockwise([plain], multiprocessing=False, progress=False) - assert daisy.last_report().render() == "" + section = plain.report().render() + assert section.strip().startswith("serial_plain 8 blocks") + assert "workers" not in section and "round trip" not in section and "wall " not in section def test_panel_always_prints_store_free_figures(tmp_path, capfd): @@ -266,22 +268,68 @@ def test_panel_always_prints_store_free_figures(tmp_path, capfd): assert "workers startup" in out and "clean" in out for needs_store in ("cpu", "peak RSS", "io read", "overhead", "trend"): assert needs_store not in out, needs_store - t = daisy.last_report()["plain"] + t = _last_run_task("plain", tmp_path).report() assert t.blocks.round_trip.n == 8 assert 0.045 < t.blocks.round_trip.mean < 0.5 assert not t.blocks.wall -def test_last_report_is_set_by_every_entry_point(tmp_path): +def _last_run_task(task_id, tmp_path): + """A fresh Task object for a task that already ran: what a later + process would build to call `report()` — no in-memory state at all.""" + return _task(task_id, tmp_path, tracked=False) + + +def test_report_is_persisted_for_every_entry_point_and_readable_later(tmp_path): + """Every entry point leaves runs.jsonl behind — in the tracking store + for tracked tasks, next to the worker logs otherwise — and a brand-new + Task object reads it back, as a later process would.""" + import daisy.logging as dl + daisy.run_blockwise([_task("a", tmp_path, tracked=False)], progress=False) - assert "a" in daisy.last_report() daisy.Server().run_blockwise([_task("b", tmp_path, tracked=False)], progress=False) - assert "b" in daisy.last_report() daisy.run_blockwise( [_task("c", tmp_path, tracked=False)], multiprocessing=False, progress=False ) - assert "c" in daisy.last_report() - assert daisy.last_report()["c"].workers.count == 0 + daisy.run_blockwise([_task("d", tmp_path)], progress=False) + + for tid in "abc": + path = dl.get_log_basedir() / tid / "runs.jsonl" + assert path.is_file(), tid + fresh = _last_run_task(tid, tmp_path) + assert fresh.tracking_path is None + t = fresh.report() + assert t is not None and t.task_id == tid and t.blocks.count == 8 + assert _last_run_task("c", tmp_path).report().workers.count == 0 + assert _last_run_task("a", tmp_path).report().workers.count >= 1 + + # The tracked task's report is in its store, not under the logs. + assert not (dl.get_log_basedir() / "d" / "runs.jsonl").exists() + assert (tmp_path / "tracking_d" / "runs.jsonl").is_file() + fresh = _task("d", tmp_path) + t = fresh.report() + assert t.tracked and t.blocks.has_stats + assert t.block((0,)).done # the store lookup works through the fresh task + + # Two runs → two lines; report() is the latest. + daisy.run_blockwise([_task("a", tmp_path, tracked=False)], progress=False) + lines = (dl.get_log_basedir() / "a" / "runs.jsonl").read_text().splitlines() + assert len(lines) == 2 + assert ( + _last_run_task("a", tmp_path).report().started_at + == json.loads(lines[1])["started_at"] + ) + + # Nothing to persist (no store, file logging off): None from a fresh + # task, the in-memory copy from the task that ran. + dl.set_log_basedir(None) + try: + ran = _task("e", tmp_path, tracked=False) + daisy.run_blockwise([ran], progress=False) + assert _last_run_task("e", tmp_path).report() is None + assert ran.report() is not None and ran.report().blocks.count == 8 + finally: + dl.set_log_basedir(tmp_path / "daisy_logs") def test_task_run_blockwise_and_report(tmp_path): @@ -291,7 +339,6 @@ def test_task_run_blockwise_and_report(tmp_path): assert task.run_blockwise(progress=False) is True t = task.report() assert t is not None and t.task_id == "solo" - assert t is daisy.last_report()["solo"] assert t.blocks.count == 8 and t.blocks.round_trip.n == 8 assert t.workers.count >= 1 and t.workers.exits["clean"] == t.workers.count assert t.worker(0).startup > 0 From bac7fb1295691882ab4bbc37856c7fae6e997dde Mon Sep 17 00:00:00 2001 From: Will Date: Tue, 20 Oct 2026 08:04:30 -0700 Subject: [PATCH 5/8] Per-block records and a skipped count in the report `TaskReport.block_records()` (over `Task.block_records()`) is the per-block counterpart of `workers.by_id`: every recorded block in grid order with its done flag, failures, stats, worker, dispatch/return stamps and round trip, read from the tracking store in one pass. `BlockRecord.round_trip` derives from the stamps. `blocks.skipped` separates a resumed run's skipped blocks from executed ones (count still folds them in, matching the execution summary); the panel header shows it. Co-Authored-By: Claude Fable 5.1 --- CHANGELOG.md | 6 ++-- daisy-core/src/run_report.rs | 20 +++++++++-- daisy-py/python/daisy/_daisy.pyi | 1 + daisy-py/python/daisy/_report.py | 57 +++++++++++++++++++++++++++----- daisy-py/src/py_task.rs | 56 +++++++++++++++++++++++++------ docs/source/design/RUN_STATS.md | 7 ++++ tests/test_worker_timeline.py | 31 ++++++++++++++++- 7 files changed, 153 insertions(+), 25 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index c9c8fef1..6659baab 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -73,8 +73,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 trip minus the worker's own wall time — and the wall-time trend) and `workers` (count, `startup`, `idle`, `compute`, `teardown` as distributions, exit kinds, and a row per worker under `by_id`). - `TaskReport.worker(id)` and `TaskReport.block(block | grid coord | id)` - drill down; the latter reads the tracking store (`Task.block_record`). + `TaskReport.worker(id)`, `TaskReport.block(block | grid coord | id)` and + `TaskReport.block_records()` drill down; the latter two read the tracking + store (`Task.block_record`, `Task.block_records`). `blocks.skipped` + separates a resumed run's skipped blocks from executed ones. `Task.run_blockwise(**kwargs)` runs a task on its own and `Task.report()` returns its section of its most recent run's report, read from the persisted `runs.jsonl`, so it works in a later process and after an diff --git a/daisy-core/src/run_report.rs b/daisy-core/src/run_report.rs index 65735654..0c367c46 100644 --- a/daisy-core/src/run_report.rs +++ b/daisy-core/src/run_report.rs @@ -19,8 +19,12 @@ use crate::worker_timeline::{RunTimeline, WorkerReport}; #[derive(Clone, Debug, Default, Serialize)] pub struct BlockReport { /// Blocks completed this run (from the tracking layer when the task - /// has a store, else the scheduler's completed count). + /// has a store, else the scheduler's completed count). Includes the + /// blocks a resumed run skipped via done markers — see `skipped`. pub count: u64, + /// Blocks skipped this run because a done marker (or skip mask) said + /// so; they were not executed, so they contribute no timing samples. + pub skipped: u64, /// Failed attempts this run. pub failures: u64, /// True once any block carried resource measurements. @@ -42,9 +46,15 @@ pub struct BlockReport { } impl BlockReport { - fn from_summary(s: &TaskSummary, round_trip: Welford, overhead: Welford) -> Self { + fn from_summary( + s: &TaskSummary, + skipped: u64, + round_trip: Welford, + overhead: Welford, + ) -> Self { Self { count: s.blocks_recorded, + skipped, failures: s.failures_recorded, has_stats: s.has_stats, round_trip, @@ -93,12 +103,14 @@ pub fn build_reports( .map(|(task_id, c)| { let round_trip = timeline.round_trip(task_id); let overhead = timeline.overhead(task_id); + let skipped = c.skipped_count.max(0) as u64; let (tracked, blocks) = match summaries.get(task_id) { - Some(s) => (true, BlockReport::from_summary(s, round_trip, overhead)), + Some(s) => (true, BlockReport::from_summary(s, skipped, round_trip, overhead)), None => ( false, BlockReport { count: c.completed_count.max(0) as u64, + skipped, round_trip, overhead, ..BlockReport::default() @@ -135,6 +147,7 @@ mod tests { "t".to_string(), TaskCounters { completed_count: 7, + skipped_count: 3, ..TaskCounters::default() }, ); @@ -143,6 +156,7 @@ mod tests { let r = &reports["t"]; assert!(!r.tracked); assert_eq!(r.blocks.count, 7); + assert_eq!(r.blocks.skipped, 3); assert!(!r.blocks.has_stats); assert_eq!(r.workers.count, 0); let json: serde_json::Value = serde_json::from_str(&r.to_json()).unwrap(); diff --git a/daisy-py/python/daisy/_daisy.pyi b/daisy-py/python/daisy/_daisy.pyi index d84da2f5..7a60072d 100644 --- a/daisy-py/python/daisy/_daisy.pyi +++ b/daisy-py/python/daisy/_daisy.pyi @@ -245,6 +245,7 @@ class Task: def reset(self) -> str | None: ... def failed_blocks(self) -> list[Block]: ... def block_record(self, block: Block) -> dict[str, Any] | None: ... + def block_records(self) -> list[dict[str, Any]]: ... def __copy__(self) -> Task: ... def __deepcopy__(self, memo: Any) -> Task: ... diff --git a/daisy-py/python/daisy/_report.py b/daisy-py/python/daisy/_report.py index abee8bfa..6ae4e28e 100644 --- a/daisy-py/python/daisy/_report.py +++ b/daisy-py/python/daisy/_report.py @@ -173,6 +173,9 @@ class BlockSummary: minus the block's own wall time.""" count: int = 0 + #: blocks this run skipped via done markers or a skip mask; they are + #: included in ``count`` but contributed no timing samples + skipped: int = 0 failures: int = 0 has_stats: bool = False round_trip: Stat = field(default_factory=Stat) @@ -189,6 +192,7 @@ def from_dict(cls, d) -> BlockSummary: d = d or {} return cls( count=int(d.get("count", 0)), + skipped=int(d.get("skipped", 0)), failures=int(d.get("failures", 0)), has_stats=bool(d.get("has_stats", False)), round_trip=Stat.from_dict(d.get("round_trip")), @@ -204,6 +208,7 @@ def from_dict(cls, d) -> BlockSummary: def to_dict(self) -> dict: return { "count": self.count, + "skipped": self.skipped, "failures": self.failures, "has_stats": self.has_stats, "round_trip": self.round_trip.to_dict(), @@ -333,6 +338,25 @@ def wall_seconds(self) -> float | None: def peak_rss_bytes(self) -> int | None: return None if self.stats is None else self.stats.peak_rss_bytes + @property + def round_trip(self) -> float | None: + """Dispatch to return in seconds, from the scheduler's stamps.""" + if self.sent_at is None or self.returned_at is None: + return None + return self.returned_at - self.sent_at + + @classmethod + def _from_dict(cls, task_id, d) -> BlockRecord: + return cls( + block_id=(task_id, d["spatial_id"]), + done=d["done"], + failures=d["failures"], + stats=d["stats"], + worker_id=d["worker_id"], + sent_at=d["sent_at"], + returned_at=d["returned_at"], + ) + class TaskReport: """One task's report. ``blocks`` and ``workers`` are the summaries; @@ -407,15 +431,28 @@ def block(self, block) -> BlockRecord | None: rec = task.block_record(native) if rec is None: return None - return BlockRecord( - block_id=(task.task_id, native.block_id[1]), - done=rec["done"], - failures=rec["failures"], - stats=rec["stats"], - worker_id=rec["worker_id"], - sent_at=rec["sent_at"], - returned_at=rec["returned_at"], - ) + return BlockRecord._from_dict(task.task_id, rec) + + def block_records(self) -> list: + """Every block the tracking store has recorded (done, or with a + failure count) as `BlockRecord`s sorted by spatial id: the + per-block counterpart of ``workers.by_id``. Per-block timing + (``round_trip``, ``worker_id``, ``sent_at``, ``returned_at``) and + resource figures need ``resource_tracking=True``; a plain done-marker + store yields ``done`` and ``failures`` only. Walks the whole grid, + so it is O(blocks); for very large grids read the zarr arrays in + the store directly. Empty without a store; needs the task attached, + like `block`. + """ + task = self._task + if task is None: + raise RuntimeError( + f"TaskReport({self.task_id!r}).block_records(): no task attached; " + "per-block lookup reads the tracking store through the Task" + ) + rows = [BlockRecord._from_dict(task.task_id, d) for d in task.block_records()] + rows.sort(key=lambda r: r.block_id[1]) + return rows def __repr__(self) -> str: return ( @@ -430,6 +467,8 @@ def render(self, max_workers: int = 10) -> str: b, w = self.blocks, self.workers lines = [] head = f" {self.task_id} {b.count} blocks" + if b.skipped: + head += f" ({b.skipped} skipped)" if w.count: head += f", {w.count} worker{'s' if w.count != 1 else ''}" if self.elapsed > 0: diff --git a/daisy-py/src/py_task.rs b/daisy-py/src/py_task.rs index 2176a19e..98e4825b 100644 --- a/daisy-py/src/py_task.rs +++ b/daisy-py/src/py_task.rs @@ -548,19 +548,38 @@ impl PyTask { let Some(rec) = tracking.record_of(&block.inner) else { return Ok(None); }; - let d = PyDict::new(py); - d.set_item("done", rec.done)?; - d.set_item("failures", rec.failures)?; - d.set_item( - "stats", - rec.stats.map(|inner| crate::py_block::PyBlockStats { inner }), - )?; - d.set_item("worker_id", rec.dispatch.and_then(|x| x.worker_id))?; - d.set_item("sent_at", rec.dispatch.map(|x| x.sent_at))?; - d.set_item("returned_at", rec.dispatch.map(|x| x.returned_at))?; + let d = Self::record_dict(py, &rec)?; + d.set_item("spatial_id", block.inner.block_id.spatial_id)?; Ok(Some(d)) } + /// Every block the tracking store has recorded — done, or with a + /// failure count — as the dicts `block_record` returns, each with its + /// `spatial_id`. Opens the store once and walks the whole block grid, + /// so it is O(blocks); for very large grids read the zarr arrays + /// directly instead. Empty when no store is configured or none exists. + fn block_records<'py>(&self, py: Python<'py>) -> PyResult>> { + let Some((tracking, task)) = self.open_tracking(py)? else { + return Ok(Vec::new()); + }; + let graph = daisy_core::dependency_graph::BlockwiseDependencyGraph::from_task(&task); + let mut out = Vec::new(); + for level in 0..graph.num_levels() { + for block in graph.level_blocks(level) { + let Some(rec) = tracking.record_of(&block) else { + continue; + }; + if !rec.done && rec.failures == 0 { + continue; + } + let d = Self::record_dict(py, &rec)?; + d.set_item("spatial_id", block.block_id.spatial_id)?; + out.push(d); + } + } + Ok(out) + } + /// The directory this task's tracking store resolves to — an explicit /// `tracking_path`, or `/` when a basedir is /// set — or None when the task has no persistent store (tracking off, @@ -701,6 +720,23 @@ impl PyTask { /// Store access shared by the read-only diagnostics above (not exposed /// to Python). impl PyTask { + fn record_dict<'py>( + py: Python<'py>, + rec: &daisy_core::block_tracking::BlockRecord, + ) -> PyResult> { + let d = PyDict::new(py); + d.set_item("done", rec.done)?; + d.set_item("failures", rec.failures)?; + d.set_item( + "stats", + rec.stats.map(|inner| crate::py_block::PyBlockStats { inner }), + )?; + d.set_item("worker_id", rec.dispatch.and_then(|x| x.worker_id))?; + d.set_item("sent_at", rec.dispatch.map(|x| x.sent_at))?; + d.set_item("returned_at", rec.dispatch.map(|x| x.returned_at))?; + Ok(d) + } + /// Open this task's tracking store for reading, if one is configured /// and exists. Maps the stat arrays only when the store already has /// them, so a read never adds arrays to a store. diff --git a/docs/source/design/RUN_STATS.md b/docs/source/design/RUN_STATS.md index 8c3f63ae..daea276b 100644 --- a/docs/source/design/RUN_STATS.md +++ b/docs/source/design/RUN_STATS.md @@ -161,8 +161,15 @@ t.workers.startup # Stat over workers t.workers.idle # Stat over per-block gaps, pooled across workers t.worker(1) # WorkerRecord: startup, idle, compute, teardown, exit t.block((1, 2)) # BlockRecord from the store: stats, worker_id, sent_at, returned_at +t.block_records() # every recorded block, in grid order — the per-block table ``` +Before a task has ever run, `task.report()` is None. After a resumed run +that skipped every block via done markers, the new report line says so +(`blocks.skipped`, no timing samples), while `block(...)` and +`block_records()` keep returning the stamps of the run that actually did the +work: the per-block arrays are only written when a block executes. + ## The worker timeline Per-block figures say what the blocks cost; they say nothing about the time diff --git a/tests/test_worker_timeline.py b/tests/test_worker_timeline.py index 2305d307..eae95766 100644 --- a/tests/test_worker_timeline.py +++ b/tests/test_worker_timeline.py @@ -157,6 +157,18 @@ def test_worker_id_on_disk_matches_who_ran_each_block(tmp_path, monkeypatch): counted[int((out / f"block-{i}").read_text())] += 1 assert {wid: r.blocks_ok for wid, r in t.workers.by_id.items()} == counted + # The per-block table: one record per block, in grid order, with the + # same stamps as the single lookups and timings consistent with them. + rows = t.block_records() + assert [r.block_id for r in rows] == [("who", i) for i in range(8)] + for i, r in enumerate(rows): + assert r.done and r.failures == 0 + assert r.worker_id == int((out / f"block-{i}").read_text()) + assert r.round_trip is not None and r.round_trip >= r.wall_seconds >= 0.009 + assert r.sent_at == t.block((i,)).sent_at + assert t.blocks.round_trip.n == len(rows) + assert abs(sum(r.round_trip for r in rows) - t.blocks.round_trip.total) < 1e-6 + # The arrays are plain zarr v3, readable without daisy. zarr = pytest.importorskip("zarr") if int(zarr.__version__.split(".")[0]) >= 3: @@ -205,6 +217,7 @@ def key(rec): _, plain = _run(_task("plain", tmp_path, tracked=False, max_workers=1)) assert plain.block((0,)) is None + assert plain.block_records() == [] rebuilt = daisy.TaskReport.from_dict(plain.to_dict()) with pytest.raises(RuntimeError, match="no task attached"): @@ -226,6 +239,18 @@ def test_runs_jsonl_gets_one_line_per_run_and_round_trips(tmp_path): # task.report() is the last line, read from the file. assert task.report().to_dict() == second.to_dict() assert task.tracking_path == str(tmp_path / "tracking_history") + # The rerun executed nothing: count still folds the skipped blocks in + # (as the execution summary's `completed` does), `skipped` says so, and + # there are no timing samples for it; the per-block records keep the + # stamps of the run that actually did the work. + assert first.blocks.skipped == 0 and first.blocks.round_trip.n == 8 + assert second.blocks.count == 8 and second.blocks.skipped == 8 + assert second.blocks.round_trip.n == 0 and second.blocks.wall.n == 0 + assert "8 blocks (8 skipped)" in second.render() + assert second.block((3,)).sent_at == first.block((3,)).sent_at + assert [r.block_id for r in second.block_records()] == [ + ("history", i) for i in range(8) + ] def test_serial_mode_has_no_workers(tmp_path): @@ -245,7 +270,11 @@ def test_serial_mode_has_no_workers(tmp_path): daisy.run_blockwise([plain], multiprocessing=False, progress=False) section = plain.report().render() assert section.strip().startswith("serial_plain 8 blocks") - assert "workers" not in section and "round trip" not in section and "wall " not in section + assert ( + "workers" not in section + and "round trip" not in section + and "wall " not in section + ) def test_panel_always_prints_store_free_figures(tmp_path, capfd): From 783ad072b59dfd67c78389623158649834e49c81 Mon Sep 17 00:00:00 2001 From: Will Date: Tue, 27 Oct 2026 10:04:44 -0700 Subject: [PATCH 6/8] Measure blocks process-wide; peak RSS per block Per-thread counters missed every byte and CPU second a block handed to another thread: zarr writes on its own IO threads, so a 32 MB zarr write was recorded as 0 bytes and helper-thread CPU as nothing. Each worker is its own process running one block at a time, so measure the process: getrusage(RUSAGE_SELF) and /proc/self/io. process_cpu_time replaces thread_cpu_time (and its hand-rolled Mach code). peak_rss_bytes read ru_maxrss, which survives fork+exec, so every spawned worker reported its driver's peak (6 GB for every task of a run whose driver held the volume). On Linux the profiler now resets the high-water mark at block start (/proc/self/clear_refs) and reads VmHWM at the end: the process's peak while the block ran. Falls back to ru_maxrss where the reset is unavailable. Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 10 ++ daisy-core/src/block_profile.rs | 189 +++++++++++++++++++++-------- daisy-core/src/run_stats.rs | 102 +++------------- docs/source/design/DONE_MARKERS.md | 2 +- docs/source/design/RUN_STATS.md | 48 +++++--- 5 files changed, 197 insertions(+), 154 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 6659baab..5f8cc594 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -384,6 +384,16 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed +- **Block measurements cover the whole worker process.** `cpu_seconds` and + `io_*_bytes` were counted per thread (`RUSAGE_THREAD`, + `/proc/self/task//io`), so work a block handed to other threads was + missed. zarr's IO threads are one example: a 32 MB zarr write was recorded + as 0 bytes. They now come from `RUSAGE_SELF` and `/proc/self/io`. +- **`peak_rss_bytes` is the peak while the block ran.** It was read from + `ru_maxrss`, which survives fork+exec, so every spawned worker reported + its driver's peak (6.1 GB for every task of a run whose driver held the + volume). On Linux the high-water mark is now reset at block start and + `VmHWM` is read at the end. Elsewhere it falls back to `ru_maxrss`. - **The bundled benchmarks no longer compare daisy against itself.** The `gerbera -> daisy` rename left both arms of every comparison pointing at the same package: each script defined `bench_daisy` twice (the second diff --git a/daisy-core/src/block_profile.rs b/daisy-core/src/block_profile.rs index 823c4542..96da1d6d 100644 --- a/daisy-core/src/block_profile.rs +++ b/daisy-core/src/block_profile.rs @@ -15,20 +15,31 @@ //! //! ## What the numbers mean, and their honest limits //! +//! Every figure is **process-wide**. Each distributed worker is its own +//! process running one block at a time, so the process is the block's +//! natural accounting unit, and only process-wide counters see work the +//! block hands to other threads (zarr's IO and codec threads, a thread +//! pool, a helper thread). Per-thread counters reported zero IO for zarr +//! writes. In serial mode the process is the driver, and its background +//! threads are counted too. +//! //! - `wall_seconds` — elapsed time around the block function. Always exact. -//! - `cpu_seconds` — user+system CPU consumed. Per-*thread* where the OS -//! offers it (Linux `RUSAGE_THREAD`, macOS `thread_info`), so concurrent -//! thread workers don't contaminate each other. -//! - `io_read_bytes` / `io_write_bytes` — bytes through the syscall layer, -//! from `/proc/self/task//io` (per-thread on Linux) falling back to -//! `/proc/self/io`. Zero where the platform doesn't expose it. -//! - `peak_rss_bytes` — the process's peak RSS observed at the end of the -//! block. **Process-wide, not per-block**: `ru_maxrss` is a monotonic -//! high-water mark, so this reads as "how big had we grown by the time -//! this block finished". In subprocess mode (the default) each worker is -//! its own process handling one block at a time, which is the meaningful -//! case; in thread mode every concurrent block reports the same -//! process-wide figure. +//! - `cpu_seconds` — user+system CPU consumed by the process +//! (`getrusage(RUSAGE_SELF)`). +//! - `io_read_bytes` / `io_write_bytes` — bytes through the syscall layer +//! (`rchar` / `wchar` from `/proc/self/io`). Zero where the platform +//! doesn't expose it. +//! - `peak_rss_bytes` — the process's peak RSS **while this block ran**. +//! On Linux the profiler resets the kernel's high-water mark when the +//! block starts (writing `5` to `/proc/self/clear_refs`) and reads +//! `VmHWM` when it ends. That is the worker's resident baseline plus +//! whatever the block allocated on top. The reset lowers the process's +//! `ru_maxrss` too, so external tools such as `/usr/bin/time` see the +//! peak of the last block rather than of the whole process. Where the +//! reset is unavailable (macOS, kernels before 4.0) this falls back to +//! `ru_maxrss`, the process's peak so far. Never `ru_maxrss` on Linux +//! otherwise: it survives fork+exec, so a spawned worker would report +//! the driver's peak as its own. //! - `gpu_util_pct` / `gpu_mem_bytes` — reserved. Populating them needs //! NVML and a sampling loop; the schema slots exist so adding it later //! doesn't change the on-disk layout. Written as NaN / 0 for now. @@ -38,7 +49,7 @@ use std::time::{Duration, Instant}; use bincode::{Decode, Encode}; use serde::{Deserialize, Serialize}; -use crate::run_stats::thread_cpu_time; +use crate::run_stats::process_cpu_time; /// Resources consumed by one block, measured by whoever ran it. /// @@ -72,8 +83,7 @@ impl Default for BlockStats { } } -/// Bytes read/written through the syscall layer by this thread (or the -/// process, where per-thread accounting is unavailable). +/// Bytes read/written through the syscall layer by this process. #[derive(Clone, Copy, Debug, Default, PartialEq, Eq)] struct IoCounters { read: u64, @@ -81,8 +91,8 @@ struct IoCounters { } /// An in-flight measurement. `start()` snapshots the counters, `finish()` -/// returns the deltas. Cheap enough to wrap every block: three small reads -/// of `/proc` plus a `getrusage`. +/// returns the deltas. Cheap enough to wrap every block: one small write +/// and three small reads of `/proc` plus two `getrusage` calls. #[derive(Debug)] pub struct BlockProfiler { started: Instant, @@ -92,9 +102,10 @@ pub struct BlockProfiler { impl BlockProfiler { pub fn start() -> Self { + reset_peak_rss(); Self { started: Instant::now(), - cpu_at_start: thread_cpu_time(), + cpu_at_start: process_cpu_time(), io_at_start: read_io_counters(), } } @@ -105,7 +116,7 @@ impl BlockProfiler { /// unreadable mid-block) saturate at zero rather than wrapping. pub fn finish(&self) -> BlockStats { let wall = self.started.elapsed(); - let cpu = match (thread_cpu_time(), self.cpu_at_start) { + let cpu = match (process_cpu_time(), self.cpu_at_start) { (Some(now), Some(then)) => now.saturating_sub(then), _ => Duration::ZERO, }; @@ -127,11 +138,31 @@ impl BlockProfiler { } } -/// Peak resident set size of this process, in bytes. -/// -/// `ru_maxrss` is a high-water mark, so this is the process's peak so far, -/// not this block's own footprint — see the module docs. +/// Reset this process's peak-RSS high-water mark to its current RSS, so +/// the next `peak_rss_bytes` reads the peak since now. Linux 4.0+ only; a +/// failure (older kernel, restricted `/proc`) leaves the mark alone and +/// `peak_rss_bytes` reads the process's peak so far. +fn reset_peak_rss() { + #[cfg(target_os = "linux")] + { + let _ = std::fs::write("/proc/self/clear_refs", "5"); + } +} + +/// Peak resident set size of this process since the last `reset_peak_rss`, +/// in bytes. See the module docs. fn peak_rss_bytes() -> Option { + #[cfg(target_os = "linux")] + { + // VmHWM is the high-water mark of this process image; ru_maxrss + // would carry over the parent's peak across fork+exec. + if let Some(hwm) = std::fs::read_to_string("/proc/self/status") + .ok() + .and_then(|text| parse_vm_hwm(&text)) + { + return Some(hwm); + } + } #[cfg(any(target_os = "linux", target_os = "macos"))] { // SAFETY: getrusage only writes into the rusage we hand it. @@ -155,18 +186,15 @@ fn peak_rss_bytes() -> Option { } } -/// Per-thread IO byte counters, falling back to the process totals. +/// The process's IO byte counters. /// /// Linux exposes `rchar`/`wchar` (bytes through read/write syscalls, -/// including page-cache hits) per thread under `/proc/self/task//io`. -/// Elsewhere this returns `None` and the stats read zero. +/// including page-cache hits) under `/proc/self/io`, summed over all +/// threads. Elsewhere this returns `None` and the stats read zero. fn read_io_counters() -> Option { #[cfg(target_os = "linux")] { - // SAFETY: gettid takes no arguments and cannot fail. - let tid = unsafe { libc::gettid() }; - std::fs::read_to_string(format!("/proc/self/task/{tid}/io")) - .or_else(|_| std::fs::read_to_string("/proc/self/io")) + std::fs::read_to_string("/proc/self/io") .ok() .map(|text| parse_proc_io(&text)) } @@ -197,6 +225,14 @@ fn parse_proc_io(text: &str) -> IoCounters { io } +/// Pull `VmHWM` (reported in kB) out of `/proc/self/status`, in bytes. +#[cfg_attr(not(target_os = "linux"), allow(dead_code))] +fn parse_vm_hwm(text: &str) -> Option { + let line = text.lines().find(|line| line.starts_with("VmHWM:"))?; + let kb = line["VmHWM:".len()..].trim().strip_suffix("kB")?.trim(); + kb.parse::().ok().map(|kb| kb.saturating_mul(1024)) +} + #[cfg(test)] mod tests { use super::*; @@ -211,6 +247,10 @@ mod tests { std::hint::black_box(acc); } + // Every figure is process-wide and cargo runs tests as threads of one + // process, so other tests' work can only add to a measurement: these + // tests assert lower bounds, never upper ones. + #[test] fn measures_wall_and_cpu_of_busy_work() { let p = BlockProfiler::start(); @@ -219,31 +259,26 @@ mod tests { assert!(s.wall_seconds >= 0.045, "wall too small: {s:?}"); assert!(s.wall_seconds < 5.0, "wall implausible: {s:?}"); - // A busy loop spends its wall time on-CPU; allow generous slack for - // a loaded machine, and accept 0 where the platform has no probe. - if thread_cpu_time().is_some() { - assert!(s.cpu_seconds > 0.0, "expected cpu time: {s:?}"); - assert!( - s.cpu_seconds <= s.wall_seconds * 1.5 + 0.05, - "cpu exceeds wall: {s:?}" - ); + if process_cpu_time().is_some() { + assert!(s.cpu_seconds >= 0.04, "expected cpu time: {s:?}"); } } #[test] - fn sleeping_costs_wall_but_not_cpu() { + fn counts_cpu_burned_on_other_threads() { + // A block that hands its work to a helper thread (as zarr does with + // its codec and IO threads) still owns that CPU. let p = BlockProfiler::start(); - std::thread::sleep(Duration::from_millis(30)); + std::thread::spawn(|| busy(50)).join().unwrap(); let s = p.finish(); - assert!(s.wall_seconds >= 0.025, "wall too small: {s:?}"); - if thread_cpu_time().is_some() { - assert!(s.cpu_seconds < 0.020, "sleep should not burn cpu: {s:?}"); + if process_cpu_time().is_some() { + assert!(s.cpu_seconds >= 0.04, "helper-thread cpu missing: {s:?}"); } } #[test] - fn counts_bytes_written() { + fn counts_bytes_written_on_other_threads() { let p = BlockProfiler::start(); let path = std::env::temp_dir().join(format!( "daisy-profile-io-{}-{:?}.bin", @@ -251,8 +286,15 @@ mod tests { std::thread::current().id() )); let payload = vec![7u8; 256 * 1024]; - std::fs::write(&path, &payload).unwrap(); - let read_back = std::fs::read(&path).unwrap(); + let read_back = std::thread::spawn({ + let (path, payload) = (path.clone(), payload.clone()); + move || { + std::fs::write(&path, &payload).unwrap(); + std::fs::read(&path).unwrap() + } + }) + .join() + .unwrap(); let s = p.finish(); let _ = std::fs::remove_file(&path); @@ -271,12 +313,51 @@ mod tests { } } + /// Allocate and touch `bytes`, so they are resident. + fn resident(bytes: usize) -> Vec { + let mut v = vec![0u8; bytes]; + for i in (0..bytes).step_by(4096) { + v[i] = 1; + } + std::hint::black_box(v) + } + #[test] - fn peak_rss_is_reported_where_supported() { - let s = BlockProfiler::start().finish(); + fn peak_rss_covers_what_the_block_allocated() { + let p = BlockProfiler::start(); + let held = resident(64 << 20); + let s = p.finish(); // still holding it, so no concurrent reset can hide it + drop(held); + if cfg!(any(target_os = "linux", target_os = "macos")) { - assert!(s.peak_rss_bytes > 0, "expected a peak rss: {s:?}"); + assert!(s.peak_rss_bytes >= 64 << 20, "expected a peak rss: {s:?}"); + } + } + + #[test] + #[cfg(target_os = "linux")] + fn peak_rss_starts_over_with_each_block() { + if std::fs::write("/proc/self/clear_refs", "5").is_err() { + return; // kernel or sandbox without the reset: ru_maxrss fallback } + let first = BlockProfiler::start(); + let held = resident(512 << 20); + let big = first.finish(); + drop(held); + + let small = BlockProfiler::start().finish(); + assert!(big.peak_rss_bytes >= 512 << 20, "first block: {big:?}"); + assert!( + small.peak_rss_bytes + (256 << 20) < big.peak_rss_bytes, + "second block inherited the first one's peak: {small:?} vs {big:?}" + ); + } + + #[test] + fn parses_vm_hwm() { + let status = "Name:\tpython\nVmPeak:\t 999 kB\nVmHWM:\t 2048 kB\nVmRSS:\t 1 kB\n"; + assert_eq!(parse_vm_hwm(status), Some(2048 * 1024)); + assert_eq!(parse_vm_hwm("VmRSS: 1 kB\n"), None); } #[test] @@ -291,7 +372,13 @@ mod tests { let io = parse_proc_io( "rchar: 1234\nwchar: 5678\nsyscr: 9\nnot-a-number: abc\nmalformed line\n", ); - assert_eq!(io, IoCounters { read: 1234, write: 5678 }); + assert_eq!( + io, + IoCounters { + read: 1234, + write: 5678 + } + ); } #[test] diff --git a/daisy-core/src/run_stats.rs b/daisy-core/src/run_stats.rs index 189c8a00..410d74e8 100644 --- a/daisy-core/src/run_stats.rs +++ b/daisy-core/src/run_stats.rs @@ -3,10 +3,12 @@ //! Statistics themselves live with the blocks: `block_profile` measures a //! block inside the worker, the payload rides home on `Block::stats`, and //! `block_tracking` persists and aggregates it. This module holds only the -//! two pieces that are useful on their own: +//! pieces that are useful on their own: //! -//! - `thread_cpu_time` — per-OS-thread CPU accounting, so concurrent -//! thread workers don't contaminate each other's numbers. +//! - `process_cpu_time` — the whole process's CPU time, so work a block +//! hands to other threads (zarr's IO and codec threads, thread pools) is +//! counted. Every worker is its own process running one block at a time, +//! so the process is the block's natural accounting unit. //! - `Welford` / `Trend` — the O(1)-memory accumulators behind every //! `x ± y` figure and the per-block wall-time slope in the run report. //! - `linear_trend` — the least-squares fit behind "blocks started at 2 ms @@ -19,14 +21,15 @@ use std::time::Duration; -/// Read this thread's user+system CPU time. Returns None on platforms -/// without a per-thread accessor (e.g. some BSDs / Windows MSYS). -pub fn thread_cpu_time() -> Option { - #[cfg(target_os = "linux")] +/// Read this process's user+system CPU time, summed over all its threads. +/// Returns None on platforms without `getrusage` (e.g. Windows). +pub fn process_cpu_time() -> Option { + #[cfg(any(target_os = "linux", target_os = "macos"))] { + // SAFETY: getrusage only writes into the rusage we hand it. unsafe { let mut ru: libc::rusage = std::mem::zeroed(); - if libc::getrusage(libc::RUSAGE_THREAD, &mut ru) != 0 { + if libc::getrusage(libc::RUSAGE_SELF, &mut ru) != 0 { return None; } let user = duration_from_timeval(&ru.ru_utime); @@ -34,94 +37,19 @@ pub fn thread_cpu_time() -> Option { Some(user + sys) } } - #[cfg(target_os = "macos")] - { - // mach_thread_self → thread_info(thread, THREAD_BASIC_INFO, ...) - // We only need user_time + system_time from thread_basic_info. - macos_thread_cpu_time() - } #[cfg(not(any(target_os = "linux", target_os = "macos")))] { None } } -#[cfg(target_os = "linux")] +#[cfg(any(target_os = "linux", target_os = "macos"))] fn duration_from_timeval(tv: &libc::timeval) -> Duration { let secs = tv.tv_sec as u64; let micros = tv.tv_usec as u32; Duration::new(secs, micros * 1000) } -#[cfg(target_os = "macos")] -fn macos_thread_cpu_time() -> Option { - // libc on macOS exposes mach_thread_self() and the thread_info() - // syscall via the `mach2` crate, but bringing that in just for this - // is overkill. Inline what we need: the Mach syscall numbers and - // the thread_basic_info layout. The whole thing is two ints + - // four time_value_t fields. - use std::os::raw::{c_int, c_uint}; - - // thread_t is a mach_port_name_t which is an unsigned int. - type ThreadT = c_uint; - type KernReturnT = c_int; - type ThreadFlavorT = c_int; - type MachMsgTypeNumberT = c_uint; - - const THREAD_BASIC_INFO: ThreadFlavorT = 3; - // The size of `thread_basic_info_data_t` in u32-sized words. - const THREAD_BASIC_INFO_COUNT: MachMsgTypeNumberT = 10; - - #[repr(C)] - #[derive(Default)] - struct TimeValueT { - seconds: c_int, - microseconds: c_int, - } - - #[repr(C)] - #[derive(Default)] - struct ThreadBasicInfo { - user_time: TimeValueT, - system_time: TimeValueT, - cpu_usage: c_int, - policy: c_int, - run_state: c_int, - flags: c_int, - suspend_count: c_int, - sleep_time: c_int, - } - - unsafe extern "C" { - fn mach_thread_self() -> ThreadT; - fn mach_port_deallocate(task: ThreadT, port: ThreadT) -> KernReturnT; - fn mach_task_self() -> ThreadT; - fn thread_info( - target: ThreadT, - flavor: ThreadFlavorT, - info: *mut ThreadBasicInfo, - count: *mut MachMsgTypeNumberT, - ) -> KernReturnT; - } - - unsafe { - let thread = mach_thread_self(); - let mut info = ThreadBasicInfo::default(); - let mut count = THREAD_BASIC_INFO_COUNT; - let kr = thread_info(thread, THREAD_BASIC_INFO, &mut info, &mut count); - // Always release the port reference we just took. - let _ = mach_port_deallocate(mach_task_self(), thread); - if kr != 0 { - return None; - } - let user_us = info.user_time.seconds as u64 * 1_000_000 - + info.user_time.microseconds as u64; - let sys_us = info.system_time.seconds as u64 * 1_000_000 - + info.system_time.microseconds as u64; - Some(Duration::from_micros(user_us + sys_us)) - } -} - /// Least-squares fit of y = m*x + b, where x = 0, 1, ..., n-1. /// Returns (mean_y, slope_m). Slope is 0 for fewer than 2 points. pub fn linear_trend(y: &[f64]) -> (f64, f64) { @@ -173,16 +101,16 @@ mod tests { } #[test] - fn thread_cpu_time_returns_some_on_linux_and_macos() { + fn process_cpu_time_returns_some_on_linux_and_macos() { // Burn a tiny bit of CPU so the result isn't trivially zero. let mut s: u64 = 0; for i in 0..10_000 { s = s.wrapping_add(i); } std::hint::black_box(s); - let t = thread_cpu_time(); + let t = process_cpu_time(); if cfg!(any(target_os = "linux", target_os = "macos")) { - assert!(t.is_some(), "expected per-thread CPU on this platform"); + assert!(t.is_some(), "expected process CPU on this platform"); } } } diff --git a/docs/source/design/DONE_MARKERS.md b/docs/source/design/DONE_MARKERS.md index d4f395f5..c9a60b08 100644 --- a/docs/source/design/DONE_MARKERS.md +++ b/docs/source/design/DONE_MARKERS.md @@ -22,7 +22,7 @@ element-per-block grid index, so they line up element-for-element: | `failures` | uint32 | always | failed attempts for this block | | `wall_seconds` | float32 | `resource_tracking` | elapsed time in the block | | `cpu_seconds` | float32 | `resource_tracking` | user+system CPU | -| `peak_rss_bytes` | uint64 | `resource_tracking` | process peak RSS at block end | +| `peak_rss_bytes` | uint64 | `resource_tracking` | process peak RSS while the block ran | | `io_read_bytes` | uint64 | `resource_tracking` | bytes read via syscalls | | `io_write_bytes` | uint64 | `resource_tracking` | bytes written via syscalls | | `gpu_util_pct` | float32 | `resource_tracking` | reserved (NaN) | diff --git a/docs/source/design/RUN_STATS.md b/docs/source/design/RUN_STATS.md index daea276b..4cdbe5d7 100644 --- a/docs/source/design/RUN_STATS.md +++ b/docs/source/design/RUN_STATS.md @@ -48,23 +48,40 @@ worker (any mode) server | field | source | meaning | |---|---|---| | `wall_seconds` | `Instant` around the call | elapsed time in the block | -| `cpu_seconds` | `getrusage(RUSAGE_THREAD)` / mach `thread_info` | user+system CPU, **per thread** so concurrent workers don't contaminate each other | -| `io_read_bytes`, `io_write_bytes` | `/proc/self/task//io` (`rchar`/`wchar`), falling back to `/proc/self/io` | bytes through the syscall layer, including page-cache hits | -| `peak_rss_bytes` | `ru_maxrss` | see the caveat below | +| `cpu_seconds` | `getrusage(RUSAGE_SELF)` | user+system CPU of the whole process, every thread included | +| `io_read_bytes`, `io_write_bytes` | `/proc/self/io` (`rchar`/`wchar`) | bytes through the syscall layer, every thread included, page-cache hits included | +| `peak_rss_bytes` | `VmHWM`, reset at block start (Linux); `ru_maxrss` elsewhere | peak RSS of the process while the block ran; see below | | `gpu_util_pct`, `gpu_mem_bytes` | — | **reserved**; written NaN / 0 | Unsupported platforms report zero rather than failing. -### Caveat: peak RSS is process-wide - -`ru_maxrss` is a monotonic high-water mark for the whole process, so -`peak_rss_bytes` reads as "how large had this process grown by the time this -block finished" — not "what this block allocated". Every distributed worker -is its own process handling one block at a time, which makes it a useful -per-worker figure; this is one of the things that got simpler when -in-process workers went away, since concurrent blocks sharing a process all -reported the same number. A true per-block figure would still need allocator -interposition. +### Why every figure is process-wide + +Every distributed worker is its own process handling one block at a time, +so the process is the block's natural accounting unit. Only process-wide +counters see the work a block hands to other threads. zarr does its IO and +codec work on its own threads, and blocks use thread pools. Per-thread +counters (`RUSAGE_THREAD`, `/proc/self/task//io`, the previous +implementation) reported a zarr write of 32 MB as 0 bytes, and CPU burned on +a helper thread as nothing. In serial mode the process is the driver, so its +own background threads are counted too. + +### Peak RSS is per block on Linux + +When a block starts, the profiler resets the kernel's high-water mark +(writing `5` to `/proc/self/clear_refs`, Linux 4.0+). When the block ends, +it reads `VmHWM`. The figure is therefore the process's peak while this +block ran: the worker's resident baseline (interpreter, imports, caches) +plus whatever the block allocated on top. It is not the block's +allocations alone. That would need allocator interposition. + +It is deliberately not `ru_maxrss` on Linux. That value survives fork+exec, +so every spawned worker would report its driver's peak: a driver holding a +6 GB volume made every worker report 6 GB. The reset also lowers the +process's `ru_maxrss`, so a tool like `/usr/bin/time` wrapped around a +serial run reports the last block's peak rather than the driver's. Where the +reset is unavailable (macOS, older kernels, a restricted `/proc`) the figure +falls back to `ru_maxrss`, the process's peak so far. ### GPU is reserved, not faked @@ -281,8 +298,9 @@ outright, leaving one measurement path. Deleted along the way: `WorkerStats`, `TaskStats`, `ProcessStats`, `RunStats`, `build_run_stats`, the 200 ms `sysinfo` process sampler (and the -`sysinfo` dependency), and `Server.last_run_stats`. `thread_cpu_time` and -`linear_trend` survive in `run_stats.rs` because both are still used. +`sysinfo` dependency), and `Server.last_run_stats`. `linear_trend` +survives in `run_stats.rs`, alongside `process_cpu_time` (which replaced +the per-thread `thread_cpu_time`). ## Implementation pointers From 4cd72537ed0ca60f37d3e7691ae7ed25690eed7a Mon Sep 17 00:00:00 2001 From: Will Date: Tue, 27 Oct 2026 10:28:11 -0700 Subject: [PATCH 7/8] Bump version to 2.0.1 Co-Authored-By: Claude Opus 5.5 --- Cargo.lock | 4 ++-- daisy-core/Cargo.toml | 2 +- daisy-py/Cargo.toml | 2 +- daisy-py/python/daisy/__init__.py | 2 +- pyproject.toml | 2 +- uv.lock | 2 +- 6 files changed, 7 insertions(+), 7 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 3b681321..7134fd5e 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -70,7 +70,7 @@ dependencies = [ [[package]] name = "daisy-core" -version = "2.0.0" +version = "2.0.1" dependencies = [ "bincode", "libc", @@ -87,7 +87,7 @@ dependencies = [ [[package]] name = "daisy-py" -version = "2.0.0" +version = "2.0.1" dependencies = [ "daisy-core", "libc", diff --git a/daisy-core/Cargo.toml b/daisy-core/Cargo.toml index 511e9823..f845e96e 100644 --- a/daisy-core/Cargo.toml +++ b/daisy-core/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "daisy-core" -version = "2.0.0" +version = "2.0.1" edition = "2024" description = "Blockwise task scheduler for processing large volumetric data — Rust core for the daisy Python package" license = "MIT" diff --git a/daisy-py/Cargo.toml b/daisy-py/Cargo.toml index e3dc4ed3..63e2d2f1 100644 --- a/daisy-py/Cargo.toml +++ b/daisy-py/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "daisy-py" -version = "2.0.0" +version = "2.0.1" edition = "2024" description = "Python bindings for daisy-core" license = "MIT" diff --git a/daisy-py/python/daisy/__init__.py b/daisy-py/python/daisy/__init__.py index cc06a7e2..3275fdb7 100644 --- a/daisy-py/python/daisy/__init__.py +++ b/daisy-py/python/daisy/__init__.py @@ -1,4 +1,4 @@ -"""daisy v2.0.0 — blockwise task scheduler for large volumetric data. +"""daisy v2.0.1 — blockwise task scheduler for large volumetric data. The top-level namespace re-exports `daisy.v1_compat` so existing daisy 1.x scripts run unchanged wherever the v2 API didn't break diff --git a/pyproject.toml b/pyproject.toml index 263fc585..efd755b4 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,6 +1,6 @@ [project] name = "daisy" -version = "2.0.0" +version = "2.0.1" description = "Blockwise task scheduler for processing large volumetric data" readme = "README.md" license = "MIT" diff --git a/uv.lock b/uv.lock index ba8824dc..785d2da4 100644 --- a/uv.lock +++ b/uv.lock @@ -376,7 +376,7 @@ wheels = [ [[package]] name = "daisy" -version = "2.0.0" +version = "2.0.1" source = { editable = "." } dependencies = [ { name = "cloudpickle" }, From 9520273b59a6edaef307aed38ad10859b9df54cf Mon Sep 17 00:00:00 2001 From: Will Date: Tue, 27 Oct 2026 10:31:40 -0700 Subject: [PATCH 8/8] Satisfy main's lint: type BlockRecord.stats, format the RUN_STATS sample Co-Authored-By: Claude Opus 5.5 --- daisy-py/python/daisy/_report.py | 6 +++++- docs/source/design/RUN_STATS.md | 20 ++++++++++---------- 2 files changed, 15 insertions(+), 11 deletions(-) diff --git a/daisy-py/python/daisy/_report.py b/daisy-py/python/daisy/_report.py index 6ae4e28e..b0d2df7d 100644 --- a/daisy-py/python/daisy/_report.py +++ b/daisy-py/python/daisy/_report.py @@ -29,6 +29,10 @@ import json from dataclasses import dataclass, field from pathlib import Path +from typing import TYPE_CHECKING + +if TYPE_CHECKING: + from daisy._daisy import BlockStats RUNS_FILE = "runs.jsonl" @@ -323,7 +327,7 @@ class BlockRecord: done: bool failures: int #: ``daisy.BlockStats`` or None (no resource tracking, or never ran) - stats: object | None + stats: BlockStats | None #: worker that completed it, or None (unmanaged client / never ran) worker_id: int | None #: seconds since the UNIX epoch on the scheduler's clock, or None diff --git a/docs/source/design/RUN_STATS.md b/docs/source/design/RUN_STATS.md index 4cdbe5d7..197fea5c 100644 --- a/docs/source/design/RUN_STATS.md +++ b/docs/source/design/RUN_STATS.md @@ -169,16 +169,16 @@ also rides on the error as `daisy_run_report`.) ```python task = daisy.Task("seg", ...) task.run_blockwise() -t = task.report() # TaskReport, from runs.jsonl -t.blocks.round_trip # Stat(n, mean, std, min, max, total), seconds; always there -t.blocks.wall # the worker's own measurement; resource_tracking only -t.blocks.peak_rss # bytes -t.blocks.overhead # round trip − wall, per block -t.workers.startup # Stat over workers -t.workers.idle # Stat over per-block gaps, pooled across workers -t.worker(1) # WorkerRecord: startup, idle, compute, teardown, exit -t.block((1, 2)) # BlockRecord from the store: stats, worker_id, sent_at, returned_at -t.block_records() # every recorded block, in grid order — the per-block table +t = task.report() # TaskReport, from runs.jsonl +t.blocks.round_trip # Stat(n, mean, std, min, max, total), seconds; always there +t.blocks.wall # the worker's own measurement; resource_tracking only +t.blocks.peak_rss # bytes +t.blocks.overhead # round trip − wall, per block +t.workers.startup # Stat over workers +t.workers.idle # Stat over per-block gaps, pooled across workers +t.worker(1) # WorkerRecord: startup, idle, compute, teardown, exit +t.block((1, 2)) # BlockRecord from the store: stats, worker_id, sent_at, returned_at +t.block_records() # every recorded block, in grid order — the per-block table ``` Before a task has ever run, `task.report()` is None. After a resumed run