Collect PostgreSQL deadlock reports from the server log (#2661) - #2662
Conversation
We had pg_stat_database.deadlocks -- a number that goes up -- and nothing else. PostgreSQL writes a complete report to its log: the wait graph, every participant, and each one's full statement text. In one respect that beats the SQL Server deadlock graph, which names the victim's statement and often leaves the other side as a handle. It needs NOTHING configured on the target, which is what separates it from plan capture. auto_explain needs a preload and a restart, which on a managed fleet is a parameter-group change nobody can make; a deadlock report is unconditional, and log_lock_waits governs ordinary lock waits rather than this. The only precondition is reading the log, which pg_plan_capture already established and pg_plan_capture_readiness already reports on -- so this works on the Aurora fleet today. Two things in the extraction were measured against a real 17.11 rather than assumed, and both are the kind that fail silently: %Q writes the query id with NO separator before the severity -- the captured line reads `[1549] 322048460535975151ERROR: deadlock detected`. A pattern requiring whitespace there matches nothing, in the way that looks like "this server has no deadlocks". The DETAIL block runs to the next line carrying a log prefix, and a participant's statement is arbitrary user SQL that can contain newlines, each arriving tab-indented. A line-count or blank-line rule truncates multi-line SQL to its first line, and the row still looks fine. The collector re-reads an overlapping tail on purpose so a report cut in half at one edge is whole in the next, and every row carries a hash of its graph text so the store dedupes. The hash is over the graph rather than (timestamp, victim_pid): the graph is what distinguishes two reports, and hashing the thing itself needs no argument about how unlikely a collision is. Participants are counted from the wait EDGES, not the statement headers, because the server omits a header when it could not recover the text and a participant with no statement is still in the cycle. Verified end to end against a real deadlock on the rig: the collector stored it with the same hash the parser produced offline, the reads returned the victim, the graph and both participants' SQL, and after a SECOND induced deadlock the store held three rows that the read correctly collapsed to two deadlocks -- one with times_seen=2 from the overlapping window, and the repeat as its own row because the process IDs differed. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
| if (!DateTime.TryParse( | ||
| timestampText, | ||
| CultureInfo.InvariantCulture, | ||
| DateTimeStyles.AdjustToUniversal | DateTimeStyles.AssumeUniversal, | ||
| out var occurredAt)) | ||
| { | ||
| return null; | ||
| } |
There was a problem hiding this comment.
occurred_at is parsed assuming the log timestamp is already UTC — it isn't, unless log_timezone = 'UTC'.
%m (and %t) render in whatever log_timezone the target has configured, and the zone abbreviation is captured right here (s_deadlockBlock's (?<zone>\w+) group at line 61) but then discarded — Extract() only forwards match.Groups[1] (the bare digits) and match.Groups["pid"]/["detail"] into FromBlock. FromBlock then does:
DateTime.TryParse(timestampText, CultureInfo.InvariantCulture,
DateTimeStyles.AdjustToUniversal | DateTimeStyles.AssumeUniversal, out var occurredAt)AssumeUniversal treats the parsed wall-clock digits as already being UTC. That's only correct when the source server's log_timezone is UTC. This code path is explicitly for the self-hosted/filesystem transport (the RDS-API path is separate and Aurora conventionally logs in UTC), and on a self-hosted target where an admin has set log_timezone to something else (a common thing to do, e.g. to match local business hours), every stored occurred_at will be silently off by the zone offset.
That's not just cosmetic — DarlingPgDeadlockReader.GetDeadlocksAsync windows on occurred_at >= $2 AND <= $3 (built from hours_back), so a shifted timestamp can push a real deadlock outside the requested window and it just won't show up in get_pg_deadlocks — the same "silently looks like no deadlocks happened" failure mode the PR description calls out for the %Q-separator trap, just from a different cause that isn't covered by a test here (all the fixtures use UTC as the zone).
Worth either converting using the captured zone abbreviation (best-effort TimeZoneInfo lookup) or, more simply, reading the session's actual log_timezone alongside the tail (like the readiness collector already reads other GUCs) and applying that offset before storing.
|
Reviewed the diff for correctness, Lite/Darling parity, and security. Findings:
Checked and found OK:
|
…eachable (#2661) Three CI failures, all mine. PgSchemaGeneratorTests requires a collector's rung to be exactly what the generator emits, and the generator emits one index per collector -- so the extra dedupe index inside V103 was not a drafting nit the pin should tolerate. A fresh store builds from the generated schema and would silently not have had it. V103 is now byte-identical to the generated table and index, and V104 adds the index on its own, which gives BOTH populations what was actually wanted. get_pg_deadlock_detail was reachable only through MCP, which the POSTGRES_TABS pin exists to refuse -- and the fix is better than an exemption. The read took a mandatory hash, so it could only ever be a drill-down; it now takes an OPTIONAL one and answers with the most recent graphs without it, which is the shape the SQL Server "Deadlock Graphs" panel already has. A reader no longer has to call the summary first just to see a graph, and the tab gets a panel with no drill-down plumbing. DISTINCT ON (deadlock_hash) for the same reason every read here groups: the overlapping window means the newest rows are often one report several times. The viewer schema sentinel was simply missing -- my own checklist item, and the one that would have made the connect-time gate refuse a perfectly current store. Both rungs get an arm: V103 a table sentinel, V104 an index one, because a store stopped between them has the table and not the index and that is a real interrupted-upgrade state. Verified against the live rig: both statements PREPARE with their real parameter signatures, and the optional-hash read returns two distinct graphs with no hash and one with. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
| '^(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d\.\d+) \w+ \[(\d+)\][^\n]*ERROR: deadlock detected\s*\n[^\n]*DETAIL: ((?:[^\n]*\n)(?:\t[^\n]*\n)*)', | ||
| 'gn') AS m | ||
| LIMIT 500"; | ||
|
|
||
| public override string Name => "pg_deadlocks"; | ||
|
|
||
| public override string TargetTable => "pg_deadlocks"; | ||
|
|
||
| /// <summary> | ||
| /// Every PostgreSQL target, for the reason <see cref="PgPlanCaptureCollector"/> gives: gating on the | ||
| /// engine would report deadlock capture as a PERMANENT gap on Aurora, which is false — those targets | ||
| /// reach the same table through the RDS log API. The route is chosen at dispatch, so this definition | ||
| /// never executes against a managed target. | ||
| /// </summary> | ||
| public override bool AppliesTo(CollectorTargetInfo target) => true; |
There was a problem hiding this comment.
Correctness: this collector will actually run — and fail — on Aurora/RDS, contrary to the doc comments and the PR's own claims.
AppliesTo returns true for every target and the comment above it says "The route is chosen at dispatch, so this definition never executes against a managed target." But unlike pg_plan_capture, there is no dispatch branch for pg_deadlocks:
["pg_deadlocks"] = (r, s, ct) => r.RunAsync(PgDeadlocksCollector.Instance, s, ct),(DarlingWorker.cs:4823)
compare with the real managed-target routing that exists for plan capture:
["pg_plan_capture"] = (r, s, ct) =>
s.Target.IsAurora || s.Target.IsAwsRds
? r.IngestRdsPlansAsync(s, ct)
: r.RunAsync(PgPlanCaptureCollector.Instance, s, ct),(DarlingWorker.cs:4845)
There's no IngestRdsDeadlocksAsync/RdsDeadlockIngestor anywhere in the diff. So on Aurora/RDS this collector's raw query (pg_catalog.pg_ls_logdir() + pg_catalog.pg_read_file(...)) runs directly against a target where, per this codebase's own RdsLogUnavailableTests.cs, that function only returns a PERMISSIONS failure (pg_read_server_files isn't grantable there). Every 5-minute cycle will log a permission failure and never collect a row.
This directly contradicts the CHANGELOG entry ("It needs nothing configured on the target... so it works on a managed fleet today") and the MCP tool descriptions/doc comments claiming parity with pg_plan_capture's dual-transport design. Either the RDS ingestion route needs to be built (mirroring RdsPlanIngestor), or the claims need to be walked back and AppliesTo should exclude managed targets until it exists.
| /// <para><b>The hash is optional</b>, and that is what lets this be a panel as well as a drill-down. | ||
| /// With one it answers about a single report; without one it returns the most recent graphs, which is | ||
| /// the shape the SQL Server "Deadlock Graphs" panel already has and the reason a reader does not have to | ||
| /// call the summary first just to see a graph.</para> | ||
| /// | ||
| /// <para><c>DISTINCT ON (deadlock_hash)</c> for the same reason every read here groups: the collector | ||
| /// re-reads an overlapping tail, so without it the newest few rows are frequently the same report | ||
| /// several times over.</para> | ||
| /// </summary> | ||
| public const string DeadlockDetailSql = """ | ||
| SELECT DISTINCT ON (d.deadlock_hash) | ||
| d.occurred_at, | ||
| d.victim_pid, | ||
| d.participant_count, | ||
| d.lock_modes, | ||
| d.resources, | ||
| d.graph_text, | ||
| d.deadlock_hash | ||
| FROM pg_deadlocks AS d | ||
| WHERE d.server_id = $1 | ||
| AND ($2::text IS NULL OR d.deadlock_hash = $2::text) | ||
| AND d.deadlock_hash IS NOT NULL | ||
| /* The DISTINCT ON key must lead the sort; the earliest sighting of each report is the one closest | ||
| to when it actually happened. */ | ||
| ORDER BY d.deadlock_hash, d.collection_time |
There was a problem hiding this comment.
Correctness bug: "omit the hash → most recent graphs" doesn't hold.
DISTINCT ON requires its result set to follow the ORDER BY it's paired with, and here that's ORDER BY d.deadlock_hash, d.collection_time (required, since the DISTINCT ON key must lead the sort). So after dedup the rows are in hash order, not recency order, and LIMIT $3 then takes the first N in that hash order.
When deadlock_hash is supplied this doesn't matter (the WHERE clause narrows to at most one group). But the no-hash case — which is exactly how both callers use it, GetPgDeadlockDetail with deadlock_hash: null and the "Deadlock Graphs" JS panel ({ server, limit: 5 }, no hash) — is documented as returning "the most recent graphs" (see the XML doc above GetDeadlockDetailAsync and the MCP tool description in DarlingMcpPgDeadlockTools.cs). As written it instead returns an arbitrary, hash-ordered sample of up to limit distinct deadlocks, which for a busy server means the same 5 (whichever hash sorts first) forever, never the newest.
Fixing this needs the recency ordering applied after the per-hash dedup, e.g. wrap in a subquery:
SELECT * FROM (
SELECT DISTINCT ON (d.deadlock_hash) ...
ORDER BY d.deadlock_hash, d.collection_time
) x
ORDER BY x.occurred_at DESC
LIMIT $3No test exercises this query's ordering (unlike DeadlocksSql, which correctly does GROUP BY ... ORDER BY MIN(occurred_at) DESC), so it shipped unverified.
|
Reviewed the deadlock-collector addition. Overall the log parsing is careful and well tested (the two documented traps — Left two inline comments on concrete bugs, both high-confidence and independently verifiable from the diff:
No missing-index DMV suggestions, nothing security-sensitive stood out (parameterized queries throughout, no string-built SQL from user input), and I didn't spot other Lite/Darling parity gaps beyond the two above. |
Closes #2661.
What was missing
pg_stat_database.deadlocks— a number that goes up. SQL Server has three deadlock reads and a graphviewer; PostgreSQL had a counter.
PostgreSQL writes the whole thing to its server log:
The wait graph, the victim, and every participant's full statement. In that last respect it beats the
SQL Server graph, which names the victim's SQL and frequently leaves the other side as a handle.
Why it works where plan capture does not
auto_explainneeds a preload and a restart — on a managed fleet that is a parameter-group change and areboot, which is exactly why #2538's Aurora half is closed as unreachable. A deadlock report is
unconditional: no setting suppresses it, and
log_lock_waitsgoverns ordinary lock waits rather thanthis. The only precondition is reading the log, which plan capture already established and
pg_plan_capture_readinessalready reports on. So this ships value on the fleet in front of us today.Two traps, both measured rather than assumed
%Qwrites the query id with no separator before the severity. The captured line really reads[1549] 322048460535975151ERROR: deadlock detected. A pattern requiring whitespace there matches nothing —and matches nothing in the way that looks like "this server has no deadlocks", which is the worst possible
failure for this collector.
The DETAIL block ends at the next line carrying a log prefix, not at a blank line or after N lines. A
participant's statement is arbitrary user SQL that can contain newlines, each arriving tab-indented. A
line-count rule truncates every multi-line statement to its first, and the row still looks fine.
Both are pinned by tests built from real captured output, not a plausible-looking approximation — a fake
would not have had either.
Identity, because the window overlaps on purpose
Both transports read a bounded tail on a schedule, and the window overlaps deliberately so a report cut in
half at one edge is whole in the next. Every row carries a hash of its graph text and the reads group on it.
The hash is over the graph, not over
(timestamp, victim_pid): two reports in the same millisecond withthe same victim pid are vanishingly unlikely, but the graph is what actually distinguishes them, and hashing
the thing itself needs no argument about how unlikely a collision is.
Participants are counted from the wait edges, not the
Process N:headers — the server omits a headerwhen it could not recover the statement text, and a participant with no statement is still in the cycle.
Verification
A real deadlock induced on the rig, through the real service:
get_pg_deadlocksreturned the victim, participants, lock modes and resources;get_pg_deadlock_detailreturned the graph with both participants' SQL
which the read collapsed to two deadlocks — the first with
times_seen: 2from the overlappingwindow, and the repeat as its own row, because the process IDs differed and so did the hash
Both read statements were also checked with
PREPAREagainst a real PostgreSQL with their actual parametersignatures — the same thing
DarlingPgReadSqlParsesLiveTestsdoes — and all 20 parser assertions were runagainst the product assembly locally before pushing.
Empty is ambiguous, and the reads say so
No deadlocks is the healthy answer and the shape of an unreadable log. Every empty envelope here names the
independent check rather than leaving it:
pg_stat_database's cumulative counter. If that moved and this isempty, the log is the problem rather than the server.