Experiment benchmarks catalog log progress findings - kmosoti/FabricO11y GitHub Wiki
Historical report imported 2026-10-10 from
docs/experiments/benchmarks/catalog-log-progress-findings.md. Original SHA-256:f82341fb97775dfcc0ef4e905bff41c8be237218f0c1cfa8671b0c356ac2009e. Measurements and outcomes retain their stated revisions. Links and local environment labels are normalized;$FABRIC_DATAis the mounted experiment drive. See evidence policy.
Bounded collection progress and owned log projection
This round fixed a reproduced collector stall and removed redundant copies from
server log extraction. It follows the original protocol (local checkout reference docs/experiments/benchmarks/catalog-log-progress-protocol.md; not present at origin/main)
and fresh retry registration (local checkout reference docs/experiments/benchmarks/catalog-log-progress-retry-protocol.md; not present at origin/main).
The three labs separated collection progress, row ownership and evidence storage;
root serialized every workload through the resource launcher and coordinator.
Before and after
| Area | Before | Retained change and observed result |
|---|---|---|
| Oversized source line | After committing its initial gap, an otherwise quiet pass discarded further skip progress and repeatedly started at 1 MiB | Real late metrics carry forward progress through the existing Batch commit; four bounded passes reach the normal line, including a restart |
| Decoded log rows | Owned OTLP body, attribute key and string value allocations were cloned into rows | Consuming iteration moves those allocations; whole-extraction median time fell 20.9–37.0% in the four registered cells |
| Historical protocol snapshots | 195 identical files used separate physical inodes | 194 hardlink replacements retain all 195 paths and exact bytes; gross reclaim 6,356,992 bytes, net observed reclaim 6,201,344 bytes |
These results concern finite progress, extraction and experiment storage. They do not measure a new ingestion acceptance rate, ACK latency, query-service rate, application RSS or deployment readiness.
The progress defect and correction
The original reproduction receipt (local evidence omitted from stage)
records the unmodified runtime's Rust regression exit 101. Its
trace (local evidence omitted from stage) shows that pass two returned
no Batch, leaving cursor 1,048,576, ACK 1 and next sequence 2. The driver returned
0 only after confirming this expected counterexample. The complete failed
fixture is retained in an exactly read-back
archive (local evidence omitted from stage), with its
manifest (local evidence omitted from stage).
The fixture has a 3 MiB-plus-10-byte oversized line followed by normal.
The reader already offered bounded cursor progress, but collection rejected an otherwise empty candidate. A cursor-only Batch is invalid. The correction in runtime.rs recognizes forward progress from the same existing oversized-skip cursor and samples actual host metrics late. A real sample failure carries the existing host-failure gap instead. It never rereads source bytes or duplicates the already reported oversized-line gap. Cursor and replacement counter history still become authoritative only after the original durable Spool append succeeds.
The corrected trace (local evidence omitted from stage) is:
| Pass | Committed source offset | ACK after commit | Logs | Metric points | Gaps |
|---|---|---|---|---|---|
| 1 | 1,048,576 | 1 | 0 | 0 | 1 |
| 2 | 2,097,152 | 2 | 0 | 11 | 0 |
| Restart | Restored pass-two state | 2 | — | — | — |
| 3 | 3,145,728 | 3 | 0 | 11 | 0 |
| 4 | 3,145,746 | 4 | 1 | 0 | 0 |
Exactly one oversized-line gap and one normal log remain. Its byte range is
3,145,739–3,145,746; no discarded suffix becomes a log. Five
progress controls (local checkout reference src/spindle/skip_progress_tests.rs; not present at origin/main) exited 0:
the original regression, full-Spool refusal and reopen/retry, host failure,
true EOF/ordinary quiet, and closing the oversized line before an incomplete
normal suffix. Six existing collection ownership controls also exited 0. An
altered trace with a stalled second cursor is rejected by the result checker.
The explicit cost is extra metric observations on these otherwise quiet skip passes: two samples of 11 points in this fixture, despite a 3,600-second metric interval. This uses the existing metric-bearing Batch path, like rotation-driven sampling. It does not establish arbitrary-source liveness or a new freshness bound; bounded Spool capacity and source/sample errors still apply.
Log extraction comparison
The server's extractor now consumes only the decoded log tree. Metrics, spans, gap copying, node labels, hex formatting and decode order retain their prior paths. The raw release output (local evidence omitted from stage) has 24 arms: four cells, three alternating pairs, 20 repeats of eight Batches with 128 logs per arm, seed 42. Every arm checks 20,480 output rows outside timing.
| Body bytes | String attributes/log | Three candidate/legacy time ratios | Median ratio | Median time reduction |
|---|---|---|---|---|
| 16 | 0 | 0.749, 0.784, 0.780 | 0.780 | 22.0% |
| 16 | 8 | 0.525, 0.650, 0.630 | 0.630 | 37.0% |
| 1024 | 0 | 0.848, 0.791, 0.715 | 0.791 | 20.9% |
| 1024 | 8 | 0.644, 0.731, 0.596 | 0.644 | 35.6% |
All registered median guards met: at least 5% less time in each large-body cell and no more than 10% regression in each small-body cell. The summary (local evidence omitted from stage) retains all ratios. Fixture encoding is outside the timer; whole Batch/request decoding, projection, decoded-tree destruction and output accumulation are inside. Both arms retain all output sets until after timing, so final output destruction is outside. The baseline is a literal frozen whole extractor, not a projection-only model. Three pairs on one host do not establish a general speedup distribution.
Three projection controls exited 0 before timing. They compare frozen output and literal fields across mixed signals, resource/scope boundaries, Unicode, missing/non-string bodies, duplicate attributes, NaN/signed-zero bits, integer boundaries, malformed inputs and partial output on later decode failure. Live pointer controls distinguish moved body/key/value allocations from clones; they do not measure total allocator traffic. Altered duplicate, body and signed-zero outputs are rejected. Review subsequently identified OTLP dictionary-reference fields omitted from the original fixture; an additional exact compatibility control preserves the legacy literal-key/StringValue-only behavior. It is part of final verification, without modifying the measured production source or timing fixture. Fabric does not gain dictionary resolution from this change.
The first corrected run failed compiling two new KeyValue test constructors
that omitted key_strindex. Its receipt (local evidence omitted from stage)
and compiler output remain; no projection control or timing ran there. The fresh
retry supplied those default fields and preserved all expected data and guards.
Resources, cleanup and verification
Exact executed commands, exit codes and source hashes are in the comparison receipt (local evidence omitted from stage), with exact post-format source copies. The retry launch was:
python3 -B tools/resource_group.py -- python3 -B tools/bench/labs/completion/run_job.py --id catalog-log-progress-round-02 --lab coordinator --stage preparation --seconds 900 -- python3 -B tools/bench/labs/catalog/coupled_admit.py --reserve-mib 2 -- python3 -B tools/bench/labs/catalog/log_progress_round.py
It exited 0 in 42.554 seconds, used 126.873 cgroup CPU seconds and peaked at
1,402,757,120 cgroup memory bytes. Sampled scratch peaked at 3,147,550 bytes.
These include compilation and cache, not application RSS or per-arm CPU. The
coordinator receipt (local evidence omitted from stage)
records zero high/max/OOM events, zero swap, no surviving descendants and owned
scratch removal. Build/scratch paths use $FABRIC_DATA.
All descendants share 20 GiB max, 16 GiB high, no swap and a 30-minute outer
deadline; the default launcher imposes no CPU quota. No remote workload ran.
The storage reclamation protocol (local checkout reference docs/experiments/benchmarks/catalog-protocol-dedup-protocol.md; not present at origin/main) and
receipt (local evidence omitted from stage)
record exact byte/inode and full manifest readback for every transformed path,
inactive producer checks, rejected corrupt-content/wrong-target controls and no
orphaned temporary links. Original metadata is retained in the manifest; the
linked files now share the keeper's metadata. Historical copies must remain
immutable. The failed-run cleanup receipt (local evidence omitted from stage)
preserves its empty remaining fixture tree with an archive manifest before
removing only the inactive owned root. Prior failures and results remain intact.
Final fast and manual documentation commands and actual outcomes are recorded in the verification receipt (local evidence omitted from stage). Its coordinator receipt (local evidence omitted from stage) records resource observations and cleanup. The temporary Bun executable is removed only after exact comparison with its retained archive member and a saved reference. All elapsed work remains charged to the original frontier; these runs create no new budget or qualification claim.
What this suggests next
The larger gain with eight attributes suggests allocation/copy work, not body length alone, is important in this fixture. Measure complete dev/small service CPU and ACK/query latency before translating this kernel result into capacity. Inspect the remaining per-row node-label copies and per-byte hex formatting as separate candidates, preserving exact row and error behavior. Metrics/span ownership can be explored separately. Late skip sampling also deserves a finite cost screen with many long-line sources; this round establishes progress, not its maximum sustainable rate.