From eafd2b250b0a91e485ad221ca6f9ec644e246834 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Mon, 5 Oct 2026 02:07:39 -0400 Subject: [PATCH 1/7] get_blocking_stats: tests for the data-start notice (#4966) --- .../DarlingBlockingStatsReadTests.cs | 170 ++++++++++++++++++ 1 file changed, 170 insertions(+) diff --git a/Darling/Darling.Tests/DarlingBlockingStatsReadTests.cs b/Darling/Darling.Tests/DarlingBlockingStatsReadTests.cs index 0ff6902d75..eba149e4d1 100644 --- a/Darling/Darling.Tests/DarlingBlockingStatsReadTests.cs +++ b/Darling/Darling.Tests/DarlingBlockingStatsReadTests.cs @@ -7,11 +7,14 @@ */ using System; +using System.Linq; using System.Text.Json; using System.Threading; using System.Threading.Tasks; using Npgsql; using PerformanceMonitor.Collectors; +using PerformanceMonitor.Common; +using PerformanceMonitor.Darling.Service; using PerformanceMonitor.Darling.Service.Mcp; using PerformanceMonitor.Darling.Storage; using Xunit; @@ -123,6 +126,173 @@ await LiveStoreCleanup.RunAsync(cs!, bodySucceeded, async (cleanup, cleanupCt) = } } + /* ── #4966: the data-start notice. Two separate series (blocking, deadlocks), one notice at the LATER of their floors. ── */ + + private static readonly string[] WindowTables = ["blocked_process_reports", "dmv_blocking_snapshots", "deadlocks"]; + private static readonly string[] WindowCollectors = ["blocked_process_reports", "dmv_blocking_snapshots", "deadlocks"]; + + private static string WindowName(string w) => "blocking-stats-window-" + w; + + private static Task CallWindowAsync(NpgsqlDataSource ds, string w, int hours, DateTime end) => + DarlingMcpDataTools.GetBlockingStats(ds, WindowName(w), hours, WebDataStartNote.FormatWindowEnd(end)); + + private static Task RunWindowAsync(string w, Func body) => + WindowFloorLiveHarness.RunAsync(ConnectionString, WindowCollectors, [WindowName(w)], WindowTables, body); + + private static Task SeedWindowAsync(NpgsqlConnection c, string w, DateTime end) => + WindowFloorLiveHarness.SeedServerAsync(c, WindowName(w), end.AddDays(-30), "blocked_process_report", null, 30, end, WindowTables, TestContext.Current.CancellationToken); + + private static Task SeedBprAsync(NpgsqlConnection c, string w, DateTime eventTime, DateTime collectedAt) => + DarlingMcpTestData.ExecAsync(c, TestContext.Current.CancellationToken, + "INSERT INTO blocked_process_reports (blocked_report_id, collection_time, server_id, server_name, event_time, database_name, blocked_spid, blocking_spid, wait_time_ms) VALUES ($1,$2,$3,$4,$5,'d',50,90,8000)", + CollectionIdGenerator.Next(), DarlingMcpTestData.Naive(collectedAt), ServerIdHelper.GetDeterministicHashCode(WindowName(w)), WindowName(w), DarlingMcpTestData.Naive(eventTime)); + + private static Task SeedDmvAsync(NpgsqlConnection c, string w, DateTime eventTime, DateTime collectedAt) => + DarlingMcpTestData.ExecAsync(c, TestContext.Current.CancellationToken, + "INSERT INTO dmv_blocking_snapshots (collection_id, collection_time, server_id, server_name, monitor_loop, event_time, database_name, blocked_spid, blocking_spid, wait_time_ms) VALUES ($1,$2,$3,$4,-1,$5,'d',50,90,3000)", + CollectionIdGenerator.Next(), DarlingMcpTestData.Naive(collectedAt), ServerIdHelper.GetDeterministicHashCode(WindowName(w)), WindowName(w), DarlingMcpTestData.Naive(eventTime)); + + private static Task SeedDeadlockWindowAsync(NpgsqlConnection c, string w, DateTime at, DateTime collectedAt) => + DarlingMcpTestData.ExecAsync(c, TestContext.Current.CancellationToken, + "INSERT INTO deadlocks (deadlock_id, collection_time, server_id, server_name, deadlock_time, victim_process_id, victim_sql_text, deadlock_graph_xml) VALUES ($1,$2,$3,$4,$5,'p1','x',$6)", + CollectionIdGenerator.Next(), DarlingMcpTestData.Naive(collectedAt), ServerIdHelper.GetDeterministicHashCode(WindowName(w)), WindowName(w), DarlingMcpTestData.Naive(at), GraphXml); + + private static string Start(DateTime t) => McpHelpers.FormatEffectiveStart(t); + + [Fact] + public async Task BlockingCoveredFromBefore_DeadlocksStartInside_NamesTheDeadlockStart_AgainstDevPostgres() => + await RunWindowAsync("bc", async (c, ds, end) => + { + await SeedWindowAsync(c, "bc", end); + await SeedBprAsync(c, "bc", end.AddHours(-3), end.AddDays(-3)); + await SeedBprAsync(c, "bc", end.AddHours(-2), end.AddHours(-2)); + await SeedDeadlockWindowAsync(c, "bc", end.AddHours(-1), end.AddHours(-10)); + var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "bc", 168, end)); + Assert.True(root.GetProperty("window_truncated").GetBoolean()); + Assert.Equal(Start(end.AddHours(-10)), root.GetProperty("effective_start").GetString()); + Assert.Contains("blocked_process_report", root.GetProperty("truncation_note").GetString(), StringComparison.Ordinal); + Assert.Contains("deadlocks", root.GetProperty("truncation_note").GetString(), StringComparison.Ordinal); + }); + + [Fact] + public async Task DeadlocksCoveredFromBefore_BlockingStartsInside_NamesTheBlockingStart_AgainstDevPostgres() => + await RunWindowAsync("dc", async (c, ds, end) => + { + await SeedWindowAsync(c, "dc", end); + await SeedDeadlockWindowAsync(c, "dc", end.AddDays(-4), end.AddDays(-4)); + await SeedBprAsync(c, "dc", end.AddHours(-1), end.AddHours(-12)); + var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "dc", 168, end)); + Assert.True(root.GetProperty("window_truncated").GetBoolean()); + Assert.Equal(Start(end.AddHours(-12)), root.GetProperty("effective_start").GetString()); + }); + + [Fact] + public async Task TheLaterOfTheTwoFloors_Wins_AgainstDevPostgres() => + await RunWindowAsync("later", async (c, ds, end) => + { + await SeedWindowAsync(c, "later", end); + await SeedBprAsync(c, "later", end.AddHours(-30), end.AddHours(-30)); + await SeedDeadlockWindowAsync(c, "later", end.AddHours(-5), end.AddHours(-5)); + var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "later", 168, end)); + Assert.Equal(Start(end.AddHours(-5)), root.GetProperty("effective_start").GetString()); + }); + + [Fact] + public async Task DeadlockRowsOnly_IsADataAnswer_WithTheDeadlockFloor_AgainstDevPostgres() => + await RunWindowAsync("donly", async (c, ds, end) => + { + await SeedWindowAsync(c, "donly", end); + await SeedDeadlockWindowAsync(c, "donly", end.AddHours(-2), end.AddHours(-6)); + var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "donly", 168, end)); + Assert.False(root.TryGetProperty("status", out _)); + Assert.Equal(Start(end.AddHours(-6)), root.GetProperty("effective_start").GetString()); + Assert.Equal(1, root.GetProperty("deadlock_severity").GetArrayLength()); + }); + + [Fact] + public async Task XeEarlyDmvLate_GivesTheXeStartAsTheBlockingFloor_AgainstDevPostgres() => + await RunWindowAsync("xedmv", async (c, ds, end) => + { + await SeedWindowAsync(c, "xedmv", end); + await SeedBprAsync(c, "xedmv", end.AddHours(-20), end.AddHours(-20)); + await SeedDmvAsync(c, "xedmv", end.AddHours(-3), end.AddHours(-3)); + var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "xedmv", 168, end)); + Assert.Equal(Start(end.AddHours(-20)), root.GetProperty("effective_start").GetString()); + }); + + [Fact] + public async Task BothCovered_GivesNoNotice_AgainstDevPostgres() => + await RunWindowAsync("both", async (c, ds, end) => + { + await SeedWindowAsync(c, "both", end); + await SeedBprAsync(c, "both", end.AddDays(-5), end.AddDays(-5)); + await SeedBprAsync(c, "both", end.AddHours(-2), end.AddHours(-2)); + await SeedDeadlockWindowAsync(c, "both", end.AddDays(-5), end.AddDays(-5)); + await SeedDeadlockWindowAsync(c, "both", end.AddHours(-2), end.AddHours(-2)); + var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "both", 72, end)); + Assert.False(root.GetProperty("window_truncated").GetBoolean()); + Assert.Equal(System.Text.Json.JsonValueKind.Null, root.GetProperty("truncation_note").ValueKind); + var names = root.EnumerateObject().Select(p => p.Name).ToList(); + Assert.Equal(["effective_start", "window_truncated", "truncation_note"], names.Skip(names.IndexOf("hours_back") + 1).Take(3)); + Assert.True(names.IndexOf("truncation_note") < names.IndexOf("blocking_duration")); + }); + + [Fact] + public async Task AnEventOlderThanItsCollection_MovesThatSeriesFloorEarlier_AgainstDevPostgres() => + await RunWindowAsync("early", async (c, ds, end) => + { + await SeedWindowAsync(c, "early", end); + /* Collected ten hours ago, but the event happened eleven and a half hours ago. */ + await SeedBprAsync(c, "early", end.AddHours(-11).AddMinutes(-30), end.AddHours(-10)); + await SeedDeadlockWindowAsync(c, "early", end.AddHours(-11).AddMinutes(-30), end.AddHours(-10)); + var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "early", 12, end)); + Assert.False(root.GetProperty("window_truncated").GetBoolean()); + }); + + [Fact] + public async Task AnEmptyAnswer_PastCoverage_CarriesHints_AgainstDevPostgres() => + await RunWindowAsync("empty", async (c, ds, end) => + { + await SeedWindowAsync(c, "empty", end); + await DarlingMcpTestData.ExecAsync(c, TestContext.Current.CancellationToken, + "INSERT INTO collection_log (log_id, server_id, server_name, collector_name, collection_time, duration_ms, status, rows_collected) VALUES ($1,$2,$3,'blocked_process_report',$4,10,'SUCCESS',0)", + CollectionIdGenerator.Next(), ServerIdHelper.GetDeterministicHashCode(WindowName("empty")), WindowName("empty"), DarlingMcpTestData.Naive(end.AddMinutes(-5))); + var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "empty", 1, end)); + Assert.Equal("empty", root.GetProperty("status").GetString()); + var hints = root.GetProperty("hints"); + Assert.True(hints.GetProperty("window_truncated").GetBoolean()); + Assert.Equal(System.Text.Json.JsonValueKind.Null, hints.GetProperty("effective_start").ValueKind); + }); + + [Fact] + public async Task AShortWindow_WithRows_StartsNoProbe_AgainstDevPostgres() => + await RunWindowAsync("short", async (c, ds, end) => + { + await SeedWindowAsync(c, "short", end); + await SeedBprAsync(c, "short", end.AddMinutes(-20), end.AddMinutes(-20)); + var calls = 0; + DarlingMcpWindowNotice.TestOnlyProbe = () => { calls++; return Task.FromResult(null); }; + var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "short", 1, end)); + Assert.Equal(0, calls); + Assert.False(root.GetProperty("window_truncated").GetBoolean()); + Assert.Equal(1, root.GetProperty("blocking_duration").GetArrayLength()); + }); + + [Fact] + public async Task AFailedProbe_CostsTheNotice_NeverTheRows_AgainstDevPostgres() => + await RunWindowAsync("probefail", async (c, ds, end) => + { + await SeedWindowAsync(c, "probefail", end); + await SeedBprAsync(c, "probefail", end.AddHours(-3), end.AddHours(-3)); + DarlingMcpWindowNotice.TestOnlyProbe = () => throw new TimeoutException("the probe's deadline passed"); + var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "probefail", 168, end)); + Assert.False(root.TryGetProperty("status", out _)); + Assert.Equal(1, root.GetProperty("blocking_duration").GetArrayLength()); + Assert.False(root.TryGetProperty("effective_start", out _)); + Assert.False(root.TryGetProperty("window_truncated", out _)); + Assert.False(root.TryGetProperty("truncation_note", out _)); + }); + private static DateTime MinutesAgo(int minutes) => DarlingMcpTestData.TruncateToSeconds(DateTime.UtcNow.AddMinutes(-minutes)); From 25192009c76bb0706dfd71b5460043a5a0f8b072 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Mon, 5 Oct 2026 02:09:52 -0400 Subject: [PATCH 2/7] get_blocking_stats: name where the data starts, at the later of the two series' floors (#4966) --- .../DarlingBlockingStatsReadTests.cs | 48 +++++++++---------- .../Darling.Tests/EffectiveStartUtcTests.cs | 2 +- .../McpPayloadContractCensusTests.cs | 2 +- .../Mcp/DarlingMcpDataTools.cs | 44 ++++++++++++++++- .../Mcp/DarlingMcpWindowNotice.cs | 8 ++++ 5 files changed, 76 insertions(+), 28 deletions(-) diff --git a/Darling/Darling.Tests/DarlingBlockingStatsReadTests.cs b/Darling/Darling.Tests/DarlingBlockingStatsReadTests.cs index eba149e4d1..e78afc774a 100644 --- a/Darling/Darling.Tests/DarlingBlockingStatsReadTests.cs +++ b/Darling/Darling.Tests/DarlingBlockingStatsReadTests.cs @@ -139,8 +139,9 @@ private static Task CallWindowAsync(NpgsqlDataSource ds, string w, int h private static Task RunWindowAsync(string w, Func body) => WindowFloorLiveHarness.RunAsync(ConnectionString, WindowCollectors, [WindowName(w)], WindowTables, body); - private static Task SeedWindowAsync(NpgsqlConnection c, string w, DateTime end) => - WindowFloorLiveHarness.SeedServerAsync(c, WindowName(w), end.AddDays(-30), "blocked_process_report", null, 30, end, WindowTables, TestContext.Current.CancellationToken); + /* Registered at `created`: both series share that floor, and an event stamped before it is what moves one series' floor earlier. */ + private static Task SeedWindowAsync(NpgsqlConnection c, string w, DateTime end, DateTime created) => + WindowFloorLiveHarness.SeedServerAsync(c, WindowName(w), created, "blocked_process_report", null, 30, end, WindowTables, TestContext.Current.CancellationToken); private static Task SeedBprAsync(NpgsqlConnection c, string w, DateTime eventTime, DateTime collectedAt) => DarlingMcpTestData.ExecAsync(c, TestContext.Current.CancellationToken, @@ -163,10 +164,9 @@ private static Task SeedDeadlockWindowAsync(NpgsqlConnection c, string w, DateTi public async Task BlockingCoveredFromBefore_DeadlocksStartInside_NamesTheDeadlockStart_AgainstDevPostgres() => await RunWindowAsync("bc", async (c, ds, end) => { - await SeedWindowAsync(c, "bc", end); - await SeedBprAsync(c, "bc", end.AddHours(-3), end.AddDays(-3)); - await SeedBprAsync(c, "bc", end.AddHours(-2), end.AddHours(-2)); - await SeedDeadlockWindowAsync(c, "bc", end.AddHours(-1), end.AddHours(-10)); + await SeedWindowAsync(c, "bc", end, end.AddHours(-10)); + await SeedBprAsync(c, "bc", end.AddHours(-11), end.AddHours(-9)); + await SeedDeadlockWindowAsync(c, "bc", end.AddHours(-1), end.AddHours(-1)); var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "bc", 168, end)); Assert.True(root.GetProperty("window_truncated").GetBoolean()); Assert.Equal(Start(end.AddHours(-10)), root.GetProperty("effective_start").GetString()); @@ -178,9 +178,9 @@ await RunWindowAsync("bc", async (c, ds, end) => public async Task DeadlocksCoveredFromBefore_BlockingStartsInside_NamesTheBlockingStart_AgainstDevPostgres() => await RunWindowAsync("dc", async (c, ds, end) => { - await SeedWindowAsync(c, "dc", end); - await SeedDeadlockWindowAsync(c, "dc", end.AddDays(-4), end.AddDays(-4)); - await SeedBprAsync(c, "dc", end.AddHours(-1), end.AddHours(-12)); + await SeedWindowAsync(c, "dc", end, end.AddHours(-12)); + await SeedDeadlockWindowAsync(c, "dc", end.AddHours(-13), end.AddHours(-11)); + await SeedBprAsync(c, "dc", end.AddHours(-1), end.AddHours(-1)); var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "dc", 168, end)); Assert.True(root.GetProperty("window_truncated").GetBoolean()); Assert.Equal(Start(end.AddHours(-12)), root.GetProperty("effective_start").GetString()); @@ -190,18 +190,18 @@ await RunWindowAsync("dc", async (c, ds, end) => public async Task TheLaterOfTheTwoFloors_Wins_AgainstDevPostgres() => await RunWindowAsync("later", async (c, ds, end) => { - await SeedWindowAsync(c, "later", end); - await SeedBprAsync(c, "later", end.AddHours(-30), end.AddHours(-30)); - await SeedDeadlockWindowAsync(c, "later", end.AddHours(-5), end.AddHours(-5)); + await SeedWindowAsync(c, "later", end, end.AddHours(-5)); + await SeedBprAsync(c, "later", end.AddHours(-30), end.AddHours(-4)); + await SeedDeadlockWindowAsync(c, "later", end.AddHours(-20), end.AddHours(-4)); var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "later", 168, end)); - Assert.Equal(Start(end.AddHours(-5)), root.GetProperty("effective_start").GetString()); + Assert.Equal(Start(end.AddHours(-20)), root.GetProperty("effective_start").GetString()); }); [Fact] public async Task DeadlockRowsOnly_IsADataAnswer_WithTheDeadlockFloor_AgainstDevPostgres() => await RunWindowAsync("donly", async (c, ds, end) => { - await SeedWindowAsync(c, "donly", end); + await SeedWindowAsync(c, "donly", end, end.AddHours(-6)); await SeedDeadlockWindowAsync(c, "donly", end.AddHours(-2), end.AddHours(-6)); var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "donly", 168, end)); Assert.False(root.TryGetProperty("status", out _)); @@ -213,9 +213,9 @@ await RunWindowAsync("donly", async (c, ds, end) => public async Task XeEarlyDmvLate_GivesTheXeStartAsTheBlockingFloor_AgainstDevPostgres() => await RunWindowAsync("xedmv", async (c, ds, end) => { - await SeedWindowAsync(c, "xedmv", end); - await SeedBprAsync(c, "xedmv", end.AddHours(-20), end.AddHours(-20)); - await SeedDmvAsync(c, "xedmv", end.AddHours(-3), end.AddHours(-3)); + await SeedWindowAsync(c, "xedmv", end, end.AddHours(-3)); + await SeedBprAsync(c, "xedmv", end.AddHours(-20), end.AddHours(-2)); + await SeedDmvAsync(c, "xedmv", end.AddHours(-2), end.AddHours(-2)); var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "xedmv", 168, end)); Assert.Equal(Start(end.AddHours(-20)), root.GetProperty("effective_start").GetString()); }); @@ -224,7 +224,7 @@ await RunWindowAsync("xedmv", async (c, ds, end) => public async Task BothCovered_GivesNoNotice_AgainstDevPostgres() => await RunWindowAsync("both", async (c, ds, end) => { - await SeedWindowAsync(c, "both", end); + await SeedWindowAsync(c, "both", end, end.AddDays(-30)); await SeedBprAsync(c, "both", end.AddDays(-5), end.AddDays(-5)); await SeedBprAsync(c, "both", end.AddHours(-2), end.AddHours(-2)); await SeedDeadlockWindowAsync(c, "both", end.AddDays(-5), end.AddDays(-5)); @@ -241,7 +241,7 @@ await RunWindowAsync("both", async (c, ds, end) => public async Task AnEventOlderThanItsCollection_MovesThatSeriesFloorEarlier_AgainstDevPostgres() => await RunWindowAsync("early", async (c, ds, end) => { - await SeedWindowAsync(c, "early", end); + await SeedWindowAsync(c, "early", end, end.AddHours(-10)); /* Collected ten hours ago, but the event happened eleven and a half hours ago. */ await SeedBprAsync(c, "early", end.AddHours(-11).AddMinutes(-30), end.AddHours(-10)); await SeedDeadlockWindowAsync(c, "early", end.AddHours(-11).AddMinutes(-30), end.AddHours(-10)); @@ -253,22 +253,22 @@ await RunWindowAsync("early", async (c, ds, end) => public async Task AnEmptyAnswer_PastCoverage_CarriesHints_AgainstDevPostgres() => await RunWindowAsync("empty", async (c, ds, end) => { - await SeedWindowAsync(c, "empty", end); + await SeedWindowAsync(c, "empty", end, end.AddHours(-2)); await DarlingMcpTestData.ExecAsync(c, TestContext.Current.CancellationToken, "INSERT INTO collection_log (log_id, server_id, server_name, collector_name, collection_time, duration_ms, status, rows_collected) VALUES ($1,$2,$3,'blocked_process_report',$4,10,'SUCCESS',0)", CollectionIdGenerator.Next(), ServerIdHelper.GetDeterministicHashCode(WindowName("empty")), WindowName("empty"), DarlingMcpTestData.Naive(end.AddMinutes(-5))); - var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "empty", 1, end)); + var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "empty", 6, end)); Assert.Equal("empty", root.GetProperty("status").GetString()); var hints = root.GetProperty("hints"); Assert.True(hints.GetProperty("window_truncated").GetBoolean()); - Assert.Equal(System.Text.Json.JsonValueKind.Null, hints.GetProperty("effective_start").ValueKind); + Assert.Equal(Start(end.AddHours(-2)), hints.GetProperty("effective_start").GetString()); }); [Fact] public async Task AShortWindow_WithRows_StartsNoProbe_AgainstDevPostgres() => await RunWindowAsync("short", async (c, ds, end) => { - await SeedWindowAsync(c, "short", end); + await SeedWindowAsync(c, "short", end, end.AddDays(-30)); await SeedBprAsync(c, "short", end.AddMinutes(-20), end.AddMinutes(-20)); var calls = 0; DarlingMcpWindowNotice.TestOnlyProbe = () => { calls++; return Task.FromResult(null); }; @@ -282,7 +282,7 @@ await RunWindowAsync("short", async (c, ds, end) => public async Task AFailedProbe_CostsTheNotice_NeverTheRows_AgainstDevPostgres() => await RunWindowAsync("probefail", async (c, ds, end) => { - await SeedWindowAsync(c, "probefail", end); + await SeedWindowAsync(c, "probefail", end, end.AddDays(-2)); await SeedBprAsync(c, "probefail", end.AddHours(-3), end.AddHours(-3)); DarlingMcpWindowNotice.TestOnlyProbe = () => throw new TimeoutException("the probe's deadline passed"); var root = WindowFloorLiveHarness.Parse(await CallWindowAsync(ds, "probefail", 168, end)); diff --git a/Darling/Darling.Tests/EffectiveStartUtcTests.cs b/Darling/Darling.Tests/EffectiveStartUtcTests.cs index eb4d371c61..aa463dbf96 100644 --- a/Darling/Darling.Tests/EffectiveStartUtcTests.cs +++ b/Darling/Darling.Tests/EffectiveStartUtcTests.cs @@ -44,7 +44,7 @@ public void FormatEffectiveStart_NamesTheInstantAsUtc_WhicheverKindItCameWith() /// [Theory] [InlineData("DarlingMcpConfigHistoryTools.cs", 3)] - [InlineData("DarlingMcpDataTools.cs", 5)] + [InlineData("DarlingMcpDataTools.cs", 6)] [InlineData("DarlingMcpQueryStoreClutterTools.cs", 1)] [InlineData("DarlingMcpSessionTools.cs", 2)] [InlineData("DarlingMcpMemoryGrantTools.cs", 1)] diff --git a/Darling/Darling.Tests/McpPayloadContractCensusTests.cs b/Darling/Darling.Tests/McpPayloadContractCensusTests.cs index d2106df087..9018025332 100644 --- a/Darling/Darling.Tests/McpPayloadContractCensusTests.cs +++ b/Darling/Darling.Tests/McpPayloadContractCensusTests.cs @@ -1541,7 +1541,7 @@ public static readonly (string Key, string[] Files, string WhatWasCut)[] SecondB ("processes_truncated", ["DarlingMcpBlockingTools.cs"], "get_deadlock_detail's processes[] is cut by two bounds, the per-deadlock cap DarlingDeadlockProcessRows.MaxProcessesPerDeadlock (12) and the default page's shared row budget (DefaultPageRowBudget, 24); the rows cut from one deadlock are counted beside it. Unlike the boolean _truncated keys around it, processes_truncated is a COUNT (0 when nothing was cut), kept under this name because it is the per-deadlock twin of the page's truncated and a reader looks for it beside processes"), ("window_truncated", ["DarlingMcpBlockingTools.cs", "DarlingMcpConfigHistoryTools.cs", "DarlingMcpDataTools.cs", "DarlingMcpJobTools.cs", "DarlingMcpLongQueryTools.cs", "DarlingMcpMemoryGrantTools.cs", "DarlingMcpPlanCorrectionTools.cs", "DarlingMcpQueryHeatmapTools.cs", "DarlingMcpQueryStoreClutterTools.cs", "DarlingMcpQueryStoreRegressionTools.cs", "DarlingMcpSessionTools.cs", "DarlingMcpTrendTools.cs", "McpBlockingTools.cs", "McpConfigHistoryTools.cs", "McpHealthTools.cs", "McpLongQueryTools.cs", "McpMemoryTools.cs", "McpPlanCorrectionTools.cs", "McpQueryTools.cs", "McpSessionTools.cs", "McpWaitTools.cs"], - "the #2364 / #2353 WINDOW floor (#3653 item 17): the tier that answered did not hold the whole requested window, so the served series begins later than asked — beside effective_start / effective_hours_back, observed off the served head against the shared ninety-minute TruncationSlack, no cap involved; get_query_trend and get_query_store_top write it in their initializers, the duration-trend trio through TrendDisclosure.WriteTo (Darling) and WriteDisclosure (Lite); get_query_store_clutter (#3797) writes it in its initializer for its plan-churn and wait arms, which read the same raw tier get_query_store_top does, off the same window-floor read and the same ninety-minute slack; Lite's get_active_queries and get_waiting_tasks (QuerySnapshots / WaitingTasks, read by coverage), get_query_store_regressions (checked against the baseline's start, the earlier of its two windows) and get_query_heatmap (#4966) write it in their initializers through McpQueryTools.WindowNotice, beside a page cut of their own (truncated), so they publish effective_start without effective_hours_back, which the window-floor rule below holds apart for the window floor; Darling's get_server_config_changes, get_database_config_changes and get_trace_flag_changes (#4966) write them after hours_back from the coverage probe of server_config, database_config and trace_flags (the same rule as the viewer's and the web's Config Changes notes), and on their empty answer inside the hints; Darling's get_collection_log (one server), get_plan_corrections and get_memory_pressure_events (#4966) write them after hours_back too: the log from its own coverage probe, which ignores the collector, status and duration filters so the note says where the log starts, plan corrections from plan_correction's coverage, where an answer of only automatic-tuning rows is a data answer, and memory pressure from the events' sample_time with its edge at the purge cutoff, each on its empty answer inside the hints; Darling's get_active_queries, get_waiting_tasks, get_query_heatmap and get_query_store_regressions (#4966) write the same three keys after hours_back through DarlingMcpWindowNotice, with the same wording and the same absence of effective_hours_back (the regressions tool checks its baseline's start, as Lite's does); Darling's get_active_queries (DarlingMcpSessionTools.cs) writes them only when the window was cut, so a covered default call stays inside the response budget and a missing key there means covered (Lite's writes them always), and each of the four leaves them off when its coverage probe failed, since a failed probe costs the notice and never the rows; and Lite's config-change, collection-log, plan-correction and memory-pressure tools (#4966) write it as well; Darling's get_blocking, get_deadlocks, get_deadlock_detail, get_blocked_process_xml and get_long_query_completions (#4966) write the three keys after hours_back through DarlingMcpWindowNotice.ReadEventAsync, beside a page cut of their own (truncated), and leave them off when the coverage probe failed"), + "the #2364 / #2353 WINDOW floor (#3653 item 17): the tier that answered did not hold the whole requested window, so the served series begins later than asked — beside effective_start / effective_hours_back, observed off the served head against the shared ninety-minute TruncationSlack, no cap involved; get_query_trend and get_query_store_top write it in their initializers, the duration-trend trio through TrendDisclosure.WriteTo (Darling) and WriteDisclosure (Lite); get_query_store_clutter (#3797) writes it in its initializer for its plan-churn and wait arms, which read the same raw tier get_query_store_top does, off the same window-floor read and the same ninety-minute slack; Lite's get_active_queries and get_waiting_tasks (QuerySnapshots / WaitingTasks, read by coverage), get_query_store_regressions (checked against the baseline's start, the earlier of its two windows) and get_query_heatmap (#4966) write it in their initializers through McpQueryTools.WindowNotice, beside a page cut of their own (truncated), so they publish effective_start without effective_hours_back, which the window-floor rule below holds apart for the window floor; Darling's get_server_config_changes, get_database_config_changes and get_trace_flag_changes (#4966) write them after hours_back from the coverage probe of server_config, database_config and trace_flags (the same rule as the viewer's and the web's Config Changes notes), and on their empty answer inside the hints; Darling's get_collection_log (one server), get_plan_corrections and get_memory_pressure_events (#4966) write them after hours_back too: the log from its own coverage probe, which ignores the collector, status and duration filters so the note says where the log starts, plan corrections from plan_correction's coverage, where an answer of only automatic-tuning rows is a data answer, and memory pressure from the events' sample_time with its edge at the purge cutoff, each on its empty answer inside the hints; Darling's get_active_queries, get_waiting_tasks, get_query_heatmap and get_query_store_regressions (#4966) write the same three keys after hours_back through DarlingMcpWindowNotice, with the same wording and the same absence of effective_hours_back (the regressions tool checks its baseline's start, as Lite's does); Darling's get_active_queries (DarlingMcpSessionTools.cs) writes them only when the window was cut, so a covered default call stays inside the response budget and a missing key there means covered (Lite's writes them always), and each of the four leaves them off when its coverage probe failed, since a failed probe costs the notice and never the rows; and Lite's config-change, collection-log, plan-correction and memory-pressure tools (#4966) write it as well; Darling's get_blocking, get_deadlocks, get_deadlock_detail, get_blocked_process_xml and get_long_query_completions (#4966) write the three keys after hours_back through DarlingMcpWindowNotice.ReadEventAsync, beside a page cut of their own (truncated), and leave them off when the coverage probe failed; Darling's get_blocking_stats (#4966) writes them after hours_back as one notice for its two series (blocking and deadlock severity), at the later of the two series' floors (blocking: the earlier of blocked_process_reports and dmv_blocking_snapshots), and leaves them off when the probe failed"), ("findings_truncated", ["DarlingMcpTools.cs", "McpAnalysisTools.cs"], "#4198: get_analysis_findings' GROUP PAGE cut — limit caps the collapsed per-chain groups returned (default 18), independent of the pre-existing truncated above (the raw WindowCoveringLimit occurrence read, beside truncation_note): truncated warns occurrence stats may under-report, findings_truncated warns other diagnostic chains exist but are not on this page at all"), ]; diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpDataTools.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpDataTools.cs index a9acc80e43..7c778e9107 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpDataTools.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpDataTools.cs @@ -2873,6 +2873,7 @@ public static async Task GetBlockingStats( [Description("Server name or display name.")] string? server_name = null, [Description("Hours of history. Default 24. No upper bound (this read exists to look further back than the 168-hour reads allow); a negative or zero value is refused rather than read as its absolute value.")] int hours_back = 24, [Description(McpHelpers.AsOfDescription)] string? as_of = null, + ILogger? logger = null, CancellationToken cancellationToken = default) { var (resolved, error) = await DarlingServerResolver.ResolveOrErrorAsync(postgres, server_name, cancellationToken); @@ -2924,16 +2925,26 @@ await DarlingBlockingTrendReader.HasAnyBlockingCollectorRunAsync(postgres, resol return everRan ? McpHelpers.Status( "empty", - $"No blocking or deadlocks recorded for {resolved.ServerName} in the last {hours_back} hour(s). The blocking collectors HAVE run successfully for this server, so the window is genuinely clear rather than blind.") + $"No blocking or deadlocks recorded for {resolved.ServerName} in the last {hours_back} hour(s). The blocking collectors HAVE run successfully for this server, so the window is genuinely clear rather than blind.", + (await BlockingStatsNoticeAsync(postgres, resolved.ServerName, start, end, null, null, emptyAnswer: true, logger, cancellationToken)).AsHints()) : McpHelpers.Status( "unavailable", $"The blocking collectors have NEVER run successfully for {resolved.ServerName}, so this is NOT a clean bill of health — nothing looked. Blocked-process reports need the XE session running, or the DMV blocking snapshot collector enabled; check those before concluding this server does not block."); } - return JsonSerializer.Serialize(new + /* #4966: one notice for two separate series; see BlockingStatsNoticeAsync. */ + var notice = await BlockingStatsNoticeAsync( + postgres, resolved.ServerName, start, end, + blocking.Count == 0 ? null : blocking.Min(b => b.Time), deadlocks.Count == 0 ? null : deadlocks.Min(d => d.Time), + emptyAnswer: false, logger, cancellationToken); + + var json = JsonSerializer.Serialize(new { server = resolved.ServerName, hours_back = hours_back, + effective_start = notice.EffectiveStart, + window_truncated = notice.WindowTruncated, + truncation_note = notice.TruncationNote, /* Severity, not counts. get_blocking_trend already answers how OFTEN; ten one-second blocks and one ten-minute block share a count and are different problems. @@ -2956,10 +2967,39 @@ blocks and one ten-minute block share a count and are different problems. avg_wait_ms = Math.Round(d.AvgWaitMs, 0), }), }, McpHelpers.JsonOptions); + + /* A failed probe costs the notice, never the rows (see DarlingMcpWindowNotice.ReadAsync). */ + return notice.IsUnavailable ? DarlingMcpWindowNotice.WithoutKeys(json) : json; } catch (Exception ex) when (ex is not OperationCanceledException) { return McpHelpers.FormatError("get_blocking_stats", ex); } } + + /// + /// The window-floor notice of get_blocking_stats (#4966). The answer is two SEPARATE series, so each has its own floor and the + /// notice names the LATER of them (the answer is only as complete as its least-covered series; a series with no floor gives way to + /// the other). The blocking floor is the earlier of the XE blocked process reports' and the DMV snapshots' coverage, which stand in + /// for each other; the deadlock floor is the deadlocks' coverage. Both series window on event time while the probes read + /// collection_time, and a first run of a collector can store events from before itself, so each floor also takes the + /// earlier of itself and that series' oldest bucket (, ), before + /// the later is taken. + /// + private static Task BlockingStatsNoticeAsync( + NpgsqlDataSource postgres, string serverName, DateTime start, DateTime end, DateTime? oldestBlocking, DateTime? oldestDeadlock, + bool emptyAnswer, ILogger? logger, CancellationToken cancellationToken) => + DarlingMcpWindowNotice.ReadAsync( + async () => + { + var blocking = DarlingMcpWindowNotice.Earlier( + await DarlingMcpWindowNotice.Probe(postgres, BlockingStatsBlockingSources, serverName, start, end, cancellationToken), oldestBlocking); + var deadlock = DarlingMcpWindowNotice.Earlier( + await DarlingMcpWindowNotice.Probe(postgres, "deadlocks", serverName, start, end, cancellationToken), oldestDeadlock); + return DarlingMcpWindowNotice.Later(blocking, deadlock); + }, + start, end, "blocked_process_reports, dmv_blocking_snapshots and deadlocks", emptyAnswer: emptyAnswer, logger: logger, cancellationToken: cancellationToken); + + private static readonly DataWindowFloor.Source[] BlockingStatsBlockingSources = + [DataWindowFloor.Source.ForCollectorTable("blocked_process_reports"), DataWindowFloor.Source.ForCollectorTable("dmv_blocking_snapshots")]; } diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpWindowNotice.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpWindowNotice.cs index 0d9bbc52e5..689fe4290c 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpWindowNotice.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpWindowNotice.cs @@ -132,6 +132,14 @@ internal static async Task ReadAsync( internal static DateTime? Earlier(DateTime? first, DateTime? second) => first is DateTime a && second is DateTime b ? (a <= b ? a : b) : first ?? second; + /// + /// The later of two instants, a null (nothing to report) giving way to the other; null when both are. For an answer that + /// carries two separate series (get_blocking_stats): the one notice names the later of the two floors, since the answer is + /// only as complete as its least-covered series. Lite's LocalDataService.LaterCoverageFloor. + /// + internal static DateTime? Later(DateTime? first, DateTime? second) => + first is DateTime a && second is DateTime b ? (a >= b ? a : b) : first ?? second; + /// /// for an EVENT list (deadlocks, blocked process reports, long query completions), where a first run /// of the collector can store events from before itself (#4966): the coverage probe reads the collector's table on From a2eb3364e3325e7c119adaae9f2991d8bc3d2484 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Mon, 5 Oct 2026 02:11:43 -0400 Subject: [PATCH 3/7] Tests: get_pg_deadlocks and get_pg_log_events say where their data starts (part of #4966) --- .../PgEventToolsWindowFloorLiveTests.cs | 328 ++++++++++++++++++ 1 file changed, 328 insertions(+) create mode 100644 Darling/Darling.Tests/PgEventToolsWindowFloorLiveTests.cs diff --git a/Darling/Darling.Tests/PgEventToolsWindowFloorLiveTests.cs b/Darling/Darling.Tests/PgEventToolsWindowFloorLiveTests.cs new file mode 100644 index 0000000000..b148170548 --- /dev/null +++ b/Darling/Darling.Tests/PgEventToolsWindowFloorLiveTests.cs @@ -0,0 +1,328 @@ +/* + * Copyright (c) 2026 Erik Darling, Darling Data LLC + * + * This file is part of the SQL Server Performance Monitor. + * + * Licensed under the MIT License. See LICENSE file in the project root for full license information. + */ + +using System; +using System.Linq; +using System.Text.Json; +using System.Threading; +using System.Threading.Tasks; +using Npgsql; +using PerformanceMonitor.Collectors; +using PerformanceMonitor.Common; +using PerformanceMonitor.Darling.Service; +using PerformanceMonitor.Darling.Service.Mcp; +using PerformanceMonitor.Darling.Storage; +using Xunit; + +namespace Darling.Tests; + +/// +/// #4966: where the data starts on Darling's two PostgreSQL event lists, get_pg_deadlocks and get_pg_log_events. +/// Both are sparse, newest first and capped, and both window on the event's own time, so the notice is the earlier of the +/// coverage floor and the oldest event shown, and a full page names its oldest row with no probe. Every instant is an offset +/// from one anchor minute, so the probe's purge edge never lands inside a window. +/// +public sealed class PgEventToolsWindowFloorLiveTests +{ + private static string? ConnectionString => Environment.GetEnvironmentVariable("DARLING_TEST_PG"); + + private sealed record PgTool(string Name, string Table, string ArrayKey); + + private static readonly PgTool[] Tools = + [ + new("get_pg_deadlocks", "pg_deadlocks", "deadlocks"), + new("get_pg_log_events", "pg_log_events", "events"), + ]; + + private static string ServerOf(PgTool tool, string window) => "darling-mcp-pgevt-" + window + "-" + tool.Name.Replace('_', '-'); + + private static JsonElement Parse(string json) => JsonDocument.Parse(json).RootElement.Clone(); + + private static Task CallAsync(NpgsqlDataSource postgres, PgTool tool, string server, int hours, DateTime end, int limit = 15) + { + var asOf = WebDataStartNote.FormatWindowEnd(end); + return tool.Name == "get_pg_deadlocks" + ? DarlingMcpPgDeadlockTools.GetPgDeadlocks(postgres, server, hours, limit, asOf) + : DarlingMcpPgLogEventTools.GetPgLogEvents(postgres, server, hours, null, null, limit, asOf); + } + + /// A server registered at with three events an hour apart from (none when null). + private static async Task SeedAsync( + NpgsqlConnection connection, PgTool tool, string name, DateTime created, DateTime? firstEvent, CancellationToken ct, DateTime? collectedAt = null) + { + var serverId = ServerIdHelper.GetDeterministicHashCode(name); + await DeleteAsync(connection, name, ct); + await DarlingMcpTestData.RegisterServerAsync(connection, serverId, name, ct); + await DarlingMcpTestData.ExecAsync(connection, ct, "UPDATE servers SET created_date = $2 WHERE server_id = $1", serverId, DarlingMcpTestData.Naive(created)); + if (firstEvent is not DateTime first) return; + + for (var i = 0; i < 3; i++) + { + var at = DarlingMcpTestData.Naive(first.AddHours(i)); + var collected = collectedAt is DateTime c ? DarlingMcpTestData.Naive(c) : at; + if (tool.Table == "pg_deadlocks") + { + await DarlingMcpTestData.ExecAsync(connection, ct, + @"INSERT INTO pg_deadlocks (collection_id, collection_time, server_id, server_name, occurred_at, victim_pid, participant_count, deadlock_hash, lock_modes, resources, victim_statement, graph_text) +VALUES ($1,$2,$3,$4,$5,4242,2,$6,'ShareLock','relation','UPDATE t SET x = ?','graph')", + CollectionIdGenerator.Next(), collected, serverId, name, at, "pgevt-hash-" + i); + } + else + { + await DarlingMcpTestData.ExecAsync(connection, ct, + @"INSERT INTO pg_log_events (collection_id, collection_time, server_id, server_name, occurred_at, family, severity, message, raw_line_hash) +VALUES ($1,$2,$3,$4,$5,'error','ERROR',$6,$7)", + CollectionIdGenerator.Next(), collected, serverId, name, at, "boom " + i, "pgevt-line-" + i); + } + } + } + + private static async Task DeleteAsync(NpgsqlConnection connection, string name, CancellationToken ct) + { + var serverId = ServerIdHelper.GetDeterministicHashCode(name); + foreach (var table in new[] { "pg_deadlocks", "pg_log_events", "collection_log", "servers" }) + { + await DarlingMcpTestData.ExecAsync(connection, ct, $"DELETE FROM {table} WHERE server_id = $1", serverId); + } + } + + private static async Task ForEachToolAsync(string window, Func body) + { + var cs = ConnectionString; + Assert.SkipWhen(string.IsNullOrEmpty(cs), "Set DARLING_TEST_PG to a Postgres connection string to run the live PostgreSQL event-tool test."); + + var ct = TestContext.Current.CancellationToken; + using var connection = new NpgsqlConnection(cs); + await connection.OpenAsync(ct); + await PgMigrations.MigrateAsync(connection, ct); + await using var postgres = NpgsqlDataSource.Create(cs!); + + var bodySucceeded = false; + try + { + var end = WindowFloorLiveHarness.AnchorNow(); + foreach (var tool in Tools) + { + await body(connection, postgres, tool, ServerOf(tool, window), end); + } + + bodySucceeded = true; + } + finally + { + await LiveStoreCleanup.RunAsync(cs!, bodySucceeded, async (cleanup, cleanupCt) => + { + foreach (var tool in Tools) + { + await DeleteAsync(cleanup, ServerOf(tool, window), cleanupCt); + } + }); + } + } + + /// Runs with the probe stand-in set, and clears it after. + private static async Task WithProbeAsync(Func> probe, Func act) + { + var bodySucceeded = false; + DarlingMcpWindowNotice.TestOnlyProbe = probe; + try + { + await act(); + bodySucceeded = true; + } + finally + { + await LiveStoreCleanup.RunOwnedAsync(bodySucceeded, () => + { + DarlingMcpWindowNotice.TestOnlyProbe = null; + return Task.CompletedTask; + }); + } + } + + [Fact] + public async Task ServerAddedTwoDaysAgo_NamesWhereCoverageStarts_AndKeepsTheKeyOrder_AgainstDevPostgres() + { + var ct = TestContext.Current.CancellationToken; + await ForEachToolAsync("added", async (connection, postgres, tool, name, end) => + { + var added = end.AddDays(-2); + await SeedAsync(connection, tool, name, added, end.AddDays(-1), ct); + + var root = Parse(await CallAsync(postgres, tool, name, 168, end)); + + Assert.True(root.GetProperty("window_truncated").GetBoolean(), tool.Name); + Assert.Equal(McpHelpers.FormatEffectiveStart(added), root.GetProperty("effective_start").GetString()); + Assert.Equal( + DarlingMcpWindowNotice.Build(added, end.AddHours(-168), tool.Table).TruncationNote, + root.GetProperty("truncation_note").GetString()); + Assert.Equal(3, root.GetProperty(tool.ArrayKey).GetArrayLength()); + + var names = root.EnumerateObject().Select(p => p.Name).ToList(); + var at = names.IndexOf("hours_back"); + Assert.Equal(["effective_start", "window_truncated", "truncation_note"], names.Skip(at + 1).Take(3)); + }); + } + + [Fact] + public async Task QuietStart_FirstEventLate_GivesNoNotice_AgainstDevPostgres() + { + var ct = TestContext.Current.CancellationToken; + await ForEachToolAsync("quiet", async (connection, postgres, tool, name, end) => + { + await SeedAsync(connection, tool, name, end.AddDays(-30), end.AddDays(-5), ct); + + var root = Parse(await CallAsync(postgres, tool, name, 168, end)); + + Assert.False(root.GetProperty("window_truncated").GetBoolean(), tool.Name); + Assert.Equal(JsonValueKind.Null, root.GetProperty("truncation_note").ValueKind); + }); + } + + [Fact] + public async Task AnEvent_OlderThanTheFirstCollection_MovesTheStartBackToIt_AgainstDevPostgres() + { + var ct = TestContext.Current.CancellationToken; + await ForEachToolAsync("backfill", async (connection, postgres, tool, name, end) => + { + await SeedAsync(connection, tool, name, end.AddHours(-1), end.AddHours(-23.5), ct, collectedAt: end.AddMinutes(-30)); + + var root = Parse(await CallAsync(postgres, tool, name, 24, end)); + + Assert.Equal(3, root.GetProperty(tool.ArrayKey).GetArrayLength()); + Assert.False(root.GetProperty("window_truncated").GetBoolean(), tool.Name); + Assert.Equal(JsonValueKind.Null, root.GetProperty("truncation_note").ValueKind); + Assert.Equal(McpHelpers.FormatEffectiveStart(end.AddHours(-23.5)), root.GetProperty("effective_start").GetString()); + }); + } + + [Fact] + public async Task AFullCappedPage_NamesItsOldestRowShown_WithNoProbe_AgainstDevPostgres() + { + var ct = TestContext.Current.CancellationToken; + await ForEachToolAsync("capped", async (connection, postgres, tool, name, end) => + { + /* Events at 10, 9 and 8 hours back; a page of 2 shows 8 and 9 hours back, so the answer starts 9 hours back. */ + await SeedAsync(connection, tool, name, end.AddDays(-30), end.AddHours(-10), ct); + + var probes = 0; + await WithProbeAsync(() => { probes++; throw new TimeoutException("the probe must not run"); }, async () => + { + var root = Parse(await CallAsync(postgres, tool, name, 24, end, limit: 2)); + + Assert.Equal(0, probes); + Assert.True(root.GetProperty("truncated").GetBoolean(), tool.Name); + Assert.Equal(2, root.GetProperty(tool.ArrayKey).GetArrayLength()); + Assert.True(root.GetProperty("window_truncated").GetBoolean(), tool.Name); + Assert.Equal(McpHelpers.FormatEffectiveStart(end.AddHours(-9)), root.GetProperty("effective_start").GetString()); + Assert.Contains("page is full", root.GetProperty("truncation_note").GetString(), StringComparison.Ordinal); + }); + }); + } + + [Fact] + public async Task ACappedPage_ReachingTheWindowStart_GivesNoNotice_AgainstDevPostgres() + { + var ct = TestContext.Current.CancellationToken; + await ForEachToolAsync("cappedstart", async (connection, postgres, tool, name, end) => + { + /* The page's oldest row is 22h48m back, 72 minutes past the window's start: inside the 90-minute slack. */ + await SeedAsync(connection, tool, name, end.AddDays(-30), end.AddHours(-23.8), ct); + + var root = Parse(await CallAsync(postgres, tool, name, 24, end, limit: 2)); + + Assert.True(root.GetProperty("truncated").GetBoolean(), tool.Name); + Assert.False(root.GetProperty("window_truncated").GetBoolean(), tool.Name); + Assert.Equal(JsonValueKind.Null, root.GetProperty("truncation_note").ValueKind); + }); + } + + [Fact] + public async Task AnEmptyAnswer_PastCoverage_CarriesTheNoticeUnderHints_AgainstDevPostgres() + { + var ct = TestContext.Current.CancellationToken; + await ForEachToolAsync("empty", async (connection, postgres, tool, name, end) => + { + await SeedAsync(connection, tool, name, end.AddDays(-2), null, ct); + + var root = Parse(await CallAsync(postgres, tool, name, 1, end.AddDays(-5))); + + var hints = root.GetProperty("hints"); + Assert.True(hints.GetProperty("window_truncated").GetBoolean(), tool.Name); + Assert.Equal(JsonValueKind.Null, hints.GetProperty("effective_start").ValueKind); + Assert.Contains("no collection of " + tool.Table, hints.GetProperty("truncation_note").GetString(), StringComparison.Ordinal); + Assert.False(root.TryGetProperty("window_truncated", out _), tool.Name); + }); + } + + [Fact] + public async Task NotCollected_StaysBare_AndStartsNoProbe_AgainstDevPostgres() + { + var ct = TestContext.Current.CancellationToken; + await ForEachToolAsync("notcollected", async (connection, postgres, tool, name, end) => + { + await SeedAsync(connection, tool, name, end.AddDays(-2), null, ct); + await DarlingMcpTestData.ExecAsync(connection, ct, + "UPDATE servers SET engine_kind = $2 WHERE server_id = $1", ServerIdHelper.GetDeterministicHashCode(name), MonitoredEngineKind.SqlServer); + + var probes = 0; + await WithProbeAsync(() => { probes++; throw new TimeoutException("the probe must not run"); }, async () => + { + var root = Parse(await CallAsync(postgres, tool, name, 1, end.AddDays(-5))); + + Assert.Equal("not_collected", root.GetProperty("status").GetString()); + Assert.False(root.TryGetProperty("hints", out _), tool.Name); + Assert.Equal(0, probes); + }); + }); + } + + [Fact] + public async Task AShortWindow_WithRows_StartsNoProbe_AgainstDevPostgres() + { + var ct = TestContext.Current.CancellationToken; + await ForEachToolAsync("short", async (connection, postgres, tool, name, end) => + { + await SeedAsync(connection, tool, name, end.AddDays(-30), end.AddMinutes(-40), ct); + + var probes = 0; + await WithProbeAsync(() => { probes++; throw new TimeoutException("the probe must not run"); }, async () => + { + var root = Parse(await CallAsync(postgres, tool, name, 1, end)); + + Assert.Equal(0, probes); + Assert.True(root.GetProperty(tool.ArrayKey).GetArrayLength() > 0, tool.Name); + Assert.False(root.GetProperty("window_truncated").GetBoolean(), tool.Name); + }); + }); + } + + [Fact] + public async Task AFailedProbe_CostsTheNotice_NeverTheRows_AgainstDevPostgres() + { + var ct = TestContext.Current.CancellationToken; + await ForEachToolAsync("probefail", async (connection, postgres, tool, name, end) => + { + await SeedAsync(connection, tool, name, end.AddDays(-2), end.AddDays(-1), ct); + + await WithProbeAsync(() => throw new TimeoutException("the probe's deadline passed"), async () => + { + var root = Parse(await CallAsync(postgres, tool, name, 168, end)); + + Assert.False(root.TryGetProperty("error", out _), tool.Name); + Assert.Equal(3, root.GetProperty(tool.ArrayKey).GetArrayLength()); + Assert.False(root.TryGetProperty("effective_start", out _), tool.Name); + Assert.False(root.TryGetProperty("window_truncated", out _), tool.Name); + Assert.False(root.TryGetProperty("truncation_note", out _), tool.Name); + + var empty = Parse(await CallAsync(postgres, tool, name, 1, end.AddDays(-5))); + Assert.False(empty.TryGetProperty("hints", out _), tool.Name); + }); + }); + } +} From cf144e49d2dcb67b886319dd6cc6d6070ac131e7 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Mon, 5 Oct 2026 02:12:43 -0400 Subject: [PATCH 4/7] MCP: get_pg_deadlocks and get_pg_log_events say where their data starts (part of #4966) --- .../Darling.Tests/EffectiveStartUtcTests.cs | 2 ++ .../McpPayloadContractCensusTests.cs | 6 ++--- .../Mcp/DarlingMcpPgDeadlockTools.cs | 24 +++++++++++++++-- .../Mcp/DarlingMcpPgLogEventTools.cs | 26 ++++++++++++++++--- .../Mcp/DarlingMcpWindowNotice.cs | 23 ++++++++++++++++ 5 files changed, 73 insertions(+), 8 deletions(-) diff --git a/Darling/Darling.Tests/EffectiveStartUtcTests.cs b/Darling/Darling.Tests/EffectiveStartUtcTests.cs index eb4d371c61..2c9dc52aba 100644 --- a/Darling/Darling.Tests/EffectiveStartUtcTests.cs +++ b/Darling/Darling.Tests/EffectiveStartUtcTests.cs @@ -49,6 +49,8 @@ public void FormatEffectiveStart_NamesTheInstantAsUtc_WhicheverKindItCameWith() [InlineData("DarlingMcpSessionTools.cs", 2)] [InlineData("DarlingMcpMemoryGrantTools.cs", 1)] [InlineData("DarlingMcpPlanCorrectionTools.cs", 1)] + [InlineData("DarlingMcpPgDeadlockTools.cs", 1)] + [InlineData("DarlingMcpPgLogEventTools.cs", 1)] [InlineData("DarlingMcpQueryHeatmapTools.cs", 1)] [InlineData("DarlingMcpQueryStoreRegressionTools.cs", 1)] public void EveryWindowFloorWrite_RoutesThroughTheSharedFormatter(string file, int minimumRouted) diff --git a/Darling/Darling.Tests/McpPayloadContractCensusTests.cs b/Darling/Darling.Tests/McpPayloadContractCensusTests.cs index d2106df087..832993e371 100644 --- a/Darling/Darling.Tests/McpPayloadContractCensusTests.cs +++ b/Darling/Darling.Tests/McpPayloadContractCensusTests.cs @@ -1540,7 +1540,7 @@ public static readonly (string Key, string[] Files, string WhatWasCut)[] SecondB "the dedup_key fingerprint scan's ceiling (FingerprintScanCeiling), observed off a ceiling + 1 fetch, beside the page's own truncated — two bounds in one payload, the second spelled _truncated"), ("processes_truncated", ["DarlingMcpBlockingTools.cs"], "get_deadlock_detail's processes[] is cut by two bounds, the per-deadlock cap DarlingDeadlockProcessRows.MaxProcessesPerDeadlock (12) and the default page's shared row budget (DefaultPageRowBudget, 24); the rows cut from one deadlock are counted beside it. Unlike the boolean _truncated keys around it, processes_truncated is a COUNT (0 when nothing was cut), kept under this name because it is the per-deadlock twin of the page's truncated and a reader looks for it beside processes"), - ("window_truncated", ["DarlingMcpBlockingTools.cs", "DarlingMcpConfigHistoryTools.cs", "DarlingMcpDataTools.cs", "DarlingMcpJobTools.cs", "DarlingMcpLongQueryTools.cs", "DarlingMcpMemoryGrantTools.cs", "DarlingMcpPlanCorrectionTools.cs", "DarlingMcpQueryHeatmapTools.cs", "DarlingMcpQueryStoreClutterTools.cs", "DarlingMcpQueryStoreRegressionTools.cs", "DarlingMcpSessionTools.cs", "DarlingMcpTrendTools.cs", "McpBlockingTools.cs", "McpConfigHistoryTools.cs", "McpHealthTools.cs", "McpLongQueryTools.cs", "McpMemoryTools.cs", "McpPlanCorrectionTools.cs", "McpQueryTools.cs", "McpSessionTools.cs", "McpWaitTools.cs"], + ("window_truncated", ["DarlingMcpBlockingTools.cs", "DarlingMcpConfigHistoryTools.cs", "DarlingMcpDataTools.cs", "DarlingMcpJobTools.cs", "DarlingMcpLongQueryTools.cs", "DarlingMcpMemoryGrantTools.cs", "DarlingMcpPgDeadlockTools.cs", "DarlingMcpPgLogEventTools.cs", "DarlingMcpPlanCorrectionTools.cs", "DarlingMcpQueryHeatmapTools.cs", "DarlingMcpQueryStoreClutterTools.cs", "DarlingMcpQueryStoreRegressionTools.cs", "DarlingMcpSessionTools.cs", "DarlingMcpTrendTools.cs", "McpBlockingTools.cs", "McpConfigHistoryTools.cs", "McpHealthTools.cs", "McpLongQueryTools.cs", "McpMemoryTools.cs", "McpPlanCorrectionTools.cs", "McpQueryTools.cs", "McpSessionTools.cs", "McpWaitTools.cs"], "the #2364 / #2353 WINDOW floor (#3653 item 17): the tier that answered did not hold the whole requested window, so the served series begins later than asked — beside effective_start / effective_hours_back, observed off the served head against the shared ninety-minute TruncationSlack, no cap involved; get_query_trend and get_query_store_top write it in their initializers, the duration-trend trio through TrendDisclosure.WriteTo (Darling) and WriteDisclosure (Lite); get_query_store_clutter (#3797) writes it in its initializer for its plan-churn and wait arms, which read the same raw tier get_query_store_top does, off the same window-floor read and the same ninety-minute slack; Lite's get_active_queries and get_waiting_tasks (QuerySnapshots / WaitingTasks, read by coverage), get_query_store_regressions (checked against the baseline's start, the earlier of its two windows) and get_query_heatmap (#4966) write it in their initializers through McpQueryTools.WindowNotice, beside a page cut of their own (truncated), so they publish effective_start without effective_hours_back, which the window-floor rule below holds apart for the window floor; Darling's get_server_config_changes, get_database_config_changes and get_trace_flag_changes (#4966) write them after hours_back from the coverage probe of server_config, database_config and trace_flags (the same rule as the viewer's and the web's Config Changes notes), and on their empty answer inside the hints; Darling's get_collection_log (one server), get_plan_corrections and get_memory_pressure_events (#4966) write them after hours_back too: the log from its own coverage probe, which ignores the collector, status and duration filters so the note says where the log starts, plan corrections from plan_correction's coverage, where an answer of only automatic-tuning rows is a data answer, and memory pressure from the events' sample_time with its edge at the purge cutoff, each on its empty answer inside the hints; Darling's get_active_queries, get_waiting_tasks, get_query_heatmap and get_query_store_regressions (#4966) write the same three keys after hours_back through DarlingMcpWindowNotice, with the same wording and the same absence of effective_hours_back (the regressions tool checks its baseline's start, as Lite's does); Darling's get_active_queries (DarlingMcpSessionTools.cs) writes them only when the window was cut, so a covered default call stays inside the response budget and a missing key there means covered (Lite's writes them always), and each of the four leaves them off when its coverage probe failed, since a failed probe costs the notice and never the rows; and Lite's config-change, collection-log, plan-correction and memory-pressure tools (#4966) write it as well; Darling's get_blocking, get_deadlocks, get_deadlock_detail, get_blocked_process_xml and get_long_query_completions (#4966) write the three keys after hours_back through DarlingMcpWindowNotice.ReadEventAsync, beside a page cut of their own (truncated), and leave them off when the coverage probe failed"), ("findings_truncated", ["DarlingMcpTools.cs", "McpAnalysisTools.cs"], "#4198: get_analysis_findings' GROUP PAGE cut — limit caps the collapsed per-chain groups returned (default 18), independent of the pre-existing truncated above (the raw WindowCoveringLimit occurrence read, beside truncation_note): truncated warns occurrence stats may under-report, findings_truncated warns other diagnostic chains exist but are not on this page at all"), @@ -1548,8 +1548,8 @@ public static readonly (string Key, string[] Files, string WhatWasCut)[] SecondB public static readonly (string Key, string[] Files, string WhatItExplains)[] CutNoteKeys = [ - ("truncation_note", ["DarlingMcpBlockingTools.cs", "DarlingMcpConfigHistoryTools.cs", "DarlingMcpDataTools.cs", "DarlingMcpLongQueryTools.cs", "DarlingMcpMemoryGrantTools.cs", "DarlingMcpPlanCorrectionTools.cs", "DarlingMcpQueryHeatmapTools.cs", "DarlingMcpQueryStoreClutterTools.cs", "DarlingMcpQueryStoreRegressionTools.cs", "DarlingMcpSessionTools.cs", "DarlingMcpTools.cs", "McpAnalysisTools.cs", "McpBlockingTools.cs", "McpConfigHistoryTools.cs", "McpHealthTools.cs", "McpLongQueryTools.cs", "McpMemoryTools.cs", "McpPlanCorrectionTools.cs", "McpQueryTools.cs", "McpSessionTools.cs", "McpWaitTools.cs"], - "the prose beside the flag: on get_analysis_findings (both SKUs) beside truncated, the WindowCoveringLimit read cap observed off a cap + 1 fetch; on get_query_store_top and get_query_store_clutter beside window_truncated, the #2364 window floor — the store's raw retention did not reach the whole requested window (on the clutter view, for the two arms that read the raw tier); on Lite's get_top_queries_by_cpu / get_top_procedures_by_cpu / get_query_store_top (#4231), the same window-floor note, from LocalDataService.GetQueryWindowFloorAsync; and on Lite's get_active_queries, get_waiting_tasks, get_query_store_regressions and get_query_heatmap (#4966), the same note beside window_truncated, built by McpQueryTools.WindowNotice with the table each one read; and on Darling's get_active_queries, get_waiting_tasks, get_query_heatmap and get_query_store_regressions (#4966), the same note beside window_truncated, built by DarlingMcpWindowNotice with the table each one read (query_snapshots, waiting_tasks, query_stats, query_store_stats); and Lite's config-change, collection-log, plan-correction and memory-pressure tools (#4966), the same note from the coverage probe; and Darling's get_blocking, get_deadlocks, get_deadlock_detail, get_blocked_process_xml and get_long_query_completions (#4966), the same note, built by DarlingMcpWindowNotice with the collector table each one read"), + ("truncation_note", ["DarlingMcpBlockingTools.cs", "DarlingMcpConfigHistoryTools.cs", "DarlingMcpDataTools.cs", "DarlingMcpLongQueryTools.cs", "DarlingMcpMemoryGrantTools.cs", "DarlingMcpPgDeadlockTools.cs", "DarlingMcpPgLogEventTools.cs", "DarlingMcpPlanCorrectionTools.cs", "DarlingMcpQueryHeatmapTools.cs", "DarlingMcpQueryStoreClutterTools.cs", "DarlingMcpQueryStoreRegressionTools.cs", "DarlingMcpSessionTools.cs", "DarlingMcpTools.cs", "McpAnalysisTools.cs", "McpBlockingTools.cs", "McpConfigHistoryTools.cs", "McpHealthTools.cs", "McpLongQueryTools.cs", "McpMemoryTools.cs", "McpPlanCorrectionTools.cs", "McpQueryTools.cs", "McpSessionTools.cs", "McpWaitTools.cs"], + "the prose beside the flag: on get_analysis_findings (both SKUs) beside truncated, the WindowCoveringLimit read cap observed off a cap + 1 fetch; on get_query_store_top and get_query_store_clutter beside window_truncated, the #2364 window floor — the store's raw retention did not reach the whole requested window (on the clutter view, for the two arms that read the raw tier); on Lite's get_top_queries_by_cpu / get_top_procedures_by_cpu / get_query_store_top (#4231), the same window-floor note, from LocalDataService.GetQueryWindowFloorAsync; and on Lite's get_active_queries, get_waiting_tasks, get_query_store_regressions and get_query_heatmap (#4966), the same note beside window_truncated, built by McpQueryTools.WindowNotice with the table each one read; and on Darling's get_active_queries, get_waiting_tasks, get_query_heatmap and get_query_store_regressions (#4966), the same note beside window_truncated, built by DarlingMcpWindowNotice with the table each one read (query_snapshots, waiting_tasks, query_stats, query_store_stats); and Lite's config-change, collection-log, plan-correction and memory-pressure tools (#4966), the same note from the coverage probe; and Darling's get_blocking, get_deadlocks, get_deadlock_detail, get_blocked_process_xml and get_long_query_completions (#4966), the same note, built by DarlingMcpWindowNotice with the collector table each one read; and on Darling's get_pg_deadlocks and get_pg_log_events (#4966), the same note beside window_truncated on a sparse newest-first event list, from the earlier of the coverage floor and the oldest event shown, or the oldest row of a full page"), ("findings_truncated_note", ["DarlingMcpTools.cs", "McpAnalysisTools.cs"], "#4198: the prose beside findings_truncated — how many diagnostic chains were active in the window and that raising limit or narrowing hours_back would show more of them"), ]; diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgDeadlockTools.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgDeadlockTools.cs index e225ae308b..7feb342863 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgDeadlockTools.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgDeadlockTools.cs @@ -7,6 +7,7 @@ using System.Text.Json; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using ModelContextProtocol.Server; using Npgsql; using PerformanceMonitor.Common; @@ -81,6 +82,7 @@ public static async Task GetPgDeadlocks( [Description("Hours of history to analyze. Default 24.")] int hours_back = 24, [Description("Maximum deadlocks to return. Default 25. See the tool's reading guide.")] int limit = 25, [Description(McpHelpers.AsOfDescription)] string? as_of = null, + ILogger? logger = null, CancellationToken cancellationToken = default) { var (resolved, error) = await DarlingServerResolver.ResolveOrErrorAsync(postgres, server_name, cancellationToken); @@ -94,6 +96,7 @@ public static async Task GetPgDeadlocks( try { + var windowStart = windowEnd.AddHours(-hours_back); /* #3653 (the #3541 A3 class, the residue #3679 named): the caller's limit + 1 as the fetch, the extra row as the OBSERVED truncation signal. This used to publish `rows.Count >= limit`, which says "more" for a window holding exactly `limit` distinct deadlocks - the one case an @@ -116,15 +119,29 @@ public static async Task GetPgDeadlocks( postgres, resolved.ServerId, resolved.ServerName, "pg_deadlocks", cancellationToken) ?? await DarlingRuntimePrecondition.StatusAsync( postgres, resolved.ServerId, resolved.ServerName, "pg_deadlocks", cancellationToken) + /* #4966: not_collected and the precondition stay bare; a quiet answer carries the window keys under hints. */ ?? McpHelpers.Status( "no_deadlocks", - NoDeadlocksText(resolved.ServerName, hours_back)); + NoDeadlocksText(resolved.ServerName, hours_back), + (await DarlingMcpWindowNotice.ReadEventAsync( + () => DarlingMcpWindowNotice.Probe(postgres, "pg_deadlocks", resolved.ServerName, windowStart, windowEnd, cancellationToken), + null, windowStart, windowEnd, "pg_deadlocks", emptyAnswer: true, logger: logger, cancellationToken: cancellationToken)).AsHints()); } - return JsonSerializer.Serialize(new + /* #4966: a sparse event list kept newest first, windowed on the event's own time. A full page starts at its oldest row + (no probe); otherwise the floor is the earlier of the coverage probe (sparse, so the schedule's retention edge and the + server's first collection, never an oldest row) and the oldest event shown (a first run stores events from before itself). */ + var notice = await DarlingMcpWindowNotice.ReadEventPageAsync( + () => DarlingMcpWindowNotice.Probe(postgres, "pg_deadlocks", resolved.ServerName, windowStart, windowEnd, cancellationToken), + rows.Min(r => r.OccurredAtUtc), truncated, windowStart, windowEnd, "pg_deadlocks", logger: logger, cancellationToken: cancellationToken); + + var json = JsonSerializer.Serialize(new { server = resolved.ServerName, hours_back, + effective_start = notice.EffectiveStart, + window_truncated = notice.WindowTruncated, + truncation_note = notice.TruncationNote, status = "deadlocks", deadlock_count = rows.Count, truncated, @@ -143,6 +160,9 @@ is usually the only end anybody noticed. */ times_seen = r.TimesSeen, }), }, McpHelpers.JsonOptions); + + /* A failed probe costs the notice, never the rows (see DarlingMcpWindowNotice.ReadAsync). */ + return notice.IsUnavailable ? DarlingMcpWindowNotice.WithoutKeys(json) : json; } catch (Exception ex) when (ex is not OperationCanceledException) { diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgLogEventTools.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgLogEventTools.cs index 44da243c2f..f49e7c8a1c 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgLogEventTools.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgLogEventTools.cs @@ -12,6 +12,7 @@ using System.Text.Json; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using ModelContextProtocol.Server; using Npgsql; using PerformanceMonitor.Collectors; @@ -36,6 +37,7 @@ public static async Task GetPgLogEvents( [Description("Lowest severity to return, by seriousness: LOG, INFO, NOTICE, WARNING, ERROR, FATAL, PANIC. Default LOG (everything). See the tool's reading guide.")] string? min_severity = null, [Description("Maximum events to return. Default 50. The page is truncated when the window holds more; total_events is the window's count.")] int limit = 50, [Description(McpHelpers.AsOfDescription)] string? as_of = null, + ILogger? logger = null, CancellationToken cancellationToken = default) { var (resolved, error) = await DarlingServerResolver.ResolveOrErrorAsync(postgres, server_name, cancellationToken); @@ -73,10 +75,11 @@ public static async Task GetPgLogEvents( try { + var windowStart = windowEnd.AddHours(-hours_back); /* limit + 1 so truncation is OBSERVED from the extra row rather than inferred from the count reaching the cap (#3594). */ var page = await DarlingPgLogEventReader.GetEventsAsync( - postgres, resolved.ServerId, windowEnd.AddHours(-hours_back), windowEnd, + postgres, resolved.ServerId, windowStart, windowEnd, familyFilter, minRank, limit + 1, cancellationToken); if (page.Rows.Count == 0) @@ -91,6 +94,7 @@ the cap (#3594). */ postgres, resolved.ServerId, resolved.ServerName, "pg_log_events", cancellationToken) ?? await DarlingRuntimePrecondition.StatusAsync( postgres, resolved.ServerId, resolved.ServerName, "pg_log_events", cancellationToken) + /* #4966: not_collected and the precondition stay bare; a quiet answer carries the window keys under hints. */ ?? McpHelpers.Status( "no_events", $"No log event{(familyFilter is null ? string.Empty : $" in family '{familyFilter}'")}" @@ -108,16 +112,29 @@ the cap (#3594). */ + "FEHLER: line matches nothing - the readiness read's message_locale facet). " + "pg_stat_database's counters in get_pg_database_stats are the independent check " + "for the error and temp_file families: if they moved and nothing is here, the log " - + "is the problem rather than the server."); + + "is the problem rather than the server.", + (await DarlingMcpWindowNotice.ReadEventAsync( + () => DarlingMcpWindowNotice.Probe(postgres, "pg_log_events", resolved.ServerName, windowStart, windowEnd, cancellationToken), + null, windowStart, windowEnd, "pg_log_events", emptyAnswer: true, logger: logger, cancellationToken: cancellationToken)).AsHints()); } var truncated = page.Rows.Count > limit; var rows = truncated ? page.Rows.Take(limit).ToList() : page.Rows.ToList(); - return JsonSerializer.Serialize(new + /* #4966: a sparse event list kept newest first, windowed on the event's own time. A full page starts at its oldest row + (no probe); otherwise the floor is the earlier of the coverage probe (the schedule's retention edge and the server's first + collection, never an oldest row) and the oldest event shown (a first run stores events from before itself). */ + var notice = await DarlingMcpWindowNotice.ReadEventPageAsync( + () => DarlingMcpWindowNotice.Probe(postgres, "pg_log_events", resolved.ServerName, windowStart, windowEnd, cancellationToken), + rows.Min(r => r.OccurredAtUtc), truncated, windowStart, windowEnd, "pg_log_events", logger: logger, cancellationToken: cancellationToken); + + var json = JsonSerializer.Serialize(new { server = resolved.ServerName, hours_back, + effective_start = notice.EffectiveStart, + window_truncated = notice.WindowTruncated, + truncation_note = notice.TruncationNote, family = familyFilter, min_severity = severityLabel, status = "events", @@ -171,6 +188,9 @@ the cap (#3594). */ : null, }), }, McpHelpers.JsonOptions); + + /* A failed probe costs the notice, never the rows (see DarlingMcpWindowNotice.ReadAsync). */ + return notice.IsUnavailable ? DarlingMcpWindowNotice.WithoutKeys(json) : json; } catch (Exception ex) when (ex is not OperationCanceledException) { diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpWindowNotice.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpWindowNotice.cs index 0d9bbc52e5..90f329e48f 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpWindowNotice.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpWindowNotice.cs @@ -152,6 +152,29 @@ internal static Task ReadEventAsync( requestedStart, windowEnd, table, emptyAnswer: emptyAnswer, logger: logger, cancellationToken: cancellationToken); } + /// + /// for an event list that keeps its NEWEST limit rows (#4966). A full page + /// (, observed from the limit + 1 fetch) stops at its oldest row whatever the store covers, so that + /// row IS where the answer starts: the notice names it, with no probe (the rows say it), as the viewer's grid does when its read + /// hits its cap (ViewerEventDataStart.Of). The Service does not reference the viewer, so the rule is restated here. A page + /// under its cap keeps 's rule: the earlier of the coverage floor and the oldest event shown. + /// A capped page that reaches the window's start (within the slack) gives no notice. + /// + internal static Task ReadEventPageAsync( + Func> probe, DateTime? oldestEventShown, bool pageFull, DateTime requestedStart, DateTime windowEnd, string table, + ILogger? logger = null, CancellationToken cancellationToken = default) + { + ArgumentNullException.ThrowIfNull(probe); + if (pageFull && oldestEventShown is DateTime oldest) + { + return Task.FromResult(Build( + oldest, requestedStart, table, + "The page is full, so the events older than its oldest row were not read: raise limit or narrow the window.")); + } + + return ReadEventAsync(probe, oldestEventShown, requestedStart, windowEnd, table, logger: logger, cancellationToken: cancellationToken); + } + /// /// A payload already serialized with the three window-floor keys, without them: what a tool answers when its probe failed /// (). Only top-level keys are touched, and the order of the rest is kept. From fb6ae999e0c6c2d5eefcfe70ba673316c007ea28 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Mon, 5 Oct 2026 02:28:42 -0400 Subject: [PATCH 5/7] Give the PostgreSQL event lists the coverage notice on a capped page too (#4966) Drop ReadEventPageAsync; the deadlock and log-event reads call ReadEventAsync, as get_deadlocks does. The cap is reported by truncated. --- .../PgEventToolsWindowFloorLiveTests.cs | 46 +++++++++---------- .../Mcp/DarlingMcpPgDeadlockTools.cs | 8 ++-- .../Mcp/DarlingMcpPgLogEventTools.cs | 10 ++-- .../Mcp/DarlingMcpWindowNotice.cs | 23 ---------- 4 files changed, 32 insertions(+), 55 deletions(-) diff --git a/Darling/Darling.Tests/PgEventToolsWindowFloorLiveTests.cs b/Darling/Darling.Tests/PgEventToolsWindowFloorLiveTests.cs index b148170548..f1c092b416 100644 --- a/Darling/Darling.Tests/PgEventToolsWindowFloorLiveTests.cs +++ b/Darling/Darling.Tests/PgEventToolsWindowFloorLiveTests.cs @@ -23,8 +23,8 @@ namespace Darling.Tests; /// /// #4966: where the data starts on Darling's two PostgreSQL event lists, get_pg_deadlocks and get_pg_log_events. -/// Both are sparse, newest first and capped, and both window on the event's own time, so the notice is the earlier of the -/// coverage floor and the oldest event shown, and a full page names its oldest row with no probe. Every instant is an offset +/// Both are sparse, newest first and capped, and both window on the event's own time, so the notice is always coverage: the earlier of the +/// coverage floor and the oldest event shown, whether or not the cap cut the page (the cap is reported by truncated). Every instant is an offset /// from one anchor minute, so the probe's purge edge never lands inside a window. /// public sealed class PgEventToolsWindowFloorLiveTests @@ -202,43 +202,43 @@ await ForEachToolAsync("backfill", async (connection, postgres, tool, name, end) } [Fact] - public async Task AFullCappedPage_NamesItsOldestRowShown_WithNoProbe_AgainstDevPostgres() + public async Task AFullCappedPage_BesideAnEarlyCoverage_ReadsCovered_WhileTruncatedIsTrue_AgainstDevPostgres() { var ct = TestContext.Current.CancellationToken; await ForEachToolAsync("capped", async (connection, postgres, tool, name, end) => { - /* Events at 10, 9 and 8 hours back; a page of 2 shows 8 and 9 hours back, so the answer starts 9 hours back. */ + /* Events at 10, 9 and 8 hours back, a page of 2, and a server registered 30 days ago: the cap is reported by truncated, + and the notice is coverage, which reaches back past the window's start. */ await SeedAsync(connection, tool, name, end.AddDays(-30), end.AddHours(-10), ct); - var probes = 0; - await WithProbeAsync(() => { probes++; throw new TimeoutException("the probe must not run"); }, async () => - { - var root = Parse(await CallAsync(postgres, tool, name, 24, end, limit: 2)); + var root = Parse(await CallAsync(postgres, tool, name, 24, end, limit: 2)); - Assert.Equal(0, probes); - Assert.True(root.GetProperty("truncated").GetBoolean(), tool.Name); - Assert.Equal(2, root.GetProperty(tool.ArrayKey).GetArrayLength()); - Assert.True(root.GetProperty("window_truncated").GetBoolean(), tool.Name); - Assert.Equal(McpHelpers.FormatEffectiveStart(end.AddHours(-9)), root.GetProperty("effective_start").GetString()); - Assert.Contains("page is full", root.GetProperty("truncation_note").GetString(), StringComparison.Ordinal); - }); + Assert.True(root.GetProperty("truncated").GetBoolean(), tool.Name); + Assert.Equal(2, root.GetProperty(tool.ArrayKey).GetArrayLength()); + Assert.False(root.GetProperty("window_truncated").GetBoolean(), tool.Name); + Assert.Equal(JsonValueKind.Null, root.GetProperty("truncation_note").ValueKind); }); } [Fact] - public async Task ACappedPage_ReachingTheWindowStart_GivesNoNotice_AgainstDevPostgres() + public async Task ACappedPage_BesideALateCoverage_NamesTheEarlierOfTheCoverageAndTheOldestEventShown_AgainstDevPostgres() { var ct = TestContext.Current.CancellationToken; - await ForEachToolAsync("cappedstart", async (connection, postgres, tool, name, end) => + await ForEachToolAsync("cappedlate", async (connection, postgres, tool, name, end) => { - /* The page's oldest row is 22h48m back, 72 minutes past the window's start: inside the 90-minute slack. */ - await SeedAsync(connection, tool, name, end.AddDays(-30), end.AddHours(-23.8), ct); + /* The page of 2 shows the events 8 and 9 hours back; coverage starts 6 hours back, later than both, so the answer starts + at the oldest event shown. */ + await SeedAsync(connection, tool, name, end.AddDays(-30), end.AddHours(-10), ct); - var root = Parse(await CallAsync(postgres, tool, name, 24, end, limit: 2)); + await WithProbeAsync(() => Task.FromResult(end.AddHours(-6)), async () => + { + var root = Parse(await CallAsync(postgres, tool, name, 24, end, limit: 2)); - Assert.True(root.GetProperty("truncated").GetBoolean(), tool.Name); - Assert.False(root.GetProperty("window_truncated").GetBoolean(), tool.Name); - Assert.Equal(JsonValueKind.Null, root.GetProperty("truncation_note").ValueKind); + Assert.True(root.GetProperty("truncated").GetBoolean(), tool.Name); + Assert.True(root.GetProperty("window_truncated").GetBoolean(), tool.Name); + Assert.Equal(McpHelpers.FormatEffectiveStart(end.AddHours(-9)), root.GetProperty("effective_start").GetString()); + Assert.NotEqual(JsonValueKind.Null, root.GetProperty("truncation_note").ValueKind); + }); }); } diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgDeadlockTools.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgDeadlockTools.cs index 7feb342863..b1a50d8543 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgDeadlockTools.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgDeadlockTools.cs @@ -128,12 +128,12 @@ public static async Task GetPgDeadlocks( null, windowStart, windowEnd, "pg_deadlocks", emptyAnswer: true, logger: logger, cancellationToken: cancellationToken)).AsHints()); } - /* #4966: a sparse event list kept newest first, windowed on the event's own time. A full page starts at its oldest row - (no probe); otherwise the floor is the earlier of the coverage probe (sparse, so the schedule's retention edge and the + /* #4966: the notice is always COVERAGE, whether or not the cap cut the page (the cap is reported by truncated). A sparse event + list windowed on the event's own time: the floor is the earlier of the coverage probe (the schedule's retention edge and the server's first collection, never an oldest row) and the oldest event shown (a first run stores events from before itself). */ - var notice = await DarlingMcpWindowNotice.ReadEventPageAsync( + var notice = await DarlingMcpWindowNotice.ReadEventAsync( () => DarlingMcpWindowNotice.Probe(postgres, "pg_deadlocks", resolved.ServerName, windowStart, windowEnd, cancellationToken), - rows.Min(r => r.OccurredAtUtc), truncated, windowStart, windowEnd, "pg_deadlocks", logger: logger, cancellationToken: cancellationToken); + rows.Min(r => r.OccurredAtUtc), windowStart, windowEnd, "pg_deadlocks", logger: logger, cancellationToken: cancellationToken); var json = JsonSerializer.Serialize(new { diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgLogEventTools.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgLogEventTools.cs index f49e7c8a1c..5afb83595f 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgLogEventTools.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgLogEventTools.cs @@ -121,12 +121,12 @@ the cap (#3594). */ var truncated = page.Rows.Count > limit; var rows = truncated ? page.Rows.Take(limit).ToList() : page.Rows.ToList(); - /* #4966: a sparse event list kept newest first, windowed on the event's own time. A full page starts at its oldest row - (no probe); otherwise the floor is the earlier of the coverage probe (the schedule's retention edge and the server's first - collection, never an oldest row) and the oldest event shown (a first run stores events from before itself). */ - var notice = await DarlingMcpWindowNotice.ReadEventPageAsync( + /* #4966: the notice is always COVERAGE, whether or not the cap cut the page (the cap is reported by truncated). A sparse event + list windowed on the event's own time: the floor is the earlier of the coverage probe (the schedule's retention edge and the + server's first collection, never an oldest row) and the oldest event shown (a first run stores events from before itself). */ + var notice = await DarlingMcpWindowNotice.ReadEventAsync( () => DarlingMcpWindowNotice.Probe(postgres, "pg_log_events", resolved.ServerName, windowStart, windowEnd, cancellationToken), - rows.Min(r => r.OccurredAtUtc), truncated, windowStart, windowEnd, "pg_log_events", logger: logger, cancellationToken: cancellationToken); + rows.Min(r => r.OccurredAtUtc), windowStart, windowEnd, "pg_log_events", logger: logger, cancellationToken: cancellationToken); var json = JsonSerializer.Serialize(new { diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpWindowNotice.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpWindowNotice.cs index 90f329e48f..0d9bbc52e5 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpWindowNotice.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpWindowNotice.cs @@ -152,29 +152,6 @@ internal static Task ReadEventAsync( requestedStart, windowEnd, table, emptyAnswer: emptyAnswer, logger: logger, cancellationToken: cancellationToken); } - /// - /// for an event list that keeps its NEWEST limit rows (#4966). A full page - /// (, observed from the limit + 1 fetch) stops at its oldest row whatever the store covers, so that - /// row IS where the answer starts: the notice names it, with no probe (the rows say it), as the viewer's grid does when its read - /// hits its cap (ViewerEventDataStart.Of). The Service does not reference the viewer, so the rule is restated here. A page - /// under its cap keeps 's rule: the earlier of the coverage floor and the oldest event shown. - /// A capped page that reaches the window's start (within the slack) gives no notice. - /// - internal static Task ReadEventPageAsync( - Func> probe, DateTime? oldestEventShown, bool pageFull, DateTime requestedStart, DateTime windowEnd, string table, - ILogger? logger = null, CancellationToken cancellationToken = default) - { - ArgumentNullException.ThrowIfNull(probe); - if (pageFull && oldestEventShown is DateTime oldest) - { - return Task.FromResult(Build( - oldest, requestedStart, table, - "The page is full, so the events older than its oldest row were not read: raise limit or narrow the window.")); - } - - return ReadEventAsync(probe, oldestEventShown, requestedStart, windowEnd, table, logger: logger, cancellationToken: cancellationToken); - } - /// /// A payload already serialized with the three window-floor keys, without them: what a tool answers when its probe failed /// (). Only top-level keys are touched, and the order of the rest is kept. From 59489c8b8077e2f687b0b602935a2ee502d262e8 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Mon, 5 Oct 2026 02:46:25 -0400 Subject: [PATCH 6/7] Tests: the PG event tools' census prose says the notice is coverage whatever the cap, and name the blocking-stats event test for what it proves --- Darling/Darling.Tests/DarlingBlockingStatsReadTests.cs | 2 +- Darling/Darling.Tests/McpPayloadContractCensusTests.cs | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/Darling/Darling.Tests/DarlingBlockingStatsReadTests.cs b/Darling/Darling.Tests/DarlingBlockingStatsReadTests.cs index e78afc774a..0e978b7750 100644 --- a/Darling/Darling.Tests/DarlingBlockingStatsReadTests.cs +++ b/Darling/Darling.Tests/DarlingBlockingStatsReadTests.cs @@ -238,7 +238,7 @@ await RunWindowAsync("both", async (c, ds, end) => }); [Fact] - public async Task AnEventOlderThanItsCollection_MovesThatSeriesFloorEarlier_AgainstDevPostgres() => + public async Task AnEventOlderThanItsCollection_MovesTheFloorEarlier_AgainstDevPostgres() => await RunWindowAsync("early", async (c, ds, end) => { await SeedWindowAsync(c, "early", end, end.AddHours(-10)); diff --git a/Darling/Darling.Tests/McpPayloadContractCensusTests.cs b/Darling/Darling.Tests/McpPayloadContractCensusTests.cs index 1b083fb640..ea889e2cd0 100644 --- a/Darling/Darling.Tests/McpPayloadContractCensusTests.cs +++ b/Darling/Darling.Tests/McpPayloadContractCensusTests.cs @@ -1549,7 +1549,7 @@ public static readonly (string Key, string[] Files, string WhatWasCut)[] SecondB public static readonly (string Key, string[] Files, string WhatItExplains)[] CutNoteKeys = [ ("truncation_note", ["DarlingMcpBlockingTools.cs", "DarlingMcpConfigHistoryTools.cs", "DarlingMcpDataTools.cs", "DarlingMcpLongQueryTools.cs", "DarlingMcpMemoryGrantTools.cs", "DarlingMcpPgDeadlockTools.cs", "DarlingMcpPgLogEventTools.cs", "DarlingMcpPlanCorrectionTools.cs", "DarlingMcpQueryHeatmapTools.cs", "DarlingMcpQueryStoreClutterTools.cs", "DarlingMcpQueryStoreRegressionTools.cs", "DarlingMcpSessionTools.cs", "DarlingMcpTools.cs", "McpAnalysisTools.cs", "McpBlockingTools.cs", "McpConfigHistoryTools.cs", "McpHealthTools.cs", "McpLongQueryTools.cs", "McpMemoryTools.cs", "McpPlanCorrectionTools.cs", "McpQueryTools.cs", "McpSessionTools.cs", "McpWaitTools.cs"], - "the prose beside the flag: on get_analysis_findings (both SKUs) beside truncated, the WindowCoveringLimit read cap observed off a cap + 1 fetch; on get_query_store_top and get_query_store_clutter beside window_truncated, the #2364 window floor — the store's raw retention did not reach the whole requested window (on the clutter view, for the two arms that read the raw tier); on Lite's get_top_queries_by_cpu / get_top_procedures_by_cpu / get_query_store_top (#4231), the same window-floor note, from LocalDataService.GetQueryWindowFloorAsync; and on Lite's get_active_queries, get_waiting_tasks, get_query_store_regressions and get_query_heatmap (#4966), the same note beside window_truncated, built by McpQueryTools.WindowNotice with the table each one read; and on Darling's get_active_queries, get_waiting_tasks, get_query_heatmap and get_query_store_regressions (#4966), the same note beside window_truncated, built by DarlingMcpWindowNotice with the table each one read (query_snapshots, waiting_tasks, query_stats, query_store_stats); and Lite's config-change, collection-log, plan-correction and memory-pressure tools (#4966), the same note from the coverage probe; and Darling's get_blocking, get_deadlocks, get_deadlock_detail, get_blocked_process_xml and get_long_query_completions (#4966), the same note, built by DarlingMcpWindowNotice with the collector table each one read; and on Darling's get_pg_deadlocks and get_pg_log_events (#4966), the same note beside window_truncated on a sparse newest-first event list, from the earlier of the coverage floor and the oldest event shown, or the oldest row of a full page"), + "the prose beside the flag: on get_analysis_findings (both SKUs) beside truncated, the WindowCoveringLimit read cap observed off a cap + 1 fetch; on get_query_store_top and get_query_store_clutter beside window_truncated, the #2364 window floor — the store's raw retention did not reach the whole requested window (on the clutter view, for the two arms that read the raw tier); on Lite's get_top_queries_by_cpu / get_top_procedures_by_cpu / get_query_store_top (#4231), the same window-floor note, from LocalDataService.GetQueryWindowFloorAsync; and on Lite's get_active_queries, get_waiting_tasks, get_query_store_regressions and get_query_heatmap (#4966), the same note beside window_truncated, built by McpQueryTools.WindowNotice with the table each one read; and on Darling's get_active_queries, get_waiting_tasks, get_query_heatmap and get_query_store_regressions (#4966), the same note beside window_truncated, built by DarlingMcpWindowNotice with the table each one read (query_snapshots, waiting_tasks, query_stats, query_store_stats); and Lite's config-change, collection-log, plan-correction and memory-pressure tools (#4966), the same note from the coverage probe; and Darling's get_blocking, get_deadlocks, get_deadlock_detail, get_blocked_process_xml and get_long_query_completions (#4966), the same note, built by DarlingMcpWindowNotice with the collector table each one read; and on Darling's get_pg_deadlocks and get_pg_log_events (#4966), the same note beside window_truncated on a sparse newest-first event list, from the earlier of the coverage floor and the oldest event shown, whether or not the cap cut the page (the answer reports the cap through truncated)"), ("findings_truncated_note", ["DarlingMcpTools.cs", "McpAnalysisTools.cs"], "#4198: the prose beside findings_truncated — how many diagnostic chains were active in the window and that raising limit or narrowing hours_back would show more of them"), ]; From cc01507e22f6818eac31e349913271bf93938b0f Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Mon, 5 Oct 2026 04:47:50 -0400 Subject: [PATCH 7/7] Tests: the PG event tools' window-floor live class joins the live-postgres collection --- Darling/Darling.Tests/PgEventToolsWindowFloorLiveTests.cs | 1 + 1 file changed, 1 insertion(+) diff --git a/Darling/Darling.Tests/PgEventToolsWindowFloorLiveTests.cs b/Darling/Darling.Tests/PgEventToolsWindowFloorLiveTests.cs index f1c092b416..279971e384 100644 --- a/Darling/Darling.Tests/PgEventToolsWindowFloorLiveTests.cs +++ b/Darling/Darling.Tests/PgEventToolsWindowFloorLiveTests.cs @@ -27,6 +27,7 @@ namespace Darling.Tests; /// coverage floor and the oldest event shown, whether or not the cap cut the page (the cap is reported by truncated). Every instant is an offset /// from one anchor minute, so the probe's purge edge never lands inside a window. /// +[Collection("live-postgres")] public sealed class PgEventToolsWindowFloorLiveTests { private static string? ConnectionString => Environment.GetEnvironmentVariable("DARLING_TEST_PG");