The zarr export is 88% of the pipeline and ~5x its last recorded cost — measure before optimising

The zarr export is now 88% of the pipeline's wall time and roughly 5× its last recorded cost. This issue asks for a measurement, not a fix — the leading candidate below is grounded in code but does not fully close the arithmetic, and ADR-041's own history is a warning against acting on a diagnosis that names one cause when there are three.

Measured

2026-10-16 production run, v1.14.0, views-datafactory-00 (CPX32: 4 vCPU, 8 GB RAM, 160 GB SSD):

Output: data/assembled/grid.zarr
Store size: 3.1 GB
Chunks: 12 months x 360 lat x 720 lon
Time: 18426.6s
PASS
...
Pipeline refresh complete
Duration: 21007s


Zarr export	18,427s (5h07m)
Whole pipeline	21,007s (5h50m)
Export share	88%
Assembly this run	skipped — inputs unchanged (ADR-041)

Against the two prior records:

When	Export	Store	Features	Source
2026-03	~14 min	1.8 GB	43	`docs/guides/hetzner_deployment_log.md` step table
2026-06	~57 min	—	—	`docs/ADRs/041_content_addressed_skip.md` Context
2026-10-16	307 min	3.1 GB	79	this run

The feature count is derived, not printed: grid.npy is 37,349,683,328 bytes and one 456 × 360 × 720 float32 plane is 472,780,800 bytes — exactly 79.00 planes. The grid has grown 43 → 79 features (1.8×) while the export grew 14 → 307 min (22×).

That gap is the whole question. Growth in the data does not explain growth in the cost.

Leading candidate, grounded but incomplete

scripts/export_zarr.py memmaps the grid and then slices the last axis:

grid = np.load(grid_path, mmap_mode="r")          # :212  — 37.3 GB, C-order
...
for i, name in enumerate(feature_names):          # :241
    feature_slice = grid[:, :, :, i]              # :242  — last-axis slice
    source_sums[name] = float(feature_slice.sum())# :243  — full pass, per feature
    data_vars[name] = (["time", "lat", "lon"], feature_slice)

The grid is [T, H, W, F] in C order, so the 79 features for a given (t, h, w) are adjacent and a single feature plane is maximally strided. Reading feature i touches every 4 KB page in the file while using 1/79 of each page's contents. With 37.3 GB against 8 GB of RAM the page cache cannot hold it, so each feature read is effectively a full-file read.

The file is then traversed this way at least twice:

:243 — feature_slice.sum() for all 79 features, purely to populate source_sums for the later integrity check. One full-file traversal per feature.
ds.to_zarr(...) at :373 — xarray pulls each feature_slice again to compile and write. A second traversal per feature.
:384 — the round-trip check does np.array(store[name]).sum() for every feature. This one reads from the 3.1 GB zarr rather than the memmap, so it is cheap by comparison, but it does fully decompress ~29 GB.

Upper bound if nothing caches: 79 × 37.3 GB ≈ 2.95 TB of page-ins per pass, twice. At a plausible effective SSD rate that lands in the right order of magnitude for 5 hours.

Why I am not calling this the cause. The same access pattern existed in March at 43 features and the export took 14 minutes. A 1.8× growth in F does not turn 14 min into 307 min under this model either. Something is non-linear — plausibly the point at which the working set crossed a threshold (RAM, or SSD read-ahead effectiveness), but that is a hypothesis about the machine, not a reading of the code. There may also be a second cause entirely.

Ask — instrument before changing anything

