From 7179006aee8267414029428a5e520afaae54b4d5 Mon Sep 17 00:00:00 2001 From: osobh Date: Sun, 27 Sep 2026 19:43:07 -0500 Subject: [PATCH] docs: local read A/B re-run on an idle machine The first run of the day could not get an idle tank: two orphaned h5py SWMR reader processes from earlier interop tests (since stopped) kept a core each busy. Re-run with the load below 2 at every round: ObjectHeader::parse is +4.2% (real: the ranges do not overlap; about 2.5 ns per header, not visible in the facade listing, which is -1.7%); full deflate reads +1.7% (1 thread) to +36% (16 threads); the -5.6% single- thread contiguous hyperslab result from the loaded run is noise (-1.7%, overlapping ranges) and is withdrawn from known-issues. Co-Authored-By: Claude Opus 5.5 (1M context) --- BENCHMARKS.md | 116 ++++++++++++++++++------------------------- CHANGELOG.md | 33 ++++++------ docs/known-issues.md | 36 ++++++-------- 3 files changed, 79 insertions(+), 106 deletions(-) diff --git a/BENCHMARKS.md b/BENCHMARKS.md index b5b3b07..f6e8a3c 100644 --- a/BENCHMARKS.md +++ b/BENCHMARKS.md @@ -502,83 +502,61 @@ explain the slower windows. ### Local metadata and data reads after range-read M2/M3 (2026-09-27, tank) -Range-read M2/M3 (PR #18) moved the facade onto the `Storage` abstraction. -This compares `main` just before it, `8f59b2e`, with `main` at `7a8fae0` -(PR #18 and PR #19 merged, including the slice-entry-point fix `ef428d7` -and the object-header fix `4313917`), each built in its own worktree and -target directory and run as separate binaries, alternating base, -candidate, base, candidate. +`main` just before range-read M2/M3 (`8f59b2e`, PR #17) against `main` +`7a8fae0` (PRs #18 and #19), each built in its own worktree and run as +separate binaries, alternating base and candidate. Machine: tank (AMD Ryzen +7 7800X3D, 16 threads). **Idle:** every round started with the 1-minute load +average below 2 (1.05–1.98; `target/ab-results2/load.log`). Criterion: +`taskset -c 5 local_metadata_bench --bench --warm-up-time 3 +--measurement-time 10`, 3 rounds each. Reads: `concurrent_read --dir +~/.cache/concurrent-read --decode-threads 1 --reps 3`, 3 rounds each. +Median (range) over the rounds. -**Provisional: tank was not idle.** Two orphaned h5py processes (leftover -SWMR test readers from earlier test runs, about 100% of a core each) held -the 1-minute load average at 2.1-2.6 throughout; the load < 2 gate was -polled every 20 s for 2 hours and never met, so the runs went ahead -anyway. Load average (1-minute) during the runs: Criterion rounds 1-3 -2.29-3.31, rounds 4-6 2.41-3.12 (each started below 2.5); -`concurrent_read` 3.04-6.49 (that figure includes its own 16 threads). -Machine: AMD Ryzen 7 7800X3D (8 cores, 16 threads). +`local_metadata_bench` (the 400-group v1 fixture): -Metadata, Criterion `crates/clawhdf5/benches/local_metadata_bench.rs` over -`clawhdf5-format/tests/fixtures/v1_groups_400.h5`, pinned to one CPU, 6 -alternating rounds each (median of each round's Criterion estimate, then -median and range over the rounds): - -```text -cargo bench -p clawhdf5 --bench local_metadata_bench --no-run -cd crates/clawhdf5 && taskset -c 5 --bench --noplot \ - --warm-up-time 3 --measurement-time 10 -``` - -| function | `8f59b2e` median (range) | `7a8fae0` median (range) | change | +| function | 8f59b2e | 7a8fae0 | change | |---|---:|---:|---:| -| `object_header_parse_x401` | 24.13 us (23.97-25.56) | 25.11 us (24.73-25.21) | +4.1% | -| `snod_parse_all` | 1.866 us (1.855-1.888) | 1.858 us (1.846-1.884) | -0.4% | -| `btree_v1_walk` | 344 ns (337-355) | 346 ns (340-355) | +0.5% | -| `facade_list_400_groups` | 8.26 ms (8.08-8.45) | 8.20 ms (8.14-8.36) | -0.8% | +| `object_header_parse_x401` | 23.86 µs (23.79–23.96) | 24.86 µs (24.69–24.98) | **+4.2%** | +| `snod_parse_all` | 1.842 µs (1.835–1.847) | 1.833 µs (1.833–1.854) | −0.5% | +| `btree_v1_walk` | 344 ns (338–346) | 348 ns (337–356) | +1.1% | +| `facade_list_400_groups` | 8.24 ms (8.04–8.28) | 8.10 ms (8.04–8.13) | −1.7% | -The facade listing's +7-10% seen during PR #18 is gone (-0.8%, within the -ranges). `ObjectHeader::parse` of 401 small headers is still slower: five -of six base rounds measured 23.97-24.29 us (one outlier 25.56), every -candidate round 24.73-25.21 us, so +4% (about 2.4 ns per header) looks -real rather than noise; it does not show in the listing that parses those -headers. Listed in `docs/known-issues.md`. +`concurrent_read`, MB/s (64 datasets of 64 MiB `f32`; deflate chunks +256 x 256, level 4): -Data reads, `concurrent_read` (the "Concurrent reads" workload below: 64 -datasets of 64 MiB, `--decode-threads 1`, 3 repetitions per point, median -MB/s reported by the harness), 3 alternating rounds each; median and range -over the rounds: - -```text -cargo build --release -p clawhdf5-bench --bin concurrent_read -concurrent_read --dir ~/.cache/concurrent-read --decode-threads 1 --reps 3 -``` - -| layout | mode | threads | `8f59b2e` MB/s (range) | `7a8fae0` MB/s (range) | change | +| layout | mode | threads | 8f59b2e | 7a8fae0 | change | |---|---|---:|---:|---:|---:| -| deflate | distinct | 1 | 815 (810-816) | 875 (874-877) | +7.4% | -| deflate | distinct | 4 | 2964 (2959-2969) | 3302 (3301-3309) | +11.4% | -| deflate | distinct | 8 | 4401 (4379-4414) | 5074 (5072-5080) | +15.3% | -| deflate | distinct | 16 | 5568 (5500-5598) | 6862 (6781-6962) | +23.2% | -| deflate | same | 1 | 228 (228-230) | 230 (230-231) | +1.1% | -| deflate | same | 4 | 896 (893-900) | 893 (890-896) | -0.3% | -| deflate | same | 16 | 1837 (1829-1839) | 1844 (1805-1865) | +0.4% | -| contiguous | distinct | 1 | 10360 (9636-10625) | 10143 (10063-10402) | -2.1% | -| contiguous | distinct | 4 | 13658 (13543-13750) | 13704 (13448-13770) | +0.3% | -| contiguous | distinct | 16 | 12311 (12256-12354) | 12307 (12273-12337) | -0.0% | -| contiguous | same | 1 | 22682 (22658-23411) | 21421 (20358-21908) | -5.6% | -| contiguous | same | 4 | 97424 (96473-100871) | 99417 (98952-105308) | +2.0% | -| contiguous | same | 16 | 137754 (126322-156061) | 152767 (136109-154669) | +10.9% | +| deflate | distinct | 1 | 891 (880–892) | 907 (906–908) | +1.7% | +| deflate | distinct | 2 | 1692 (1680–1699) | 1777 (1767–1779) | +5.0% | +| deflate | distinct | 4 | 3102 (3099–3102) | 3348 (3347–3350) | +8.0% | +| deflate | distinct | 8 | 5306 (5168–5345) | 6240 (6226–6248) | +17.6% | +| deflate | distinct | 16 | 6258 (6109–6442) | 8525 (8513–8561) | **+36.2%** | +| deflate | same | 1 | 234 (234–235) | 233 (233–234) | −0.5% | +| deflate | same | 16 | 2443 (2038–2444) | 2468 (2424–2473) | +1.0% | +| contiguous | distinct | 1 | 13477 (12949–13874) | 13302 (13287–13578) | −1.3% | +| contiguous | distinct | 16 | 12501 (12484–12530) | 12566 (12449–12567) | +0.5% | +| contiguous | same | 1 | 29866 (28832–30207) | 29364 (28838–29780) | −1.7% | +| contiguous | same | 16 | 163415 (161097–229146) | 233280 (159377–238440) | (noise) | -(2- and 8-thread rows are in line with their neighbours.) Full reads of -chunked deflate data are 7-23% *faster* at `7a8fae0`, with tight ranges; -which commit did it was not bisected. Contiguous full reads and deflate -hyperslabs are unchanged. One row is slower: one thread reading 256 x 256 -hyperslabs of a contiguous dataset, -5.6% with no overlap between the -rounds (about 0.6 us more per 256 KiB slab); the multi-thread `contiguous -same` rows, which are cache-bound and noisy, went the other way. Listed in -`docs/known-issues.md` as open, pending an idle re-run. +What this shows: +- **Local metadata reads are at parity or faster.** Listing the 400-group + file through the facade is 1.7% faster than before M2/M3; the +7–10% + listing regression found while merging #18 is gone. +- **`ObjectHeader::parse` alone is 4.2% slower** (about 2.5 ns per header; + the base and candidate ranges do not overlap). It is the cost of reading + continuation chunks from a bounded queue (the fix for unbounded reads on + crafted headers) and does not show in the listing. Kept open in + `docs/known-issues.md`. +- **Full reads of deflate data got faster** after #18 (in-place chunk + decoding into the typed output and per-thread scratch buffers): +1.7% on + one thread, +36% at 16. +- Single-thread contiguous hyperslabs are within noise (−1.7%, overlapping + ranges). The multi-thread `contiguous same` rows read one 64 MiB dataset + out of the CPU caches and swing widely between rounds of the same build. -## Concurrent reads +An earlier run the same day at load 2.3–3.3 (two orphaned h5py processes, +since stopped, each using a core) reported that single-thread contiguous +hyperslab row as −5.6%; the idle rerun above does not reproduce it. ### Results after in-place chunk decoding (2026-09-26, tank, `c5334b1`) diff --git a/CHANGELOG.md b/CHANGELOG.md index 2743744..306dd13 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -477,19 +477,19 @@ Design: `docs/design/swmr.md`. `main` and it calls only format-crate code; its earlier +5–10% (323–355 vs 353–363 ns) was run-to-run layout noise (at `2893b6c` it measured 357–374 ns against `main`'s 355–371 in the same rounds). - **Rechecked 2026-09-27** (still provisional: two orphaned h5py test - processes kept tank's 1-minute load at 2.1–2.6, the load < 2 gate was - not met in 2 hours, load 2.3–3.3 during the runs; `8f59b2e` vs `main` - `7a8fae0` as separate binaries, pinned to one CPU, 6 alternating rounds, - median (range) over rounds; `BENCHMARKS.md`, "Local metadata and data - reads after range-read M2/M3"): facade listing 8.26 (8.08–8.45) → 8.20 - (8.14–8.36) ms, −0.8%, so the listing regression is gone; symbol-table - nodes −0.4%, B-tree walk +0.5%; `ObjectHeader::parse` ×401 24.13 - (23.97–25.56) → 25.11 (24.73–25.21) µs, **+4.1%, still open** - (`docs/known-issues.md`). Data reads (`concurrent_read --decode-threads - 1`, 3 alternating rounds): full reads of deflate data 7–23% faster, - contiguous full reads and deflate hyperslabs within ±2%, one-thread - contiguous hyperslabs −5.6% (open, same entry). + **Rechecked 2026-09-27 on an idle tank** (load below 2 at every round; + `8f59b2e` vs `main` `7a8fae0` as separate binaries, pinned to one CPU, 3 + alternating rounds, median (range); `BENCHMARKS.md`, "Local metadata and + data reads after range-read M2/M3"): facade listing 8.24 (8.04–8.28) → + 8.10 (8.04–8.13) ms, **−1.7%**, so the listing regression is gone; + symbol-table nodes −0.5%, B-tree walk +1.1%; `ObjectHeader::parse` ×401 + 23.86 (23.79–23.96) → 24.86 (24.69–24.98) µs, **+4.2%, open** + (`docs/known-issues.md`; about 2.5 ns per header, not visible in the + listing). Data reads (`concurrent_read --decode-threads 1`): full reads + of deflate data +1.7% (1 thread) to +36% (16 threads), contiguous reads + and deflate hyperslabs within ±2%. (A run earlier that day under load + 2.3–3.3 put single-thread contiguous hyperslabs at −5.6%; the idle rerun + does not reproduce it.) - Tests (2026-09-26, tank): - `clawhdf5-format/tests/storage_equivalence.rs` now also reads every dataset — whole, fill-aware, through a chunk cache (twice) and the @@ -644,10 +644,9 @@ Design: `docs/design/swmr.md`. instead of being inlined into the generic parser. Provisional (tank load 3–4; Criterion, separate binaries, 2 alternating rounds): 24.96–25.12 vs 24.85–25.15 µs on `main`. - Rechecked 2026-09-27 with 6 alternating rounds (load 2.3–3.3, still - provisional): 24.73–25.21 µs against 23.97–24.29 µs (one outlier 25.56) - for `8f59b2e`, median +4.1%; a residual cost remains (see the M2 speed - note and `docs/known-issues.md`). + Rechecked 2026-09-27 on an idle tank (3 alternating rounds, load below + 2): 24.69–24.98 µs against 23.79–23.96 µs for `8f59b2e`, median +4.2%; a + residual cost remains (see the M2 speed note and `docs/known-issues.md`). - Tests: `crates/clawhdf5-tools/tests/edit_coverage_interop.rs` (h5py `earliest`/`v110`/`latest` and clawhdf5-written files; structure comparisons with libhdf5 for version-2 B-trees, shrink on every index, diff --git a/docs/known-issues.md b/docs/known-issues.md index 613a729..98e1fac 100644 --- a/docs/known-issues.md +++ b/docs/known-issues.md @@ -7,27 +7,23 @@ deleting it. --- -## Local-read slowdowns left after range-read M2/M3 (measured 2026-09-27) +## `ObjectHeader::parse` 4% slower after range-read M2/M3 (measured 2026-09-27) -**Status:** open (speed only; values are correct). Measured on tank, -`main` before range-read M2/M3 (`8f59b2e`) against `main` `7a8fae0`, -alternating separate binaries (`BENCHMARKS.md`, "Local metadata and data -reads after range-read M2/M3"). Provisional: the machine never went idle -(1-minute load 2.3–3.3 for the metadata runs, two orphaned h5py processes -using a core each), so re-run both on an idle tank before acting. -- `ObjectHeader::parse` of 401 small headers (`local_metadata_bench`, - `object_header_parse_x401`): 24.13 → 25.11 µs median over 6 rounds - (+4.1%, about 2.4 ns per header; ranges 23.97–25.56 vs 24.73–25.21, five - of six base rounds at or below 24.29). The header parser has read its - continuation chunks from a queue since `a69c5be`; `4313917` removed its - per-header allocations but not all of the cost. Listing the 400-group - file through the facade, which parses those headers, is not slower - (−0.8%). -- One thread reading 256 x 256 hyperslabs of a contiguous dataset - (`concurrent_read`, `contiguous same`, 1 thread): 22682 → 21421 MB/s - median over 3 rounds (−5.6%; 22658–23411 vs 20358–21908), about 0.6 µs - more per 256 KiB slab. The multi-thread rows of that mode, which are - cache-bound and noisy, did not slow down; full reads did not either. +**Status:** open (speed only; values are correct). Measured on an idle tank +(load below 2 at every round), `main` before range-read M2/M3 (`8f59b2e`) +against `main` `7a8fae0`, separate binaries alternating, 3 rounds +(`BENCHMARKS.md`, "Local metadata and data reads after range-read M2/M3"): +`object_header_parse_x401` 23.86 → 24.86 µs median (+4.2%; ranges +23.79–23.96 vs 24.69–24.98), about 2.5 ns per header. The parser has read +continuation chunks from a bounded queue since `a69c5be` (bounding what a +crafted header can make it read); `4313917` removed its per-header +allocations but not all of the cost. Listing the 400-group file through the +facade, which parses the same headers, is 1.7% faster, so no user-visible +path is slower. + +An earlier run the same day under load also listed single-thread contiguous +hyperslab reads as 5.6% slower; the idle rerun puts them at −1.7% with +overlapping ranges (noise), so that item is withdrawn. ## Files a SWMR writer had open could not be read past a stale end of file