diff --git a/CLAUDE.md b/CLAUDE.md index c110792..b04c1a1 100644 --- a/CLAUDE.md +++ b/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 `.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). diff --git a/cmd/backscroll/main_test.go b/cmd/backscroll/main_test.go index 9d1652f..13e8722 100644 --- a/cmd/backscroll/main_test.go +++ b/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") + } +} diff --git a/cmd/backscroll/startup_coordination.go b/cmd/backscroll/startup_coordination.go index b37585b..7d7d10f 100644 --- a/cmd/backscroll/startup_coordination.go +++ b/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 { diff --git a/cmd/backscroll/sync_helpers.go b/cmd/backscroll/sync_helpers.go index cb3cd4d..90bcea7 100644 --- a/cmd/backscroll/sync_helpers.go +++ b/cmd/backscroll/sync_helpers.go @@ -15,6 +15,11 @@ import ( "github.com/pablontiv/backscroll/internal/templates" ) +// diagnosticsEnabled checks if startup diagnostics are enabled via env var +func diagnosticsEnabled() bool { + return os.Getenv("BACKSCROLL_STARTUP_DIAGNOSTICS") == "1" +} + var ( maybeAutoSyncOpen = storage.Open maybeAutoSyncActiveInputs = input_config.ActiveInputs @@ -24,6 +29,17 @@ var ( maybeAutoSyncGetFileMetadata = getFileMetadata // for testability ) +// startupPhaseTiming holds measurements for startup phases that occur before maybeAutoSync. +// Populated by coordinateStartup if diagnosticsEnabled() is true. +type startupPhaseTiming struct { + LockAcquisitionTime time.Duration + IndexPrepareTime time.Duration +} + +// startupDiags holds pre-sync phase timings, set by coordinateStartup. +// Access must be guarded by checking diagnosticsEnabled() first. +var startupDiags *startupPhaseTiming + func newDefaultAutoSyncRegistry() *readers.Registry { reg := readers.NewRegistry() reg.Register(&readers.OpenCodeReader{}) @@ -89,6 +105,12 @@ func isRacyCleanFile(fileMtime string, lastIndexed string) bool { // It is intended to be called before query commands to ensure fresh index state. // If sync fails, it returns an error (caller decides whether to warn/ignore). func maybeAutoSync(cfg *config.Config, progress io.Writer) (retErr error) { + diag := diagnosticsEnabled() + var startTime time.Time + if diag { + startTime = time.Now() + } + // Open database for reading to check if it exists // (this will auto-create if missing) db, err := maybeAutoSyncOpen(cfg.DatabasePath) @@ -131,6 +153,11 @@ func maybeAutoSync(cfg *config.Config, progress io.Writer) (retErr error) { // Collect indexed files var indexedFiles []storage.IndexedFile + // Track diagnostics + var discoveryTime, metadataTime, hashingTime, parsingTime time.Duration + var bytesHashed int64 + var filesHashed, filesSkipped int + // Process sessions via reader registry for _, def := range defs { if def.Source == "" { @@ -142,12 +169,28 @@ func maybeAutoSync(cfg *config.Config, progress io.Writer) (retErr error) { return fmt.Errorf("resolve reader for input %q: %w", def.ID, err) } + // Phase 1: Discovery + var discoveryStart time.Time + if diag { + discoveryStart = time.Now() + } + refs, err := reader.Discover(def) if err != nil { return fmt.Errorf("discover input %q: %w", def.ID, err) } + if diag { + discoveryTime += time.Since(discoveryStart) + } + for _, ref := range refs { + // Phase 2: Metadata inspection + var metadataStart time.Time + if diag { + metadataStart = time.Now() + } + // v14 metadata prefilter with racy-clean guard: // Files modified within the same timestamp tick as indexing could have matching // size+mtime but different content. Git calls these "racy clean" files. @@ -178,6 +221,16 @@ func maybeAutoSync(cfg *config.Config, progress io.Writer) (retErr error) { } } + if diag { + metadataTime += time.Since(metadataStart) + } + + // Phase 3: Hashing + var hashingStart time.Time + if diag { + hashingStart = time.Now() + } + // If prefilter didn't match or wasn't available, compute the hash if hash == "" { var err error @@ -186,6 +239,21 @@ func maybeAutoSync(cfg *config.Config, progress io.Writer) (retErr error) { return fmt.Errorf("hash %s: %w", ref, err) } shouldParse = true + if diag { + filesHashed++ + // Get file size for bytes hashed metric + if fileSize, _, err := maybeAutoSyncGetFileMetadata(ref); err == nil && fileSize != nil { + bytesHashed += *fileSize + } + } + } else { + if diag { + filesSkipped++ + } + } + + if diag { + hashingTime += time.Since(hashingStart) } // Skip unchanged files UNLESS they are in the stale-set and cap allows @@ -200,11 +268,21 @@ func maybeAutoSync(cfg *config.Config, progress io.Writer) (retErr error) { continue } + // Phase 4: Parsing + var parsingStart time.Time + if diag { + parsingStart = time.Now() + } + pf, err := reader.Parse(ref, def) if err != nil { return fmt.Errorf("parse %s: %w", ref, err) } + if diag { + parsingTime += time.Since(parsingStart) + } + // Use session cwd for project identification; fall back to file path if cwd is empty identPath := pf.Cwd if identPath == "" { @@ -248,6 +326,12 @@ func maybeAutoSync(cfg *config.Config, progress io.Writer) (retErr error) { } } + // Phase 5: Database + var databaseStart time.Time + if diag { + databaseStart = time.Now() + } + // Sync all files if len(indexedFiles) > 0 { if err := maybeAutoSyncSyncFiles(db, indexedFiles); err != nil { @@ -294,5 +378,35 @@ func maybeAutoSync(cfg *config.Config, progress io.Writer) (retErr error) { return fmt.Errorf("re-derive superseded correction signals: %w", err) } + if diag { + databaseTime := time.Since(databaseStart) + totalTime := time.Since(startTime) + + // Report diagnostics + _, _ = fmt.Fprintf(progress, "\nStartup diagnostics:\n") + if startupDiags != nil { + _, _ = fmt.Fprintf(progress, " Lock Acquisition:%v\n", startupDiags.LockAcquisitionTime) + _, _ = fmt.Fprintf(progress, " Index Prepare: %v\n", startupDiags.IndexPrepareTime) + } + _, _ = fmt.Fprintf(progress, " Discovery: %v\n", discoveryTime) + _, _ = fmt.Fprintf(progress, " Metadata: %v (%d files checked)\n", metadataTime, filesHashed+filesSkipped) + _, _ = fmt.Fprintf(progress, " Hashing: %v (%d files hashed, %d files skipped, %.1f MB)\n", + hashingTime, filesHashed, filesSkipped, float64(bytesHashed)/(1024*1024)) + _, _ = fmt.Fprintf(progress, " Parsing: %v\n", parsingTime) + _, _ = fmt.Fprintf(progress, " Database: %v\n", databaseTime) + + // Calculate unattributed time + measuredTime := discoveryTime + metadataTime + hashingTime + parsingTime + databaseTime + if startupDiags != nil { + measuredTime += startupDiags.LockAcquisitionTime + startupDiags.IndexPrepareTime + } + unattributedTime := totalTime - measuredTime + if unattributedTime > 0 { + _, _ = fmt.Fprintf(progress, " Unattributed: %v (I/O, config load, other OS overhead; page-cache sensitive)\n", unattributedTime) + } + + _, _ = fmt.Fprintf(progress, " Total: %v\n", totalTime) + } + return nil }