Order the latest collector outcome read by collection_time first (#4974)

[erikdarlingdata]

Change

DarlingRuntimePrecondition.LatestCollectorOutcomeSql now reads ORDER BY collection_time DESC, log_id DESC LIMIT 1 instead of ORDER BY log_id DESC LIMIT 1. collection_log has no index on log_id, so the old order sorted every retained row for the (server, collector) pair. The existing idx_collection_log_watermark (server_id, collector_name, collection_time DESC) serves the first sort key, so the read walks chunks newest-first and stops in the first chunk that holds a row for the pair; no new index. log_id DESC stays as a tie-break that only makes the order deterministic (two runs of one server and collector don't share a microsecond in practice); it costs a sort of the pair's rows in each chunk visited. A collector with no row in the newest chunk (a daily collector, or one that never ran) walks back through older, compressed chunks. The doc comment states the current reason.

Production measurement (EXPLAIN (ANALYZE, BUFFERS), 43-server store, one server)

shape	deadlocks (sparse)	wait_stats (busy)	collector never run
old: ORDER BY log_id DESC	576.7 ms	349.7 ms	n/a
new: ORDER BY collection_time DESC, log_id DESC	0.47 ms	0.28 ms	16.4 ms

Both shapes returned the same row for both collectors.

Correctness

Can a later-inserted row for one (server, collector) carry an earlier collection_time? Not in the normal write path. DarlingObservability.LogCollectionAsync stamps collection_time with DateTime.UtcNow at the insert, after the run ends, and log_id comes from the process-wide monotonic CollectionIdGenerator, so both rise together. Exceptions: a wall-clock step backwards (NTP, VM migration), or a restart while the clock reads earlier than the previous process's start. Neither order gives the latest run in both cases. The trade this change takes: after the wall clock steps back, this read can return a run from before the step, for as long as the step lasts (the old order could instead stay on a previous process's last row after such a restart). The sibling CollectorLastRunSql and the self-alert reads also order by time first; the collection-signals reads use the same time-then-id order.

Tests

• LatestCollectorOutcomeOrderShapeTests (source pin): RED on origin/dev (Total: 1, Failed: 1), GREEN after.
• LatestCollectorOutcomeOrderLiveTests (through StatusAsync): newest-by-time wins over older-chunk rows with higher ids, and the timestamp tie goes to the higher log_id in both orders. RED on origin/dev for the newest-by-time case (Total: 2, Failed: 1). GREEN after: Total: 2, Failed: 0. The old SQL returns the same row on most seeds; the source pin is the RED that matters.
• LatestCollectorOutcomePlanTests (live): a scratch store seeded with exactly eight 1-day collection_log chunks aligned to the UTC day (asserted with show_chunks, so the result does not depend on the time of day the test runs), EXPLAIN (ANALYZE) of the shipped statement, asserting at most one chunk executes. RED under a temporary revert to ORDER BY log_id DESC ("more than one chunk executed").
• GREEN, same run: CollectorRuntimePreconditionTests 46, CollectionSignalsChunkOrderTests 3, CaptureDownChunkOrderTests 3, TsqlConventionGuardTests 14, DocCommentHygieneTests 77, RepoFileAdoptionTests 2, CommandDeadlineScannerAdoptionTests 1; all 0 failed.
• Build (Darling.Tests, Release): 0 warnings, 0 errors.
• Greps: LatestCollectorOutcomeSql|ORDER BY log_id over Darling.Tests and Lite.Tests: only doc-comment hits in CollectionSignalsChunkOrderTests and CaptureDownChunkOrderTests; no assertion on the old text. Lite's own ORDER BY log_id reads are a separate store and are untouched.

Closes #4974

CHANGELOG

SECTION: Fixed
ENTRY: - Faster "latest collector outcome" check on MCP reads ([#4975]) - the read that tells an empty answer apart from a collector problem no longer sorts a server's whole collection history, cutting it from hundreds of milliseconds to under one on a large store.
REF: [#4975]: #4975

[erikdarlingdata]

Claude posting for Erik Darling

Read-only review of 116c1ac. I did not run the tests, and I did not connect to PostgreSQL.

The change is correct. Inside one service process, log_id and collection_time rise together for one server and one collector. So on the normal path, the new order returns the same row as the old order. Two items need a change: two doc comments that still describe the old order, and a tie test that does not vary the insertion order. The other four comments are notes.

Claim in the PR	Grade	Evidence
collection_log has no index on log_id	VERIFIED	PgMigrations.cs:2750-2764, PgMigrations.cs:2682-2683
The old order sorted every retained row for the pair	VERIFIED as plan reasoning	No log_id index. The same cause is measured at DarlingSelfAlertEvaluator.cs:7373-7378.
idx_collection_log_watermark serves the new order	VERIFIED for the WHERE and the first sort key	PgMigrations.cs:2682-2683. log_id is not in the index.
The read is served from the newest chunk	UNVERIFIED	No plan test. It is true only when the pair has a row in the newest chunk. See the note on DarlingRuntimePrecondition.cs line 103.
collection_time is DateTime.UtcNow at the insert, after the run ends	VERIFIED	DarlingObservability.cs:263-271, DarlingWorker.cs:12379-12383
log_id and collection_time rise together	VERIFIED inside one process	CollectionIdGenerator.cs:22-27, DarlingObservability.cs:266, DarlingObservability.cs:271
After a clock step back, the newest row by time is the right latest outcome	REFUTED for a step without a restart. Across a restart, it is the better order.	See the note on DarlingRuntimePrecondition.cs lines 95-96.
A timestamp tie goes to the higher log_id	VERIFIED as SQL. The tie cannot happen for one pair.	DarlingRuntimePrecondition.cs:103, DarlingSelfAlertEvaluator.cs:7482-7486
CollectorLastRunSql uses the same order	REFUTED	It has no log_id tiebreak: DarlingRuntimePrecondition.cs:75
The collection-signals reads use the same order	VERIFIED	DarlingSelfAlertEvaluator.cs:7415, DarlingSelfAlertEvaluator.cs:7417
The tie test covers both id orders	REFUTED	Both halves insert id 200 before id 300: LatestCollectorOutcomeOrderTests.cs:93-94, LatestCollectorOutcomeOrderTests.cs:102-103
A test store has too few chunks for a plan test	REFUTED	CaptureDownChunkOrderTests.cs:94-175
Lite's reads are untouched	VERIFIED	But the Lite doc now claims to mirror this read. See the comment on DarlingRuntimePrecondition.cs line 92.
RED and GREEN counts, build result, production timings, same row returned	UNVERIFIED	I did not run anything.

A static reading agrees with the reported RED. Under ORDER BY log_id DESC, the first live test gets the 120-day-old PERMISSIONS row (id 300) and fails. The tie test passes under that order.

Callers. Only ReadLatestOutcomeAsync (DarlingRuntimePrecondition.cs:236) runs LatestCollectorOutcomeSql, and only StatusAsync calls it. StatusAsync has 17 production call sites in 14 MCP tool files. All of them run on the empty-result path after the capability check. Each one passes one fixed collector name and uses only the returned envelope. Call sites: DarlingMcpBlockingTools.cs:332 and :555, DarlingMcpDataTools.cs:1082, DarlingMcpJobTools.cs:53, DarlingMcpPgIndexTools.cs:101 and :432, DarlingMcpLongQueryTools.cs:65, DarlingMcpPgPlanTools.cs:193 and :292, DarlingMcpPgLogEventTools.cs:92, DarlingMcpPgPredicateTools.cs:70, DarlingMcpPgKernelStatsTools.cs:78, DarlingMcpPgDeadlockTools.cs:117, DarlingMcpPgServerStateTools.cs:68, DarlingMcpPgWaitSamplingTools.cs:104, DarlingMcpPgStatementTools.cs:73, DarlingMcpQueryStoreClutterTools.cs:135. Each one wants the latest run, so the change affects them only in the clock-step case.

NULL collection_time cannot occur. The column is NOT NULL (PgMigrations.cs:2755), and the later migrations only add columns.

[erikdarlingdata]

Claude posting for Erik Darling

Second review of the delta 116c1acc2..9af2041bf (4 files). I found no defects. There are three notes inline, and I recommend the one-line seed change in the second note. I read the code only. I did not run a test or look at a plan. So the author's RED runs stay unverified, and I graded each mechanism from the code.

Lite's claim: VERIFIED

Doc line: Lite/Services/LocalDataService.RuntimePrecondition.cs:28.

• RemoteCollectorService.cs:635 sets startTime = DateTime.UtcNow before the run starts. Line 914 passes it to LogCollectionAsync, which writes it as collection_time (line 943).
• The same insert takes log_id from GenerateCollectionId() (line 939), which forwards to the process counter in CollectionIdGenerator.cs:22-27. This is the only collection_log insert in Lite.
• So in Lite, the id order is the order in which runs finished. Darling's time order means the same thing, because Darling stamps collection_time with DateTime.UtcNow at log time (DarlingObservability.cs:271). Lite's SQL still orders by log_id DESC (line 41).

Tie test: VERIFIED

Lines: LatestCollectorOutcomeOrderTests.cs:92-106.

• Half 1 needs id 300, the row inserted last (PERMISSIONS, so a message). Half 2 needs id 300, the row inserted first (SUCCESS, so null, because CollectionOutcomeMessage returns null for SUCCESS).
• Without the tiebreak, tied rows come back in heap order. If the first insert wins, half 1 fails. If the last insert wins, half 2 fails.
• With log_id ASC, half 1 picks 200 (SUCCESS), so Assert.NotNull fails.

Plan test

• RED on ORDER BY log_id DESC: VERIFIED from the code. The statement has no time predicate (DarlingRuntimePrecondition.cs:104-110), so nothing excludes a chunk. A log_id order needs a top-N sort over every chunk, so every seeded chunk executes, and executed.Count <= 1 (line 89) fails. The failure text that the author reports is the line 90 message, so the reverted plan had no Chunks Visited line and took the chunk-scan branch.
• What it reads: the CI runtime is PostgreSQL 18.6 with TimescaleDB 2.30.1 (Darling/tools/fetch-pg-runtime.ps1:104-108). When the plan has a DeferredChunkAppend, the test reads its Chunks Visited: N count, which the earlier test measured on 2.30.1 (CaptureDownChunkOrderTests.cs:149-153). Otherwise it reads the chunk scan lines (PlanChunkScans.cs:29) and never executed. I did not see which branch the shipped plan takes on CI.
• Vacuous passes: a constant time predicate, constraint exclusion and a pushed-down LIMIT do not apply, because the statement has no time predicate. The newest chunk wins by design, because ChunkAppend walks the chunks in time order. The notes cover two gaps. The Chunks Visited branch does not assert the chunk count, and the seed is not aligned to the UTC day.

Docs

• CollectorLastRunSql (line 63): VERIFIED. That read has no tiebreak (line 75), and LatestCollectorOutcomeSql keeps one (line 109).
• "serves that first key": VERIFIED (PgMigrations.cs:2682-2683). No index carries log_id: VERIFIED.
• The clock-step trade: VERIFIED. collection_time is the wall clock at log time, and log_id is a process counter. After the clock steps back N minutes, new rows sort below the old ones for N minutes.
• "do not share a microsecond in practice": VERIFIED. There is one row per run, stamped at log time. The note at DarlingSelfAlertEvaluator.cs:7484-7486 says the same.
• Older chunks "are compressed": VERIFIED for a store whose policy has run (CompressAfterDays = 1, TimescaleSupport.cs:81).
• "stops at the first row" and "a sort of the pair's rows in each chunk": UNVERIFIED. See the inline note on these lines.
• The unused using: VERIFIED removed. Nothing in that file uses PerformanceMonitor.Collectors.