Skip to content
3 changes: 3 additions & 0 deletions CHANGELOG.md

Large diffs are not rendered by default.

491 changes: 491 additions & 0 deletions Darling/Darling.Tests/ViewerCommandTimeoutTests.cs

Large diffs are not rendered by default.

130 changes: 130 additions & 0 deletions Darling/PerformanceMonitor.Darling.Viewer/ViewerCommandDeadlines.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,130 @@
/*
* 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.
*/

namespace PerformanceMonitor.Darling.Viewer;

/// <summary>
/// The explicit command deadlines for the viewer's store reads (#2874). Every one of this project's
/// 193 command sites previously set no <c>CommandTimeout</c> and so inherited Npgsql's undocumented
/// 30 s default — a value nobody chose, and the defect class behind three production failures
/// (#2810, #2871, #2796): exceeding the ceiling surfaces as <c>Exception while reading from stream</c>,
/// which reads as a network fault rather than a deadline.
///
/// <para><b>Three regimes, because this surface really has three.</b> The bulk of the project is one
/// regime and deliberately so: the fleet timer and the per-tab auto-refresh timer call the SAME
/// <c>ViewerDataService</c> methods a user gesture calls — <c>RefreshActiveInnerTabAsync</c> is
/// literally the method tab-activation invokes — so "interactive" and "background refresh" cannot be
/// told apart at the command site, and the set of reads reached ONLY by the unattended fleet fan-out
/// is empty. Splitting them would need a budget threaded through every call site, not a constant. The
/// two regimes that ARE separable are separable because something else bounds them: the command plane
/// sits inside a real orchestration budget, and the connect-time gate runs before the window is usable
/// and swallows its own failures.</para>
///
/// <para><b>What is NOT a regime here.</b> Export was the obvious fourth candidate and it does not
/// exist: <c>PerformanceMonitor.Ui.DataGridExport</c> is synchronous, store-unaware, and iterates
/// <c>grid.Items</c>, so every CSV/copy path formats rows a visible-tab load already paid for. The
/// long-running operations a user knowingly waits minutes for (snapshot_now, analyze_now, purge_now,
/// Get Actual Plan) are COMMANDS on the command plane below, not reads.</para>
///
/// <para><b>Why none of these is <c>StorageCommandDeadlines.McpReadSeconds</c>.</b> That constant is
/// 30 s for the MCP read surface and its derivation does not transfer. The MCP's worst verified read
/// was 685 ms and its permit is an unbounded pool; the viewer's worst measured read is 3.0 s — 4.4x
/// slower — yet its permit is ten times scarcer (<c>MaxPoolSize = 10</c>, set on the managed-derived
/// string in <c>ViewerSettings</c>), a single control fans out to exactly ten concurrent reads and so
/// can hold every one of them, and an unguarded fleet-timer read can re-fire every 10 s. Slower reads
/// against a scarcer permit land BELOW 30 s, not at it.</para>
/// </summary>
public static class ViewerCommandDeadlines
{
/// <summary>
/// The interactive/refresh store reads — 188 of the project's 193 command sites: everything
/// except the three on the command plane and the two connect-gate probes, which share
/// <c>ViewerDataService.cs</c> with two ordinary reads, so the regime is decided per SITE here
/// rather than per file.
///
/// <para>ABOVE the measured worst case. Timed against a store stood up by the product's own
/// <c>PgMigrations.MigrateAsync</c> at V109 with TimescaleDB and seeded to EXACT production
/// per-server density (<c>get_collector_cost</c> over 2 days x 42 servers: 189,414 query_stats
/// rows/server/day), across the collector's full 30-day retention horizon — 5.68 M query_stats
/// rows and 1.98 M procedure_stats rows for one server. The heaviest shipped per-server read,
/// <c>TopQueriesSql</c> (a windowed aggregate plus a <c>LEFT JOIN LATERAL</c> back through
/// <c>v_query_stats</c> and a <c>ROW_NUMBER</c> module join), measured COLD: 588 ms on the default
/// 1-hour preset, 1.12 s on the widest 7-day preset, and 3.01 s on a 30-day custom range — the
/// widest window any shipped read can be asked for, since retention drops the data behind it.
/// Fifteen seconds is 5x that worst case, 13x the widest preset, and 25x the default.</para>
///
/// <para>BELOW the point where a stalled read is worse than a failed one, which here is a permit
/// argument rather than a budget one. Nothing encloses these reads — no <c>CancelAfter</c>, no
/// <c>SemaphoreSlim</c>, no <c>WaitAsync</c>, and no request timeout, because the viewer is a WPF
/// <c>WinExe</c> and hosts no web endpoint — so this deadline IS the budget, the same finding
/// #2882 and #2888 both made, and the same reason both erred short. What it competes for is the
/// ten-connection pool: <c>CorrelatedTimelineLanesControl</c> awaits one <c>Task.WhenAll</c> over
/// exactly ten reads, so a single panel can hold every permit, and while they are held the sidebar
/// freshness dots, the alert poll and every other panel get nothing — read eleven waits
/// <c>ConnectionTimeoutSeconds</c> (default 5) for a slot and then throws a CONNECT error, which
/// misattributes a slow store to the network. Halving the inherited 30 s halves that worst-case
/// hold. Ten concurrent 30-day reads on the rig above measured 24.4-64.1 s, six of them past the
/// silent default they used to inherit; cutting each at 15 s returns permits sooner, which is the
/// outcome to want in that state.</para>
///
/// <para>The asymmetry, worked out for this surface rather than assumed: too short and one panel
/// shows an error the user can retry — and the auto-refresh timer retries it within 30 s anyway,
/// unprompted. Too long and the user watches a spinner while a pooled connection is held, which is
/// the failure mode that cannot be diagnosed from the UI. Erring short is right here.</para>
/// </summary>
public const int InteractiveReadSeconds = 15;

/// <summary>
/// The store&lt;-&gt;service command plane — the three commands in
/// <c>ViewerDataService.Commands.cs</c> (enqueue, poll, delete).
///
/// <para>ABOVE the measured worst case with room to spare: the poll is a single-row primary-key
/// lookup on <c>config_command</c>, measured at 3.9 ms cold and 0.1 ms warm; the enqueue and the
/// delete are single-row writes on that same table. Five seconds is three orders of magnitude over
/// the cold measurement, deliberately, because the delete is what removes a DPAPI
/// credential-bearing <c>args_json</c> row after a <c>test_connect</c> and should not be the thing
/// that gives up early.</para>
///
/// <para>BELOW the budget it shares, which unlike the interactive regime is real and explicit:
/// <c>PollCommandResultAsync</c> loops until <c>DefaultCommandTimeout</c> (45 s) or
/// <c>ImperativeCommandTimeout</c> (3 min), re-issuing the poll every 400 ms. That budget is
/// checked only BETWEEN iterations, so with no deadline on the read itself one hung poll overshot
/// the stated 45 s by up to Npgsql's 30 s — the loop was bounded and the read inside it was not.
/// Five seconds puts the read an order of magnitude under the smaller of the two enclosing
/// budgets, which restores the loop's budget as the binding constraint. That is the point: too
/// short and the poll throws where the caller is written to receive null and show "still running /
/// try again"; too long and a dialog's stated 45 s silently becomes 75 s.</para>
/// </summary>
public const int CommandPlaneSeconds = 5;

/// <summary>
/// The connect-time gate — <c>ReadOnlyProbeSql</c> in <c>DetectReadOnlyAsync</c> and
/// <c>StoreSchemaProbeSql</c> in <c>GetStoreSchemaVersionAsync</c>.
///
/// <para>ABOVE the measured worst case, and this one does not grow with the store: both read
/// <c>information_schema</c> / <c>has_table_privilege</c> only, touching no hypertable and scanning
/// no data. The 85-sentinel schema probe measured 79 ms cold and 49 ms warm on the seeded V109 rig
/// above; ten seconds is ~127x that. A store ten times larger does not move it, which is why this
/// regime can sit far tighter than the interactive one despite having no budget either.</para>
///
/// <para>BELOW the point where startup hangs. These are the first two statements after connect, in
/// <c>MainWindow.OnLoaded</c>, before any timer starts and before the window is usable — and there
/// is no splash to explain the wait. Ten seconds is twice the default connect budget
/// (<c>ConnectionTimeoutSeconds</c> = 5) and bounded well under its 60 s ceiling, so a slow link
/// cannot turn the gate into a silent hang.</para>
///
/// <para>The asymmetry here is different from the other two regimes and is the reason this is its
/// own constant: both probes CATCH their own failures. <c>GetStoreSchemaVersionAsync</c> fails open
/// (returns null, so a healthy store is never blocked by a probe hiccup) and
/// <c>DetectReadOnlyAsync</c> fails safe (records read-only, so the UI hides writes rather than
/// dead-clicking a permission error). So a blown deadline here raises nothing — it silently
/// MIS-CLASSIFIES the store, hiding every write affordance on a writable one. A visible,
/// reconnectable mis-classification is the better trade against a startup that never finishes.</para>
/// </summary>
public const int ConnectGateSeconds = 10;
}
Original file line number Diff line number Diff line change
Expand Up @@ -135,6 +135,7 @@ public async Task<List<ViewerAlertRow>> GetAlertHistoryAsync(
var rows = new List<ViewerAlertRow>();

await using var command = _dataSource.CreateCommand(serverId.HasValue ? AlertHistorySql : AlertHistoryAllServersSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
command.Parameters.Add(new NpgsqlParameter<DateTime>
{
TypedValue = DateTime.SpecifyKind(sinceUtc, DateTimeKind.Unspecified),
Expand Down Expand Up @@ -232,6 +233,7 @@ public async Task<int> DismissAlertsAsync(IReadOnlyList<ViewerAlertRow> alerts,
}

await using var command = _dataSource.CreateCommand(DismissAlertsSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
command.Parameters.Add(new NpgsqlParameter { Value = times });
command.Parameters.Add(new NpgsqlParameter { Value = ids });
command.Parameters.Add(new NpgsqlParameter { Value = metrics });
Expand All @@ -249,6 +251,7 @@ public async Task<int> DismissAllVisibleAlertsAsync(
{
await using var command = _dataSource.CreateCommand(
serverId.HasValue ? DismissAllAlertsForServerSql : DismissAllAlertsSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
command.Parameters.Add(new NpgsqlParameter<DateTime>
{
TypedValue = DateTime.SpecifyKind(sinceUtc, DateTimeKind.Unspecified),
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -150,6 +150,7 @@ ON CONFLICT (id) DO UPDATE SET
public async Task<AlertSettingsRow?> GetAlertSettingsAsync(CancellationToken cancellationToken = default)
{
await using var command = _dataSource.CreateCommand(AlertSettingsSelectSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
await using var reader = await command.ExecuteReaderAsync(cancellationToken);
return await reader.ReadAsync(cancellationToken) ? ReadAlertSettingsRow(reader) : null;
}
Expand All @@ -161,6 +162,7 @@ public async Task UpsertAlertSettingsAsync(AlertSettingsRow row, CancellationTok
ArgumentNullException.ThrowIfNull(row);

await using var command = _dataSource.CreateCommand(AlertSettingsUpsertSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
BindAlertSettings(command, row);
await ExecuteWriteAsync(command, cancellationToken);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -113,6 +113,7 @@ private async Task<List<AgTopologyReplicaRow>> ReadAgReplicasAsync(CancellationT
{
var rows = new List<AgTopologyReplicaRow>();
await using var command = _dataSource.CreateCommand(AgReplicaStatesSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
await using var reader = await command.ExecuteReaderAsync(cancellationToken);
while (await reader.ReadAsync(cancellationToken))
{
Expand Down Expand Up @@ -142,6 +143,7 @@ private async Task<List<AgTopologyDatabaseRow>> ReadAgDatabasesAsync(Cancellatio
{
var rows = new List<AgTopologyDatabaseRow>();
await using var command = _dataSource.CreateCommand(AgDatabaseReplicaStatesSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
await using var reader = await command.ExecuteReaderAsync(cancellationToken);
while (await reader.ReadAsync(cancellationToken))
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -243,6 +243,7 @@ private async Task<List<ViewerBlockedProcessRow>> ReadBlockedProcessRowsAsync(
var rows = new List<ViewerBlockedProcessRow>();

await using var command = _dataSource.CreateCommand(BlockedProcessReportsSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
AddBlockingParameters(command, serverId, startUtc, endUtc);
command.Parameters.Add(DatabaseFilterParameter(databaseNames));
await using var reader = await command.ExecuteReaderAsync(cancellationToken);
Expand Down Expand Up @@ -303,6 +304,7 @@ private async Task<List<ViewerBlockedProcessRow>> ReadDmvBlockedProcessRowsAsync
var rows = new List<ViewerBlockedProcessRow>();

await using var command = _dataSource.CreateCommand(DmvBlockingSnapshotsSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
AddBlockingParameters(command, serverId, startUtc, endUtc);
command.Parameters.Add(DatabaseFilterParameter(databaseNames));
await using var reader = await command.ExecuteReaderAsync(cancellationToken);
Expand Down Expand Up @@ -358,6 +360,7 @@ internal async Task<List<BlockingPairRow>> GetBlockingPairRowsAsync(
await using var connection = await _dataSource.OpenConnectionAsync(cancellationToken);
await using (var command = connection.CreateCommand())
{
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
command.CommandText = BlockingPairRowsSql;
AddBlockingParameters(command, serverId, startUtc, endUtc);
await using var reader = await command.ExecuteReaderAsync(cancellationToken);
Expand All @@ -369,8 +372,18 @@ internal async Task<List<BlockingPairRow>> GetBlockingPairRowsAsync(
// blocked-process-report XE captured nothing (threshold unset / AWS RDS). Same connection.
/* #2443: the viewer passes its own window token — this read serves a person waiting at a
grid, not an analysis pass, so there is no budget or service stop for it to abandon under. */
/* A FACTORY that stamps the deadline, not the bare `connection.CreateCommand` method group
(#2874). This command is constructed inside PgBlockingPairRowQuery, so a deadline set here
is the only one it can get - and a method-group hand-off is invisible to both of #2874's
census regexes, which is how this site survived the sweep of the other 192. */
await PgBlockingPairRowQuery.AppendDmvSnapshotRowsAsync(
connection.CreateCommand, rows, serverId, startUtc, endUtc, cancellationToken);
() =>
{
var command = connection.CreateCommand();
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
return command;
},
rows, serverId, startUtc, endUtc, cancellationToken);

Comment on lines 379 to 387

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice catch on this method-group handoff — but the same shape (bare connection.CreateCommand passed to PgBlockingPairRowQuery.AppendDmvSnapshotRowsAsync, which builds the command in a different project and never sets CommandTimeout) still exists in two sibling call sites that aren't touched by this PR:

  • Darling/PerformanceMonitor.Darling.Analysis/PgDrillDownCollector.Blocking.cs:160
  • Darling/PerformanceMonitor.Darling.Analysis/PgFactCollector.Waits.cs:230

Both pass connection.CreateCommand as a bare method group exactly like the pre-fix Viewer code did. I checked whether this is actually a latent hang risk:

  • On the scheduled collector path, context.CancellationToken comes from DarlingWorker's CancelAfter(s_analysisTimeout) (120 s), so a stuck DMV-snapshot read there is bounded — worst case it burns the whole analysis pass instead of the collector's usual 30/60 s budget.
  • But AnalysisContext.CancellationToken defaults to CancellationToken.None for callers that don't plumb one (per its own doc comment, "the fact-inspection paths") — for those callers this command is genuinely unbounded, relying on Npgsql's undocumented 30 s default same as the bug this PR fixes.
  • Neither existing pin catches it: ViewerCommandTimeoutTests's new method-group scan is scoped to Darling/PerformanceMonitor.Darling.Viewer only (ViewerSources()), and FactCollectorCommandTimeoutTests's s_commandCtor regex only matches new NpgsqlCommand(, not .CreateCommand or a bare method-group handoff.

Worth a small follow-up (same factory-lambda fix, or a CommandTimeout set inside AppendDmvSnapshotRowsAsync itself as a shared floor) so this defect class doesn't have two known survivors right after being fixed once. Not a blocker for this PR since its stated scope is the .Viewer group of #2874.

Copy link
Copy Markdown
Owner Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Confirmed, and it is worse than two — the shape survives in six places repo-wide. But only your two are the same defect, and the distinction matters:

Genuine Npgsql-default inheritors (2). Both of yours, and I verified the mechanism rather than the pattern: PgBlockingPairRowQuery.AppendDmvSnapshotRowsAsync takes Func<NpgsqlCommand> and sets only CommandText on what the factory returns — never CommandTimeout — so a bare method group there inherits the 30 s default exactly as the Viewer site did.

  • Darling/PerformanceMonitor.Darling.Analysis/PgFactCollector.Waits.cs:231
  • Darling/PerformanceMonitor.Darling.Analysis/PgDrillDownCollector.Blocking.cs:161

That helper's own doc comment says "Three callers share this fetch", which corroborates the census: three Darling-side callers, one of them the Viewer site fixed here, two left.

Same shape, different provider (4) — probably not the same defect. These are DuckDB.NET.Data, not Npgsql, so there is no undocumented 30 s ceiling to inherit and CommandTimeout may not even be honoured:

  • Lite/Analysis/DuckDbFactCollector.Waits.cs:234
  • Lite/Analysis/DrillDownCollector.Blocking.cs:165
  • Lite/Services/LocalDataService.Blocking.cs:426 and :547

I would not sweep those in on this reasoning; whether a DuckDB command wants a deadline at all is a separate question from #2874's, and asserting one would be a pin that cannot fail.

Not fixing either here, deliberately. .Analysis is #2871's group and it has already landed, so re-opening it belongs to that lane rather than to a .Viewer PR — and the better fix is probably not six call sites at all but a shared floor inside AppendDmvSnapshotRowsAsync itself, which is a decision about that helper's contract and wants its own review. Filed with the mechanism, both candidate fixes, and the DuckDB caveat.

Your read on the exposure is also right and worth keeping on the record: the scheduled path is bounded by DarlingWorker's 120 s CancelAfter, so the unbounded case is specifically the callers that leave AnalysisContext.CancellationToken at None. That is the half a fix should target.

On the pin scoping — correct, and intentional. ViewerCommandTimeoutTests globs Darling/PerformanceMonitor.Darling.Viewer only, because a pin that swept another project would go red on a lane that has not agreed to the claim. A repo-wide method-group scan is the right instrument and belongs with whoever takes the fix.

return rows;
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -74,6 +74,7 @@ public async Task<List<TimeSliceBucket>> GetBlockingSlicerDataAsync(
var items = new List<TimeSliceBucket>();

await using var command = _dataSource.CreateCommand(BlockingSlicerSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
AddBlockingParameters(command, serverId, startUtc, endUtc);
command.Parameters.Add(DatabaseFilterParameter(databaseNames));
await using var reader = await command.ExecuteReaderAsync(cancellationToken);
Expand Down Expand Up @@ -117,6 +118,7 @@ public async Task<List<TimeSliceBucket>> GetDeadlockSlicerDataAsync(
var items = new List<TimeSliceBucket>();

await using var command = _dataSource.CreateCommand(DeadlockSlicerSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
AddBlockingParameters(command, serverId, startUtc, endUtc);
await using var reader = await command.ExecuteReaderAsync(cancellationToken);
while (await reader.ReadAsync(cancellationToken))
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -85,6 +85,7 @@ public async Task<List<BlockingDurationStatsPoint>> GetBlockingDurationStatsAsyn
var items = new List<BlockingDurationStatsPoint>();

await using var command = _dataSource.CreateCommand(BlockingDurationStatsSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
command.Parameters.Add(new NpgsqlParameter<int> { TypedValue = serverId });
command.Parameters.Add(new NpgsqlParameter<DateTime>
{
Expand Down Expand Up @@ -148,6 +149,7 @@ public async Task<List<DeadlockSeverityStatsPoint>> GetDeadlockSeverityStatsAsyn
var graphs = new List<(DateTime? DeadlockTime, string? Xml)>();

await using var command = _dataSource.CreateCommand(DeadlockSeverityGraphsSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
AddBlockingParameters(command, serverId, startUtc, endUtc);
await using var reader = await command.ExecuteReaderAsync(cancellationToken);
while (await reader.ReadAsync(cancellationToken))
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -196,6 +196,7 @@ private async Task<List<BlockingTrendPoint>> ReadCountTrendAsync(
var items = new List<BlockingTrendPoint>();

await using var command = _dataSource.CreateCommand(sql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
command.Parameters.Add(new NpgsqlParameter<int> { TypedValue = serverId });
command.Parameters.Add(new NpgsqlParameter<DateTime>
{
Expand Down Expand Up @@ -225,6 +226,7 @@ public async Task<List<LockWaitTrendPoint>> GetLockWaitTrendAsync(
var items = new List<LockWaitTrendPoint>();

await using var command = _dataSource.CreateCommand(LockWaitTrendSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
command.Parameters.Add(new NpgsqlParameter<int> { TypedValue = serverId });
command.Parameters.Add(new NpgsqlParameter<DateTime>
{
Expand Down Expand Up @@ -253,6 +255,7 @@ public async Task<List<WaitingTaskTrendPoint>> GetWaitingTaskTrendAsync(
var items = new List<WaitingTaskTrendPoint>();

await using var command = _dataSource.CreateCommand(WaitingTaskTrendSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
command.Parameters.Add(new NpgsqlParameter<int> { TypedValue = serverId });
command.Parameters.Add(new NpgsqlParameter<DateTime>
{
Expand Down Expand Up @@ -281,6 +284,7 @@ public async Task<List<BlockedSessionTrendPoint>> GetBlockedSessionTrendAsync(
var items = new List<BlockedSessionTrendPoint>();

await using var command = _dataSource.CreateCommand(BlockedSessionTrendSql);
command.CommandTimeout = ViewerCommandDeadlines.InteractiveReadSeconds;
command.Parameters.Add(new NpgsqlParameter<int> { TypedValue = serverId });
command.Parameters.Add(new NpgsqlParameter<DateTime>
{
Expand Down
Loading
Loading