Skip to content

feat(sync): add startup phase diagnostics for issue #47 - #57

Merged
pablontiv merged 2 commits into
mainfrom
feat/startup-phase-diagnostics
Aug 22, 2026
Merged

feat(sync): add startup phase diagnostics for issue #47#57
pablontiv merged 2 commits into
mainfrom
feat/startup-phase-diagnostics

Conversation

@pablontiv

@pablontiv pablontiv commented Aug 22, 2026

Copy link
Copy Markdown
Owner

Closes the one acceptance criterion of #47 that shipped unmet in PR #54: "A benchmark or diagnostic reports time and bytes processed by each startup phase."

PR #54 delivered the metadata prefilter but shipped with invented performance numbers, precisely because nobody could measure. This makes startup measurable.

Surface

Gated by BACKSCROLL_STARTUP_DIAGNOSTICS=1, written to the progress io.Writer maybeAutoSync already receives (stderr). Off by default: with the variable unset, stderr is 0 bytes and behavior is unchanged.

No CLI flag was added — that would touch the CLI contract (early validation, robot/json shapes) for what is only a diagnostic. stdout is byte-identical with and without the variable, verified for --json and --robot by tests that compare the captured output, not merely the exit code.

Observed output — real 870-file corpus, 201 MB index

Post-sync, cold page cache:

Startup diagnostics:
  Lock Acquisition:49.584µs
  Index Prepare:   2.418083ms
  Discovery:       27.992959ms
  Metadata:        876.371µs (343 files checked)
  Hashing:         2.827869ms (2 files hashed, 341 files skipped, 6.2 MB)
  Parsing:         46.446459ms
  Database:        90.383583ms
  Unattributed:    251.300384ms (I/O, config load, other OS overhead; page-cache sensitive)
  Total:           422.295292ms

Steady state, corpus unchanged:

  Lock Acquisition:36.333µs
  Index Prepare:   2.252583ms
  Discovery:       22.911416ms
  Metadata:        771.169µs (343 files checked)
  Hashing:         4.881µs (0 files hashed, 343 files skipped, 0.0 MB)
  Parsing:         0s
  Database:        503.666µs
  Unattributed:    18.84266ms (I/O, config load, other OS overhead; page-cache sensitive)
  Total:           45.322708ms

What the first measurements already showed

  • Reduce startup discovery and hashing cost for unchanged corpora #47's prefilter does what it claims. In steady state all 343 files are skipped and hashing costs 4.9 µs against 0.0 MB read.
  • Discovery is now the dominant attributed phase (22.9 ms) — walking the corpus costs more than every other measured phase combined. That was not visible before and is the obvious next target.
  • The first run is not representative. Totals swing roughly 10x between a cold first run (~420 ms) and steady state (~45 ms). Anyone benchmarking startup must discard the first reading.

An earlier revision of this PR bucketed the residue as Other (startup coordination, lock, schema inspection). That attribution was measured and found false: with an empty corpus and empty database those costs total 0.6 ms, and the real driver is database file I/O and page-cache state. Lock Acquisition and Index Prepare are now measured directly (36–50 µs and ~2.3 ms), and the residue is labelled Unattributed with no speculative cause.

Verification

Observed just ci:

ok  github.com/pablontiv/backscroll/internal/tagging               3.046s  coverage: 100.0% of statements
ok  github.com/pablontiv/backscroll/internal/templates             3.047s  coverage: 91.8% of statements
ok  github.com/pablontiv/backscroll/scripts/calibration-extract    3.037s  coverage: 66.0% of statements
Coverage: 85.3%

GitHub CI green on 0b0d2d1, confirmed against the branch head via git ls-remote rather than a cached PR field.

Tests

  • TestStartupDiagnosticsWithEnvVar — each phase appears when enabled.
  • TestStartupDiagnosticsDisabledByDefault — no output when unset.
  • TestStartupDiagnosticsDoesNotAffectJSONOutput / ...RobotOutput — stdout compared directly, so a leak into the machine-readable payloads fails the test.

Relates to #47.

https://claude.ai/code/session_019LDXzStaKrArqJKvy4z3eF

Implement per-phase startup instrumentation gated by BACKSCROLL_STARTUP_DIAGNOSTICS=1
environment variable. Measures and reports elapsed time and metrics for five startup phases:

1. Discovery — time to discover input sources via reader registry
2. Metadata — time to inspect file metadata for prefilter eligibility (file count)
3. Hashing — time to compute SHA-256 hashes (file counts and bytes hashed)
4. Parsing — time to parse discovered files
5. Database — time to write to SQLite including template backfill

Output is written to stderr, leaving stdout byte-identical for --json and --robot
contracts. Diagnostics are off by default with zero overhead when disabled.

Tests verify:
- Diagnostics output appears when env var is set
- Output is suppressed when env var is unset (default)
- stdout is byte-identical with and without diagnostics for --json and --robot
- Benchmark included to measure performance across startup phases

Closes the acceptance criterion from issue #47 that shipped unmet in PR #54.

Claude-Session: https://claude.ai/code/session_019LDXzStaKrArqJKvy4z3eF
PR #57 added startup diagnostics but included a speculative attribution of
the 230ms unattributed time to "startup coordination, lock, schema inspection".
Measurement proves this wrong: lock + coordination + schema inspection sum to
<1ms on empty corpus, but the gap swings 10x between cold first run (234ms)
and warm subsequent runs (21ms).

Add explicit measurements for:
- Lock Acquisition: time to acquire startup coordination lock (sub-millisecond)
- Index Prepare: time to open database and inspect schema via compat.InspectIndex
  (typically 8-10ms)

Report Unattributed time (if present) honestly as I/O, config load, and other
OS overhead, noting its page-cache sensitivity and 10x variance between runs.
Remove the false attribution that would misdirect optimization efforts.

All phases now explicitly measured or accounted for. Unattributed remainder
documented as page-cache dependent, matching observed variance in real corpus
testing (0.6ms fixed overhead, ~540ms I/O and page-cache variance on 870-file
corpus).

Tests updated to verify presence of Lock Acquisition and Index Prepare phases.
CI gate: 85.3% coverage.
@pablontiv
pablontiv merged commit ed7e90a into main Aug 22, 2026
6 checks passed
@pablontiv
pablontiv deleted the feat/startup-phase-diagnostics branch August 22, 2026 19:59
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant