sync: measure where a pass actually spends its time - #68
Merged
Conversation
Nathan says fabric uses too much CPU. Nobody can currently say which part of a sync pass spends it, and three attributions were reported and withdrawn in one evening because of that. Each guess cost more than measuring would have. This adds the measurement. TWO COUNTERS, AND THE FIRST ONE IS A BUG FIX AS MUCH AS AN INSTRUMENT. `sync_passes` counts calls to `sync_once`. `full_scans` does NOT: it counts TWO per call, because `sync_once` scans before the peer step and again after. Reading `full_scans` as a pass rate doubles it, and dividing a per-pass cost by it halves the answer. That is exactly how a guard effectiveness figure of 58 percent was reported against the live fleet and then withdrawn; the honest number was at most about 15 percent. `scan_micros`, `materialize_micros`, `persist_micros` and `reconcile_micros` are cumulative microseconds per phase. Cumulative, not per-pass, so a reader takes two samples and divides. A total on its own describes the past. All of it is exposed through `fabric sync ls` and its `--json` form, next to the counters already there. WHY CUMULATIVE COUNTERS RATHER THAN LOG LINES. The existing observability counters are read by sampling `fabric sync ls` twice, and a log line would need a parser and a retention policy to answer the same question. TESTS, AND I WATCHED BOTH FAIL. `full_scans_counts_two_per_pass_and_sync_passes_counts_one` pins the 2:1 ratio as a property of the function. Mutated `sync_passes` to increment by two: "left: 10, right: 5". `phase_timers_follow_the_work_and_not_the_pass` pins that a phase timer is wired to the work it names, not to the pass. Every pass scans; only a changed pass writes. So `scan_micros` must keep rising while `persist_micros` stays flat across no-op passes. Moved the persist timer outside the guard that skips the write, and it failed. Neither test mirrors the change. Both would fail if the timers were attached to the wrong call sites. THE NEW FIELDS BROKE THE `sync ls --json` SCHEMA TEST, AS THEY SHOULD. That test only runs at all because #67 added `cargo test --bins` an hour ago. Before that it did not compile and CI could not see it. This is the first change it has caught. WHAT THIS DOES NOT DO. It fixes no CPU. It makes the next fix aimable. The walk is already known not to be the answer: the watched tree is 16.6 MB across 17,175 files, a full stat pass over it costs about 36 ms, and one `sync_once` costs roughly 1.8 s. Agent: Silber.fabric
myobie
added a commit
that referenced
this pull request
Aug 24, 2026
The per-phase counters from #68 say the peer step is 90.8 percent of a sync pass on Silber, and that it is CPU rather than blocking. They cannot say whether both peers cost the same. That distinction decides the fix. In the window I measured, droppy was relay-routed and hetz was direct, in the same pass. If one of those dominates, the answer is about the path. If they cost the same, the answer is about the manifest, which is the same 31,000 entries either way. The aggregate counter hides exactly that. So each peer's reconcile is timed and logged to the validation log: peer, microseconds, and whether it failed. EMITTED BEFORE THE OUTCOME IS MATCHED, DELIBERATELY. Putting this inside the Ok arm would have hidden every failing peer, and a peer that times out or retries on a relay is precisely the expensive case being hunted. A diagnostic that only fires on success fails open and reports a healthy picture of an unhealthy one. A LOG LINE RATHER THAN A COUNTER, WHICH IS THE OPPOSITE OF #68. Peers are dynamic, so per-peer counters would put an unbounded set of keys on the control wire. This question is also a one-off: once we know whether the path matters, the line has served. The volume is proportionate at about 4.6 lines a minute against the roughly 15 that log already writes. `VALIDATION_LOG_TARGET` becomes `pub(crate)` instead of being retyped in a second place. Two copies of a literal drift apart. NO NEW TEST, AND I WILL NOT PRETEND OTHERWISE. This emits a diagnostic and changes no behaviour. The 237 lib and 12 bin tests are the control that it changed nothing. A test asserting a log line fires would need a subscriber-capture harness and would mirror the change rather than check it. Verified on macOS 15 arm64. Linux is CI's. Agent: Silber.fabric
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What this changes
Nathan says fabric uses too much CPU. Nobody can currently say which part of a
sync pass spends it. Three attributions were reported and withdrawn in one
evening for exactly that reason. Each guess cost more than measuring would have.
sync_passesis a bug fix as much as an instrument. It counts calls tosync_once.full_scansdoes not — it counts two per call, becausesync_oncescans before the peer step and again after. Readingfull_scansasa pass rate doubles it; dividing a per-pass cost by it halves the answer. That is
precisely how a guard-effectiveness figure of 58% was reported against the
live fleet and then withdrawn. The honest number was at most about 15%.
scan_micros/materialize_micros/persist_micros/reconcile_microsare cumulative microseconds per phase, exposed through
fabric sync lsand--jsonbeside the counters already there. Cumulative rather than per-pass, so areader takes two samples and divides — a total on its own describes the past.
What was verified, and what was not
Platform: macOS 15 on arm64 (Silber). Linux is CI's.
cargo test --lib— 237 passed, 0 failed.cargo test --bins— 12 passed, 0 failed.I watched both new tests fail, by mutating the code they guard.
full_scans_counts_two_per_pass_and_sync_passes_counts_onesync_passesincrements by 2left: 10, right: 5phase_timers_follow_the_work_and_not_the_passNeither test mirrors the change. The second pins a property rather than a
counter: every pass scans, only a changed pass writes, so
scan_microsmust keeprising while
persist_microsstays flat across no-op passes. A timer attached tothe wrong call site fails it.
The new fields broke the
sync ls --jsonschema test, as they should. Thattest only runs at all because #67 added
cargo test --binsan hour ago — beforethat it did not compile and CI could not see it. This is the first change it
has caught.
Not verified: the instrument's own overhead. Four
Instant::now()pairs perpass against a pass costing ~1.8 s is not a number I felt the need to defend, but
I did not measure it and am not claiming it is zero.
What this does not do
It fixes no CPU. It makes the next fix aimable.
It also rules nothing in. The walk is already known not to be the answer: the
watched tree is 16.6 MB across 17,175 files, a full stat pass costs ~36 ms, and
one
sync_oncecosts roughly 1.8 s. I am not naming a target until thisinstrument names one.