observe(storage): extend per-phase I/O attribution beyond the construction path - #1422
Conversation
|
Important Review skippedAuto reviews are disabled on this repository. Please check the settings in the CodeRabbit UI or the ⚙️ Run configurationConfiguration used: Path: .coderabbit.yaml Review profile: CHILL Plan: Advanced Run ID: You can disable this status message by setting the Use the checkbox below for a quick retry:
Warning Billing warning: we have not been able to collect payment for this subscription for more than 72 hours. Please update the payment method or pay any pending invoices in Billing to avoid service interruption. Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
10a779f to
fff970c
Compare
`StorageIoPhase` attribution existed for the construction path only, which is why ingest can say 99.1% of its reads are authentication while nothing could be said about the 30% of lifecycle time spent opening projects. This adds the same attribution, in the same document shape, to project open, reopen, recount, query, export and clean import. Mechanism, modelled on the existing `io_stats` precedent: process-global phase-keyed counters in `graphforge_storage::lifecycle_io`, a thread-local `PhaseScope` for work whose owning phase is only known to the caller (the recovery-on-open pass), and a `ReadPathFile` `ChunkReader` that delegates entirely to Parquet's own `impl ChunkReader for File` and only counts, so read placement, buffering and error behaviour are unchanged. One phase name is added, `read_path_scan`. Every existing row names write-side construction, publication or open-time hydration; none describes decoding already-committed data to answer a read request. Without it, query I/O would be mislabelled as hydration and the open-versus-execute split this issue exists to measure would be destroyed. `StorageIoPhase::ALL` stays at nine and `ConstructionPhaseAttribution` still emits exactly those rows, so construction attribution is byte-identical; the new row lives only in `StorageIoPhase::LIFECYCLE`, used by `lifecycle_io`. Surfaced as an `application_io` block on the storage-attribution, result-sink, portable export and portable import CLI receipts, carried through the certify runner behind a fail-closed validator that requires the complete inventory and exact reconciliation, and assembled into rung evidence as `storage_attribution.lifecycle_application_io`. Evidence recorded before this change carries the block nowhere; such a rung omits the field and stays comparable, while a run where some phases carry it and others do not is refused. Instrumentation only: no behaviour, scheduling, durability, locking, result or error changes. The emitted document is the closed phase inventory and integer counters, with no paths, identifiers, query text or property content. Measured on the ordinary `gf` lifecycle at two scales: - A project open reads 3.99x the entire retained graph, flat across a 4x size range, and 99.97% of it is `hydration_verification`, which is authentication. - A bounded query's own `read_path_scan` work is 20,404 bytes against 71,846,538 bytes of re-opening the project. - A second query in the same session re-pays no open cost at all. - Instrumentation overhead is 14.3 ns per recorded operation and is not resolvable above noise end to end. Closes #1389 Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
… Python The new integration test crates/graphforge-api/tests/lifecycle_io_attribution.rs has a Bazel rule but no entry in the fail-closed migration target map, so the ledger check refused with cargo_target_count mismatch: map=127 cargo=128. Adds the mapped entry and bumps the count. Also applies ruff format to three benchmark harness files; those three diffs are formatting only, confirmed AST-identical to their previous contents. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
757654a to
211096a
Compare
What this does
StorageIoPhaseattribution existed for the construction path only. This extends it, in the same document shape, to project open, reopen, recount, query, export and clean import, and carries it into ladder rung evidence.Instrumentation only. No behaviour, scheduling, durability, locking, result or error change.
Mechanism
Modelled on the existing
io_statsprecedent rather than a parallel accounting scheme:graphforge_storage::lifecycle_io— process-global phase-keyed counters using the samePhaseIoTotalsfields and the same{phases, totals}document asConstructionPhaseAttribution, so existing analysis reads it without new tooling.PhaseScope— a thread-local override for work whose owning phase is only known to the caller (the recovery-on-open pass, which reuses the ordinary generation readers).ReadPathFile— aChunkReaderthat delegates entirely to Parquet's ownimpl ChunkReader for Fileand only counts, so read placement, buffering and error behaviour are unchanged.Surfaced as an
application_ioblock on the storage-attribution, result-sink, portable export and portable import CLI receipts; carried through the certify runner behind a fail-closed validator requiring the complete inventory and exact reconciliation; assembled intostorage_attribution.lifecycle_application_ioin rung evidence.The one new phase name, and why
read_path_scan. Every existing row names write-side construction, publication, or open-time hydration. None describes decoding already-committed data to answer a read request. Without it, query I/O is either unattributed or mislabelled as hydration — which would destroy exactly the open-versus-execute separation this issue exists to measure.StorageIoPhase::ALLstays at nine andConstructionPhaseAttributionstill emits exactly those rows. The new row lives only inStorageIoPhase::LIFECYCLE, with its own$defsin the rung and certification schemas, so the existing nine-namephaseMap, the twog500-*.schema.jsonphase maps andscripts/ci/validate-g500-certification.pyare untouched.Construction attribution is byte-identical — proven by diff
Identical ingest workflow (same scale, seed and operation UUID), run with
gfbuilt at the merge base1c078fa2and withgfbuilt from this branch, diffing theconstructionblock of the commit receipt:Rung evidence recorded before this change carries the new block nowhere; such a rung omits the field and stays comparable. A run where some lifecycle phases carry it and others do not is refused as a real gap. Both cases are covered by tests.
Measured per-phase attribution
The ordinary
gflifecycle — the same phases and the same commands the ladder profile runs — on a compact v2 project at two scales. Retained graph is 33.6 B/edge (s12) and 34.3 B/edge (s14)."Opens" counts the project opens performed by the receipts that carry attribution.
reopenexceeds 4× becausegf storage-attributionalso walks the authenticated inventories twice;exportandclean_importexceed it because the operation itself re-reads the graph on top of its open.Phase composition of the
queryphase at s14 (twogfprocesses, two boundedORDER BY ... LIMITtraversals):hydration_verificationpublication_preauthenticationread_path_scanFor comparison, the existing construction attribution on the same run (unchanged by this PR), s14 ingest:
recovery_reauthentication1,630 B/edge,shape_consume_reauthentication1,432 B/edge,encode_write_postwrite_authentication679 B/edge, total 3,812 B/edge read — the same order as the 4,579 B/edge recorded at S22 in #1384, an independent cross-check that the new mechanism agrees with the old one.The four questions
1. Does opening a project read or verify data proportional to edge count, and in which phase? — Yes, in
hydration_verification.A single project open reads 3.99× the entire retained graph, constant to within 0.5% across a 4× size range. It is
hydration_verificationat 99.96%. The remainingpublication_preauthenticationterm is flat at 16,252 bytes / 52 reads regardless of graph size — that one isFORMAT,CURRENT, the generation manifest and its participants, and it does not scale.A control run settles that this is the open and not the query. Four different queries against the same s14 project:
hydration_verificationbytesread_path_scanbytesRETURN 1(touches no graph data)MATCH (n) RETURN count(n)MATCH ()-[r]->() RETURN count(r)ORDER BY ... LIMIT 1000A query that reads nothing pays the identical 35,907,457 bytes, to the byte. The hydration figure is the open, in full, and
read_path_scanisolates the query's own work correctly.The code path responsible is
verify_graph_objectinsideResolvedProjectGeneration::graph_files_inventory()(project_generation.rs:358), whose V2 branch stream-hashes every CAS object, reached fromworkspace_hydration.rs:394,workspace_hydration.rs:275andproperty_overlay/inventory.rs:390, plus a further pass inmaterialize_graph_objects.One honest qualification: the counters record 138 object authentications per open against 60 CAS objects — 2.3 per object — while the byte multiplier is 3.99×. The two disagree, so authentication is biased toward the large objects rather than uniform, and the neat "reached three times plus once" reading of the call sites is not established by this instrumentation. Whoever removes the redundancy should confirm the per-object call multiplicity directly; what is established here is the byte volume and that it is authentication.
2. Is any part of the open path authentication or reauthentication, as the construction path is? — Yes; essentially all of it.
Every byte in
hydration_verificationon the open path is a SHA-256 authentication read.write_bytesis 0 on every open: nothing is copied, CAS objects are hard-linked, so there is no data-movement component to confuse it with. The open path has the same disease as ingest, at 4× rather than 17.3×.This is not #1269. #1269 (PR #1270, commit
7c0075d9) touched onlygraph_construction.rs,graph_construction/supersession.rsandconstruction_lifecycle_tests.rs, and chargesrecovery_application_read_bytes— it is therecovery_reauthenticationrow of the ingest attribution, the largest single ingest row at 1,630 B/edge. That work is deliberate and load-bearing. The open-path sweep is a different thing: it dates from #933 ("publish compact authenticated graph roots",project_generation.rs:358), and its multiplier is redundancy — the same objects authenticated four times within one open. Verifying once per open would preserve identical guarantees. The two must not be conflated when #1384 decides what can be removed.3. Is the cost dominated by I/O or CPU? — Partially answered; see the caveat.
Isolating the terms with
gf --info(no project open) as the fixed baseline:gf --infogf recoverys12 (1 open)gf recoverys14 (1 open)Process startup is only ~25 ms, so the growth is the open. Marginal cost between the two scales is 1.1 ms of CPU per MB authenticated (≈905 MB/s) against ~3.7 ms/MB of wall. So roughly 30% of the marginal cost is on-CPU, and
sysexceedsuser— the largest single CPU component is read syscalls, not the hash.Caveat, stated plainly: the remaining off-CPU time could not be cleanly attributed because other agents were building concurrently on this host throughout the measurement window, and the data here is page-cache warm at a scale where the ladder's 0.63 µs/edge regime does not yet apply. I could not settle device-versus-CPU at ladder scale. That needs a rung run carrying this attribution, which this PR enables and I deliberately did not run.
One incidental confirmation for #1384: a
storage-attributioninvocation authenticates 89.8 MB within 0.07 s of total user CPU, implying a SHA-256 rate above 1.28 GB/s. The host reportssha_niand OpenSSL measures 1.89 GB/s on it. So the hash primitive is hardware-accelerated, as #1384 assumed, and remains not the lever.4. Does a bounded query re-pay the open cost per query, or once per session? — Once per session; but the ladder's session is one process per query, so in the ladder it is per query.
In-process, a second identical bounded query on the same handle re-pays zero
hydration_verificationand zeropublication_preauthentication(asserted incrates/graphforge-api/tests/lifecycle_io_attribution.rs). Query execution clones cachedArcs and never re-resolves the generation.But each ladder query is its own
gfprocess. At s14 the two-queryqueryphase reads 71,846,538 bytes, of which 20,404 bytes (0.03%) is the query's own work and the rest is opening the project twice. A single boundedORDER BY ... LIMIT 1000traversal pays 35,907,457 bytes of open authentication to perform 10,202 bytes of its own reads — a factor of 3,520. Thequeryandreopencosts in the ladder are the same cost, counted once per process.Instrumentation overhead
record_readcalls in 142.98 ms).read()— roughly 500–2,000 invocations pergfprocess at these scales, i.e. 7–29 µs against phases of 0.2–3 s.gf, six runs each ofstorage-attributionon the same project: user 0.06–0.07 s both, sys 0.09–0.11 s both. Not resolvable above noise.It does not distort what it measures.
Verification
cargo fmt --all -- --checkclean;cargo clippy --workspace -- -D warningsclean. (--all-targetshas pre-existing failures across unrelated crates onmain; none in files this PR touches.)graphforge-storage1267 passed,graphforge-apilib 760 passed,graphforge-cli110 passed, certify runner 29 passed, plus the newlifecycle_io_attributionintegration test.make smoke-python's discovery (baseline runs 415; this PR adds one).progressive_run/progressive_storage_qualificationinventories, the exhaustivephase_namematch inscale_g500_ladder.rs, and the CLI closed-receipt tests.crates/graphforge-cli/tests/portable.rsnow asserts the new block separately and compares the remaining package receipt to the facade receipt, so the original "CLI invents or drops no package field" contract is exactly as strict as before.Known limits
PhaseScopedoes not propagate into DataFusion worker threads. Open-path decoding is synchronous on the opening thread, so this is sound today; it is documented in the module.Closes #1389
🤖 Generated with Claude Code
Need help on this PR? Tag
@codesmith-botwith what you need. Autofix is disabled.