Skip to content

Trace-flag reads decide on the newest successful run's row count, so an ordinary run no longer hides every enabled flag (#3999 follow-up) #4032

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
erikdarlingdata merged 1 commit into from
Sep 23, 2026
Merged

Trace-flag reads decide on the newest successful run's row count, so an ordinary run no longer hides every enabled flag (#3999 follow-up) #4032

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
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
70 changes: 49 additions & 21 deletions Darling/Darling.Tests/ViewerConfigurationTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@
using System.Threading.Tasks;
using Npgsql;
using PerformanceMonitor.Collectors;
using PerformanceMonitor.Darling.Service.Mcp;
using PerformanceMonitor.Darling.Storage;
using PerformanceMonitor.Darling.Viewer;
using Xunit;
Expand Down Expand Up @@ -405,19 +406,24 @@ await LiveStoreCleanup.RunAsync(connectionString!, bodySucceeded, async (cleanup
}

/// <summary>
/// #3999: the all-off case. A capture that finds every flag off writes ZERO rows to <c>trace_flags</c>
/// (<c>DBCC TRACESTATUS(-1)</c> only ever lists flags that are ON), so the newest ROW can be older than
/// the newest SUCCESSFUL run. Before this fix, <c>capture_time = MAX(capture_time)</c> could not see that
/// the collector had run again and fell back to the stale ON row - reporting a flag enabled days after it
/// (and every other flag) was turned off. Seeded here at the exact shape: one old ON row, then a newer
/// SUCCESS in collection_log with no corresponding trace_flags row at all.
/// #3999: the display reads answer for the collector's newest SUCCESSFUL run. A capture that finds every
/// flag off writes ZERO rows to <c>trace_flags</c> (<c>DBCC TRACESTATUS(-1)</c> only ever lists flags that
/// are ON), so the newest ROW can outlive the state it describes: before this fix the reads fell back to a
/// stale ON row days after every flag was turned off.
///
/// <para>Seeded in the order the service really writes. A run's capture rows first, then its
/// collection_log row, stamped when the run ENDS (<c>DarlingObservability.LogCollectionAsync</c> uses
/// UtcNow at log time), so an ordinary run's SUCCESS is always a few seconds NEWER than its own capture.
/// The first version of this fix compared those two timestamps and hid every enabled flag after every
/// ordinary run; step 1 is the pin for that. Both readers are asserted: the viewer grid and the MCP
/// reader carry the same SQL.</para>
/// </summary>
[Fact]
public async Task TraceFlags_AllOffSinceNewerSuccessfulRun_ReadsNoFlags_AgainstDevPostgres()
public async Task TraceFlags_AnswerForTheNewestSuccessfulRun_AgainstDevPostgres()
{
var connectionString = Environment.GetEnvironmentVariable("DARLING_TEST_PG");
Assert.SkipWhen(string.IsNullOrEmpty(connectionString),
"Set DARLING_TEST_PG to a Postgres connection string to run the live trace-flags all-off test.");
"Set DARLING_TEST_PG to a Postgres connection string to run the live trace-flags anchor test.");

using var connection = new NpgsqlConnection(connectionString);
await connection.OpenAsync(TestContext.Current.CancellationToken);
Expand All @@ -426,23 +432,40 @@ public async Task TraceFlags_AllOffSinceNewerSuccessfulRun_ReadsNoFlags_AgainstD
await DeleteRowsAsync(connection, "collection_log", TraceFlagsServerId, TestContext.Current.CancellationToken);

await using var viewer = new ViewerDataService(connectionString!);
await using var postgres = NpgsqlDataSource.Create(connectionString!);

async Task<int[]> BothReadersAsync()
{
var viewerFlags = (await viewer.GetLatestTraceFlagsAsync(TraceFlagsServerId)).Select(r => r.TraceFlag).ToArray();
var mcpFlags = (await DarlingCurrentConfigReader.GetLatestTraceFlagsAsync(postgres, TraceFlagsServerId, TestContext.Current.CancellationToken))
.Rows.Select(r => r.TraceFlag).ToArray();
Assert.Equal(viewerFlags, mcpFlags);
return viewerFlags;
}

var bodySucceeded = false;
try
{
var flagWasOnAt = TruncateToSeconds(DateTime.UtcNow.AddDays(-2));
var laterSuccessfulRunFoundNothingAt = flagWasOnAt.AddDays(1);
var day1 = TruncateToSeconds(DateTime.UtcNow.AddDays(-3));

await InsertTraceFlagAsync(connection, flagWasOnAt, 1117, status: true, isGlobal: true, isSession: false);
await InsertCollectionLogSuccessAsync(connection, laterSuccessfulRunFoundNothingAt);
/* 1. An ordinary run: 1117 on, captured, then logged SUCCESS 3 s later with its one row. */
await InsertTraceFlagAsync(connection, day1, 1117, status: true, isGlobal: true, isSession: false);
await InsertCollectionLogSuccessAsync(connection, day1.AddSeconds(3), rowsCollected: 1);
Assert.Equal(new[] { 1117 }, await BothReadersAsync());

/* The control: without the newer collection_log SUCCESS, the same row still reads (proven by
TraceFlags_LatestCaptureWins_OrderedByFlag_AgainstDevPostgres above with no collection_log row
at all — the COALESCE floor covers that case). This test is the case that row's coverage
cannot reach: a genuinely newer successful capture that stored nothing. */
var rows = await viewer.GetLatestTraceFlagsAsync(TraceFlagsServerId);
/* 2. The next day every flag is off: a SUCCESS that wrote nothing. The stale 1117 row must not read. */
await InsertCollectionLogSuccessAsync(connection, day1.AddDays(1).AddSeconds(3), rowsCollected: 0);
Assert.Empty(await BothReadersAsync());

Assert.Empty(rows);
/* 3. A run that failed after that proves nothing about the flags, so the answer stays "none". */
await InsertCollectionLogAsync(connection, day1.AddDays(1).AddHours(1), "ERROR", rowsCollected: 0);
Assert.Empty(await BothReadersAsync());

/* 4. The day after, 4199 is on: a new capture with its own SUCCESS reads again, and only 4199. */
var day3 = day1.AddDays(2);
await InsertTraceFlagAsync(connection, day3, 4199, status: true, isGlobal: true, isSession: false);
await InsertCollectionLogSuccessAsync(connection, day3.AddSeconds(3), rowsCollected: 1);
Assert.Equal(new[] { 4199 }, await BothReadersAsync());

bodySucceeded = true;
}
Expand All @@ -456,15 +479,20 @@ await LiveStoreCleanup.RunAsync(connectionString!, bodySucceeded, async (cleanup
}
}

private static async Task InsertCollectionLogSuccessAsync(NpgsqlConnection connection, DateTime collectionTimeUtc)
private static Task InsertCollectionLogSuccessAsync(NpgsqlConnection connection, DateTime collectionTimeUtc, int rowsCollected) =>
InsertCollectionLogAsync(connection, collectionTimeUtc, "SUCCESS", rowsCollected);

private static async Task InsertCollectionLogAsync(NpgsqlConnection connection, DateTime collectionTimeUtc, string status, int rowsCollected)
{
using var command = new NpgsqlCommand(
"INSERT INTO collection_log (log_id, server_id, server_name, collector_name, collection_time, status) " +
"VALUES ($1, $2, $3, 'trace_flags', $4, 'SUCCESS')", connection);
"INSERT INTO collection_log (log_id, server_id, server_name, collector_name, collection_time, status, rows_collected) " +
"VALUES ($1, $2, $3, 'trace_flags', $4, $5, $6)", connection);
command.Parameters.AddWithValue(CollectionIdGenerator.Next());
command.Parameters.AddWithValue(TraceFlagsServerId);
command.Parameters.AddWithValue("viewer-trace-flags-e2e");
command.Parameters.AddWithValue(DateTime.SpecifyKind(collectionTimeUtc, DateTimeKind.Unspecified));
command.Parameters.AddWithValue(status);
command.Parameters.AddWithValue(rowsCollected);
await command.ExecuteNonQueryAsync(TestContext.Current.CancellationToken);
}

