amadan

oficina / sheets Public

store: add reproducible benchmark for setBlank/Open batching claim

The 32m02s -> 8.818s and 6.728s -> 2.779s headline figures in
batching-report.md were measured with a throwaway benchmark that was
deleted after use, so nobody could independently check them. Add
TestBlankRecoveryBench (internal/sheets/store), an env-var-gated test
(RUN_BLANK_RECOVERY_BENCH=1, N via BLANK_RECOVERY_BENCH_N, default
5,001) that reproduces both timings on the current, fixed code. It is
a Test rather than a Benchmark* function so its two phases can be
timed once, separately, without testing.B rerunning the whole
several-hundred-thousand-row fixture build; it stays out of `make
test` because the env var is unset there (testing.Short() alone
would not skip it, since CI never passes -short).

Does not touch TestBlankCrashLeavesDependentsRecoverable or
TestBlankFeederOverCapDependentsAreRecoverable, and does not
re-measure or revert the pre-fix code.
Paul Campbell pushed by paul@keymail.dev 7c43427759999979a13f60aa64e3c5a362057eb2 parent 1197fa2
1 file changed, +222 −0
  • internal/sheets/store/handle_blank_recovery_bench_test.go +222 −0

CI passed — run details

Intent

full ledger: core

diff --git a/internal/sheets/store/handle_blank_recovery_bench_test.go b/internal/sheets/store/handle_blank_recovery_bench_test.go
new file mode 100644
index 0000000..f8344fd
--- /dev/null
+++ b/internal/sheets/store/handle_blank_recovery_bench_test.go
@@ -0,0 +1,222 @@
+package store
+
+import (
+ "context"
+ "os"
+ "path/filepath"
+ "strconv"
+ "testing"
+ "time"
+
+ rdb "github.com/carlosframework/rastrillo/db"
+ "github.com/carlosframework/rastrillo/migrate"
+ "gorm.io/gorm"
+
+ "amadan.net/oficina/sheets/internal/sheets"
+ "amadan.net/oficina/sheets/internal/sheets/calc"
+ "amadan.net/oficina/sheets/internal/sheets/seal"
+)
+
+// TestBlankRecoveryBench reproduces, on demand, the two headline timings
+// batching-report.md's "Measurements" section reports for this task: the
+// setBlank/markDirty lock-hold time and Open's crash-recovery pass, both
+// measured over the FIXED code (this file never touches, reverts or
+// otherwise reconstructs the pre-fix path — see handle_batch.go for what
+// changed).
+//
+// RECORDED FIGURES (batching-report.md), for comparison against a run of
+// this test:
+//
+// N = 199,999 dependents (calc.MaxCellsPerTab - 1, the real ceiling)
+// setBlank (h.mu hold, whole Set call): 2.779s
+// Open (crash-recovery pass over the N stale dependents): 8.818s
+//
+// Machine those were measured on: whatever ran the original task session
+// — a single unspecified development machine, WAL-mode SQLite via the
+// project's real rdb.Open + migrate.Apply boot path (not :memory:), with
+// (per the report) "other unrelated background jobs contending for disk"
+// noted as a caveat on a related run. No CPU/disk model, core count or
+// load average was recorded, which is itself a gap: a wall-clock number
+// with no machine description is only reproducible in shape, not in
+// absolute value. Treat the figures above as an order-of-magnitude
+// target, not a number this test should assert against — a wall-clock
+// benchmark that fails CI because a shared runner was slow that day is a
+// worse outcome than a benchmark nobody trusts, so this is a Test that
+// logs, not a Test that fails, on timing.
+//
+// WHAT IT MEASURES:
+// - Phase 1 ("setBlank"): one Handle.Set call blanking a feeder cell
+// that N dependent cells reference as "=A1*2", timed end to end. Set
+// holds h.mu for its entire body (handle_set.go), so this is the
+// real exclusive-lock hold time any other Value/Set call on this tab
+// would have queued behind. At N above calc.MaxDirtyPerPass (5,000)
+// — true by default here, see below — setBlank's withinCap is false,
+// so this call does ONLY markDirty's batched marking; the recompute
+// and persistTouched steps do not run inside it. That is what makes
+// this a clean read on markDirty specifically at the real ceiling,
+// matching how the recorded 2.779s figure above was measured.
+// - Phase 2 ("Open"): the very next Open on the same tab, timed end to
+// end. Phase 1 left every dependent's InputVersion ahead of its own
+// CacheVersion (markDirty's job), so buildHandle's stale scan
+// (handle_open.go) finds all N of them and this Open drives
+// recoverStale (handle_batch.go) — the batched crash-recovery pass —
+// over the whole set before returning.
+//
+// GATING: skipped unless RUN_BLANK_RECOVERY_BENCH is set, and always
+// skipped under -short. This is a Test, not a Benchmark* function,
+// specifically so its two phases can be timed separately with plain
+// time.Since calls around a single deliberate run — go test's
+// -bench/testing.B machinery reruns its body b.N times to reach a
+// stable per-op estimate, which would mean rebuilding a
+// several-hundred-thousand-row SQLite fixture on every iteration; that
+// is the wrong shape for a fixture this expensive to build once. The
+// env var is what actually keeps this out of `make test`: CI's test-go
+// target runs plain `go test -count=1 ./...` with no -short flag (see
+// Makefile), so testing.Short() alone would not skip it there — the
+// env var being unset is what does. testing.Short() is kept as a second,
+// independent gate for anyone who runs `go test -short ./...` by habit.
+//
+// N: set BLANK_RECOVERY_BENCH_N to override; unset defaults to
+// calc.MaxDirtyPerPass+1 (5,001) — just over the recompute cap, so a
+// default run still exercises the marking-only path the recorded figures
+// above describe, and finishes in well under a second post-fix (the
+// sibling correctness test, TestBlankFeederOverCapDependentsAreRecoverable,
+// runs the same shape at the same N as part of every `make test`). Push
+// BLANK_RECOVERY_BENCH_N=199999 to reach the real MaxCellsPerTab-1
+// ceiling the recorded figures were measured at; expect several minutes
+// total, dominated by seeding N rows and cells, not by the two timed
+// phases themselves.
+func TestBlankRecoveryBench(t *testing.T) {
+ if testing.Short() {
+ t.Skip("store: skipping blank/recovery benchmark under -short")
+ }
+ if os.Getenv("RUN_BLANK_RECOVERY_BENCH") == "" {
+ t.Skip("store: set RUN_BLANK_RECOVERY_BENCH=1 to run (see this file's doc comment; minutes at large N)")
+ }
+ n := blankRecoveryBenchN(t)
+
+ dir := t.TempDir()
+ d, err := rdb.Open(filepath.Join(dir, "bench.db"), nil)
+ if err != nil {
+ t.Fatalf("open db: %v", err)
+ }
+ t.Cleanup(func() {
+ if err := d.Close(); err != nil {
+ t.Errorf("close db: %v", err)
+ }
+ })
+ db := d.G
+ if _, err := migrate.Apply(context.Background(), d, sheets.BootSchema); err != nil {
+ t.Fatalf("migrate: %v", err)
+ }
+ s, err := seal.New(make([]byte, 32))
+ if err != nil {
+ t.Fatal(err)
+ }
+
+ const localTab, feederRow, colA uint64 = 1, 1, 1
+ seedBlankRecoveryFixture(t, db, s, localTab, feederRow, colA, n)
+
+ h, err := Open(db, s, localTab)
+ if err != nil {
+ t.Fatalf("Open (initial): %v", err)
+ }
+
+ blankStart := time.Now()
+ if err := h.Set(feederRow, colA, "", 7); err != nil {
+ t.Fatalf("blank feeder: %v", err)
+ }
+ blankElapsed := time.Since(blankStart)
+ h.Release()
+
+ openStart := time.Now()
+ h2, err := Open(db, s, localTab)
+ openElapsed := time.Since(openStart)
+ if err != nil {
+ t.Fatalf("Open (recovery): %v", err)
+ }
+ defer h2.Release()
+
+ t.Logf("N=%d setBlank(h.mu hold)=%s Open(recovery pass)=%s", n, blankElapsed, openElapsed)
+ t.Logf("recorded (batching-report.md, N=199999): setBlank=2.779s Open=8.818s")
+}
+
+// blankRecoveryBenchN reads BLANK_RECOVERY_BENCH_N, defaulting to
+// calc.MaxDirtyPerPass+1 — see this file's doc comment for why.
+func blankRecoveryBenchN(t *testing.T) int {
+ t.Helper()
+ raw := os.Getenv("BLANK_RECOVERY_BENCH_N")
+ if raw == "" {
+ return calc.MaxDirtyPerPass + 1
+ }
+ n, err := strconv.Atoi(raw)
+ if err != nil || n <= 0 {
+ t.Fatalf("store: BLANK_RECOVERY_BENCH_N=%q is not a positive integer", raw)
+ }
+ return n
+}
+
+// seedBlankRecoveryFixture seeds one feeder cell holding "5" plus n
+// dependent cells each holding "=A1*2" with an already-consistent cache
+// (cached value 10) — the exact fixture shape
+// TestBlankFeederOverCapDependentsAreRecoverable uses, batched via
+// db.CreateInBatches the same way, so seeding N rows stays proportional
+// rather than N round trips. The same two sealed blobs are reused for
+// every dependent (seal.Sealer.Seal takes no per-call AAD binding it to
+// a specific cell), matching that test's own reasoning for doing so.
+func seedBlankRecoveryFixture(t *testing.T, db *gorm.DB, s *seal.Sealer, tabID, feederRow, colA uint64, n int) {
+ t.Helper()
+
+ if err := db.Create(&sheets.Tab{ID: tabID, SheetID: 1}).Error; err != nil {
+ t.Fatalf("seed tab: %v", err)
+ }
+ if err := db.Create(&sheets.Col{ID: colA, TabID: tabID, Position: 0}).Error; err != nil {
+ t.Fatalf("seed col: %v", err)
+ }
+ if err := db.Create(&sheets.Row{ID: feederRow, TabID: tabID, Position: 0}).Error; err != nil {
+ t.Fatalf("seed feeder row: %v", err)
+ }
+
+ feederInputSealed, err := s.Seal("cell.input", []byte("5"))
+ if err != nil {
+ t.Fatal(err)
+ }
+ feederCachedSealed, err := s.Seal("cell.cached", encodeValue(calc.Value{Kind: calc.KindNum, Num: 5}))
+ if err != nil {
+ t.Fatal(err)
+ }
+ if err := db.Create(&sheets.Cell{
+ TabID: tabID, RowID: feederRow, ColID: colA,
+ InputSealed: feederInputSealed, InputVersion: 1,
+ CachedSealed: feederCachedSealed, CacheVersion: 1,
+ }).Error; err != nil {
+ t.Fatalf("seed feeder cell: %v", err)
+ }
+
+ depInputSealed, err := s.Seal("cell.input", []byte("=A1*2"))
+ if err != nil {
+ t.Fatal(err)
+ }
+ depCachedSealed, err := s.Seal("cell.cached", encodeValue(calc.Value{Kind: calc.KindNum, Num: 10}))
+ if err != nil {
+ t.Fatal(err)
+ }
+ rows := make([]*sheets.Row, 0, n)
+ cells := make([]*sheets.Cell, 0, n)
+ for i := 1; i <= n; i++ {
+ rid := feederRow + uint64(i)
+ rows = append(rows, &sheets.Row{ID: rid, TabID: tabID, Position: i})
+ cells = append(cells, &sheets.Cell{
+ TabID: tabID, RowID: rid, ColID: colA,
+ InputSealed: depInputSealed, InputVersion: 1,
+ CachedSealed: depCachedSealed, CacheVersion: 1,
+ })
+ }
+ const batch = 500
+ if err := db.CreateInBatches(&rows, batch).Error; err != nil {
+ t.Fatalf("seed dependent rows: %v", err)
+ }
+ if err := db.CreateInBatches(&cells, batch).Error; err != nil {
+ t.Fatalf("seed dependent cells: %v", err)
+ }
+}