The lock-wait fact counts each logged line once and each lock wait once

[erikdarlingdata]

What was wrong

PgTargetLockWaitEventsSql, the PostgreSQL target analysis's lock-wait fact, counted RAW collect.pg_log_events rows. It computed still_waiting as COUNT(*) FILTER (WHERE message LIKE 'process % still waiting for %'), documented as "one per wait", along with lines, the max/sum of "after N ms", and the top relation and fingerprint. Two things inflate those numbers.

1. One logged line is stored more than once.
   • No unique key: pg_log_events has no unique key, and only a non-unique (server_id, collection_time) index.
   • Re-reads by design: the resumed read deliberately re-reads an overlap. That's why DarlingPgLogEventReader dedupes with DISTINCT ON (raw_line_hash).
   • Measured on a production monitoring store (50 Aurora/RDS clusters, the last 7 days):
     • 10,854 of 863,728 distinct lines (1.26%) were stored more than once, up to 3 times;
     • re-sightings arrived up to 3,504 s after the first;
     • 452 re-sightings crossed an hour boundary.
   • The self-hosted transport keeps a line in its 1 MiB overlap until 1 MiB of newer log is written, which can take much longer on a quiet log.
2. One lock wait can write several "still waiting" lines. PostgreSQL 18's ProcSleep (src/backend/storage/lmgr/proc.c, REL_18_STABLE) logs process %d still waiting for %s on %s after %ld.%03d ms on every latch wakeup while the backend still waits, once the first deadlock check has run.

The same store had no lock_wait rows in that week, so there is no field number for the inflation. The fix rests on the code reading and the measured duplicate rate.

What changed

Only PgTargetLockWaitEventsSql changes. Its output columns, their order, the looked CTE and the collection_time window are all unchanged: "an event is in the window when it was COLLECTED in it".

• Each stored line counts once, in the window of its first sighting.

  • in_window keeps one row per distinct raw_line_hash collected in the window.
  • first_seen drops a line that an earlier pass already stored. A line is never collected before it occurred, so an earlier sighting can only lie in [occurred_at, $2). That range is bounded by the line's own time, with no fixed lookback, so it's exact however late the re-sighting comes. A NULL occurred_at searches all history.

• Each lock wait counts once, at the line that opens it. waits keeps a "still waiting" line only when no EARLIER line of the same wait is stored. An earlier line of the same wait means:

  • the same pid (the one the message names);
  • the same lock text;
  • a strictly smaller "after N ms";
  • an occurred_at within [L.occurred_at − (N + 1 s), L.occurred_at];
  • collected no later than the candidate's own first sighting. An earlier line of the same wait is read before it, in the same pass or an earlier one.

  A backend waits on one lock at a time, so the probe is bounded by the line's own N. The 1 s pad covers whole-second %t stamps. Two separate waits by one backend count twice. A line with no parsable lock text, duration or time counts as its own wait.

