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

Filter by extension

Filter by extension

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

### Fixed

- **Query Store execution counts stopped reporting a sliver of an interval instead of the whole thing** ([#1907]) - `sys.query_store_runtime_stats` returns the FLUSHED slice and the still-IN-MEMORY slice of one `runtime_stats_interval_id` as two separate rows, and they are ADDITIVE members of one interval rather than competing snapshots of it. The collector selected straight from the view, so both were stored - and they then shared every column of the read-side dedup key ([#1841]/[#1845]/[#1853]) **and** `collection_time`, which meant the viewer's `ROW_NUMBER() ... ORDER BY collection_time DESC` and the rollups' `last(execution_count, collection_time)` were both ordering by a value identical for both rows. The survivor was whichever the engine happened to emit first. Live on Azure SQL Database that showed as **8 executions reported where 94 was true**, on two of five rows, with a different two wrong on the next run - not a stale number but an arbitrary fraction of one. Query Store's default 900-second flush against its default 3600-second interval means one interval can hold several flushed slices, so the split is not bounded at two, and it is not an Azure peculiarity: it reproduces on box SQL Server 2022 (16.0.4255.1), where 100 executions flushed plus 25 in memory came back as two rows while `sys.dm_exec_procedure_stats` - a wholly separate source, read at the same instant - reported 125.

**The slices are now combined at COLLECTION**, in the one payload body both the on-prem and Azure execution shapes run, grouped on exactly the natural key of the view (`plan_id`, `runtime_stats_interval_id`, `execution_type`, replica group) so one interval yields at most one row per cycle. Read-side aggregation was not an option and is not a matter of taste: it would mean teaching every consumer the difference between "same interval, later cycle" (keep the latest) and "same interval, same cycle" (add them), and a TimescaleDB continuous aggregate cannot express that at all. `execution_count` SUMs; every `avg_*` column takes the count-WEIGHTED mean, because Query Store stores an average and a count but never a total, so `avg * count` is what recovers a slice's total - a plain average of the slice averages would weight a 25-execution sliver the same as a 100-execution flush. `min_*` and `max_*` take the extreme, `first_execution_time`/`last_execution_time` the interval's own span. Verified live: the emitted collector SQL returns 125 and 70 where the raw view holds `{100, 25}` and `{60, 10}`, matching `dm_exec_procedure_stats` exactly, and the weighted mean lands on 1871.856 for slices of (1778.42 over 100) and (2245.60 over 25) - which is `(1778.42*100 + 2245.60*25) / 125` and is not the 2012.01 an unweighted average would have given.

**The incremental cutoff had to move from a per-slice `WHERE` to an interval-grain `HAVING`, and that is load-bearing rather than tidiness.** The flushed slice is STATIC, so once the growing in-memory slice pushes the watermark past its `last_execution_time` the flushed slice stops qualifying - and a sum over the survivors is the sliver alone, the original defect with an aggregate bolted on top. `HAVING MAX(last_execution_time) > @cutoff_time` asks whether the INTERVAL saw new activity and then takes all of it, which is strictly more permissive than the predicate it replaces, so nothing that used to be collected stops being. **The fixed query is FASTER than the one it replaces**, despite the added aggregate: measured on a real 212,000-row Query Store with the full 55-column payload, 375/422/438 ms against 453/485/516 ms, because half the rows means half the `nvarchar(max)` query text and plan XML to materialize and ship. That depends on the interval pre-filter, which is a prune and not a semantic - its interval list is by construction a superset of what the `HAVING` keeps, so it cannot subtract a row - and without it the aggregate runs over the database's entire retained Query Store every cycle and costs 1203 ms instead.

**No stored row shape changed**: the same 55 columns in the same order, the same positional writers, no migration and no storage-version bump - only the number of rows per interval. The `TOP` backstop now caps intervals rather than slices, which is also why it sits outside the aggregate: a cap falling mid-interval would emit a partial sum, which is worse than omitting the interval. The deprecated Dashboard's `collect.query_store_collector` had the identical defect against the identical view and takes the identical fix (it is a proc body change, so an upgrade re-applies it with no schema step); its grouping key carries `replica_group_id` under a 2022+/Azure gate for the same bind-safety reason the collector's does, since naming a column that does not exist in a `GROUP BY` fails the whole batch rather than yielding a NULL.

**Rows already collected cannot be repaired, and are handled honestly rather than quietly.** All 19 read-side dedup sites across both apps now order by `collection_time DESC, execution_count DESC`, so a pre-fix tie resolves to the FLUSHED slice - the one holding the bulk of the interval's work - deterministically instead of flapping between runs. That is closest-available, not correct; the correct value is the sum, and the materialized rollups cannot be tie-broken at all because `last()` has no tie-break and the tied rows are gone once materialized. The residual, including the fact that the indefinitely-kept daily tier keeps understated counts for the pre-fix period, is tracked as [#1912]. Verified end to end against live PostgreSQL 18 + TimescaleDB 2.28.1: the corrected rollups report the hand-computed 155 for an hour of two combined intervals and the exact execution-weighted mean off the same rows, while the same store fed the pre-fix split slices reports a single slice and can never reach the 125 they add up to.
- **The force-plan recommendation was telling operators to write the one call form that errors** ([#1914]) - [#1882] disclosed that a secondary-derived recommendation forces on the PRIMARY, and told the operator how to scope it deliberately: "pass it as the fourth argument (they are extended stored procedure arguments, so the documented order matters)". That instruction came from the reference page's syntax block and had not been run. **It fails.** `sp_query_store_force_plan` is an `EXTENDED_STORED_PROCEDURE`, so `sys.system_parameters` is empty for it and its argument surface can only be established by executing it - which is what [#1914] did, on **SQL Server 2022 (16.0.4255.1) and SQL Server 2025 (17.0.4045.5)**, each form run from a freshly-unforced plan:

- `@query_id, @plan_id, @disable_optimized_plan_forcing = 0, @replica_group_id = 1` - the documented four-argument order - **fails on both versions** with error 12463, *"Role id should be between (including) 1 and 4"*, for a role id of 1, which is in that range. The same call with that argument set to `1` succeeds.
Expand Down Expand Up @@ -2250,12 +2259,16 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
[#1899]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1899
[#1889]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1889
[#1893]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1893
[#1845]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1845
[#1853]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1853
[#1873]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1873
[#1896]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1896
[#1898]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1898
[#1913]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1913
[#1914]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1914
[#1902]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1902
[#1907]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1907
[#1912]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1912
[#1905]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1905
[#1906]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1906
[#1824]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/1824
Expand Down
7 changes: 6 additions & 1 deletion Darling/Darling.Tests/DarlingComposeTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -1172,9 +1172,14 @@ is the whole reason it has to be in the partition too. */
ValidPlan("{\"source\":\"query_store_stats\",\"measure\":\"qs_executions\",\"aggregate\":\"sum\",\"timeBucket\":\"hour\",\"viz\":\"line\"}"),
servers: ["srv-a", "srv-b"]);

/* The execution_count tie-break is the #1907 residual and is pinned as part of the ORDER BY rather
than left to a looser Contains: collection_time alone was not a total order on rows collected
before that fix, where Query Store's flushed and in-memory slices of one interval were stored as
two rows sharing this whole partition AND collection_time. It cannot fire on rows collected since
— the collector combines the slices — so it exists for what is already stored (#1912). */
Assert.Contains(
"PARTITION BY server_id, server_name, database_name, query_id, plan_id, runtime_stats_interval_id, "
+ "first_execution_time, execution_type_desc, replica_role ORDER BY collection_time DESC",
+ "first_execution_time, execution_type_desc, replica_role ORDER BY collection_time DESC, execution_count DESC",
sql, StringComparison.Ordinal);
Assert.Contains("AS qs_rn", sql, StringComparison.Ordinal);
Assert.Contains("WHERE qs_rn = 1", sql, StringComparison.Ordinal);
Expand Down
152 changes: 152 additions & 0 deletions Darling/Darling.Tests/QueryStoreCorrectedRollupLiveTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -679,8 +679,160 @@ stop the others" is a claim about independent policies rather than about one rel
"tristate had to preserve.");
}

/// <summary>
/// #1907 against the real TimescaleDB: what the corrected rollups compute when an interval arrives as ONE
/// row per collection (the post-fix collector) versus as the two tied slice rows every pre-fix build
/// stored, proving the defect reached the materialized rollup and that the fix resolves it exactly.
///
/// <para>Query Store returns the flushed and the still-in-memory slice of one runtime_stats_interval_id as
/// two ADDITIVE rows. Stored as-is they share the L1 GROUP BY key AND <c>collection_time</c>, so
/// <c>last(execution_count, collection_time)</c> — the aggregate #1853 probed and chose because a CAGG
/// cannot contain a window function — is ordering by a value identical for both rows. It cannot sum them
/// and it cannot even choose between them. Whatever it returns is a SLICE, so the rollup understates the
/// interval no matter which row wins; on the live Azure store that was 8 reported against 94 true.</para>
///
/// <para>Both halves are asserted in ONE test on purpose. The post-fix number alone would pass against a
/// build that never had the bug, and the pre-fix number alone says nothing about whether the fix works —
/// it is the pair, in one store on one refresh, that shows the rollup arithmetic actually changed.</para>
/// </summary>
[Fact]
public async Task CorrectedRollups_SeeTheWholeInterval_OnlyWhenTheSlicesAreCombinedAtCollection()
{
var baseConnectionString = Environment.GetEnvironmentVariable("DARLING_TEST_PG");
Assert.SkipWhen(string.IsNullOrEmpty(baseConnectionString),
"Set DARLING_TEST_PG to a Postgres connection string (with TimescaleDB installed) to run the live #1907 slice-aggregation rollup test (it mints its own scratch database).");

var ct = TestContext.Current.CancellationToken;

await using var scratch = await ScratchPostgres.CreateAsync(baseConnectionString!, ct);
await using var connection = new NpgsqlConnection(scratch.ConnectionString);
await connection.OpenAsync(ct);
await PgMigrations.MigrateAsync(connection, ct);

Assert.True(await TimescaleSupport.TryEnableAsync(connection, null, ct),
"the dev fixture is expected to have TimescaleDB installed");
await TimescaleSupport.ConvertToHypertablesAsync(connection, null, ct);

var postFixHour = new DateTime(2026, 5, 6, 9, 0, 0, DateTimeKind.Unspecified);
var preFixHour = postFixHour.AddHours(1);

/* ── POST-FIX: the collector combines the slices, so each collection contributes exactly one row and
execution_count is the interval's running TOTAL. 40 -> 90 -> 125 is the live SQL 2022 repro's
arithmetic (100 flushed + 25 in memory = 125, cross-checked against dm_exec_procedure_stats)
arriving over three cycles. Honest answer for the interval: its last snapshot, 125. ── */
await SeedSnapshotsAsync(connection, intervalId: 7001, queryId: 61, planId: 91,
intervalStart: postFixHour, avgDurationUs: 100, avgCpuUs: 50,
snapshots:
[
(postFixHour.AddMinutes(5), 40L),
(postFixHour.AddMinutes(10), 90L),
(postFixHour.AddMinutes(15), 125L),
], ct: ct);

/* A second interval in the same hour, so the hour total is a sum of two deduped intervals rather than
one value that could be right by accident. */
await SeedSnapshotsAsync(connection, intervalId: 7002, queryId: 62, planId: 92,
intervalStart: postFixHour.AddMinutes(30), avgDurationUs: 200, avgCpuUs: 80,
snapshots:
[
(postFixHour.AddMinutes(35), 10L),
(postFixHour.AddMinutes(40), 30L),
], ct: ct);

/* ── PRE-FIX: the SAME interval and the SAME true total of 125, but stored the way it used to be —
the flushed slice (100) and the in-memory slice (25) as two rows at ONE collection_time. ── */
await SeedTiedSlicesAsync(connection, intervalId: 7003, queryId: 63, planId: 93,
intervalStart: preFixHour, collectionTime: preFixHour.AddMinutes(5),
sliceCounts: [100L, 25L], avgDurationUs: 100, avgCpuUs: 50, ct: ct);

await EnsureAggregatesWithoutRefreshPoliciesAsync(connection, ct);
await RefreshAllAsync(connection, ct);

/* ── 1. L1 collapses each interval to one row. Post-fix that row IS the interval's truth. ── */
var l1 = await ReadIntervalRowsAsync(connection, TimescaleSupport.QueryStoreStatsIntervalHourlyView, ct);

var combined = Assert.Single(l1, r => r.QueryId == 61);
Assert.Equal(125, combined.ExecutionCount);
Assert.Equal(7001L, combined.IntervalId);

var second = Assert.Single(l1, r => r.QueryId == 62);
Assert.Equal(30, second.ExecutionCount);

/* ── 2. THE HAND-COMPUTED HOUR. 125 + 30 = 155, and the weighted mean composes off the same two
deduped rows: (125 x 100 + 30 x 200) / 155. ── */
var correctedHour = await ReadCompositeAsync(connection, TimescaleSupport.QueryStoreStatsCorrectedHourlyView, postFixHour, ct);
Assert.Equal(155, correctedHour.ExecutionCountSum);
Assert.Equal(
((125d * 100d) + (30d * 200d)) / 155d,
correctedHour.DurationWeightedSum / correctedHour.ExecutionCountSum,
6);

/* ── 3. THE SPLIT SLICES, same store, same refresh. L1 still produces ONE row — the two slices share
its whole grouping key — but the value it carries is one SLICE, never the 125 they add up to.
Which slice is not asserted, because last() has no tie-break and picking one is not something
the engine promises; that it cannot reach 125 is the point, and it is what makes this an
under-count rather than a coin flip with a correct face. ── */
var split = Assert.Single(l1, r => r.QueryId == 63);
Assert.Equal(7003L, split.IntervalId);
Assert.Contains(split.ExecutionCount, new long[] { 100L, 25L });
Assert.NotEqual(125, split.ExecutionCount);

var splitHour = await ReadCompositeAsync(connection, TimescaleSupport.QueryStoreStatsCorrectedHourlyView, preFixHour, ct);
Assert.Equal(split.ExecutionCount, splitHour.ExecutionCountSum);
Assert.True(splitHour.ExecutionCountSum < 125,
$"the split-slice hour must UNDER-report the interval's true 125, got {splitHour.ExecutionCountSum}");

/* ── 4. The daily tier inherits both, so the defect and its fix are visible where history is kept
indefinitely — which is exactly why the pre-fix residual needed its own issue (#1912) rather
than an assumption that retention would carry it away. ── */
var correctedDay = await ReadCompositeAsync(connection, TimescaleSupport.QueryStoreStatsCorrectedDailyView, postFixHour.Date, ct);
Assert.Equal(155 + split.ExecutionCount, correctedDay.ExecutionCountSum);
}

/* ─────────────────────────── seeding + reading helpers ─────────────────────────── */

/// <summary>
/// Plants ONE Query Store interval as the pre-#1907 shape: several slice rows sharing a single
/// <c>collection_time</c> and the entire dedup key, differing only in <c>execution_count</c> — the flushed
/// slice and the still-in-memory slice as <c>sys.query_store_runtime_stats</c> hands them back and as
/// every build before #1907 stored them.
///
/// <para>Separate from <see cref="SeedSnapshotsAsync"/> because that helper derives one collection_id per
/// collection_time, which is precisely what cannot be done here: these rows SHARE a collection time, so
/// the id has to come from the slice's position instead.</para>
/// </summary>
private static async Task SeedTiedSlicesAsync(
NpgsqlConnection connection, long intervalId, long queryId, long planId, DateTime intervalStart,
DateTime collectionTime, long[] sliceCounts, long avgDurationUs, long avgCpuUs, CancellationToken ct)
{
const string sql = @"
INSERT INTO collect.query_store_stats
(collection_id, collection_time, server_id, server_name, database_name, module_name, query_hash,
query_id, plan_id, execution_type_desc, replica_role,
runtime_stats_interval_id, interval_start_time_utc, first_execution_time,
execution_count, avg_duration_us, avg_cpu_time_us, max_duration_us, max_cpu_time_us)
VALUES
((extract(epoch FROM $1)::bigint * 100000) + ($2 * 10) + $10, $1, $3, 'SQL01', 'AdventureWorks', 'dbo.GetOrders', '0xABCD',
$4, $5, 'Regular', 'PRIMARY', $2, $6, $6, $7, $8, $9, 900, 400)";

for (var slice = 0; slice < sliceCounts.Length; slice++)
{
await using var command = new NpgsqlCommand(sql, connection);
command.Parameters.AddWithValue(collectionTime);
command.Parameters.AddWithValue(intervalId);
command.Parameters.AddWithValue(TestServerId);
command.Parameters.AddWithValue(queryId);
command.Parameters.AddWithValue(planId);
command.Parameters.AddWithValue(intervalStart);
command.Parameters.AddWithValue(sliceCounts[slice]);
command.Parameters.AddWithValue(avgDurationUs);
command.Parameters.AddWithValue(avgCpuUs);
command.Parameters.AddWithValue(slice);
await command.ExecuteNonQueryAsync(ct);
}
}


/// <summary>
/// Plants one Query Store interval as <paramref name="snapshots"/> CUMULATIVE re-collections of the same
/// interval — <c>execution_count</c> running 1..n, which is what the collector actually stores when it
Expand Down
Loading
Loading