Skip to content
Merged
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,7 @@ namespace PerformanceMonitor.Darling.Service.Mcp;
[McpServerToolType]
public sealed class DarlingMcpPgDeadlockTools
{
[McpServerTool(Name = "get_pg_deadlocks"), Description("Gets PostgreSQL deadlocks that were reported in the window, newest first, with the victim process, how many sessions were in the cycle, the lock modes and resources involved, and the victim's full statement text. PostgreSQL writes a complete deadlock report to its server log unconditionally - there is no setting that suppresses it - so this needs nothing configured on the target, unlike plan capture. Each row is one DISTINCT deadlock: the collector re-reads an overlapping tail of the log every cycle on purpose, so the same report is seen several times, and times_seen reports that rather than hiding it. A deadlock that genuinely recurred appears as a separate row, because the participating process IDs differ. Use get_pg_deadlock_detail with a deadlock_hash for the full wait graph and every participant's SQL.")]
[McpServerTool(Name = "get_pg_deadlocks"), Description("Gets PostgreSQL deadlocks that were reported in the window, newest first, with the victim process, how many sessions were in the cycle, the lock modes and resources involved, and the victim's full statement text. PostgreSQL writes a complete deadlock report to its server log at default settings and needs nothing ENABLED on the target, unlike plan capture - but that is not the same as unsuppressable. log_error_verbosity = terse drops the DETAIL field, which is where the wait graph and every participant's SQL live, so the ERROR line is still logged and this tool still returns nothing. If this comes back empty, check log_error_verbosity on the target (and log_min_messages) before concluding the server does not deadlock; get_pg_database_stats' cumulative deadlock counter is the independent test. Each row is one DISTINCT deadlock, and a deadlock that genuinely recurred appears as a separate row because the participating process IDs differ. times_seen counts how often the collector saw that SAME report, and what a value means depends on the transport. Where the collector reads the log file itself it re-reads an overlapping tail every cycle on purpose, so one report is seen several times and times_seen climbs while it stays in the window. On RDS and Aurora the log API is consume-once, so a report is normally seen once and times_seen normally stays 1: there a low value is the ordinary state and NOT a partial count, so do not read 1 as 'seen once so far, expect more'. It is not guaranteed to be 1 there either - the collector holds its resume position in memory, so a restart re-reads a bounded tail, and a window whose write did not land is offered again - so treat times_seen as a sighting count whose meaning depends on the transport, and never as a count of deadlocks on either. Use get_pg_deadlock_detail with a deadlock_hash for the full wait graph and every participant's SQL.")]
public static async Task<string> GetPgDeadlocks(
NpgsqlDataSource postgres,
[Description("Server name or display name.")] string? server_name = null,
Expand Down Expand Up @@ -65,9 +65,15 @@ public static async Task<string> GetPgDeadlocks(
deadlock_count = rows.Count,
truncated = rows.Count >= limit,
note = "occurred_at is when PostgreSQL wrote the report, not when the collector found it. "
+ "times_seen counts how often the collector saw the SAME report while it stayed inside "
+ "the log tail it re-reads - it is a property of the read window and not a repeat "
+ "deadlock, which would appear as its own row with different process IDs.",
+ "times_seen counts how often the collector saw the SAME report, never how many times "
+ "the deadlock happened - a genuine repeat appears as its own row with different "
+ "process IDs. What a given value MEANS depends on the transport: reading the log file "
+ "directly re-reads an overlapping tail, so times_seen climbs while the report stays "
+ "in the window and is a property of that read window. On RDS and Aurora the log API "
+ "is consume-once, so times_seen is normally 1 and a low value there is the ordinary "
+ "state rather than a partial count. It is not guaranteed to be 1 there: the resume "
+ "position lives in the collector process, so a restart re-reads a bounded tail, and "
+ "a window whose write did not land is offered again.",
deadlocks = rows.Select(r => new
{
occurred_at = r.OccurredAtUtc,
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -12,10 +12,15 @@ namespace PerformanceMonitor.Darling.Storage;
/// <summary>
/// Reads the stored PostgreSQL deadlock reports (#2661).
///
/// <para><b>Once per deadlock, not once per sighting.</b> The collector re-reads an overlapping tail of the
/// server log every cycle on purpose, so a report inside the window arrives again and again until it falls
/// out. Every read here groups on <c>deadlock_hash</c> and takes the earliest sighting, which is also the
/// closest to when it actually happened.</para>
/// <para><b>Once per deadlock, not once per sighting.</b> On the <c>pg_read_file</c> route the collector
/// re-reads an overlapping tail of the server log every cycle on purpose, so a report inside the window
/// arrives again and again until it falls out. Every read here groups on <c>deadlock_hash</c> and takes
/// the earliest sighting, which is also the closest to when it actually happened.</para>
///
/// <para>The grouping still earns its place on the consume-once RDS log-API route, which can re-offer a
/// window after a restart or a write that did not land (#3008). But there a report normally arrives ONCE,
/// so a low <c>times_seen</c> is the ordinary state rather than a partial count, and nothing in a row
/// says which transport produced it (#3009).</para>
/// </summary>
public static class DarlingPgDeadlockReader
{
Expand Down Expand Up @@ -55,10 +60,12 @@ public readonly record struct PgDeadlockDetailRow(
MIN(d.lock_modes) AS lock_modes,
MIN(d.resources) AS resources,
MIN(d.victim_statement) AS victim_statement,
/* How many times the collector saw this same report. Not a count of deadlocks — it is a
property of the overlapping read window, and it is surfaced so a reader can tell it apart
from a deadlock that genuinely recurred, which would carry a DIFFERENT hash each time
because the pids differ. */
/* How many times the collector saw this same report. Never a count of deadlocks: one that
genuinely recurred carries a DIFFERENT hash each time because the pids differ, and being
told apart from that is what this is surfaced for. On the pg_read_file route it is a
property of the overlapping read window; on the consume-once RDS route there is no such
window, so it is normally 1 and a low value is the ordinary state rather than a partial
count -- see the class remarks for the two ways it can still exceed 1 there (#3009). */
COUNT(*)::int AS times_seen
FROM pg_deadlocks AS d
WHERE d.server_id = $1
Expand All @@ -78,9 +85,10 @@ ORDER BY MIN(d.occurred_at) DESC
/// 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>
/// <para><c>DISTINCT ON (deadlock_hash)</c> for the same reason every read here groups: on the
/// <c>pg_read_file</c> route the collector re-reads an overlapping tail, so without it the newest few
/// rows are frequently the same report several times over. Costless where that route is not in
/// use.</para>
/// </summary>
public const string DeadlockDetailSql = """
SELECT DISTINCT ON (d.deadlock_hash)
Expand Down
22 changes: 14 additions & 8 deletions Darling/PerformanceMonitor.Darling.Storage/PgMigrations.cs
Original file line number Diff line number Diff line change
Expand Up @@ -2641,10 +2641,13 @@ CREATE INDEX IF NOT EXISTS idx_collector_cost_lookup
/// generated schema and would silently not have it. Putting it in its own rung gives BOTH populations
/// the index, which is what was actually wanted.</para>
///
/// <para><b>Why the index earns its place.</b> The collector re-reads an OVERLAPPING tail of the server
/// log every cycle, deliberately, so a report cut in half at one edge is whole in the next. Every read
/// therefore groups or filters on <c>deadlock_hash</c> to answer once per deadlock rather than once per
/// sighting, and the detail read looks a report up by hash directly.</para>
/// <para><b>Why the index earns its place.</b> The <c>pg_read_file</c> route re-reads an OVERLAPPING
/// tail of the server log every cycle, deliberately, so a report cut in half at one edge is whole in
/// the next and one deadlock lands many times. Every read therefore groups or filters on
/// <c>deadlock_hash</c> to answer once per deadlock rather than once per sighting, and the detail read
/// looks a report up by hash directly. The consume-once RDS route repeats less often and for other
/// reasons (#3008, #3009), which changes how many sightings a row has rather than what the reads
/// do.</para>
///
/// <para><b>Not UNIQUE.</b> Two servers legitimately produce identical graph text — the same query pair
/// deadlocking with the same process ids on two hosts is not impossible — and a unique constraint would
Expand All @@ -2660,10 +2663,13 @@ CREATE INDEX IF NOT EXISTS idx_pg_deadlocks_identity
/// We collected the COUNT (<c>pg_stat_database.deadlocks</c>) and nothing else: a number that goes up.
/// This is which sessions, holding what, running what SQL.
///
/// <para><b>The identity column is the point.</b> Both transports read a bounded TAIL of the log on a
/// schedule and the window OVERLAPS deliberately — a report cut in half at the edge of one read is whole
/// in the next — so without <c>deadlock_hash</c> the same deadlock is stored once per cycle for as long
/// as it stays inside the window. The hash is over the graph text rather than over
/// <para><b>The identity column is the point.</b> The <c>pg_read_file</c> transport reads a bounded
/// TAIL of the log on a schedule and the window OVERLAPS deliberately, so without
/// <c>deadlock_hash</c> the same deadlock is stored once per cycle for as long as it stays inside the
/// window. The RDS log-API transport is consume-once and does not overlap — its repeats come from a
/// restart discarding the in-process marker, or from #3008 leaving it in place after a write that did
/// not land — and a report cut at one of its chunk boundaries is NOT whole in the next read (#3009).
/// The hash is over the graph text rather than over
/// (timestamp, victim_pid): two reports in the same millisecond with the 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.</para>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -359,9 +359,10 @@ public async Task<List<PgCpuUtilizationRow>> GetPgCpuUtilizationHistoryAsync(
}

/// <summary>Activity tab - PostgreSQL deadlocks reported in the window (#2661), one row per distinct
/// report. Windowed on when the deadlock HAPPENED rather than when it was collected: the collector
/// re-reads an overlapping log tail, so a report is found minutes later and found again for as long as
/// it stays in the window, and filtering on collection time would place it wrongly and move it.</summary>
/// report. Windowed on when the deadlock HAPPENED rather than when it was collected: a report is
/// always found some minutes after the fact, and on the <c>pg_read_file</c> route it is found again
/// for as long as it stays in the re-read tail, so filtering on collection time would place it
/// wrongly and move it every cycle.</summary>
public Task<List<DarlingPgDeadlockReader.PgDeadlockRow>> GetPgDeadlocksAsync(
int serverId, DateTime startUtc, DateTime endUtc, int limit = 100,
CancellationToken cancellationToken = default) =>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -540,12 +540,14 @@ private async Task LoadPgPlanCaptureAsync(DateTime startUtc, DateTime endUtc)
/// Deadlocks reported in the window (#2661), last on this tab because they are blocking at its limit: a
/// chain the server had to break by cancelling somebody.
///
/// <para><b>An empty grid is the healthy answer AND the shape of an unreadable log</b>, which is why the
/// note names the other check rather than leaving it. Deadlock reports need nothing configured on the
/// target — unlike plan capture there is no setting that suppresses them — so the only precondition is
/// being able to read the server log, which the plan-capture panel above already reports on because it
/// reads the same file. pg_stat_database's cumulative deadlock counter is the independent test: if that
/// moved and this is empty, the log is the problem rather than the server.</para>
/// <para><b>An empty grid is the healthy answer AND the shape of a log that cannot be read or cannot be
/// parsed</b>, which is why the note names the other checks rather than leaving them. Deadlock reports
/// need nothing ENABLED on the target, unlike plan capture, but they are not unsuppressable. Two things
/// have to hold: the log must be readable, which the plan-capture panel above already reports on
/// because it reads the same file, AND it must carry DETAIL, which <c>log_error_verbosity = terse</c>
/// strips along with the whole graph. pg_stat_database's cumulative deadlock counter is the independent
/// test: if that moved and this is empty, the log is the problem — unreadable or too terse — rather
/// than the server (#3030).</para>
/// </summary>
private async Task LoadPgDeadlocksAsync(DateTime startUtc, DateTime endUtc)
{
Expand Down
Loading
Loading