Time the three phases separately inside export_zarr.py and print each: (1) the source_sums loop, (2) ds.to_zarr, (3) the round-trip verification. This is a few time.monotonic() calls and a print. It is the only thing that distinguishes the candidate above from an unrelated cause, and nothing should be optimised before it exists.
Record the result against the figures in the table above, in reports/. · reports/investigation_zarr_export_cost/findings.md (Record the 2026-10-21 export breakdown in reports/, and amend the one stale cost record the October sweep missed (#501 box 2) #515, 2026-10-21)

Deliberately not proposed here: any change to chunking, compression, the slicing pattern, or the integrity check. Each is a plausible remedy for a cause that is not yet established, and the integrity check in particular is a C-144/ADR-011 guarantee that must not be weakened to save time.

Consequence worth recording regardless

ADR-041 understates its own benefit by about 3.4×. Its Consequences section says "no-change deploys drop from ~103 min to ~30 sec", derived from assembly ~46 min + export ~57 min. With the export at ~307 min the skip now avoids roughly 350 min, making it the single largest runtime saving in the pipeline. Any future decision that treats assembly and export as comparable in cost — which to optimise, which to parallelise, which to make skippable — starts from a false premise.

Amended in docs/ADRs/041_content_addressed_skip.md (2026-10-18) rather than rewritten; the Context figures are left as measured in June.

Why this issue exists separately from the docs fix

The stale duration figures across the guides were a documentation defect and are corrected in #500. This is not that. It is a performance question that needs instrumentation, and conflating the two would have shipped a guess as a finding.

See also: ADR-041 (content-addressed skip, and its 2026-10-18 amendment), C-343's 2026-10-18 addendum in reports/technical_risk_register.md, #500 (the duration figures), C-105 (disk pre-flight, which sizes against expected_bytes × 1.2), C-144 (the atomic .tmp → rename swap this export performs).

Instrumentation built — and a prediction registered before it runs

The instrumentation this issue asked for is implemented. This comment records what each outcome would mean, before the production measurement exists, so the result is a test rather than something to rationalise afterwards. The leading candidate in the issue body is mine; pre-committing the falsification criterion is the only thing that stops me reading the eventual numbers as confirmation of it.

What gets measured

Four phases, printed in the export's own summary and written to export_ledger.jsonl as phase_seconds:

Phase	What it covers
`scan`	the `source_sums` loop — one strided traversal of `grid.npy` per feature
`write`	`ds.to_zarr(...)` + `consolidate_metadata` — the second traversal, plus compression
`verify`	the round-trip integrity check — full decompression of the written store
`swap`	the C-144 `.tmp` → rename dance
`other`	the remainder, reported explicitly so the columns account for the whole of `Time`

Baseline: the synthetic grid, where the hypothesis should NOT hold

7 features, 12 months, 0.1 GB — comfortably inside RAM, so the page cache absorbs the strided reads:

Time: 1.9s
Phases:
  scan          0.2s   10.1%
  write         0.7s   35.2%
  verify        0.5s   24.7%
  swap          0.0s    0.0%
  other         0.6s   30.0%

scan is the smallest named phase here. That is the expected shape when the working set fits in memory, and it is the contrast the production run is measured against.

Pre-registered interpretation

If production shows	Then
`scan` > 50%	the strided last-axis read of a 37 GB memmap is the dominant cost. The candidate in the issue body is supported.
`write` dominant, `scan` small	the cost is compression or the zarr write path, not the access pattern. Chunking and codec become the question.
`verify` dominant	the integrity read-back is the cost. This is the hardest case, because the check is an ADR-011/C-144 guarantee and must not simply be deleted.
`other` dominant	the cost is in grid load or digest computation, and every hypothesis in this issue is wrong.

Falsification criterion: if scan comes in under ~25% of the export, the strided-memmap explanation is refuted and I stop advancing it. The synthetic run above puts scan at 10.1% when the data fits in RAM; the entire hypothesis is that crossing the RAM boundary changes that relationship. If it does not, the explanation is wrong regardless of how plausible the page arithmetic looks.

A second prediction worth separating, because it is independently falsifiable: scan and write should be roughly comparable if the hypothesis holds, since under this model both make one full-file traversal per feature and the compression in write is a smaller additional cost. If scan is large and write is small, something asymmetric is happening that the model does not capture.

Guarded, and the guard drilled

Three tests in tests/test_synthetic_pipeline.py::TestZarrExport:

the four phase labels reach the ledger as an exact set — a subset assertion would let a dropped phase restore the original blindness silently
phases are non-negative
phases sum to no more than the reported total — a timer that spans work it does not own would misattribute precisely the cost this issue exists to locate

Both substantive guards were sabotaged to confirm they bite, rather than assumed to work:

Sabotage	Result
delete `phase_seconds["swap"] = ...`	`test_phase_timings_recorded` FAILED
inflate the `scan` timer past the total	`test_phases_do_not_exceed_the_total` FAILED — `phases sum to 9999.8s but total is 1.3s`

Explicitly not done

No change to chunking, compression, the slicing pattern, or the integrity check. The first ask of this issue is a number, and nothing should be optimised before it exists.

How to get the number

Next pipeline run on the server produces it automatically — the breakdown prints in logs/refresh.log and persists in data/assembled/export_ledger.jsonl, so it survives log rotation. No separate run required, and it will be the first export measured this way.

perf: time the zarr export's four phases — 5h07m with no breakdown co…

Correction: the number does not arrive on its own

My previous comment closed with "Next pipeline run on the server produces it automatically." That is wrong, and I am correcting it before anyone waits on a number that cannot arrive.

The server does not run development. Per ADR-022, refresh_pipeline.sh reads ~/.views-deploy-tag and git checkouts that exact tag before running any step. The deployed tag is v1.14.0, which points at 2b22a64 — four commits before the instrumentation:

$ git show v1.14.0:scripts/export_zarr.py | grep -c phase_seconds
0

So the next monthly run on the 21st will execute the uninstrumented export and print no breakdown. The measurement requires a release and a deploy, each separately gated and not started without explicit confirmation.

The shape of the mistake is the one C-343 is about

C-343's standing statement is "writing the deploy tag is not deploying." I made the structurally identical error one layer up: merging the instrumentation is not deploying the instrumentation. The register's own open concern describes exactly the gap I just fell into — the step between "the change exists in the repository" and "the change is what runs" is invisible unless something names it.

That is worth more than the correction itself: it is the second independent instance of the same confusion in three days, by the author of the first correction. Logged here rather than in chat so the pattern is countable.

What this issue is actually waiting on

Step	State
Instrumentation merged to `development` (#502)	done, `7ce9b6b`
Release — version bump, `development`→`main`, tag, GitHub Release	not started — needs explicit confirmation
Deploy — write the new tag to `~/.views-deploy-tag`, verify it took	not started — needs explicit confirmation
Production run produces `phase_seconds`	blocked on the two above, then automatic
Compare against the pre-registered table, record in `reports/`	blocked

Once deployed, the rest of the earlier comment stands: the breakdown prints to logs/refresh.log and persists in data/assembled/export_ledger.jsonl, so it survives log rotation and no separate run is needed.

The timing is not neutral. The monthly cron runs 00:00 on the 21st. A deploy before then gets the measurement on a run that was going to happen anyway; missing it means either a deliberate out-of-band run or waiting until 21 November — five weeks of this issue sitting open with the instrument built and idle.

The pre-registered falsification criterion is unchanged and still committed ahead of any production figure: if scan comes in under ~25% of the export, the strided-memmap explanation is refuted and I stop advancing it.

chore: bump to 1.15.0 — the wheel is code-identical, the git tag is t…

Merge pull request #504 from views-platform/development

docs: a count is a copy too — four places still said deploying is thr…

docs: post-mortem for v1.15.0 — the spine named in August recurred fi…

The breakdown exists. The criterion was committed before it did, and it is not met.

2026-10-21 production run, v1.15.0, views-datafactory-00. First export_ledger.jsonl entry ever
to carry timings — the three prior entries (2026-08-21, 2026-09-21, 2026-10-16) have outcome and a
digest and nothing else, so there is no earlier production breakdown to compare against.

{"stage": "export", "outcome": "success", "elapsed_seconds": 17773.8,
 "phase_seconds": {"scan": 8434.2, "write": 8558.9, "verify": 23.8, "swap": 0.3},
 "source_digest": "053241912fc36c92", "timestamp": "2026-10-21T11:52:34.324282+00:00"}

phase	seconds	share of export
`scan` — `source_sums` loop, one strided traversal per feature	8,434.2	47.5%
`write` — `to_zarr` + metadata consolidation	8,558.9	48.2%
`other` — grid load, coords, digests, sentinel	756.6	4.3%
`verify` — ADR-011/C-144 round-trip read	23.8	0.1%
`swap` — `.tmp` → rename	0.3	0.0%
	17,773.8	100%

Against the pre-registered criterion

if scan comes in under ~25% of the export, the strided-memmap explanation is refuted and I stop
advancing it

scan is 47.5% — nearly twice the refutation threshold. The explanation survives this test.

The stated contrast holds in the direction predicted. On the synthetic baseline, where the grid is
0.1 GB and fits in RAM, scan was 10.1% and the smallest named phase. In production at 37.3 GB
against 8 GB of RAM it is 47.5% and co-largest. That is the inversion the claim was entirely
about, and it was written down before the number existed.

What this does not establish. Surviving a refutation test is not confirmation. #501's own
objection stands untouched by this breakdown: a 43 → 79 feature growth does not turn 14 minutes into
307 under any linear reading of the strided model, so something is still non-linear and the
breakdown cannot say what. scan being large is consistent with the explanation; it is not proof of
it, and it does not exclude a second cause.

The one new observation worth recording

verify reads every feature back out of the finished store — by #501's own estimate ~29 GB
decompressed — in 23.8 seconds, while scan reads 37.3 GB strided out of the memmap in 8,434
seconds. Comparable volumes, same machine, same run, ~350× apart.

That is suggestive rather than clean: the 3.1 GB store had just been written and fits inside 8 GB of
RAM, so much of verify was very likely served from page cache. The 350× is therefore an upper
bound on the access-pattern effect, not a controlled measurement of it. The honest statement is
that the cheap read is the sequential one over data that fits, and the expensive read is the strided
one over data that does not.

Two figures in the issue body that this run changes

Export cost is stable. 17,773.8s here against 18,426.6s on 2026-10-16 — a 3.5% drop. This run
is a fair proxy for the one the issue was opened on, which is what makes the breakdown applicable.
The 88% share is not a constant. Whole pipeline today: 26,708s (7h25m), so export was
66.5%. The difference is that 2026-10-16 skipped assembly under ADR-041 and this run did not.
88% describes a no-change-upstream run, not every run.

Still open on this issue

The second ## Ask box — recording the result in reports/ — is not done by this comment. Nothing
in ## Deliberately not proposed here has been touched: no change to chunking, compression, the
slicing pattern, or the integrity check.

One defect noticed and deliberately not fixed here: other is printed to logs/refresh.log but
not persisted into phase_seconds in the ledger, so the ledger's four keys sum to 17,017.2 of
17,773.8s and a reader has to subtract to find the missing 756.6s. Logs rotate, the ledger does not
— which was the stated reason for the ledger in the first place.

Navigation Menu

Repository navigation

The zarr export is 88% of the pipeline and ~5x its last recorded cost — measure before optimising #501

Measured

Leading candidate, grounded but incomplete

Ask — instrument before changing anything

Consequence worth recording regardless

Why this issue exists separately from the docs fix

Instrumentation built — and a prediction registered before it runs

What gets measured

Baseline: the synthetic grid, where the hypothesis should NOT hold

Pre-registered interpretation

Guarded, and the guard drilled

Explicitly not done

How to get the number

Correction: the number does not arrive on its own

The shape of the mistake is the one C-343 is about

What this issue is actually waiting on

The breakdown exists. The criterion was committed before it did, and it is not met.

Against the pre-registered criterion

The one new observation worth recording

Two figures in the issue body that this run changes

Still open on this issue

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

The zarr export is 88% of the pipeline and ~5x its last recorded cost — measure before optimising #501

Description

Measured

Leading candidate, grounded but incomplete

Ask — instrument before changing anything

Consequence worth recording regardless

Why this issue exists separately from the docs fix

Activity

Polichinel commented on Oct 18, 2026

Instrumentation built — and a prediction registered before it runs

What gets measured

Baseline: the synthetic grid, where the hypothesis should NOT hold

Pre-registered interpretation

Guarded, and the guard drilled

Explicitly not done

How to get the number

Polichinel commented on Oct 18, 2026

Correction: the number does not arrive on its own

The shape of the mistake is the one C-343 is about

What this issue is actually waiting on

Polichinel commented on Oct 21, 2026

The breakdown exists. The criterion was committed before it did, and it is not met.

Against the pre-registered criterion

The one new observation worth recording

Two figures in the issue body that this run changes

Still open on this issue

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions