From ee38c4b525e4b3177ce95ecb0874a0ac66ca5a07 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Thu, 8 Oct 2026 13:12:51 -0400 Subject: [PATCH 1/7] Perfmon data is compressed per counter, and chunks compressed by server alone are re-grouped (#5574) New perfmon_stats chunks compress by server_id and counter_name. An hourly pass re-groups the already compressed chunks inside the 30-day trend reach, newest first, one transaction per chunk under the bounded lock timeout, for at most two minutes a pass. Below the floor (no per-chunk settings view, TimescaleDB 2.14.1) nothing changes. Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_015vDtCAiuajanNsX2cbhnwg --- .../Darling.Tests/PerfmonRegroupGateTests.cs | 62 ++++ .../Darling.Tests/TimescaleSupportTests.cs | 12 +- .../DarlingWorker.cs | 10 + .../TimescaleSupport.cs | 337 +++++++++++++++++- 4 files changed, 400 insertions(+), 21 deletions(-) create mode 100644 Darling/Darling.Tests/PerfmonRegroupGateTests.cs diff --git a/Darling/Darling.Tests/PerfmonRegroupGateTests.cs b/Darling/Darling.Tests/PerfmonRegroupGateTests.cs new file mode 100644 index 0000000000..08c07b0399 --- /dev/null +++ b/Darling/Darling.Tests/PerfmonRegroupGateTests.cs @@ -0,0 +1,62 @@ +/* + * 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 PerformanceMonitor.Darling.Storage; +using Xunit; + +namespace Darling.Tests; + +/// +/// #5574: the pure gates around the perfmon_stats chunk re-group. The live behaviour (settings change, newest-first +/// re-group, budget, no-op second pass) needs a TimescaleDB 2.14.1+ store and is the part still to be written as a +/// live class beside CollectionLogSegmentByLiveTests. +/// +public sealed class PerfmonRegroupGateTests +{ + private const string Wanted = "server_id, counter_name"; + + [Fact] + public void ThePerfmonSegmentBy_IsServerAndCounter_InTheSpellingTheConvergenceReadJoinsWith() + { + Assert.Equal("server_id, counter_name", TimescaleSupport.PerfmonStatsSegmentBy); + Assert.Equal("server_id,counter_name", TimescaleSupport.PerfmonStatsChunkSegmentBy); + Assert.Equal(TimescaleSupport.PerfmonStatsSegmentBy, TimescaleSupport.CompressionSegmentByFor("perfmon_stats")); + Assert.Equal(TimescaleSupport.PerfmonStatsSegmentBy, TimescaleSupport.CompressionSegmentByFor("collect.perfmon_stats")); + Assert.Contains("compress_segmentby = 'server_id, counter_name'", TimescaleSupport.EnableCompressionSql("perfmon_stats"), StringComparison.Ordinal); + } + + [Theory] + [InlineData("2.13.1", true, Wanted, false)] + [InlineData("2.14.0", false, Wanted, false)] + public void TheRegroup_DoesNotRun_BelowTheFloor_OrWithoutThePerChunkView(string version, bool hasView, string segmentBy, bool expectOpen) + { + var reason = TimescaleSupport.PerfmonRegroupBlockedReason(TimescaleSupport.ParseTimescaleVersion(version), hasView, segmentBy); + Assert.Equal(expectOpen, reason is null); + } + + [Fact] + public void TheRegroup_DoesNotRun_UntilTheHypertableCarriesTheNewGrouping_AndRunsOtherwise() + { + var version = TimescaleSupport.ParseTimescaleVersion("2.30.1"); + Assert.NotNull(TimescaleSupport.PerfmonRegroupBlockedReason(version, true, "server_id")); + Assert.NotNull(TimescaleSupport.PerfmonRegroupBlockedReason(version, true, null)); + Assert.Null(TimescaleSupport.PerfmonRegroupBlockedReason(version, true, Wanted)); + + /* An unknown version is not a reason: the view test and the segmentby test decide. */ + Assert.Null(TimescaleSupport.PerfmonRegroupBlockedReason(null, true, Wanted)); + Assert.NotNull(TimescaleSupport.PerfmonRegroupBlockedReason(null, false, Wanted)); + } + + [Fact] + public void ThePerChunkSettingsView_ArrivedIn2_14_1_NotIn2_14_0() + { + Assert.Equal(new Version(2, 14, 1), TimescaleSupport.PerChunkCompressionSettingsViewFrom); + Assert.True(TimescaleSupport.PerChunkCompressionSettingsViewFrom > TimescaleSupport.CompressionSettingsChangeWithCompressedChunksFrom); + } +} diff --git a/Darling/Darling.Tests/TimescaleSupportTests.cs b/Darling/Darling.Tests/TimescaleSupportTests.cs index a0b1508062..4869439721 100644 --- a/Darling/Darling.Tests/TimescaleSupportTests.cs +++ b/Darling/Darling.Tests/TimescaleSupportTests.cs @@ -142,7 +142,9 @@ other pin in this file still expects. CompressAfterFor is the single source both foreach (var schema in CollectorCatalog.All) { - Assert.Contains("timescaledb.compress_segmentby = 'server_id'", + /* #5574: perfmon_stats segments by counter as well; every other collector table keeps server_id alone. */ + var wantedSegmentBy = schema.TargetTable == TimescaleSupport.PerfmonStatsTable ? "server_id, counter_name" : "server_id"; + Assert.Contains($"timescaledb.compress_segmentby = '{wantedSegmentBy}'", TimescaleSupport.EnableCompressionSql(schema), StringComparison.Ordinal); Assert.Contains("if_not_exists => true", TimescaleSupport.AddCompressionPolicySql(schema), StringComparison.Ordinal); @@ -162,7 +164,10 @@ other pin in this file still expects. CompressAfterFor is the single source both time for its lock. */ Assert.Equal("server_id, collector_name", TimescaleSupport.CollectionLogSegmentBy); Assert.Equal(TimescaleSupport.CollectionLogSegmentBy, TimescaleSupport.CompressionSegmentByFor(TimescaleSupport.CollectionLogTable)); - Assert.All(CollectorCatalog.All, schema => Assert.Equal("server_id", TimescaleSupport.CompressionSegmentByFor(schema.TargetTable))); + /* #5574: perfmon_stats alone among the collector tables also segments by counter. */ + Assert.Equal("server_id, counter_name", TimescaleSupport.PerfmonStatsSegmentBy); + Assert.All(CollectorCatalog.All.Where(schema => schema.TargetTable != TimescaleSupport.PerfmonStatsTable), schema => Assert.Equal("server_id", TimescaleSupport.CompressionSegmentByFor(schema.TargetTable))); + Assert.Equal(TimescaleSupport.PerfmonStatsSegmentBy, TimescaleSupport.CompressionSegmentByFor(TimescaleSupport.PerfmonStatsTable)); /* Callers spell tables both ways ("collect.x" and bare "x"). A schema-qualified collection_log must get the same value as the bare name the convergence read compares against, or the read never sees the table as @@ -171,7 +176,8 @@ converged and every hourly pass issues the ALTER (#3817's divergence, reached th Assert.Equal( "ALTER TABLE collect.collection_log SET (timescaledb.compress, timescaledb.compress_segmentby = 'server_id, collector_name')", TimescaleSupport.EnableCompressionSql("collect." + TimescaleSupport.CollectionLogTable)); - Assert.All(CollectorCatalog.All, schema => Assert.Equal("server_id", TimescaleSupport.CompressionSegmentByFor("collect." + schema.TargetTable))); + Assert.All(CollectorCatalog.All.Where(schema => schema.TargetTable != TimescaleSupport.PerfmonStatsTable), schema => Assert.Equal("server_id", TimescaleSupport.CompressionSegmentByFor("collect." + schema.TargetTable))); + Assert.Equal(TimescaleSupport.PerfmonStatsSegmentBy, TimescaleSupport.CompressionSegmentByFor("collect." + TimescaleSupport.PerfmonStatsTable)); Assert.Equal("3s", TimescaleSupport.HourlyDdlLockTimeout); Assert.True(TimescaleSupport.TryCompressionPhaseMinutesFor(TimescaleSupport.CollectionLogTable, out var logPhase)); Assert.Equal( diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs index b95cc46f6f..2810ca40f5 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs @@ -436,6 +436,16 @@ finds nothing once every hypertable carries the reloption. Wrapped whole rather new("composer performance tuning", StoreObjectConvergenceStage.Tuning, StoreObjectChangeSignal.InPlace, (connection, logger, ct) => PgTableTuning.ApplyAsync(connection, logger, ct), (connection, logger, ct) => PgTableTuning.ApplyAsync(connection, logger, hourly: true, ct)), + + /* #5574: LAST on purpose. perfmon_stats chunks compressed before the segmentby change (server_id alone) are + re-grouped by counter, newest first, inside the 30-day trend reach, for at most two minutes of a pass, so the + cheap steps above are never made to wait behind it. Hourly only: the start path would hold the service's + start for those minutes, and a store that has not converged is served by the next :30 tick. It follows the + "compression policies" step in the same pass, which is what moves the hypertable to the new setting first + (the re-group does nothing until it has). Counted as a change per chunk re-grouped. */ + new("perfmon chunk re-group", StoreObjectConvergenceStage.TimescaleAfterRepairLaunch, StoreObjectChangeSignal.Delta, + (connection, logger, ct) => Task.FromResult(0), + (connection, logger, ct) => TimescaleSupport.RegroupPerfmonChunksAsync(connection, logger, ct)), }; /// What one convergence pass did, accumulated across its segments so the start path's three diff --git a/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs b/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs index 4cdcbcedd1..5751f54e43 100644 --- a/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs +++ b/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs @@ -316,16 +316,41 @@ public static string EnableCompressionSql(string table) /// public const string CollectionLogSegmentBy = CompressionSegmentByColumn + ", collector_name"; + /// The collector table the Performance Counters collector writes (the bare name, as + /// hypertable_name spells it). + public const string PerfmonStatsTable = "perfmon_stats"; + + /// + /// perfmon_stats's segmentby (#5574): by counter as well as by server. The one-counter trend read + /// (get_perfmon_trend, the Viewer's perfmon charts) filters server_id = $1 AND counter_name = $2 and + /// nothing else by equality (its object_name test is a suffix match), and with server_id alone + /// every such read decompressed the counter and object names of every counter the server collects, to keep + /// one counter's rows (11.2 s cold on a large store, #5562). object_name and instance_name are + /// left out on purpose: no read asks for them by equality, and a finer grouping only adds batches that compress + /// worse. Spelled with ", " for the reason gives. The orderby is not set, + /// so it stays what the table already had (collection_time DESC). + /// + public const string PerfmonStatsSegmentBy = CompressionSegmentByColumn + ", counter_name"; + /// /// The segmentby the enable statement sets for and the convergence read compares - /// against: for collection_log, - /// for every other table. Keyed by the bare name, which is how both and the - /// read's hypertable_name spell it; a schema-qualified name (collect.collection_log) is matched by + /// against: for collection_log, for + /// perfmon_stats (#5574), for every other table. Keyed by the bare + /// name, which is how , and the read's + /// hypertable_name spell it; a schema-qualified name (collect.collection_log) is matched by /// its last part, so a statement built from that spelling sets the value the read compares against. One lookup /// for both halves, for the reason gives. /// public static string CompressionSegmentByFor(string table) - => table.AsSpan(table.LastIndexOf('.') + 1).Equals(CollectionLogTable, StringComparison.Ordinal) ? CollectionLogSegmentBy : CompressionSegmentByColumn; + { + var bare = table.AsSpan(table.LastIndexOf('.') + 1); + if (bare.Equals(CollectionLogTable, StringComparison.Ordinal)) + { + return CollectionLogSegmentBy; + } + + return bare.Equals(PerfmonStatsTable, StringComparison.Ordinal) ? PerfmonStatsSegmentBy : CompressionSegmentByColumn; + } /// /// One collector table's background compression policy — chunks older than @@ -10831,8 +10856,28 @@ internal enum BoundedDdlOutcome /// Warning and clears the streak. Neither throws, so the caller keeps its per-table /// isolation; cancellation still propagates. /// - internal static async Task TryRunBoundedDdlAsync( + internal static Task TryRunBoundedDdlAsync( NpgsqlConnection connection, IReadOnlyList statements, ILogger? logger, string what, CancellationToken cancellationToken) + => TryRunBoundedDdlAsync( + connection, + async transaction => + { + foreach (var statement in statements) + { + using var command = new NpgsqlCommand(statement, connection, transaction) { CommandTimeout = SetupTimeoutSeconds }; + await command.ExecuteNonQueryAsync(cancellationToken); + } + }, + logger, what, cancellationToken); + + /// + /// + /// for a body that needs a statement's result (#5574: the chunk re-group counts its rows between the decompress and + /// the compress). runs in the same transaction, behind the same SET LOCAL + /// lock_timeout, and the same outcomes and log lines apply. The list overload is this one with a loop for a body. + /// + internal static async Task TryRunBoundedDdlAsync( + NpgsqlConnection connection, Func body, ILogger? logger, string what, CancellationToken cancellationToken) { try { @@ -10842,11 +10887,7 @@ internal static async Task TryRunBoundedDdlAsync( await timeout.ExecuteNonQueryAsync(cancellationToken); } - foreach (var statement in statements) - { - using var command = new NpgsqlCommand(statement, connection, transaction) { CommandTimeout = SetupTimeoutSeconds }; - await command.ExecuteNonQueryAsync(cancellationToken); - } + await body(transaction); await transaction.CommitAsync(cancellationToken); if (BusyStreaks.Clear(what, out var busyPasses)) @@ -10950,6 +10991,14 @@ is idempotent in cost as well as in effect. Only the ALTER needed guarding. */ { enabledAlready++; } + else if (!string.Equals(CompressionSegmentByFor(schema.TargetTable), CompressionSegmentByColumn, StringComparison.Ordinal) + && await SettingsChangeBlockedAsync(connection, schema.TargetTable, logger, cancellationToken)) + { + /* #5574: a table with a grouping of its own (perfmon_stats) on a TimescaleDB that cannot change the + settings while compressed chunks exist keeps compressing under the ones it has, exactly as + collection_log does (#4951); the policy call below still runs. The other tables all want plain + server_id, so they skip this read and attempt the ALTER as before. */ + } else { var outcome = await TryRunBoundedDdlAsync( @@ -12108,13 +12157,14 @@ public static async Task EnsureCollectionLogHypertableAsync(NpgsqlConnecti public static bool CompressionSettingsChangeBlocked(Version? timescaleVersion, bool hasCompressedChunks) => hasCompressedChunks && timescaleVersion is not null && timescaleVersion < CompressionSettingsChangeWithCompressedChunksFrom; - /// The TimescaleDB version and whether collection_log has a compressed chunk, in one round trip. - private const string CollectionLogSettingsChangeStateSql = @" + /// The TimescaleDB version and whether the collect table in $1 has a compressed chunk, in one round + /// trip (collection_log since #4951, perfmon_stats since #5574). + private const string SettingsChangeStateSql = @" SELECT (SELECT e.extversion FROM pg_extension AS e WHERE e.extname = 'timescaledb'), EXISTS (SELECT 1 FROM timescaledb_information.chunks AS c WHERE c.hypertable_schema = 'collect' - AND c.hypertable_name = 'collection_log' + AND c.hypertable_name = $1 AND c.is_compressed)"; /// @@ -12123,13 +12173,23 @@ FROM timescaledb_information.chunks AS c /// finds the settings differ, which is every hourly pass on such a store, so the line says what changes it. A read /// that fails is not a block: the ALTER is attempted, and its own failure line covers a store that refuses it. /// - private static async Task CollectionLogSettingsChangeBlockedAsync(NpgsqlConnection connection, ILogger? logger, CancellationToken cancellationToken) + private static Task CollectionLogSettingsChangeBlockedAsync(NpgsqlConnection connection, ILogger? logger, CancellationToken cancellationToken) + => SettingsChangeBlockedAsync(connection, CollectionLogTable, logger, cancellationToken); + + /// + /// for any collect table (#5574 asks it for + /// perfmon_stats): the same version floor, the same "a failed read is not a block" rule, the same line each pass. + /// Every table that asks wants a segmentby of its own on top of plain server_id, so "keeps compressing by + /// server_id" is true of each. + /// + private static async Task SettingsChangeBlockedAsync(NpgsqlConnection connection, string table, ILogger? logger, CancellationToken cancellationToken) { Version? version; bool hasCompressedChunks; try { - using var command = new NpgsqlCommand(CollectionLogSettingsChangeStateSql, connection) { CommandTimeout = JobCatalogReadTimeoutSeconds }; + using var command = new NpgsqlCommand(SettingsChangeStateSql, connection) { CommandTimeout = JobCatalogReadTimeoutSeconds }; + command.Parameters.AddWithValue(table); await using var reader = await command.ExecuteReaderAsync(cancellationToken); if (!await reader.ReadAsync(cancellationToken)) { @@ -12141,7 +12201,7 @@ private static async Task CollectionLogSettingsChangeBlockedAsync(NpgsqlCo } catch (Exception ex) when (ex is not OperationCanceledException) { - logger?.LogDebug("Could not read the TimescaleDB version or collection_log's compressed chunks, so the compression settings change is attempted (#4951): {Message}", ex.Message); + logger?.LogDebug("Could not read the TimescaleDB version or {Table}'s compressed chunks, so the compression settings change is attempted (#4951): {Message}", table, ex.Message); return false; } @@ -12151,11 +12211,252 @@ private static async Task CollectionLogSettingsChangeBlockedAsync(NpgsqlCo } logger?.LogInformation( - "TimescaleDB: collection_log keeps compressing by server_id: TimescaleDB {Version} cannot change compression settings while compressed chunks exist, and {Floor} and later can. Each hourly pass checks again, so the change applies after the extension is upgraded (#4951)", - version, CompressionSettingsChangeWithCompressedChunksFrom); + "TimescaleDB: {Table} keeps compressing by server_id: TimescaleDB {Version} cannot change compression settings while compressed chunks exist, and {Floor} and later can. Each hourly pass checks again, so the change applies after the extension is upgraded (#4951, #5574)", + table, version, CompressionSettingsChangeWithCompressedChunksFrom); return true; } + /* ---------------- perfmon_stats chunk re-group (#5574) ---------------- */ + + /// + /// How many days back the perfmon chunk re-group reaches (#5574): the window the one-counter trend read can ask + /// for, so a chunk older than this is never read by it and ages out with retention, untouched. The same 30 days + /// as the web and MCP trend reads' raw reach. + /// + public const int PerfmonRegroupReachDays = 30; + + /// + /// How long one pass keeps starting chunks (#5574). A chunk already running finishes, so a pass can run past this + /// by one chunk; the first chunk of a pass always starts, so a budget shorter than a chunk still makes progress. + /// + public static readonly TimeSpan PerfmonRegroupPassBudget = TimeSpan.FromMinutes(2); + + /// Chunks in a row that fail (not a busy lock) before a pass stops: a condition that fails one chunk (a full + /// disk, a missing privilege) fails the next one too, and each attempt decompresses a whole chunk first. + internal const int PerfmonRegroupFailureLimit = 3; + + /// perfmon_stats's wanted segmentby as timescaledb_information.chunk_compression_settings spells it + /// (comma, no space), which is not how the hypertable-level view spells it. + internal static readonly string PerfmonStatsChunkSegmentBy = PerfmonStatsSegmentBy.Replace(", ", ",", StringComparison.Ordinal); + + /// The first TimescaleDB release with timescaledb_information.chunk_compression_settings (#5574). + /// Settings can change with compressed chunks from 2.14.0 + /// (), but the per-chunk view that says which grouping + /// a chunk was compressed with arrived in 2.14.1 (sql/updates/2.14.0--2.14.1.sql creates it; the 2.14.0 views + /// file has no such view). Without it the re-group cannot tell an old chunk from a new one, so the gate reads the + /// view's presence, not a version number. + public static readonly Version PerChunkCompressionSettingsViewFrom = new(2, 14, 1); + + /// The version, whether the per-chunk settings view exists, and perfmon_stats's own segmentby, in one round + /// trip. The view test is to_regclass, which answers NULL rather than raising on a store without it. + private const string PerfmonRegroupStateSql = @" +SELECT (SELECT e.extversion FROM pg_extension AS e WHERE e.extname = 'timescaledb'), + to_regclass('timescaledb_information.chunk_compression_settings') IS NOT NULL, + (SELECT string_agg(cs.attname, ', ' ORDER BY cs.segmentby_column_index) + FROM timescaledb_information.compression_settings AS cs + WHERE cs.hypertable_schema = 'collect' + AND cs.hypertable_name = 'perfmon_stats' + AND cs.segmentby_column_index IS NOT NULL)"; + + /// + /// The compressed perfmon_stats chunks inside the reach that were compressed with another grouping, newest first: + /// $1 the reach in days, $2 the wanted grouping in the per-chunk view's spelling. Each chunk's OWN setting is read + /// (the view joins the chunk, not the hypertable), because the hypertable's setting says nothing about a chunk + /// compressed before it changed. range_end is the chunk's upper bound as a real instant (the view converts the + /// internal UTC microseconds), so it compares to now() without a time zone step. The result is empty on a + /// converged store, and the read costs one catalog join. + /// + private const string PerfmonRegroupCandidatesSql = @" +SELECT format('%I.%I', c.chunk_schema, c.chunk_name), s.segmentby +FROM timescaledb_information.chunks AS c +JOIN timescaledb_information.chunk_compression_settings AS s + ON s.chunk = to_regclass(format('%I.%I', c.chunk_schema, c.chunk_name)) +WHERE c.hypertable_schema = 'collect' +AND c.hypertable_name = 'perfmon_stats' +AND c.is_compressed +AND c.range_end > now() - make_interval(days => $1) +AND s.segmentby IS DISTINCT FROM $2 +ORDER BY c.range_start DESC"; + + /// + /// Why the perfmon chunk re-group cannot run now, or null when it can (#5574). Pure, so the arms pin. Three + /// reasons, checked in this order: a TimescaleDB below + /// (the settings never changed, so there is nothing to + /// re-group to), no per-chunk settings view (), and a hypertable that + /// does not yet carry the wanted grouping (the settings change was busy or failed this pass: compressing a chunk now + /// would write it with the OLD grouping again, and the next pass would find it again). An unknown version is not a + /// reason, for the reason gives; the view test covers it. + /// + internal static string? PerfmonRegroupBlockedReason(Version? timescaleVersion, bool hasPerChunkSettingsView, string? hypertableSegmentBy) + { + if (timescaleVersion is not null && timescaleVersion < CompressionSettingsChangeWithCompressedChunksFrom) + { + return $"TimescaleDB {timescaleVersion} cannot change compression settings while compressed chunks exist, so perfmon_stats was never re-grouped"; + } + + if (!hasPerChunkSettingsView) + { + return $"this TimescaleDB has no timescaledb_information.chunk_compression_settings (added in {PerChunkCompressionSettingsViewFrom}), so a chunk's grouping cannot be read"; + } + + if (!string.Equals(hypertableSegmentBy, PerfmonStatsSegmentBy, StringComparison.Ordinal)) + { + return $"perfmon_stats still has segmentby '{hypertableSegmentBy ?? "(none)"}', not '{PerfmonStatsSegmentBy}' (the settings change has not applied), and a chunk compressed now would get the old grouping again"; + } + + return null; + } + + /// + /// Re-groups the perfmon_stats chunks that were compressed by server_id alone (#5574), so a one-counter trend + /// read over them skips every other counter's batches the way it already does on a chunk compressed after the + /// settings change. Returns the number of chunks re-grouped this pass. + /// + /// Why it exists. The settings change () reaches only chunks + /// compressed after it ( explains why), and collection_log can + /// let its old chunks age out. perfmon_stats cannot: its trend read now reaches 30 days, and chunks compress after + /// days, so a store would read old-shape chunks for the better part of a month. This rewrites the ones inside the + /// reach (); older ones are never read by it and go with retention. + /// + /// One chunk, one transaction. decompress_chunk then compress_chunk run in ONE transaction + /// behind (), + /// so no other session ever sees the chunk uncompressed or half done, and any failure leaves the chunk as it was. + /// The decompress takes an ACCESS EXCLUSIVE lock on that chunk until commit, so reads of that chunk's days wait + /// for it; a lock that cannot be had in time skips the chunk to the next pass. Between the two calls the chunk's + /// rows are counted (a plain heap scan, for the log line). Needs room for the whole chunk uncompressed plus its + /// indexes, and writes it to the WAL, for the length of one chunk. + /// + /// Gates. . The hypertable's own setting is checked every pass + /// because compressing under the old one would undo the work. + /// + /// Budget. Chunks are taken newest first (the most-read days first), and no new chunk starts after + /// (the first always does). A converged store costs two catalog reads + /// and logs at Debug; a pass that did or skipped work logs one Information line with the chunks left. + /// + public static Task RegroupPerfmonChunksAsync(NpgsqlConnection connection, ILogger? logger, CancellationToken cancellationToken = default) + => RegroupPerfmonChunksAsync(connection, logger, PerfmonRegroupReachDays, PerfmonRegroupPassBudget, cancellationToken); + + /// + internal static async Task RegroupPerfmonChunksAsync( + NpgsqlConnection connection, ILogger? logger, int reachDays, TimeSpan budget, CancellationToken cancellationToken) + { + if (connection is null) + { + throw new ArgumentNullException(nameof(connection)); + } + + var candidates = new List<(string Chunk, string? OldSegmentBy)>(); + try + { + Version? version; + bool hasView; + string? current; + using (var state = new NpgsqlCommand(PerfmonRegroupStateSql, connection) { CommandTimeout = JobCatalogReadTimeoutSeconds }) + await using (var reader = await state.ExecuteReaderAsync(cancellationToken)) + { + if (!await reader.ReadAsync(cancellationToken)) + { + return 0; + } + + version = ParseTimescaleVersion(reader.IsDBNull(0) ? null : reader.GetString(0)); + hasView = !reader.IsDBNull(1) && reader.GetBoolean(1); + current = reader.IsDBNull(2) ? null : reader.GetString(2); + } + + var blocked = PerfmonRegroupBlockedReason(version, hasView, current); + if (blocked is not null) + { + logger?.LogDebug("TimescaleDB: perfmon_stats chunks are not re-grouped this pass: {Reason} (#5574)", blocked); + return 0; + } + + using var find = new NpgsqlCommand(PerfmonRegroupCandidatesSql, connection) { CommandTimeout = JobCatalogReadTimeoutSeconds }; + find.Parameters.AddWithValue(reachDays); + find.Parameters.AddWithValue(PerfmonStatsChunkSegmentBy); + await using var chunks = await find.ExecuteReaderAsync(cancellationToken); + while (await chunks.ReadAsync(cancellationToken)) + { + candidates.Add((chunks.GetString(0), chunks.IsDBNull(1) ? null : chunks.GetString(1))); + } + } + catch (Exception ex) when (ex is not OperationCanceledException) + { + logger?.LogDebug("TimescaleDB: could not read perfmon_stats's chunk compression settings, so no chunk is re-grouped this pass (#5574): {Message}", ex.Message); + return 0; + } + + if (candidates.Count == 0) + { + logger?.LogDebug("TimescaleDB: no perfmon_stats chunk inside the {Days}-day reach has the old grouping (#5574)", reachDays); + return 0; + } + + var done = 0; + var tried = 0; + var failuresInARow = 0; + var pass = Stopwatch.StartNew(); + foreach (var (chunk, oldSegmentBy) in candidates) + { + if (tried > 0 && pass.Elapsed >= budget) + { + break; + } + + tried++; + long rows = 0; + var clock = Stopwatch.StartNew(); + var outcome = await TryRunBoundedDdlAsync( + connection, + async transaction => + { + using (var decompress = new NpgsqlCommand("SELECT decompress_chunk($1::regclass)", connection, transaction) { CommandTimeout = SetupTimeoutSeconds }) + { + decompress.Parameters.AddWithValue(chunk); + await decompress.ExecuteNonQueryAsync(cancellationToken); + } + + /* The chunk's name came out of the catalog already quoted by format('%I.%I'), so it is safe to splice. */ + using (var count = new NpgsqlCommand($"SELECT count(*) FROM {chunk}", connection, transaction) { CommandTimeout = SetupTimeoutSeconds }) + { + rows = Convert.ToInt64(await count.ExecuteScalarAsync(cancellationToken), CultureInfo.InvariantCulture); + } + + using (var compress = new NpgsqlCommand("SELECT compress_chunk($1::regclass)", connection, transaction) { CommandTimeout = SetupTimeoutSeconds }) + { + compress.Parameters.AddWithValue(chunk); + await compress.ExecuteNonQueryAsync(cancellationToken); + } + }, + logger, $"re-grouping perfmon_stats chunk {chunk}", cancellationToken); + + if (outcome == BoundedDdlOutcome.Applied) + { + done++; + failuresInARow = 0; + logger?.LogInformation( + "TimescaleDB: re-grouped perfmon_stats chunk {Chunk} ({Rows} rows) from '{Old}' to '{New}' in {ElapsedMs} ms (#5574)", + chunk, rows, oldSegmentBy ?? "(none)", PerfmonStatsChunkSegmentBy, clock.ElapsedMilliseconds); + } + else if (outcome == BoundedDdlOutcome.Failed && ++failuresInARow >= PerfmonRegroupFailureLimit) + { + logger?.LogWarning( + "TimescaleDB: {Failures} perfmon_stats chunks in a row could not be re-grouped, so this pass stops; the next hourly pass tries again (#5574)", + failuresInARow); + break; + } + else if (outcome == BoundedDdlOutcome.LockBusy) + { + failuresInARow = 0; + } + } + + logger?.LogInformation( + "TimescaleDB: perfmon_stats re-group: {Done} chunk(s) re-grouped to '{New}' this pass in {ElapsedMs} ms; {Left} chunk(s) inside the {Days}-day reach still have the old grouping and are taken, newest first, on the next hourly passes (#5574)", + done, PerfmonStatsChunkSegmentBy, pass.ElapsedMilliseconds, candidates.Count - done, reachDays); + return done; + } + /* ---------------- compression-job self-heal (#1581) ---------------- */ /// From 0ed76bdefcffb5b5a3737813167e1fd3fd12d011 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Thu, 8 Oct 2026 14:02:21 -0400 Subject: [PATCH 2/7] Perfmon re-group: readers are never blocked, and a background loop converges the 30-day reach in hours (#5574) The re-group now decompresses a chunk in one transaction and compresses it in a second, so the ACCESS EXCLUSIVE lock that decompress_chunk takes at its end is released before the compress half; reads of the chunk no longer wait for the rewrite. The work moves from a 2-minute slice of each hourly pass to a background loop (PerfmonRegroupDrain): one chunk at a time, newest first, a pause after each chunk as long as it took (at least 15 s), a busy lock skips the chunk for the run, three failures in a row stop it, and it ends on its own once nothing is left. --- .../BoundedDdlSingleCopyTests.cs | 4 +- .../Darling.Tests/PerfmonRegroupGateTests.cs | 75 +++++ .../Darling.Tests/PerfmonRegroupLiveTests.cs | 209 +++++++++++++ .../DarlingWorker.cs | 39 ++- .../PerfmonRegroupDrain.cs | 250 ++++++++++++++++ .../TimescaleSupport.cs | 274 ++++++++++++------ 6 files changed, 744 insertions(+), 107 deletions(-) create mode 100644 Darling/Darling.Tests/PerfmonRegroupLiveTests.cs create mode 100644 Darling/PerformanceMonitor.Darling.Storage/PerfmonRegroupDrain.cs diff --git a/Darling/Darling.Tests/BoundedDdlSingleCopyTests.cs b/Darling/Darling.Tests/BoundedDdlSingleCopyTests.cs index 17b30ef86e..40ff6dd58d 100644 --- a/Darling/Darling.Tests/BoundedDdlSingleCopyTests.cs +++ b/Darling/Darling.Tests/BoundedDdlSingleCopyTests.cs @@ -35,7 +35,9 @@ public void TheHourlyLockTimeout_IsSetInOneMethodOnly() var helper = text.IndexOf("internal static async Task TryRunBoundedDdlAsync(", StringComparison.Ordinal); Assert.True(helper >= 0 && helper < first && first - helper < 1200, "the one SET LOCAL lock_timeout must sit inside TryRunBoundedDdlAsync"); - Assert.Equal(1, text.Split("BoundedDdlOutcome> TryRun", StringSplitOptions.None).Length - 1); + /* Two overloads since #5574 (the statement-list one calls the body one, which owns the SET LOCAL above); a third + would be a second copy of the helper. */ + Assert.Equal(2, text.Split("BoundedDdlOutcome> TryRun", StringSplitOptions.None).Length - 1); } [Fact] diff --git a/Darling/Darling.Tests/PerfmonRegroupGateTests.cs b/Darling/Darling.Tests/PerfmonRegroupGateTests.cs index 08c07b0399..951d6f2295 100644 --- a/Darling/Darling.Tests/PerfmonRegroupGateTests.cs +++ b/Darling/Darling.Tests/PerfmonRegroupGateTests.cs @@ -7,6 +7,9 @@ */ using System; +using System.Threading; +using System.Threading.Tasks; +using Npgsql; using PerformanceMonitor.Darling.Storage; using Xunit; @@ -59,4 +62,76 @@ public void ThePerChunkSettingsView_ArrivedIn2_14_1_NotIn2_14_0() Assert.Equal(new Version(2, 14, 1), TimescaleSupport.PerChunkCompressionSettingsViewFrom); Assert.True(TimescaleSupport.PerChunkCompressionSettingsViewFrom > TimescaleSupport.CompressionSettingsChangeWithCompressedChunksFrom); } + + /// The hourly pass must never wait for a rewrite: StartIfIdle returns at once even while the run is + /// still opening its connection, a second start while one is in flight does nothing, and a run that fails ends + /// without throwing so the next hourly start can try again. + [Fact] + public async Task TheDrain_StartsWithoutWaiting_RunsOnce_AndANewRunFollowsAFailedOne() + { + var release = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var opens = 0; + var logger = new CapturingTestLogger(); + var drain = new PerfmonRegroupDrain(token => + { + Interlocked.Increment(ref opens); + return new ValueTask(release.Task); + }, logger); + + Assert.True(drain.StartIfIdle(CancellationToken.None)); + Assert.False(drain.StartIfIdle(CancellationToken.None)); + + release.SetException(new InvalidOperationException("no store")); + await drain.Completion!.WaitAsync(TimeSpan.FromSeconds(10), TestContext.Current.CancellationToken); + + Assert.True(drain.Completion.IsCompletedSuccessfully); + Assert.Equal(1, Volatile.Read(ref opens)); + Assert.Contains(logger.Lines, line => line.StartsWith("Warning:", StringComparison.Ordinal) && line.Contains("no store", StringComparison.Ordinal)); + Assert.True(drain.StartIfIdle(CancellationToken.None)); + await drain.Completion.WaitAsync(TimeSpan.FromSeconds(10), TestContext.Current.CancellationToken); + Assert.Equal(2, Volatile.Read(ref opens)); + } + + /// The service stopping ends a run that is still opening its connection, quietly. + [Fact] + public async Task TheDrain_StopsPromptly_WhenTheServiceStops() + { + using var stop = new CancellationTokenSource(); + var logger = new CapturingTestLogger(); + var drain = new PerfmonRegroupDrain(async token => + { + await Task.Delay(Timeout.Infinite, token); + throw new InvalidOperationException("unreachable"); + }, logger); + + Assert.True(drain.StartIfIdle(stop.Token)); + stop.Cancel(); + await drain.Completion!.WaitAsync(TimeSpan.FromSeconds(10), TestContext.Current.CancellationToken); + + Assert.True(drain.Completion.IsCompletedSuccessfully); + Assert.DoesNotContain(logger.Lines, line => line.StartsWith("Warning:", StringComparison.Ordinal)); + } + + /// + /// The wiring, as source text because the pass is an instance method that needs a store: the loop is started from the + /// hourly pass only (never the start path), after the convergence list, behind the TimescaleDB flag, and the pass + /// does not run the rewrite itself; shutdown joins it. + /// + [Fact] + public void TheHourlyPass_StartsTheDrain_AfterTheList_BehindTheTimescaleFlag_AndNeverAwaitsTheRewrite() + { + var worker = RepoFile.ReadRepoFile("Darling", "PerformanceMonitor.Darling.Service", "DarlingWorker.cs"); + var passStart = worker.IndexOf("private async Task ConvergeStoreObjectsAsync(", StringComparison.Ordinal); + Assert.True(passStart > 0); + var pass = worker.Substring(passStart, worker.IndexOf("private PerfmonRegroupDrain? _perfmonRegroupDrain;", passStart, StringComparison.Ordinal) - passStart); + var loopEnd = pass.IndexOf("RunStoreObjectConvergenceStepAsync(connection, step, tally, _logger, budget.Token, hourly: true);", StringComparison.Ordinal); + var start = pass.IndexOf("StartPerfmonRegroupDrain(cancellationToken);", StringComparison.Ordinal); + var gate = pass.IndexOf("if (timescaleAvailable)", loopEnd, StringComparison.Ordinal); + Assert.True(loopEnd > 0 && gate > loopEnd && start > gate, "the drain must start after the list, behind the TimescaleDB flag"); + Assert.DoesNotContain("RegroupPerfmonChunkAsync", pass, StringComparison.Ordinal); + Assert.DoesNotContain("await StartPerfmonRegroupDrain", pass, StringComparison.Ordinal); + Assert.Equal(1, worker.Split("StartPerfmonRegroupDrain(", StringSplitOptions.None).Length - 2); + Assert.DoesNotContain("perfmon chunk re-group", worker, StringComparison.Ordinal); + Assert.Contains("_perfmonRegroupDrain?.Completion is { IsCompleted: false }", worker, StringComparison.Ordinal); + } } diff --git a/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs b/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs new file mode 100644 index 0000000000..91f85f09e2 --- /dev/null +++ b/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs @@ -0,0 +1,209 @@ +/* + * 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.Linq; +using System.Text.RegularExpressions; +using System.Threading; +using System.Threading.Tasks; +using Npgsql; +using PerformanceMonitor.Darling.Storage; +using Xunit; + +namespace Darling.Tests; + +/// +/// #5574: the perfmon_stats re-group loop against a real TimescaleDB store. Each test mints its own scratch database, like +/// , which this class mirrors. The old store is built with the statements +/// every build before #5574 ran (create_hypertable, then the enable ALTER with server_id alone), with its chunks +/// compressed under those settings. The expected groupings are literals on purpose: they pin the value the store ends up +/// with, so they must not move when the product's constant does. +/// +[Collection("live-postgres")] +public sealed class PerfmonRegroupLiveTests +{ + private const string WantedChunkSegmentBy = "server_id,counter_name"; + private const string OldChunkSegmentBy = "server_id"; + private const long IdBase = -495_200_000_000L; + + private sealed record ChunkRow(string Name, bool IsCompressed, string SegmentBy, DateTime Start); + + /// + /// The upgraded store converges: with the hypertable already on the new grouping, the drain re-groups the chunks inside + /// the 30-day reach newest first, leaves the chunk outside it alone, changes no row (count and a checksum per counter), + /// pauses after every chunk but the last, and a second run is a no-op. + /// + [Fact] + public async Task AnUpgradedStore_IsReGroupedNewestFirst_KeepsEveryRow_LeavesOutOfReachAlone_AndASecondRunIsANoOp() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + + var before = await ReadChunksAsync(connection, ct); + Assert.Equal(6, before.Count); + Assert.All(before, chunk => Assert.Equal(OldChunkSegmentBy, chunk.SegmentBy)); + var fingerprint = await FingerprintAsync(connection, ct); + + /* The hypertable still has the old grouping: the gate keeps the drain from writing the old grouping again. */ + var gated = new CapturingTestLogger(); + Assert.Equal(0, await NewDrain(scratch.ConnectionString, gated, TimeSpan.Zero, new List()).RunAsync(ct)); + Assert.DoesNotContain(gated.Lines, line => line.Contains("re-grouped perfmon_stats chunk", StringComparison.Ordinal)); + + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + var inReachNewestFirst = before.Where(chunk => chunk.Start > DateTime.UtcNow.AddDays(-30)).OrderByDescending(chunk => chunk.Start).Select(chunk => chunk.Name).ToList(); + Assert.Equal(5, inReachNewestFirst.Count); + + var logger = new CapturingTestLogger(); + var pauses = new List(); + Assert.Equal(5, await NewDrain(scratch.ConnectionString, logger, TimeSpan.FromSeconds(90), pauses).RunAsync(ct)); + + var after = await ReadChunksAsync(connection, ct); + Assert.All(after.Where(chunk => inReachNewestFirst.Contains(chunk.Name)), chunk => Assert.Equal(WantedChunkSegmentBy, chunk.SegmentBy)); + Assert.Equal(OldChunkSegmentBy, after.Single(chunk => !inReachNewestFirst.Contains(chunk.Name)).SegmentBy); + Assert.Equal(inReachNewestFirst, logger.Lines + .Select(line => Regex.Match(line, @"re-grouped perfmon_stats chunk (\S+) ")) + .Where(match => match.Success).Select(match => match.Groups[1].Value).ToList()); + Assert.Equal(fingerprint, await FingerprintAsync(connection, ct)); + + /* Four pauses for five chunks, none after the last, each the floor (a chunk this small takes far less). */ + Assert.Equal(4, pauses.Count); + Assert.All(pauses, pause => Assert.Equal(TimeSpan.FromSeconds(90), pause)); + + var second = new CapturingTestLogger(); + Assert.Equal(0, await NewDrain(scratch.ConnectionString, second, TimeSpan.Zero, new List()).RunAsync(ct)); + Assert.DoesNotContain(second.Lines, line => line.StartsWith("Information:", StringComparison.Ordinal)); + Assert.Equal(after, await ReadChunksAsync(connection, ct)); + } + + /* ---------------- fixture ---------------- */ + + private static string RequireLivePostgres() + { + var connectionString = Environment.GetEnvironmentVariable("DARLING_TEST_PG"); + Assert.SkipWhen(string.IsNullOrEmpty(connectionString), + "Set DARLING_TEST_PG to a Postgres connection string to run the perfmon_stats re-group tests (each mints its own scratch database)."); + return connectionString!; + } + + private static PerfmonRegroupDrain NewDrain(string connectionString, CapturingTestLogger logger, TimeSpan minPause, List pauses) => + new(async token => + { + var connection = new NpgsqlConnection(connectionString); + await connection.OpenAsync(token); + return connection; + }, + logger, 30, minPause, + (pause, token) => + { + pauses.Add(pause); + return Task.CompletedTask; + }); + + /// + /// perfmon_stats as every build before #5574 left it: a hypertable compressed by server_id alone, five daily + /// chunks inside the reach (yesterday back to five days ago) and one 45 days back, all compressed. Skips on a TimescaleDB + /// without the per-chunk settings view (before 2.14.1), which these tests read. + /// + private static async Task BuildOldStoreAsync(NpgsqlConnection connection, string connectionString, CancellationToken ct) + { + await PgMigrations.MigrateAsync(connection, ct); + Assert.SkipUnless(await LiveTimescaleProbe.TryEnableAsync(connectionString, ct), "TimescaleDB is not available on this cluster."); + await ExecAsync(connection, "SELECT _timescaledb_functions.stop_background_workers()", ct); + Assert.SkipUnless( + await ScalarAsync(connection, "SELECT to_regclass('timescaledb_information.chunk_compression_settings') IS NOT NULL", ct), + "this TimescaleDB has no timescaledb_information.chunk_compression_settings (before 2.14.1)."); + + await ExecAsync(connection, TimescaleSupport.CreateHypertableSql(TimescaleSupport.PerfmonStatsTable, "collection_time"), ct); + await ExecAsync(connection, "ALTER TABLE perfmon_stats SET (timescaledb.compress, timescaledb.compress_segmentby = 'server_id')", ct); + + var today = DateTime.SpecifyKind(DateTime.UtcNow.Date, DateTimeKind.Unspecified); + foreach (var daysBack in new[] { 1, 2, 3, 4, 5, 45 }) + { + await SeedDayAsync(connection, today.AddDays(-daysBack), daysBack, ct); + } + + var chunks = new List(); + using (var list = new NpgsqlCommand( + "SELECT format('%I.%I', chunk_schema, chunk_name) FROM timescaledb_information.chunks " + + "WHERE hypertable_schema = 'collect' AND hypertable_name = 'perfmon_stats' AND NOT is_compressed AND range_end <= now()", connection)) + await using (var reader = await list.ExecuteReaderAsync(ct)) + { + while (await reader.ReadAsync(ct)) + { + chunks.Add(reader.GetString(0)); + } + } + + foreach (var chunk in chunks) + { + await ExecAsync(connection, $"SELECT compress_chunk('{chunk}')", ct); + } + } + + /// Two servers, four counters, two instances each, a sample every 30 minutes: 768 rows for the day. + private static async Task SeedDayAsync(NpgsqlConnection connection, DateTime day, int salt, CancellationToken ct) + { + using var command = new NpgsqlCommand( + @"INSERT INTO perfmon_stats (collection_id, collection_time, server_id, server_name, object_name, counter_name, instance_name, cntr_value, delta_cntr_value, sample_interval_seconds, cntr_type) + SELECT $1 - $3 * 100000 - row_number() OVER (), g.t, s.id, 'REGROUP-SRV', 'SQLServer:Test', 'Counter ' || c.n, + CASE WHEN i.i = 0 THEN '' ELSE 'inst' || i.i END, + (extract(epoch FROM g.t)::bigint / 60 + s.id + c.n * 7 + i.i) % 100000, (extract(epoch FROM g.t)::bigint / 60 + c.n) % 50, 60, 65792 + FROM generate_series($2::timestamp, $2::timestamp + INTERVAL '23 hours 30 minutes', INTERVAL '30 minutes') AS g(t) + CROSS JOIN generate_series(1, 2) AS s(id) + CROSS JOIN generate_series(1, 4) AS c(n) + CROSS JOIN generate_series(0, 1) AS i(i)", connection); + command.Parameters.AddWithValue(IdBase); + command.Parameters.AddWithValue(day); + command.Parameters.AddWithValue(salt); + await command.ExecuteNonQueryAsync(ct); + } + + private static async Task> ReadChunksAsync(NpgsqlConnection connection, CancellationToken ct) + { + using var command = new NpgsqlCommand( + @"SELECT format('%I.%I', c.chunk_schema, c.chunk_name), c.is_compressed, coalesce(s.segmentby, ''), (c.range_start AT TIME ZONE 'UTC') + FROM timescaledb_information.chunks AS c + LEFT JOIN timescaledb_information.chunk_compression_settings AS s ON s.chunk = to_regclass(format('%I.%I', c.chunk_schema, c.chunk_name)) + WHERE c.hypertable_schema = 'collect' AND c.hypertable_name = 'perfmon_stats' + ORDER BY c.range_start DESC", connection); + var chunks = new List(); + await using var reader = await command.ExecuteReaderAsync(ct); + while (await reader.ReadAsync(ct)) + { + chunks.Add(new ChunkRow(reader.GetString(0), reader.GetBoolean(1), reader.GetString(2), DateTime.SpecifyKind(reader.GetDateTime(3), DateTimeKind.Utc))); + } + + return chunks; + } + + /// One md5 over the row count and a hash sum per (server, counter): unchanged data gives the same value. + private static Task FingerprintAsync(NpgsqlConnection connection, CancellationToken ct) => + ScalarAsync(connection, + @"SELECT md5(string_agg(concat_ws('|', server_id, counter_name, n, h), ',' ORDER BY server_id, counter_name)) + FROM (SELECT server_id, counter_name, count(*) AS n, + sum(hashtextextended(concat_ws('|', collection_id, collection_time, instance_name, cntr_value, delta_cntr_value, sample_interval_seconds, cntr_type), 0)::numeric) AS h + FROM perfmon_stats GROUP BY server_id, counter_name) AS t", ct); + + private static async Task ExecAsync(NpgsqlConnection connection, string sql, CancellationToken ct) + { + using var command = new NpgsqlCommand(sql, connection); + await command.ExecuteNonQueryAsync(ct); + } + + private static async Task ScalarAsync(NpgsqlConnection connection, string sql, CancellationToken ct) + { + using var command = new NpgsqlCommand(sql, connection); + var value = await command.ExecuteScalarAsync(ct); + return (T)Convert.ChangeType(value!, typeof(T), System.Globalization.CultureInfo.InvariantCulture); + } +} diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs index 2810ca40f5..b026410bc2 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs @@ -436,16 +436,6 @@ finds nothing once every hypertable carries the reloption. Wrapped whole rather new("composer performance tuning", StoreObjectConvergenceStage.Tuning, StoreObjectChangeSignal.InPlace, (connection, logger, ct) => PgTableTuning.ApplyAsync(connection, logger, ct), (connection, logger, ct) => PgTableTuning.ApplyAsync(connection, logger, hourly: true, ct)), - - /* #5574: LAST on purpose. perfmon_stats chunks compressed before the segmentby change (server_id alone) are - re-grouped by counter, newest first, inside the 30-day trend reach, for at most two minutes of a pass, so the - cheap steps above are never made to wait behind it. Hourly only: the start path would hold the service's - start for those minutes, and a store that has not converged is served by the next :30 tick. It follows the - "compression policies" step in the same pass, which is what moves the hypertable to the new setting first - (the re-group does nothing until it has). Counted as a change per chunk re-grouped. */ - new("perfmon chunk re-group", StoreObjectConvergenceStage.TimescaleAfterRepairLaunch, StoreObjectChangeSignal.Delta, - (connection, logger, ct) => Task.FromResult(0), - (connection, logger, ct) => TimescaleSupport.RegroupPerfmonChunksAsync(connection, logger, ct)), }; /// What one convergence pass did, accumulated across its segments so the start path's three @@ -4022,6 +4012,13 @@ because stoppingToken is already cancelled at this point. */ inFlightSweeps.Add(_selfAlertPass); } + /* #5574: the perfmon_stats re-group loop ends on the same cancellation; its chunk in flight rolls back or is left + for the compression policy, and the loop never faults. */ + if (_perfmonRegroupDrain?.Completion is { IsCompleted: false } regroupRun) + { + inFlightSweeps.Add(regroupRun); + } + /* #4938: the daily runs detached from those bodies join the wait inside DrainInFlightAsync. */ await DrainInFlightAsync(inFlightSweeps); @@ -10071,6 +10068,18 @@ private async Task ConvergeStoreObjectsAsync(CancellationToken cancellationToken await RunStoreObjectConvergenceStepAsync(connection, step, tally, _logger, budget.Token, hourly: true); } + /* #5574: the perfmon_stats chunk re-group, AFTER the whole list because the "compression policies" step is what + moves the hypertable to the new grouping first (the re-group does nothing until it has). It is a background + loop on its own connection and the service's stopping token, not a step: the rewrite of a large store's chunk + takes minutes, and a step would hold this pass (and the sweep loop that awaits it) for them. Starting it costs + nothing here (no database work, and nothing when a run is already going); a converged store's run is two + catalog reads and it ends. Hourly only: the start path does not call it, so a restart is not held, and the + first :30 tick starts it. TimescaleDB-gated like the steps that need it. */ + if (timescaleAvailable) + { + StartPerfmonRegroupDrain(cancellationToken); + } + LogStoreObjectConvergence(tally, passClock.ElapsedMilliseconds, startup: false); } catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) @@ -10091,6 +10100,16 @@ private async Task ConvergeStoreObjectsAsync(CancellationToken cancellationToken } } + /// The perfmon_stats chunk re-group loop (#5574); null until the first hourly pass on a store with TimescaleDB. + private PerfmonRegroupDrain? _perfmonRegroupDrain; + + /// Starts the re-group loop unless one is running. Never throws and does no database work on this thread. + private void StartPerfmonRegroupDrain(CancellationToken stoppingToken) + { + _perfmonRegroupDrain ??= new PerfmonRegroupDrain(token => _postgres!.OpenConnectionAsync(token), _logger); + _perfmonRegroupDrain.StartIfIdle(stoppingToken); + } + /// /// One SEGMENT of on the start path — the steps tagged /// , in the list's order, on the connection that segment's try block owns diff --git a/Darling/PerformanceMonitor.Darling.Storage/PerfmonRegroupDrain.cs b/Darling/PerformanceMonitor.Darling.Storage/PerfmonRegroupDrain.cs new file mode 100644 index 0000000000..2b1a50a077 --- /dev/null +++ b/Darling/PerformanceMonitor.Darling.Storage/PerfmonRegroupDrain.cs @@ -0,0 +1,250 @@ +/* + * 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.Diagnostics; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using Npgsql; + +namespace PerformanceMonitor.Darling.Storage; + +/// +/// The background loop that re-groups the perfmon_stats chunks compressed by server_id alone (#5574), one chunk at +/// a time, newest first, inside the 30-day reach (). +/// +/// Why a loop of its own, not a step of the hourly pass. The first version re-grouped for at most two minutes +/// of each hourly pass. A large store's chunk (13.1 M rows measured, about 14 M per day on the biggest) takes minutes +/// to rewrite, so two minutes an hour reached one chunk an hour and the 30-day reach took more than a day of hourly +/// passes. The hourly pass now only calls , which does no database work and returns at once; the +/// rewrite runs here, on its own connection, so the pass (and the collection sweep that awaits it) never waits for a chunk. +/// +/// One chunk, then a pause as long as the chunk took (never under ), +/// so the store spends at most half its time on the rewrite. Thirty chunks of about 3 minutes finish in about three hours, +/// which is "hours, not days" without loading the store: the reads and the collectors share the disk with it. +/// +/// It stops by itself. When no chunk is left it ends after two catalog reads (Debug); the next hourly pass +/// starts it again for the price of those two reads on a new connection. It also ends on three failed chunks in a row +/// (), and when every chunk left was skipped for a busy lock this +/// run (a skipped chunk is not tried again until the next hourly start, so one busy chunk cannot pin the loop). It stops +/// within a statement of the service stopping: the chunk in progress is cancelled and rolls back, or, when only the compress +/// half was cancelled, is left uncompressed for the compression policy to compress with the new grouping. +/// +/// Gated exactly as the first version was: is asked +/// before every chunk (the hypertable must already carry the new grouping, TimescaleDB must be able to change settings +/// with compressed chunks, and the per-chunk settings view must exist), and the caller starts it only on a store with +/// TimescaleDB and only on the hourly pass, never on the start path. +/// +public sealed class PerfmonRegroupDrain +{ + private readonly Func> _openConnection; + private readonly ILogger? _logger; + private readonly int _reachDays; + private readonly TimeSpan _minPause; + private readonly Func _delay; + private readonly object _gate = new(); + private Task? _running; + + /// Opens a store connection; the drain owns and disposes what it gets, one per run. + /// Where the per-chunk and per-run lines go. + public PerfmonRegroupDrain(Func> openConnection, ILogger? logger) + : this(openConnection, logger, TimescaleSupport.PerfmonRegroupReachDays, TimescaleSupport.PerfmonRegroupMinPause, Task.Delay) + { + } + + /// The test seam: the reach, the pause floor and the wait itself (a test records the pauses it is asked for + /// instead of sleeping them). + internal PerfmonRegroupDrain( + Func> openConnection, + ILogger? logger, + int reachDays, + TimeSpan minPause, + Func delay) + { + _openConnection = openConnection ?? throw new ArgumentNullException(nameof(openConnection)); + _logger = logger; + _reachDays = reachDays; + _minPause = minPause; + _delay = delay ?? throw new ArgumentNullException(nameof(delay)); + } + + /// The run in flight (or the last one), so shutdown can wait for it. It never faults. + public Task? Completion + { + get + { + lock (_gate) + { + return _running; + } + } + } + + /// + /// Starts a run unless one is in flight; returns whether it started one. No database work happens on the caller's + /// thread: the first thing the run does is open its own connection and read the catalog, so the hourly pass pays + /// nothing for a converged store. + /// + public bool StartIfIdle(CancellationToken stoppingToken) + { + lock (_gate) + { + if (_running is { IsCompleted: false }) + { + return false; + } + + _running = Task.Run(() => RunGuardedAsync(stoppingToken), CancellationToken.None); + return true; + } + } + + private async Task RunGuardedAsync(CancellationToken stoppingToken) + { + try + { + await RunAsync(stoppingToken); + } + catch (OperationCanceledException) + { + /* The service is stopping; the chunk in flight rolled back or was left for the compression policy. */ + } + catch (Exception ex) + { + _logger?.LogWarning( + "TimescaleDB: the perfmon_stats re-group stopped on an error and starts again at the next hourly check (#5574): {Message}", + ex.Message); + } + } + + /// + /// One run: re-groups chunks, newest first, until none is left, the failure limit is reached, every chunk left was + /// skipped, or is cancelled (which throws). Returns the chunks re-grouped. + /// + internal async Task RunAsync(CancellationToken cancellationToken) + { + await using var connection = await _openConnection(cancellationToken); + var skipped = new HashSet(StringComparer.Ordinal); + var run = Stopwatch.StartNew(); + var done = 0; + var failuresInARow = 0; + var left = 0; + var owedPause = TimeSpan.Zero; + var started = false; + + while (true) + { + var candidates = await TimescaleSupport.ReadPerfmonRegroupCandidatesAsync(connection, _logger, _reachDays, cancellationToken); + var next = Next(candidates, skipped); + if (next is null) + { + left = candidates?.Count ?? -1; + break; + } + + if (owedPause > TimeSpan.Zero) + { + /* The wait is spent only when there is more to do (nothing waits after the last chunk), and the catalog + is read again after it: the policy or a restart may have re-grouped the chunk meanwhile. */ + await _delay(owedPause, cancellationToken); + owedPause = TimeSpan.Zero; + candidates = await TimescaleSupport.ReadPerfmonRegroupCandidatesAsync(connection, _logger, _reachDays, cancellationToken); + next = Next(candidates, skipped); + if (next is null) + { + left = candidates?.Count ?? -1; + break; + } + } + + if (!started) + { + started = true; + _logger?.LogInformation( + "TimescaleDB: perfmon_stats re-group started: {Chunks} chunk(s) inside the {Days}-day reach have the old grouping; they are re-grouped one at a time, newest first, each followed by a pause as long as it took (at least {MinPauseSeconds} s) (#5574)", + candidates!.Count, _reachDays, (int)_minPause.TotalSeconds); + } + + var outcome = await TimescaleSupport.RegroupPerfmonChunkAsync(connection, _logger, next.Value, cancellationToken); + switch (outcome.Result) + { + case TimescaleSupport.PerfmonRegroupChunkResult.Regrouped: + done++; + failuresInARow = 0; + owedPause = Max(outcome.Elapsed, _minPause); + break; + + case TimescaleSupport.PerfmonRegroupChunkResult.LockBusy: + /* Nothing changed. Skipped until the next start, so a chunk that stays busy is not hammered, and the + wait is the floor: the chunk cost a 3 s lock wait, not a rewrite. */ + skipped.Add(next.Value.Chunk); + failuresInARow = 0; + owedPause = _minPause; + break; + + case TimescaleSupport.PerfmonRegroupChunkResult.LeftUncompressed: + /* The chunk is now the compression policy's (no longer a candidate: it is not compressed). The store + just did a whole rewrite, so the wait is as long as it took, and it counts toward the limit. */ + owedPause = Max(outcome.Elapsed, _minPause); + failuresInARow++; + break; + + default: + skipped.Add(next.Value.Chunk); + failuresInARow++; + owedPause = _minPause; + break; + } + + if (failuresInARow >= TimescaleSupport.PerfmonRegroupFailureLimit) + { + _logger?.LogWarning( + "TimescaleDB: {Failures} perfmon_stats chunks in a row could not be re-grouped, so the re-group stops; the next hourly check tries again (#5574)", + failuresInARow); + left = -1; + break; + } + } + + if (done > 0 || skipped.Count > 0 || started) + { + _logger?.LogInformation( + "TimescaleDB: perfmon_stats re-group run over: {Done} chunk(s) re-grouped to '{New}' in {ElapsedMs} ms; {Skipped} skipped for a busy lock or an error (tried again at the next hourly check); {Left} chunk(s) inside the {Days}-day reach still have the old grouping (#5574)", + done, TimescaleSupport.PerfmonStatsSegmentBy, run.ElapsedMilliseconds, skipped.Count, left < 0 ? "an unknown number of" : left.ToString(System.Globalization.CultureInfo.InvariantCulture), _reachDays); + } + else + { + _logger?.LogDebug("TimescaleDB: no perfmon_stats chunk inside the {Days}-day reach has the old grouping to re-group (#5574)", _reachDays); + } + + return done; + } + + private static TimescaleSupport.PerfmonRegroupCandidate? Next( + IReadOnlyList? candidates, HashSet skipped) + { + if (candidates is null) + { + return null; + } + + foreach (var candidate in candidates) + { + if (!skipped.Contains(candidate.Chunk)) + { + return candidate; + } + } + + return null; + } + + private static TimeSpan Max(TimeSpan a, TimeSpan b) => a >= b ? a : b; +} diff --git a/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs b/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs index 5751f54e43..09ae452033 100644 --- a/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs +++ b/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs @@ -12226,15 +12226,26 @@ private static async Task SettingsChangeBlockedAsync(NpgsqlConnection conn public const int PerfmonRegroupReachDays = 30; /// - /// How long one pass keeps starting chunks (#5574). A chunk already running finishes, so a pass can run past this - /// by one chunk; the first chunk of a pass always starts, so a budget shorter than a chunk still makes progress. + /// The least the re-group drain waits after a chunk (#5574). It waits as long as the chunk it just did took, so the + /// store is busy with the rewrite at most half the time, and never less than this, so a small chunk cannot turn the + /// drain into back-to-back rewrites. Measured on a 13.1 M-row chunk the rewrite takes about 90 s, so the wait there is + /// the chunk's own time and this floor only matters for the small chunks of a quiet store. /// - public static readonly TimeSpan PerfmonRegroupPassBudget = TimeSpan.FromMinutes(2); + public static readonly TimeSpan PerfmonRegroupMinPause = TimeSpan.FromSeconds(15); - /// Chunks in a row that fail (not a busy lock) before a pass stops: a condition that fails one chunk (a full - /// disk, a missing privilege) fails the next one too, and each attempt decompresses a whole chunk first. + /// Chunks in a row that fail (not a busy lock) before the drain stops: a condition that fails one chunk (a full + /// disk, a missing privilege) fails the next one too, and each attempt decompresses a whole chunk first. The next + /// hourly check starts it again. internal const int PerfmonRegroupFailureLimit = 3; + /// + /// How many times the compress half of one chunk's re-group is tried (#5574). By then the decompress has committed, so + /// the chunk is uncompressed and a busy lock is worth a short retry; after the last try the chunk is left for the + /// compression policy, which compresses every uncompressed chunk past with the + /// hypertable's current grouping, which is the wanted one. + /// + internal const int PerfmonRegroupCompressAttempts = 3; + /// perfmon_stats's wanted segmentby as timescaledb_information.chunk_compression_settings spells it /// (comma, no space), which is not how the hypertable-level view spells it. internal static readonly string PerfmonStatsChunkSegmentBy = PerfmonStatsSegmentBy.Replace(", ", ",", StringComparison.Ordinal); @@ -12307,45 +12318,51 @@ AND s.segmentby IS DISTINCT FROM $2 return null; } + /// The wait between two tries of the compress half (see ). + internal static readonly TimeSpan PerfmonRegroupCompressRetryDelay = TimeSpan.FromSeconds(5); + + /// A compressed perfmon_stats chunk inside the reach that was compressed with another grouping. + internal readonly record struct PerfmonRegroupCandidate(string Chunk, string? OldSegmentBy); + + /// What did to one chunk. + internal enum PerfmonRegroupChunkResult + { + /// Decompressed and compressed again with the wanted grouping. + Regrouped, + + /// The decompress could not get its lock in time, so nothing changed. + LockBusy, + + /// The decompress failed and rolled back, so nothing changed. + Failed, + + /// The decompress committed and the compress did not (a busy lock on every try, a failure, or the + /// service stopping): the chunk is uncompressed and the compression policy compresses it with the wanted grouping. + LeftUncompressed, + } + + /// One chunk's result, the rows it held (-1 when the count failed) and how long it took. + internal readonly record struct PerfmonRegroupChunkOutcome(PerfmonRegroupChunkResult Result, long Rows, TimeSpan Elapsed); + /// - /// Re-groups the perfmon_stats chunks that were compressed by server_id alone (#5574), so a one-counter trend - /// read over them skips every other counter's batches the way it already does on a chunk compressed after the - /// settings change. Returns the number of chunks re-grouped this pass. - /// - /// Why it exists. The settings change () reaches only chunks - /// compressed after it ( explains why), and collection_log can - /// let its old chunks age out. perfmon_stats cannot: its trend read now reaches 30 days, and chunks compress after - /// days, so a store would read old-shape chunks for the better part of a month. This rewrites the ones inside the - /// reach (); older ones are never read by it and go with retention. - /// - /// One chunk, one transaction. decompress_chunk then compress_chunk run in ONE transaction - /// behind (), - /// so no other session ever sees the chunk uncompressed or half done, and any failure leaves the chunk as it was. - /// The decompress takes an ACCESS EXCLUSIVE lock on that chunk until commit, so reads of that chunk's days wait - /// for it; a lock that cannot be had in time skips the chunk to the next pass. Between the two calls the chunk's - /// rows are counted (a plain heap scan, for the log line). Needs room for the whole chunk uncompressed plus its - /// indexes, and writes it to the WAL, for the length of one chunk. - /// - /// Gates. . The hypertable's own setting is checked every pass - /// because compressing under the old one would undo the work. + /// The compressed perfmon_stats chunks inside the reach that still have the old grouping, newest first (#5574), or + /// null when the re-group cannot run now () or the catalog could not be + /// read; both are one Debug line, because both are a normal state of some store. An empty list means converged. /// - /// Budget. Chunks are taken newest first (the most-read days first), and no new chunk starts after - /// (the first always does). A converged store costs two catalog reads - /// and logs at Debug; a pass that did or skipped work logs one Information line with the chunks left. + /// This is the whole of the "is anything left" check, two catalog reads, and it is what the drain repeats + /// before every chunk: the gate (the hypertable's own setting is checked every time because compressing under the old + /// one would undo the work) and the candidates are read fresh, so a chunk the compression policy has meanwhile + /// compressed with the new grouping drops out of the list on its own. /// - public static Task RegroupPerfmonChunksAsync(NpgsqlConnection connection, ILogger? logger, CancellationToken cancellationToken = default) - => RegroupPerfmonChunksAsync(connection, logger, PerfmonRegroupReachDays, PerfmonRegroupPassBudget, cancellationToken); - - /// - internal static async Task RegroupPerfmonChunksAsync( - NpgsqlConnection connection, ILogger? logger, int reachDays, TimeSpan budget, CancellationToken cancellationToken) + internal static async Task?> ReadPerfmonRegroupCandidatesAsync( + NpgsqlConnection connection, ILogger? logger, int reachDays, CancellationToken cancellationToken) { if (connection is null) { throw new ArgumentNullException(nameof(connection)); } - var candidates = new List<(string Chunk, string? OldSegmentBy)>(); + var candidates = new List(); try { Version? version; @@ -12356,7 +12373,7 @@ internal static async Task RegroupPerfmonChunksAsync( { if (!await reader.ReadAsync(cancellationToken)) { - return 0; + return null; } version = ParseTimescaleVersion(reader.IsDBNull(0) ? null : reader.GetString(0)); @@ -12367,8 +12384,8 @@ internal static async Task RegroupPerfmonChunksAsync( var blocked = PerfmonRegroupBlockedReason(version, hasView, current); if (blocked is not null) { - logger?.LogDebug("TimescaleDB: perfmon_stats chunks are not re-grouped this pass: {Reason} (#5574)", blocked); - return 0; + logger?.LogDebug("TimescaleDB: perfmon_stats chunks are not re-grouped now: {Reason} (#5574)", blocked); + return null; } using var find = new NpgsqlCommand(PerfmonRegroupCandidatesSql, connection) { CommandTimeout = JobCatalogReadTimeoutSeconds }; @@ -12377,84 +12394,149 @@ internal static async Task RegroupPerfmonChunksAsync( await using var chunks = await find.ExecuteReaderAsync(cancellationToken); while (await chunks.ReadAsync(cancellationToken)) { - candidates.Add((chunks.GetString(0), chunks.IsDBNull(1) ? null : chunks.GetString(1))); + candidates.Add(new PerfmonRegroupCandidate(chunks.GetString(0), chunks.IsDBNull(1) ? null : chunks.GetString(1))); } } catch (Exception ex) when (ex is not OperationCanceledException) { - logger?.LogDebug("TimescaleDB: could not read perfmon_stats's chunk compression settings, so no chunk is re-grouped this pass (#5574): {Message}", ex.Message); - return 0; + logger?.LogDebug("TimescaleDB: could not read perfmon_stats's chunk compression settings, so no chunk is re-grouped now (#5574): {Message}", ex.Message); + return null; } - if (candidates.Count == 0) + return candidates; + } + + /// + /// Re-groups ONE perfmon_stats chunk that was compressed by server_id alone, so a one-counter trend read over it + /// skips every other counter's batches the way it already does on a chunk compressed after the settings change + /// (#5574). + /// + /// Why it exists. The settings change () reaches only chunks compressed + /// after it ( explains why), and collection_log can let its old chunks + /// age out. perfmon_stats cannot: its trend read reaches 30 days, and chunks compress after a day, so a store would + /// read old-shape chunks for the better part of a month. The drain () calls this for + /// the chunks inside ; older ones are never read by that query and go with + /// retention. + /// + /// Two transactions, because of when the lock escalates. decompress_chunk holds only an + /// EXCLUSIVE lock on the chunk, which lets reads go on, until the very end, where it takes ACCESS EXCLUSIVE to drop the + /// old compressed chunk (TimescaleDB 2.30.1, tsl/src/compression/api.c, decompress_chunk_impl); + /// compress_chunk holds EXCLUSIVE throughout. A lock is held to the end of its transaction, so + /// decompress and compress in ONE transaction (the first version of this) kept every read of the chunk waiting for the + /// whole compress half: 54 s of a 113 s re-group on a 13.1 M-row chunk. Two transactions put the ACCESS EXCLUSIVE at + /// the end of the first, so a read waits at most the a busy lock is given, and + /// measured 0 waits and a slowest read of 2 s over a 94 s re-group (reads slow down from the disk work, not from + /// a lock). compress_chunk(..., recompress => true) does not help: with changed settings it runs the same two + /// halves inside one statement and measured a 34 s wait of 85 s. + /// + /// A crash between the two leaves an uncompressed chunk, not a broken one. The compression policy compresses + /// every uncompressed chunk older than with the hypertable's current grouping, so the + /// chunk comes back compressed with the NEW grouping at the policy's next run. The compress half is retried + /// times first, and passes if_not_compressed so a policy run that got + /// there first is not an error. Between the two calls the chunk's rows are counted (a plain heap scan, for the log + /// line). Needs room for the whole chunk uncompressed plus its indexes, and writes it to the WAL, for the length of one + /// chunk. + /// + /// Never throws, except for cancellation. + /// + internal static async Task RegroupPerfmonChunkAsync( + NpgsqlConnection connection, ILogger? logger, PerfmonRegroupCandidate candidate, CancellationToken cancellationToken) + { + if (connection is null) { - logger?.LogDebug("TimescaleDB: no perfmon_stats chunk inside the {Days}-day reach has the old grouping (#5574)", reachDays); - return 0; + throw new ArgumentNullException(nameof(connection)); } - var done = 0; - var tried = 0; - var failuresInARow = 0; - var pass = Stopwatch.StartNew(); - foreach (var (chunk, oldSegmentBy) in candidates) - { - if (tried > 0 && pass.Elapsed >= budget) + var chunk = candidate.Chunk; + var clock = Stopwatch.StartNew(); + var decompressed = await TryRunBoundedDdlAsync( + connection, + async transaction => { - break; - } + using var decompress = new NpgsqlCommand("SELECT decompress_chunk($1::regclass)", connection, transaction) { CommandTimeout = SetupTimeoutSeconds }; + decompress.Parameters.AddWithValue(chunk); + await decompress.ExecuteNonQueryAsync(cancellationToken); + }, + logger, $"re-grouping perfmon_stats chunk {chunk} (decompress)", cancellationToken); - tried++; - long rows = 0; - var clock = Stopwatch.StartNew(); - var outcome = await TryRunBoundedDdlAsync( - connection, - async transaction => - { - using (var decompress = new NpgsqlCommand("SELECT decompress_chunk($1::regclass)", connection, transaction) { CommandTimeout = SetupTimeoutSeconds }) - { - decompress.Parameters.AddWithValue(chunk); - await decompress.ExecuteNonQueryAsync(cancellationToken); - } + if (decompressed != BoundedDdlOutcome.Applied) + { + return new PerfmonRegroupChunkOutcome( + decompressed == BoundedDdlOutcome.LockBusy ? PerfmonRegroupChunkResult.LockBusy : PerfmonRegroupChunkResult.Failed, + 0, clock.Elapsed); + } - /* The chunk's name came out of the catalog already quoted by format('%I.%I'), so it is safe to splice. */ - using (var count = new NpgsqlCommand($"SELECT count(*) FROM {chunk}", connection, transaction) { CommandTimeout = SetupTimeoutSeconds }) - { - rows = Convert.ToInt64(await count.ExecuteScalarAsync(cancellationToken), CultureInfo.InvariantCulture); - } + long rows = -1; + try + { + /* The chunk's name came out of the catalog already quoted by format('%I.%I'), so it is safe to splice. */ + using var count = new NpgsqlCommand($"SELECT count(*) FROM {chunk}", connection) { CommandTimeout = SetupTimeoutSeconds }; + rows = Convert.ToInt64(await count.ExecuteScalarAsync(cancellationToken), CultureInfo.InvariantCulture); + } + catch (Exception ex) when (ex is not OperationCanceledException) + { + logger?.LogDebug("TimescaleDB: could not count the rows of perfmon_stats chunk {Chunk} before compressing it again: {Message}", chunk, ex.Message); + } + + if (await CompressRegroupedChunkAsync(connection, logger, chunk, PerfmonRegroupCompressAttempts, PerfmonRegroupCompressRetryDelay, cancellationToken)) + { + logger?.LogInformation( + "TimescaleDB: re-grouped perfmon_stats chunk {Chunk} ({Rows} rows) from '{Old}' to '{New}' in {ElapsedMs} ms (#5574)", + chunk, rows, candidate.OldSegmentBy ?? "(none)", PerfmonStatsChunkSegmentBy, clock.ElapsedMilliseconds); + return new PerfmonRegroupChunkOutcome(PerfmonRegroupChunkResult.Regrouped, rows, clock.Elapsed); + } - using (var compress = new NpgsqlCommand("SELECT compress_chunk($1::regclass)", connection, transaction) { CommandTimeout = SetupTimeoutSeconds }) + return new PerfmonRegroupChunkOutcome(PerfmonRegroupChunkResult.LeftUncompressed, rows, clock.Elapsed); + } + + /// + /// The compress half of a chunk's re-group (#5574): the chunk was decompressed in a transaction that has committed, + /// so it is uncompressed now and a busy lock is worth tries, + /// apart, each behind the 3 s lock timeout. Returns whether the chunk is compressed again. When every try failed the + /// chunk stays uncompressed, with one Warning, and the compression policy compresses it with the hypertable's grouping + /// at its next run. if_not_compressed makes a policy run that got there first a success, not an error. + /// A cancellation (the service stopping) leaves the chunk the same way, says so at Information, and propagates. + /// + internal static async Task CompressRegroupedChunkAsync( + NpgsqlConnection connection, ILogger? logger, string chunk, int attempts, TimeSpan retryDelay, CancellationToken cancellationToken) + { + try + { + for (var attempt = 1; attempt <= attempts; attempt++) + { + var compressed = await TryRunBoundedDdlAsync( + connection, + async transaction => { + using var compress = new NpgsqlCommand("SELECT compress_chunk($1::regclass, if_not_compressed => true)", connection, transaction) { CommandTimeout = SetupTimeoutSeconds }; compress.Parameters.AddWithValue(chunk); await compress.ExecuteNonQueryAsync(cancellationToken); - } - }, - logger, $"re-grouping perfmon_stats chunk {chunk}", cancellationToken); + }, + logger, $"re-grouping perfmon_stats chunk {chunk} (compress)", cancellationToken); - if (outcome == BoundedDdlOutcome.Applied) - { - done++; - failuresInARow = 0; - logger?.LogInformation( - "TimescaleDB: re-grouped perfmon_stats chunk {Chunk} ({Rows} rows) from '{Old}' to '{New}' in {ElapsedMs} ms (#5574)", - chunk, rows, oldSegmentBy ?? "(none)", PerfmonStatsChunkSegmentBy, clock.ElapsedMilliseconds); - } - else if (outcome == BoundedDdlOutcome.Failed && ++failuresInARow >= PerfmonRegroupFailureLimit) - { - logger?.LogWarning( - "TimescaleDB: {Failures} perfmon_stats chunks in a row could not be re-grouped, so this pass stops; the next hourly pass tries again (#5574)", - failuresInARow); - break; - } - else if (outcome == BoundedDdlOutcome.LockBusy) - { - failuresInARow = 0; + if (compressed == BoundedDdlOutcome.Applied) + { + return true; + } + + if (attempt < attempts) + { + await Task.Delay(retryDelay, cancellationToken); + } } } + catch (OperationCanceledException) + { + logger?.LogInformation( + "TimescaleDB: the service is stopping with perfmon_stats chunk {Chunk} decompressed; the compression policy compresses it again with '{New}' at its next run (#5574)", + chunk, PerfmonStatsChunkSegmentBy); + throw; + } - logger?.LogInformation( - "TimescaleDB: perfmon_stats re-group: {Done} chunk(s) re-grouped to '{New}' this pass in {ElapsedMs} ms; {Left} chunk(s) inside the {Days}-day reach still have the old grouping and are taken, newest first, on the next hourly passes (#5574)", - done, PerfmonStatsChunkSegmentBy, pass.ElapsedMilliseconds, candidates.Count - done, reachDays); - return done; + logger?.LogWarning( + "TimescaleDB: perfmon_stats chunk {Chunk} was decompressed for re-grouping but could not be compressed again after {Attempts} tries, so it stays uncompressed until the compression policy compresses it with '{New}' at its next run; reads of it use the heap and its indexes meanwhile (#5574)", + chunk, attempts, PerfmonStatsChunkSegmentBy); + return false; } /* ---------------- compression-job self-heal (#1581) ---------------- */ From 9b384f783af8261e80f6acf112e5ccf99e16715b Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Thu, 8 Oct 2026 14:22:51 -0400 Subject: [PATCH 3/7] perfmon re-group: live tests for the crash between halves, the pause, a busy lock, repeated failure, the compress retry, the plan shape, a concurrent reader and a service stop (#5574) --- .../Darling.Tests/PerfmonRegroupLiveTests.cs | 630 +++++++++++++++++- 1 file changed, 627 insertions(+), 3 deletions(-) diff --git a/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs b/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs index 91f85f09e2..64e2597696 100644 --- a/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs +++ b/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs @@ -56,7 +56,7 @@ public async Task AnUpgradedStore_IsReGroupedNewestFirst_KeepsEveryRow_LeavesOut /* The hypertable still has the old grouping: the gate keeps the drain from writing the old grouping again. */ var gated = new CapturingTestLogger(); - Assert.Equal(0, await NewDrain(scratch.ConnectionString, gated, TimeSpan.Zero, new List()).RunAsync(ct)); + Assert.Equal(0, await RunBoundedAsync(NewDrain(scratch.ConnectionString, gated, TimeSpan.Zero, new List()), 60, ct)); Assert.DoesNotContain(gated.Lines, line => line.Contains("re-grouped perfmon_stats chunk", StringComparison.Ordinal)); await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); @@ -65,7 +65,7 @@ public async Task AnUpgradedStore_IsReGroupedNewestFirst_KeepsEveryRow_LeavesOut var logger = new CapturingTestLogger(); var pauses = new List(); - Assert.Equal(5, await NewDrain(scratch.ConnectionString, logger, TimeSpan.FromSeconds(90), pauses).RunAsync(ct)); + Assert.Equal(5, await RunBoundedAsync(NewDrain(scratch.ConnectionString, logger, TimeSpan.FromSeconds(90), pauses), 120, ct)); var after = await ReadChunksAsync(connection, ct); Assert.All(after.Where(chunk => inReachNewestFirst.Contains(chunk.Name)), chunk => Assert.Equal(WantedChunkSegmentBy, chunk.SegmentBy)); @@ -80,11 +80,512 @@ public async Task AnUpgradedStore_IsReGroupedNewestFirst_KeepsEveryRow_LeavesOut Assert.All(pauses, pause => Assert.Equal(TimeSpan.FromSeconds(90), pause)); var second = new CapturingTestLogger(); - Assert.Equal(0, await NewDrain(scratch.ConnectionString, second, TimeSpan.Zero, new List()).RunAsync(ct)); + Assert.Equal(0, await RunBoundedAsync(NewDrain(scratch.ConnectionString, second, TimeSpan.Zero, new List()), 60, ct)); Assert.DoesNotContain(second.Lines, line => line.StartsWith("Information:", StringComparison.Ordinal)); Assert.Equal(after, await ReadChunksAsync(connection, ct)); } + /* ---------------- round 2b: the rest of the behaviours, each with its own store ---------------- */ + + /// + /// A fresh store gets the new grouping on its first compressed chunk (#5574): the usual order (migrations first, the + /// extension after), converted and given its policy by the product's own two steps, then days of samples, then the + /// policy's run. No chunk is ever compressed by server_id alone, so the drain has nothing to do. + /// + [Fact] + public async Task AFreshStore_CompressesItsFirstChunksWithTheNewGrouping_AndTheDrainHasNothingToDo() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await PgMigrations.MigrateAsync(connection, ct); + Assert.SkipUnless(await LiveTimescaleProbe.TryEnableAsync(scratch.ConnectionString, ct), "TimescaleDB is not available on this cluster."); + await ExecAsync(connection, "SELECT _timescaledb_functions.stop_background_workers()", ct); + await RequirePerChunkSettingsAsync(connection, ct); + + await TimescaleSupport.ConvertToHypertablesAsync(connection, null, ct); + await TimescaleSupport.ApplyCompressionPolicyAsync(connection, null, ct); + Assert.Equal("server_id, counter_name", await HypertableSegmentByAsync(connection, ct)); + + var today = DateTime.SpecifyKind(DateTime.UtcNow.Date, DateTimeKind.Unspecified); + foreach (var daysBack in new[] { 2, 3, 4 }) + { + await SeedDayAsync(connection, today.AddDays(-daysBack), daysBack, ct); + } + + var fingerprint = await FingerprintAsync(connection, ct); + await RunPerfmonPolicyAsync(connection, ct); + + var chunks = await ReadChunksAsync(connection, ct); + Assert.Equal(3, chunks.Count); + Assert.All(chunks, chunk => + { + Assert.True(chunk.IsCompressed, chunk.Name + " was not compressed by the policy"); + Assert.Equal(WantedChunkSegmentBy, chunk.SegmentBy); + }); + Assert.Equal(fingerprint, await FingerprintAsync(connection, ct)); + + var logger = new CapturingTestLogger(); + Assert.Equal(0, await RunBoundedAsync(NewDrain(scratch.ConnectionString, logger, TimeSpan.Zero, new List()), 60, ct)); + Assert.DoesNotContain(logger.Lines, line => line.StartsWith("Information:", StringComparison.Ordinal)); + } + + /// + /// A crash between the two halves (the decompress committed, the compress never ran) leaves a chunk that is + /// uncompressed, not broken (#5574). The drain does not see it (it is not compressed, so it is not a candidate) and + /// goes on with the others; the compression policy then compresses it with the hypertable's NEW grouping, with every + /// row intact. The settings change itself is the product's: the policy step run on the old store. + /// + [Fact] + public async Task ACrashBetweenTheTwoHalves_LeavesAnUncompressedChunk_ThatThePolicyCompressesWithTheNewGrouping() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await TimescaleSupport.ConvertToHypertablesAsync(connection, null, ct); + await TimescaleSupport.ApplyCompressionPolicyAsync(connection, null, ct); + Assert.Equal("server_id, counter_name", await HypertableSegmentByAsync(connection, ct)); + var fingerprint = await FingerprintAsync(connection, ct); + + var crashed = ChunkOfDay(await ReadChunksAsync(connection, ct), 3); + await ExecAsync(connection, $"SELECT decompress_chunk('{crashed.Name}')", ct); + + /* The drain goes on with the four others and leaves the crashed one alone. */ + var logger = new CapturingTestLogger(); + Assert.Equal(4, await RunBoundedAsync(NewDrain(scratch.ConnectionString, logger, TimeSpan.Zero, new List()), 120, ct)); + Assert.Equal(0, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); + var afterDrain = await ReadChunksAsync(connection, ct); + Assert.False(afterDrain.Single(chunk => chunk.Name == crashed.Name).IsCompressed); + Assert.All(afterDrain.Where(chunk => chunk.Name != crashed.Name && chunk.Start > DateTime.UtcNow.AddDays(-30)), chunk => Assert.Equal(WantedChunkSegmentBy, chunk.SegmentBy)); + + /* The policy's next run compresses it with the hypertable's grouping. */ + await RunPerfmonPolicyAsync(connection, ct); + var recompressed = (await ReadChunksAsync(connection, ct)).Single(chunk => chunk.Name == crashed.Name); + Assert.True(recompressed.IsCompressed); + Assert.Equal(WantedChunkSegmentBy, recompressed.SegmentBy); + Assert.Equal(fingerprint, await FingerprintAsync(connection, ct)); + } + + /// + /// The compression policy and the drain compressing the same chunk must not fail the drain (#5574): the policy got there + /// first, so the compress half finds the chunk already compressed (if_not_compressed) and reports done, with + /// no warning. + /// + [Fact] + public async Task WhenThePolicyCompressedTheChunkFirst_TheCompressHalfIsDone_NotAnError() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await TimescaleSupport.ConvertToHypertablesAsync(connection, null, ct); + await TimescaleSupport.ApplyCompressionPolicyAsync(connection, null, ct); + + var chunk = ChunkOfDay(await ReadChunksAsync(connection, ct), 3); + await ExecAsync(connection, $"SELECT decompress_chunk('{chunk.Name}')", ct); + await RunPerfmonPolicyAsync(connection, ct); + Assert.True((await ReadChunksAsync(connection, ct)).Single(c => c.Name == chunk.Name).IsCompressed); + + var logger = new CapturingTestLogger(); + Assert.True(await TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.Zero, ct)); + Assert.Equal(0, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); + var after = (await ReadChunksAsync(connection, ct)).Single(c => c.Name == chunk.Name); + Assert.True(after.IsCompressed); + Assert.Equal(WantedChunkSegmentBy, after.SegmentBy); + } + + /// + /// The pause after a chunk is the chunk's own time when that is longer than the floor (#5574): with no floor, the + /// pause the drain asks for after each chunk equals the milliseconds the chunk's own log line says it took. + /// + [Fact] + public async Task ThePauseAfterAChunk_IsAtLeastTheTimeThatChunkTook() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + + var logger = new CapturingTestLogger(); + var pauses = new List(); + Assert.Equal(5, await RunBoundedAsync(NewDrain(scratch.ConnectionString, logger, TimeSpan.Zero, pauses), 120, ct)); + + var tookMs = logger.Lines + .Select(line => Regex.Match(line, @"re-grouped perfmon_stats chunk \S+ \(\d+ rows\) from .* in (\d+) ms")) + .Where(match => match.Success).Select(match => long.Parse(match.Groups[1].Value, System.Globalization.CultureInfo.InvariantCulture)).ToList(); + Assert.Equal(5, tookMs.Count); + Assert.Equal(4, pauses.Count); + for (var i = 0; i < pauses.Count; i++) + { + Assert.True(pauses[i].TotalMilliseconds >= tookMs[i] && pauses[i].TotalMilliseconds < tookMs[i] + 250, + $"pause {i} was {pauses[i].TotalMilliseconds} ms, but chunk {i} took {tookMs[i]} ms"); + Assert.True(pauses[i] > TimeSpan.Zero); + } + } + + /// + /// A chunk whose lock is held is skipped for the rest of the run (#5574): the newest chunk is held by another session, + /// the decompress gives up after the 3 s lock timeout, the other four are re-grouped, the held one is not tried a + /// second time, and a pause (the floor) follows the busy one like any other. + /// + [Fact] + public async Task ABusyChunk_IsSkippedForTheRun_AndTheOthersAreReGrouped() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + TimescaleSupport.BusyStreaks.Reset(); + + var held = ChunkOfDay(await ReadChunksAsync(connection, ct), 1); + var holder = await HoldLockAsync(scratch.ConnectionString, held.Name, ct); + var logger = new CapturingTestLogger(); + var pauses = new List(); + try + { + Assert.Equal(4, await RunBoundedAsync(NewDrain(scratch.ConnectionString, logger, TimeSpan.FromSeconds(90), pauses), 60, ct)); + } + finally + { + await ReleaseLockAsync(holder, ct); + } + + var after = await ReadChunksAsync(connection, ct); + Assert.Equal(OldChunkSegmentBy, after.Single(chunk => chunk.Name == held.Name).SegmentBy); + Assert.All(after.Where(chunk => chunk.Name != held.Name && chunk.Start > DateTime.UtcNow.AddDays(-30)), chunk => Assert.Equal(WantedChunkSegmentBy, chunk.SegmentBy)); + Assert.Single(logger.Lines, line => line.Contains("not changed this pass", StringComparison.Ordinal) && line.Contains(held.Name, StringComparison.Ordinal)); + Assert.Contains(logger.Lines, line => line.Contains("1 skipped", StringComparison.Ordinal)); + Assert.Equal(4, pauses.Count); + Assert.All(pauses, pause => Assert.Equal(TimeSpan.FromSeconds(90), pause)); + TimescaleSupport.BusyStreaks.Reset(); + } + + /// + /// Three chunks in a row that fail (an error that is not a busy lock) stop the run (#5574). The drain's connection is + /// read-only here, so every decompress fails the same way; the run ends after the third, with one Warning saying so, + /// and the other two chunks are never touched. + /// + [Fact] + public async Task ThreeFailuresInARow_StopTheRun() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + var before = await ReadChunksAsync(connection, ct); + + var logger = new CapturingTestLogger(); + var drain = new PerfmonRegroupDrain( + async token => + { + var readOnly = new NpgsqlConnection(scratch.ConnectionString); + await readOnly.OpenAsync(token); + await ExecAsync(readOnly, "SET default_transaction_read_only = on", token); + return readOnly; + }, + logger, 30, TimeSpan.Zero, (pause, token) => Task.CompletedTask); + + Assert.Equal(0, await RunBoundedAsync(drain, 60, ct)); + Assert.Equal(3, logger.Lines.Count(line => line.Contains("(decompress) could not be changed", StringComparison.Ordinal))); + Assert.Single(logger.Lines, line => line.Contains("3 perfmon_stats chunks in a row could not be re-grouped", StringComparison.Ordinal)); + Assert.Equal(before, await ReadChunksAsync(connection, ct)); + } + + /// + /// The compress half is retried (#5574): the chunk is already decompressed when it starts, so a lock another session + /// holds for a moment costs a try, not the chunk. The first try gives up after the lock timeout, the lock is then + /// released, and the second try compresses the chunk with the new grouping. + /// + [Fact] + public async Task TheCompressHalf_IsRetriedAfterABusyLock_AndSucceedsOnALaterTry() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + TimescaleSupport.BusyStreaks.Reset(); + + var chunk = ChunkOfDay(await ReadChunksAsync(connection, ct), 3); + await ExecAsync(connection, $"SELECT decompress_chunk('{chunk.Name}')", ct); + NpgsqlConnection? holder = await HoldLockAsync(scratch.ConnectionString, chunk.Name, ct); + var logger = new CapturingTestLogger(); + bool compressed; + try + { + var compress = TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.FromMilliseconds(200), ct); + await WaitForAsync(() => logger.Lines.Any(line => line.Contains("not changed this pass", StringComparison.Ordinal)), 15, ct); + await ReleaseLockAsync(holder, ct); + holder = null; + compressed = await compress; + } + finally + { + if (holder is not null) + { + await ReleaseLockAsync(holder, ct); + } + } + + Assert.True(compressed); + Assert.Equal(1, logger.Lines.Count(line => line.Contains("not changed this pass", StringComparison.Ordinal))); + Assert.Equal(0, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); + var after = (await ReadChunksAsync(connection, ct)).Single(c => c.Name == chunk.Name); + Assert.True(after.IsCompressed); + Assert.Equal(WantedChunkSegmentBy, after.SegmentBy); + TimescaleSupport.BusyStreaks.Reset(); + } + + /// + /// When every try of the compress half is busy (#5574), the chunk is left uncompressed with ONE Warning, after exactly + /// the attempts it is given, and the compression policy compresses it with the new grouping once the lock is gone. + /// + [Fact] + public async Task WhenEveryCompressTryIsBusy_TheChunkIsLeftToThePolicy_WithOneWarning() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await TimescaleSupport.ConvertToHypertablesAsync(connection, null, ct); + await TimescaleSupport.ApplyCompressionPolicyAsync(connection, null, ct); + TimescaleSupport.BusyStreaks.Reset(); + + var chunk = ChunkOfDay(await ReadChunksAsync(connection, ct), 3); + await ExecAsync(connection, $"SELECT decompress_chunk('{chunk.Name}')", ct); + var holder = await HoldLockAsync(scratch.ConnectionString, chunk.Name, ct); + var logger = new CapturingTestLogger(); + try + { + Assert.False(await TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.Zero, ct)); + } + finally + { + await ReleaseLockAsync(holder, ct); + } + + Assert.Equal(3, logger.Lines.Count(line => line.Contains("not changed this pass", StringComparison.Ordinal))); + Assert.Single(logger.Lines, line => line.StartsWith("Warning:", StringComparison.Ordinal) && line.Contains("stays uncompressed", StringComparison.Ordinal)); + Assert.False((await ReadChunksAsync(connection, ct)).Single(c => c.Name == chunk.Name).IsCompressed); + + await RunPerfmonPolicyAsync(connection, ct); + var after = (await ReadChunksAsync(connection, ct)).Single(c => c.Name == chunk.Name); + Assert.True(after.IsCompressed); + Assert.Equal(WantedChunkSegmentBy, after.SegmentBy); + TimescaleSupport.BusyStreaks.Reset(); + } + + /// + /// The plan shape the whole change is for (#5574): a one-counter read over a chunk filters the COMPRESSED chunk on the + /// segment columns, server_id and counter_name, once it is re-grouped. Over the same chunk before the + /// re-group only server_id is a segment column, so the counter is tested after the batches are decompressed. + /// The filters are the trend read's own (equality on both, a time window). + /// + [Fact] + public async Task AOneCounterRead_FiltersTheCompressedChunkOnBothSegmentColumns_OnceItIsReGrouped() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + var day = ChunkOfDay(await ReadChunksAsync(connection, ct), 3); + + var before = await CompressedScanFilterAsync(connection, day.Start, ct); + Assert.Contains("server_id", before, StringComparison.Ordinal); + Assert.DoesNotContain("counter_name", before, StringComparison.Ordinal); + + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + Assert.Equal(5, await RunBoundedAsync(NewDrain(scratch.ConnectionString, new CapturingTestLogger(), TimeSpan.Zero, new List()), 120, ct)); + + var after = await CompressedScanFilterAsync(connection, day.Start, ct); + Assert.Contains("server_id", after, StringComparison.Ordinal); + Assert.Contains("counter_name", after, StringComparison.Ordinal); + } + + /// + /// A reader beside the re-group of a chunk of about 1.5 M rows never waits more than a few seconds (#5574): the + /// decompress holds only a lock that lets reads go on, and the ACCESS EXCLUSIVE it takes at its end is released by + /// its own commit, before the compress half starts. The same re-group in ONE transaction made the reader wait for + /// the whole compress half. + /// + [Fact] + public async Task AReaderBesideTheReGroupOfALargeChunk_NeverWaitsMoreThanAFewSeconds() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await PgMigrations.MigrateAsync(connection, ct); + Assert.SkipUnless(await LiveTimescaleProbe.TryEnableAsync(scratch.ConnectionString, ct), "TimescaleDB is not available on this cluster."); + await ExecAsync(connection, "SELECT _timescaledb_functions.stop_background_workers()", ct); + await RequirePerChunkSettingsAsync(connection, ct); + await ExecAsync(connection, TimescaleSupport.CreateHypertableSql(TimescaleSupport.PerfmonStatsTable, "collection_time"), ct); + await ExecAsync(connection, "ALTER TABLE perfmon_stats SET (timescaledb.compress, timescaledb.compress_segmentby = 'server_id')", ct); + + /* 4 servers x 130 counters x 2 instances = 1040 series, a sample a minute for a day: 1,497,600 rows. */ + var day = DateTime.SpecifyKind(DateTime.UtcNow.Date.AddDays(-3), DateTimeKind.Unspecified); + using (var seed = new NpgsqlCommand( + @"INSERT INTO perfmon_stats (collection_id, collection_time, server_id, server_name, object_name, counter_name, instance_name, cntr_value, delta_cntr_value, sample_interval_seconds, cntr_type) + SELECT $1 - row_number() OVER (), g.t, s.id, 'REGROUP-SRV', 'SQLServer:Test', 'Counter ' || c.n, 'inst' || i.i, + (extract(epoch FROM g.t)::bigint / 60 + s.id + c.n * 7 + i.i) % 100000, (extract(epoch FROM g.t)::bigint / 60 + c.n) % 50, 60, 65792 + FROM generate_series($2::timestamp, $2::timestamp + INTERVAL '23 hours 59 minutes', INTERVAL '1 minute') AS g(t) + CROSS JOIN generate_series(1, 4) AS s(id) + CROSS JOIN generate_series(1, 130) AS c(n) + CROSS JOIN generate_series(0, 1) AS i(i)", connection) { CommandTimeout = 300 }) + { + seed.Parameters.AddWithValue(IdBase); + seed.Parameters.AddWithValue(day); + await seed.ExecuteNonQueryAsync(ct); + } + + var chunkName = await ScalarAsync(connection, + "SELECT format('%I.%I', chunk_schema, chunk_name) FROM timescaledb_information.chunks WHERE hypertable_name = 'perfmon_stats' AND NOT is_compressed AND range_end <= now()", ct); + await ExecAsync(connection, $"SELECT compress_chunk('{chunkName}')", ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + + var stop = false; + var slowest = TimeSpan.Zero; + var reads = 0; + var reader = Task.Run(async () => + { + using var readConnection = new NpgsqlConnection(scratch.ConnectionString); + await readConnection.OpenAsync(ct); + while (!Volatile.Read(ref stop)) + { + var clock = System.Diagnostics.Stopwatch.StartNew(); + using var read = new NpgsqlCommand( + "SELECT count(*), max(cntr_value) FROM v_perfmon_stats WHERE server_id = 2 AND counter_name = 'Counter 7' AND collection_time >= now() - INTERVAL '30 days'", readConnection) + { CommandTimeout = 120 }; + await read.ExecuteScalarAsync(ct); + clock.Stop(); + if (clock.Elapsed > slowest) + { + slowest = clock.Elapsed; + } + + reads++; + await Task.Delay(100, ct); + } + }, ct); + + var logger = new CapturingTestLogger(); + var outcome = await TimescaleSupport.RegroupPerfmonChunkAsync( + connection, logger, new TimescaleSupport.PerfmonRegroupCandidate(chunkName, OldChunkSegmentBy), ct); + Volatile.Write(ref stop, true); + await reader; + + Assert.Equal(TimescaleSupport.PerfmonRegroupChunkResult.Regrouped, outcome.Result); + Assert.Equal(1_497_600, outcome.Rows); + Assert.True(reads >= 3, $"the reader only got {reads} reads in during a {outcome.Elapsed.TotalSeconds:0.0} s re-group"); + Assert.True(slowest < TimeSpan.FromSeconds(5), $"a read waited {slowest.TotalSeconds:0.0} s during a {outcome.Elapsed.TotalSeconds:0.0} s re-group"); + } + + /// + /// A service stop during the drain's pause ends the run at once (#5574): the pause is waited on with the stopping token, + /// so the run's task completes within a moment, without a warning, with the chunks it had not reached untouched. + /// + [Fact] + public async Task AServiceStopDuringThePause_EndsTheRunPromptly_WithoutAWarning() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + + var logger = new CapturingTestLogger(); + var pauseRequested = 0; + var drain = new PerfmonRegroupDrain( + async token => + { + var drainConnection = new NpgsqlConnection(scratch.ConnectionString); + await drainConnection.OpenAsync(token); + return drainConnection; + }, + logger, 30, TimeSpan.FromSeconds(90), + async (pause, token) => + { + Interlocked.Increment(ref pauseRequested); + await Task.Delay(Timeout.Infinite, token); + }); + + using var stopping = new CancellationTokenSource(); + Assert.True(drain.StartIfIdle(stopping.Token)); + await WaitForAsync(() => Volatile.Read(ref pauseRequested) > 0, 60, ct); + stopping.Cancel(); + + var finished = await Task.WhenAny(drain.Completion!, Task.Delay(TimeSpan.FromSeconds(5), ct)); + Assert.Same(drain.Completion, finished); + Assert.False(drain.Completion!.IsFaulted); + Assert.Equal(0, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); + var after = await ReadChunksAsync(connection, ct); + Assert.Equal(1, after.Count(chunk => chunk.SegmentBy == WantedChunkSegmentBy)); + Assert.Equal(5, after.Count(chunk => chunk.SegmentBy == OldChunkSegmentBy)); + } + + /// + /// A service stop during the compress half (#5574): the wait for a held lock is cancelled at once (not after the 3 s lock + /// timeout), the cancellation propagates, and the log says the chunk is left for the compression policy. + /// + [Fact] + public async Task AServiceStopDuringTheCompressHalf_CancelsTheWait_AndSaysTheChunkIsLeftToThePolicy() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + TimescaleSupport.BusyStreaks.Reset(); + + var chunk = ChunkOfDay(await ReadChunksAsync(connection, ct), 3); + await ExecAsync(connection, $"SELECT decompress_chunk('{chunk.Name}')", ct); + var holder = await HoldLockAsync(scratch.ConnectionString, chunk.Name, ct); + var logger = new CapturingTestLogger(); + var clock = System.Diagnostics.Stopwatch.StartNew(); + try + { + using var stopping = CancellationTokenSource.CreateLinkedTokenSource(ct); + stopping.CancelAfter(TimeSpan.FromMilliseconds(500)); + await Assert.ThrowsAnyAsync( + () => TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.FromSeconds(5), stopping.Token)); + } + finally + { + await ReleaseLockAsync(holder, ct); + } + + Assert.True(clock.Elapsed < TimeSpan.FromSeconds(2.5), $"the stop took {clock.Elapsed.TotalSeconds:0.0} s to end the wait"); + Assert.Single(logger.Lines, line => line.Contains("the service is stopping with perfmon_stats chunk", StringComparison.Ordinal)); + TimescaleSupport.BusyStreaks.Reset(); + } + /* ---------------- fixture ---------------- */ private static string RequireLivePostgres() @@ -206,4 +707,127 @@ private static async Task ScalarAsync(NpgsqlConnection connection, string var value = await command.ExecuteScalarAsync(ct); return (T)Convert.ChangeType(value!, typeof(T), System.Globalization.CultureInfo.InvariantCulture); } + + /* ---------------- round 2b helpers ---------------- */ + + /// Runs the drain to the end, or fails the test when it has not ended in (a drain + /// that loops on a chunk it should have skipped would otherwise hang the suite). + private static async Task RunBoundedAsync(PerfmonRegroupDrain drain, int seconds, CancellationToken ct) + { + using var limit = CancellationTokenSource.CreateLinkedTokenSource(ct); + limit.CancelAfter(TimeSpan.FromSeconds(seconds)); + try + { + return await drain.RunAsync(limit.Token); + } + catch (OperationCanceledException) when (!ct.IsCancellationRequested) + { + Assert.Fail($"the drain had not finished {seconds} s into the run"); + return -1; + } + } + + private static async Task WaitForAsync(Func condition, int seconds, CancellationToken ct) + { + var deadline = DateTime.UtcNow.AddSeconds(seconds); + while (!condition()) + { + Assert.True(DateTime.UtcNow < deadline, $"the condition did not hold within {seconds} s"); + await Task.Delay(50, ct); + } + } + + private static ChunkRow ChunkOfDay(List chunks, int daysBack) => + chunks.Single(chunk => chunk.Start.Date == DateTime.UtcNow.Date.AddDays(-daysBack)); + + /// Another session holds ROW EXCLUSIVE on the chunk inside an open transaction, which conflicts with the + /// EXCLUSIVE lock both halves of the re-group ask for. + private static async Task HoldLockAsync(string connectionString, string chunk, CancellationToken ct) + { + var holder = new NpgsqlConnection(connectionString); + await holder.OpenAsync(ct); + await ExecAsync(holder, "BEGIN", ct); + await ExecAsync(holder, $"LOCK TABLE {chunk} IN ROW EXCLUSIVE MODE", ct); + return holder; + } + + private static async Task ReleaseLockAsync(NpgsqlConnection holder, CancellationToken ct) + { + await ExecAsync(holder, "ROLLBACK", ct); + await holder.DisposeAsync(); + } + + private static async Task RequirePerChunkSettingsAsync(NpgsqlConnection connection, CancellationToken ct) => + Assert.SkipUnless( + await ScalarAsync(connection, "SELECT to_regclass('timescaledb_information.chunk_compression_settings') IS NOT NULL", ct), + "this TimescaleDB has no timescaledb_information.chunk_compression_settings (before 2.14.1)."); + + /// perfmon_stats's own segmentby columns in order, joined with ", " (how the product's gate reads them). + private static Task HypertableSegmentByAsync(NpgsqlConnection connection, CancellationToken ct) => + ScalarAsync(connection, + @"SELECT string_agg(attname, ', ' ORDER BY segmentby_column_index) FROM timescaledb_information.compression_settings + WHERE hypertable_schema = 'collect' AND hypertable_name = 'perfmon_stats' AND segmentby_column_index IS NOT NULL", ct); + + /// One run of perfmon_stats's compression policy in this session, as the scheduler runs it: every chunk older + /// than the policy's compress-after is compressed with the settings the hypertable has at that moment. + private static async Task RunPerfmonPolicyAsync(NpgsqlConnection connection, CancellationToken ct) + { + var jobId = await ScalarAsync(connection, + @"SELECT job_id FROM timescaledb_information.jobs WHERE proc_name = 'policy_compression' + AND hypertable_schema = 'collect' AND hypertable_name = 'perfmon_stats'", ct); + await ExecAsync(connection, $"CALL run_job({jobId})", ct); + } + + /// + /// The filter text of every scan of a COMPRESSED chunk's own relation (named compress_hyper_* or _hyper_N_M_chunk_compressed, by TimescaleDB release) in the plan of a + /// one-counter read over the chunk starting at : what the read can skip without + /// decompressing. The read has the trend read's filters (equality on server and counter, a time window). + /// + private static bool IsCompressedRelationName(string? name) => + name is not null && (name.StartsWith("compress_hyper", StringComparison.Ordinal) || name.EndsWith("_compressed", StringComparison.Ordinal)); + + private static async Task CompressedScanFilterAsync(NpgsqlConnection connection, DateTime dayStart, CancellationToken ct) + { + var from = dayStart.ToString("yyyy-MM-dd HH:mm:ss", System.Globalization.CultureInfo.InvariantCulture); + var to = dayStart.AddDays(1).ToString("yyyy-MM-dd HH:mm:ss", System.Globalization.CultureInfo.InvariantCulture); + var json = await ScalarAsync(connection, + "EXPLAIN (FORMAT JSON, COSTS OFF) SELECT collection_time, cntr_value FROM v_perfmon_stats " + + $"WHERE server_id = 1 AND counter_name = 'Counter 2' AND collection_time >= '{from}' AND collection_time < '{to}'", ct); + + var filters = new List(); + void Walk(System.Text.Json.JsonElement node) + { + if (node.ValueKind == System.Text.Json.JsonValueKind.Object) + { + if (node.TryGetProperty("Relation Name", out var relation) + && IsCompressedRelationName(relation.GetString())) + { + foreach (var key in new[] { "Filter", "Index Cond", "Recheck Cond" }) + { + if (node.TryGetProperty(key, out var text)) + { + filters.Add(text.GetString() ?? string.Empty); + } + } + } + + foreach (var property in node.EnumerateObject()) + { + Walk(property.Value); + } + } + else if (node.ValueKind == System.Text.Json.JsonValueKind.Array) + { + foreach (var item in node.EnumerateArray()) + { + Walk(item); + } + } + } + + using var document = System.Text.Json.JsonDocument.Parse(json); + Walk(document.RootElement); + Assert.True(filters.Count > 0, "no compressed chunk scan in the plan: " + json); + return string.Join(" | ", filters); + } } From 8cec10e6d48a2765961db2f669d0a254fe33f2a6 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Thu, 8 Oct 2026 15:03:19 -0400 Subject: [PATCH 4/7] perfmon re-group tests: hold a chunk's lock through a disposable (live-cleanup ratchet), reader bound 2.5 s (#5574) --- .../Darling.Tests/PerfmonRegroupLiveTests.cs | 100 ++++++++---------- 1 file changed, 46 insertions(+), 54 deletions(-) diff --git a/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs b/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs index 64e2597696..2b4a75ecf5 100644 --- a/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs +++ b/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs @@ -251,17 +251,11 @@ public async Task ABusyChunk_IsSkippedForTheRun_AndTheOthersAreReGrouped() TimescaleSupport.BusyStreaks.Reset(); var held = ChunkOfDay(await ReadChunksAsync(connection, ct), 1); - var holder = await HoldLockAsync(scratch.ConnectionString, held.Name, ct); + await using var holder = await HoldLockAsync(scratch.ConnectionString, held.Name, ct); var logger = new CapturingTestLogger(); var pauses = new List(); - try - { - Assert.Equal(4, await RunBoundedAsync(NewDrain(scratch.ConnectionString, logger, TimeSpan.FromSeconds(90), pauses), 60, ct)); - } - finally - { - await ReleaseLockAsync(holder, ct); - } + Assert.Equal(4, await RunBoundedAsync(NewDrain(scratch.ConnectionString, logger, TimeSpan.FromSeconds(90), pauses), 60, ct)); + await holder.ReleaseAsync(ct); var after = await ReadChunksAsync(connection, ct); Assert.Equal(OldChunkSegmentBy, after.Single(chunk => chunk.Name == held.Name).SegmentBy); @@ -326,24 +320,12 @@ public async Task TheCompressHalf_IsRetriedAfterABusyLock_AndSucceedsOnALaterTry var chunk = ChunkOfDay(await ReadChunksAsync(connection, ct), 3); await ExecAsync(connection, $"SELECT decompress_chunk('{chunk.Name}')", ct); - NpgsqlConnection? holder = await HoldLockAsync(scratch.ConnectionString, chunk.Name, ct); + await using var holder = await HoldLockAsync(scratch.ConnectionString, chunk.Name, ct); var logger = new CapturingTestLogger(); - bool compressed; - try - { - var compress = TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.FromMilliseconds(200), ct); - await WaitForAsync(() => logger.Lines.Any(line => line.Contains("not changed this pass", StringComparison.Ordinal)), 15, ct); - await ReleaseLockAsync(holder, ct); - holder = null; - compressed = await compress; - } - finally - { - if (holder is not null) - { - await ReleaseLockAsync(holder, ct); - } - } + var compress = TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.FromMilliseconds(200), ct); + await WaitForAsync(() => logger.Lines.Any(line => line.Contains("not changed this pass", StringComparison.Ordinal)), 15, ct); + await holder.ReleaseAsync(ct); + var compressed = await compress; Assert.True(compressed); Assert.Equal(1, logger.Lines.Count(line => line.Contains("not changed this pass", StringComparison.Ordinal))); @@ -373,16 +355,10 @@ public async Task WhenEveryCompressTryIsBusy_TheChunkIsLeftToThePolicy_WithOneWa var chunk = ChunkOfDay(await ReadChunksAsync(connection, ct), 3); await ExecAsync(connection, $"SELECT decompress_chunk('{chunk.Name}')", ct); - var holder = await HoldLockAsync(scratch.ConnectionString, chunk.Name, ct); + await using var holder = await HoldLockAsync(scratch.ConnectionString, chunk.Name, ct); var logger = new CapturingTestLogger(); - try - { - Assert.False(await TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.Zero, ct)); - } - finally - { - await ReleaseLockAsync(holder, ct); - } + Assert.False(await TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.Zero, ct)); + await holder.ReleaseAsync(ct); Assert.Equal(3, logger.Lines.Count(line => line.Contains("not changed this pass", StringComparison.Ordinal))); Assert.Single(logger.Lines, line => line.StartsWith("Warning:", StringComparison.Ordinal) && line.Contains("stays uncompressed", StringComparison.Ordinal)); @@ -425,7 +401,7 @@ public async Task AOneCounterRead_FiltersTheCompressedChunkOnBothSegmentColumns_ } /// - /// A reader beside the re-group of a chunk of about 1.5 M rows never waits more than a few seconds (#5574): the + /// A reader beside the re-group of a chunk of about 1.5 M rows never waits more than a few seconds (#5574; the bound is 2.5 s, against 0.1 to 0.2 s measured with two transactions and 4.9 s of a 10.3 s re-group with one): the /// decompress holds only a lock that lets reads go on, and the ACCESS EXCLUSIVE it takes at its end is released by /// its own commit, before the compress half starts. The same re-group in ONE transaction made the reader wait for /// the whole compress half. @@ -500,7 +476,7 @@ CROSS JOIN generate_series(0, 1) AS i(i)", connection) { CommandTimeout = 300 }) Assert.Equal(TimescaleSupport.PerfmonRegroupChunkResult.Regrouped, outcome.Result); Assert.Equal(1_497_600, outcome.Rows); Assert.True(reads >= 3, $"the reader only got {reads} reads in during a {outcome.Elapsed.TotalSeconds:0.0} s re-group"); - Assert.True(slowest < TimeSpan.FromSeconds(5), $"a read waited {slowest.TotalSeconds:0.0} s during a {outcome.Elapsed.TotalSeconds:0.0} s re-group"); + Assert.True(slowest < TimeSpan.FromSeconds(2.5), $"a read waited {slowest.TotalSeconds:0.0} s during a {outcome.Elapsed.TotalSeconds:0.0} s re-group"); } /// @@ -566,20 +542,14 @@ public async Task AServiceStopDuringTheCompressHalf_CancelsTheWait_AndSaysTheChu var chunk = ChunkOfDay(await ReadChunksAsync(connection, ct), 3); await ExecAsync(connection, $"SELECT decompress_chunk('{chunk.Name}')", ct); - var holder = await HoldLockAsync(scratch.ConnectionString, chunk.Name, ct); + await using var holder = await HoldLockAsync(scratch.ConnectionString, chunk.Name, ct); var logger = new CapturingTestLogger(); var clock = System.Diagnostics.Stopwatch.StartNew(); - try - { - using var stopping = CancellationTokenSource.CreateLinkedTokenSource(ct); - stopping.CancelAfter(TimeSpan.FromMilliseconds(500)); - await Assert.ThrowsAnyAsync( - () => TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.FromSeconds(5), stopping.Token)); - } - finally - { - await ReleaseLockAsync(holder, ct); - } + using var stopping = CancellationTokenSource.CreateLinkedTokenSource(ct); + stopping.CancelAfter(TimeSpan.FromMilliseconds(500)); + await Assert.ThrowsAnyAsync( + () => TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.FromSeconds(5), stopping.Token)); + await holder.ReleaseAsync(ct); Assert.True(clock.Elapsed < TimeSpan.FromSeconds(2.5), $"the stop took {clock.Elapsed.TotalSeconds:0.0} s to end the wait"); Assert.Single(logger.Lines, line => line.Contains("the service is stopping with perfmon_stats chunk", StringComparison.Ordinal)); @@ -742,19 +712,41 @@ private static ChunkRow ChunkOfDay(List chunks, int daysBack) => /// Another session holds ROW EXCLUSIVE on the chunk inside an open transaction, which conflicts with the /// EXCLUSIVE lock both halves of the re-group ask for. - private static async Task HoldLockAsync(string connectionString, string chunk, CancellationToken ct) + private static async Task HoldLockAsync(string connectionString, string chunk, CancellationToken ct) { var holder = new NpgsqlConnection(connectionString); await holder.OpenAsync(ct); await ExecAsync(holder, "BEGIN", ct); await ExecAsync(holder, $"LOCK TABLE {chunk} IN ROW EXCLUSIVE MODE", ct); - return holder; + return new HeldLock(holder); } - private static async Task ReleaseLockAsync(NpgsqlConnection holder, CancellationToken ct) + /// The session that holds a chunk's lock; released by or, at the latest, when + /// the test's scope ends. + private sealed class HeldLock : IAsyncDisposable { - await ExecAsync(holder, "ROLLBACK", ct); - await holder.DisposeAsync(); + private NpgsqlConnection? _connection; + + public HeldLock(NpgsqlConnection connection) => _connection = connection; + + public async Task ReleaseAsync(CancellationToken ct) + { + var connection = Interlocked.Exchange(ref _connection, null); + if (connection is not null) + { + await ExecAsync(connection, "ROLLBACK", ct); + await connection.DisposeAsync(); + } + } + + public async ValueTask DisposeAsync() + { + var connection = Interlocked.Exchange(ref _connection, null); + if (connection is not null) + { + await connection.DisposeAsync(); + } + } } private static async Task RequirePerChunkSettingsAsync(NpgsqlConnection connection, CancellationToken ct) => From b0a1a80ebfafd09e155814a247b950d2c55601a3 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Thu, 8 Oct 2026 16:06:07 -0400 Subject: [PATCH 5/7] perfmon re-group: pause for the time a busy lock cost, 30-minute statement cap, remember done and capped chunks, honest run-end reasons (#5574) --- .../BoundedDdlBusyStreakTests.cs | 3 +- .../Darling.Tests/PerfmonRegroupLiveTests.cs | 361 ++++++++++++++++-- .../DarlingWorker.cs | 5 +- .../PerfmonRegroupDrain.cs | 214 +++++++++-- .../TimescaleSupport.cs | 155 ++++++-- 5 files changed, 648 insertions(+), 90 deletions(-) diff --git a/Darling/Darling.Tests/BoundedDdlBusyStreakTests.cs b/Darling/Darling.Tests/BoundedDdlBusyStreakTests.cs index 34717ee3ce..e1bcda6078 100644 --- a/Darling/Darling.Tests/BoundedDdlBusyStreakTests.cs +++ b/Darling/Darling.Tests/BoundedDdlBusyStreakTests.cs @@ -93,7 +93,8 @@ public void TheWiring_ClearsOnApplied_AndOnFailed_AndEscalatesOnBusy() Assert.True(start > 0); var body = text.Substring(start, text.IndexOf("\n }\n", start, StringComparison.Ordinal) - start); Assert.Contains("BusyStreaks.RecordBusy(what", body, StringComparison.Ordinal); - Assert.Equal(2, body.Split("BusyStreaks.Clear(what", StringSplitOptions.None).Length - 1); + /* Applied, Failed, and (#5574) a relation that is gone: a chunk dropped by retention must not leave its streak behind. */ + Assert.Equal(3, body.Split("BusyStreaks.Clear(what", StringSplitOptions.None).Length - 1); Assert.Contains("LogWarning", body, StringComparison.Ordinal); } } diff --git a/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs b/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs index 2b4a75ecf5..ae95dbeb68 100644 --- a/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs +++ b/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs @@ -32,6 +32,11 @@ public sealed class PerfmonRegroupLiveTests private const string OldChunkSegmentBy = "server_id"; private const long IdBase = -495_200_000_000L; + /// "Now" for every day the tests seed, name and compare, captured ONCE: a run that crosses midnight UTC between a + /// seed and a lookup must not move the day a chunk is looked up by (the database's own clock decides only the reach, which + /// has days of slack on both sides of the seeded chunks). + private static readonly DateTime RunStartUtc = DateTime.UtcNow; + private sealed record ChunkRow(string Name, bool IsCompressed, string SegmentBy, DateTime Start); /// @@ -56,11 +61,13 @@ public async Task AnUpgradedStore_IsReGroupedNewestFirst_KeepsEveryRow_LeavesOut /* The hypertable still has the old grouping: the gate keeps the drain from writing the old grouping again. */ var gated = new CapturingTestLogger(); - Assert.Equal(0, await RunBoundedAsync(NewDrain(scratch.ConnectionString, gated, TimeSpan.Zero, new List()), 60, ct)); + var gatedRun = await RunDetailedBoundedAsync(NewDrain(scratch.ConnectionString, gated, TimeSpan.Zero, new List()), 60, ct); + Assert.Equal(0, gatedRun.Done); + Assert.Equal(PerfmonRegroupRunEnd.Blocked, gatedRun.End); Assert.DoesNotContain(gated.Lines, line => line.Contains("re-grouped perfmon_stats chunk", StringComparison.Ordinal)); await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); - var inReachNewestFirst = before.Where(chunk => chunk.Start > DateTime.UtcNow.AddDays(-30)).OrderByDescending(chunk => chunk.Start).Select(chunk => chunk.Name).ToList(); + var inReachNewestFirst = before.Where(chunk => chunk.Start > RunStartUtc.AddDays(-30)).OrderByDescending(chunk => chunk.Start).Select(chunk => chunk.Name).ToList(); Assert.Equal(5, inReachNewestFirst.Count); var logger = new CapturingTestLogger(); @@ -80,7 +87,9 @@ public async Task AnUpgradedStore_IsReGroupedNewestFirst_KeepsEveryRow_LeavesOut Assert.All(pauses, pause => Assert.Equal(TimeSpan.FromSeconds(90), pause)); var second = new CapturingTestLogger(); - Assert.Equal(0, await RunBoundedAsync(NewDrain(scratch.ConnectionString, second, TimeSpan.Zero, new List()), 60, ct)); + var secondRun = await RunDetailedBoundedAsync(NewDrain(scratch.ConnectionString, second, TimeSpan.Zero, new List()), 60, ct); + Assert.Equal(0, secondRun.Done); + Assert.Equal(PerfmonRegroupRunEnd.NothingLeft, secondRun.End); Assert.DoesNotContain(second.Lines, line => line.StartsWith("Information:", StringComparison.Ordinal)); Assert.Equal(after, await ReadChunksAsync(connection, ct)); } @@ -109,7 +118,7 @@ public async Task AFreshStore_CompressesItsFirstChunksWithTheNewGrouping_AndTheD await TimescaleSupport.ApplyCompressionPolicyAsync(connection, null, ct); Assert.Equal("server_id, counter_name", await HypertableSegmentByAsync(connection, ct)); - var today = DateTime.SpecifyKind(DateTime.UtcNow.Date, DateTimeKind.Unspecified); + var today = DateTime.SpecifyKind(RunStartUtc.Date, DateTimeKind.Unspecified); foreach (var daysBack in new[] { 2, 3, 4 }) { await SeedDayAsync(connection, today.AddDays(-daysBack), daysBack, ct); @@ -128,7 +137,9 @@ public async Task AFreshStore_CompressesItsFirstChunksWithTheNewGrouping_AndTheD Assert.Equal(fingerprint, await FingerprintAsync(connection, ct)); var logger = new CapturingTestLogger(); - Assert.Equal(0, await RunBoundedAsync(NewDrain(scratch.ConnectionString, logger, TimeSpan.Zero, new List()), 60, ct)); + var run = await RunDetailedBoundedAsync(NewDrain(scratch.ConnectionString, logger, TimeSpan.Zero, new List()), 60, ct); + Assert.Equal(0, run.Done); + Assert.Equal(PerfmonRegroupRunEnd.NothingLeft, run.End); Assert.DoesNotContain(logger.Lines, line => line.StartsWith("Information:", StringComparison.Ordinal)); } @@ -161,7 +172,7 @@ public async Task ACrashBetweenTheTwoHalves_LeavesAnUncompressedChunk_ThatThePol Assert.Equal(0, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); var afterDrain = await ReadChunksAsync(connection, ct); Assert.False(afterDrain.Single(chunk => chunk.Name == crashed.Name).IsCompressed); - Assert.All(afterDrain.Where(chunk => chunk.Name != crashed.Name && chunk.Start > DateTime.UtcNow.AddDays(-30)), chunk => Assert.Equal(WantedChunkSegmentBy, chunk.SegmentBy)); + Assert.All(afterDrain.Where(chunk => chunk.Name != crashed.Name && chunk.Start > RunStartUtc.AddDays(-30)), chunk => Assert.Equal(WantedChunkSegmentBy, chunk.SegmentBy)); /* The policy's next run compresses it with the hypertable's grouping. */ await RunPerfmonPolicyAsync(connection, ct); @@ -227,7 +238,7 @@ public async Task ThePauseAfterAChunk_IsAtLeastTheTimeThatChunkTook() Assert.Equal(4, pauses.Count); for (var i = 0; i < pauses.Count; i++) { - Assert.True(pauses[i].TotalMilliseconds >= tookMs[i] && pauses[i].TotalMilliseconds < tookMs[i] + 250, + Assert.True(pauses[i].TotalMilliseconds >= tookMs[i] && pauses[i].TotalMilliseconds < tookMs[i] + 2000, $"pause {i} was {pauses[i].TotalMilliseconds} ms, but chunk {i} took {tookMs[i]} ms"); Assert.True(pauses[i] > TimeSpan.Zero); } @@ -259,7 +270,7 @@ public async Task ABusyChunk_IsSkippedForTheRun_AndTheOthersAreReGrouped() var after = await ReadChunksAsync(connection, ct); Assert.Equal(OldChunkSegmentBy, after.Single(chunk => chunk.Name == held.Name).SegmentBy); - Assert.All(after.Where(chunk => chunk.Name != held.Name && chunk.Start > DateTime.UtcNow.AddDays(-30)), chunk => Assert.Equal(WantedChunkSegmentBy, chunk.SegmentBy)); + Assert.All(after.Where(chunk => chunk.Name != held.Name && chunk.Start > RunStartUtc.AddDays(-30)), chunk => Assert.Equal(WantedChunkSegmentBy, chunk.SegmentBy)); Assert.Single(logger.Lines, line => line.Contains("not changed this pass", StringComparison.Ordinal) && line.Contains(held.Name, StringComparison.Ordinal)); Assert.Contains(logger.Lines, line => line.Contains("1 skipped", StringComparison.Ordinal)); Assert.Equal(4, pauses.Count); @@ -362,6 +373,9 @@ public async Task WhenEveryCompressTryIsBusy_TheChunkIsLeftToThePolicy_WithOneWa Assert.Equal(3, logger.Lines.Count(line => line.Contains("not changed this pass", StringComparison.Ordinal))); Assert.Single(logger.Lines, line => line.StartsWith("Warning:", StringComparison.Ordinal) && line.Contains("stays uncompressed", StringComparison.Ordinal)); + + /* Every Warning, not one text (#5574): the three in-call tries are not "three passes in a row". */ + Assert.Equal(1, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); Assert.False((await ReadChunksAsync(connection, ct)).Single(c => c.Name == chunk.Name).IsCompressed); await RunPerfmonPolicyAsync(connection, ct); @@ -422,10 +436,10 @@ public async Task AReaderBesideTheReGroupOfALargeChunk_NeverWaitsMoreThanAFewSec await ExecAsync(connection, "ALTER TABLE perfmon_stats SET (timescaledb.compress, timescaledb.compress_segmentby = 'server_id')", ct); /* 4 servers x 130 counters x 2 instances = 1040 series, a sample a minute for a day: 1,497,600 rows. */ - var day = DateTime.SpecifyKind(DateTime.UtcNow.Date.AddDays(-3), DateTimeKind.Unspecified); + var day = DateTime.SpecifyKind(RunStartUtc.Date.AddDays(-3), DateTimeKind.Unspecified); using (var seed = new NpgsqlCommand( @"INSERT INTO perfmon_stats (collection_id, collection_time, server_id, server_name, object_name, counter_name, instance_name, cntr_value, delta_cntr_value, sample_interval_seconds, cntr_type) - SELECT $1 - row_number() OVER (), g.t, s.id, 'REGROUP-SRV', 'SQLServer:Test', 'Counter ' || c.n, 'inst' || i.i, + SELECT $1 - row_number() OVER (), g.t AT TIME ZONE 'UTC', s.id, 'REGROUP-SRV', 'SQLServer:Test', 'Counter ' || c.n, 'inst' || i.i, (extract(epoch FROM g.t)::bigint / 60 + s.id + c.n * 7 + i.i) % 100000, (extract(epoch FROM g.t)::bigint / 60 + c.n) % 50, 60, 65792 FROM generate_series($2::timestamp, $2::timestamp + INTERVAL '23 hours 59 minutes', INTERVAL '1 minute') AS g(t) CROSS JOIN generate_series(1, 4) AS s(id) @@ -442,6 +456,30 @@ CROSS JOIN generate_series(0, 1) AS i(i)", connection) { CommandTimeout = 300 }) await ExecAsync(connection, $"SELECT compress_chunk('{chunkName}')", ct); await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + /* The bound is on what the re-group ADDS to a read (#5574): the same read is timed without a re-group first, in this test, + so a slow runner moves both numbers and only a lock wait moves the difference. */ + static async Task TimeReadAsync(NpgsqlConnection readConnection, CancellationToken token) + { + var clock = System.Diagnostics.Stopwatch.StartNew(); + using var read = new NpgsqlCommand( + "SELECT count(*), max(cntr_value) FROM v_perfmon_stats WHERE server_id = 2 AND counter_name = 'Counter 7' AND collection_time >= now() - INTERVAL '30 days'", readConnection) + { CommandTimeout = 120 }; + await read.ExecuteScalarAsync(token); + clock.Stop(); + return clock.Elapsed; + } + + var baseline = TimeSpan.Zero; + using (var baselineConnection = new NpgsqlConnection(scratch.ConnectionString)) + { + await baselineConnection.OpenAsync(ct); + for (var i = 0; i < 5; i++) + { + var took = await TimeReadAsync(baselineConnection, ct); + baseline = took > baseline ? took : baseline; + } + } + var stop = false; var slowest = TimeSpan.Zero; var reads = 0; @@ -451,15 +489,10 @@ CROSS JOIN generate_series(0, 1) AS i(i)", connection) { CommandTimeout = 300 }) await readConnection.OpenAsync(ct); while (!Volatile.Read(ref stop)) { - var clock = System.Diagnostics.Stopwatch.StartNew(); - using var read = new NpgsqlCommand( - "SELECT count(*), max(cntr_value) FROM v_perfmon_stats WHERE server_id = 2 AND counter_name = 'Counter 7' AND collection_time >= now() - INTERVAL '30 days'", readConnection) - { CommandTimeout = 120 }; - await read.ExecuteScalarAsync(ct); - clock.Stop(); - if (clock.Elapsed > slowest) + var took = await TimeReadAsync(readConnection, ct); + if (took > slowest) { - slowest = clock.Elapsed; + slowest = took; } reads++; @@ -476,7 +509,8 @@ CROSS JOIN generate_series(0, 1) AS i(i)", connection) { CommandTimeout = 300 }) Assert.Equal(TimescaleSupport.PerfmonRegroupChunkResult.Regrouped, outcome.Result); Assert.Equal(1_497_600, outcome.Rows); Assert.True(reads >= 3, $"the reader only got {reads} reads in during a {outcome.Elapsed.TotalSeconds:0.0} s re-group"); - Assert.True(slowest < TimeSpan.FromSeconds(2.5), $"a read waited {slowest.TotalSeconds:0.0} s during a {outcome.Elapsed.TotalSeconds:0.0} s re-group"); + Assert.True(slowest - baseline < TimeSpan.FromSeconds(2.5), + $"a read took {slowest.TotalSeconds:0.0} s during a {outcome.Elapsed.TotalSeconds:0.0} s re-group, against {baseline.TotalSeconds:0.0} s without one"); } /// @@ -515,7 +549,7 @@ public async Task AServiceStopDuringThePause_EndsTheRunPromptly_WithoutAWarning( await WaitForAsync(() => Volatile.Read(ref pauseRequested) > 0, 60, ct); stopping.Cancel(); - var finished = await Task.WhenAny(drain.Completion!, Task.Delay(TimeSpan.FromSeconds(5), ct)); + var finished = await Task.WhenAny(drain.Completion!, Task.Delay(TimeSpan.FromSeconds(10), ct)); Assert.Same(drain.Completion, finished); Assert.False(drain.Completion!.IsFaulted); Assert.Equal(0, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); @@ -556,6 +590,256 @@ await Assert.ThrowsAnyAsync( TimescaleSupport.BusyStreaks.Reset(); } + /* ---------------- check round 1 (#5579) ---------------- */ + + /// + /// A busy lock pauses the drain as long as the work it cost, like every other outcome (#5574, M1): a lock lost at the END of + /// a decompress throws the whole rewrite away, and the pause is that time, not the floor. Here the lock is lost at the start + /// (the 3 s lock wait is the time spent), the floor is 1 ms, and the pause after the busy chunk must still be the wait; a + /// busy chunk that cost at least the lost-work threshold also gets its own Information line saying so. + /// + [Fact] + public async Task ABusyLock_PausesAsLongAsTheTimeItCost_AndALongOneSaysSo() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + TimescaleSupport.BusyStreaks.Reset(); + + var held = ChunkOfDay(await ReadChunksAsync(connection, ct), 1); + await using var holder = await HoldLockAsync(scratch.ConnectionString, held.Name, ct); + var logger = new CapturingTestLogger(); + var pauses = new List(); + var run = await RunDetailedBoundedAsync( + NewDrain(scratch.ConnectionString, logger, TimeSpan.FromMilliseconds(1), pauses, lostWorkThreshold: TimeSpan.FromSeconds(1)), 60, ct); + await holder.ReleaseAsync(ct); + + Assert.Equal(4, run.Done); + Assert.True(pauses[0] >= TimeSpan.FromSeconds(2.5), $"the pause after the busy chunk was {pauses[0].TotalSeconds:0.0} s, not the {TimescaleSupport.HourlyDdlLockTimeout} it cost"); + Assert.Single(logger.Lines, line => line.Contains("was lost after", StringComparison.Ordinal) && line.Contains(held.Name, StringComparison.Ordinal)); + TimescaleSupport.BusyStreaks.Reset(); + } + + /// + /// A decompress that runs into its statement cap is not retried while the process lives (#5574, M2): the newest chunk's lock is + /// held, so its decompress waits and the 2 s cap (a test value for the 30 minutes) ends it before the 3 s lock timeout. The + /// other four chunks are re-grouped, the capped one is untouched with ONE Warning, and a second run of the same drain does not + /// try it again even though it is still a candidate. + /// + [Fact] + public async Task ADecompressThatHitsTheStatementCap_IsNotTriedAgainForTheLifeOfTheProcess() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + TimescaleSupport.BusyStreaks.Reset(); + + var held = ChunkOfDay(await ReadChunksAsync(connection, ct), 1); + await using var holder = await HoldLockAsync(scratch.ConnectionString, held.Name, ct); + var logger = new CapturingTestLogger(); + var drain = NewDrain(scratch.ConnectionString, logger, TimeSpan.Zero, new List(), statementTimeoutSeconds: 2); + var first = await RunDetailedBoundedAsync(drain, 60, ct); + await holder.ReleaseAsync(ct); + + Assert.Equal(4, first.Done); + Assert.Equal(1, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); + Assert.Single(logger.Lines, line => line.Contains("could not be decompressed within 2 s", StringComparison.Ordinal) && line.Contains(held.Name, StringComparison.Ordinal)); + Assert.Equal(OldChunkSegmentBy, (await ReadChunksAsync(connection, ct)).Single(chunk => chunk.Name == held.Name).SegmentBy); + + var linesBefore = logger.Lines.Count; + var second = await RunDetailedBoundedAsync(drain, 60, ct); + Assert.Equal(0, second.Done); + Assert.Equal(PerfmonRegroupRunEnd.AllSkipped, second.End); + Assert.DoesNotContain(logger.Lines.Skip(linesBefore), line => line.Contains("(decompress)", StringComparison.Ordinal)); + Assert.Equal(OldChunkSegmentBy, (await ReadChunksAsync(connection, ct)).Single(chunk => chunk.Name == held.Name).SegmentBy); + TimescaleSupport.BusyStreaks.Reset(); + } + + /// + /// The compress half retries ONLY a busy lock (#5574, M2): a statement that ran into its cap ends the tries at once, with the + /// statement's own Warning and no second one, instead of three whole compressions. + /// + [Fact] + public async Task TheCompressHalf_IsNotRetriedAfterAnythingButABusyLock() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + TimescaleSupport.BusyStreaks.Reset(); + + var chunk = ChunkOfDay(await ReadChunksAsync(connection, ct), 3); + await ExecAsync(connection, $"SELECT decompress_chunk('{chunk.Name}')", ct); + await using var holder = await HoldLockAsync(scratch.ConnectionString, chunk.Name, ct); + var logger = new CapturingTestLogger(); + Assert.False(await TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.Zero, ct, statementTimeoutSeconds: 1)); + await holder.ReleaseAsync(ct); + + Assert.Equal(1, logger.Lines.Count(line => line.Contains("(compress) could not be changed", StringComparison.Ordinal))); + Assert.Equal(1, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); + Assert.Equal(0, logger.Lines.Count(line => line.Contains("not changed this pass", StringComparison.Ordinal))); + TimescaleSupport.BusyStreaks.Reset(); + } + + /// + /// A chunk that stays a candidate after this process re-grouped it is not rewritten forever (#5574, L2): the candidates read is + /// stubbed to keep answering with the chunk (as a TimescaleDB that spells the setting another way would), the drain rewrites it + /// once, skips it when it comes back with ONE Warning naming the setting text, and says nothing more in a second run. + /// + [Fact] + public async Task AChunkThatStaysACandidateAfterItsReGroup_IsSkipped_WithOneWarningPerProcess() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + + var chunk = ChunkOfDay(await ReadChunksAsync(connection, ct), 2); + var stub = new TimescaleSupport.PerfmonRegroupRead( + TimescaleSupport.PerfmonRegroupReadStatus.Candidates, + new[] { new TimescaleSupport.PerfmonRegroupCandidate(chunk.Name, "server_id, counter_name") }, null); + var logger = new CapturingTestLogger(); + var drain = NewDrain(scratch.ConnectionString, logger, TimeSpan.Zero, new List(), readCandidates: FixedRead(stub)); + + var first = await RunDetailedBoundedAsync(drain, 30, ct); + Assert.Equal(1, first.Done); + Assert.Equal(PerfmonRegroupRunEnd.AllSkipped, first.End); + Assert.Equal(1, logger.Lines.Count(line => line.Contains("re-grouped perfmon_stats chunk", StringComparison.Ordinal))); + Assert.Equal(1, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); + Assert.Single(logger.Lines, line => line.StartsWith("Warning:", StringComparison.Ordinal) && line.Contains("'server_id, counter_name'", StringComparison.Ordinal)); + + var second = await RunDetailedBoundedAsync(drain, 30, ct); + Assert.Equal(0, second.Done); + Assert.Equal(1, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); + Assert.Equal(1, logger.Lines.Count(line => line.Contains("re-grouped perfmon_stats chunk", StringComparison.Ordinal))); + } + + /// + /// A compressed chunk with no per-chunk settings row counts as the old grouping (#5574, L3): the row is deleted from the + /// catalog, and the candidates read still lists the chunk (an INNER JOIN to the view dropped it). + /// + [Fact] + public async Task AChunkWithNoPerChunkSettingsRow_IsACandidate() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + + var chunk = ChunkOfDay(await ReadChunksAsync(connection, ct), 2); + await ExecAsync(connection, $"DELETE FROM _timescaledb_catalog.compression_settings WHERE relid = '{chunk.Name}'::regclass", ct); + Assert.Equal("", (await ReadChunksAsync(connection, ct)).Single(c => c.Name == chunk.Name).SegmentBy); + + var read = await TimescaleSupport.ReadPerfmonRegroupCandidatesAsync(connection, null, 30, ct); + Assert.Equal(TimescaleSupport.PerfmonRegroupReadStatus.Candidates, read.Status); + Assert.Contains(read.Candidates, candidate => candidate.Chunk == chunk.Name && candidate.OldSegmentBy is null); + Assert.Equal(5, read.Candidates.Count); + } + + /// + /// A chunk that retention dropped between the candidates read and the decompress is skipped, not failed (#5574, L4): no + /// Warning, no count toward the failure limit (so the four others behind it, here three, are still tried). + /// + [Fact] + public async Task AChunkThatIsGoneAtDecompressTime_IsSkippedQuietly_NotFailed() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + + var gone = new TimescaleSupport.PerfmonRegroupCandidate("_timescaledb_internal._hyper_99999_99999_chunk", OldChunkSegmentBy); + var stub = new TimescaleSupport.PerfmonRegroupRead(TimescaleSupport.PerfmonRegroupReadStatus.Candidates, new[] { gone }, null); + var logger = new CapturingTestLogger(); + var run = await RunDetailedBoundedAsync(NewDrain(scratch.ConnectionString, logger, TimeSpan.Zero, new List(), readCandidates: FixedRead(stub)), 30, ct); + + Assert.Equal(0, run.Done); + Assert.Equal(PerfmonRegroupRunEnd.AllSkipped, run.End); + Assert.Equal(0, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); + Assert.DoesNotContain(logger.Lines, line => line.Contains("in a row could not be re-grouped", StringComparison.Ordinal)); + } + + /// + /// The reach is the shorter of 30 days and one day under the perfmon retention (#5574, L4): with a fleet retention of 4 days + /// only the chunks of the last 3 days are re-grouped, the 4- and 5-day-old ones (about to be dropped) are left. + /// + [Fact] + public async Task TheReach_IsClampedToTheRetentionLessADay() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + await ExecAsync(connection, + "INSERT INTO config.config_collector_schedules (server_id, collector_name, retention_days) VALUES (NULL, 'perfmon_stats', 4)", ct); + + var run = await RunDetailedBoundedAsync(NewDrain(scratch.ConnectionString, new CapturingTestLogger(), TimeSpan.Zero, new List()), 60, ct); + + Assert.Equal(3, run.Done); + var after = await ReadChunksAsync(connection, ct); + foreach (var daysBack in new[] { 1, 2, 3 }) + { + Assert.Equal(WantedChunkSegmentBy, after.Single(chunk => chunk.Name == ChunkOfDay(after, daysBack).Name).SegmentBy); + } + + Assert.Equal(OldChunkSegmentBy, ChunkOfDay(after, 4).SegmentBy); + Assert.Equal(OldChunkSegmentBy, ChunkOfDay(after, 5).SegmentBy); + } + + /// + /// A catalog read that fails is not reported as "converged" (#5574, L5): the run ends as ReadFailed, with ONE Warning + /// the first time in the process and Debug lines after; a closed gate ends it as Blocked with no Warning at all. + /// + [Fact] + public async Task AFailedCandidatesRead_IsWarnedOncePerProcess_AndIsNotConvergence() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await PgMigrations.MigrateAsync(connection, ct); + + var failed = new TimescaleSupport.PerfmonRegroupRead(TimescaleSupport.PerfmonRegroupReadStatus.ReadFailed, Array.Empty(), "permission denied for view chunks"); + var logger = new CapturingTestLogger(); + var drain = NewDrain(scratch.ConnectionString, logger, TimeSpan.Zero, new List(), readCandidates: FixedRead(failed)); + Assert.Equal(PerfmonRegroupRunEnd.ReadFailed, (await RunDetailedBoundedAsync(drain, 30, ct)).End); + Assert.Equal(PerfmonRegroupRunEnd.ReadFailed, (await RunDetailedBoundedAsync(drain, 30, ct)).End); + Assert.Equal(1, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); + Assert.Contains(logger.Lines, line => line.StartsWith("Warning:", StringComparison.Ordinal) && line.Contains("permission denied for view chunks", StringComparison.Ordinal)); + Assert.DoesNotContain(logger.Lines, line => line.Contains("has the old grouping to re-group", StringComparison.Ordinal)); + + var blocked = new TimescaleSupport.PerfmonRegroupRead(TimescaleSupport.PerfmonRegroupReadStatus.Blocked, Array.Empty(), "closed"); + var blockedLogger = new CapturingTestLogger(); + var blockedDrain = NewDrain(scratch.ConnectionString, blockedLogger, TimeSpan.Zero, new List(), readCandidates: FixedRead(blocked)); + Assert.Equal(PerfmonRegroupRunEnd.Blocked, (await RunDetailedBoundedAsync(blockedDrain, 30, ct)).End); + Assert.Equal(0, blockedLogger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); + Assert.DoesNotContain(blockedLogger.Lines, line => line.Contains("has the old grouping to re-group", StringComparison.Ordinal)); + } + /* ---------------- fixture ---------------- */ private static string RequireLivePostgres() @@ -566,7 +850,11 @@ private static string RequireLivePostgres() return connectionString!; } - private static PerfmonRegroupDrain NewDrain(string connectionString, CapturingTestLogger logger, TimeSpan minPause, List pauses) => + private static PerfmonRegroupDrain NewDrain( + string connectionString, CapturingTestLogger logger, TimeSpan minPause, List pauses, + int statementTimeoutSeconds = TimescaleSupport.PerfmonRegroupStatementTimeoutSeconds, + Func>? readCandidates = null, + TimeSpan? lostWorkThreshold = null) => new(async token => { var connection = new NpgsqlConnection(connectionString); @@ -578,7 +866,14 @@ private static PerfmonRegroupDrain NewDrain(string connectionString, CapturingTe { pauses.Add(pause); return Task.CompletedTask; - }); + }, + statementTimeoutSeconds, readCandidates, lostWorkThreshold); + + /// A candidates read that always answers with (a catalog the product's query cannot be made + /// to produce on a real store: a chunk that stays a candidate, a failed read, a chunk that is already gone). + private static Func> FixedRead( + TimescaleSupport.PerfmonRegroupRead read) => + (connection, logger, reach, token) => Task.FromResult(read); /// /// perfmon_stats as every build before #5574 left it: a hypertable compressed by server_id alone, five daily @@ -597,7 +892,7 @@ await ScalarAsync(connection, "SELECT to_regclass('timescaledb_information await ExecAsync(connection, TimescaleSupport.CreateHypertableSql(TimescaleSupport.PerfmonStatsTable, "collection_time"), ct); await ExecAsync(connection, "ALTER TABLE perfmon_stats SET (timescaledb.compress, timescaledb.compress_segmentby = 'server_id')", ct); - var today = DateTime.SpecifyKind(DateTime.UtcNow.Date, DateTimeKind.Unspecified); + var today = DateTime.SpecifyKind(RunStartUtc.Date, DateTimeKind.Unspecified); foreach (var daysBack in new[] { 1, 2, 3, 4, 5, 45 }) { await SeedDayAsync(connection, today.AddDays(-daysBack), daysBack, ct); @@ -626,7 +921,7 @@ private static async Task SeedDayAsync(NpgsqlConnection connection, DateTime day { using var command = new NpgsqlCommand( @"INSERT INTO perfmon_stats (collection_id, collection_time, server_id, server_name, object_name, counter_name, instance_name, cntr_value, delta_cntr_value, sample_interval_seconds, cntr_type) - SELECT $1 - $3 * 100000 - row_number() OVER (), g.t, s.id, 'REGROUP-SRV', 'SQLServer:Test', 'Counter ' || c.n, + SELECT $1 - $3 * 100000 - row_number() OVER (), g.t AT TIME ZONE 'UTC', s.id, 'REGROUP-SRV', 'SQLServer:Test', 'Counter ' || c.n, CASE WHEN i.i = 0 THEN '' ELSE 'inst' || i.i END, (extract(epoch FROM g.t)::bigint / 60 + s.id + c.n * 7 + i.i) % 100000, (extract(epoch FROM g.t)::bigint / 60 + c.n) % 50, 60, 65792 FROM generate_series($2::timestamp, $2::timestamp + INTERVAL '23 hours 30 minutes', INTERVAL '30 minutes') AS g(t) @@ -697,6 +992,22 @@ private static async Task RunBoundedAsync(PerfmonRegroupDrain drain, int se } } + /// with the reason the run ended. + private static async Task RunDetailedBoundedAsync(PerfmonRegroupDrain drain, int seconds, CancellationToken ct) + { + using var limit = CancellationTokenSource.CreateLinkedTokenSource(ct); + limit.CancelAfter(TimeSpan.FromSeconds(seconds)); + try + { + return await drain.RunDetailedAsync(limit.Token); + } + catch (OperationCanceledException) when (!ct.IsCancellationRequested) + { + Assert.Fail($"the drain had not finished {seconds} s into the run"); + return default; + } + } + private static async Task WaitForAsync(Func condition, int seconds, CancellationToken ct) { var deadline = DateTime.UtcNow.AddSeconds(seconds); @@ -708,7 +1019,7 @@ private static async Task WaitForAsync(Func condition, int seconds, Cancel } private static ChunkRow ChunkOfDay(List chunks, int daysBack) => - chunks.Single(chunk => chunk.Start.Date == DateTime.UtcNow.Date.AddDays(-daysBack)); + chunks.Single(chunk => chunk.Start.Date == RunStartUtc.Date.AddDays(-daysBack)); /// Another session holds ROW EXCLUSIVE on the chunk inside an open transaction, which conflicts with the /// EXCLUSIVE lock both halves of the re-group ask for. diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs index b387f9cac5..765cc78f57 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs @@ -10104,8 +10104,9 @@ private async Task ConvergeStoreObjectsAsync(CancellationToken cancellationToken loop on its own connection and the service's stopping token, not a step: the rewrite of a large store's chunk takes minutes, and a step would hold this pass (and the sweep loop that awaits it) for them. Starting it costs nothing here (no database work, and nothing when a run is already going); a converged store's run is two - catalog reads and it ends. Hourly only: the start path does not call it, so a restart is not held, and the - first :30 tick starts it. TimescaleDB-gated like the steps that need it. */ + catalog reads and it ends. Hourly pass only: the start path does not call it, so a restart is not held; the + first hourly pass, about 30 s after a start (its stamp seeds at MinValue, #3812/#3817), starts it, and + every hourly pass after. TimescaleDB-gated like the steps that need it. */ if (timescaleAvailable) { StartPerfmonRegroupDrain(cancellationToken); diff --git a/Darling/PerformanceMonitor.Darling.Storage/PerfmonRegroupDrain.cs b/Darling/PerformanceMonitor.Darling.Storage/PerfmonRegroupDrain.cs index 2b1a50a077..97cbeb0d89 100644 --- a/Darling/PerformanceMonitor.Darling.Storage/PerfmonRegroupDrain.cs +++ b/Darling/PerformanceMonitor.Darling.Storage/PerfmonRegroupDrain.cs @@ -1,4 +1,4 @@ -/* +/* * Copyright (c) 2026 Erik Darling, Darling Data LLC * * This file is part of the SQL Server Performance Monitor. @@ -16,9 +16,32 @@ namespace PerformanceMonitor.Darling.Storage; +/// Why a drain run ended (#5574); tests assert it, so "nothing ran" can be told apart from "could not run". +internal enum PerfmonRegroupRunEnd +{ + /// The catalog was read and no chunk in the reach has the old grouping (converged). + NothingLeft, + + /// The gate was closed (the hypertable still has the old grouping, or TimescaleDB cannot change settings). + Blocked, + + /// The catalog could not be read. + ReadFailed, + + /// Three chunks in a row failed. + FailureLimit, + + /// Every chunk left was skipped (busy, failed, gone, timed out, or already re-grouped by this process). + AllSkipped, +} + +/// One run's chunks re-grouped and the reason it ended. +internal readonly record struct PerfmonRegroupRunResult(int Done, PerfmonRegroupRunEnd End); + /// /// The background loop that re-groups the perfmon_stats chunks compressed by server_id alone (#5574), one chunk at -/// a time, newest first, inside the 30-day reach (). +/// a time, newest first, inside the reach: 30 days (), or one day less +/// than the perfmon retention when that is shorter (a chunk retention is about to drop is not worth a rewrite). /// /// Why a loop of its own, not a step of the hourly pass. The first version re-grouped for at most two minutes /// of each hourly pass. A large store's chunk (13.1 M rows measured, about 14 M per day on the biggest) takes minutes @@ -27,15 +50,23 @@ namespace PerformanceMonitor.Darling.Storage; /// rewrite runs here, on its own connection, so the pass (and the collection sweep that awaits it) never waits for a chunk. /// /// One chunk, then a pause as long as the chunk took (never under ), -/// so the store spends at most half its time on the rewrite. Thirty chunks of about 3 minutes finish in about three hours, -/// which is "hours, not days" without loading the store: the reads and the collectors share the disk with it. +/// so the store spends at most half its time on the rewrite. Every outcome pauses, a busy lock included: a lock lost at the +/// END of a decompress (the final ACCESS EXCLUSIVE) throws away the whole rewrite, and the pause is the time that cost, not +/// the floor. Thirty chunks of about 3 minutes finish in about three hours, which is "hours, not days" without loading the +/// store: the reads and the collectors share the disk with it. /// /// It stops by itself. When no chunk is left it ends after two catalog reads (Debug); the next hourly pass /// starts it again for the price of those two reads on a new connection. It also ends on three failed chunks in a row -/// (), and when every chunk left was skipped for a busy lock this -/// run (a skipped chunk is not tried again until the next hourly start, so one busy chunk cannot pin the loop). It stops -/// within a statement of the service stopping: the chunk in progress is cancelled and rolls back, or, when only the compress -/// half was cancelled, is left uncompressed for the compression policy to compress with the new grouping. +/// (), and when every chunk left was skipped this run (a skipped chunk +/// is not tried again until the next hourly start, so one busy chunk cannot pin the loop). It stops within a statement of +/// the service stopping: the chunk in progress is cancelled and rolls back, or, when only the compress half was cancelled, +/// is left uncompressed for the compression policy to compress with the new grouping. +/// +/// What it remembers for the life of the process (the drain object lives as long as the service): the chunks it +/// re-grouped, so a chunk that still reads as a candidate afterwards (a TimescaleDB release that spells the setting +/// differently) is skipped with one Warning instead of rewritten forever; the chunks whose decompress hit the statement cap +/// (), which would hit it every hour; and that a failed +/// catalog read has been reported once at Warning. /// /// Gated exactly as the first version was: is asked /// before every chunk (the hypertable must already carry the new grouping, TimescaleDB must be able to change settings @@ -44,12 +75,23 @@ namespace PerformanceMonitor.Darling.Storage; /// public sealed class PerfmonRegroupDrain { + /// A busy lock that lost at least this much work is worth an Information line of its own (a lock lost at the + /// start of a decompress costs the 3 s lock wait; anything near this was lost after a rewrite). + internal static readonly TimeSpan DefaultLostWorkThreshold = TimeSpan.FromSeconds(10); + private readonly Func> _openConnection; private readonly ILogger? _logger; private readonly int _reachDays; private readonly TimeSpan _minPause; private readonly Func _delay; + private readonly int _statementTimeoutSeconds; + private readonly Func> _readCandidates; + private readonly TimeSpan _lostWorkThreshold; private readonly object _gate = new(); + private readonly HashSet _regrouped = new(StringComparer.Ordinal); + private readonly HashSet _gaveUp = new(StringComparer.Ordinal); + private bool _warnedReadFailure; + private bool _warnedRepeatCandidate; private Task? _running; /// Opens a store connection; the drain owns and disposes what it gets, one per run. @@ -59,20 +101,26 @@ public PerfmonRegroupDrain(Func> { } - /// The test seam: the reach, the pause floor and the wait itself (a test records the pauses it is asked for - /// instead of sleeping them). + /// The test seam: the reach, the pause floor, the wait itself (a test records the pauses it is asked for + /// instead of sleeping them) and the statement cap in seconds. internal PerfmonRegroupDrain( Func> openConnection, ILogger? logger, int reachDays, TimeSpan minPause, - Func delay) + Func delay, + int statementTimeoutSeconds = TimescaleSupport.PerfmonRegroupStatementTimeoutSeconds, + Func>? readCandidates = null, + TimeSpan? lostWorkThreshold = null) { + _readCandidates = readCandidates ?? TimescaleSupport.ReadPerfmonRegroupCandidatesAsync; + _lostWorkThreshold = lostWorkThreshold ?? DefaultLostWorkThreshold; _openConnection = openConnection ?? throw new ArgumentNullException(nameof(openConnection)); _logger = logger; _reachDays = reachDays; _minPause = minPause; _delay = delay ?? throw new ArgumentNullException(nameof(delay)); + _statementTimeoutSeconds = statementTimeoutSeconds; } /// The run in flight (or the last one), so shutdown can wait for it. It never faults. @@ -128,24 +176,28 @@ private async Task RunGuardedAsync(CancellationToken stoppingToken) /// One run: re-groups chunks, newest first, until none is left, the failure limit is reached, every chunk left was /// skipped, or is cancelled (which throws). Returns the chunks re-grouped. /// - internal async Task RunAsync(CancellationToken cancellationToken) + internal async Task RunAsync(CancellationToken cancellationToken) => (await RunDetailedAsync(cancellationToken)).Done; + + /// with the reason the run ended, so a test can tell "nothing left" from "could not run". + internal async Task RunDetailedAsync(CancellationToken cancellationToken) { await using var connection = await _openConnection(cancellationToken); + var reach = await EffectiveReachDaysAsync(connection, cancellationToken); var skipped = new HashSet(StringComparer.Ordinal); var run = Stopwatch.StartNew(); var done = 0; var failuresInARow = 0; var left = 0; + var end = PerfmonRegroupRunEnd.NothingLeft; var owedPause = TimeSpan.Zero; var started = false; while (true) { - var candidates = await TimescaleSupport.ReadPerfmonRegroupCandidatesAsync(connection, _logger, _reachDays, cancellationToken); - var next = Next(candidates, skipped); + var read = await _readCandidates(connection, _logger, reach, cancellationToken); + var next = Next(read, skipped, out end, out left); if (next is null) { - left = candidates?.Count ?? -1; break; } @@ -155,11 +207,10 @@ internal async Task RunAsync(CancellationToken cancellationToken) is read again after it: the policy or a restart may have re-grouped the chunk meanwhile. */ await _delay(owedPause, cancellationToken); owedPause = TimeSpan.Zero; - candidates = await TimescaleSupport.ReadPerfmonRegroupCandidatesAsync(connection, _logger, _reachDays, cancellationToken); - next = Next(candidates, skipped); + read = await _readCandidates(connection, _logger, reach, cancellationToken); + next = Next(read, skipped, out end, out left); if (next is null) { - left = candidates?.Count ?? -1; break; } } @@ -169,37 +220,63 @@ internal async Task RunAsync(CancellationToken cancellationToken) started = true; _logger?.LogInformation( "TimescaleDB: perfmon_stats re-group started: {Chunks} chunk(s) inside the {Days}-day reach have the old grouping; they are re-grouped one at a time, newest first, each followed by a pause as long as it took (at least {MinPauseSeconds} s) (#5574)", - candidates!.Count, _reachDays, (int)_minPause.TotalSeconds); + read.Candidates.Count, reach, (int)_minPause.TotalSeconds); } - var outcome = await TimescaleSupport.RegroupPerfmonChunkAsync(connection, _logger, next.Value, cancellationToken); + var chunk = next.Value.Chunk; + var outcome = await TimescaleSupport.RegroupPerfmonChunkAsync(connection, _logger, next.Value, cancellationToken, _statementTimeoutSeconds); + + /* Every outcome waits as long as the work took: a lock lost at the end of a decompress threw a whole rewrite away, + and the store was just as busy as after a good one. */ + owedPause = Max(outcome.Elapsed, _minPause); switch (outcome.Result) { case TimescaleSupport.PerfmonRegroupChunkResult.Regrouped: done++; failuresInARow = 0; - owedPause = Max(outcome.Elapsed, _minPause); + _regrouped.Add(chunk); break; case TimescaleSupport.PerfmonRegroupChunkResult.LockBusy: - /* Nothing changed. Skipped until the next start, so a chunk that stays busy is not hammered, and the - wait is the floor: the chunk cost a 3 s lock wait, not a rewrite. */ - skipped.Add(next.Value.Chunk); + /* Nothing changed. Skipped until the next start, so a chunk that stays busy is not hammered. */ + skipped.Add(chunk); failuresInARow = 0; - owedPause = _minPause; + if (outcome.Elapsed >= _lostWorkThreshold) + { + _logger?.LogInformation( + "TimescaleDB: the lock on perfmon_stats chunk {Chunk} was lost after {ElapsedMs} ms of decompress work, which rolled back; the chunk is tried again at the next hourly check and the drain waits as long as the lost work took (#5574)", + chunk, (long)outcome.Elapsed.TotalMilliseconds); + } + break; case TimescaleSupport.PerfmonRegroupChunkResult.LeftUncompressed: /* The chunk is now the compression policy's (no longer a candidate: it is not compressed). The store - just did a whole rewrite, so the wait is as long as it took, and it counts toward the limit. */ - owedPause = Max(outcome.Elapsed, _minPause); + just did a whole rewrite, and it counts toward the limit. */ + failuresInARow++; + break; + + case TimescaleSupport.PerfmonRegroupChunkResult.Gone: + /* Retention dropped the chunk between the read and the decompress: nothing to do, nothing failed. */ + skipped.Add(chunk); + failuresInARow = 0; + _logger?.LogDebug("TimescaleDB: perfmon_stats chunk {Chunk} no longer exists (retention dropped it), so it is not re-grouped (#5574)", chunk); + break; + + case TimescaleSupport.PerfmonRegroupChunkResult.TimedOut: + /* The decompress ran into its statement cap. The same chunk would run into it at every hourly start, + so it is left alone while this process lives. The statement's own Warning has said why. */ + skipped.Add(chunk); + _gaveUp.Add(chunk); failuresInARow++; + _logger?.LogInformation( + "TimescaleDB: perfmon_stats chunk {Chunk} could not be decompressed within {Seconds} s, so it is not tried again until the service restarts (#5574)", + chunk, _statementTimeoutSeconds); break; default: - skipped.Add(next.Value.Chunk); + skipped.Add(chunk); failuresInARow++; - owedPause = _minPause; break; } @@ -209,6 +286,7 @@ internal async Task RunAsync(CancellationToken cancellationToken) "TimescaleDB: {Failures} perfmon_stats chunks in a row could not be re-grouped, so the re-group stops; the next hourly check tries again (#5574)", failuresInARow); left = -1; + end = PerfmonRegroupRunEnd.FailureLimit; break; } } @@ -217,32 +295,88 @@ internal async Task RunAsync(CancellationToken cancellationToken) { _logger?.LogInformation( "TimescaleDB: perfmon_stats re-group run over: {Done} chunk(s) re-grouped to '{New}' in {ElapsedMs} ms; {Skipped} skipped for a busy lock or an error (tried again at the next hourly check); {Left} chunk(s) inside the {Days}-day reach still have the old grouping (#5574)", - done, TimescaleSupport.PerfmonStatsSegmentBy, run.ElapsedMilliseconds, skipped.Count, left < 0 ? "an unknown number of" : left.ToString(System.Globalization.CultureInfo.InvariantCulture), _reachDays); + done, TimescaleSupport.PerfmonStatsSegmentBy, run.ElapsedMilliseconds, skipped.Count, left < 0 ? "an unknown number of" : left.ToString(System.Globalization.CultureInfo.InvariantCulture), reach); } - else + else if (end == PerfmonRegroupRunEnd.NothingLeft) { - _logger?.LogDebug("TimescaleDB: no perfmon_stats chunk inside the {Days}-day reach has the old grouping to re-group (#5574)", _reachDays); + _logger?.LogDebug("TimescaleDB: no perfmon_stats chunk inside the {Days}-day reach has the old grouping to re-group (#5574)", reach); + } + else if (end == PerfmonRegroupRunEnd.Blocked) + { + _logger?.LogDebug("TimescaleDB: the perfmon_stats re-group did not run: the gate is closed (the reason is in the line above) (#5574)"); } - return done; + return new PerfmonRegroupRunResult(done, end); } - private static TimescaleSupport.PerfmonRegroupCandidate? Next( - IReadOnlyList? candidates, HashSet skipped) + /// The reach this run uses: the configured days, or one day less than the perfmon retention when that is + /// shorter (#5574). A retention that could not be read leaves the configured reach. + private async Task EffectiveReachDaysAsync(NpgsqlConnection connection, CancellationToken cancellationToken) + { + var retention = await TimescaleSupport.ReadPerfmonRetentionDaysAsync(connection, cancellationToken); + return retention is int days ? Math.Min(_reachDays, Math.Max(0, days - 1)) : _reachDays; + } + + /// + /// The newest candidate this run may still do, or null with saying why not: the gate + /// blocked, the read failed (a Warning the first time in the process, Debug after), nothing is left, or every candidate + /// was skipped. A candidate this process already re-grouped is skipped, with one Warning per process that names the + /// setting text the view returned (a TimescaleDB that spells it another way than the literal the read compares to). + /// + private TimescaleSupport.PerfmonRegroupCandidate? Next( + TimescaleSupport.PerfmonRegroupRead read, HashSet skipped, out PerfmonRegroupRunEnd end, out int left) { - if (candidates is null) + left = -1; + switch (read.Status) { - return null; + case TimescaleSupport.PerfmonRegroupReadStatus.Blocked: + end = PerfmonRegroupRunEnd.Blocked; + return null; + + case TimescaleSupport.PerfmonRegroupReadStatus.ReadFailed: + end = PerfmonRegroupRunEnd.ReadFailed; + if (!_warnedReadFailure) + { + _warnedReadFailure = true; + _logger?.LogWarning( + "TimescaleDB: could not read perfmon_stats's chunk compression settings, so no chunk is re-grouped; this is logged once per service run and repeated only at Debug (#5574): {Message}", + read.Detail); + } + else + { + _logger?.LogDebug("TimescaleDB: could not read perfmon_stats's chunk compression settings again (#5574): {Message}", read.Detail); + } + + return null; } - foreach (var candidate in candidates) + left = read.Candidates.Count; + foreach (var candidate in read.Candidates) { - if (!skipped.Contains(candidate.Chunk)) + if (skipped.Contains(candidate.Chunk) || _gaveUp.Contains(candidate.Chunk)) { - return candidate; + continue; } + + if (_regrouped.Contains(candidate.Chunk)) + { + skipped.Add(candidate.Chunk); + if (!_warnedRepeatCandidate) + { + _warnedRepeatCandidate = true; + _logger?.LogWarning( + "TimescaleDB: perfmon_stats chunk {Chunk} was re-grouped by this service run but the catalog still reports its grouping as '{Setting}' (the wanted one is '{New}'), so it is not re-grouped again; check the TimescaleDB version's spelling of the setting (#5574)", + candidate.Chunk, candidate.OldSegmentBy ?? "(none)", TimescaleSupport.PerfmonStatsChunkSegmentBy); + } + + continue; + } + + end = PerfmonRegroupRunEnd.NothingLeft; + return candidate; } + end = read.Candidates.Count == 0 ? PerfmonRegroupRunEnd.NothingLeft : PerfmonRegroupRunEnd.AllSkipped; return null; } diff --git a/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs b/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs index 09ae452033..3197229fec 100644 --- a/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs +++ b/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs @@ -10842,6 +10842,15 @@ internal enum BoundedDdlOutcome /// A statement failed for another reason and the transaction rolled back; nothing changed. Failed, + + /// The statement ran into its client timeout and rolled back; nothing changed. Returned only to a caller that + /// asked for it (distinguishTimeoutAndMissing), who gives a statement a long timeout and wants to know it was the + /// cap; every other caller keeps getting . + TimedOut, + + /// The relation the statement named is gone (42P01), and nothing changed. Returned only to a caller that asked + /// for it (distinguishTimeoutAndMissing); it costs a Debug line, not a Warning. + RelationMissing, } /// @@ -10877,7 +10886,8 @@ internal static Task TryRunBoundedDdlAsync( /// lock_timeout, and the same outcomes and log lines apply. The list overload is this one with a loop for a body. /// internal static async Task TryRunBoundedDdlAsync( - NpgsqlConnection connection, Func body, ILogger? logger, string what, CancellationToken cancellationToken) + NpgsqlConnection connection, Func body, ILogger? logger, string what, CancellationToken cancellationToken, + bool recordBusyStreak = true, bool distinguishTimeoutAndMissing = false) { try { @@ -10905,7 +10915,10 @@ internal static async Task TryRunBoundedDdlAsync( "TimescaleDB: {What} not changed this pass: another session held the table for {Timeout}, and waiting longer would hold up every collector's writes to it; the next hourly pass tries again", what, HourlyDdlLockTimeout); var now = DateTime.UtcNow; - if (BusyStreaks.RecordBusy(what, now, out var passes, out var firstBusyUtc)) + + /* #5574: the compress half's in-call retries (three tries inside ten seconds) are not "passes", and counting + them would add a "busy for 3 passes in a row" Warning to the one the half logs itself. */ + if (recordBusyStreak && BusyStreaks.RecordBusy(what, now, out var passes, out var firstBusyUtc)) { logger?.LogWarning( "TimescaleDB: {What} has been busy for {Passes} passes in a row, since {Since:u} UTC ({Elapsed} ago); its settings stay as they are until another session releases the table", @@ -10914,16 +10927,37 @@ internal static async Task TryRunBoundedDdlAsync( return BoundedDdlOutcome.LockBusy; } + catch (PostgresException ex) when (distinguishTimeoutAndMissing + && string.Equals(ex.SqlState, PostgresErrorCodes.UndefinedTable, StringComparison.Ordinal)) + { + /* #5574: the chunk was dropped (retention) between the candidates read and the statement. Nothing to do. */ + BusyStreaks.Clear(what, out _); + logger?.LogDebug("TimescaleDB: {What} skipped: the relation no longer exists ({Message})", what, ex.Message); + return BoundedDdlOutcome.RelationMissing; + } catch (Exception ex) when (ex is not OperationCanceledException) { BusyStreaks.Clear(what, out _); logger?.LogWarning( "TimescaleDB: {What} could not be changed, so the change was rolled back and the table keeps its current settings: {Message}", what, ex.Message); - return BoundedDdlOutcome.Failed; + return distinguishTimeoutAndMissing && IsStatementTimeout(ex, cancellationToken) + ? BoundedDdlOutcome.TimedOut + : BoundedDdlOutcome.Failed; } } + /// + /// Whether is a statement that ran into its client CommandTimeout (and not the caller's + /// cancellation): Npgsql reports it as a (itself or inside an ), + /// or as the server's query-cancelled error (57014) its cancel request caused. + /// + internal static bool IsStatementTimeout(Exception ex, CancellationToken cancellationToken) => + !cancellationToken.IsCancellationRequested + && (ex is TimeoutException + || ex.InnerException is TimeoutException + || (ex is PostgresException { SqlState: PostgresErrorCodes.QueryCanceled })); + /// /// Enables compression and adds the -day background policy on /// every collector table (both statements per table, failure-isolated per table — a table @@ -12275,12 +12309,14 @@ FROM timescaledb_information.compression_settings AS cs /// (the view joins the chunk, not the hypertable), because the hypertable's setting says nothing about a chunk /// compressed before it changed. range_end is the chunk's upper bound as a real instant (the view converts the /// internal UTC microseconds), so it compares to now() without a time zone step. The result is empty on a - /// converged store, and the read costs one catalog join. + /// converged store, and the read costs one catalog join. The join is a LEFT JOIN (#5574): a compressed chunk with no + /// per-chunk settings row (one compressed before the extension moved to per-chunk settings) has no known grouping, so + /// it counts as the old one, and the drain's done-set stops any loop over a chunk that stays a candidate. /// private const string PerfmonRegroupCandidatesSql = @" SELECT format('%I.%I', c.chunk_schema, c.chunk_name), s.segmentby FROM timescaledb_information.chunks AS c -JOIN timescaledb_information.chunk_compression_settings AS s +LEFT JOIN timescaledb_information.chunk_compression_settings AS s ON s.chunk = to_regclass(format('%I.%I', c.chunk_schema, c.chunk_name)) WHERE c.hypertable_schema = 'collect' AND c.hypertable_name = 'perfmon_stats' @@ -12336,6 +12372,14 @@ internal enum PerfmonRegroupChunkResult /// The decompress failed and rolled back, so nothing changed. Failed, + /// The decompress ran into its statement cap () and rolled + /// back, so nothing changed. The drain does not try the chunk again while the process lives. + TimedOut, + + /// The chunk was gone (retention dropped it) when the decompress asked for it, so nothing changed and + /// nothing failed. + Gone, + /// The decompress committed and the compress did not (a busy lock on every try, a failure, or the /// service stopping): the chunk is uncompressed and the compression policy compresses it with the wanted grouping. LeftUncompressed, @@ -12344,17 +12388,59 @@ internal enum PerfmonRegroupChunkResult /// One chunk's result, the rows it held (-1 when the count failed) and how long it took. internal readonly record struct PerfmonRegroupChunkOutcome(PerfmonRegroupChunkResult Result, long Rows, TimeSpan Elapsed); + /// The longest one re-group statement (the decompress, the compress) may run before the client gives up on it + /// (#5574): 30 minutes, far above the ~90-180 s a 13 M-row chunk takes, so only a chunk several times that size, or a + /// store that is struggling, reaches it. The service's stopping token cancels a statement long before. + internal const int PerfmonRegroupStatementTimeoutSeconds = 1800; + + /// The state of the candidates read (#5574): which of the three things the old null stood for it was. + internal enum PerfmonRegroupReadStatus + { + /// The gate is open and the catalog was read; the list may be empty (converged). + Candidates, + + /// The gate is closed (); the reason is in the detail. + Blocked, + + /// The catalog could not be read; the error message is in the detail. + ReadFailed, + } + + /// One candidates read: its status, the chunks (empty unless ), + /// and the reason or error text for the other two. + internal readonly record struct PerfmonRegroupRead(PerfmonRegroupReadStatus Status, IReadOnlyList Candidates, string? Detail); + + /// The configured fleet retention of the perfmon collector in days, or null when it could not be read + /// (#5574). The drain clamps its reach to it. + internal static async Task ReadPerfmonRetentionDaysAsync(NpgsqlConnection connection, CancellationToken cancellationToken) + { + try + { + using var command = new NpgsqlCommand( + "SELECT retention_days FROM config.config_collector_schedules WHERE server_id IS NULL AND lower(collector_name) = $1 AND retention_days >= 1 LIMIT 1", + connection) { CommandTimeout = JobCatalogReadTimeoutSeconds }; + command.Parameters.AddWithValue(PerfmonStatsTable); + var value = await command.ExecuteScalarAsync(cancellationToken); + return DarlingRetentionHorizons.ResolveFleetRetentionDays(PerfmonStatsTable, value is int days ? days : (int?)null); + } + catch (Exception ex) when (ex is not OperationCanceledException) + { + return null; + } + } + /// - /// The compressed perfmon_stats chunks inside the reach that still have the old grouping, newest first (#5574), or - /// null when the re-group cannot run now () or the catalog could not be - /// read; both are one Debug line, because both are a normal state of some store. An empty list means converged. + /// The compressed perfmon_stats chunks inside the reach that still have the old grouping, newest first (#5574), as a + /// that says which of three things happened: the candidates (an empty list means + /// converged), the gate blocked the re-group (; one Debug line, a normal state of + /// some store), or the catalog could not be read (the caller logs it). /// /// This is the whole of the "is anything left" check, two catalog reads, and it is what the drain repeats /// before every chunk: the gate (the hypertable's own setting is checked every time because compressing under the old /// one would undo the work) and the candidates are read fresh, so a chunk the compression policy has meanwhile /// compressed with the new grouping drops out of the list on its own. /// - internal static async Task?> ReadPerfmonRegroupCandidatesAsync( + internal static async Task ReadPerfmonRegroupCandidatesAsync( NpgsqlConnection connection, ILogger? logger, int reachDays, CancellationToken cancellationToken) { if (connection is null) @@ -12373,7 +12459,7 @@ internal enum PerfmonRegroupChunkResult { if (!await reader.ReadAsync(cancellationToken)) { - return null; + return new PerfmonRegroupRead(PerfmonRegroupReadStatus.ReadFailed, candidates, "the state query returned no row"); } version = ParseTimescaleVersion(reader.IsDBNull(0) ? null : reader.GetString(0)); @@ -12385,7 +12471,7 @@ internal enum PerfmonRegroupChunkResult if (blocked is not null) { logger?.LogDebug("TimescaleDB: perfmon_stats chunks are not re-grouped now: {Reason} (#5574)", blocked); - return null; + return new PerfmonRegroupRead(PerfmonRegroupReadStatus.Blocked, candidates, blocked); } using var find = new NpgsqlCommand(PerfmonRegroupCandidatesSql, connection) { CommandTimeout = JobCatalogReadTimeoutSeconds }; @@ -12399,11 +12485,11 @@ internal enum PerfmonRegroupChunkResult } catch (Exception ex) when (ex is not OperationCanceledException) { - logger?.LogDebug("TimescaleDB: could not read perfmon_stats's chunk compression settings, so no chunk is re-grouped now (#5574): {Message}", ex.Message); - return null; + /* The drain logs this one (a Warning the first time in the process, then Debug), so it is not logged here. */ + return new PerfmonRegroupRead(PerfmonRegroupReadStatus.ReadFailed, new List(), ex.Message); } - return candidates; + return new PerfmonRegroupRead(PerfmonRegroupReadStatus.Candidates, candidates, null); } /// @@ -12440,7 +12526,8 @@ internal enum PerfmonRegroupChunkResult /// Never throws, except for cancellation. /// internal static async Task RegroupPerfmonChunkAsync( - NpgsqlConnection connection, ILogger? logger, PerfmonRegroupCandidate candidate, CancellationToken cancellationToken) + NpgsqlConnection connection, ILogger? logger, PerfmonRegroupCandidate candidate, CancellationToken cancellationToken, + int statementTimeoutSeconds = PerfmonRegroupStatementTimeoutSeconds) { if (connection is null) { @@ -12453,16 +12540,23 @@ internal static async Task RegroupPerfmonChunkAsync( connection, async transaction => { - using var decompress = new NpgsqlCommand("SELECT decompress_chunk($1::regclass)", connection, transaction) { CommandTimeout = SetupTimeoutSeconds }; + using var decompress = new NpgsqlCommand("SELECT decompress_chunk($1::regclass)", connection, transaction) { CommandTimeout = statementTimeoutSeconds }; decompress.Parameters.AddWithValue(chunk); await decompress.ExecuteNonQueryAsync(cancellationToken); }, - logger, $"re-grouping perfmon_stats chunk {chunk} (decompress)", cancellationToken); + logger, $"re-grouping perfmon_stats chunk {chunk} (decompress)", cancellationToken, + distinguishTimeoutAndMissing: true); if (decompressed != BoundedDdlOutcome.Applied) { return new PerfmonRegroupChunkOutcome( - decompressed == BoundedDdlOutcome.LockBusy ? PerfmonRegroupChunkResult.LockBusy : PerfmonRegroupChunkResult.Failed, + decompressed switch + { + BoundedDdlOutcome.LockBusy => PerfmonRegroupChunkResult.LockBusy, + BoundedDdlOutcome.TimedOut => PerfmonRegroupChunkResult.TimedOut, + BoundedDdlOutcome.RelationMissing => PerfmonRegroupChunkResult.Gone, + _ => PerfmonRegroupChunkResult.Failed, + }, 0, clock.Elapsed); } @@ -12478,7 +12572,7 @@ internal static async Task RegroupPerfmonChunkAsync( logger?.LogDebug("TimescaleDB: could not count the rows of perfmon_stats chunk {Chunk} before compressing it again: {Message}", chunk, ex.Message); } - if (await CompressRegroupedChunkAsync(connection, logger, chunk, PerfmonRegroupCompressAttempts, PerfmonRegroupCompressRetryDelay, cancellationToken)) + if (await CompressRegroupedChunkAsync(connection, logger, chunk, PerfmonRegroupCompressAttempts, PerfmonRegroupCompressRetryDelay, cancellationToken, statementTimeoutSeconds)) { logger?.LogInformation( "TimescaleDB: re-grouped perfmon_stats chunk {Chunk} ({Rows} rows) from '{Old}' to '{New}' in {ElapsedMs} ms (#5574)", @@ -12496,9 +12590,15 @@ internal static async Task RegroupPerfmonChunkAsync( /// chunk stays uncompressed, with one Warning, and the compression policy compresses it with the hypertable's grouping /// at its next run. if_not_compressed makes a policy run that got there first a success, not an error. /// A cancellation (the service stopping) leaves the chunk the same way, says so at Information, and propagates. + /// + /// Only a busy lock is retried (55P03, behind the 3 s lock timeout): any other error, a statement that ran + /// into its cap included, ends the tries at once, because a second try of a compression that just failed (or ran + /// 30 minutes) is another whole compression. The busy tries are not fed to : three tries inside + /// ten seconds are not "three passes", and the Warning below is the one line an all-busy half logs. /// internal static async Task CompressRegroupedChunkAsync( - NpgsqlConnection connection, ILogger? logger, string chunk, int attempts, TimeSpan retryDelay, CancellationToken cancellationToken) + NpgsqlConnection connection, ILogger? logger, string chunk, int attempts, TimeSpan retryDelay, CancellationToken cancellationToken, + int statementTimeoutSeconds = PerfmonRegroupStatementTimeoutSeconds) { try { @@ -12508,17 +12608,28 @@ internal static async Task CompressRegroupedChunkAsync( connection, async transaction => { - using var compress = new NpgsqlCommand("SELECT compress_chunk($1::regclass, if_not_compressed => true)", connection, transaction) { CommandTimeout = SetupTimeoutSeconds }; + using var compress = new NpgsqlCommand("SELECT compress_chunk($1::regclass, if_not_compressed => true)", connection, transaction) { CommandTimeout = statementTimeoutSeconds }; compress.Parameters.AddWithValue(chunk); await compress.ExecuteNonQueryAsync(cancellationToken); }, - logger, $"re-grouping perfmon_stats chunk {chunk} (compress)", cancellationToken); + logger, $"re-grouping perfmon_stats chunk {chunk} (compress)", cancellationToken, + recordBusyStreak: false, distinguishTimeoutAndMissing: true); if (compressed == BoundedDdlOutcome.Applied) { return true; } + if (compressed != BoundedDdlOutcome.LockBusy) + { + /* Not a busy lock (an error, the cap, a chunk that is gone): the line above says why, and the chunk is + the compression policy's. */ + logger?.LogInformation( + "TimescaleDB: perfmon_stats chunk {Chunk} was decompressed for re-grouping and compressing it again did not work ({Outcome}), so it stays uncompressed until the compression policy compresses it with '{New}' at its next run (#5574)", + chunk, compressed, PerfmonStatsChunkSegmentBy); + return false; + } + if (attempt < attempts) { await Task.Delay(retryDelay, cancellationToken); From 0da387840f72c410e0147acae21697feef8e9747 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Thu, 8 Oct 2026 16:33:16 -0400 Subject: [PATCH 6/7] perfmon re-group: server cancel logged as such with its real time, gone chunk at either half confirmed by the chunk catalog, sturdier reach and reader tests (#5574) --- .../Darling.Tests/PerfmonRegroupLiveTests.cs | 153 +++++++++++++++--- .../PerfmonRegroupDrain.cs | 30 +++- .../TimescaleSupport.cs | 85 ++++++++-- 3 files changed, 226 insertions(+), 42 deletions(-) diff --git a/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs b/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs index ae95dbeb68..bfd7a4bb72 100644 --- a/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs +++ b/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs @@ -33,8 +33,9 @@ public sealed class PerfmonRegroupLiveTests private const long IdBase = -495_200_000_000L; /// "Now" for every day the tests seed, name and compare, captured ONCE: a run that crosses midnight UTC between a - /// seed and a lookup must not move the day a chunk is looked up by (the database's own clock decides only the reach, which - /// has days of slack on both sides of the seeded chunks). + /// seed and a lookup must not move the day a chunk is looked up by. The database's own clock decides the reach, which has + /// days of slack on both sides of the seeded chunks in every test but TheReach_IsClampedToTheRetentionLessADay; that + /// one reads the chunks in its reach from now() itself. private static readonly DateTime RunStartUtc = DateTime.UtcNow; private sealed record ChunkRow(string Name, bool IsCompressed, string SegmentBy, DateTime Start); @@ -205,7 +206,7 @@ public async Task WhenThePolicyCompressedTheChunkFirst_TheCompressHalfIsDone_Not Assert.True((await ReadChunksAsync(connection, ct)).Single(c => c.Name == chunk.Name).IsCompressed); var logger = new CapturingTestLogger(); - Assert.True(await TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.Zero, ct)); + Assert.Equal(TimescaleSupport.PerfmonRegroupChunkResult.Regrouped, await TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.Zero, ct)); Assert.Equal(0, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); var after = (await ReadChunksAsync(connection, ct)).Single(c => c.Name == chunk.Name); Assert.True(after.IsCompressed); @@ -338,7 +339,7 @@ public async Task TheCompressHalf_IsRetriedAfterABusyLock_AndSucceedsOnALaterTry await holder.ReleaseAsync(ct); var compressed = await compress; - Assert.True(compressed); + Assert.Equal(TimescaleSupport.PerfmonRegroupChunkResult.Regrouped, compressed); Assert.Equal(1, logger.Lines.Count(line => line.Contains("not changed this pass", StringComparison.Ordinal))); Assert.Equal(0, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); var after = (await ReadChunksAsync(connection, ct)).Single(c => c.Name == chunk.Name); @@ -368,7 +369,7 @@ public async Task WhenEveryCompressTryIsBusy_TheChunkIsLeftToThePolicy_WithOneWa await ExecAsync(connection, $"SELECT decompress_chunk('{chunk.Name}')", ct); await using var holder = await HoldLockAsync(scratch.ConnectionString, chunk.Name, ct); var logger = new CapturingTestLogger(); - Assert.False(await TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.Zero, ct)); + Assert.Equal(TimescaleSupport.PerfmonRegroupChunkResult.LeftUncompressed, await TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.Zero, ct)); await holder.ReleaseAsync(ct); Assert.Equal(3, logger.Lines.Count(line => line.Contains("not changed this pass", StringComparison.Ordinal))); @@ -469,17 +470,22 @@ static async Task TimeReadAsync(NpgsqlConnection readConnection, Cance return clock.Elapsed; } - var baseline = TimeSpan.Zero; + /* The baseline is the MEDIAN of the warm reads (#5574, check round 2): the first read after the compress is cold (plan, + buffers) and is dropped, and one slow outlier must not lift the baseline, because the stall this test guards is a + lock wait of about 3 s on top of a warm read, and a baseline raised by 0.5 s lets it through. */ + var warm = new List(); using (var baselineConnection = new NpgsqlConnection(scratch.ConnectionString)) { await baselineConnection.OpenAsync(ct); + await TimeReadAsync(baselineConnection, ct); for (var i = 0; i < 5; i++) { - var took = await TimeReadAsync(baselineConnection, ct); - baseline = took > baseline ? took : baseline; + warm.Add(await TimeReadAsync(baselineConnection, ct)); } } + var baseline = warm.OrderBy(took => took).ElementAt(warm.Count / 2); + var stop = false; var slowest = TimeSpan.Zero; var reads = 0; @@ -651,7 +657,8 @@ public async Task ADecompressThatHitsTheStatementCap_IsNotTriedAgainForTheLifeOf Assert.Equal(4, first.Done); Assert.Equal(1, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); - Assert.Single(logger.Lines, line => line.Contains("could not be decompressed within 2 s", StringComparison.Ordinal) && line.Contains(held.Name, StringComparison.Ordinal)); + Assert.Single(logger.Lines, line => line.Contains("could not be decompressed within 2 s", StringComparison.Ordinal) && line.Contains("hit the statement cap after", StringComparison.Ordinal) && line.Contains(held.Name, StringComparison.Ordinal)); + Assert.DoesNotContain(logger.Lines, line => line.Contains("cancelled by the server", StringComparison.Ordinal)); Assert.Equal(OldChunkSegmentBy, (await ReadChunksAsync(connection, ct)).Single(chunk => chunk.Name == held.Name).SegmentBy); var linesBefore = logger.Lines.Count; @@ -663,6 +670,51 @@ public async Task ADecompressThatHitsTheStatementCap_IsNotTriedAgainForTheLifeOf TimescaleSupport.BusyStreaks.Reset(); } + /// + /// A decompress the SERVER cancels before the 30-minute cap (a short statement_timeout on the role, a cancel from + /// another session) is still not tried again until the restart, so a short server timeout does not cost a rewrite every hour, + /// but the log tells the truth about it (#5574, check round 2): "cancelled by the server" with the real elapsed time, not + /// "could not be decompressed within 1800 s". The session's statement_timeout is 2 s here, under the 3 s lock wait the + /// held chunk gives, so the server cancels first and the cap (the default 1800 s) is nowhere near. + /// + [Fact] + public async Task ADecompressTheServerCancelsBeforeTheCap_IsNotTriedAgain_AndTheLogSaysTheServerDidIt() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + TimescaleSupport.BusyStreaks.Reset(); + + var held = ChunkOfDay(await ReadChunksAsync(connection, ct), 1); + var stub = new TimescaleSupport.PerfmonRegroupRead( + TimescaleSupport.PerfmonRegroupReadStatus.Candidates, + new[] { new TimescaleSupport.PerfmonRegroupCandidate(held.Name, OldChunkSegmentBy) }, null); + var drainConnection = new NpgsqlConnectionStringBuilder(scratch.ConnectionString) { Options = "-c statement_timeout=2000" }.ConnectionString; + await using var holder = await HoldLockAsync(scratch.ConnectionString, held.Name, ct); + var logger = new CapturingTestLogger(); + var drain = NewDrain(drainConnection, logger, TimeSpan.Zero, new List(), readCandidates: FixedRead(stub)); + var first = await RunDetailedBoundedAsync(drain, 60, ct); + await holder.ReleaseAsync(ct); + + Assert.Equal(0, first.Done); + Assert.Single(logger.Lines, line => line.Contains("cancelled by the server", StringComparison.Ordinal) + && line.Contains(held.Name, StringComparison.Ordinal) && line.Contains("before the 1800 s statement cap", StringComparison.Ordinal)); + Assert.DoesNotContain(logger.Lines, line => line.Contains("could not be decompressed within", StringComparison.Ordinal) || line.Contains("hit the statement cap", StringComparison.Ordinal)); + Assert.Equal(OldChunkSegmentBy, (await ReadChunksAsync(connection, ct)).Single(chunk => chunk.Name == held.Name).SegmentBy); + + /* Not tried again while the process lives, though the stub keeps answering with it. */ + var linesBefore = logger.Lines.Count; + var second = await RunDetailedBoundedAsync(drain, 60, ct); + Assert.Equal(0, second.Done); + Assert.Equal(PerfmonRegroupRunEnd.AllSkipped, second.End); + Assert.DoesNotContain(logger.Lines.Skip(linesBefore), line => line.Contains("(decompress)", StringComparison.Ordinal)); + TimescaleSupport.BusyStreaks.Reset(); + } + /// /// The compress half retries ONLY a busy lock (#5574, M2): a statement that ran into its cap ends the tries at once, with the /// statement's own Warning and no second one, instead of three whole compressions. @@ -683,7 +735,7 @@ public async Task TheCompressHalf_IsNotRetriedAfterAnythingButABusyLock() await ExecAsync(connection, $"SELECT decompress_chunk('{chunk.Name}')", ct); await using var holder = await HoldLockAsync(scratch.ConnectionString, chunk.Name, ct); var logger = new CapturingTestLogger(); - Assert.False(await TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.Zero, ct, statementTimeoutSeconds: 1)); + Assert.Equal(TimescaleSupport.PerfmonRegroupChunkResult.LeftUncompressed, await TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.Zero, ct, statementTimeoutSeconds: 1)); await holder.ReleaseAsync(ct); Assert.Equal(1, logger.Lines.Count(line => line.Contains("(compress) could not be changed", StringComparison.Ordinal))); @@ -768,8 +820,12 @@ public async Task AChunkThatIsGoneAtDecompressTime_IsSkippedQuietly_NotFailed() await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); - var gone = new TimescaleSupport.PerfmonRegroupCandidate("_timescaledb_internal._hyper_99999_99999_chunk", OldChunkSegmentBy); - var stub = new TimescaleSupport.PerfmonRegroupRead(TimescaleSupport.PerfmonRegroupReadStatus.Candidates, new[] { gone }, null); + /* THREE gone chunks (the failure limit is three in a row): a gone chunk that counted as a failure would end the run at the + third, and the run would end FailureLimit with a Warning instead of getting past all three (#5574, check round 2). */ + var gone = Enumerable.Range(1, 3) + .Select(n => new TimescaleSupport.PerfmonRegroupCandidate($"_timescaledb_internal._hyper_99999_{n}_chunk", OldChunkSegmentBy)) + .ToArray(); + var stub = new TimescaleSupport.PerfmonRegroupRead(TimescaleSupport.PerfmonRegroupReadStatus.Candidates, gone, null); var logger = new CapturingTestLogger(); var run = await RunDetailedBoundedAsync(NewDrain(scratch.ConnectionString, logger, TimeSpan.Zero, new List(), readCandidates: FixedRead(stub)), 30, ct); @@ -777,6 +833,53 @@ public async Task AChunkThatIsGoneAtDecompressTime_IsSkippedQuietly_NotFailed() Assert.Equal(PerfmonRegroupRunEnd.AllSkipped, run.End); Assert.Equal(0, logger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); Assert.DoesNotContain(logger.Lines, line => line.Contains("in a row could not be re-grouped", StringComparison.Ordinal)); + foreach (var candidate in gone) + { + Assert.Contains(logger.Lines, line => line.StartsWith("Debug:", StringComparison.Ordinal) + && line.Contains(candidate.Chunk, StringComparison.Ordinal) && line.Contains("no longer exists", StringComparison.Ordinal)); + } + } + + /// + /// A chunk that is gone by the compress half is Gone too, not "left for the policy" (#5574, check round 2): no Warning, no + /// "stays uncompressed until the compression policy compresses it" line (there is nothing to compress). And a 42P01 on a chunk the + /// catalog still lists is a Failed chunk with a Warning, never Gone. + /// + [Fact] + public async Task ARelationErrorIsGoneOnlyWhenTheChunkCatalogAgrees_AtEitherHalf() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + TimescaleSupport.BusyStreaks.Reset(); + + /* The compress half on a chunk that is not there. */ + var goneLogger = new CapturingTestLogger(); + var result = await TimescaleSupport.CompressRegroupedChunkAsync( + connection, goneLogger, "_timescaledb_internal._hyper_99999_9_chunk", 3, TimeSpan.Zero, ct); + Assert.Equal(TimescaleSupport.PerfmonRegroupChunkResult.Gone, result); + Assert.Equal(0, goneLogger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); + Assert.DoesNotContain(goneLogger.Lines, line => line.Contains("compression policy", StringComparison.Ordinal)); + Assert.Single(goneLogger.Lines, line => line.StartsWith("Debug:", StringComparison.Ordinal) && line.Contains("no longer exists (compress half;", StringComparison.Ordinal)); + + /* The same relation error on a chunk the catalog still lists: Failed, with a Warning that says why. */ + var listed = ChunkOfDay(await ReadChunksAsync(connection, ct), 2); + foreach (var half in new[] { "decompress", "compress" }) + { + var listedLogger = new CapturingTestLogger(); + var listedResult = await TimescaleSupport.ResolveMissingRelationAsync(connection, listedLogger, listed.Name, half, ct); + Assert.Equal(TimescaleSupport.PerfmonRegroupChunkResult.Failed, listedResult); + Assert.Equal(1, listedLogger.CountAtLevel(Microsoft.Extensions.Logging.LogLevel.Warning)); + Assert.Single(listedLogger.Lines, line => line.StartsWith("Warning:", StringComparison.Ordinal) + && line.Contains(half, StringComparison.Ordinal) && line.Contains("still lists the chunk", StringComparison.Ordinal)); + } + + var goneDirect = await TimescaleSupport.ResolveMissingRelationAsync(connection, null, "_timescaledb_internal._hyper_99999_9_chunk", "decompress", ct); + Assert.Equal(TimescaleSupport.PerfmonRegroupChunkResult.Gone, goneDirect); } /// @@ -796,15 +899,29 @@ public async Task TheReach_IsClampedToTheRetentionLessADay() await ExecAsync(connection, "INSERT INTO config.config_collector_schedules (server_id, collector_name, retention_days) VALUES (NULL, 'perfmon_stats', 4)", ct); - var run = await RunDetailedBoundedAsync(NewDrain(scratch.ConnectionString, new CapturingTestLogger(), TimeSpan.Zero, new List()), 60, ct); - - Assert.Equal(3, run.Done); - var after = await ReadChunksAsync(connection, ct); - foreach (var daysBack in new[] { 1, 2, 3 }) + /* The expected chunks come from the DATABASE clock, read here (#5574, check round 2): the reach is "ends within 3 days of + now()", and the day-3 chunk drops out of it at midnight UTC, so a count of 3 fixed when the class loaded fails a run that + crosses midnight between the class start and this test. The chunks themselves are named by the seeded days. */ + var expected = new List(); + using (var inReach = new NpgsqlCommand( + @"SELECT format('%I.%I', chunk_schema, chunk_name) FROM timescaledb_information.chunks + WHERE hypertable_schema = 'collect' AND hypertable_name = 'perfmon_stats' AND is_compressed + AND range_end > now() - make_interval(days => 3)", connection)) + await using (var names = await inReach.ExecuteReaderAsync(ct)) { - Assert.Equal(WantedChunkSegmentBy, after.Single(chunk => chunk.Name == ChunkOfDay(after, daysBack).Name).SegmentBy); + while (await names.ReadAsync(ct)) + { + expected.Add(names.GetString(0)); + } } + Assert.InRange(expected.Count, 2, 3); + var run = await RunDetailedBoundedAsync(NewDrain(scratch.ConnectionString, new CapturingTestLogger(), TimeSpan.Zero, new List()), 60, ct); + + Assert.Equal(expected.Count, run.Done); + var after = await ReadChunksAsync(connection, ct); + Assert.All(after.Where(chunk => expected.Contains(chunk.Name)), chunk => Assert.Equal(WantedChunkSegmentBy, chunk.SegmentBy)); + Assert.All(after.Where(chunk => !expected.Contains(chunk.Name) && chunk.IsCompressed), chunk => Assert.Equal(OldChunkSegmentBy, chunk.SegmentBy)); Assert.Equal(OldChunkSegmentBy, ChunkOfDay(after, 4).SegmentBy); Assert.Equal(OldChunkSegmentBy, ChunkOfDay(after, 5).SegmentBy); } diff --git a/Darling/PerformanceMonitor.Darling.Storage/PerfmonRegroupDrain.cs b/Darling/PerformanceMonitor.Darling.Storage/PerfmonRegroupDrain.cs index 97cbeb0d89..b503b8d5f1 100644 --- a/Darling/PerformanceMonitor.Darling.Storage/PerfmonRegroupDrain.cs +++ b/Darling/PerformanceMonitor.Darling.Storage/PerfmonRegroupDrain.cs @@ -64,8 +64,9 @@ internal enum PerfmonRegroupRunEnd /// /// What it remembers for the life of the process (the drain object lives as long as the service): the chunks it /// re-grouped, so a chunk that still reads as a candidate afterwards (a TimescaleDB release that spells the setting -/// differently) is skipped with one Warning instead of rewritten forever; the chunks whose decompress hit the statement cap -/// (), which would hit it every hour; and that a failed +/// differently) is skipped with one Warning instead of rewritten forever; the chunks whose decompress was cancelled, by the statement cap +/// () or by the server (a statement_timeout shorter +/// than the cap, or a cancel), which would be cancelled again every hour (the log line says which and how long it ran); and that a failed /// catalog read has been reported once at Warning. /// /// Gated exactly as the first version was: is asked @@ -264,14 +265,29 @@ and the store was just as busy as after a good one. */ break; case TimescaleSupport.PerfmonRegroupChunkResult.TimedOut: - /* The decompress ran into its statement cap. The same chunk would run into it at every hourly start, - so it is left alone while this process lives. The statement's own Warning has said why. */ + /* The decompress was cancelled: by its own cap, or by the server (a statement_timeout on the role or database, + or someone's cancel). Either way the same chunk would be cancelled at every hourly start, and a rewrite + costs minutes, so it is left alone while this process lives. The statement's own Warning has said why; + this line says which of the two it was and how long it really ran (#5574). */ skipped.Add(chunk); _gaveUp.Add(chunk); failuresInARow++; - _logger?.LogInformation( - "TimescaleDB: perfmon_stats chunk {Chunk} could not be decompressed within {Seconds} s, so it is not tried again until the service restarts (#5574)", - chunk, _statementTimeoutSeconds); + var ranSeconds = (int)outcome.Elapsed.TotalSeconds; + /* A second of slack: the client's timer runs from the command's start, a timer can fire a few + milliseconds early, and a server cancel inside the last second is the cap for every practical purpose. */ + if (outcome.Elapsed >= TimeSpan.FromSeconds(_statementTimeoutSeconds - 1)) + { + _logger?.LogInformation( + "TimescaleDB: perfmon_stats chunk {Chunk} could not be decompressed within {Seconds} s (it hit the statement cap after {Ran} s), so it is not tried again until the service restarts (#5574)", + chunk, _statementTimeoutSeconds, ranSeconds); + } + else + { + _logger?.LogInformation( + "TimescaleDB: perfmon_stats chunk {Chunk} was cancelled by the server (a statement_timeout or a cancel) after {Ran} s, before the {Seconds} s statement cap, so it is not tried again until the service restarts (#5574)", + chunk, ranSeconds, _statementTimeoutSeconds); + } + break; default: diff --git a/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs b/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs index 3197229fec..9932ebe20d 100644 --- a/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs +++ b/Darling/PerformanceMonitor.Darling.Storage/TimescaleSupport.cs @@ -10930,9 +10930,10 @@ internal static async Task TryRunBoundedDdlAsync( catch (PostgresException ex) when (distinguishTimeoutAndMissing && string.Equals(ex.SqlState, PostgresErrorCodes.UndefinedTable, StringComparison.Ordinal)) { - /* #5574: the chunk was dropped (retention) between the candidates read and the statement. Nothing to do. */ + /* #5574: probably a chunk dropped (retention) between the candidates read and the statement; the caller re-reads the + chunk catalog to tell (ResolveMissingRelationAsync), because a chunk that still exists is a failure. */ BusyStreaks.Clear(what, out _); - logger?.LogDebug("TimescaleDB: {What} skipped: the relation no longer exists ({Message})", what, ex.Message); + logger?.LogDebug("TimescaleDB: {What} stopped: the server reported that a relation does not exist ({Message})", what, ex.Message); return BoundedDdlOutcome.RelationMissing; } catch (Exception ex) when (ex is not OperationCanceledException) @@ -12372,12 +12373,12 @@ internal enum PerfmonRegroupChunkResult /// The decompress failed and rolled back, so nothing changed. Failed, - /// The decompress ran into its statement cap () and rolled - /// back, so nothing changed. The drain does not try the chunk again while the process lives. + /// The decompress was cancelled, by its statement cap () or by + /// the server (a shorter statement_timeout, a cancel), and rolled back, so nothing changed. The drain does not try the chunk again while the process lives. TimedOut, - /// The chunk was gone (retention dropped it) when the decompress asked for it, so nothing changed and - /// nothing failed. + /// The chunk was gone (retention dropped it; the chunk catalog confirmed it) when the decompress, or the + /// compress after it, asked for it, so nothing failed and there is nothing left to do. Gone, /// The decompress committed and the compress did not (a busy lock on every try, a failure, or the @@ -12554,7 +12555,7 @@ internal static async Task RegroupPerfmonChunkAsync( { BoundedDdlOutcome.LockBusy => PerfmonRegroupChunkResult.LockBusy, BoundedDdlOutcome.TimedOut => PerfmonRegroupChunkResult.TimedOut, - BoundedDdlOutcome.RelationMissing => PerfmonRegroupChunkResult.Gone, + BoundedDdlOutcome.RelationMissing => await ResolveMissingRelationAsync(connection, logger, chunk, "decompress", cancellationToken), _ => PerfmonRegroupChunkResult.Failed, }, 0, clock.Elapsed); @@ -12572,21 +12573,63 @@ internal static async Task RegroupPerfmonChunkAsync( logger?.LogDebug("TimescaleDB: could not count the rows of perfmon_stats chunk {Chunk} before compressing it again: {Message}", chunk, ex.Message); } - if (await CompressRegroupedChunkAsync(connection, logger, chunk, PerfmonRegroupCompressAttempts, PerfmonRegroupCompressRetryDelay, cancellationToken, statementTimeoutSeconds)) + var compressResult = await CompressRegroupedChunkAsync(connection, logger, chunk, PerfmonRegroupCompressAttempts, PerfmonRegroupCompressRetryDelay, cancellationToken, statementTimeoutSeconds); + if (compressResult == PerfmonRegroupChunkResult.Regrouped) { logger?.LogInformation( "TimescaleDB: re-grouped perfmon_stats chunk {Chunk} ({Rows} rows) from '{Old}' to '{New}' in {ElapsedMs} ms (#5574)", chunk, rows, candidate.OldSegmentBy ?? "(none)", PerfmonStatsChunkSegmentBy, clock.ElapsedMilliseconds); - return new PerfmonRegroupChunkOutcome(PerfmonRegroupChunkResult.Regrouped, rows, clock.Elapsed); } - return new PerfmonRegroupChunkOutcome(PerfmonRegroupChunkResult.LeftUncompressed, rows, clock.Elapsed); + return new PerfmonRegroupChunkOutcome(compressResult, rows, clock.Elapsed); + } + + /// + /// What a "relation does not exist" (42P01) from either half of a chunk's re-group means (#5574): the chunk catalog is read + /// again, and only a chunk that is really gone (retention dropped it between the half before and this one) is + /// , which costs a Debug line and no failure. A chunk the catalog still lists did + /// not fail for that reason (a name or quoting bug, a catalog that disagrees with itself), so it is a + /// chunk with a Warning. A catalog that cannot be read is no proof of + /// anything and counts as Failed too. + /// + internal static async Task ResolveMissingRelationAsync( + NpgsqlConnection connection, ILogger? logger, string chunk, string half, CancellationToken cancellationToken) + { + bool? listed; + try + { + using var read = new NpgsqlCommand( + @"SELECT EXISTS (SELECT 1 FROM timescaledb_information.chunks AS c +WHERE c.hypertable_schema = 'collect' AND c.hypertable_name = 'perfmon_stats' +AND format('%I.%I', c.chunk_schema, c.chunk_name) = $1)", + connection) { CommandTimeout = JobCatalogReadTimeoutSeconds }; + read.Parameters.AddWithValue(chunk); + listed = (bool?)await read.ExecuteScalarAsync(cancellationToken); + } + catch (Exception ex) when (ex is not OperationCanceledException) + { + logger?.LogDebug("TimescaleDB: could not re-read the chunk catalog for perfmon_stats chunk {Chunk}: {Message}", chunk, ex.Message); + listed = null; + } + + if (listed == false) + { + logger?.LogDebug("TimescaleDB: perfmon_stats chunk {Chunk} no longer exists ({Half} half; retention dropped it), so it is not re-grouped (#5574)", chunk, half); + return PerfmonRegroupChunkResult.Gone; + } + + logger?.LogWarning( + "TimescaleDB: the {Half} of perfmon_stats chunk {Chunk} reported that a relation does not exist, but {Catalog}, so this is a failure and not a chunk that retention dropped (#5574)", + half, chunk, listed == true ? "the chunk catalog still lists the chunk" : "the chunk catalog could not be read to tell"); + return PerfmonRegroupChunkResult.Failed; } /// /// The compress half of a chunk's re-group (#5574): the chunk was decompressed in a transaction that has committed, /// so it is uncompressed now and a busy lock is worth tries, - /// apart, each behind the 3 s lock timeout. Returns whether the chunk is compressed again. When every try failed the + /// apart, each behind the 3 s lock timeout. Returns when the chunk is compressed again, + /// when the chunk is really gone (retention dropped it between the halves), + /// and otherwise. When every try failed the /// chunk stays uncompressed, with one Warning, and the compression policy compresses it with the hypertable's grouping /// at its next run. if_not_compressed makes a policy run that got there first a success, not an error. /// A cancellation (the service stopping) leaves the chunk the same way, says so at Information, and propagates. @@ -12596,7 +12639,7 @@ internal static async Task RegroupPerfmonChunkAsync( /// 30 minutes) is another whole compression. The busy tries are not fed to : three tries inside /// ten seconds are not "three passes", and the Warning below is the one line an all-busy half logs. /// - internal static async Task CompressRegroupedChunkAsync( + internal static async Task CompressRegroupedChunkAsync( NpgsqlConnection connection, ILogger? logger, string chunk, int attempts, TimeSpan retryDelay, CancellationToken cancellationToken, int statementTimeoutSeconds = PerfmonRegroupStatementTimeoutSeconds) { @@ -12617,17 +12660,25 @@ internal static async Task CompressRegroupedChunkAsync( if (compressed == BoundedDdlOutcome.Applied) { - return true; + return PerfmonRegroupChunkResult.Regrouped; + } + + if (compressed == BoundedDdlOutcome.RelationMissing + && await ResolveMissingRelationAsync(connection, logger, chunk, "compress", cancellationToken) == PerfmonRegroupChunkResult.Gone) + { + /* Retention dropped the chunk between the two halves: there is nothing for the policy to compress, and + nothing failed (a chunk the catalog still lists is the Warning above, and stays uncompressed). */ + return PerfmonRegroupChunkResult.Gone; } if (compressed != BoundedDdlOutcome.LockBusy) { - /* Not a busy lock (an error, the cap, a chunk that is gone): the line above says why, and the chunk is - the compression policy's. */ + /* Not a busy lock (an error, the cap, a relation error on a chunk that still exists): the line above says + why, and the chunk is the compression policy's. */ logger?.LogInformation( "TimescaleDB: perfmon_stats chunk {Chunk} was decompressed for re-grouping and compressing it again did not work ({Outcome}), so it stays uncompressed until the compression policy compresses it with '{New}' at its next run (#5574)", chunk, compressed, PerfmonStatsChunkSegmentBy); - return false; + return PerfmonRegroupChunkResult.LeftUncompressed; } if (attempt < attempts) @@ -12647,7 +12698,7 @@ the compression policy's. */ logger?.LogWarning( "TimescaleDB: perfmon_stats chunk {Chunk} was decompressed for re-grouping but could not be compressed again after {Attempts} tries, so it stays uncompressed until the compression policy compresses it with '{New}' at its next run; reads of it use the heap and its indexes meanwhile (#5574)", chunk, attempts, PerfmonStatsChunkSegmentBy); - return false; + return PerfmonRegroupChunkResult.LeftUncompressed; } /* ---------------- compression-job self-heal (#1581) ---------------- */ From 9b9ce22337cc24f3482766e334573ce655831e01 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Thu, 8 Oct 2026 20:43:23 -0400 Subject: [PATCH 7/7] get_perfmon_trend reaches 30 days on the web and MCP; the two timed re-group tests run in the timing collection (#5574) --- .../PerfmonRegroupLiveSupport.cs | 188 +++++++++++ .../Darling.Tests/PerfmonRegroupLiveTests.cs | 297 +----------------- .../PerfmonRegroupTimingLiveTests.cs | 168 ++++++++++ .../Darling.Tests/WebReadReachLiveTests.cs | 5 +- Darling/Darling.Tests/WebReadReachTests.cs | 20 +- .../Mcp/DarlingMcpTrendTools.cs | 10 +- .../WebReadReach.cs | 9 +- 7 files changed, 391 insertions(+), 306 deletions(-) create mode 100644 Darling/Darling.Tests/PerfmonRegroupLiveSupport.cs create mode 100644 Darling/Darling.Tests/PerfmonRegroupTimingLiveTests.cs diff --git a/Darling/Darling.Tests/PerfmonRegroupLiveSupport.cs b/Darling/Darling.Tests/PerfmonRegroupLiveSupport.cs new file mode 100644 index 0000000000..28364660b2 --- /dev/null +++ b/Darling/Darling.Tests/PerfmonRegroupLiveSupport.cs @@ -0,0 +1,188 @@ +/* + * 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.Linq; +using System.Threading; +using System.Threading.Tasks; +using Npgsql; +using PerformanceMonitor.Darling.Storage; +using Xunit; + +namespace Darling.Tests; + +/* #1776 own-store: this class holds no test; it is the fixture code that PerfmonRegroupLiveTests and + PerfmonRegroupTimingLiveTests share, and every test that uses it mints its own scratch database through + ScratchPostgres, so neither class touches the shared store. */ + +/// +/// The scratch-store helpers that the perfmon_stats re-group live tests share (#5574): the old-grouping store builder, the +/// chunk catalog read, and the held chunk lock. keeps the tests that judge the +/// drain's results; holds the two that judge a time against a limit and so run +/// in the timing collection. +/// +internal static class PerfmonRegroupLiveSupport +{ + + internal const string OldChunkSegmentBy = "server_id"; + internal const long IdBase = -495_200_000_000L; + + /// "Now" for every day the tests seed, name and compare, captured ONCE: a run that crosses midnight UTC between a + /// seed and a lookup must not move the day a chunk is looked up by. The database's own clock decides the reach, which has + /// days of slack on both sides of the seeded chunks in every test but TheReach_IsClampedToTheRetentionLessADay; that + /// one reads the chunks in its reach from now() itself. + internal static readonly DateTime RunStartUtc = DateTime.UtcNow; + + internal sealed record ChunkRow(string Name, bool IsCompressed, string SegmentBy, DateTime Start); + + internal static string RequireLivePostgres() + { + var connectionString = Environment.GetEnvironmentVariable("DARLING_TEST_PG"); + Assert.SkipWhen(string.IsNullOrEmpty(connectionString), + "Set DARLING_TEST_PG to a Postgres connection string to run the perfmon_stats re-group tests (each mints its own scratch database)."); + return connectionString!; + } + + /// + /// perfmon_stats as every build before #5574 left it: a hypertable compressed by server_id alone, five daily + /// chunks inside the reach (yesterday back to five days ago) and one 45 days back, all compressed. Skips on a TimescaleDB + /// without the per-chunk settings view (before 2.14.1), which these tests read. + /// + internal static async Task BuildOldStoreAsync(NpgsqlConnection connection, string connectionString, CancellationToken ct) + { + await PgMigrations.MigrateAsync(connection, ct); + Assert.SkipUnless(await LiveTimescaleProbe.TryEnableAsync(connectionString, ct), "TimescaleDB is not available on this cluster."); + await ExecAsync(connection, "SELECT _timescaledb_functions.stop_background_workers()", ct); + Assert.SkipUnless( + await ScalarAsync(connection, "SELECT to_regclass('timescaledb_information.chunk_compression_settings') IS NOT NULL", ct), + "this TimescaleDB has no timescaledb_information.chunk_compression_settings (before 2.14.1)."); + + await ExecAsync(connection, TimescaleSupport.CreateHypertableSql(TimescaleSupport.PerfmonStatsTable, "collection_time"), ct); + await ExecAsync(connection, "ALTER TABLE perfmon_stats SET (timescaledb.compress, timescaledb.compress_segmentby = 'server_id')", ct); + + var today = DateTime.SpecifyKind(RunStartUtc.Date, DateTimeKind.Unspecified); + foreach (var daysBack in new[] { 1, 2, 3, 4, 5, 45 }) + { + await SeedDayAsync(connection, today.AddDays(-daysBack), daysBack, ct); + } + + var chunks = new List(); + using (var list = new NpgsqlCommand( + "SELECT format('%I.%I', chunk_schema, chunk_name) FROM timescaledb_information.chunks " + + "WHERE hypertable_schema = 'collect' AND hypertable_name = 'perfmon_stats' AND NOT is_compressed AND range_end <= now()", connection)) + await using (var reader = await list.ExecuteReaderAsync(ct)) + { + while (await reader.ReadAsync(ct)) + { + chunks.Add(reader.GetString(0)); + } + } + + foreach (var chunk in chunks) + { + await ExecAsync(connection, $"SELECT compress_chunk('{chunk}')", ct); + } + } + + /// Two servers, four counters, two instances each, a sample every 30 minutes: 768 rows for the day. + internal static async Task SeedDayAsync(NpgsqlConnection connection, DateTime day, int salt, CancellationToken ct) + { + using var command = new NpgsqlCommand( + @"INSERT INTO perfmon_stats (collection_id, collection_time, server_id, server_name, object_name, counter_name, instance_name, cntr_value, delta_cntr_value, sample_interval_seconds, cntr_type) + SELECT $1 - $3 * 100000 - row_number() OVER (), g.t AT TIME ZONE 'UTC', s.id, 'REGROUP-SRV', 'SQLServer:Test', 'Counter ' || c.n, + CASE WHEN i.i = 0 THEN '' ELSE 'inst' || i.i END, + (extract(epoch FROM g.t)::bigint / 60 + s.id + c.n * 7 + i.i) % 100000, (extract(epoch FROM g.t)::bigint / 60 + c.n) % 50, 60, 65792 + FROM generate_series($2::timestamp, $2::timestamp + INTERVAL '23 hours 30 minutes', INTERVAL '30 minutes') AS g(t) + CROSS JOIN generate_series(1, 2) AS s(id) + CROSS JOIN generate_series(1, 4) AS c(n) + CROSS JOIN generate_series(0, 1) AS i(i)", connection); + command.Parameters.AddWithValue(IdBase); + command.Parameters.AddWithValue(day); + command.Parameters.AddWithValue(salt); + await command.ExecuteNonQueryAsync(ct); + } + + internal static async Task> ReadChunksAsync(NpgsqlConnection connection, CancellationToken ct) + { + using var command = new NpgsqlCommand( + @"SELECT format('%I.%I', c.chunk_schema, c.chunk_name), c.is_compressed, coalesce(s.segmentby, ''), (c.range_start AT TIME ZONE 'UTC') + FROM timescaledb_information.chunks AS c + LEFT JOIN timescaledb_information.chunk_compression_settings AS s ON s.chunk = to_regclass(format('%I.%I', c.chunk_schema, c.chunk_name)) + WHERE c.hypertable_schema = 'collect' AND c.hypertable_name = 'perfmon_stats' + ORDER BY c.range_start DESC", connection); + var chunks = new List(); + await using var reader = await command.ExecuteReaderAsync(ct); + while (await reader.ReadAsync(ct)) + { + chunks.Add(new ChunkRow(reader.GetString(0), reader.GetBoolean(1), reader.GetString(2), DateTime.SpecifyKind(reader.GetDateTime(3), DateTimeKind.Utc))); + } + + return chunks; + } + + internal static async Task ExecAsync(NpgsqlConnection connection, string sql, CancellationToken ct) + { + using var command = new NpgsqlCommand(sql, connection); + await command.ExecuteNonQueryAsync(ct); + } + + internal static async Task ScalarAsync(NpgsqlConnection connection, string sql, CancellationToken ct) + { + using var command = new NpgsqlCommand(sql, connection); + var value = await command.ExecuteScalarAsync(ct); + return (T)Convert.ChangeType(value!, typeof(T), System.Globalization.CultureInfo.InvariantCulture); + } + + internal static ChunkRow ChunkOfDay(List chunks, int daysBack) => + chunks.Single(chunk => chunk.Start.Date == RunStartUtc.Date.AddDays(-daysBack)); + + /// Another session holds ROW EXCLUSIVE on the chunk inside an open transaction, which conflicts with the + /// EXCLUSIVE lock both halves of the re-group ask for. + internal static async Task HoldLockAsync(string connectionString, string chunk, CancellationToken ct) + { + var holder = new NpgsqlConnection(connectionString); + await holder.OpenAsync(ct); + await ExecAsync(holder, "BEGIN", ct); + await ExecAsync(holder, $"LOCK TABLE {chunk} IN ROW EXCLUSIVE MODE", ct); + return new HeldLock(holder); + } + + /// The session that holds a chunk's lock; released by or, at the latest, when + /// the test's scope ends. + internal sealed class HeldLock : IAsyncDisposable + { + private NpgsqlConnection? _connection; + + public HeldLock(NpgsqlConnection connection) => _connection = connection; + + public async Task ReleaseAsync(CancellationToken ct) + { + var connection = Interlocked.Exchange(ref _connection, null); + if (connection is not null) + { + await ExecAsync(connection, "ROLLBACK", ct); + await connection.DisposeAsync(); + } + } + + public async ValueTask DisposeAsync() + { + var connection = Interlocked.Exchange(ref _connection, null); + if (connection is not null) + { + await connection.DisposeAsync(); + } + } + } + + internal static async Task RequirePerChunkSettingsAsync(NpgsqlConnection connection, CancellationToken ct) => + Assert.SkipUnless( + await ScalarAsync(connection, "SELECT to_regclass('timescaledb_information.chunk_compression_settings') IS NOT NULL", ct), + "this TimescaleDB has no timescaledb_information.chunk_compression_settings (before 2.14.1)."); +} diff --git a/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs b/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs index bfd7a4bb72..c566a5e48a 100644 --- a/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs +++ b/Darling/Darling.Tests/PerfmonRegroupLiveTests.cs @@ -15,6 +15,7 @@ using Npgsql; using PerformanceMonitor.Darling.Storage; using Xunit; +using static Darling.Tests.PerfmonRegroupLiveSupport; namespace Darling.Tests; @@ -29,16 +30,6 @@ namespace Darling.Tests; public sealed class PerfmonRegroupLiveTests { private const string WantedChunkSegmentBy = "server_id,counter_name"; - private const string OldChunkSegmentBy = "server_id"; - private const long IdBase = -495_200_000_000L; - - /// "Now" for every day the tests seed, name and compare, captured ONCE: a run that crosses midnight UTC between a - /// seed and a lookup must not move the day a chunk is looked up by. The database's own clock decides the reach, which has - /// days of slack on both sides of the seeded chunks in every test but TheReach_IsClampedToTheRetentionLessADay; that - /// one reads the chunks in its reach from now() itself. - private static readonly DateTime RunStartUtc = DateTime.UtcNow; - - private sealed record ChunkRow(string Name, bool IsCompressed, string SegmentBy, DateTime Start); /// /// The upgraded store converges: with the hypertable already on the new grouping, the drain re-groups the chunks inside @@ -120,7 +111,10 @@ public async Task AFreshStore_CompressesItsFirstChunksWithTheNewGrouping_AndTheD Assert.Equal("server_id, counter_name", await HypertableSegmentByAsync(connection, ct)); var today = DateTime.SpecifyKind(RunStartUtc.Date, DateTimeKind.Unspecified); - foreach (var daysBack in new[] { 2, 3, 4 }) + /* Three to five days back, not two to four: perfmon_stats compresses after 1 day plus its heavy-table offset hours + (TimescaleSupport.CompressAfterFor), so the chunk of two days back is not yet old enough in the first hours after + midnight UTC, and the policy rightly leaves it alone. From three days back every chunk is due at any hour. */ + foreach (var daysBack in new[] { 3, 4, 5 }) { await SeedDayAsync(connection, today.AddDays(-daysBack), daysBack, ct); } @@ -415,110 +409,6 @@ public async Task AOneCounterRead_FiltersTheCompressedChunkOnBothSegmentColumns_ Assert.Contains("counter_name", after, StringComparison.Ordinal); } - /// - /// A reader beside the re-group of a chunk of about 1.5 M rows never waits more than a few seconds (#5574; the bound is 2.5 s, against 0.1 to 0.2 s measured with two transactions and 4.9 s of a 10.3 s re-group with one): the - /// decompress holds only a lock that lets reads go on, and the ACCESS EXCLUSIVE it takes at its end is released by - /// its own commit, before the compress half starts. The same re-group in ONE transaction made the reader wait for - /// the whole compress half. - /// - [Fact] - public async Task AReaderBesideTheReGroupOfALargeChunk_NeverWaitsMoreThanAFewSeconds() - { - var connectionString = RequireLivePostgres(); - var ct = TestContext.Current.CancellationToken; - await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); - using var connection = new NpgsqlConnection(scratch.ConnectionString); - await connection.OpenAsync(ct); - await PgMigrations.MigrateAsync(connection, ct); - Assert.SkipUnless(await LiveTimescaleProbe.TryEnableAsync(scratch.ConnectionString, ct), "TimescaleDB is not available on this cluster."); - await ExecAsync(connection, "SELECT _timescaledb_functions.stop_background_workers()", ct); - await RequirePerChunkSettingsAsync(connection, ct); - await ExecAsync(connection, TimescaleSupport.CreateHypertableSql(TimescaleSupport.PerfmonStatsTable, "collection_time"), ct); - await ExecAsync(connection, "ALTER TABLE perfmon_stats SET (timescaledb.compress, timescaledb.compress_segmentby = 'server_id')", ct); - - /* 4 servers x 130 counters x 2 instances = 1040 series, a sample a minute for a day: 1,497,600 rows. */ - var day = DateTime.SpecifyKind(RunStartUtc.Date.AddDays(-3), DateTimeKind.Unspecified); - using (var seed = new NpgsqlCommand( - @"INSERT INTO perfmon_stats (collection_id, collection_time, server_id, server_name, object_name, counter_name, instance_name, cntr_value, delta_cntr_value, sample_interval_seconds, cntr_type) - SELECT $1 - row_number() OVER (), g.t AT TIME ZONE 'UTC', s.id, 'REGROUP-SRV', 'SQLServer:Test', 'Counter ' || c.n, 'inst' || i.i, - (extract(epoch FROM g.t)::bigint / 60 + s.id + c.n * 7 + i.i) % 100000, (extract(epoch FROM g.t)::bigint / 60 + c.n) % 50, 60, 65792 - FROM generate_series($2::timestamp, $2::timestamp + INTERVAL '23 hours 59 minutes', INTERVAL '1 minute') AS g(t) - CROSS JOIN generate_series(1, 4) AS s(id) - CROSS JOIN generate_series(1, 130) AS c(n) - CROSS JOIN generate_series(0, 1) AS i(i)", connection) { CommandTimeout = 300 }) - { - seed.Parameters.AddWithValue(IdBase); - seed.Parameters.AddWithValue(day); - await seed.ExecuteNonQueryAsync(ct); - } - - var chunkName = await ScalarAsync(connection, - "SELECT format('%I.%I', chunk_schema, chunk_name) FROM timescaledb_information.chunks WHERE hypertable_name = 'perfmon_stats' AND NOT is_compressed AND range_end <= now()", ct); - await ExecAsync(connection, $"SELECT compress_chunk('{chunkName}')", ct); - await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); - - /* The bound is on what the re-group ADDS to a read (#5574): the same read is timed without a re-group first, in this test, - so a slow runner moves both numbers and only a lock wait moves the difference. */ - static async Task TimeReadAsync(NpgsqlConnection readConnection, CancellationToken token) - { - var clock = System.Diagnostics.Stopwatch.StartNew(); - using var read = new NpgsqlCommand( - "SELECT count(*), max(cntr_value) FROM v_perfmon_stats WHERE server_id = 2 AND counter_name = 'Counter 7' AND collection_time >= now() - INTERVAL '30 days'", readConnection) - { CommandTimeout = 120 }; - await read.ExecuteScalarAsync(token); - clock.Stop(); - return clock.Elapsed; - } - - /* The baseline is the MEDIAN of the warm reads (#5574, check round 2): the first read after the compress is cold (plan, - buffers) and is dropped, and one slow outlier must not lift the baseline, because the stall this test guards is a - lock wait of about 3 s on top of a warm read, and a baseline raised by 0.5 s lets it through. */ - var warm = new List(); - using (var baselineConnection = new NpgsqlConnection(scratch.ConnectionString)) - { - await baselineConnection.OpenAsync(ct); - await TimeReadAsync(baselineConnection, ct); - for (var i = 0; i < 5; i++) - { - warm.Add(await TimeReadAsync(baselineConnection, ct)); - } - } - - var baseline = warm.OrderBy(took => took).ElementAt(warm.Count / 2); - - var stop = false; - var slowest = TimeSpan.Zero; - var reads = 0; - var reader = Task.Run(async () => - { - using var readConnection = new NpgsqlConnection(scratch.ConnectionString); - await readConnection.OpenAsync(ct); - while (!Volatile.Read(ref stop)) - { - var took = await TimeReadAsync(readConnection, ct); - if (took > slowest) - { - slowest = took; - } - - reads++; - await Task.Delay(100, ct); - } - }, ct); - - var logger = new CapturingTestLogger(); - var outcome = await TimescaleSupport.RegroupPerfmonChunkAsync( - connection, logger, new TimescaleSupport.PerfmonRegroupCandidate(chunkName, OldChunkSegmentBy), ct); - Volatile.Write(ref stop, true); - await reader; - - Assert.Equal(TimescaleSupport.PerfmonRegroupChunkResult.Regrouped, outcome.Result); - Assert.Equal(1_497_600, outcome.Rows); - Assert.True(reads >= 3, $"the reader only got {reads} reads in during a {outcome.Elapsed.TotalSeconds:0.0} s re-group"); - Assert.True(slowest - baseline < TimeSpan.FromSeconds(2.5), - $"a read took {slowest.TotalSeconds:0.0} s during a {outcome.Elapsed.TotalSeconds:0.0} s re-group, against {baseline.TotalSeconds:0.0} s without one"); - } - /// /// A service stop during the drain's pause ends the run at once (#5574): the pause is waited on with the stopping token, /// so the run's task completes within a moment, without a warning, with the chunks it had not reached untouched. @@ -564,38 +454,6 @@ public async Task AServiceStopDuringThePause_EndsTheRunPromptly_WithoutAWarning( Assert.Equal(5, after.Count(chunk => chunk.SegmentBy == OldChunkSegmentBy)); } - /// - /// A service stop during the compress half (#5574): the wait for a held lock is cancelled at once (not after the 3 s lock - /// timeout), the cancellation propagates, and the log says the chunk is left for the compression policy. - /// - [Fact] - public async Task AServiceStopDuringTheCompressHalf_CancelsTheWait_AndSaysTheChunkIsLeftToThePolicy() - { - var connectionString = RequireLivePostgres(); - var ct = TestContext.Current.CancellationToken; - await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); - using var connection = new NpgsqlConnection(scratch.ConnectionString); - await connection.OpenAsync(ct); - await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); - await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); - TimescaleSupport.BusyStreaks.Reset(); - - var chunk = ChunkOfDay(await ReadChunksAsync(connection, ct), 3); - await ExecAsync(connection, $"SELECT decompress_chunk('{chunk.Name}')", ct); - await using var holder = await HoldLockAsync(scratch.ConnectionString, chunk.Name, ct); - var logger = new CapturingTestLogger(); - var clock = System.Diagnostics.Stopwatch.StartNew(); - using var stopping = CancellationTokenSource.CreateLinkedTokenSource(ct); - stopping.CancelAfter(TimeSpan.FromMilliseconds(500)); - await Assert.ThrowsAnyAsync( - () => TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.FromSeconds(5), stopping.Token)); - await holder.ReleaseAsync(ct); - - Assert.True(clock.Elapsed < TimeSpan.FromSeconds(2.5), $"the stop took {clock.Elapsed.TotalSeconds:0.0} s to end the wait"); - Assert.Single(logger.Lines, line => line.Contains("the service is stopping with perfmon_stats chunk", StringComparison.Ordinal)); - TimescaleSupport.BusyStreaks.Reset(); - } - /* ---------------- check round 1 (#5579) ---------------- */ /// @@ -959,14 +817,6 @@ public async Task AFailedCandidatesRead_IsWarnedOncePerProcess_AndIsNotConvergen /* ---------------- fixture ---------------- */ - private static string RequireLivePostgres() - { - var connectionString = Environment.GetEnvironmentVariable("DARLING_TEST_PG"); - Assert.SkipWhen(string.IsNullOrEmpty(connectionString), - "Set DARLING_TEST_PG to a Postgres connection string to run the perfmon_stats re-group tests (each mints its own scratch database)."); - return connectionString!; - } - private static PerfmonRegroupDrain NewDrain( string connectionString, CapturingTestLogger logger, TimeSpan minPause, List pauses, int statementTimeoutSeconds = TimescaleSupport.PerfmonRegroupStatementTimeoutSeconds, @@ -992,83 +842,6 @@ private static PerfmonRegroupDrain NewDrain( TimescaleSupport.PerfmonRegroupRead read) => (connection, logger, reach, token) => Task.FromResult(read); - /// - /// perfmon_stats as every build before #5574 left it: a hypertable compressed by server_id alone, five daily - /// chunks inside the reach (yesterday back to five days ago) and one 45 days back, all compressed. Skips on a TimescaleDB - /// without the per-chunk settings view (before 2.14.1), which these tests read. - /// - private static async Task BuildOldStoreAsync(NpgsqlConnection connection, string connectionString, CancellationToken ct) - { - await PgMigrations.MigrateAsync(connection, ct); - Assert.SkipUnless(await LiveTimescaleProbe.TryEnableAsync(connectionString, ct), "TimescaleDB is not available on this cluster."); - await ExecAsync(connection, "SELECT _timescaledb_functions.stop_background_workers()", ct); - Assert.SkipUnless( - await ScalarAsync(connection, "SELECT to_regclass('timescaledb_information.chunk_compression_settings') IS NOT NULL", ct), - "this TimescaleDB has no timescaledb_information.chunk_compression_settings (before 2.14.1)."); - - await ExecAsync(connection, TimescaleSupport.CreateHypertableSql(TimescaleSupport.PerfmonStatsTable, "collection_time"), ct); - await ExecAsync(connection, "ALTER TABLE perfmon_stats SET (timescaledb.compress, timescaledb.compress_segmentby = 'server_id')", ct); - - var today = DateTime.SpecifyKind(RunStartUtc.Date, DateTimeKind.Unspecified); - foreach (var daysBack in new[] { 1, 2, 3, 4, 5, 45 }) - { - await SeedDayAsync(connection, today.AddDays(-daysBack), daysBack, ct); - } - - var chunks = new List(); - using (var list = new NpgsqlCommand( - "SELECT format('%I.%I', chunk_schema, chunk_name) FROM timescaledb_information.chunks " - + "WHERE hypertable_schema = 'collect' AND hypertable_name = 'perfmon_stats' AND NOT is_compressed AND range_end <= now()", connection)) - await using (var reader = await list.ExecuteReaderAsync(ct)) - { - while (await reader.ReadAsync(ct)) - { - chunks.Add(reader.GetString(0)); - } - } - - foreach (var chunk in chunks) - { - await ExecAsync(connection, $"SELECT compress_chunk('{chunk}')", ct); - } - } - - /// Two servers, four counters, two instances each, a sample every 30 minutes: 768 rows for the day. - private static async Task SeedDayAsync(NpgsqlConnection connection, DateTime day, int salt, CancellationToken ct) - { - using var command = new NpgsqlCommand( - @"INSERT INTO perfmon_stats (collection_id, collection_time, server_id, server_name, object_name, counter_name, instance_name, cntr_value, delta_cntr_value, sample_interval_seconds, cntr_type) - SELECT $1 - $3 * 100000 - row_number() OVER (), g.t AT TIME ZONE 'UTC', s.id, 'REGROUP-SRV', 'SQLServer:Test', 'Counter ' || c.n, - CASE WHEN i.i = 0 THEN '' ELSE 'inst' || i.i END, - (extract(epoch FROM g.t)::bigint / 60 + s.id + c.n * 7 + i.i) % 100000, (extract(epoch FROM g.t)::bigint / 60 + c.n) % 50, 60, 65792 - FROM generate_series($2::timestamp, $2::timestamp + INTERVAL '23 hours 30 minutes', INTERVAL '30 minutes') AS g(t) - CROSS JOIN generate_series(1, 2) AS s(id) - CROSS JOIN generate_series(1, 4) AS c(n) - CROSS JOIN generate_series(0, 1) AS i(i)", connection); - command.Parameters.AddWithValue(IdBase); - command.Parameters.AddWithValue(day); - command.Parameters.AddWithValue(salt); - await command.ExecuteNonQueryAsync(ct); - } - - private static async Task> ReadChunksAsync(NpgsqlConnection connection, CancellationToken ct) - { - using var command = new NpgsqlCommand( - @"SELECT format('%I.%I', c.chunk_schema, c.chunk_name), c.is_compressed, coalesce(s.segmentby, ''), (c.range_start AT TIME ZONE 'UTC') - FROM timescaledb_information.chunks AS c - LEFT JOIN timescaledb_information.chunk_compression_settings AS s ON s.chunk = to_regclass(format('%I.%I', c.chunk_schema, c.chunk_name)) - WHERE c.hypertable_schema = 'collect' AND c.hypertable_name = 'perfmon_stats' - ORDER BY c.range_start DESC", connection); - var chunks = new List(); - await using var reader = await command.ExecuteReaderAsync(ct); - while (await reader.ReadAsync(ct)) - { - chunks.Add(new ChunkRow(reader.GetString(0), reader.GetBoolean(1), reader.GetString(2), DateTime.SpecifyKind(reader.GetDateTime(3), DateTimeKind.Utc))); - } - - return chunks; - } - /// One md5 over the row count and a hash sum per (server, counter): unchanged data gives the same value. private static Task FingerprintAsync(NpgsqlConnection connection, CancellationToken ct) => ScalarAsync(connection, @@ -1077,19 +850,6 @@ private static Task FingerprintAsync(NpgsqlConnection connection, Cancel sum(hashtextextended(concat_ws('|', collection_id, collection_time, instance_name, cntr_value, delta_cntr_value, sample_interval_seconds, cntr_type), 0)::numeric) AS h FROM perfmon_stats GROUP BY server_id, counter_name) AS t", ct); - private static async Task ExecAsync(NpgsqlConnection connection, string sql, CancellationToken ct) - { - using var command = new NpgsqlCommand(sql, connection); - await command.ExecuteNonQueryAsync(ct); - } - - private static async Task ScalarAsync(NpgsqlConnection connection, string sql, CancellationToken ct) - { - using var command = new NpgsqlCommand(sql, connection); - var value = await command.ExecuteScalarAsync(ct); - return (T)Convert.ChangeType(value!, typeof(T), System.Globalization.CultureInfo.InvariantCulture); - } - /* ---------------- round 2b helpers ---------------- */ /// Runs the drain to the end, or fails the test when it has not ended in (a drain @@ -1135,53 +895,6 @@ private static async Task WaitForAsync(Func condition, int seconds, Cancel } } - private static ChunkRow ChunkOfDay(List chunks, int daysBack) => - chunks.Single(chunk => chunk.Start.Date == RunStartUtc.Date.AddDays(-daysBack)); - - /// Another session holds ROW EXCLUSIVE on the chunk inside an open transaction, which conflicts with the - /// EXCLUSIVE lock both halves of the re-group ask for. - private static async Task HoldLockAsync(string connectionString, string chunk, CancellationToken ct) - { - var holder = new NpgsqlConnection(connectionString); - await holder.OpenAsync(ct); - await ExecAsync(holder, "BEGIN", ct); - await ExecAsync(holder, $"LOCK TABLE {chunk} IN ROW EXCLUSIVE MODE", ct); - return new HeldLock(holder); - } - - /// The session that holds a chunk's lock; released by or, at the latest, when - /// the test's scope ends. - private sealed class HeldLock : IAsyncDisposable - { - private NpgsqlConnection? _connection; - - public HeldLock(NpgsqlConnection connection) => _connection = connection; - - public async Task ReleaseAsync(CancellationToken ct) - { - var connection = Interlocked.Exchange(ref _connection, null); - if (connection is not null) - { - await ExecAsync(connection, "ROLLBACK", ct); - await connection.DisposeAsync(); - } - } - - public async ValueTask DisposeAsync() - { - var connection = Interlocked.Exchange(ref _connection, null); - if (connection is not null) - { - await connection.DisposeAsync(); - } - } - } - - private static async Task RequirePerChunkSettingsAsync(NpgsqlConnection connection, CancellationToken ct) => - Assert.SkipUnless( - await ScalarAsync(connection, "SELECT to_regclass('timescaledb_information.chunk_compression_settings') IS NOT NULL", ct), - "this TimescaleDB has no timescaledb_information.chunk_compression_settings (before 2.14.1)."); - /// perfmon_stats's own segmentby columns in order, joined with ", " (how the product's gate reads them). private static Task HypertableSegmentByAsync(NpgsqlConnection connection, CancellationToken ct) => ScalarAsync(connection, diff --git a/Darling/Darling.Tests/PerfmonRegroupTimingLiveTests.cs b/Darling/Darling.Tests/PerfmonRegroupTimingLiveTests.cs new file mode 100644 index 0000000000..f6fe6595e9 --- /dev/null +++ b/Darling/Darling.Tests/PerfmonRegroupTimingLiveTests.cs @@ -0,0 +1,168 @@ +/* + * 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.Linq; +using System.Threading; +using System.Threading.Tasks; +using Npgsql; +using PerformanceMonitor.Darling.Storage; +using Xunit; +using static Darling.Tests.PerfmonRegroupLiveSupport; + +namespace Darling.Tests; + +/// +/// #5574: the two perfmon_stats re-group tests that start a clock and judge a time against a limit. They are split out of +/// into the timing collection, so the timed calls run on a quiet process +/// instead of sharing CPU with the parallel classes. Each test mints its own scratch database, like the class they came +/// from, and every assertion and bar is unchanged. +/// +/* #1776 own-store: both facts mint their own scratch database through ScratchPostgres and never touch another + test's rows, so this class is deliberately NOT [Collection("live-postgres")]. */ +[Collection("timing")] +public sealed class PerfmonRegroupTimingLiveTests +{ + + /// + /// A reader beside the re-group of a chunk of about 1.5 M rows never waits more than a few seconds (#5574; the bound is 2.5 s, against 0.1 to 0.2 s measured with two transactions and 4.9 s of a 10.3 s re-group with one): the + /// decompress holds only a lock that lets reads go on, and the ACCESS EXCLUSIVE it takes at its end is released by + /// its own commit, before the compress half starts. The same re-group in ONE transaction made the reader wait for + /// the whole compress half. + /// + [Fact] + public async Task AReaderBesideTheReGroupOfALargeChunk_NeverWaitsMoreThanAFewSeconds() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await PgMigrations.MigrateAsync(connection, ct); + Assert.SkipUnless(await LiveTimescaleProbe.TryEnableAsync(scratch.ConnectionString, ct), "TimescaleDB is not available on this cluster."); + await ExecAsync(connection, "SELECT _timescaledb_functions.stop_background_workers()", ct); + await RequirePerChunkSettingsAsync(connection, ct); + await ExecAsync(connection, TimescaleSupport.CreateHypertableSql(TimescaleSupport.PerfmonStatsTable, "collection_time"), ct); + await ExecAsync(connection, "ALTER TABLE perfmon_stats SET (timescaledb.compress, timescaledb.compress_segmentby = 'server_id')", ct); + + /* 4 servers x 130 counters x 2 instances = 1040 series, a sample a minute for a day: 1,497,600 rows. */ + var day = DateTime.SpecifyKind(RunStartUtc.Date.AddDays(-3), DateTimeKind.Unspecified); + using (var seed = new NpgsqlCommand( + @"INSERT INTO perfmon_stats (collection_id, collection_time, server_id, server_name, object_name, counter_name, instance_name, cntr_value, delta_cntr_value, sample_interval_seconds, cntr_type) + SELECT $1 - row_number() OVER (), g.t AT TIME ZONE 'UTC', s.id, 'REGROUP-SRV', 'SQLServer:Test', 'Counter ' || c.n, 'inst' || i.i, + (extract(epoch FROM g.t)::bigint / 60 + s.id + c.n * 7 + i.i) % 100000, (extract(epoch FROM g.t)::bigint / 60 + c.n) % 50, 60, 65792 + FROM generate_series($2::timestamp, $2::timestamp + INTERVAL '23 hours 59 minutes', INTERVAL '1 minute') AS g(t) + CROSS JOIN generate_series(1, 4) AS s(id) + CROSS JOIN generate_series(1, 130) AS c(n) + CROSS JOIN generate_series(0, 1) AS i(i)", connection) { CommandTimeout = 300 }) + { + seed.Parameters.AddWithValue(IdBase); + seed.Parameters.AddWithValue(day); + await seed.ExecuteNonQueryAsync(ct); + } + + var chunkName = await ScalarAsync(connection, + "SELECT format('%I.%I', chunk_schema, chunk_name) FROM timescaledb_information.chunks WHERE hypertable_name = 'perfmon_stats' AND NOT is_compressed AND range_end <= now()", ct); + await ExecAsync(connection, $"SELECT compress_chunk('{chunkName}')", ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + + /* The bound is on what the re-group ADDS to a read (#5574): the same read is timed without a re-group first, in this test, + so a slow runner moves both numbers and only a lock wait moves the difference. */ + static async Task TimeReadAsync(NpgsqlConnection readConnection, CancellationToken token) + { + var clock = System.Diagnostics.Stopwatch.StartNew(); + using var read = new NpgsqlCommand( + "SELECT count(*), max(cntr_value) FROM v_perfmon_stats WHERE server_id = 2 AND counter_name = 'Counter 7' AND collection_time >= now() - INTERVAL '30 days'", readConnection) + { CommandTimeout = 120 }; + await read.ExecuteScalarAsync(token); + clock.Stop(); + return clock.Elapsed; + } + + /* The baseline is the MEDIAN of the warm reads (#5574, check round 2): the first read after the compress is cold (plan, + buffers) and is dropped, and one slow outlier must not lift the baseline, because the stall this test guards is a + lock wait of about 3 s on top of a warm read, and a baseline raised by 0.5 s lets it through. */ + var warm = new List(); + using (var baselineConnection = new NpgsqlConnection(scratch.ConnectionString)) + { + await baselineConnection.OpenAsync(ct); + await TimeReadAsync(baselineConnection, ct); + for (var i = 0; i < 5; i++) + { + warm.Add(await TimeReadAsync(baselineConnection, ct)); + } + } + + var baseline = warm.OrderBy(took => took).ElementAt(warm.Count / 2); + + var stop = false; + var slowest = TimeSpan.Zero; + var reads = 0; + var reader = Task.Run(async () => + { + using var readConnection = new NpgsqlConnection(scratch.ConnectionString); + await readConnection.OpenAsync(ct); + while (!Volatile.Read(ref stop)) + { + var took = await TimeReadAsync(readConnection, ct); + if (took > slowest) + { + slowest = took; + } + + reads++; + await Task.Delay(100, ct); + } + }, ct); + + var logger = new CapturingTestLogger(); + var outcome = await TimescaleSupport.RegroupPerfmonChunkAsync( + connection, logger, new TimescaleSupport.PerfmonRegroupCandidate(chunkName, OldChunkSegmentBy), ct); + Volatile.Write(ref stop, true); + await reader; + + Assert.Equal(TimescaleSupport.PerfmonRegroupChunkResult.Regrouped, outcome.Result); + Assert.Equal(1_497_600, outcome.Rows); + Assert.True(reads >= 3, $"the reader only got {reads} reads in during a {outcome.Elapsed.TotalSeconds:0.0} s re-group"); + Assert.True(slowest - baseline < TimeSpan.FromSeconds(2.5), + $"a read took {slowest.TotalSeconds:0.0} s during a {outcome.Elapsed.TotalSeconds:0.0} s re-group, against {baseline.TotalSeconds:0.0} s without one"); + } + + /// + /// A service stop during the compress half (#5574): the wait for a held lock is cancelled at once (not after the 3 s lock + /// timeout), the cancellation propagates, and the log says the chunk is left for the compression policy. + /// + [Fact] + public async Task AServiceStopDuringTheCompressHalf_CancelsTheWait_AndSaysTheChunkIsLeftToThePolicy() + { + var connectionString = RequireLivePostgres(); + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(connectionString, ct); + using var connection = new NpgsqlConnection(scratch.ConnectionString); + await connection.OpenAsync(ct); + await BuildOldStoreAsync(connection, scratch.ConnectionString, ct); + await ExecAsync(connection, TimescaleSupport.EnableCompressionSql(TimescaleSupport.PerfmonStatsTable), ct); + TimescaleSupport.BusyStreaks.Reset(); + + var chunk = ChunkOfDay(await ReadChunksAsync(connection, ct), 3); + await ExecAsync(connection, $"SELECT decompress_chunk('{chunk.Name}')", ct); + await using var holder = await HoldLockAsync(scratch.ConnectionString, chunk.Name, ct); + var logger = new CapturingTestLogger(); + var clock = System.Diagnostics.Stopwatch.StartNew(); + using var stopping = CancellationTokenSource.CreateLinkedTokenSource(ct); + stopping.CancelAfter(TimeSpan.FromMilliseconds(500)); + await Assert.ThrowsAnyAsync( + () => TimescaleSupport.CompressRegroupedChunkAsync(connection, logger, chunk.Name, 3, TimeSpan.FromSeconds(5), stopping.Token)); + await holder.ReleaseAsync(ct); + + Assert.True(clock.Elapsed < TimeSpan.FromSeconds(2.5), $"the stop took {clock.Elapsed.TotalSeconds:0.0} s to end the wait"); + Assert.Single(logger.Lines, line => line.Contains("the service is stopping with perfmon_stats chunk", StringComparison.Ordinal)); + TimescaleSupport.BusyStreaks.Reset(); + } +} diff --git a/Darling/Darling.Tests/WebReadReachLiveTests.cs b/Darling/Darling.Tests/WebReadReachLiveTests.cs index 479e76844c..1c22095465 100644 --- a/Darling/Darling.Tests/WebReadReachLiveTests.cs +++ b/Darling/Darling.Tests/WebReadReachLiveTests.cs @@ -44,6 +44,7 @@ private static async Task WebReadAsync(NpgsqlDataSource postgres, string { new("server_name", ServerName), new("hours_back", hours.ToString(System.Globalization.CultureInfo.InvariantCulture)), + new("counter_name", "Batch Requests/sec"), }); return await DarlingWebEndpoints.BuildReadDispatch()[read](context, postgres, null!); } @@ -139,7 +140,7 @@ await DarlingMcpTestData.ExecAsync(connection, ct, } /* The raw-table trends reach their table's 30 days (#5562 L4b): 720 is answered, 721 is refused, never clamped. */ - foreach (var read in new[] { "get_tempdb_trend", "get_memory_trend", "get_cpu_utilization" }) + foreach (var read in new[] { "get_tempdb_trend", "get_memory_trend", "get_cpu_utilization", "get_perfmon_trend" }) { /* No "error" key at all, not merely a message without the ceiling text: a read that failed for another reason must not pass (review L6). */ var answered = await WebReadAsync(postgres, read, WebReadReach.RawTrendHours); @@ -152,7 +153,7 @@ await DarlingMcpTestData.ExecAsync(connection, ct, Assert.Contains("exceeds maximum of 720 hours (30 days)", refused); } - /* Raised-then-lowered (#5562 review r1): the perfmon trend (11.2 s cold at 30 days, #5574) and the heatmap (raw query_stats, four days on a TimescaleDB store) stay at 168. */ + /* The perfmon trend joined the raised set with #5574 (re-grouped by counter: 11.2 s to 1.3 s cold at 30 days); the heatmap (raw query_stats, four days on a TimescaleDB store) stays at 168. */ foreach (var read in new[] { "get_query_heatmap" }) { Assert.Contains("exceeds maximum of 168 hours (7 days)", diff --git a/Darling/Darling.Tests/WebReadReachTests.cs b/Darling/Darling.Tests/WebReadReachTests.cs index c0bb93885a..04129ce5e9 100644 --- a/Darling/Darling.Tests/WebReadReachTests.cs +++ b/Darling/Darling.Tests/WebReadReachTests.cs @@ -102,7 +102,7 @@ public void OnlyBucketedTrends_ReachPastTheDefault_AndNoneReachesPastTheirRollup new[] { "get_alert_history", "get_blocking_stats", "get_blocking_trend", "get_cpu_utilization", "get_deadlock_trend", "get_file_io_trend", - "get_lock_wait_trend", "get_memory_trend", "get_pg_cpu_utilization", "get_pg_database_trend", "get_pg_io_trend", + "get_lock_wait_trend", "get_memory_trend", "get_perfmon_trend", "get_pg_cpu_utilization", "get_pg_database_trend", "get_pg_io_trend", "get_procedure_duration_trend", "get_query_duration_trend", "get_query_store_duration_trend", "get_tempdb_trend", "get_wait_trend", }, @@ -111,8 +111,8 @@ public void OnlyBucketedTrends_ReachPastTheDefault_AndNoneReachesPastTheirRollup Assert.Equal(720, WebReadReach.RawTrendHours); Assert.Equal(2160, WebReadReach.AlertHistoryHours); - /* Review r1: get_perfmon_trend (11.2 s cold at 30 days, #5574) and get_query_heatmap (raw query_stats, four days on a TimescaleDB store) stay at a week. */ - Assert.Equal(McpHelpers.MaxHoursBack, WebReadReach.MaxHoursFor("get_perfmon_trend")); + /* #5574: get_perfmon_trend joined the raised set once its compressed data was re-grouped by counter (11.2 s to 1.3 s cold at 30 days); get_query_heatmap (raw query_stats, four days on a TimescaleDB store) stays at a week. */ + Assert.Equal(WebReadReach.RawTrendHours, WebReadReach.MaxHoursFor("get_perfmon_trend")); Assert.Equal(McpHelpers.MaxHoursBack, WebReadReach.MaxHoursFor("get_query_heatmap")); } @@ -233,6 +233,19 @@ public void NoRawTableRead_ReachesPastItsCollectorsDefaultRetention() Assert.Equal(168, WebReadReach.MaxHoursFor("get_current_waits_trend")); } + /// + /// #5574: the perfmon re-group drain covers exactly what the 30-day perfmon trend reads. The trend is fast over a + /// chunk only once that chunk is re-grouped by counter, so the drain's reach in days must be the trend's reach in + /// hours divided by 24: raising one without the other would leave part of the window on the 11.2 s shape, or + /// re-group chunks no read ever reaches. + /// + [Fact] + public void ThePerfmonReGroupDrainsReach_IsThePerfmonTrendsReachInDays() + { + Assert.Equal(PerformanceMonitor.Darling.Storage.TimescaleSupport.PerfmonRegroupReachDays, WebReadReach.RawTrendHours / 24); + Assert.Equal(PerformanceMonitor.Darling.Storage.TimescaleSupport.PerfmonRegroupReachDays, WebReadReach.MaxHoursFor("get_perfmon_trend") / 24); + } + /// /// The validator of each opted-in read takes its ceiling from the table, and no other tool does: a row that says /// 2,160 with a validator still on the 168-hour overload would advertise a window the read then refuses, and a @@ -308,6 +321,7 @@ public void Catalog_EveryHoursParam_CarriesMaxHoursFromTheTable() Assert.Equal(2160, HoursParam(catalog, "get_query_store_duration_trend")["max_hours"]!.GetValue()); Assert.Equal(720, HoursParam(catalog, "get_wait_trend")["max_hours"]!.GetValue()); + Assert.Equal(720, HoursParam(catalog, "get_perfmon_trend")["max_hours"]!.GetValue()); Assert.Equal(168, HoursParam(catalog, "get_server_trend")["max_hours"]!.GetValue()); Assert.Equal(2160, HoursParam(catalog, "get_alert_history")["max_hours"]!.GetValue()); Assert.Equal("bucketed_trend", HoursParam(catalog, "get_wait_trend")["shape"]!.GetValue()); diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpTrendTools.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpTrendTools.cs index 0d66783410..63cfd7c8dd 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpTrendTools.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpTrendTools.cs @@ -167,7 +167,7 @@ appears where snapshots exist with nothing granted. Lite's tool builds the same } } - [McpServerTool(Name = "get_perfmon_trend"), Description("Gets one performance counter over time in buckets, ending at as_of. counter_kind says the unit: gauge - value is the bucket average, delta_value and sample_interval_seconds null (no delta for a level); rate - per-second is delta_value divided by sample_interval_seconds, never delta_value alone or when the interval is 0; other - delta_value is a non-rate change; null - classify by name (ends in /sec = rate). No points never returns empty: not_collected covers a gated engine, Page Life Expectancy, or an unknown counter name; unavailable: no counter at all collected in the window. <> Gets one performance counter over time in time buckets. Use get_perfmon_stats first to see available counter names. artifacts_set_aside counts an isolated single-sample Wait Statistics spike excluded from the sums before bucketing (notes explains it); it is not a missing-data count. counter_kind (from the stored cntr_type) says what a point's number is: 'gauge' — value is the bucket's average reading and peak_value its highest, delta_value and sample_interval_seconds are null because a level has no delta; 'rate' — the per-second figure is delta_value divided by sample_interval_seconds, never delta_value alone, and never where sample_interval_seconds is 0 (no delta was knowable), and each point carries it as per_second (null where the interval is 0); 'other' — delta_value is the change of an average/fraction numerator, not a rate and not a level; null — the rows predate the stored type or the instances mix types, so classify by name (a name ending in /sec is a rate)." + BaselineDiscontinuities.DescriptionSentence)] + [McpServerTool(Name = "get_perfmon_trend"), Description("Gets one performance counter over time in buckets, ending at as_of. counter_kind says the unit: gauge - value is the bucket average, delta_value and sample_interval_seconds null (no delta for a level); rate - per-second is delta_value divided by sample_interval_seconds, never delta_value alone or when the interval is 0; other - delta_value is a non-rate change; null - classify by name (ends in /sec = rate). No points never returns empty: not_collected covers a gated engine, Page Life Expectancy, or an unknown counter name; unavailable: no counter at all collected in the window. <> Gets one performance counter over time in time buckets. hours_back reaches 720 (30 days). Use get_perfmon_stats first to see available counter names. artifacts_set_aside counts an isolated single-sample Wait Statistics spike excluded from the sums before bucketing (notes explains it); it is not a missing-data count. counter_kind (from the stored cntr_type) says what a point's number is: 'gauge' — value is the bucket's average reading and peak_value its highest, delta_value and sample_interval_seconds are null because a level has no delta; 'rate' — the per-second figure is delta_value divided by sample_interval_seconds, never delta_value alone, and never where sample_interval_seconds is 0 (no delta was knowable), and each point carries it as per_second (null where the interval is 0); 'other' — delta_value is the change of an average/fraction numerator, not a rate and not a level; null — the rows predate the stored type or the instances mix types, so classify by name (a name ending in /sec is a rate)." + BaselineDiscontinuities.DescriptionSentence)] public static Task GetPerfmonTrend( NpgsqlDataSource postgres, [Description("The exact counter name, e.g. 'Batch Requests/sec'.")] string counter_name, @@ -187,10 +187,10 @@ internal static async Task GetPerfmonTrend( var (resolved, error) = await DarlingServerResolver.ResolveOrErrorAsync(postgres, server_name, cancellationToken); if (error != null) return error; - /* #5562: stays at 168 h. The re-time on a large store read 11.2 s cold at 30 days even with the LIKE predicate (DarlingTrendReader.PerfmonTrendSql, - which saved 1.3 s cold): the compressed perfmon_stats data is grouped by server only, so the read decodes every counter's name no matter which - counter was asked for. A month is too slow to offer (#5574 tracks compressing the data by counter so it can reach 30 days); this keeps the 168-hour overload, as its WebReadReach row says. */ - var validation = McpHelpers.ValidateWindow(hours_back, as_of, out var windowEnd); + /* #5574: reaches the raw table's 30-day retention (720 h); 1.3 s cold at 30 days on a large store once the compressed perfmon_stats + data was re-grouped by counter (it read 11.2 s while the compression grouped by server only, so the read decoded every counter's + name). The ceiling is the WebReadReach row. */ + var validation = McpHelpers.ValidateWindow(hours_back, as_of, WebReadReach.MaxHoursFor("get_perfmon_trend"), out var windowEnd); if (validation != null) return validation; var bucketError = TrendBuckets.Resolve(hours_back, bucket_minutes, 1, budget, out var bucketMinutes); diff --git a/Darling/PerformanceMonitor.Darling.Service/WebReadReach.cs b/Darling/PerformanceMonitor.Darling.Service/WebReadReach.cs index cc35c7e0aa..2874f60121 100644 --- a/Darling/PerformanceMonitor.Darling.Service/WebReadReach.cs +++ b/Darling/PerformanceMonitor.Darling.Service/WebReadReach.cs @@ -110,9 +110,10 @@ internal static class WebReadReach /* Raw-table bucketed trends: 720 hours where the large-store timing run measured a month under 10 s (#5562 L4b; each validator names its time). Left at 168: get_current_waits_trend (its waiting_tasks table keeps 7 days), get_server_trend (6 of its 11 metrics were never timed), get_pg_wait_trend (its timing table was empty), - get_pg_query_duration_trend (not timed), get_perfmon_trend (11.2 s cold at 30 days on a large store: the compressed data is - grouped by server only, so the read decodes every counter's name; #5574 tracks the fix) and get_query_heatmap (raw query_stats, which a TimescaleDB - store drops at four days, so a month is a window the table cannot fill). get_blocking_stats is uncapped on the MCP side (ValidateUncappedWindow). */ + get_pg_query_duration_trend (not timed) and get_query_heatmap (raw query_stats, which a TimescaleDB + store drops at four days, so a month is a window the table cannot fill). get_perfmon_trend reaches 720 since #5574 re-grouped + the compressed perfmon_stats data by counter: the cold read at 30 days on a large store fell from 11.2 s to 1.3 s, inside the 10 s bar. + get_blocking_stats is uncapped on the MCP side (ValidateUncappedWindow). */ ["get_blocking_trend"] = Trend("blocked_process_report", RawTrendHours), ["get_deadlock_trend"] = Trend("deadlocks", RawTrendHours), ["get_lock_wait_trend"] = Trend("wait_stats", RawTrendHours), @@ -125,7 +126,7 @@ internal static class WebReadReach ["get_file_io_trend"] = Trend("file_io_stats", RawTrendHours), ["get_memory_trend"] = Trend("memory_stats", RawTrendHours), ["get_server_trend"] = Trend(null), - ["get_perfmon_trend"] = Trend("perfmon_stats"), + ["get_perfmon_trend"] = Trend("perfmon_stats", RawTrendHours), ["get_pg_cpu_utilization"] = Trend("pg_cpu_utilization", RawTrendHours), ["get_pg_wait_trend"] = Trend("pg_wait_sampling"), ["get_pg_query_duration_trend"] = Trend("pg_statement_stats"),