diff --git a/CHANGELOG.md b/CHANGELOG.md index 0d684948..5f8cc594 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -65,6 +65,41 @@ 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 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 + distributions, exit kinds, and a row per worker under `by_id`). + `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 + 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, + is always collected (O(workers) memory), and covers startup and teardown, + which a worker cannot report about itself. The "Resource Utilization" + 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`. + 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`). - `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, @@ -349,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/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/MIGRATION.md b/MIGRATION.md index 02041826..a09126c2 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: `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-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-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_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/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..0c367c46 --- /dev/null +++ b/daisy-core/src/run_report.rs @@ -0,0 +1,167 @@ +//! 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). 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. + 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, + 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, + 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, + 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 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, skipped, round_trip, overhead)), + None => ( + false, + BlockReport { + count: c.completed_count.max(0) as u64, + skipped, + round_trip, + 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, + skipped_count: 3, + ..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_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(); + 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..410d74e8 100644 --- a/daisy-core/src/run_stats.rs +++ b/daisy-core/src/run_stats.rs @@ -3,10 +3,14 @@ //! 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 //! and ended at 12 ms", applied to the per-block wall times collected by //! `block_tracking::TaskSummary`. @@ -17,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); @@ -32,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) { @@ -171,16 +101,234 @@ 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"); + } + } +} + +/// 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 321965d6..80918fc5 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 { @@ -110,13 +111,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)) } /// The next block to process, or `None` when no task has ready work. @@ -237,9 +242,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..79f2c57f --- /dev/null +++ b/daisy-core/src/worker_timeline.rs @@ -0,0 +1,562 @@ +//! 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 { + /// 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, +} + +/// 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(), + }; + let side = self.tasks.entry(task_id.to_string()).or_default(); + if ok { + side.round_trip.push(elapsed); + } + if let Some(wall) = wall_seconds { + side.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 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) + .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); + 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); + 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/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 30396781..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 @@ -25,10 +25,12 @@ JsonProgressObserver, Pipeline, Roi, + RunReport, Scheduler, SerialServer, Server, Task, + TaskReport, TaskState, __version__, get_done_marker_basedir, @@ -50,10 +52,12 @@ "JsonProgressObserver", "Pipeline", "Roi", + "RunReport", "Scheduler", "SerialServer", "Server", "Task", + "TaskReport", "TaskState", "__version__", "profile_block", diff --git a/daisy-py/python/daisy/_daisy.pyi b/daisy-py/python/daisy/_daisy.pyi index 8e270ca8..3a6352ae 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]: ... @@ -242,6 +244,8 @@ 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: ... @@ -361,14 +365,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 = ..., @@ -376,5 +380,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 86a98dca..53daea2a 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,18 @@ 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 if order is not None: self.order = order @@ -207,11 +209,11 @@ 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 states is None: return False if isinstance(exc, KeyboardInterrupt): @@ -226,7 +228,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 @@ -437,32 +439,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 @@ -472,56 +467,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..b0d2df7d --- /dev/null +++ b/daisy-py/python/daisy/_report.py @@ -0,0 +1,696 @@ +"""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 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, in the process that ran or any later one:: + + 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(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 +from typing import TYPE_CHECKING + +if TYPE_CHECKING: + from daisy._daisy import BlockStats + +RUNS_FILE = "runs.jsonl" + + +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 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 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 --------------------------------------------------------------- + + +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. + + ``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 + #: 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) + 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)), + 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")), + 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, + "skipped": self.skipped, + "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(), + "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: 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 + 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 + + @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; + ``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._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 ( + 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 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: + 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"{label} 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} + + @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`), 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 + report = self.tasks[tid] + report._task = task + try: + 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 + ``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: + 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..f694d8e3 100644 --- a/daisy-py/python/daisy/_runner.py +++ b/daisy-py/python/daisy/_runner.py @@ -44,23 +44,33 @@ 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) 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) + + 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_tracking_summary` or - `last_task_order` after the run.""" + 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 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,39 +86,49 @@ 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, host=host, block_tracking=block_tracking, ) + except BaseException as e: + _attach_report(e, original.tasks) + raise finally: _worker_log.close_all_log_files() - self.last_tracking_summary = stats - rec.set(states, stats) + _attach_report(report, 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) + except BaseException as e: + _attach_report(e, original.tasks) + raise finally: _worker_log.close_all_log_files() - rec.set(states, stats) + _attach_report(report, original.tasks) + rec.set(states, report) return states @@ -162,7 +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. + 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 @@ -176,12 +198,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, @@ -189,9 +212,13 @@ 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() - rec.set(states, stats) + _attach_report(report, original.tasks) + rec.set(states, report) if return_states: return states return _all_succeeded(states) diff --git a/daisy-py/python/daisy/_task.py b/daisy-py/python/daisy/_task.py index 69ca6441..29f5e116 100644 --- a/daisy-py/python/daisy/_task.py +++ b/daisy-py/python/daisy/_task.py @@ -288,6 +288,37 @@ 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 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) + def _block_fn_arity(fn): """Positional arity of a process function: 0 means a worker function diff --git a/daisy-py/python/daisy/v1_compat.py b/daisy-py/python/daisy/v1_compat.py index ec7efa08..8f0a2189 100644 --- a/daisy-py/python/daisy/v1_compat.py +++ b/daisy-py/python/daisy/v1_compat.py @@ -44,7 +44,9 @@ JsonProgressObserver, Pipeline, Roi, + RunReport, Server, + TaskReport, TaskState, __version__, get_done_marker_basedir, @@ -164,10 +166,12 @@ def run_blockwise(self, tasks, block_tracking=True): "JsonProgressObserver", "Pipeline", "Roi", + "RunReport", "Scheduler", "SerialServer", "Server", "Task", + "TaskReport", "TaskState", "__version__", "profile_block", diff --git a/daisy-py/python/daisy/v2.py b/daisy-py/python/daisy/v2.py index 606cda8b..035d799f 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 from daisy._runner import Server, run_blockwise from daisy._task import ( Block, @@ -66,9 +67,11 @@ "JsonProgressObserver", "Pipeline", "Roi", + "RunReport", "Scheduler", "Server", "Task", + "TaskReport", "TaskState", "__version__", "BlockStats", 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..98e4825b 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,63 @@ 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 = 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, + /// 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)] @@ -683,3 +716,62 @@ impl PyTask { Ok(arc) } } + +/// 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. + 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..c86ec3b3 100644 --- a/docs/source/api.md +++ b/docs/source/api.md @@ -61,6 +61,31 @@ as in 1.x. Every daisy entry point accepts them (or anything with integer :members: ``` +## Run report + +```{eval-rst} +.. 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..c9a60b08 100644 --- a/docs/source/design/DONE_MARKERS.md +++ b/docs/source/design/DONE_MARKERS.md @@ -22,13 +22,21 @@ 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) | | `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..197fea5c 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 @@ -107,34 +124,143 @@ 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 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 + 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. + +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 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`.) -`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 +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 +``` -Programmatic access: `daisy.Server().last_tracking_summary`, keyed -`{"per_task": {task_id: {...}}}`. +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 +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`: +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 @@ -172,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 @@ -181,5 +308,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/pyproject.toml b/pyproject.toml index 7a8f714d..a7f0f809 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/tests/test_block_profiling.py b/tests/test_block_profiling.py index a867d8db..9488e6cd 100644 --- a/tests/test_block_profiling.py +++ b/tests/test_block_profiling.py @@ -49,7 +49,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(): @@ -104,10 +104,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): @@ -138,8 +138,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): @@ -239,8 +239,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): @@ -275,7 +275,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() ) @@ -285,10 +285,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 665636ec..abb276d6 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 @@ -37,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): @@ -48,21 +48,21 @@ 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.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["shape2"].blocks == report["shape2"].blocks + assert again["shape2"].workers.by_id.keys() == report["shape2"].workers.by_id.keys() def _busy_worker(): @@ -94,21 +94,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): @@ -119,8 +119,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}" @@ -129,10 +129,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}" @@ -160,12 +160,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", @@ -179,11 +180,20 @@ 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 + # 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(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 @@ -199,42 +209,175 @@ def _render(summary): 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 test_renderer_omits_panel_without_measurements(): - """Nothing at all when no task measured anything — a table of zeros is - worse than no table.""" +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_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({"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 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( - { - "per_task": { - "seg": { + _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).""" + 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( + _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, - } + "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), + "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 "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 + 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..eae95766 --- /dev/null +++ b/tests/test_worker_timeline.py @@ -0,0 +1,387 @@ +"""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 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: + 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 + assert plain.block_records() == [] + + rebuilt = daisy.TaskReport.from_dict(plain.to_dict()) + with pytest.raises(RuntimeError, match="no task attached"): + rebuilt.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"] + # 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): + task = _task("serial", tmp_path, max_workers=1) + ok = daisy.run_blockwise([task], multiprocessing=False, progress=False) + assert ok + 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 == {} + 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() 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) + 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): + """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("plain", tmp_path, tracked=False)], progress=False) + out = capfd.readouterr().out + assert "Execution Summary" in out + 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 = _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 _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) + daisy.Server().run_blockwise([_task("b", tmp_path, tracked=False)], progress=False) + daisy.run_blockwise( + [_task("c", tmp_path, tracked=False)], multiprocessing=False, progress=False + ) + 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): + """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.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 diff --git a/uv.lock b/uv.lock index 4ad89db0..4445ae17 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" },