Expand Down
25 changes: 14 additions & 11 deletions Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingCurrentConfigReader.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -167,23 +167,26 @@ public sealed record TraceFlagReadRow(int TraceFlag, bool Status, bool IsGlobal,
/// that finds every flag off writes ZERO rows (<c>DBCC TRACESTATUS(-1)</c> only ever lists flags that are
/// ON), so plain <c>capture_time = MAX(capture_time)</c> cannot see that capture at all and silently falls
/// back to an older capture that still had a flag on — reporting a flag enabled days or weeks after it (and
/// every other flag) was turned off. The second <c>AND</c> below closes that: it compares the newest row's
/// own timestamp against the newest SUCCESS this collector logged in <c>v_collection_log</c>, and if that
/// successful run is NEWER than the newest row, the run that ran most recently found nothing on, so the
/// whole predicate goes false and the read reports no flags — exact, rather than a stale fallback. The
/// <c>COALESCE</c> floor only matters when collection_log's retention has aged past this collector's
/// oldest trace_flags row (or nothing has run yet), and defaults to the pre-fix reading rather than
/// wrongly suppressing a real row it cannot corroborate.</para>
/// every other flag) was turned off. The second <c>AND</c> below closes that on the ROW COUNT of the newest
/// SUCCESS this collector logged in <c>v_collection_log</c>: every capture writes the full list of flags
/// that are on, so a newest successful run that wrote 0 rows found every flag off, and the read reports
/// none. Timestamps can't decide it: this service stamps a collection_log row when the run ENDS (after its
/// capture rows), Lite stamps it when the run STARTS, so "is the newest success newer than the newest
/// capture" is true after every ordinary run here and would hide every enabled flag. No SUCCESS row, or a
/// NULL count from an old row, keeps the pre-fix reading rather than suppressing a capture it can't
/// corroborate.</para>
/// </summary>
public const string TraceFlagsSql = """
SELECT trace_flag, status, is_global, is_session, capture_time
FROM v_trace_flags
WHERE server_id = $1
AND capture_time = (SELECT MAX(capture_time) FROM v_trace_flags WHERE server_id = $1)
AND (SELECT MAX(capture_time) FROM v_trace_flags WHERE server_id = $1) >= COALESCE(
(SELECT MAX(collection_time) FROM v_collection_log
WHERE server_id = $1 AND collector_name = 'trace_flags' AND status = 'SUCCESS'),
TIMESTAMP '1900-01-01')
AND COALESCE(
(SELECT rows_collected FROM v_collection_log
WHERE server_id = $1 AND collector_name = 'trace_flags' AND status = 'SUCCESS'
ORDER BY collection_time DESC NULLS LAST
LIMIT 1),
1) > 0
ORDER BY trace_flag
""";

Expand Down
21 changes: 12 additions & 9 deletions Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Config.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -82,21 +82,24 @@ ORDER BY database_name
/// #3999: anchored on the trace_flags collector's newest SUCCESSFUL run, not the newest row. A capture
/// that finds every flag off writes ZERO rows (<c>DBCC TRACESTATUS(-1)</c> only lists flags that are ON),
/// so a plain <c>capture_time = MAX(capture_time)</c> falls back to an older capture that still had a
/// flag on. The second <c>AND</c> compares the newest row's timestamp against the newest SUCCESS this
/// collector logged in <c>v_collection_log</c>; if that run is newer, it found nothing on, and the whole
/// predicate goes false so the read reports no flags rather than a stale one. The <c>COALESCE</c> floor
/// only matters once collection_log's retention has aged past this collector's oldest trace_flags row,
/// and defaults to the pre-fix reading rather than wrongly suppressing a row it cannot corroborate.
/// flag on. The second <c>AND</c> decides on the ROW COUNT of the newest SUCCESS this collector logged
/// in <c>v_collection_log</c>: every capture writes the full list of flags that are on, so 0 rows means
/// every flag was off and the read reports none. Not on timestamps: the service stamps collection_log at
/// a run's END, after its capture rows, so "newest success is newer than the newest capture" holds after
/// every ordinary run and would hide every enabled flag. No SUCCESS row, or a NULL count, keeps the
/// pre-fix reading. <c>DarlingCurrentConfigReader.TraceFlagsSql</c> and Lite's twin carry the same test.
/// </summary>
public const string TraceFlagsSql = """
SELECT trace_flag, status, is_global, is_session
FROM v_trace_flags
WHERE server_id = $1
AND capture_time = (SELECT MAX(capture_time) FROM v_trace_flags WHERE server_id = $1)
AND (SELECT MAX(capture_time) FROM v_trace_flags WHERE server_id = $1) >= COALESCE(
(SELECT MAX(collection_time) FROM v_collection_log
WHERE server_id = $1 AND collector_name = 'trace_flags' AND status = 'SUCCESS'),
TIMESTAMP '1900-01-01')
AND COALESCE(
(SELECT rows_collected FROM v_collection_log
WHERE server_id = $1 AND collector_name = 'trace_flags' AND status = 'SUCCESS'
ORDER BY collection_time DESC NULLS LAST
LIMIT 1),
1) > 0
ORDER BY trace_flag
""";

Expand Down
126 changes: 126 additions & 0 deletions Lite.Tests/TraceFlagsLatestRunTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,126 @@
/*
* 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.Threading.Tasks;
using DuckDB.NET.Data;
using PerformanceMonitorLite.Database;
using PerformanceMonitorLite.Services;
using Xunit;

namespace PerformanceMonitorLite.Tests;

/// <summary>
/// #3999: Lite's trace-flag read answers for the collector's newest SUCCESSFUL run, the twin of Darling's
/// <c>TraceFlags_AnswerForTheNewestSuccessfulRun_AgainstDevPostgres</c>. A capture that finds every flag off
/// writes ZERO rows (<c>DBCC TRACESTATUS(-1)</c> lists only flags that are on), so the newest trace_flags row
/// can outlive the state it describes. The read decides on the newest SUCCESS's <c>rows_collected</c>, never on
/// timestamps. Lite stamps collection_log when a run STARTS and Darling when it ENDS, so no timestamp
/// comparison means the same thing on both; seeded here in Lite's order, log stamp first.
/// </summary>
public sealed class TraceFlagsLatestRunTests : IClassFixture<SharedDuckDbFixture>, IDisposable
{
private const int ServerId = 3999;

private readonly DuckDbInitializer _duckDb;
private DuckDBConnection? _seedConn;
private long _nextId = 1;

public TraceFlagsLatestRunTests(SharedDuckDbFixture fixture)
{
fixture.ResetData();
_duckDb = fixture.DuckDb;
}

public void Dispose() => _seedConn?.Dispose();

[Fact]
public async Task TheReadAnswersForTheNewestSuccessfulRun()
{
var service = new LocalDataService(_duckDb);
var day1 = new DateTime(2026, 9, 20, 6, 0, 0, DateTimeKind.Utc);

async Task<int[]> FlagsAsync() =>
(await service.GetLatestTraceFlagsAsync(ServerId)).Select(r => r.TraceFlag).ToArray();

/* 1. An ordinary run: logged at its start, capture 1 s later with 1117 on. */
await SeedRunAsync(day1, "SUCCESS", rowsCollected: 1);
await SeedTraceFlagAsync(day1.AddSeconds(1), 1117);
Assert.Equal(new[] { 1117 }, await FlagsAsync());

/* 2. The next day every flag is off: a SUCCESS that wrote nothing. The stale 1117 row must not read. */
await SeedRunAsync(day1.AddDays(1), "SUCCESS", rowsCollected: 0);
Assert.Empty(await FlagsAsync());

/* 3. A failed run after that proves nothing about the flags, so the answer stays "none". */
await SeedRunAsync(day1.AddDays(1).AddHours(1), "ERROR", rowsCollected: 0);
Assert.Empty(await FlagsAsync());

/* 4. The day after, 4199 is on: a new run with its capture reads again, and only 4199. */
await SeedRunAsync(day1.AddDays(2), "SUCCESS", rowsCollected: 1);
await SeedTraceFlagAsync(day1.AddDays(2).AddSeconds(1), 4199);
Assert.Equal(new[] { 4199 }, await FlagsAsync());
}

