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

CLAUDE.md

@@ -122,6 +122,7 @@ External knowledge sources are configured with active `*.inputs.toml` manifests
 - **Startup coordination**: `github.com/gofrs/flock` via `internal/startuplock` — persistent `<db>.startup-sync.lock` sidecar with `0600` permissions, OS-owned advisory lock, local-host-only WAL snapshot coordination, and read-only followers that never delete the sidecar.
 - **Connection pragmas via `_pragma`**: `modernc.org/sqlite` honors DSN pragmas only in the `_pragma=name(value)` form; the mattn-style `_name=value` (e.g. `_busy_timeout=5000`, `_journal_mode=WAL`) is silently ignored, which had left the DB in rollback (delete) journal mode with a zero busy timeout — the root cause of `database is locked` (SQLITE_BUSY) errors. Both connections in `internal/storage/storage.go` set `_pragma=journal_mode(WAL)`, `_pragma=synchronous(NORMAL)`, and `_pragma=busy_timeout(5000)` (read-only sets only the busy timeout; journal mode is persisted in the file). Always use `_pragma=name(value)` for any new connection pragma here.
 - **Autoupdate**: `picokit/autoupdate` fetches and stages the latest GitHub release in the background; `run()` waits up to 10s after the command completes so short-lived commands don't kill the download before it finishes. Autoupdate is mandatory: there is no runtime opt-out. `newUpdater()` in `cmd/backscroll/main.go` is the single wiring point — it calls `autoupdate.New` with no `envDisable`, and both `run()` and the wiring test go through it, so re-adding an opt-out would fail the test. Dev builds are exempt by identity — a plain `go build` yields `version="dev"`, which picokit never fetches or applies — so validate against a dev build, not an env var. `scripts/eval.sh` builds its own dev binary for the same reason (a release binary would fetch+wait ~10s per invocation).
