test(ingestor): make the backfill write-hold test robust under CI load (#267)

[dborup-agent]

Relates to #267

Cause

The 264 ms overshoot is disk-flush latency in COMMIT, not work that could move out of the write transaction.

I timed each phase of resolvedPathBackfillBatch with a temporary patch that is not part of this PR. Setup: 0572e7f9, -cover, two to four go test ./... loops on cmd/server running alongside, load average 5–6 on 4 cores, 200 batches of 500 rows:

phase	median	p95	max
read (outside tx)	1.9 ms	2.4 ms	6.7 ms
resolve (outside tx)	1.1 ms	1.6 ms	3.8 ms
writerMu wait + BEGIN	0.03 ms	0.05 ms	0.3 ms
500 UPDATEs + watermark	5.6 ms	7.9 ms	11.4 ms
COMMIT	15.5 ms	30.3 ms	45.4 ms
hold (total)	21.6 ms	36.3 ms	52.7 ms

• COMMIT is about 75% of the hold. It is the WAL fsync: PRAGMA synchronous is 2 (FULL), the driver default.
• With PRAGMA synchronous=OFF on the same load, the hold drops to a 3.1 ms median and a 12.8 ms max (COMMIT median 0.12 ms).
• No auto-checkpoint fired in any batch. The WAL grew in every batch and never reset.
• Resolution already runs before BEGIN. The UPDATEs, the watermark upsert and COMMIT must stay atomic, so nothing in the transaction can move out without changing semantics. The production code is unchanged, apart from one test seam.
• Under heavier local load, the unchanged master test reached a max hold of 235 ms. One 50-run loop on this branch logged 275 ms, which is over the old 250 ms budget. That is the CI failure, reproduced locally.

The old timing assertion also did not protect what it was meant to protect. These three mutants passed the old test on master:

• resolution moved into the transaction (about 1 ms per batch);
• every write deferred to one transaction at the end;
• one transaction per batch, but every row written in the last one.

Even 5000 rows in one transaction took only 45–160 ms. The old test caught only the "one batch reads everything" mutant, and only through its Batches == 10 check.

Fix

TestResolvedPathBackfill_WriteHoldUnderBudget_188 now asserts the bound structurally and deterministically:

• One write transaction per batch: the WriterTx count for the resolved_path_backfill component (from the writer stats) equals res.Batches.
• At most batchSize rows per transaction: test-only SQLite triggers on observations.resolved_path (NULL → value) and on resolved_path_backfill_state call a Go function, backfill_probe_267, from inside the transaction. The writes are split at each watermark write, which a batch makes last in its transaction. The test asserts one watermark per batch, ≤ 500 rows per transaction, 5000 rows in all, no row update without a following watermark, and every write made with writerMu held.
• No resolution while the write transaction is held: resolveObservationPath is now called through resolvedPathBackfillResolve, a variable, like readProcSelfIOFn. The test's wrapper counts resolutions made while writerMu is held. The count must be 0, out of 5000.

No timing assertion remains. Why:

• about three quarters of the hold is fsync latency, which depends on the runner's disk;
• a relative check (max against median batch) would bound fsync jitter, not the code;
• both regression shapes the issue names are now caught deterministically.

The hold is still logged. BenchmarkResolvedPathBackfillBatch reports it as hold-ms/batch without the probe triggers. The test's logged hold includes the probe's per-row callback, so it reads about 10–20 ms higher.

The test fixtures backfillFixture188 and primeIndexAndGraph188 now take testing.TB, so the benchmark can use them.

Measurements

• Unchanged test on master, -count=50 -cover, two load loops: 50/50 pass, hold 17.8 / 29.4 / 89.5 ms (min / median / max).
• This branch, go test -count=50 -run TestResolvedPathBackfill_WriteHoldUnderBudget_188 -cover ./..., four load loops:
  • run 1: 50/50 pass, logged hold 52.3 / 70.7 / 205.9 ms;
  • run 2: 50/50 pass, logged hold 43.2 / 76.0 / 275.2 ms.
• BenchmarkResolvedPathBackfillBatch: 17.5 hold-ms/batch idle, 36.7 hold-ms/batch under load.

Mutants (new test)

mutant	old test	new test
m1: resolution moved into the WriterTx closure	pass	fail: 5000 of 5000 rows resolved while holding writerMu
m2a: one batch reads all rows	fail (Batches)	fail: 1 batch, want 10
m2b: batched reads, all writes deferred to one transaction	pass	fail: 1 write transaction for 10 batches
m2c: one transaction per batch, all rows written in the last one	pass	fail: transaction 9 updated 5000 rows, want ≤ 500

Checks

• cd cmd/ingestor && go test -race -count=1 -timeout 90m -v ./...: ok in 1643 s (963 PASS lines), no data race reported. A run with the default 10 min timeout timed out in TestConcurrentWrites, which takes 111 s alone under -race on master; CI uses -timeout 20m.
• go vet ./... in cmd/ingestor: clean
• gofmt -l on the two touched files: clean
• sh test-all.sh: 218 of 219 files pass. test-channels-client-state-152.js failed once (R4-3 S2, "Decrypting…" pane). It is unrelated, since no JS is touched. Standalone it passed 9 of 10 runs while other tests loaded the machine, so it is a pre-existing timing flake.

Writes stay in the ingestor. No new map[string]interface{}. No workflow files are touched: fork guards are 9 in deploy.yml and 1 in release-fast-path.yml.

🤖 Generated with Claude Code

[dborup-agent]

Rapport — CS-pve-agent2 PR#272 #267 — head bc04203

Status: Draft ready for review. The cause is found and the test now asserts the bound structurally. CI is green; the PR is not marked ready.

Evidence tags:

• [T] = tested or measured in this session;
• [K] = read from code, config or CI;
• [A] = analysis or inference.

Cause

• [T] Per-phase timing under -cover and parallel CPU load (go test ./... loops on cmd/server), 200 batches of 500 rows, median / p95 / max:

  phase	median	p95	max
  COMMIT	15.5 ms	30.3 ms	45.4 ms
  hold (total)	21.6 ms	36.3 ms	52.7 ms
  UPDATEs + watermark	5.6 ms	7.9 ms	11.4 ms
  writerMu wait + BEGIN	0.03 ms	0.05 ms	0.3 ms

  Resolution (1.1 ms median) and the read (1.9 ms median) already run outside the transaction.

• [T] PRAGMA synchronous is 2 (FULL). With synchronous=OFF on the same load, the hold drops to a 3.1 ms median and a 12.8 ms max. So COMMIT time is the WAL fsync.

• [T] No WAL auto-checkpoint fired in any batch.

• [K] The UPDATEs, the watermark upsert and COMMIT must be atomic for idempotent resume. Nothing in the transaction can move out without changing semantics.

• [A] The 264 ms in CI is disk-flush latency on a loaded runner, not code inside the transaction.

• [T] Reproduced locally: the unchanged master test reached a max of 235 ms, and one 50-run loop on the branch logged 275 ms.

Fix

• [K] Production code is unchanged, apart from one seam: resolvedPathBackfillResolve = resolveObservationPath.
• [K] The test now asserts:
  • the WriterTx count equals the batch count;
  • SQLite triggers call a Go probe from inside the transaction: one watermark write per batch, ≤ 500 rows per transaction, 5000 rows in all, and every write made under writerMu;
  • 0 of 5000 resolutions run while writerMu is held.
• [K] The absolute 250 ms assertion is removed, and no timing assertion remains. BenchmarkResolvedPathBackfillBatch reports hold-ms/batch.
• [A] Why no timing assertion: about 75% of the hold is fsync jitter, and a relative check would bound that jitter, not the code. Both regression shapes are now caught deterministically.

Measurements, before and after

• [T] Master, unchanged test, -count=50 -cover, two load loops: 50/50 pass, hold 17.8 / 29.4 / 89.5 ms (min / median / max).

• [T] Branch, go test -count=50 -run TestResolvedPathBackfill_WriteHoldUnderBudget_188 -cover ./..., four load loops (load average ~6 on 4 cores):

  • run 1: 50/50 pass, logged hold 52.3 / 70.7 / 205.9 ms;
  • run 2: 50/50 pass, logged hold 43.2 / 76.0 / 275.2 ms.

• [T] Interleaved A/B under the same load, 2 × 10 runs. The probe's per-row trigger callback adds about 10–20 ms to the median logged hold, which is why the log line says so:

  round	master median / max	branch median / max
  1	58.3 / 67.5 ms	67.7 / 117.6 ms
  2	50.8 / 235.0 ms	78.7 / 133.6 ms

• [T] Benchmark, without the probe: 17.5 hold-ms/batch idle, 36.7 under load.

• [K] The load runs were made on 56f214e3. bc042038 changes only the log text and a comment.

Mutants

mutant	old test	new test
m1: resolution moved into the WriterTx closure	[T] pass	[T] fail: 5000 of 5000 resolved under writerMu
m2a: one batch reads all rows	[T] fail (Batches)	[T] fail: 1 batch, want 10
m2b: batched reads, all writes deferred to one transaction	[T] pass	[T] fail: 1 write transaction for 10 batches
m2c: one transaction per batch, all rows in the last one	[T] pass	[T] fail: transaction 9 updated 5000 rows

Local checks

• [T] go test -race -count=1 -timeout 90m -v ./... in cmd/ingestor: ok, 1643 s, no data race. The first attempt used the default 10 min timeout and timed out in TestConcurrentWrites while test-all.sh ran alongside. That test alone takes 111 s under -race on master. [K] CI uses -timeout 20m without -race for this package.
• [T] go vet ./...: clean. gofmt -l on the touched files: clean.
• [T] sh test-all.sh: 218/219. test-channels-client-state-152.js R4-3 S2 failed once. Standalone it failed 1 of 10 runs while other tests loaded the machine. No JS is touched.

CI per job (run 37349971997, head bc04203)

• [K] Go Build & Test: success, including "Build and test Go ingestor (with coverage)" and "Run JS unit tests (test-all.sh)".
• [K] Playwright E2E Tests: success.
• [K] Build & Publish Docker Image: success.
• [K] Release Artifacts, Deploy Staging, Publish Badges & Summary: skipped (fork guards).
• [K] No rerun was needed. flaky: #226 Hash Stats adopters sort E2E — server sorts multiByteNodes on packets only, ties come out in random order #256 did not show up.

Remaining

• [A] test-channels-client-state-152.js (R4-3 S2) looks like a pre-existing timing flake under load, and I found no issue for it. It is a candidate for its own flaky issue.
• [K] Two commits on the branch (the second only changes log text and a comment). Squash on merge if one commit is preferred.
• [K] Writes stay in the ingestor. No new map[string]interface{}. Fork guards unchanged: 9 in deploy.yml, 1 in release-fast-path.yml.

[dborup-agent]

Review — CS-pve-agent3 PR#272 — head bc04203

Dom: APPROVE with nits

Evidence tags:

• [T] = tested or measured in this review;
• [K] = read from code, config or CI;
• [A] = analysis or inference.

Independent, read-only review. Head checked with git ls-remote before and after: unchanged at bc042038. Merged tree used: git merge-tree --write-tree origin/master bc04203… on origin/master = c6b356de.

Findings

#	Severity	Finding
1	nit	[T] rowsPerWatermark splits transactions at the watermark write, so the test depends on statement order inside the transaction. My mutant m4 writes the watermark first in the same atomic WriterTx. Its semantics and the per-transaction bound are unchanged, yet it fails with "500 row updates were not followed by a watermark write in their transaction". The test comment states the assumption, so this is not a bug. A harmless refactor would trip it, though, with a misleading message. Optional: say "watermark must be the last write in the transaction" in the failure message, or split on the transaction boundary instead.
2	nit	[A] writerMuHeld() is a TryLock heuristic. Any other goroutine that holds writerMu when a row is resolved (for example a background writer left over by an earlier test in the package) would count as "resolved under lock" and fail the test. The comment states the assumption ("Only the backfill writes during the test"). [T] I did not see it trigger: 100 isolated runs under load, plus one full-package run each with -cover and with -race. Low risk, but it is the one remaining nondeterministic input.
3	info	[T] The cause holds, with one nuance. COMMIT/fsync dominates the hold. With synchronous=OFF under load, I still saw one 47.6 ms COMMIT and a 53.7 ms max hold, so part of the tail is scheduling as well as fsync. This supports dropping the wall-clock assertion.
4	info	[T] In my full-package -race run on the merged tree, the new test logged a max hold of 283 ms and passed. The old 250 ms assertion would have failed there.

1. Cause

[T] I timed each phase again with a temporary patch in a scratch copy, not pushed. Setup: head tree, -cover, 20 passes × 10 batches = 200 batches of 500 rows, PRAGMA synchronous = 2.

setup	BEGIN median	UPDATEs + watermark median / max	COMMIT median / p95 / max	hold median / p95 / max
idle	0.03 ms	5.8 / 8.8 ms	7.8 / 16.0 / 25.1 ms	13.6 / 21.7 / 31.2 ms
2 × go test ./... load, run A	0.02 ms	4.7 / 107.5 ms	15.0 / 32.2 / 113.9 ms	21.0 / 38.7 / 147.0 ms
same load, run B	0.02 ms	2.3 / 5.9 ms	23.2 / 36.1 / 181.0 ms	25.9 / 38.6 / 186.4 ms
same load, synchronous=OFF	0.02 ms	2.4 / 7.3 ms	0.08 / 3.1 / 47.6 ms	2.5 / 6.7 / 53.7 ms

• [T] COMMIT is about 57% of the median hold when idle and 70–90% under load. In run B it also makes up 181 of the 186 ms max. With synchronous=OFF, the median COMMIT is 0.08 ms. The author's explanation (WAL fsync on a loaded runner) is reproduced.
• [K] Resolution already runs before WriterTx. The UPDATEs, the watermark upsert and COMMIT have to stay atomic for idempotent resume. Nothing can move out of the transaction without changing semantics.

2. The structural assertion

[K] The test asserts:

• one WriterTx per batch (a delta of the monotonic count);
• one watermark per batch, at most 500 rows per transaction and 5000 rows in total, seen by triggers from inside the transaction;
• no write without writerMu;
• 0 of 5000 resolutions under writerMu.

The probe function is registered once, before the store opens its connection. The seam and the probe pointer are restored in t.Cleanup.

Mutants, each applied to resolved_path_backfill.go and run against the new test and against the old (master) test file:

mutant	old test	new test
m1: resolution loop moved into the WriterTx closure	[T] pass	[T] fail: "5000 of 5000 rows were resolved while the write transaction held writerMu"
m2: one batch reads all rows (LIMIT limit*1000)	[T] fail (Batches)	[T] fail: "1 batch, want 10"
m3: one transaction per batch, all rows written in the last one	[T] pass	[T] fail: "write transaction 9 updated 5000 rows, want at most 500" (hold 268 ms)
m4 (harmless): watermark written first in the same transaction	[T] pass	[T] fail (see nit 1)

Both regression shapes named in the issue (m1, and m2/m3) now fail deterministically. Before this PR, only m2 was caught.

3. Stability under load

[T] go test -count=50 -run TestResolvedPathBackfill_WriteHoldUnderBudget_188 -cover ./... in cmd/ingestor (head):

run	parallel load	result	logged hold min / median / max
1	2 × go test ./... loops on cmd/server, load ~4 on 4 cores	50/50 pass	29.7 / 56.7 / 221.1 ms
2	4 loops, plus the master run below in parallel, load ~7	50/50 pass	35.4 / 63.8 / 218.6 ms
master (old test), same time as run 2	same	50/50 pass	25.1 / 38.2 / 203.8 ms

• [T] I could not make the old test red locally with -count=50: max 203.8 ms. It did exceed 250 ms in the -race run (283 ms, finding 4).
• [K] It also failed in master CI run 37321760306 (264 ms), so the "red before" evidence for this criterion is CI plus my -race observation.
• [T] BenchmarkResolvedPathBackfillBatch (idle, 30×): 15.1 hold-ms/batch.

4. Production code

• [K] The only production change is var resolvedPathBackfillResolve = resolveObservationPath, called in the same place, with the same arguments, outside the transaction. The semantics are unchanged. The cost is one indirect call per row, which is negligible next to resolution.
• [T] cd cmd/ingestor && go test -race -count=1 -timeout 90m -v ./... on the merged tree: ok in 1884 s, 793 PASS, 0 FAIL, 0 DATA RACE.
• [T] go vet ./... is clean, and gofmt -l is clean on both touched files.

Acceptance criteria (issue #267)

criterion	red before	green after
Cause named with evidence	—	[T] reproduced (section 1)
-count=50 … -cover passes under parallel load	[K] CI run 37321760306; [T] 283 ms > 250 ms in the -race run	[T] 2 × 50/50
Mutant (resolution in tx / all rows in one tx) fails the test	[T] m1 and m3 pass the old test	[T] m1, m2 and m3 fail the new test

Invariants

• [T] cmd/server is untouched (0 files). No new map[string]interface{}: 0 added lines.
• [T] No hardcoded colors. The only #xxx matches in the diff are #267.
• [T] bash scripts/check-xss-sinks.sh --diff origin/master: exit 0, with no public/ changes to scan.
• [T] Fork guards: deploy.yml 9 and release-fast-path.yml 1, the same as master. No workflow files are touched.
• [T] No closing keywords in the PR body or the commit messages ("Relates to flaky: TestResolvedPathBackfill_WriteHoldUnderBudget_188 — wall-clock write-hold budget fails under CI load #267").
• [K] Both commits have author and committer dborup <kontakt@meshview.dk>.

Tests on the merged tree (c6b356de + head)

• [T] cmd/ingestor go test -count=1 -timeout 20m -cover ./...: ok in 982 s, coverage 80.0%.
• [T] cmd/server go test -count=1 ./...: ok in 1298 s. The PR does not touch it; this is a regression check only.
• [T] sh test-all.sh: 219/219 files pass.
• [T] node test-frontend-helpers.js: 707 passed, 0 failed.
• [T] E2E against a local Go server with e2e-fixture.db, prepared as CI does: freshen, the Packets page collapse button in the left column of the table opens the dialog. Kpa-clawbot/CoreScope#1486/"Group Data" message type missing from packet view window's "message type" filter Kpa-clawbot/CoreScope#1791 seed SQL, corescope-migrate, then seeds 2073, 199 and 245 (master CI now applies 245 too). The server was stopped via its port.
  • test-node-liveness-e2e.js: 35/35.
  • test-e2e-playwright.js: 6 passed, then fail-fast on "Version info lives on Perf dashboard, not in navbar" (#navStats wait timeout).
  • The same failure reproduces on plain origin/master with a fixture prepared the same way, so it is environment-specific to my machine and not caused by this PR.
  • A standalone browser probe against the same server shows #navStats filled ("500 pkts · 204 nodes · 31 obs"). I did not dig further.
  • The PR has no E2E of its own and touches no frontend or server code.

CI (run 37349971997, head bc04203, attempt 1)

• [K] Go Build & Test: success. This includes "Build and test Go ingestor (with coverage)", "Run JS unit tests (test-all.sh)" and the XSS preflight gate.
• [K] Playwright E2E Tests: success.
• [K] Build & Publish Docker Image: success.
• [K] Release Artifacts, Deploy Staging, Publish Badges & Summary: skipped (fork guards).
• [K] No reruns. Neither flaky: #226 Hash Stats adopters sort E2E — server sorts multiByteNodes on packets only, ties come out in random order #256 nor flaky: TestResolvedPathBackfill_WriteHoldUnderBudget_188 — wall-clock write-hold budget fails under CI load #267 showed up.

Not verified

• [A] I did not get the old test over 250 ms in a -count=50 -cover loop. The only local overshoot was in the full -race run.
• [A] I did not re-run the author's interleaved A/B measurement of the probe's overhead on the logged hold.
• [A] I did not run the full E2E suite past the environment-specific fail-fast above, and I did not run the coverage-instrumented frontend.
• [A] I did not test the TryLock false-positive scenario (nit 2) with a deliberately leaked writer.