The newest-snapshot block-count test no longer fails between 00:00 and 04:00 UTC (#5608)

[erikdarlingdata]

Fixes #5608.

SECTION: None
ENTRY: (test-only change; no CHANGELOG entry)

Why

The newest-snapshot block-count test seeded four hours of perfmon rows ending at the wall clock and compared the blocks the old and new reads touch. Its 3x margin held at midday and failed at 00:50 UTC (perfmon old=264 new=120), so every pull request whose Darling PG shard ran between 00:00 and 04:00 UTC failed.

Diagnosis, measured on a throwaway rig by pinning the test's end time (perfmon blocks, old read 264 in every layout):

end time (UTC)	new read blocks	3x check
00:10	18	pass
00:20	13	pass
00:30	47	pass
00:40	84	pass (limit 88)
00:50	120	FAIL
00:55	138	FAIL
01:13	57	pass
03:50	78	pass
05:50, 09:50, 12:00, 15:50, 20:50, 23:50	78 each	pass

So the cause is the chunk boundary, but not as "two chunks cost twice": raw chunks are one UTC day. When the window sits wholly in one chunk the new read costs 78 blocks at every hour. When it straddles midnight the newest chunk holds only the rows since 00:00, and the 60 rows that share the newest timestamp sit in a different physical order. The newest read walks back through those rows until it meets each counter ("Rows Removed by Filter" was 39 to 41 per counter at 00:50, 15 to 17 at 01:13), so the count swings between 13 and 138. That is a property of the seed (60 tied rows scrambled by the insert), bounded by one snapshot's rows, not a worse shipped read: the product read never touches more than the newest snapshot's rows per counter. No product change.

What changes

• New LiveClock test helper (Darling/Darling.Tests/LiveClock.cs): AnchoredEnd() is a fixed point inside one chunk (22:00 UTC on the previous UTC day), and Now() is the clock with a test-only override, the environment variable DARLING_TEST_CLOCK_UTC, read only by tests. The machine clock is never touched.
• NewestSnapshotReadsLiveTests: every window ends at LiveClock.AnchoredEnd(). The guard is unchanged.
• PlanRegressionDailyReadShapeLiveTests and QueryStoreIntervalFloorWarmUpTests: their wall-clock reads go through LiveClock.Now() so a run can be proved at any hour (verdicts below).
• New census LiveClockCensusTests (Guard stage, per-file allow list with a reason per entry, stale entries fail, anti-vacuity floor): a live test that reads a plan's Shared Hit Blocks / Shared Read Blocks and reads the wall clock without LiveClock. fails. The allow list is empty.
• Census second rule (e1): a live file that uses EXPLAIN, show_chunks, timescaledb_information.chunks, compress_chunk or ChunkAppend and reads the wall clock in code without LiveClock. fails unless it is in s_allowedPlanShape with a reason. Stale entries fail; a floor of 20 files keeps the scan from going vacuous.

Audit (W1)

Files that are live, read a wall clock and look at a plan or chunk catalog: about 77. Audited so far, the ones that assert on block counts:

file	verdict
NewestSnapshotReadsLiveTests	the defect; anchored
PlanRegressionDailyReadShapeLiveTests	counts blocks, but seeds whole UTC days relative to today's date and asserts partitions scanned; no hour-of-day dependence. Clock moved to LiveClock and run at 00:30Z and 12:00Z
QueryStoreIntervalFloorWarmUpTests	counts blocks; rows land in the single legacy table (MINVALUE..MAXVALUE), so no chunk or day boundary applies. Clock moved to LiveClock and run at 00:30Z and 12:00Z
QueryStoreBackfillCandidateLiveTests	already uses a fixed anchor
JobHistoryWatermarkEpochLiveTests	see Audit e1 (now on LiveClock)
PgTargetKnobsTests, SharedBaselineCacheTests	false matches (a setting named shared_buffers, a comment)
PerfmonRegroupLiveTests and support	see Audit e2

Audit e1

Method: every file on the e1 list was read at its clock sites. Where the test hands its "now" to the product read, it now takes it from LiveClock; where the product reads the real clock itself (SQL now(), DateTime.UtcNow in product code) the test stays on the real clock and the assertion is checked to hold for any chunk layout. Each converted class ran with DARLING_TEST_CLOCK_UTC at 00:30Z, at 12:00Z and unset (the real clock was 02:00 to 02:40 UTC, inside the failing window), three runs at once on separate databases. A first pass of the same classes at the real clock, before any change, passed everywhere.

File	Verdict	Change
AnomalyObjectStatsLatestSnapshotsLiveTests	no layout dependence: no time predicate, plan names an index	none; census allow entry
BlockingListPlanFlagsLivePostgresTests	EXPLAIN window passed by the test; the tool reads its own window from the real clock	EXPLAIN test on LiveClock.Now; the two tool tests stay on the real clock (they failed under 12:00Z)
CaggGroupIndexDropUpgradeLiveTests	clock is only a stopwatch	none; allow entry
CaptureDownChunkOrderTests	newest-chunk plan: layout-sensitive for a minute after midnight	LiveClock.AnchoredEnd()
CollectionGapAtStartTests	35-day seed, access-path plan	none; allow entry
CollectionHealthAggregateTests	seeds with SQL now(); assertions hold for any layout	none; allow entry
CollectionHealthKeyedLookupParityTests	parity of two reads over a passed window	LiveClock.Now
CollectionHistoryAuditTests	no clock read	none
CollectionLogSegmentByLiveTests	product compresses by SQL now(); per-chunk setting is layout-free	none; allow entry
DailySummaryReadShapeTests	day-aligned seed, window passed to the read	LiveClock.Now
DarlingAgStatesReaderLiveEqualityTests	now passed to every reader	LiveClock.Now
DarlingDeltaSeederTests	SeedFromStoreAsync reads the real clock; two tests failed under 00:30Z	tried, reverted; allow entry
DarlingFleetReaderTests (live class)	now passed to the reader	LiveClock.Now
DarlingModuleMapGroupedSourceLiveTests	daily refresh reads now(); failed under 12:00Z	tried, reverted; allow entry
DarlingPgIndexBloatCoverageLivePostgresTests	now passed to the read	LiveClock.Now
DarlingRetentionTests	now passed to the retention calls	LiveClock.Now
DarlingSecuritySplitLiveTests	no direct clock read	none
DarlingSelfAlertTests	live region seeds and passes now	live region on LiveClock.Now
DarlingStoreUpgradeTests	clock is a 30 second polling deadline	none; allow entry
DarlingWatermarkFloorPlanShapeLiveTests, ...ScanBoundLiveTests, ...IndexEquivalenceLiveTests	floor and chunk slack are read against a plan	LiveClock.AnchoredEnd()
DeadlockDuplicateCleanupLiveTests	no direct clock read	none
EventWindowedReadsAreBoundedLivePostgresTests, FleetReadsAreBoundedByTheFleetTests	now passed to the reads	LiveClock.Now
ForcePlanFailuresAccessPathTests	now passed to the read	LiveClock.Now (see Not done)
FrozenRollupLiveTests	now passed to repair and read; one freeze-verdict test reads the session clock (failed under 12:00Z)	LiveClock.Now, except that one test
JobHistoryPerServerTopNLiveTests, LatestCollectorOutcomePlanTests, LatestValueLookbackTests, MaterializationHole{Probe,Repair,ScanShape}Tests	now or a day-aligned seed passed to the read	LiveClock.Now
LatestCpuReadShapeTests	trap predicate compares to the store's now() (failed under 00:30Z)	LiveClock.Now everywhere except that one seed

Not on either list, found by the census scan: JobHistoryWatermarkEpochLiveTests (now passed to the product; converted to LiveClock.Now) and PerfmonRegroupLiveTests (only a poll deadline; e2 checked it, see Audit e2).

Census: the e2 files were put on s_allowedPlanShape with the reason "e2 audits". After merging e2's push I dropped the eight entries for the files it converted. 22 "e2 audits" entries remain, one per file e2 left on the real clock; each should be replaced with e2's reason from the Audit e2 table (not done, see below). RED-plant at this head: a planted live file with EXPLAIN and DateTime.UtcNow made the new test fail and name it. The class is new on this branch, so there is no origin/dev copy to run; the same regexes over origin/dev's test folder match every such file because dev has no helper.

Totals (final code except the merge, one run each; every class Failed: 0 unless noted):

Class group	00:30Z	12:00Z	unset
26 converted live classes (BlockingList ... FrozenRollup)	Failed 0 except ForcePlanFailuresAccessPathTests (Total 4, Failed 1)	Failed 0	Failed 0
LiveClockCensusTests	not run	not run	Total 4, Failed 0 (before the merge with e2)

Largest classes: DarlingSelfAlertTests Total 294, FrozenRollupLiveTests 31, DarlingRetentionTests 48.

Not run (the lane hit its wall limit): the *Census* and *Ratchet* classes other than LiveClockCensusTests, -trait Stage=Guard -failSkips, and LiveClockCensusTests after the merge with e2's push and the eight-entry removal. The merge was clean, but the census was last run before it. The rig on port 5607 may still be running.

Not done:

• ForcePlanFailuresAccessPathTests, TheShippedRead_PlansAsAnIndexOnlyScanOnTheCoveringIndex_AgainstDevPostgres, passed under 00:30Z in the first sweep and failed under 00:30Z on a fresh database in the last one; it passed at 12:00Z and unset. It also failed in all three settings when anchored with AnchoredEnd(), which is why it is on LiveClock.Now. Not diagnosed; CI runs it unset, where it passes. A successor should find what the index-only-scan plan needs (visibility map or the chunk the rows land in).
• Replace the 22 "e2 audits" entries with e2's reasons, and run the census once more.

Audit e2

Second half of the live files that read a wall clock and use EXPLAIN or the chunk catalog (34 files). The real clock was 01:47 to 02:30 UTC while I worked, so every class below also ran inside the 00:00 to 04:00 window for real, and the converted ones were also run with the override at 00:30Z and 12:00Z.

Result: 8 files moved to LiveClock.Now() (the test hands that time to the product as the window end), 26 left alone with the reason below. No file needed AnchoredEnd(): none has an assertion that moves with the chunk or day layout.

file	verdict	change
ParameterSensitiveDrillDownTextLiveTests	4 hour window, counts rows fetched from the text dimension (not blocks); window end goes to the product through the analysis context	clock via LiveClock
TopCpuQueriesTextLiveTests	same shape	clock via LiveClock
PlanRegressionDrillDownReuseLiveTests	counts rows read per plan node; period end goes to the product	clock via LiveClock
TopTextLookupPlanLiveTests	seeds 12 hourly rows ending now, so it crosses midnight for half the day; asserts raw rows read per ranked key, which held at 00:30Z, 12:00Z and unset	clock via LiveClock
PgTargetConfigSnapshotBoundTests	ten day hourly seed; chunk-scan asserts are written as ranges (fallback at least 11, day 1 to 4), so they hold for any layout; end goes to the product	clock via LiveClock
RawChunkIntervalReconcilerLiveTests	one row per day lands in its own 24 hour chunk and fillers are exactly 6 hours apart, so chunk counts do not move; the reconcile time goes to the product	clock via LiveClock
RollupBackfillLiveTests	day-sized windows, aligned to the date	clock via LiveClock
RollupFloorCacheLiveTests	same	clock via LiveClock (the 30 second poll deadline stays on the real clock)
PerfmonRegroupLiveSupport, PerfmonRegroupLiveTests, PerfmonRegroupTimingLiveTests	#5579's defect, checked. Every seed is a whole UTC day taken from the run start date, the compress reach is read from the database clock, the policy test already seeds three to five days back (the two-days-back version was the 00:00 to 03:00 failure), and the reach test counts chunks from the database clock. Ran 23 tests at 01:47 to 01:50 UTC: Total 23, Failed 0. The override cannot reach the database clock, so the file stays on the real clock	none
PgTargetSeqScanTests	no EXPLAIN or chunks (the "Seq Scan" is planted plan JSON); the analyze tool rejects an end ahead of the real clock, which the 12:00Z override proved (it failed at 01:54 UTC), so it must stay on the real clock	none
PgServerConfigToolBoundTests	same range asserts as the config snapshot test above, but the reader's own read takes the real clock	none
ServerListAndSummaryPlanShapeTests	newest row one minute ago; asserts at most two chunks visited, true on either side of midnight; no time goes to the product	none
StoreMetricsLatestSkipScanLiveTests	plain table, asserts index names	none
QueryStoreBackfillCutChunkLiveTests	fixed June dates; the one test that follows the real clock waits until the floor is 3 minutes clear of a boundary	none
QueryStoreTopLiteralEndStraddleLiveTests, QueryStoreIntervalWideGridLiveTests, QueryStoreTopMcpLiveTests	fixed 15 September window; the clock is only a write stamp	none
QueryStoreIntervalWideBelowFloorLiveTests	anchored to the date (6 days back); the clock is only a stamp	none
QueryStoreBackgroundIndexesLiveTests	seeds from SQL now(), compares the same store before and after the indexes, so the layout is the same on both sides	none
QueryStoreIntervalPurgeRowCappedTests	plain tables, fixed dates for the plan asserts, whole day margins around the retention horizon	none
RawPurgeTriggerLiveTests, RawPurgeTriggerGateErrorTests, RawRetentionPurgeJobLiveTests, RawTablesLeaveCatalogSweepLiveTests	seed from the database clock one to ten days back; asserts are relative (chunks before > 0, after < before, equal before and after)	none
PlanRegressionDailyBuilderLiveTests, PlanRegressionDailyRungTests	fixed March dates on plain tables (including the block count); the one real-clock fact seeds five whole days back and its trigger reads the database clock; the Rung file only pins source text	none
StoreSelfMetricsTests, TimescaleSupportTests	seeds already placed at midday of a date (#1972); the clock is a stamp	none
PayloadDimensionLiveTests	dates 45 and 400 days back, mid-chunk; asserts on dimension rows	none
PgDeadlockRemaskTests	midday of a date or fixed dates	none
PgSettingScrubLiveTests, PgStatementTextScrubLiveTests	fixed 2026 days; now() is only a stamp	none
PgPlanCaptureLiveTests, PgPlanCaptureCsvLiveTests	clock is only the collection stamp; they need an external target and skip on this rig	none

Runs (rig on UTC, Total / Failed):

classes	00:30Z	12:00Z	unset
ParameterSensitiveDrillDownText, PgTargetConfigSnapshotBound (both classes), PlanRegressionDrillDownReuse, TopCpuQueriesText, TopTextLookupPlan (set of 6 classes, with PgTargetSeqScanTests included before I took it back out)	41 / 0	41 / 1 (PgTargetSeqScanTests, then reverted)	41 / 0
RollupBackfill, RollupFloorCache, RawChunkIntervalReconciler	22 / 0	22 / 0	22 / 0
the other 25 unchanged live classes, unset, at 01:57 to 02:02 UTC			183 / 0 (3 skipped: external target)
TimescaleSupportTests, PayloadDimensionLiveTests, StoreSelfMetricsTests, unset			135 / 0
PerfmonRegroupLiveTests and PerfmonRegroupTimingLiveTests, unset, 01:47 UTC			23 / 0
*Census*, *Ratchet*, LiveClockCensusTests			512 / 0
-trait Stage=Guard -failSkips			1446 / 0

0 build warnings.

Not done in this section:

• No RED-plant: nothing here was anchored with AnchoredEnd() and no assertion was changed, so there is no guard to plant against. The one-way proof that the override reaches the product is the PgTargetSeqScanTests failure at 12:00Z.
• LiveClockCensusTests is e1's. When e1 pushed nothing yet, so no "e2 audits" entries existed to replace. If e1 adds them, each of the 26 left-alone files above has its reason in this table and the entry can quote it.
• Full suite not run (CI decides).

Finish (lane f)

Head after this lane: 2641503 (one commit on top of 2848555). The branch was not merged with dev.

What I ran on the merged head, rig on UTC, 0 build warnings:

class	Total	Failed
LiveClockCensusTests	4	0
every *Census* class	499	0 (first run: 1, StatementCollectionCensusTests.ABlockingRingBufferOfAboutFourMegabytes_IsJudgedInTimeLinearInItsSize, a timing test in a file this branch does not touch; it passed alone, 46 / 0, and in a full *Census* rerun, 499 / 0)
every *Ratchet* class	15	0
-trait Stage=Guard -failSkips	1448	0
ForcePlanFailuresAccessPathTests	4	see below

What I fixed:

1. Census allow list: all 22 entries that said "e2 audits" now carry e2's own reason from its table above, plus one more: the PerfmonRegroupLiveTests.cs entry pointed at lane e2's audit, and it now states e2's verdict (whole UTC days from the run start date, the two-days-back seed that was Perfmon data is compressed per counter, so a one-counter trend reads only that counter's data (#5574) #5579's defect replaced by three to five days back, chunk counts from the database clock). No "e2 audits" or "lane e2" text remains in LiveClockCensusTests, and the E2Audits constant is gone. The stale-entry check passed with all of them, so none of the files stopped matching the rule.
2. ForcePlanFailuresAccessPathTests: see the verdict.

ForcePlanFailuresAccessPathTests verdict: a clock-mixing defect, not a layout defect, and now fixed.

• Before: at the 00:30Z override, five fresh databases, 5 of 5 runs failed (4 tests, 1 failed). At 12:00Z, 5 runs, 0 failed. The failure is Assert.Single(failures) on the product read (The collection was empty), which is after every plan assertion, so the plan check passed in all five.
• Cause: the test seeded from LiveClock.Now() and handed that to the EXPLAIN, but DarlingAlertReadAdapter.GetForcePlanFailuresAsync takes its two-hour window from the product's own DateTime.UtcNow and has no clock seam. With the override at 00:30Z and the real clock about two and a half hours later, the seed fell outside the product's window and the read came back empty. At 12:00Z the seed sat in the future of the real clock, and the window has no upper bound, so it passed. That also explains the earlier single failure, the earlier pass at 00:30Z (the real clock was then within two hours of it), and why AnchoredEnd() failed in all three settings (22:00 on the previous day is always more than two hours before the real clock).
• Fix: the seed goes back to DateTime.UtcNow, with a comment saying why. The plan assertions hold across a chunk boundary (the five 00:30Z runs passed all of them before the read), so no anchor is needed. The file moves to the census allow list with that reason.
• After: 00:30Z 5 runs, 12:00Z 5 runs, unset 2 runs, each 4 / 0 (no skips).
• RED-plant of the guard: with the covering index dropped after the migration and the pg_indexes asserts removed, the plan check fails (Assert.Contains() Failure: Sub-string not found on "Index Only Scan" / the index name; 4 / 1). Plant reverted, rebuilt, 4 / 0.

RED-plant of the census at origin/dev (5ac86ba): I copied LiveClock.cs and LiveClockCensusTests.cs from this head onto a clean origin/dev checkout in scratch, built (0 warnings), and ran LiveClockCensusTests: 4 total, 2 failed. Both rules fail: the block-counting rule and the plan/chunk-catalog rule together name 34 distinct live files (37 names across the two failures) that read the clock without LiveClock. The checkout is deleted.

Rig: removed. No full suite was run on this laptop; CI decides.

Not done

Nothing. Lane f finished both items left under "Not done" in Audit e1 (see Finish above).

Test plan

• NewestSnapshotReadsLiveTests with the clock override unset, at 00:30Z, 00:55Z and 12:00Z: Total 6, Failed 0 each
• RED-plant, perfmon read swapped for the pre-Analysis reads of the newest file I/O and perfmon rows read the whole window #5516 window-function shape: the block-count test fails at 00:30Z, 12:00Z and unset
• RED-plant, database-size read swapped for the pre-Analysis reads of the newest file I/O and perfmon rows read the whole window #5516 full read: fails at 00:30Z, 12:00Z and unset
• The pre-fix test body (wall-clock end) failed at 00:50 and 00:55 and passed at 12:00 on the same rig
• PlanRegressionDailyReadShapeLiveTests: Total 2, Failed 0 unset, at 00:30Z and at 12:00Z
• QueryStoreIntervalFloorWarmUpTests: Total 17, Failed 0 unset, at 00:30Z and at 12:00Z
• LiveClockCensusTests: Total 4, Failed 0 before the e2 merge; RED-plant (wall-clock end put back, and a planted EXPLAIN plus clock file) fails naming that file
• *Census*: Total 497, Failed 0; *Ratchet*: Total 15, Failed 0; -trait Stage=Guard -failSkips: Total 1446, Failed 0 (these three were run by e2 on its tree, not on the merged tree)
• 0 build warnings
• LiveClockCensusTests and the Census, Ratchet and Guard sets on the merged head (run by lane f, see Finish above)
• Full suite not run (CI decides)

Double-check

The anchor is the previous UTC day at 22:00, so the data is a day old; no test here depends on recency. LiveClock.Now() returns an unspecified-kind time; converted tests wrap it as the kind they used before. Check ForcePlanFailuresAccessPathTests at 00:30Z (see Audit e1) and run the census on the merged head before readying.