Skip to content

executor: warm the parser before timing the lock-budget test - #212

Open
Kiran01bm wants to merge 2 commits into
mainfrom
kiran01bm/fix-lock-budget-test-timer
Open

Kiran01bm wants to merge 2 commits into
mainfrom
kiran01bm/fix-lock-budget-test-timer

Conversation

@Kiran01bm

Copy link
Copy Markdown
Collaborator

Parse the statement before starting the stopwatch in the accepted-blocking lock-budget test, so the SQL parser's one-time startup no longer counts against the test's 2s bound.

Why

TestExecuteAcceptedBlockingLockBudgetExecutesNothing times a call to ExecuteAcceptedBlocking, which parses its statement before it waits on anything. The first parse in a process pays the Wasm parser's startup, which under -race took about 5.6s, so the test failed every time it ran alone even though the executor gave up the lock wait after its 100ms budget. In the full package run an earlier test has already warmed the parser, which is why it passes in CI.

What

  • Parse the test's statement once before start := time.Now(), so the stopwatch covers only the call's own work.
  • The 2s bound and every assertion are unchanged. A lock budget the executor does not honour still fails the test: with the executor's lock_timeout hardcoded to 3s, it fails at 3.0s.

Before / after

Here is one example: the test's DROP INDEX <schema>.i while another session holds ACCESS EXCLUSIVE on the table, with a 100ms lock budget, run alone under -race. Only the point where the stopwatch starts moves. The executor, its budget, and the 2s bound do not change.

Before   (test run alone, -race)
  start the stopwatch
    │
    ├─ ExecuteAcceptedBlocking parses DROP INDEX <schema>.i: the parser's first use, ~5.6s
    │
    ├─ it waits for the table lock and gives up after the 100ms budget: lock-budget error (correct)
    │
    └─ the stopwatch reads ~5.7s, over the 2s bound   ✗ the test fails though the executor was right

After    (test run alone, -race)
  parse DROP INDEX <schema>.i once, outside the stopwatch: the parser's first use, ~5.6s
  start the stopwatch
    │
    ├─ ExecuteAcceptedBlocking parses the statement again: the parser is warm, so this is quick
    │
    ├─ it waits for the table lock and gives up after the 100ms budget: lock-budget error (correct)
    │
    └─ the stopwatch reads ~0.11s, under the 2s bound   ✓

ExecuteAcceptedBlocking parses before it waits; the first parse in a
fresh process under -race took seconds and was counted against the
test's 2s lock-wait bound, so the test failed when run alone.
@Kiran01bm
Kiran01bm marked this pull request as ready for review October 17, 2026 07:15
@chatgpt-codex-connector

Copy link
Copy Markdown

Codex Review Summary

This comment shows the latest Codex review activity on this pull request.

Review Status Commit Review trigger
📝 Code Review ⚠️ Failed 2026-10-17T07:15:58.991644Z f084edf Draft marked ready
ℹ️ About Codex in GitHub

Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review" or "@codex security review".

Codex reacts with 👀 while any review is running, comments if it has suggestions, and reacts with 👍 once all reviews finish with no findings.

@chatgpt-codex-connector

Copy link
Copy Markdown

You have reached your Codex usage limits for code reviews. You can see your limits in the Codex usage dashboard.

@aparajon

Copy link
Copy Markdown
Collaborator

🤖 Review 1/2 (adversarial correctness) of efc4d58: 0 blocking, 1 non-blocking.

Inspected the whole diff at efc4d58 (one test file, +7/-1), the code under test (ExecuteAcceptedBlocking), and the other timing assertions in the repo. The PR moves the parse of the test's statement ahead of the stopwatch in TestExecuteAcceptedBlockingLockBudgetExecutesNothing, so the Wasm parser's one-time startup no longer counts against the 2s bound. The diagnosis is correct: the executor parses at accepted_blocking.go#L114, before it takes the table lock, and the warm-up at accepted_blocking_integration_test.go#L51 parses the byte-identical SQL through the same statement.ParseOne. The fix is correct and does not weaken the test: the bound and every assertion are unchanged, and a lock budget the executor does not honour still fails it. Production code is untouched, so AB-2 (lock-budget exhaustion executes nothing, invariants.md#L625) is upheld and the test still pins it.

