A shallow clone of a big repository writes its checkpoint object by object, and holds it in memory whole issue #137 closed: completed andymccall opened this · 6 comments
andymccall set labels bug ·
closed by change 7bd805ffb418 ·
Fixed in 910c8ce4 (batched checkpoint; the state's binary files' blobs fetched, or lazy under --max-blob). Measured on Earth after the fix (VS Code history, loopback, server's checkpoint warm): oxy clone --depth 0 now completes, 458 s (git clone 91 s, git --filter=blob:none 30.5 s), 977 MB.
Profile (OXY_TIMINGS=1, 508 s that run): checkout 120 s (render 111 s over 19,545 files), decode the checkpoint 12 s, read its graph blobs 1.7 s, and about 375 s before that, in the fetch. The imported history's main has 33,835 heads, and depth 0 takes the changes "within 0 steps", i.e. the heads themselves: 33,837 changes bundled by the server and stored one by one (each quick). But the checkpoint already carries every change's metadata, and spec §17 calls a thin clone "a checkpoint plus zero history".
Next steps (not done tonight):
- Depth 0 takes no change: the heads become the shallow boundary and the checkpoint is the whole base.
- The checkpoint in parts (objects of about push.batch-bytes) instead of one response.
- Render the checkout on every core (render is 93% of checkout). Numbers are in docs/lazy-clone.md §9 (oxygen#132).
andymccall reopened ·
andymccall referenced by change 2aa1854b0d13 on main ·
Correction to my comment above: the 33,835 head changes were not where the time went. With phase timings on both sides (VS Code state, loopback, Earth under CI load, 2026-10-25 02:30 GMT):
| phase | before | after |
|---|---|---|
| server: gather the checkpoint's objects (57k graph blobs + chunks) | 375 s, one read at a time | 239 s, two parallel get_many reads |
| server: encode the bundle | 18.5 s | 19.3 s |
| client: whole checkpoint answer (incl. the above + transfer) | 405 s | 270 s |
| client: decode / store the checkpoint / binary blobs | 7.9 s / 5.9 s / 4.9 s | |
| client: checkout (render 19,545 files, one core) | 116-122 s | 121 s |
| total | 704 s | 547 s |
So the remaining cost is reading 57k objects out of ~95 packs (still ~4 ms each in parallel: worth profiling the pack read path), encoding and moving one 2 GB answer, and rendering on one core. Depth 0 now takes no change anyway (spec §17), which is right but saved little here. Next: profile pack reads; the checkpoint in parts (and without graphs for issue #132's lazy clone); render on every core.
referenced by 2 changes on 25 Oct 2026
Rendering fixed in 9580390c (run #375 green), with issue #138 and the measurements found on the way. Profiled with OXY_TIMINGS and counters (perf is blocked by perf_event_paranoid=4 on Earth and here, a system setting I left alone).
The checkout was slow, not the reads. On the VS Code depth-0 clone (19,545 files, 166,425 changes):
State::depends_on, which rendering asks of every deleted line with a live successor, was a depth-first walk that compared a change with the one sought only on popping it, so it went through thousands of changes before finding a direct dependency, which spec §8.1 makes the usual answer (a deletion depends on the inserter of the line after it). 262,678 questions took 4.4 billion steps and 838 CPU-seconds; looking for the dependency as each change's deps are pushed answers all but 12 at once: 5 CPU-seconds, same answers.subrepos()materialized the whole state (rendered every file) after every clone, pull, switch andworkspace add; it now reads the tree and the pins (~70 s and 11 GB on that clone).oxy workspace addstarted the new workspace on the target heads with an empty directory, so the checkout's first snapshot found the whole tree deleted and rendered it to say so (195 s on Earth); it now starts on nothing.
| before | after | |
|---|---|---|
oxy workspace add, workstation (8 cores) | 176 s, 11.4 GB | 7.5 s, 1.8 GB |
oxy workspace add, Earth (4 cores, HDD) | 467 s | (250 s with the workspace fix alone) |
oxy clone --depth 0, Earth: checkout | 116-121 s | 9.9 s |
oxy clone --depth 0, Earth: total | 547 s | 477 s |
The graph-blob reads I suspected (4.5 ms each) were a cold page cache on Earth's spinning disk: warm, the same 17,444 reads take 1.2 s.
What is left is the server gathering the checkpoint's objects: 411 s of the 477 (239 s last night, so it varies with Earth's page cache), then 21 s encoding. The reads are random across ~95 packs on an HDD. Next, in order: read a get_many's packed objects in (pack, offset) order so the disk sweeps instead of seeking (cheap; needs a cold-cache measurement, which wants root to drop caches); then keep the encoded checkpoint answer beside the checkpoint so it is gathered once, not per clone; then the checkpoint in parts.
andymccall referenced by change 795b8b502ded on main ·
Decided (Andy, 2026-10-26): no cache; the checkpoint in parts. The answer names its objects and the client fetches them in batches of about push.batch-bytes, so it streams, holds less in memory, and a lazy clone (issue #132) can leave graph parts out.
andymccall referenced by change 80b069facc69 on main ·
Measured 2026-10-27 05:41 on Earth: oxygen main (the checkpoint in parts) built in release, the VS Code depth-0 clone over loopback, CI idle, the run itself under ionice -c3 nice -n19 as heavy disk work on Earth now runs:
| before (2026-10-25) | now | |
|---|---|---|
| total | 477 s | 303 s |
| the checkpoint's graphs (server gathering + transfer) | 411 s gather + 21 s encode | 280 s, in parts |
| binary files' blobs | 6.2 s | |
| store the checkpoint | 0.9 s | |
| checkout (render and write 19,545 files) | 9.9 s | 10.8 s |
| peak memory | 1.67 GB | |
| disk | 940 MB |
Most of what's left is the server reading the graph parts' objects across ~95 packs on a spinning disk, now streamed in parts instead of gathered into one 2 GB answer. The next lever is the pack read path itself (reads in (pack, offset) order went in on 10-26, d4a414b5), or a lazy clone that leaves graph parts out (issue #132).
Closing: all three causes are fixed and released. (1) The checkpoint is stored in one batch (oxy 0.7.0). (2) It comes in parts: checkpoint-index plus objects in batches of 2,048, never one 2 GB answer (0.8.0), and objects are read in pack order. (3) Building a checkpoint for heads with none is timed on its own (checkpoint: find or make under OXY_TIMINGS=1). Measured 2026-10-27: the VS Code depth-0 clone went from 477 s to 303 s at 1.67 GB peak, most of what is left being the server's pack reads on a spinning disk. The next step there is a lazy clone that leaves graph parts out (issue #132).
andymccall closed ·
Found measuring oxygen#132's baseline on Earth (2026-10-25 01:00, VS Code history,
oxy clone --depth 0over loopback): after 38 minutes the clone had written 57,498 loose objects (1.8 GB, about 27 a second), the client held 3 GB, and the disk was 91% busy with flushes; git clone of the same history takes 91 s.Causes:
Repo::fetch_shallowstores the checkpoint bundle withstore.putper object, outside a batch, so each graph blob and chunk is written loose and flushed. A fetch'simport_bundleusesbegin_batch+put_many(packed, compressed on every core). Fix: the same here (done in the working copy; measuring).checkpointanswer is one response: the whole state's graph blobs in one body, decoded in memory. It should stream, or come in parts (the client askingobjectsfor the graph blobs the payload names, in batches of aboutpush.batch-bytes), which also lets a lazy clone (issue #132) leave them out.