Store checkpointer alert: a requested checkpoint is no longer blamed on max_wal_size alone (#4758)

Darling/Darling.Tests/DarlingMcpStoreMetricsToolsTests.cs

@@ -1420,6 +1420,23 @@ public async Task TheLiveInventoryReads_FailToNull_AndSkipTheCatalogsThatDoNotEx
         Assert.Null(await DarlingStoreMetricsReader.GetLargestUnenumeratedAsync(nowhere, notRegistered, ct));
     }
 
+    /// <summary>
+    /// #4758: the description's <c>requested</c> field says what PostgreSQL's counter counts. A requested
+    /// checkpoint is started by WAL volume reaching <c>max_wal_size</c>, a base backup or a <c>CHECKPOINT</c>
+    /// statement, and the counter does not say which, so the description must not call them all WAL-forced.
+    /// </summary>
+    [Fact]
+    public void TheDescription_SaysARequestedCheckpointHasThreeCauses_NotOnlyWalVolume()
+    {
+        var description = ToolMethods().Single().GetCustomAttribute<DescriptionAttribute>()?.Description;
+        Assert.NotNull(description);
+
+        Assert.Contains(
+            "requested (checkpoints started by WAL volume reaching max_wal_size, a base backup, or a CHECKPOINT statement rather than by checkpoint_timeout; the counter does not say which)",
+            description!, StringComparison.Ordinal);
+        Assert.DoesNotContain("checkpoints forced by WAL volume", description!, StringComparison.Ordinal);
+    }
+
     /// <summary>
     /// #3582: the description names every new kind, the coverage fields and the reconciliation bar,
     /// asserted TOGETHER with the sweep arms that write the kinds and the constants that set the bar.

Darling/Darling.Tests/StoreSelfMetricsTests.cs

@@ -884,7 +884,7 @@ store rather than a difference of two numbers that happened to be there. */
         Assert.True(second.SyncMs is >= 0);
         Assert.True(second.Requested is >= 1, $"the forced CHECKPOINT must land in the interval's requested count, not {second.Requested}");
         Assert.Equal(first.CumulativeRequested + second.Requested, second.CumulativeRequested);
-        Assert.True(second.IsPressure, "one WAL-forced checkpoint in the interval IS the pressure arm");
+        Assert.True(second.IsPressure, "one requested checkpoint in the interval IS the pressure arm");
 
         /* #4619: the existence check, through the shipped SQL, over the names THIS SWEEP WROTE. Every one must
            resolve back to its object: a kind whose lookup drifted from the sweep's name form (the job name, a

Darling/Darling.Tests/StoreToastAndCheckpointerTests.cs

@@ -588,9 +588,17 @@ rule would have judged 84s against the same bar and misfired (#4037). */
         Assert.Contains("a per-checkpoint sync average past 10s", storm, StringComparison.Ordinal);
         Assert.Contains("25.2 s and 14.0 s sync phases", storm, StringComparison.Ordinal);
 
-        /* Requested arm: low sync average, but one requested checkpoint still fires. */
+        /* Requested arm: low sync average, but one requested checkpoint still fires. The note says what the alert
+           says (#4758): a requested checkpoint comes from WAL volume, a base backup or a CHECKPOINT statement, the
+           counters do not say which, and raising max_wal_size is the remedy for the first cause only. */
         var forced = DarlingMcpStoreMetricsTools.CheckpointerNote(DarlingStoreMetricsReader.CheckpointerReading.From(new(t1, 2_000, 3_000, 6, Timed: 5), new(t0, 1_000, 1_000, 5, Timed: 0)));
-        Assert.Contains("a requested checkpoint means the store wrote more WAL between checkpoints than max_wal_size allows", forced, StringComparison.Ordinal);
+        Assert.Contains("a requested checkpoint comes from WAL volume reaching max_wal_size, a base backup, or a CHECKPOINT statement", forced, StringComparison.Ordinal);
+        Assert.Contains("counters do not say which", forced, StringComparison.Ordinal);
+        Assert.Contains("log_checkpoints", forced, StringComparison.Ordinal);
+        Assert.Contains("Raising max_wal_size is the remedy only for the first cause", forced, StringComparison.Ordinal);
+        Assert.DoesNotContain("WAL-forced", forced, StringComparison.Ordinal);
+        Assert.DoesNotContain("means the store wrote more WAL", forced, StringComparison.Ordinal);
+        Assert.Contains("The informational Store Checkpointer Pressure self-alert says the same.", forced, StringComparison.Ordinal);
 
         /* Zero checkpoints in the interval: no average to state, unmeasured, not judged either way. */
         var idle = DarlingMcpStoreMetricsTools.CheckpointerNote(DarlingStoreMetricsReader.CheckpointerReading.From(new(t1, 1_000, 1_000, 5, Timed: 0), new(t0, 1_000, 1_000, 5, Timed: 0)));
@@ -899,12 +907,25 @@ public async Task CheckpointerPressure_FiresInfoOnEitherArm_AndNotUnderBothLines
         Assert.Equal("average sync > 10s per checkpoint, or any requested checkpoint", fired.ThresholdValue);
         Assert.Contains("25.2 s and 14.0 s sync phases", fired.DetailText!, StringComparison.Ordinal);
 
-        /* The other arm alone: one WAL-forced checkpoint with a short average sync. */
+        /* The other arm alone: one requested checkpoint with a short average sync. A requested checkpoint comes
+           from WAL volume reaching max_wal_size, a base backup, or a CHECKPOINT statement, and the counters do not
+           say which (#4758), so the alert calls it "requested", names all three causes and the log_checkpoints
+           lines that say which, and offers max_wal_size as the remedy for the first cause only. */
         var forced = new Harness();
         await forced.Build().ApplyCheckpointerPressureAsync(Interval(syncMs: 800, requested: 1, timed: 1), Ct);
         var forcedFire = Assert.Single(forced.Deliverer.Outcomes);
-        Assert.Contains("1 WAL-forced checkpoint(s)", forcedFire.CurrentValue, StringComparison.Ordinal);
-        Assert.Contains("more WAL between checkpoints than max_wal_size allows", forcedFire.DetailText!, StringComparison.Ordinal);
+        Assert.Contains("1 requested checkpoint(s)", forcedFire.CurrentValue, StringComparison.Ordinal);
+        Assert.DoesNotContain("WAL-forced", forcedFire.CurrentValue, StringComparison.Ordinal);
+        Assert.DoesNotContain("WAL-forced", forcedFire.ShortMessage!, StringComparison.Ordinal);
+        Assert.Contains("WAL volume reaching max_wal_size, a base backup, or a CHECKPOINT statement", forcedFire.DetailText!, StringComparison.Ordinal);
+        Assert.Contains("base backup", forcedFire.DetailText!, StringComparison.Ordinal);
+        Assert.Contains("CHECKPOINT statement", forcedFire.DetailText!, StringComparison.Ordinal);
+        Assert.Contains("counters do not say which", forcedFire.DetailText!, StringComparison.Ordinal);
+        Assert.Contains("log_checkpoints", forcedFire.DetailText!, StringComparison.Ordinal);
+        Assert.Contains("Raising max_wal_size is the remedy only for the first cause", forcedFire.DetailText!, StringComparison.Ordinal);
+        Assert.DoesNotContain("forced by WAL volume", forcedFire.DetailText!, StringComparison.Ordinal);
+        Assert.Null(forcedFire.Severity);
+        Assert.Equal("average sync > 10s per checkpoint, or any requested checkpoint", forcedFire.ThresholdValue);
 
         /* Exactly the bar, no forced checkpoint: quiet. */
         var quiet = new Harness();
@@ -1013,7 +1034,7 @@ public async Task CheckpointerPressure_TheSameCountersWithoutARestart_StillFireA
         await h.Build().ApplyCheckpointerPressureAsync(Interval(syncMs: 800, requested: 2, restarted: false, timed: 1), Ct);
         var fired = Assert.Single(h.Deliverer.Outcomes);
         Assert.Equal(DarlingSelfAlertEvaluator.CheckpointerPressureMetric, fired.MetricName);
