Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -108,6 +108,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0

### Fixed
- **The Plan Viewer's inner tab handler is now subscribed once, not re-subscribed on every reopen** ([#2828]) - the shared `StandalonePlanViewerController` wired the inner plan `TabControl`'s `SelectionChanged` handler inside `EnsureInitialized`, and `Reset()` (Plan Viewer close) re-arms that path by clearing the `_initialized` guard. The controller instance and its `TabControl` both persist across open/close cycles, so each reopen added another handler to the same control - N cycles leaked N handlers. Not a crash and not a double-add: the #2825 `_addTabInsertDeferred` one-shot latch collapses the duplicate invocations to a single add, so this was a delegate/CPU leak rather than a correctness bug, which is why it was filed separately. The subscription now lives in the constructor, wired exactly once for the controller's lifetime; the first `EnsureInitialized`'s `Items.Add` still fires it once while it is live, which defers-then-no-ops through the same latch. The deprecated Dashboard is unaffected - it builds a fresh `TabControl` per open and nulls it on close, so it never accumulated.
- **The plan-regression analysis read had no command deadline, so it inherited one nobody chose** ([#2810]) - every one of `PgFactCollector`'s thirty-one commands ran with no `CommandTimeout`, taking Npgsql's undocumented 30s default. Nobody picked 30s; it was simply what happened, and on the largest servers `PlanRegressionSql` needed more. Two earlier changes aimed elsewhere and neither could have fixed it: [#2827] made the query 2.4x faster and [#2826] made the failure visible, but the binding constraint was a ceiling neither touched. Measured on the production store AFTER retention was restored ([#2809]) and with [#2827] in place, the read still crosses 30s on a COLD run - 34.7s and 32.4s on the two largest servers, against 10.6-21.2s for those same servers warm, so it fails on the cold/large combination only. That is why it presented as intermittent rather than broken, and why the store's own log showed cancellations while the query looked fast whenever anyone measured it by hand - a warm second run is the one you get when you go looking. **60s, and the upper bound is the one that matters.** Below, it must clear the 34.7s cold worst case or the defect reproduces. Above, `DarlingWorker.s_analysisTimeout` gives the WHOLE analysis pass 120s and thirty collect methods share it, so a per-command deadline near that figure would let one stalled read consume the pass and cost the server its other twenty-nine facts - converting "one fact is missing" into "every fact is missing", strictly worse than the failure being fixed. 60s clears the measured worst case by 1.7x and still leaves half the pass for everything else. Applied to all thirty-one commands rather than the one that exposed it: they share the same pass budget and had the same missing value, and pinning one site while leaving thirty identical ones is the enumerated-list mistake this repo has paid for twice ([#2344], `PgStatementText`). A generous ceiling is inert on a query that returns in milliseconds. Pinned structurally - every command constructed in the collector must set a deadline, and the value must sit in the band where both bounds hold - and proven red three ways: reverting one site, restoring the 30s default, and raising it to the full 120s pass each fail a different assertion. No query, schedule or retention change.
- **Managed-store Postgres sizing now re-derives when the HOST changes, not only when the formula does** ([#2845]) - every conf heal block from v1 to v7 is keyed on "is this marker absent?", a question answered once in a cluster's life, so nothing re-derived when the machine underneath it was replaced. All three monitoring boxes were resized 16 GB -> 31.5 GB and kept `effective_cache_size` at 11.86 GB - 75% of the RAM they no longer had - which biases the planner toward sequential scans on a store serving on the order of 670k small index lookups a day. The new v8 block is keyed on a FINGERPRINT of the derivation inputs (RAM and hypertable count) rather than a version, so the two triggers compose: a version marker still heals "we changed our mind about the formula", and this heals "the machine changed". Precedence cannot be ambiguous even though both write the same file, because v8 calls the SAME helpers the version blocks do (`DeriveMemorySettings`, and `DeriveWorkerSettings` extracted here so v2 and v8 cannot drift) - it can only ever differ by being fresher, never by disagreeing. It compares the LAST fingerprint in the conf, not any: a host resized 16 -> 32 -> 16 GB has both, and a `Contains` test would find the stale first one and skip, leaving the 32 GB block still winning by last-occurrence-wins on a box that no longer has 32 GB - the check has to ask the question postgresql.conf itself answers. **The omissions are the load-bearing part.** `shared_buffers` is excluded STRUCTURALLY rather than by trusting its cap to hold: the 1 GB cap is the Windows error-487 mitigation ([#1559], pgsql-bugs BUG #14050 / #18954) and that condition is live on this fleet (measured 4-205 occurrences/day across the three boxes, zero `could not fork` - the retry path holding is exactly the margin a larger segment would spend), so if the cap is ever raised deliberately that is a reviewed formula change, not something a resize propagates on its own. `work_mem` is excluded because the formula would take it 31 -> 63 MB and the only measurements above 31 MB on this store's heaviest read are worse (PlanRegressionSql: default 26,565ms, 31 MB 25,617ms, 512 MB 59,323ms) - and more fundamentally because it is the wrong KIND of setting for a hardware block, a per-sort per-connection ceiling that follows from the query mix rather than from the machine. `max_parallel_workers` is untouched: this class has never set it, so it sits at the PostgreSQL default of 8 regardless of cores, and deriving it is a behaviour change that multiplies the same memory story (each parallel worker gets its own `work_mem`), wanting its own evidence. Re-stating the two worker settings is also what finally makes the v2 block's "never goes stale as collectors are added" claim true - that was true of the formula and false of its marker-keyed application.
- **Four enumerated-path phase stamps were skipped whenever the phase they timed threw** ([#2854]) - `PerItemPlanFetchMs`, `PerItemTextFetchMs`, `PerItemOpenMs` and `PerItemWatermarkMs` were assigned on the line after their `await`, so a phase that threw skipped its own stamp and reported zero. The two fetch stamps are the parents of the sub-split fixed in #2816, and they are the live half: their fetch methods catch their own exceptions and return normally, so the item still completes and still logs, and a failed fetch printed `plan_fetch:0ms` above non-zero `probe:`/`target:`/`write:` children while `PlanFetchOtherMs` clamped the impossible negative residual to zero - a line that reads as precise while being arithmetically impossible. The open and watermark stamps were bare for the same reason but are latent, not live: a throw there propagates out of the driver's per-item `try`, so the item is skipped and prints no split line at all. All four now stamp from `finally` regardless, since the field's honesty should not depend on a caller two files away continuing to discard the item. The log site gates on a new `PerItemPhasesMeasured` flag rather than `PerItemOpenMs > 0`, which suppressed the whole split for a genuinely instant open. The #2851 IL reachability pin is now DERIVED from `CollectorContext` rather than naming two setters, so it covers all twelve stamps on both paths and any stamp added later; naming them is why it did not catch these four.
- **`Collector Cost Regression` compared the day's TOTAL cost, so a cadence recovery read as a regression** ([#2846]) - total daily cost is `runs x cost-per-run`, and the predicate compared totals, so it could not tell "each run got more expensive" from "the same work ran more often". When use1's collection cadence recovered - it had been starved by `query_store` occupying the shared collection body - run counts rose sharply and daily totals rose with them while cost PER RUN fell, and the alert reported the improvement as a regression: 3,259 firings across 612 (server, collector) pairs in one day, 53% of them on collectors whose per-run cost had gone DOWN. Running the shipped predicate against that store, the total-cost rule matched 610 pairs and a per-run rule matched 14. The comparison is now cost per run, against a run-weighted baseline (`sum(sql_ms) / sum(runs)` over the prior days, not an average of daily averages, so a low-run day cannot dominate the baseline it contributes to). That fixes a second defect for free: `latest_day` is a PARTIAL day compared against FULL days, so a total grows monotonically until midnight and the tripping population could only grow within a day - which is exactly the observed shape, 510 -> 1,508 -> 1,894 -> 2,317 across four hourly samples with no decay possible. A per-run average is scale-free, so a half-finished day is directly comparable to a whole one. The total-cost floor stays on the daily total deliberately - it is what stops a 3 ms/run collector alerting on a doubling to 6 ms - and there is deliberately NO minimum run count on the latest day, because `index_object_stats` legitimately runs once per server per day and a min-runs guard would blind the alert to every daily-cadence collector. `metric_name` stays `Collector Cost Regression` (a webhook automation key the [#2768] triage map reads); the reported values change unit from ms/day to ms/run because what is measured changed, with the daily total and run count kept in the detail text. Pinned against live Postgres by an adversarial fixture whose two collectors have IDENTICAL latest-day totals and differ only in run count, so reverting the predicate fails on the cadence-recovery case specifically.
Expand Down Expand Up @@ -3167,6 +3168,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
[#2811]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2811
[#2816]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2816
[#2796]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2796
[#2809]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2809
[#2810]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2810
[#2819]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2819
[#2822]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2822
[#2823]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2823
Expand Down
164 changes: 164 additions & 0 deletions Darling/Darling.Tests/FactCollectorCommandTimeoutTests.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,164 @@
/*
* 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.Collections.Generic;
using System.IO;
using System.Linq;
using System.Runtime.CompilerServices;
using System.Text.RegularExpressions;
using PerformanceMonitor.Darling.Analysis;
using Xunit;

namespace Darling.Tests;

/// <summary>
/// Every fact read must carry an EXPLICIT command deadline (#2810).
///
/// <para>All thirty-one commands in <c>PgFactCollector</c> ran with no <c>CommandTimeout</c>, so
/// every one of them inherited Npgsql's undocumented 30 s default. Nobody chose 30 s; it was simply
/// what happened. Measured on the production store after retention was restored (#2809) and after
/// #2827's dedup rewrite, the plan-regression read still crossed that ceiling on a COLD run — 34.7 s
/// and 32.4 s on the two largest servers, against 10.6-21.2 s for the same servers warm. A few
/// seconds of overshoot, on the cold/large combination only, which is exactly why it presented as
/// intermittent and why two prior changes aimed elsewhere: #2827 made the query 2.4x faster and
/// #2826 made the failure visible, but neither touched the ceiling it was failing against.</para>
///
/// <para><b>Why this pin is shaped over the FAMILY rather than the one site.</b> The defect was
/// reported against <c>PlanRegressionSql</c>. Fixing only that command would have been
/// scenario-shaped, and this repo has already paid twice for exactly that — the #2344 enumerated pin,
/// and <c>PgStatementText</c>, where a broken sibling arm survived a green suite because the test
/// named the arm it was written for. Thirty-one commands shared one missing value; the assertion is
/// therefore structural: EVERY command constructed in this collector sets a deadline, so the next one
/// somebody adds cannot quietly reintroduce the inherited default.</para>
///
/// <para>The value itself is pinned separately and deliberately below. It is bounded ABOVE by the
/// 120 s analysis pass budget that thirty collect methods share, not just below by how long the
/// slowest query takes — a detail that is easy to lose and expensive to relearn, because a timeout
/// raised past the pass budget converts "one fact is missing" into "every fact is missing".</para>
/// </summary>
public sealed class FactCollectorCommandTimeoutTests
{
/// <summary>
/// A command construction in this collector. Matched by shape rather than by variable name — the
/// sites use both <c>cmd</c> and <c>command</c>, and a pin keyed on either spelling would miss
/// half of them.
/// </summary>
private static readonly Regex s_commandCtor = new(
@"new NpgsqlCommand\(",
RegexOptions.Compiled | RegexOptions.CultureInvariant);

private static readonly Regex s_setsTimeout = new(
@"CommandTimeout\s*=",
RegexOptions.Compiled | RegexOptions.CultureInvariant);

[Fact]
public void EveryFactCollectorCommandSetsAnExplicitTimeout()
{
var missing = new List<string>();
var covered = 0;

foreach (var file in FactCollectorSources())
{
var lines = File.ReadAllLines(file);

for (var i = 0; i < lines.Length; i++)
{
if (!s_commandCtor.IsMatch(lines[i]))
{
continue;
}

/* The initializer may wrap, so the deadline counts if it appears on the construction
line or in the statement that follows it — both are in use across this codebase
(PgPlanFetcher uses the initializer, PgDrillDownCollector assigns afterwards). */
var window = string.Join(
"\n",
lines.Skip(i).Take(Math.Min(3, lines.Length - i)));

if (s_setsTimeout.IsMatch(window))
{
covered++;
}
else
{
missing.Add($"{Path.GetFileName(file)}:{i + 1}");
}
}
}

Assert.True(
missing.Count == 0,
"These fact-collector commands carry no explicit CommandTimeout, so they inherit Npgsql's "
+ "undocumented 30 s default — the defect #2810 fixed, where a read that needed 34.7 s cold "
+ "failed on every cold pass and nobody had chosen the ceiling it failed against:"
+ Environment.NewLine + string.Join(Environment.NewLine, missing));

/* A floor, not an equality: the point is that nobody adds a command without a deadline, and a
pin that also broke on every ADDED collector would be a tax on writing one. The floor still
fails loudly if the sweep is partially reverted, which is the regression that matters. */
Assert.True(
covered >= 31,
$"Expected at least the 31 swept command sites to set a timeout; found {covered}. "
+ "A drop means sites were removed or the timeout was refactored out from under this pin.");
}

/// <summary>
/// The value is bounded on BOTH sides, and the upper bound is the one that is easy to get wrong.
///
/// <para>Below: the measured cold worst case was 34.7 s, so anything at or under that reproduces
/// #2810. Above: <c>DarlingWorker.s_analysisTimeout</c> gives the whole analysis pass 120 s and
/// thirty collect methods share it, so a per-command deadline approaching that figure lets ONE
/// stalled read consume the pass and cost the server its other twenty-nine facts — a strictly
/// worse failure than the one being fixed. This asserts the value stays in the band where both
/// arguments hold.</para>
/// </summary>
[Fact]
public void TheTimeoutClearsTheMeasuredColdWorstCaseWithoutOwningThePassBudget()
{
const int MeasuredColdWorstCaseSeconds = 35;
const int AnalysisPassBudgetSeconds = 120;

Assert.True(
PgFactCollector.FactCommandTimeoutSeconds > MeasuredColdWorstCaseSeconds,
$"The deadline ({PgFactCollector.FactCommandTimeoutSeconds}s) must clear the measured cold "
+ $"worst case ({MeasuredColdWorstCaseSeconds}s) or #2810 reproduces: the plan-regression "
+ "read took 34.7s cold on the largest production server.");

Assert.True(
PgFactCollector.FactCommandTimeoutSeconds <= AnalysisPassBudgetSeconds / 2,
$"The deadline ({PgFactCollector.FactCommandTimeoutSeconds}s) must leave at least half of "
+ $"the {AnalysisPassBudgetSeconds}s analysis pass for the other twenty-nine collect "
+ "methods. One read that stalls must not cost a server every other fact.");
}

private static IEnumerable<string> FactCollectorSources()
{
var darling = Directory.GetFiles(
Path.Combine(RepoRoot(), "Darling", "PerformanceMonitor.Darling.Analysis"),
"PgFactCollector.*.cs");

Assert.NotEmpty(darling);

return darling.OrderBy(f => f, StringComparer.Ordinal);
}

private static string RepoRoot([CallerFilePath] string thisFile = "")
{
var dir = Path.GetDirectoryName(thisFile)!;
while (dir is not null
&& !File.Exists(Path.Combine(dir, "PerformanceMonitor.sln"))
&& !Directory.Exists(Path.Combine(dir, ".git")))
{
dir = Path.GetDirectoryName(dir);
}

Assert.NotNull(dir);
return dir!;
}
}
Loading
Loading