Skip to content

Darling.Tests: the WaitRate read-count pin counts in-process instead of through evictable pg_stat_statements; the test rig recipe preloads it - #4697

Merged
erikdarlingdata merged 5 commits into
devfrom
fix/darling-waitrate-readcount-isolation
Sep 29, 2026
Merged

erikdarlingdata merged 5 commits into
devfrom
fix/darling-waitrate-readcount-isolation

Conversation

@erikdarlingdata

@erikdarlingdata erikdarlingdata commented Sep 29, 2026 •

Copy link
Copy Markdown
Owner

No issue was filed for this. WaitRateTileReadCountLiveTests.Waits_DetectAnomaliesAsync_ReadsWaitRateTileWindowSqlOnce_NotTwice passes alone on a fresh database and failed once in the full-suite run of #4681; nobody recorded the count it read.

Why

The test pins that PgAnomalyDetector reads the wait-rate window SQL once per pass, and it counted those reads through pg_stat_statements. That view is one cluster-wide table of pg_stat_statements.max = 5000 entries. Every parallel class that replays the migrations into its own scratch database refills it within seconds (utility tracking is on, so each DDL statement is an entry). Each time it is full it evicts the 250 lowest-usage entries, oldest once-called statements first. Once the test's entry is evicted the count reads 0, so the pin can fail with the product doing nothing wrong.

The local PostgreSQL test-rig recipe also listed shared_preload_libraries = 'timescaledb', while CI's darling-pg job (the "Initialize and start throwaway PostgreSQL" step in build.yml) writes 'timescaledb,pg_stat_statements'. A rig without it skips this test instead of running it.

What changes

  • WaitRateTileReadCountLiveTests counts the window reads in-process. An ActivityListener on Npgsql's Npgsql ActivitySource counts the commands run against this test's own scratch database (its name is unique to the test) whose text carries the window SQL's fragments (peak_ms_per_sec, v_wait_stats). Tags are matched by value, not by name, the way SharedBaselineCacheTests.CaptureAsync already finds command text, because Npgsql's attribute names have changed between majors.
  • A control command through the same data source must be counted exactly once before the window count is trusted, so a renamed tag fails loudly with a reason instead of reading a silent 0.
  • Assert.Equal(1, calls) is unchanged. No retry, no wider tolerance, no skip added.
  • Removed because nothing reads pg_stat_statements any more: the shared_preload_libraries skip, CREATE EXTENSION, the per-database pg_stat_statements_reset, and the database-oid lookup.
  • Every read on this path goes through the test's own NpgsqlDataSource: PgAnomalyDetector (10 sites) and PgBaselineProvider (1 site) open connections only through _postgres.OpenConnectionAsync, and nothing in PerformanceMonitor.Darling.Analysis calls NpgsqlDataSource.Create, NpgsqlDataSourceBuilder or new NpgsqlConnection. The database-name filter would also count a read through a second data source.
  • The local PostgreSQL test-rig recipe now preloads pg_stat_statements beside timescaledb, as CI's darling-pg job does, and says why.

Measured before the change (local PostgreSQL 18.6, UTC, pg_stat_statements.max = 5000, track_utility on)

Two temporary copies of the old test logged calls and pg_stat_statements_info.dealloc (before, right after the detector, after the count), run with the heavy scratch-database classes (FrozenRollupLiveTests, PgDeadlockRemaskTests, RollupBackfillLiveTests, PgSettingScrubLiveTests, FleetSweepStoreLivePostgresTests, ServerWatermarkCacheRunnerLiveTests, QueryStoreCorrectedRollupLiveTests, JobHistoryWatermarkEpochLiveTests) and, for the last two rows, a second process running eight more heavy classes. The copies are not committed.

variant calls dealloc before / mid / after the window entry
old test alone 1 9 / - / 9 present, calls 1
old test, mixed run 1 1 33 / - / 33 present, calls 1
old test, mixed run 2 (two processes) 1 326 / 326 / 326 present, calls 1
same test, 15 s pause between the detector and the count, same load 0 326 / 326 / 370 present at mid (calls 1), gone after
  • The seeded rows were intact (12) at every step and no entry had NULL query text, so the 0 is eviction of the entry, not a lost seed or a lost text.
  • The flood is about 3 deallocs a second on this machine (261 in a 100 s mixed run), and each dealloc frees 250 of the 5000 slots.
  • I did not reproduce the natural failure in three attempts: a fresh entry has the highest usage among once-called statements, so it survives until roughly twenty deallocs have passed. A stall between the detector's read and the count (a starved thread pool, a GC pause on a loaded runner) is enough to let the flood evict it, and the pause row shows exactly that: 0 with dealloc rising.
  • No run observed calls = 2, so there is no sign of a double read in the product.