• What the columns mean now:

  • still_waiting (the fact's wait_events, and so wait_events_per_hour) is the count of WAITS, as the fact's metadata always described it;
  • acquired, deadlocks, lines, max_wait_ms, acquired_wait_ms and last_event_at are over the distinct lines first sighted in the window;
  • top_relation and top_fingerprint weigh each wait once, at its opener.

• Residuals, stated in the constant's doc:

  • Clock skew: if the target's clock runs ahead of the store's, the "never collected before it occurred" bound fails. DarlingPgLogEventReader makes the same assumption, and both are left as they are.
  • Fast re-waits: a re-wait by the same backend on the same lock text that starts within one second after the previous wait's opening line folds into it, however that wait ended (that previous wait then lasted under deadlock_timeout plus one second). A pin states this limitation.
  • Late collection of an earlier line: a wait whose earlier line was collected only after the candidate's first sighting is counted at its first line collected in the window. That needs out-of-order collection, which a single file's read doesn't produce.

Wording fixed in this PR, since each claimed one "still waiting" line per wait, which is wrong for PostgreSQL 18:

• the constant's doc;
• the wait_events / wait_events_per_hour metadata-key docs (PgTargetScorer.Blocking.cs);
• the shared advice sentence (PgTargetAdvice.Blocking.cs). It now reads "…writes a 'process N still waiting…' line when a lock wait outlives deadlock_timeout (1 s by default), and may write it again while the wait continues…".

Every reader of pg_log_events, checked

Changed: Darling/PerformanceMonitor.Darling.Analysis/PgTargetFactCollector.Blocking.cs PgTargetLockWaitEventsSql. It is the only aggregate over raw rows.

Already count each line once (they read deduped rows):

• DarlingPgLogEventReader.EventsSql (DISTINCT ON (raw_line_hash), earliest sighting; window_total is counted after the distinct, and times_seen counts sightings by design);
• DarlingPgLogEventReader.AutovacuumRunsSql, with the same dedupe;
• get_pg_log_events (DarlingMcpPgLogEventTools, total_events = WindowTotal);
• get_pg_autovacuum_health's recent runs and sums (computed in C# over the deduped rows);
• the viewer's log-events panel (ViewerDataService.Postgres, ViewerServerTab.Postgres);
• the web endpoints (DarlingWebEndpoints, which call the MCP tool) and server-tabs.js, which renders the deduped payload with no client-side count.

Duplicates can't change the answer:

• the EXISTS schema probes in ViewerDataService;
• DarlingCollectorRunner's MAX(...) watermarks;
• PgTargetScorer.Blocking and PgTargetAdvice.Blocking, which grade fact metadata and contain no SQL;
• DarlingPgLoggingAudit, PgTargetToolRecommendations and ServerHealthBands, which are text or name lists only;
• PgDeadlockRemask, which doesn't read this table.

Writers and ingest (no schema or writer change here): PgLogEventsCollector (it refuses rows without a hash), RdsLogEventIngestor, RdsResumeStore, the DarlingWorker and DarlingCollectorRunner routes, retention, and the DDL.

Pins

Live pins in PgTargetBlockingTests. Each runs the constant against seeded rows with fixed timestamps. Each FAILS on dev and passes here.

• ARepeatedLineHash_InsideTheWindow_CountsOnce: one line stored twice in the window → 1 wait, 1 line.
• ALine_FirstStoredBeforeTheWindow_AndRestoredInside_IsNotCounted → 0 / 0.
• ALine_ReSightedThreeHoursLater_IsNotCounted_WhereAFixedTwoHourLookbackWould → 0 / 0. This is what tells the exact rule apart from a fixed lookback.
• OutcomeLines_StoredTwice_CountOnce: acquired 1, acquired_wait_ms 30,000 once, deadlocks 1.
• TwoLinesOfOneWait_CountOneWait: "after 1000 ms" and "after 5000 ms" → 1 wait, top-relation weight 1, max 5,000 ms.
• AWaitSplitAcrossTwoWindows_IsCountedInTheWindowOfItsOpeningLineOnly → 0 in the later window, 1 in the earlier.
• TwoSeparateWaitsByOnePid_OnTheSameLock_CountTwice_EachLineStoredTwice, with and without an acquired line between them → 2.

Unchanged: the existing end-to-end pin still reads 6 / 6 / 12, 65,000.5 ms, 1.5 per hour and a top-relation weight of 6.

Source pins on the new SQL: DISTINCT ON (e.raw_line_hash), e.collection_time AS first_collected, the occurred_at-bounded first-sighting probe, p.collection_time < $2, p.collection_time <= l.first_collected, * INTERVAL '1 millisecond' and (SELECT COUNT(*) FROM waits).

Verification

A clean --no-incremental Release build: 0 warnings and 0 errors.

In-process on macOS, against a migrated local TimescaleDB 2.30.1 / PostgreSQL 18.6 store:

Suite	Result
PgTargetBlockingTests	43/43
PgTargetFactCollectorTests	8/8 (the SQL census and the live parse)
FactCollectorCommandTimeoutTests	16/16
DocCommentHygieneTests	77/77
LiveCleanupConversionRatchetTests	15/15
McpPayloadContractCensusTests	68/68
StorageCommandTimeoutTests	19/19
RepoFileAdoptionTests	2/2
CommentFilterAdoptionTests	4/4

RED on dev: each new live pin was run against origin/dev's SQL in a detached worktree, and each failed there.

Plan cost (EXPLAIN (ANALYZE, BUFFERS), local store):

• The data: 9,000 synthetic lock_wait rows for one server, 1,801 of them "still waiting" lines inside the one-hour window. That's an extreme contention rate: the production fleet measured above logged none in a week.
• The opener probe is one idx_pg_log_events_time index range per candidate line: collection_time from occurred_at − (N + 1 s) to the line's own first sighting. That's 1,801 index searches, about 5 rows filtered per probe, and 5.7k shared-buffer hits.
• The total: 325 ms.
• Before the opener probe was bounded at the line's own first sighting (instead of the window end), the same data took 487 ms and 65k buffer hits.

CHANGELOG

None: collect.pg_log_events (V129) and the lock-wait fact are new in 3.9 (v3.8.0 is schema 125), so no released version counted a wait twice. The 3.9 entry for #3691 carries the change: PG_LOCK_WAIT_EVENTS counts each wait once, even when PostgreSQL 18 logs it again while it goes on, and each line once, even when the log is read again.

Findings: 1 substantial (this one, fixed here); 3 polish fixed in this PR (the three wording claims); 0 dropped.