+- **Startup phase diagnostics (issue #47)**: Setting `BACKSCROLL_STARTUP_DIAGNOSTICS=1` reports elapsed time and processed item counts for each phase of startup, written to stderr. Measured phases (in execution order): (1) **Lock Acquisition** — time to acquire the startup coordination lock via `startuplock.TryAcquire()` or `startupAcquire()` (typically <1ms on uncontended startup); (2) **Index Prepare** — time to open the database and inspect the schema via `compat.InspectIndex()` (typically 8-10ms); (3) **Discovery** — time to discover input sources via reader registry; (4) **Metadata** — time to inspect file metadata for prefilter eligibility (count: files checked); (5) **Hashing** — time to compute SHA-256 hashes, with breakdown of files hashed vs skipped by prefilter and bytes hashed (MB); (6) **Parsing** — time to parse discovered files; (7) **Database** — time to write to SQLite, including template backfill and correction re-derivation. **Unattributed** time (if present) captures OS-level overhead including OS I/O, page-cache effects, config load, and application framework setup; this varies with system state and exhibits 10x variance between cold first run and warm subsequent runs (page-cache dependent). All timings are elapsed wall-clock. Diagnostics are OFF by default and incur zero overhead when disabled (`diagnosticsEnabled()` checks the env var once per sync). Output goes to stderr so `--json` and `--robot` contracts remain unchanged and stdout is byte-identical whether diagnostics are enabled. Tests verify both the diagnostics appear when enabled and stdout is byte-identical for machine-readable output formats. Benchmark `BenchmarkStartupDiagnostics` measures instrumented startup performance.
 - **Schema migration rule**: Every new table or column MUST be introduced as a new migration version (increment the version number and add a new version-check block in `SetupSchema()`). Never modify existing migration blocks — existing databases that already passed that version will never re-run them. Migration v5 drops the phantom `session_events` table (and its indexes `idx_session_events_order` and `idx_session_events_project`) — the table was write-only dead weight after structured-stats filtering was removed. Migration v6 drops the phantom `search_items.source_metadata` column via `ALTER TABLE ... DROP COLUMN` — it had a setter but zero production callers and was never read. Migration v13 adds indexes on `template_matches(source_path)` and `correction_signals(source_path)` to optimize backfill discovery queries (reduces O(N·M) subquery scans to O(N·log M) index lookups). Migration count remains v1–v13; this coordination update does not add a migration.
 - **F0a rich capture (migration v8)**: readers extract per-message identity and tool metadata BEFORE serialization/cleaning destroys the evidence — `uuid` (record uuid; tool blocks get stable `#tN`/`#rN` suffixes by block index), `tool_name`, `command_head`, `is_error` (`*bool`, three-valued: tool_result blocks carry it and it is paired back onto the tool_use message cross-record via `tool_use_id`), and `was_interrupted` (detected on raw content before `CleanContent` strips "Request interrupted"). Persisted to `search_items` (`extraction_version`, `was_interrupted` columns) and the perennial `tool_events` satellite table (`UNIQUE(source_path, ordinal)`, no CASCADE lifecycle — only `purge` deletes from it, explicitly). Claude reader only; Pi/OpenCode emit zero values and stay on the legacy path. Design: `docs/superpowers/specs/2026-07-17-pattern-discovery-northstar-design.md`.
 - **F0a.1 command-head extraction v2 (extraction_version bump to 2)**: The `commandHead()` function in `internal/readers/claude_reader.go` now strips leading POSIX variable assignments (tokens containing `=`) before extracting the actual command name. Example: `"SP=/path/to/code; go test ./..."` extracts `"go"` instead of `"SP=/path/to/code;"`. This reduces noise in sequence mining and command pattern discovery. The bump to `extraction_version=2` triggers B1 backfill on next sync, incrementally re-extracting command_head from stored text for files indexed before this change (up to 200 files/run).

cmd/backscroll/main_test.go

@@ -2507,3 +2507,156 @@ func fileExists(path string) bool {
 	_, err := os.Lstat(path)
 	return err == nil
 }
+
+// TestStartupDiagnosticsWithEnvVar verifies that startup phase diagnostics
+// are emitted when BACKSCROLL_STARTUP_DIAGNOSTICS=1 is set.
+func TestStartupDiagnosticsWithEnvVar(t *testing.T) {
+	_, cleanup := testEnv(t)
+	defer cleanup()
+
+	// Set up a fixture directory with a few files to process
+	fixtureSession := filepath.Join(fixturesDir(), "claude-preset", "projects")
+	t.Setenv("BACKSCROLL_SESSION_DIRS", fixtureSession)
+	t.Setenv("BACKSCROLL_STARTUP_DIAGNOSTICS", "1")
+
+	// Run a command that triggers auto-sync
+	_, stderr, err := runCmd("list")
+	if err != nil {
+		t.Fatalf("list error: %v\nstderr: %s", err, stderr)
+	}
+
+	// Verify that diagnostics output appears in stderr
+	diagnosticsExpected := []string{
+		"Lock Acquisition:", "Index Prepare:", "Discovery:", "Metadata:", "Hashing:", "Parsing:", "Database:", "Total:",
+	}
+	for _, phase := range diagnosticsExpected {
+		if !strings.Contains(stderr, phase) {
+			t.Errorf("startup diagnostics missing phase %q in stderr:\n%s", phase, stderr)
+		}
+	}
+}
+
+// TestStartupDiagnosticsDisabledByDefault verifies that startup phase diagnostics
+// are NOT emitted when BACKSCROLL_STARTUP_DIAGNOSTICS is not set.
+func TestStartupDiagnosticsDisabledByDefault(t *testing.T) {
+	_, cleanup := testEnv(t)
+	defer cleanup()
+
+	// Ensure the env var is NOT set
+	t.Setenv("BACKSCROLL_STARTUP_DIAGNOSTICS", "")
+
+	// Set up a fixture directory
+	fixtureSession := filepath.Join(fixturesDir(), "claude-preset", "projects")
+	t.Setenv("BACKSCROLL_SESSION_DIRS", fixtureSession)
+
+	// Run a command that triggers auto-sync
+	_, stderr, err := runCmd("list")
+	if err != nil {
+		t.Fatalf("list error: %v\nstderr: %s", err, stderr)
+	}
+
+	// Verify that diagnostics output does NOT appear in stderr
+	// Check for the diagnostics header, which is more reliable than individual phase names
+	if strings.Contains(stderr, "Startup diagnostics:") {
+		t.Errorf("startup diagnostics should not appear when env var is unset; found in stderr:\n%s", stderr)
+	}
+}
+
+// TestStartupDiagnosticsDoesNotAffectJSONOutput verifies that stdout is byte-identical
+// between runs with and without diagnostics enabled when using --json flag.
+func TestStartupDiagnosticsDoesNotAffectJSONOutput(t *testing.T) {
+	fixtureSession := filepath.Join(fixturesDir(), "claude-preset", "projects")
+
+	// Run once WITHOUT diagnostics, capture stdout
+	_, cleanup1 := testEnv(t)
+	t.Setenv("BACKSCROLL_SESSION_DIRS", fixtureSession)
+	t.Setenv("BACKSCROLL_STARTUP_DIAGNOSTICS", "")
+
+	stdout1, _, err := runCmd("list", "--json")
+	cleanup1()
+	if err != nil {
+		t.Fatalf("list --json (without diagnostics) error: %v", err)
+	}
+
+	// Run once WITH diagnostics, capture stdout
+	_, cleanup2 := testEnv(t)
+	t.Setenv("BACKSCROLL_SESSION_DIRS", fixtureSession)
+	t.Setenv("BACKSCROLL_STARTUP_DIAGNOSTICS", "1")
+
+	stdout2, _, err := runCmd("list", "--json")
+	cleanup2()
+	if err != nil {
+		t.Fatalf("list --json (with diagnostics) error: %v", err)
+	}
+
+	// Verify stdout is identical
+	if stdout1 != stdout2 {
+		t.Errorf("--json stdout differs with diagnostics enabled:\nWithout:\n%s\n\nWith:\n%s", stdout1, stdout2)
+	}
+}
+
+// TestStartupDiagnosticsDoesNotAffectRobotOutput verifies that stdout is byte-identical
+// between runs with and without diagnostics enabled when using --robot flag.
+func TestStartupDiagnosticsDoesNotAffectRobotOutput(t *testing.T) {
+	fixtureSession := filepath.Join(fixturesDir(), "claude-preset", "projects")
+
+	// Run once WITHOUT diagnostics, capture stdout
+	_, cleanup1 := testEnv(t)
+	t.Setenv("BACKSCROLL_SESSION_DIRS", fixtureSession)
+	t.Setenv("BACKSCROLL_STARTUP_DIAGNOSTICS", "")
+
+	stdout1, _, err := runCmd("list", "--robot")
+	cleanup1()
+	if err != nil {
+		t.Fatalf("list --robot (without diagnostics) error: %v", err)
+	}
+
+	// Run once WITH diagnostics, capture stdout
+	_, cleanup2 := testEnv(t)
+	t.Setenv("BACKSCROLL_SESSION_DIRS", fixtureSession)
+	t.Setenv("BACKSCROLL_STARTUP_DIAGNOSTICS", "1")
+
+	stdout2, _, err := runCmd("list", "--robot")
+	cleanup2()
+	if err != nil {
+		t.Fatalf("list --robot (with diagnostics) error: %v", err)
+	}
+
+	// Verify stdout is identical
+	if stdout1 != stdout2 {
+		t.Errorf("--robot stdout differs with diagnostics enabled:\nWithout:\n%s\n\nWith:\n%s", stdout1, stdout2)
+	}
+}
+
+// BenchmarkStartupDiagnostics measures the startup performance with diagnostics enabled.
+// This benchmark satisfies the GitHub issue #47 acceptance criterion requiring
+// "a benchmark or diagnostic reports time and bytes processed by each startup phase."
+func BenchmarkStartupDiagnostics(b *testing.B) {
+	fixtureSession := filepath.Join(fixturesDir(), "claude-preset", "projects")
+
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		// Create fresh test environment for each iteration
+		dir := b.TempDir()
+		homeDir := filepath.Join(dir, "home")
+		configDir := filepath.Join(dir, "config")
+		for _, path := range []string{homeDir, configDir} {
+			if err := os.MkdirAll(path, 0o755); err != nil {
+				b.Fatalf("mkdir: %v", err)
+			}
+		}
+		dbPath := filepath.Join(dir, "test.db")
+		b.Setenv("HOME", homeDir)
+		b.Setenv("BACKSCROLL_CONFIG_DIR", configDir)
+		b.Setenv("BACKSCROLL_DATABASE_PATH", dbPath)
+		b.Setenv("BACKSCROLL_SESSION_DIRS", fixtureSession)
+		b.Setenv("BACKSCROLL_STARTUP_DIAGNOSTICS", "1")
+
+		// Ensure database is created
+		db, _ := storage.Open(dbPath)
+		db.Close()
+
+		// Run list command to trigger auto-sync and measure it
+		_, _, _ = runCmd("list")
+	}
+}

