Skip to content

The at-the-cap aggregate test no longer races TimescaleDB's scheduler (#5603) - #5605

Merged
erikdarlingdata merged 6 commits into
devfrom
fix/5603-aggregate-quiesce-cap-race
Oct 9, 2026
Merged

erikdarlingdata merged 6 commits into
devfrom
fix/5603-aggregate-quiesce-cap-race

Conversation

@erikdarlingdata

@erikdarlingdata erikdarlingdata commented Oct 9, 2026 •

Copy link
Copy Markdown
Owner

Closes #5603.

SECTION: none (test-only)

No product behaviour changes. The live aggregate quiesce tests no longer need to see a TimescaleDB job worker alive inside a time window. The hold test and the at-the-cap test give their gate function a trap. The trap counts the scheduler's cancel and keeps waiting. The cancel test is built so that the scheduler cannot change its outcome. The product comments on the quiesce sweep give the measured scheduler timing.

Why

CI run 37856872462 ("Darling PG tests (1)") failed AtTheCap_... at AggregateJobQuiesceTests.cs:445. After the zero-cap sweep the refresh worker was gone (expected 1, actual 0). The server log shows the worker (pid 1776) began its refresh at 23:15:11.889 and was cancelled about 30 ms later. The test had waited only for the worker to be listed.

The first fix aligned each test with the scheduler's idle state. It narrowed the race but did not remove it. On a CI runner with one CPU burner per processor (8 live tests x 10 iterations x 4 shards):

  • The test file at origin/dev (run 37867434337) was 40 of 40 green. But 4 of the 40 reported Skipped: 1. The only Assert.Skip in that file is the hold test's "TimescaleDB ended the job worker before the hold could be observed". So the same race happened 4 times, and the old test hid it as a skip.
  • The first fix (run 37867443100) was 39 of 40. RunningJobWorker_HoldsTheDrop_UntilItExits failed at AggregateJobQuiesceTests.cs:392 with "the hold was never observed". The alignment gives about 4.7 s before the next wake. The hold test's task start, its wait for the stop and its 2 s look loop all had to finish inside that gap. Under load they did not.

The second round (hold and cancel tests read recorded facts, as described below) was run 37872675300: 78 of 80. The hold and cancel tests had 0 failures in 80 iterations. Both failures were AtTheCap_..., the test that round left as it was.

  • Shard 0, iteration 3: AggregateJobQuiesceTests.cs:503, "the job worker (pid 2288) the sweep must leave running is gone. The scheduler HAD woken since the worker was parked". The sweep's one look saw the worker, skipped and resumed. The worker was gone a moment later.
  • Shard 4, iteration 2: AggregateJobQuiesceTests.cs:493, the zero-cap sweep returned 1 (it dropped the aggregate), expected 0. The one look saw no worker.
  • In both PostgreSQL logs the worker ended 136 to 140 ms after its refresh began. The error line is job 1000 threw an error followed by ERROR: invalid transaction termination. Neither log has a canceling statement due to user request line for that worker.

This round measured what that error is, and gives the at-the-cap test the same trap the hold test has.