-        Assert.Contains("2 WAL-forced checkpoint(s)", fired.CurrentValue, StringComparison.Ordinal);
+        Assert.Contains("2 requested checkpoint(s)", fired.CurrentValue, StringComparison.Ordinal);
         Assert.DoesNotContain("restart", fired.ShortMessage!, StringComparison.OrdinalIgnoreCase);
         Assert.DoesNotContain("RESTARTED", fired.DetailText!, StringComparison.Ordinal);
     }
@@ -1040,7 +1061,7 @@ public async Task CheckpointerPressure_TheSameSlowSyncWithoutARestart_StillFires
         await h.Build().ApplyCheckpointerPressureAsync(Interval(syncMs: 25_200, requested: 1, restarted: false, timed: 1), Ct);
         var fired = Assert.Single(h.Deliverer.Outcomes);
         Assert.Contains("average sync", fired.CurrentValue, StringComparison.Ordinal);
-        Assert.Contains("1 WAL-forced checkpoint(s)", fired.CurrentValue, StringComparison.Ordinal);
+        Assert.Contains("1 requested checkpoint(s)", fired.CurrentValue, StringComparison.Ordinal);
         Assert.DoesNotContain("restart", fired.ShortMessage!, StringComparison.OrdinalIgnoreCase);
     }
 

Darling/PerformanceMonitor.Darling.Service/DarlingSelfAlertEvaluator.cs

@@ -966,7 +966,9 @@ by dimension table name (two today: query_text_dim, query_plan_dim), STANDING li
     /// <c>checkpoint_timeout</c> covers about twelve timed checkpoints, so judging the sum against a
     /// per-checkpoint bar breached on a healthy store whose checkpoints each synced five to eight seconds and
     /// never recovered (#4037's own measured population). The second arm, <c>checkpoints_requested &gt; 0</c>,
-    /// has no threshold to tune: one WAL-forced checkpoint in an hour says the store outran <c>max_wal_size</c>.
+    /// has no threshold to tune: one requested checkpoint in an hour is worth a look, and it is a look, not a
+    /// verdict, because a requested checkpoint comes from WAL volume reaching <c>max_wal_size</c>, a base backup,
+    /// or a <c>CHECKPOINT</c> statement and the counters do not say which (#4758).
     /// Both arms are judged on an interval with no postmaster restart inside it: across one, the shutdown
     /// checkpoint is in the requested count and in the phase times alike, so neither is judged (#3955); and the
     /// average arm needs a TIMED count on both samples of the pair (V140), so a row from before that rung