cmd/backscroll/startup_coordination.go

@@ -33,7 +33,22 @@ var (
 )
 
 func coordinateStartup(ctx context.Context, cfg *config.Config, progress io.Writer, class startupCommandClass) startupResult {
+	// Measure lock acquisition time
+	var lockStart time.Time
+	if diagnosticsEnabled() {
+		lockStart = time.Now()
+	}
+
 	lease, acquired, err := startupTryAcquire(cfg.DatabasePath)
+
+	// Record lock acquisition timing for successful immediate acquisition
+	if diagnosticsEnabled() && acquired && lockStart != (time.Time{}) {
+		if startupDiags == nil {
+			startupDiags = &startupPhaseTiming{}
+		}
+		startupDiags.LockAcquisitionTime = time.Since(lockStart)
+	}
+
 	if err != nil {
 		return startupLockFailure(cfg, err)
 	}
@@ -55,7 +70,22 @@ func coordinateStartup(ctx context.Context, cfg *config.Config, progress io.Writ
 	default:
 		waitCtx, cancel := context.WithTimeout(ctx, startupMutationWait)
 		defer cancel()
+
+		// Measure waiting for lock
+		if diagnosticsEnabled() {
+			lockStart = time.Now()
+		}
+
 		lease, err := startupAcquire(waitCtx, cfg.DatabasePath, startupLockRetry)
+
+		// Record lock wait timing
+		if diagnosticsEnabled() && lockStart != (time.Time{}) {
+			if startupDiags == nil {
+				startupDiags = &startupPhaseTiming{}
+			}
+			startupDiags.LockAcquisitionTime = time.Since(lockStart)
+		}
+
 		if err != nil {
 			if errors.Is(err, context.DeadlineExceeded) && ctx.Err() == nil {
 				return startupResult{Config: cfg, Failure: syncInProgressFailure(
@@ -74,10 +104,25 @@ func coordinateStartup(ctx context.Context, cfg *config.Config, progress io.Writ
 }
 
 func runOwnedStartup(ctx context.Context, cfg *config.Config, progress io.Writer, class startupCommandClass, lease startupLease) startupResult {
+	// Measure index preparation time
+	var indexPrepareStart time.Time
+	if diagnosticsEnabled() {
+		indexPrepareStart = time.Now()
+	}
+
 	db, diag, err := startupPrepareIndex(ctx, cfg, indexMutation)
 	if db != nil {
 		err = closeIndexDB(db, err)
 	}
+
+	// Record index prepare timing
+	if diagnosticsEnabled() && indexPrepareStart != (time.Time{}) {
+		if startupDiags == nil {
+			startupDiags = &startupPhaseTiming{}
+		}
+		startupDiags.IndexPrepareTime = time.Since(indexPrepareStart)
+	}
+
 	if diag != nil || err != nil {
 		d := compat.Diagnostic{Code: compat.CodeMigrationFailed, Summary: "prepare index failed"}
 		if diag != nil {