docs: local read A/B re-run on an idle machine
CI / test-arm64 (pull_request) Successful in 1m25s
CI / test (pull_request) Successful in 15m57s

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