[Fact]
public async Task NoRunRecord_KeepsTheNewestCapture()
{
/* Nothing in collection_log (retention aged it out, or nothing has run through the log yet): the read
keeps the newest capture rather than suppressing a row it cannot corroborate. */
var service = new LocalDataService(_duckDb);
await SeedTraceFlagAsync(new DateTime(2026, 9, 20, 6, 0, 1, DateTimeKind.Utc), 1117);

Assert.Equal(new[] { 1117 }, (await service.GetLatestTraceFlagsAsync(ServerId)).Select(r => r.TraceFlag).ToArray());
}

private async Task<DuckDBConnection> SeedConnectionAsync()
{
if (_seedConn is null)
{
_seedConn = _duckDb.CreateConnection();
await _seedConn.OpenAsync();
}
return _seedConn;
}

private async Task SeedRunAsync(DateTime startedUtc, string status, int rowsCollected)
{
using var readLock = _duckDb.AcquireReadLock();
var connection = await SeedConnectionAsync();
using var cmd = connection.CreateCommand();
cmd.CommandText = @"
INSERT INTO collection_log
(log_id, server_id, server_name, collector_name, collection_time, duration_ms, status, error_message, rows_collected)
VALUES ($1, $2, $3, 'trace_flags', $4, 900, $5, NULL, $6)";
cmd.Parameters.Add(new DuckDBParameter { Value = _nextId++ });
cmd.Parameters.Add(new DuckDBParameter { Value = ServerId });
cmd.Parameters.Add(new DuckDBParameter { Value = "TestSrv" });
cmd.Parameters.Add(new DuckDBParameter { Value = startedUtc });
cmd.Parameters.Add(new DuckDBParameter { Value = status });
cmd.Parameters.Add(new DuckDBParameter { Value = rowsCollected });
await cmd.ExecuteNonQueryAsync();
}

private async Task SeedTraceFlagAsync(DateTime captureTimeUtc, int traceFlag)
{
using var readLock = _duckDb.AcquireReadLock();
var connection = await SeedConnectionAsync();
using var cmd = connection.CreateCommand();
cmd.CommandText = @"
INSERT INTO trace_flags
(config_id, capture_time, server_id, server_name, trace_flag, status, is_global, is_session)
VALUES ($1, $2, $3, $4, $5, true, true, false)";
cmd.Parameters.Add(new DuckDBParameter { Value = _nextId++ });
cmd.Parameters.Add(new DuckDBParameter { Value = captureTimeUtc });
cmd.Parameters.Add(new DuckDBParameter { Value = ServerId });
cmd.Parameters.Add(new DuckDBParameter { Value = "TestSrv" });
cmd.Parameters.Add(new DuckDBParameter { Value = traceFlag });
await cmd.ExecuteNonQueryAsync();
}
}
Loading
Loading