Measurements (local PostgreSQL 18.6, TimescaleDB 2.30.1, UTC, CI's worker settings)

Measured this round (policy worker parked on a plain gate or on the test's trapping gate):

  • A cancel of a worker on a plain gate shows up as invalid transaction termination. Sent pg_cancel_backend to the parked policy worker at 02:40:31.363. The log has job 1000 threw an error at .368 (5 ms later) and ERROR: invalid transaction termination at .392. The worker exited with code 1 at .430. There is no canceling statement due to user request line for it. So the error text in the two CI failures is what a cancel looks like on a plain gate.

  • The trapping gate survives the cancel. Same test with the gate function the test plants. The cancel count went to 1. The worker was still listed (active, waiting on the advisory lock) 1 s and 6 s after the cancel. The log has no error line for it.

  • The scheduler's own cancel is trapped too. The worker was parked on the trapping gate and the jobs were stopped. In 2 runs the cancel count went to 1 and the foreign-cancel count stayed 0. The worker stayed listed for 3.229 s and 3.256 s after the scheduler's wake began. Then the scheduler's SIGTERM ended it.

  • Stopping the jobs does not wake the scheduler early. 20 runs with a worker parked on a plain gate and the scheduler idle again. The stop came 0 to 4.8 s into the idle gap. The next wake began 129 ms to 4.95 s after the stop. It always began 4.61 to 4.97 s after the scheduler was first seen idle (the timer is 5.0 s). The wake that did the cancel ended the worker 8 to 17 ms after it began.

  • Which test the passing error belongs to.

    Shard 0 has the same error at 02:09:03.219 (refresh began 02:09:02.949), in iteration 2, which passed.

    In the three iterations I read, three tests start a worker, in the same order each time. The second one's refresh runs about 5 s, which is the hold test. The third is the at-the-cap test (pid 2288 in iteration 3 matches). By elimination the first one, which holds the iteration-2 error, is CancelledWhileWaiting_.... That test has no alignment and tolerates the worker's death. It is the same early cancel, 270 ms after launch, in a test that passes anyway.

Inferred, not measured: why the cancel arrives 140 ms after launch. The scheduler has a wake that handles the new worker's start. Under load it can run after the worker is already blocked on the gate.

The test's idle check can already be true from the scheduler's earlier idle state, so the sweep stops the jobs before that wake runs. That wake then sees a stopped job and cancels the worker. This fits both CI failures and the passing iteration-2 case. The 20 runs above show that the stop itself does not wake the scheduler early, which leaves a wake that was already pending. It was not reproduced, because that needs the CPU load of the runner.

Measured in the earlier rounds:

  • Which signal, and how fast. The scheduler sends a cancel (SIGINT) at its first wake after the stop. 3.3 s later it logs WARNING: job 1000 did not exit after SIGINT, sending SIGTERM and FATAL: terminating background worker. A worker that does not swallow the cancel exits at once with job 1000 threw an error. With a worker parked on the gate, the cancel reached the gate 4.96 to 4.99 s after the stop in 19 runs. The worker was gone 3.2 to 3.34 s after the cancel.
  • Does a worker survive stop_background_workers()? No (gone 1 ms after the call), so stopping the scratch database's scheduler cannot be used.
  • Is the scheduler "active" when its own cancel lands? Yes. A gate that reads the scheduler's pg_stat_activity row at each swallowed cancel saw state = active in 11 of 11 runs. Eight more runs traced the row for the whole time the worker lived after the cancel. It stayed active with an unchanged state_change throughout. A cancel at any other time did not come from the scheduler.
  • Does the DROP cancel a worker itself? Yes, and the foreign-cancel count caught it. With a sweep that does not wait for the worker, a cancel reached the trapped gate 0.17 s after the scheduler had gone idle. It was counted as foreign.
  • Event trigger. An event trigger ON ddl_command_start WHEN TAG IN ('DROP VIEW', 'DROP MATERIALIZED VIEW') fired once for the product's DROP inside its DO $do$ block. It saw the worker listed in pg_stat_activity, while that DROP was still waiting. So it fires before the DROP waits on the worker's locks.

What changes

Darling/Darling.Tests/AggregateJobQuiesceTests.cs:

  • AtTheCap_... (this round). Its scratch database gets PlantTrappingGateAsync. The idle alignment is gone: the worker is started with StartBlockedWorkerAsync like the hold test's. The scheduler can now cancel the worker at any wake after the stop. The trap counts that cancel, and the worker survives 3 s or more after it. The zero-cap sweep and its assertions take milliseconds. Every existing assertion stays. One new assertion: w5551_foreign_cancels = 0. It is read once the worker is gone. A cancel the sweep itself sent is swallowed by the same trap, and the handler counts it a few milliseconds later. The failure message of the still-running check now names the gate's cancel counts. The test does not require a cancel to happen, and has no "or the worker is gone" branch.
  • Removed: StartParkedWorkerAsync, ParkedWorker, SchedulerIdleSinceAsync and SchedulerWokeSinceAsync, and the unused using NpgsqlTypes. Nothing else used them.
  • RunningJobWorker_HoldsTheDrop_UntilItExits and CancelledWhileWaiting_... (second round, code unchanged this round). The hold test's gate catches query_canceled, calls nextval('collect.w5551_cancels') and waits again. The test waits (60 s safety bound only) until the count is at least 1. That count proves the worker outlived the stop, however slowly the test ran. Every per-look assertion stays, plus the foreign-cancel count and an event-trigger count of DROPs that started beside a worker. The cancel test uses a ten-minute poll, so its cancel always lands in the wait.
  • The class remarks and the ZeroCap doc now say only that the worker survives 3 s or more after a scheduler cancel. The text that said the sweep fits inside an idle gap is gone.

Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs has two comments from the second round that give the measured timing. They say the next wake comes tens of milliseconds to about 5 s after the stop. They say a worker that ignores the cancel is gone after 8 s at most. Nothing in them became untrue, so this round leaves them as they are.

Audit of every live test in AggregateJobQuiesceLiveTests

  • Sweep_StopsTheAggregatesJobsBeforeTheDrop..., EmptyFinalLookAtTheCap_..., FailedDrop_..., Reshape_..., PlainViewAndPlainPostgresStore_...: safe. No worker is ever running, because every policy starts a day out.
  • RunningJobWorker_HoldsTheDrop_UntilItExits: recorded facts (trap and event trigger).
  • CancelledWhileWaiting_...: ten-minute poll.
  • AtTheCap_...: the CI failure. Now the trap, with the foreign-cancel check.

Test plan

  • Build Darling.Tests: 0 warnings, 0 errors.
  • *AggregateJobQuiesce* (15 tests, including the 8 live ones) against a local PostgreSQL, 3 times in a row on the final head. Total 15, Failed 0 each time.
  • On the final head: *Census* 495, *Ratchet* 15, *Scrub* 123, *Guard* 338, *Hygiene* 90, *DocComment* 78, Stage=Guard trait 1444. Failed 0 in each.
  • RED plants against AtTheCap_... this round. Each plant is one product line in TimescaleSupport.cs. Built, run, then reverted, and git status was clean after each:
Plant Where it went RED Actual value
P4: the sweep terminates the worker at the cap still-running check, line 506 (Assert.Fail) "the job worker ... is gone. Its gate counted 0 cancel(s)"
P4b: the sweep cancels the worker at the cap w5551_foreign_cancels = 0, line 516 expected 0, actual 1
P1: the sweep drops at the cap zero-cap sweep result, line 494 expected 0, actual 1
P2: no resume after the skip jobs scheduled again, line 497 3 of 3 jobs not scheduled
P3: the warning logged at Debug warning count, line 498 expected 1, actual 0
P3b: the warning text without #5551 warning text, line 499 filter not matched
  • RED plants from the second round, hold and cancel tests (code unchanged this round): P9 (pg_cancel_backend in the wait loop) went RED on w5551_foreign_cancels. P9b (pg_terminate_backend in the wait loop) went RED on "gone and its gate never counted a cancel". P7 (no wait after the stop) went RED in the hold, cancel and at-the-cap tests. P5 (skip instead of drop on two empty looks) and P8 (no resume on cancel) went RED on their assertions.
  • Timing scanner (Tests stop sharing WPF threads, Postgres roles and runner CPU #5604): the clock patterns find no match in AggregateJobQuiesceTests.cs.
  • Runner proof: run 37877751999 passed 80 of 80. It was a push to a throwaway branch (head bd49adc, which holds this PR's final test file), windows-latest, 8 shards x 10 iterations. One CPU burner ran per logical processor, and the setup is copied from the darling-pg job. Every shard reported 10 passed, 0 failed. Every iteration ran all 8 live tests: Total 8, Failed 0, Skipped 0. So AtTheCap_... had 0 failures in 80, against 2 in the previous round, and no test was skipped. The cause of the early cancel stays inferred (see the Measurements section). The proof is this run plus the plants above.

Fixes #5603

…re the sweep (#5603)

The live quiesce tests that need a running job worker now start it through one helper that returns only when the worker is blocked on the gate and the scheduler has finished the wake that launched it, so the scheduler's next wake is about 5 s away while the sweep and its assertions run. The product comments that said the scheduler ends a worker 'within a few seconds' now state the measured timing.
@erikdarlingdata
erikdarlingdata marked this pull request as ready for review October 9, 2026 03:25
@erikdarlingdata
erikdarlingdata merged commit a18bad0 into dev Oct 9, 2026
36 of 40 checks passed
@erikdarlingdata
erikdarlingdata deleted the fix/5603-aggregate-quiesce-cap-race branch October 9, 2026 03:52
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.

1 participant