Test plan

  • Fixed test alone on the fresh database: passes (1 window read, control counted once).
  • Fixed test with the same heavy classes and the second process: 103 tests, 0 failed in the main process, 41 and 0 failed in the second; dealloc rose 654 to 1034 during the run. A temporary copy of the fixed test with a 15 s pause before the count was in that run and passed (the old shape read 0 under the same pause).
  • Fails on the old double-read shape: I planted a second WaitRateTileWindowSql command in DetectWaitAnomalies, and the test failed with Expected: 1, Actual: 2. Reverted with git restore; the product file is not in this diff.
  • Full Darling.Tests suite once, on a fresh darlingtest, before the last commit: Total 16750, Failed 2, Skipped 64, Not Run 1, 909 s. Both failures are listed below.
  • After the last commit: LivePostgresCollectionHygieneTests, WaitRateTileReadCountLiveTests, TrendPayloadBudgetLiveTests, LiveCleanupConversionRatchetTests and the doc-comment census, on a fresh database: 105 tests, 1 failed (the trend test below).
  • A second full-suite pass after the last commit: not run, it did not fit.

Failures in the full run:

  1. LivePostgresCollectionHygieneTests.EveryClassUsingTheSharedStore_IsSerializedOrDocumentsWhyNot: caused by this change. The longer class comment pushed the #1776 own-store marker out of the census's 25-line lookback above the class. Fixed in the second commit by moving the marker to the comment's last paragraph; it passes now.
  2. TrendPayloadBudgetLiveTests.EveryDefaultAnswer_StaysNearTheBudget_AndTheLargestAnswerStaysUnderTheCap: get_pg_io_trend over 72h answered a error ... Exception while reading from stream. Not caused by this change: it fails the same way (same message, 42 s) alone on a fresh database, and again on an unmodified build of origin/dev on this machine, while dev's own CI run for the same base commit (872e7c9) passes it. The cause on this machine was not investigated.

CHANGELOG

None: test-only change.

Worth a second look

  • Three other tests count through the same database-scoped pg_stat_statements read and share the eviction exposure: OverviewFleetHealthSingleFlightLiveTests (line 132), QueryStoreTrendRoutingCachedLiveTests (line 139) and StoreSizeCacheLiveTests (line 94). Not converted here.
  • The listener is process-wide while the test runs (two listeners, disposed at the end of the test); it only reads tags and counts, and matches on the scratch database's name.
  • "Not Run: 1" in the suite totals is the runner's count; I did not identify which test it is.

…ling-pg job does

The lane-orders rig recipe wrote shared_preload_libraries = 'timescaledb' only. The darling-pg job in
.github/workflows/build.yml writes 'timescaledb,pg_stat_statements'. A rig without pg_stat_statements
skips WaitRateTileReadCountLiveTests (and the other live tests that count statements through it)
instead of running them, so a green local run proves less than CI's.
…gh cluster-wide pg_stat_statements

The test passed alone and failed once in a full-suite run. pg_stat_statements is one cluster-wide table of
5000 entries that the parallel scratch-database classes refill within seconds, evicting the oldest
once-called statements first. Measured: the window entry was present with calls = 1 right after the
detector and gone 15 s later (dealloc 326 to 370), so the count read 0 with the seed intact.

The count now comes from an ActivityListener on Npgsql's ActivitySource, scoped to the test's own scratch
database by name and to the window SQL's fragments, with a control command that proves the listener sees
both before the count is trusted. Assert.Equal(1, calls) is unchanged. The preload skip, CREATE EXTENSION,
the reset and the oid helper are gone because nothing reads pg_stat_statements any more.
… census's 25-line lookback

The rewritten class comment pushed the #1776 own-store marker more than 25 lines above the class
declaration, so LivePostgresCollectionHygieneTests.EveryClassUsingTheSharedStore_IsSerializedOrDocumentsWhyNot
failed in the full-suite run. The marker now sits in the last paragraph of the comment.
@erikdarlingdata erikdarlingdata changed the title Darling.Tests: the WaitRate read-count pin stops counting through cluster-wide pg_stat_statements; the rig recipe preloads it Darling.Tests: the WaitRate read-count pin counts in-process instead of through evictable pg_stat_statements; the test rig recipe preloads it Sep 29, 2026
…ents

WaitRateTileReadCountLiveTests no longer reads pg_stat_statements, so it is the
wrong example for the note that a rig without the preload skips the tests that
count statements through it. StoreSizeCacheLiveTests still counts its statements
there and skips when the library is not preloaded.
@erikdarlingdata
erikdarlingdata marked this pull request as ready for review September 29, 2026 01:25
@erikdarlingdata
erikdarlingdata merged commit 326f901 into dev Sep 29, 2026
15 of 16 checks passed
@erikdarlingdata
erikdarlingdata deleted the fix/darling-waitrate-readcount-isolation branch September 29, 2026 01:36
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