Non-blocking

  1. The same first-parse hazard is still live in pkg/preflight. rewriteFixture.prove at add_column_rewrite_integration_test.go#L71-L80 starts a 10s deadline context and a stopwatch, then calls AddColumnRewrites, which parses the statement (add_column_rewrite.go#L65 and #L72), and then asserts time.Since(start) < probeDeadline/2 (5s). That is the same shape this PR fixes, with a tighter margin: the first parse costs about 5.6s to 6s under -race, which is already over the 5s assertion and more than half of the 10s context. Any preflight test that reaches prove first in a process fails when run alone, which is exactly the "failed every time it ran alone" symptom the PR describes. It passes in CI only because an earlier test in the package warms the parser. The fix is the same one-liner, placed before context.WithTimeout so the deadline is not spent on it either. A TestMain that parses once per package would cover both packages and any future timed test, instead of a per-test warm-up that each new timed test has to remember.
Test case: the existing test run alone fails, and passes with the warm-up in `prove`
// pkg/preflight/add_column_rewrite_integration_test.go
func (f rewriteFixture) prove(t *testing.T, alter string) map[string]statement.AddColumnProof {
	t.Helper()
	// The proof parses its statement; the parser's first use in a process
	// is slow under -race, so pay it before the deadline and the stopwatch.
	_, err := statement.ParseOne(fmt.Sprintf(alter, f.schema))
	require.NoError(t, err)
	ctx, cancel := context.WithTimeout(t.Context(), probeDeadline)
	defer cancel()
	start := time.Now()
	proofs, err := preflight.AddColumnRewrites(ctx, f.pool, f.schema, "t", fmt.Sprintf(alter, f.schema))
	require.NoError(t, err)
	assert.Less(t, time.Since(start), probeDeadline/2, "a probe waited on a lock")
	return proofs
}

go test -race -count=1 ./pkg/preflight/ -run '^TestAddColumnRewritesProvesEachColumnOfOneStatement$' on efc4d58: Error: "6.150193458s" is not less than "5s" and --- FAIL: TestAddColumnRewritesProvesEachColumnOfOneStatement (7.97s). With the change above: --- PASS: TestAddColumnRewritesProvesEachColumnOfOneStatement (8.17s).

Verified

  • Ran TestExecuteAcceptedBlockingLockBudgetExecutesNothing alone under -race at efc4d58: passes, with the stopwatch reading 116ms (100ms budget plus the round trips), so the claimed ~0.11s holds.
  • Reproduced the reported failure by removing only the warm-up: the stopwatch reads 5.88s and the test fails, matching the PR's ~5.6s to 5.7s.
  • Pool dial, SET LOCAL, and the LOCK TABLE request are still inside the timed region; at 116ms total they are not a flake source.
  • The other timed assertions in the repo are lower bounds (GreaterOrEqual against the lock budget in accepted_blocking_integration_test.go and recover_integration_test.go), which a slow first parse cannot break. The one upper-bound sibling is finding 1.
  • CI is green on every job at this head.
Mutant Caught by
Remove the mustParse warm-up (the pre-PR test), run alone under -race the test itself: 5.88s, fails
Executor SET LOCAL lock_timeout hardcoded to 3000ms TestExecuteAcceptedBlockingLockBudgetExecutesNothing: 3.012s, fails (the PR's "fails at 3.0s" claim holds)

This review was generated by Claude Code (claude-sonnet-5-5).

@aparajon

Copy link
Copy Markdown
Collaborator

🤖 Review 2/2 (OSS adoption and integration ease) of efc4d58: 0 blocking, 0 non-blocking.

The change is test-only, so neither lens has anything to measure in the shipped surface: no exported symbol, CLI output, document, or default moves, and go.mod is untouched.

OSS adoption. The PR improves the first-contact path. A new contributor who runs one test with go test -race -run (the natural first move on an unfamiliar repo) currently gets a red TestExecuteAcceptedBlockingLockBudgetExecutesNothing that looks like a lock-budget bug in a safety path, when it is parser startup. After this change that test is green alone, which removes a misleading failure from the first run. The PR description is accurate and checkable: it names the inputs, shows before and after, and the numbers reproduce (5.88s without the warm-up, 116ms with it, 3.0s with the budget hardcoded to 3s). The in-test comment says why the warm-up exists, so nobody deletes it as a redundant parse. The one adoption gap is the sibling timed test in pkg/preflight that still fails alone for the same reason (finding 1 in comment 1/2), so a contributor running that package's tests singly still hits the same wall.

Integration ease for schemabot and other importers. Nothing an importer links against changes. Worth knowing for importers who write their own timed tests around statement.ParseOne, ExecuteAcceptedBlocking, or AddColumnRewrites: the first parse in a process costs seconds under -race, so a long-lived importer should expect that cost on its first call and not read it as a lock wait. That is a property of the Wasm parser, not of this PR.

This review was generated by Claude Code (claude-sonnet-5-5).

@aparajon aparajon left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🤖 Stamping with comments: 0 blocking, 1 non-blocking (see the review comment above).

This stamp was left by Claude Code (claude-sonnet-5-5).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants