Files
pad/internal/store/items_version_seq_test.go
T
xarmian 3c93472613 perf(store): run the store suite in parallel (TASK-2900 deliverable 3) (#1263)
The SQLite leg was CPU-bound and serial: 154.9s of CPU inside 185.6s of wall on
an eight-core box, which is 0.84 cores. Unlike the Postgres leg there was no
setup cost to reclaim — the unattributed gap between package wall-clock and the
sum of its tests measured MINUS 1.4s, so per-binary overhead was already nil —
and no fat test to find beyond one 48s outlier. The only lever left was the
seven idle cores.

t.Parallel() on 844 of 906 tests. Every test in this package builds its own
isolated store (a SQLite file copy, or since 6f8b6eb9 a Postgres clone), so it
shares no database with any other.

Medians on a quiet box, three SQLite repeats and two Postgres:

  SQLite wall     185.6s -> 111.0s   -40%
  Postgres wall   224.4s -> 121.2s   -46%   (495.8s -> 121.2s, -76%, since 6f8b6eb9)
  -race wall     2006.3s -> 1365.0s  -32%

THE COST, stated rather than folded into the win: SQLite CPU rose 154.9s ->
159.9s, +3.2%. That is contention overhead, it is real, and it is paid by
whoever else is on the box — this change moves WALL, it does not remove work.
A pre-registered prediction that CPU would stay within ~1% is falsified by that
number, though only just.

THAT FIGURE IS ITSELF A CORRECTION. An earlier draft of this message reported
the CPU cost as +10.4%, from ONE run taken while another seat was working the
box. Three repeats on a quiet box put the median at +3.2% — the published
number overstated the cost by more than three times. The direction survived the
correction and the magnitude did not, which is the case for repeating a figure
you intend to publish as a cost just as carefully as one you intend to publish
as a win.

Postgres binary CPU is flat to slightly down (63.9s -> 63.1s), which fits the
mechanism rather than contradicting it: that leg was 82% waiting, so parallelism
fills idle time instead of competing for cycles.

VARIANCE, since it changed shape: the parallel SQLite leg's repeat spread is
5.9% (106.7 / 111.0 / 113.2) against 0.7% for the serial leg it replaces.
Parallel runs are genuinely less reproducible than serial ones — scheduling
decides which tests share a core — so a future before/after on this package
needs more than one run per side to say anything, which the serial suite did
not.

The -race figure was measured because it was a RISK, not for completeness. CI's
Go job runs `go test -race -timeout=45m ./...` and already takes ~42 minutes;
the race detector serialises heavily, so parallelism could plausibly have made
that leg slower and pushed CI toward its own timeout. It does not: 2006s ->
1365s on the same box, measured against the template-only tree.

EXCLUSIONS — 62 tests, each for a mechanism rather than caution:

  19  files measuring ALLOCATIONS (runtime.ReadMemStats). Those counters are
      process-global, so a concurrent test's allocations land in the
      measurement. Excluded by FILE, since the hazard is the process.
   7  migration_guard_test.go, every test of which mutates the EXPORTED
      globals store.AllowSchemaAhead or store.BinaryVersion and restores in a
      t.Cleanup. AllowSchemaAhead=true under parallelism disarms the
      schema-ahead guard for every concurrently-running test — which is the
      property two of those very tests exist to assert.
  23  tests measuring ELAPSED TIME. Wall-clock under contention is not the
      wall-clock the assertion was written against.
   1  test mutating a PACKAGE-LEVEL GLOBAL (see below).
   3  the template mechanism tests, which assert on package-level counters.
  16  already had t.Parallel().

Excluding a test is a real remedy here rather than a hope, and the reason is a
Go semantic worth naming: a top-level test that calls t.Parallel() is HELD and
resumed only after the sequential pass finishes. Every excluded test therefore
still runs alone in a quiet process, which is exactly the property its timing or
allocation assertion depends on.

TWO EXCLUSIONS WERE MISSED BY MY OWN SWEEP, and the shape is the same both
times — an instrument whose question was narrower than the claim resting on it.

FIRST (found before shipping, by grepping the package's own `var` lines):


I recorded that this package has "no per-test global setters", having grepped
t.Setenv, os.Setenv and Set*ForTesting — all genuinely zero. The counts were
true and the conclusion was false. That sweep asked whether a test changes the
ENVIRONMENT; the claim it was carrying was whether a test changes anything
GLOBAL, which is wider.

TestUpdateDocument_CascadeExhaustionRollsBackTheWholeRename assigns the
package-level cascadeRewriteAttempts and restores it in a defer. Under
t.Parallel that window stays open while every other cascade test runs. The
mutating test would not flake; the tests AROUND it would, intermittently, which
is the worst shape to debug. Found by a different question — grep the package's
own non-test `var` declarations, then grep the tests for each name.

SECOND (found by codex, P1, NOT by me): that grep was `^var [a-z]`. It finds
UNEXPORTED package vars and silently skips exported ones, so it never saw
store.AllowSchemaAhead or store.BinaryVersion — both mutated by every test in
migration_guard_test.go. The instrument asked "which unexported globals exist"
while the claim it carried was "which globals exist". The fix that caught the
first miss was itself too narrow to catch the second, which is the argument for
enforcing the invariant in code rather than trusting the sweep that produced it.

Both exclusions are now enforced by guards rather than by the exclusion list:
TestCascadeExhaustionStaysSerial (function-scoped) and
TestMigrationGuardTestsStaySerial (file-scoped). Both fail closed on a missing
file or renamed function, strip line comments so an explanatory comment naming
t.Parallel() can neither satisfy nor trip them, carry a positive control that
the scan can SEE a real t.Parallel() elsewhere, and are mutation-controlled in
both directions.

VERIFICATION — 10 runs, zero failures, zero data races:

  SQLite parallel    x4   exit 0
  Postgres parallel  x3   exit 0
  -race -timeout=45m x1   exit 0, zero DATA RACE reports
  baseline -race     x1   exit 0 (the counterfactual above)

A false alarm not filed as a finding: the first -race run exited 1 with zero
`--- FAIL` lines and zero data races — the shape that reads as a pass to
anything counting FAIL lines. The log said `panic: test timed out after 10m0s`.
That was the invocation, not the code: `-timeout` was omitted so Go's default
applied, and ci.yml already carries a comment explaining that the explicit
-timeout exists because the default is too low.

KNOWN BOUND, not a solved problem: the test container's max_connections is 100,
each store sets MaxOpenConns(25), and -parallel defaults to GOMAXPROCS. On an
eight-core box the worst case permits 200. Three Postgres runs showed no
53300 "too many clients", but the arithmetic still allows it on a larger box or
a heavier test, and that belongs here as a bound rather than as an absence of
observed failures.

Claude-Session: https://claude.ai/code/session_01HeChkgZVYb3NTgTcckF5KR
2026-09-06 16:59:31 -04:00

153 lines
5.7 KiB
Go

package store
import (
"testing"
"github.com/PerpetualSoftware/pad/internal/models"
)
// TestItemVersionSeqBreaksSameSecondTies is the BUG-2270 regression guard.
//
// item_versions.created_at is second-precision RFC3339. A version RESTORE
// plus rapid edits can mint several versions inside one wall-clock second;
// they tie on created_at, and the id PK is a random UUIDv4 — useless as an
// ordering tie-breaker. Before the fix, ListItemVersions ordered solely by
// `created_at DESC`, so same-second versions came back in arbitrary order
// and the newest→oldest reverse-patch walk in ListItemVersionsResolved
// reconstructed corrupt history / the wrong "latest".
//
// version_seq (migration 076/054) is a per-item monotonic counter assigned
// COALESCE(MAX,0)+1 on every version INSERT. The ORDER BYs became
// `created_at DESC, version_seq DESC`, giving a deterministic tie-break.
//
// This test mints four versions through the real Create/Update paths, then
// collapses every version row into a SINGLE created_at second to force the
// exact collision the bug is about, and asserts both:
// - ListItemVersions returns rows in strictly-descending version_seq order
// (deterministic, and proving the column was actually populated), and
// - ListItemVersionsResolved reconstructs the correct pre-update content
// for each row — which only holds if the newest→oldest walk is ordered.
func TestItemVersionSeqBreaksSameSecondTies(t *testing.T) {
t.Parallel()
s := testStore(t)
ws := createTestWorkspace(t, s, "Version Seq Test")
col := createTestCollection(t, s, ws.ID, "Tasks")
// Initial version (version_seq should become 1). CreateItem inserts a
// version row when content is non-empty.
item, err := s.CreateItem(ws.ID, col.ID, models.ItemCreate{
Title: "Versioned",
Content: "content-0",
Source: "cli",
})
if err != nil {
t.Fatalf("CreateItem: %v", err)
}
// Three more versions via the real update path. ForceVersion guarantees a
// version row each time regardless of the per-(actor,source) throttle or
// timing. Each version row records items.content IMMEDIATELY BEFORE the
// update (existing.Content), so the stored contents are:
// seq1 (initial) -> "content-0"
// seq2 (before content-1) -> "content-0"
// seq3 (before content-2) -> "content-1"
// seq4 (before content-3) -> "content-2"
updates := []string{"content-1", "content-2", "content-3"}
var current *models.Item
for _, c := range updates {
c := c
current, err = s.UpdateItem(item.ID, models.ItemUpdate{
Content: &c,
LastModifiedBy: "user",
Source: "web",
ForceVersion: true,
})
if err != nil {
t.Fatalf("UpdateItem %q: %v", c, err)
}
}
if current == nil || current.Content != "content-3" {
t.Fatalf("expected final content-3, got %+v", current)
}
// Collapse ALL version rows into one wall-clock second — the exact
// BUG-2270 collision. Before the fix this made the ordering arbitrary.
const sameSecond = "2026-01-01T00:00:00Z"
if _, err := s.db.Exec(s.q(`UPDATE item_versions SET created_at = ? WHERE item_id = ?`), sameSecond, item.ID); err != nil {
t.Fatalf("normalize created_at: %v", err)
}
// Ground truth: the ids in strict version_seq-descending order, plus the
// seq values themselves so we can assert monotonicity + distinctness.
rows, err := s.db.Query(s.q(`
SELECT id, version_seq FROM item_versions
WHERE item_id = ?
ORDER BY version_seq DESC`), item.ID)
if err != nil {
t.Fatalf("query version_seq: %v", err)
}
var wantIDs []string
var seqs []int64
for rows.Next() {
var id string
var seq int64
if err := rows.Scan(&id, &seq); err != nil {
rows.Close()
t.Fatalf("scan version_seq: %v", err)
}
wantIDs = append(wantIDs, id)
seqs = append(seqs, seq)
}
rows.Close()
if err := rows.Err(); err != nil {
t.Fatalf("version_seq rows: %v", err)
}
if len(seqs) != 4 {
t.Fatalf("expected 4 version rows (initial + 3 updates), got %d", len(seqs))
}
// Strictly descending and distinct (i.e. 4,3,2,1) — proves version_seq was
// populated monotonically rather than left at the DEFAULT 0.
for i := 1; i < len(seqs); i++ {
if seqs[i] >= seqs[i-1] {
t.Fatalf("version_seq not strictly descending: %v", seqs)
}
}
if seqs[len(seqs)-1] < 1 {
t.Fatalf("smallest version_seq must be >= 1 (populated), got %v", seqs)
}
// ListItemVersions must return rows in the same deterministic
// version_seq-descending order despite every row sharing created_at.
got, err := s.ListItemVersions(item.ID)
if err != nil {
t.Fatalf("ListItemVersions: %v", err)
}
if len(got) != len(wantIDs) {
t.Fatalf("ListItemVersions returned %d rows, want %d", len(got), len(wantIDs))
}
for i := range got {
if got[i].ID != wantIDs[i] {
t.Fatalf("ListItemVersions order mismatch at %d: got id %s, want %s (order must follow version_seq DESC)", i, got[i].ID, wantIDs[i])
}
}
// ListItemVersionsResolved reconstructs each row's pre-update content by
// walking newest→oldest. Correct output is only possible if the ordering
// is deterministic — a wrong same-second order misapplies the reverse
// patches and yields garbage. currentContent is the live items.content.
resolved, err := s.ListItemVersionsResolved(item.ID, current.Content)
if err != nil {
t.Fatalf("ListItemVersionsResolved: %v", err)
}
wantContent := []string{"content-2", "content-1", "content-0", "content-0"}
if len(resolved) != len(wantContent) {
t.Fatalf("ListItemVersionsResolved returned %d rows, want %d", len(resolved), len(wantContent))
}
for i := range resolved {
if resolved[i].Content != wantContent[i] {
t.Fatalf("resolved content mismatch at %d: got %q, want %q (corrupt reconstruction implies non-deterministic same-second ordering)", i, resolved[i].Content, wantContent[i])
}
}
}