@@ -5851,10 +5853,12 @@ public async Task EvaluateCheckpointerPressureAsync(NpgsqlDataSource postgres, C
     /// <summary>
     /// Applies the fleet-level Store Checkpointer Pressure condition (#3783) from the store's last measured
     /// checkpointer interval: the sync (fsync) phase held more than <see cref="CheckpointSyncBarMs"/> inside the
-    /// interval, OR at least one checkpoint was REQUESTED — forced by WAL volume reaching <c>max_wal_size</c>
-    /// rather than by the clock. Three unattributed read kills on a production store in one day all sat inside
-    /// checkpoint sync phases of 25.2 s and 14.0 s with nothing recording that the checkpointer had been there;
-    /// this is that record, as an alert. A STANDING condition (the Store Job Over Cadence idiom): fire once on
+    /// interval, OR at least one checkpoint was REQUESTED — started by WAL volume reaching <c>max_wal_size</c>, a
+    /// base backup, or a <c>CHECKPOINT</c> statement rather than by the clock. PostgreSQL's counters do not record
+    /// which, only its <c>log_checkpoints</c> lines do, so the text names all three causes and offers raising
+    /// <c>max_wal_size</c> as the remedy for the first only (#4758). Three unattributed read kills on a
+    /// production store in one day all sat inside checkpoint sync phases of 25.2 s and 14.0 s with nothing
+    /// recording that the checkpointer had been there; this is that record, as an alert. A STANDING condition (the Store Job Over Cadence idiom): fire once on
     /// breach, re-fire on the shared alert cooldown while each new interval keeps breaching, one "Store
     /// Checkpointer Pressure Recovered" resolution when an interval reads clean. INFORMATIONAL, fired with no
     /// severity override: the two levers are configuration — #3802's WAL sizing (<c>max_wal_size</c> /
@@ -5871,7 +5875,7 @@ public async Task EvaluateCheckpointerPressureAsync(NpgsqlDataSource postgres, C
     ///
     /// <para><b>An interval that spans a postmaster restart judges neither arm (#3955).</b> PostgreSQL counts the
     /// shutdown checkpoint as requested and keeps the count across the restart, so every service restart that
-    /// stopped the store fired this alert as "WAL-forced" pressure the store did not have; and that checkpoint's
+    /// stopped the store fired this alert as requested-checkpoint pressure the store did not have; and that checkpoint's
     /// own write and sync phases land in the same counters, where nothing can separate them from the live
     /// checkpoints' (a fast shutdown flushes every dirty buffer at once, with every client already gone, so a
     /// long one is not a stall anyone's read sat inside). The reader therefore calls such an interval
@@ -5913,9 +5917,9 @@ internal async Task ApplyCheckpointerPressureAsync(
                 var averageSecondsText = averageSyncMs is double a ? (a / 1000.0).ToString("0.0", CultureInfo.InvariantCulture) : "unmeasured";
                 var arms = (averageOverBar, requested > 0) switch
                 {
-                    (true, true) => $"average sync {averageSecondsText}s per checkpoint and {requested} WAL-forced checkpoint(s)",
+                    (true, true) => $"average sync {averageSecondsText}s per checkpoint and {requested} requested checkpoint(s)",
                     (true, false) => $"average sync {averageSecondsText}s per checkpoint",
-                    _ => $"{requested} WAL-forced checkpoint(s)",
+                    _ => $"{requested} requested checkpoint(s)",
                 };
                 await FireAsync(
                     StoreKey(CheckpointerKey), _storeLabel, CheckpointerPressureMetric,
@@ -5924,15 +5928,17 @@ await FireAsync(
                     detail: $"The store's own checkpointer ran {checkpointCount} checkpoint(s) over the {intervalMinutes} minutes " +
                         $"between the last two self-metrics sweeps, spending {(syncMs / 1000.0).ToString("0.0", CultureInfo.InvariantCulture)}s " +
                         $"total in its sync (fsync) phase and {writeSeconds}s in its write phase — an average of {averageSecondsText}s of sync " +
-                        $"per checkpoint — and {requested} of those checkpoints were REQUESTED — forced by WAL volume reaching " +
-                        "max_wal_size rather than by checkpoint_timeout. " +
+                        $"per checkpoint — and {requested} of those checkpoints were REQUESTED — started by something other than " +
+                        "checkpoint_timeout: WAL volume reaching max_wal_size, a base backup, or a CHECKPOINT statement. " +
                         (averageOverBar
                             ? $"A per-checkpoint sync average past {barSeconds}s means at least some of this interval's checkpoints ran " +
                               "an I/O stall every reader on the store shares: on one production store, three read kills in a day that " +
                               "nothing else explained all sat inside 25.2 s and 14.0 s sync phases, and the MCP host's read deadline is " +
                               $"the {barSeconds}s this line is drawn at. "
-                            : "A requested checkpoint means the store wrote more WAL between checkpoints than max_wal_size " +
-                              "allows, so the checkpointer ran early and the next one is closer — checkpoint pressure compounds. ") +
+                            : "PostgreSQL's counters do not say which of those started a requested checkpoint; the log_checkpoints " +
+                              "lines do. Raising max_wal_size is the remedy only for the first cause: when WAL volume did it, the " +
+                              "store wrote more WAL between checkpoints than max_wal_size allows, so the checkpointer ran early and " +
+                              "the next one is closer — checkpoint pressure compounds. ") +
                         "The interval series is collect.store_metrics (object_kind = 'checkpointer'; the stored columns are the " +
                         "server's cumulative counters, and get_store_metrics' checkpointer block publishes the per-interval " +
                         "differences and the same per-checkpoint average). This alert re-fires on the alert cooldown while each " +