diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index f12f770bae..16b8853e01 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -725,8 +725,8 @@ jobs: # # The values are the product's own derivation from the live hypertable count # (TimescaleSupport.HypertableCount = the 62-collector catalog + collection_log = 63): - # timescaledb.max_background_workers = HypertableCount + 2 = 68 - # max_worker_processes = 3 + (HypertableCount + 2) + 8 = 79 + # timescaledb.max_background_workers = HypertableCount + 2 = 69 + # max_worker_processes = 3 + (HypertableCount + 2) + 8 = 80 # Hard-coded here because a workflow cannot call into the product — so # CiClusterWorkerSizingTests parses THIS FILE and fails the build if either number stops # matching the formula as collectors are added, and CiClusterWorkerSizingLiveTests asserts @@ -744,8 +744,8 @@ jobs: Add-Content -Path "$dataDir\postgresql.conf" -Value "shared_preload_libraries = 'timescaledb'" Add-Content -Path "$dataDir\postgresql.conf" -Value "port = 5541" Add-Content -Path "$dataDir\postgresql.conf" -Value "listen_addresses = '127.0.0.1'" - Add-Content -Path "$dataDir\postgresql.conf" -Value "timescaledb.max_background_workers = 68" - Add-Content -Path "$dataDir\postgresql.conf" -Value "max_worker_processes = 79" + Add-Content -Path "$dataDir\postgresql.conf" -Value "timescaledb.max_background_workers = 69" + Add-Content -Path "$dataDir\postgresql.conf" -Value "max_worker_processes = 80" & "$bin\pg_ctl.exe" -D $dataDir -l $logFile -w start if ($LASTEXITCODE -ne 0) { if (Test-Path $logFile) { Get-Content $logFile -Tail 50 }; throw "pg_ctl start failed ($LASTEXITCODE)" } & "$bin\createdb.exe" -h 127.0.0.1 -p 5541 -U darling darling diff --git a/.github/workflows/nightly.yml b/.github/workflows/nightly.yml index 740258cd88..94a64601c2 100644 --- a/.github/workflows/nightly.yml +++ b/.github/workflows/nightly.yml @@ -369,8 +369,8 @@ jobs: # customer runs and made scheduler-racing failures luck-of-the-slot instead of reproducible. # Values are the product's own derivation from the live hypertable count # (TimescaleSupport.HypertableCount = the 62-collector catalog + collection_log = 63): - # timescaledb.max_background_workers = HypertableCount + 2 = 68 - # max_worker_processes = 3 + (HypertableCount + 2) + 8 = 79 + # timescaledb.max_background_workers = HypertableCount + 2 = 69 + # max_worker_processes = 3 + (HypertableCount + 2) + 8 = 80 # Kept honest by CiClusterWorkerSizingTests (parses this file against the formula) and # CiClusterWorkerSizingLiveTests (asserts the running cluster serves them). Must configure # the cluster identically to build.yml's darling-pg job: that guard parses the appended @@ -391,8 +391,8 @@ jobs: Add-Content -Path "$dataDir\postgresql.conf" -Value "shared_preload_libraries = 'timescaledb'" Add-Content -Path "$dataDir\postgresql.conf" -Value "port = 5541" Add-Content -Path "$dataDir\postgresql.conf" -Value "listen_addresses = '127.0.0.1'" - Add-Content -Path "$dataDir\postgresql.conf" -Value "timescaledb.max_background_workers = 68" - Add-Content -Path "$dataDir\postgresql.conf" -Value "max_worker_processes = 79" + Add-Content -Path "$dataDir\postgresql.conf" -Value "timescaledb.max_background_workers = 69" + Add-Content -Path "$dataDir\postgresql.conf" -Value "max_worker_processes = 80" & "$bin\pg_ctl.exe" -D $dataDir -l $logFile -w start if ($LASTEXITCODE -ne 0) { if (Test-Path $logFile) { Get-Content $logFile -Tail 50 }; throw "pg_ctl start failed ($LASTEXITCODE)" } & "$bin\createdb.exe" -h 127.0.0.1 -p 5541 -U darling darling diff --git a/CHANGELOG.md b/CHANGELOG.md index 8e476e2030..a831c0cc5b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] ### Added +- **PostgreSQL execution plans, captured and redacted** ([#2566], part of [#2538]) - schema **v99** adds `collect.pg_plan_capture`, reading `auto_explain`'s JSON output out of the server log. **Its own table, NOT `query_plan_dim`**: that one holds SQL Server plan XML and `plan_xml_compression = none` is a documented contract with direct-SQL consumers who read the column AS XML - dropping JSON rows into it would break their dashboards with no schema change to notice, no error, and no version to key off. **No query text and no literals reach the store, and that is the load-bearing part.** `auto_explain` emits `Query Text` verbatim and `auto_explain.log_parameter_max_length = 0` does NOT suppress it (that setting covers bind parameters only - measured on #2565); literals also sit inside the plan tree in `Filter` and its relatives. So the text is dropped outright - statement identity is `query_id`, whose normalised text already lives in `pg_statement_stats` - and every remaining string is redacted before storage. **Redaction is deliberately asymmetric**: quoted literals go from every string, but bare numbers only from condition fields, because a blanket numeric strip would rewrite a relation genuinely named `transactionitems1` into `transactionitems?` - destroying identity to hide a value that was never there. Verified against 25 real captured plans: **zero literals survived**, and the digit-bearing name survived intact. `plan_hash` is taken of the REDACTED plan so the same shape recurs to the same hash whatever values it ran with. The log read is **bounded to a 4 MB tail** because #2565 measured 772 MB of log in twenty seconds at capture-everything, and truncated blocks at the window edge are skipped rather than stored half-parsed. **Self-hosted in practice**: reading the log needs `pg_read_server_files` AND an explicit `GRANT EXECUTE ON FUNCTION pg_read_file` - measured, the role alone does NOT carry it, because the function's ACL is `postgres=X/postgres` - and on Aurora or RDS there is no filesystem at all, so the panel stays empty by design and says so. - **Which PostgreSQL columns are filtered on, and where the planner is wrong about them** ([#2603]) - `pg_index_usage_stats` records indexes that were USED; schema **v98** adds `collect.pg_predicate_stats` from `pg_qualstats`, which records predicates that were EVALUATED **including the ones with no index behind them**. That is the index-candidate signal, and it is invisible to every other collector because nothing records a scan that had no index to record. **The counts are a SAMPLE and the rate is stored on every row**: `pg_qualstats.sample_rate` defaults to `1/max_connections` - 0.01 on the verification rig, where `pg_qualstats()` returned ZERO rows on a server that had just run the queries it was meant to record. A small count means the sampler fired rarely, not that the predicate is rare, and the counts are deliberately NOT scaled up by the rate because three observations at 1% is not three hundred. **`worst_estimate_error_ratio` is a different problem from selectivity** - measured at **57.9x** on one predicate beside 1.04x on another: the first means the plan was built on a wrong row count, which an index will not fix. **Runs per database, and that is load-bearing**: the function returns cluster-wide rows keyed by `dbid`, but `lrelid`/`lattnum` are OIDs meaningful only inside their own database while `pg_class` and `pg_attribute` are per-database catalogs - unscoped, the join either silently DROPS other databases' rows or resolves them against whatever local object shares the OID and reports a confident wrong column name. Measured: two cross-database rows present, neither colliding locally that day, so the failure would have been silent loss and different OID luck would have produced the wrong name. The extension is itself per-database, so databases without it degrade to a named non-fatal skip. - **OS CPU and disk per query on PostgreSQL** ([#2603]) - `pg_stat_statements` reports elapsed time, which cannot separate a query that was WAITING from one burning processor. Schema **v97** adds `collect.pg_kernel_stats` from `pg_stat_kcache`: the kernel's own user CPU, system CPU and bytes that reached the disk, keyed by the same `queryid` so the two halves compose. **`exec_read_bytes = 0` does NOT mean the query read nothing** - the counters come from `getrusage` and measure I/O that reached the DEVICE, so a read served by the OS page cache is genuinely zero, which was the case on every row of the verification rig while writes were not. Zero reads with high CPU is a cached workload working properly; it is not comparable to a logical-read figure, and the columns are named `_bytes` so nothing in a SQL Server codebase reads them as one. **Only top-level statements are collected**: with `pg_stat_statements.track = 'all'` a nested statement appears both on its own row and inside its caller's, and summing them double-counts every function body on the server - the rig ran `track = 'top'` where that filter is inert, which is exactly why it is pinned rather than remembered. Times convert seconds to milliseconds once, in the collector, because a column named `_ms` holding seconds is wrong by a thousand and looks entirely plausible. Ranked by **CPU**, not bytes. Cumulative like the wait profile, but this table can do better than inferring a reset from a counter moving backwards: `stats_since` is collected, so the read detects a reset from the stamp changing AND from the backwards check. **Carries `database_name`, and that is not a contradiction of v95** - the function exposes `dbid` and `pg_database` is a SHARED catalog, so the name resolves correctly from any connection; `pg_wait_sampling` omits it because its catalog genuinely cannot support the claim. - **PostgreSQL wait analysis stops being Aurora-only** ([#2603]) - `PgWaitStatsCollector` reads `aurora_stat_system_waits()`, so every self-hosted, on-prem and plain-RDS target had **no wait data at all**, which is backwards: self-hosted is where the extension story is richest. Schema **v96** adds `collect.pg_wait_sampling` from the `pg_wait_sampling` module, attributing each wait to the `queryid` that waited so it joins `pg_statement_stats` - the "which query waited on what" question this product answers on SQL Server. **Every design choice came from running it.** `event_type = 'Activity'` is excluded at the source: measured on an idle PostgreSQL 17 the entire top of the raw profile was background processes waiting for work (`AutovacuumMain`, `LogicalLauncherMain`, `WalWriterMain`, `CheckpointerMain`), accumulating samples forever precisely BECAUSE nothing was happening, while attributed waits returned nothing at all - rank that and every healthy server reports autovacuum's idle loop as its top wait. The filter is `IS DISTINCT FROM`, never `<>`, because a NULL event means the backend was **not waiting** and `NULL <> 'Activity'` is NULL rather than true, which would silently discard every on-CPU sample; those are kept and labelled **`CPU`/`Running`** instead of stored as a blank row that sorts near the top of a count-ranked grid (23 samples across 11 backends arrived exactly that way). **`sample_count` is a tally, not a duration** - `profile_period_ms` travels beside it because a count is uninterpretable alone, and the samples-to-milliseconds multiplication happens once in the read where the header says *Est. Wait*. The profile is **cumulative**, so a counter going BACKWARDS is a reset (`pg_wait_sampling_reset_profile`, or a restart nobody chose) rather than a negative wait: the read uses the newest value whole in that case and flags `counter_reset`, where `GREATEST(new - old, 0)` would have quietly reported zero waits across a restart. **No `database_name`, deliberately** - the profile is cluster-wide and version 1.1 exposes no database column, so claiming that attribution would be the same scope error v95 removed from three other tables. Absent module degrades to a named non-fatal skip, and the Extensions panel says whether installing it would help. diff --git a/Darling/Darling.Tests/PgSchemaGeneratorTests.cs b/Darling/Darling.Tests/PgSchemaGeneratorTests.cs index 7aa1bf2096..0a0060b5a0 100644 --- a/Darling/Darling.Tests/PgSchemaGeneratorTests.cs +++ b/Darling/Darling.Tests/PgSchemaGeneratorTests.cs @@ -45,13 +45,13 @@ Availability Group collectors (#991) = 38, plus plan_correction (#1952 automatic the planner statistics that explain WHY a plan was chosen) = 59, plus pg_replication_stats (#2544, connected standbys as distinct from slots) = 60, plus pg_buffer_usage (#2544, what is resident in shared buffers) = 61, plus - pg_index_bloat (#2561) and pg_wait_sampling, pg_kernel_stats and pg_predicate_stats (#2603) = 65. The catalog is + pg_index_bloat (#2561) and pg_wait_sampling, pg_kernel_stats, pg_predicate_stats (#2603) and pg_plan_capture (#2566) = 66. The catalog is deliberately engine-mixed: the schema generator walks it to create tables and one store can hold both engines' data, so splitting it per engine would fragment DDL generation. Dispatch is gated separately, by engine, in CollectorCatalog.AppliesTo(definition, target). */ - Assert.Equal(65, CollectorCatalog.All.Count); + Assert.Equal(66, CollectorCatalog.All.Count); /* Uniqueness is asserted AGAINST THE COUNT rather than against a second literal. The literals here had drifted to 45 while the real figure tracked the count, so the test that exists to catch a @@ -635,6 +635,7 @@ public void EveryPostgresRung_IsIdenticalToTheGeneratedSchema() (96, PgWaitSamplingCollector.Instance), (97, PgKernelStatsCollector.Instance), (98, PgPredicateStatsCollector.Instance), + (99, PgPlanCaptureCollector.Instance), }; /* Every PostgreSQL collector must appear above. One added without a rung listed here would diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs index f03565faf7..f74323702e 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs @@ -4677,6 +4677,7 @@ await DarlingObservability.LogCollectionAsync( ["pg_wait_sampling"] = (r, s, ct) => r.RunAsync(PgWaitSamplingCollector.Instance, s, ct), ["pg_kernel_stats"] = (r, s, ct) => r.RunAsync(PgKernelStatsCollector.Instance, s, ct), ["pg_predicate_stats"] = (r, s, ct) => r.RunAsync(PgPredicateStatsCollector.Instance, s, ct), + ["pg_plan_capture"] = (r, s, ct) => r.RunAsync(PgPlanCaptureCollector.Instance, s, ct), ["pg_column_stats"] = (r, s, ct) => r.RunAsync(PgColumnStatsCollector.Instance, s, ct), ["pg_replication_stats"] = (r, s, ct) => r.RunAsync(PgReplicationStatsCollector.Instance, s, ct), ["pg_buffer_usage"] = (r, s, ct) => r.RunAsync(PgBufferUsageCollector.Instance, s, ct), diff --git a/Darling/PerformanceMonitor.Darling.Storage/DarlingPgPlanCaptureReader.cs b/Darling/PerformanceMonitor.Darling.Storage/DarlingPgPlanCaptureReader.cs new file mode 100644 index 0000000000..a06589e8c7 --- /dev/null +++ b/Darling/PerformanceMonitor.Darling.Storage/DarlingPgPlanCaptureReader.cs @@ -0,0 +1,109 @@ +/* + * Copyright (c) 2026 Erik Darling, Darling Data LLC + * + * This file is part of the SQL Server Performance Monitor Lite. + * + * Licensed under the MIT License. See LICENSE file in the project root for full license information. + */ + +using System; +using System.Collections.Generic; +using System.Threading; +using System.Threading.Tasks; +using Npgsql; + +namespace PerformanceMonitor.Darling.Storage; + +/// +/// Reads collect.pg_plan_capture — plans captured by auto_explain (#2566). +/// +/// Grouped by plan, not by capture. The collector reads a bounded tail of the log every cycle, +/// so the same plan is legitimately captured many times — and the overlapping window means the SAME +/// execution can be seen twice. Returning raw captures would rank by how often the reader happened to look. +/// Rows are grouped on (query_id, plan_hash), which is what makes "this shape ran a lot and is slow" +/// answerable at all. +/// +/// The plan JSON returned here is already redacted — the collector strips it before storage, so +/// there is no un-redacted copy anywhere for a read to leak. Nothing here needs to re-check that, and +/// nothing here should re-derive it. +/// +/// Ranked by TOTAL duration rather than max: a plan that takes 40 ms and runs constantly costs more +/// than one that took 900 ms once, and the second is usually a cold cache. +/// +public static class DarlingPgPlanCaptureReader +{ + /// How many times this shape was seen. A count of the CAPTURES, which the + /// overlapping tail read can inflate — treat it as a frequency signal rather than an execution count; + /// pg_statement_stats.calls is the authority on that. + /// Redacted at collection. Literals and query text never reach the store. + public sealed record PgPlanCaptureRow( + long QueryId, + string? PlanHash, + string? TopNodeType, + int NodeCount, + long Captures, + double TotalDurationMs, + double MaxDurationMs, + double AvgDurationMs, + string? PlanJson, + DateTime LastSeen); + + /* DISTINCT ON inside the aggregate is not what is wanted here: the JSON is identical for a given + plan_hash by construction (the hash is OF the redacted JSON), so any row's copy will do and min() + avoids a second scan to pick one. */ + public const string PgPlanCaptureSql = """ + SELECT + query_id, + plan_hash, + min(top_node_type) AS top_node_type, + max(node_count) AS node_count, + count(*) AS captures, + sum(duration_ms) AS total_duration_ms, + max(duration_ms) AS max_duration_ms, + avg(duration_ms) AS avg_duration_ms, + min(plan_json) AS plan_json, + max(collection_time) AS last_seen + FROM pg_plan_capture + WHERE server_id = $1 + AND collection_time >= $2 + AND collection_time <= $3 + GROUP BY query_id, plan_hash + ORDER BY sum(duration_ms) DESC + LIMIT $4 + """; + + public static async Task> GetPgPlanCaptureAsync( + NpgsqlDataSource postgres, int serverId, DateTime startUtc, DateTime endUtc, int limit, + CancellationToken cancellationToken = default) + { + ArgumentNullException.ThrowIfNull(postgres); + + var rows = new List(); + await using var command = postgres.CreateCommand(PgPlanCaptureSql); + command.Parameters.AddWithValue(serverId); + /* SpecifyKind(Unspecified) at the BIND, the convention every PostgreSQL read here follows. */ + command.Parameters.AddWithValue(DateTime.SpecifyKind(startUtc, DateTimeKind.Unspecified)); + command.Parameters.AddWithValue(DateTime.SpecifyKind(endUtc, DateTimeKind.Unspecified)); + command.Parameters.AddWithValue(limit); + + await using var reader = await command.ExecuteReaderAsync(cancellationToken); + while (await reader.ReadAsync(cancellationToken)) + { + rows.Add(new PgPlanCaptureRow( + QueryId: reader.IsDBNull(0) ? 0 : reader.GetInt64(0), + PlanHash: reader.IsDBNull(1) ? null : reader.GetString(1), + TopNodeType: reader.IsDBNull(2) ? null : reader.GetString(2), + NodeCount: reader.IsDBNull(3) ? 0 : reader.GetInt32(3), + Captures: reader.IsDBNull(4) ? 0 : reader.GetInt64(4), + TotalDurationMs: reader.IsDBNull(5) ? 0 : reader.GetDouble(5), + MaxDurationMs: reader.IsDBNull(6) ? 0 : reader.GetDouble(6), + AvgDurationMs: reader.IsDBNull(7) ? 0 : Convert.ToDouble(reader.GetValue(7)), + PlanJson: reader.IsDBNull(8) ? null : reader.GetString(8), + LastSeen: reader.IsDBNull(9) + ? default + : DateTime.SpecifyKind(reader.GetDateTime(9), DateTimeKind.Utc))); + } + + return rows; + } +} diff --git a/Darling/PerformanceMonitor.Darling.Storage/PgMigrations.cs b/Darling/PerformanceMonitor.Darling.Storage/PgMigrations.cs index dc9c17600a..58f737a9e3 100644 --- a/Darling/PerformanceMonitor.Darling.Storage/PgMigrations.cs +++ b/Darling/PerformanceMonitor.Darling.Storage/PgMigrations.cs @@ -155,6 +155,7 @@ here costs a fresh-through-this-rung store nothing and rung 54's own copy no-ops new Migration(96, "pg-wait-sampling", V96Sql), new Migration(97, "pg-kernel-stats", V97Sql), new Migration(98, "pg-predicate-stats", V98Sql), + new Migration(99, "pg-plan-capture", V99Sql), }; /// @@ -2272,6 +2273,48 @@ pool_buffers_used bigint CREATE INDEX IF NOT EXISTS idx_pg_buffer_usage_time ON collect.pg_buffer_usage(server_id, collection_time);"; + /// + /// V99 — collect.pg_plan_capture (#2566, part of #2538): execution plans captured by + /// auto_explain and read out of the server log. + /// + /// Its own table, NOT query_plan_dim. That table holds SQL Server plan XML and + /// plan_xml_compression = none is a documented contract with direct-SQL consumers who read the + /// column as XML. Introducing JSON rows into it would break those readers silently — no schema change to + /// notice, no error, no version to key off. The compression codec and + /// plan_content_retention_days machinery is shared; the table is not. + /// + /// No query text and no literals, and that is the load-bearing part. auto_explain + /// emits Query Text verbatim, and auto_explain.log_parameter_max_length = 0 does NOT + /// suppress it — that setting covers bind parameters only (measured, #2565). Literals also sit inside the + /// plan tree in Filter and its relatives. So the text is dropped — statement identity is + /// query_id, whose normalised text already lives in pg_statement_stats — and every + /// remaining string is redacted before storage. Verified against 25 captured plans: zero literals + /// survived, while a relation genuinely named transactionitems1 kept its name. + /// + /// plan_hash is of the REDACTED plan, so the same plan shape recurs to the same hash + /// whatever values it ran with. Hashing the raw text would defeat dedup exactly where it matters most. + /// + /// Self-hosted only in practice: reading the log needs pg_read_server_files AND an explicit + /// GRANT EXECUTE ON FUNCTION pg_read_file (the role alone does not carry it — measured). Aurora and + /// RDS have no filesystem and require the RDS API instead, which is a different integration (#2538). + /// + private const string V99Sql = @" +CREATE TABLE IF NOT EXISTS collect.pg_plan_capture ( + collection_id bigint NOT NULL, + collection_time timestamp NOT NULL, + server_id integer NOT NULL, + server_name text NOT NULL, + query_id bigint, + plan_hash text, + duration_ms double precision, + node_count integer, + top_node_type text, + plan_json text +); + +CREATE INDEX IF NOT EXISTS idx_pg_plan_capture_time + ON collect.pg_plan_capture(server_id, collection_time);"; + /// /// V98 — collect.pg_predicate_stats (#2603): which columns are filtered on, how selectively, and /// where the planner's estimate was wrong, from pg_qualstats. diff --git a/Darling/PerformanceMonitor.Darling.Storage/StorageVersion.cs b/Darling/PerformanceMonitor.Darling.Storage/StorageVersion.cs index b7eb3af8d1..d17aed6649 100644 --- a/Darling/PerformanceMonitor.Darling.Storage/StorageVersion.cs +++ b/Darling/PerformanceMonitor.Darling.Storage/StorageVersion.cs @@ -16,5 +16,5 @@ namespace PerformanceMonitor.Darling.Storage; /// public static class StorageVersion { - public const int SchemaVersion = 98; + public const int SchemaVersion = 99; } diff --git a/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Postgres.cs b/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Postgres.cs index 45d49cd2d8..055d886074 100644 --- a/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Postgres.cs +++ b/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Postgres.cs @@ -362,6 +362,14 @@ confusing of the two. */ int serverId, DateTime startUtc, DateTime endUtc, int limit, CancellationToken cancellationToken = default) => DarlingPgPredicateStatsReader.GetPgPredicateStatsAsync(_dataSource, serverId, startUtc, endUtc, limit, cancellationToken); + /// + /// Plans captured by auto_explain (#2566), grouped by shape. The JSON is redacted at collection — there + /// is no un-redacted copy in the store for this read to expose. + /// + public Task> GetPgPlanCaptureAsync( + int serverId, DateTime startUtc, DateTime endUtc, int limit, CancellationToken cancellationToken = default) => + DarlingPgPlanCaptureReader.GetPgPlanCaptureAsync(_dataSource, serverId, startUtc, endUtc, limit, cancellationToken); + /// Storage tab - per-column planner statistics (#2543), latest per column and ranked by /// suspicion rather than alphabetically: heavy skew first (the parameter-sensitivity signal), then low /// correlation (why an index scan was rejected). Zero rows has TWO causes - no qualifying table, or a diff --git a/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.cs b/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.cs index 4f38485b11..f4f621559d 100644 --- a/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.cs +++ b/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.cs @@ -674,7 +674,8 @@ existence cannot separate the rungs and information_schema.columns is the only s AND column_name = 'database_name'), EXISTS (SELECT 1 FROM information_schema.tables WHERE table_name = 'pg_wait_sampling'), EXISTS (SELECT 1 FROM information_schema.tables WHERE table_name = 'pg_kernel_stats'), - EXISTS (SELECT 1 FROM information_schema.tables WHERE table_name = 'pg_predicate_stats')"; + EXISTS (SELECT 1 FROM information_schema.tables WHERE table_name = 'pg_predicate_stats'), + EXISTS (SELECT 1 FROM information_schema.tables WHERE table_name = 'pg_plan_capture')"; /// The store schema version this viewer build requires — the highest migration it knows /// (). The connect-time gate blocks a store below this. @@ -695,7 +696,7 @@ existence cannot separate the rungs and information_schema.columns is the only s await using var reader = await command.ExecuteReaderAsync(cancellationToken); if (await reader.ReadAsync(cancellationToken)) { - return MapProbedSchemaVersion(reader.GetBoolean(0), reader.GetBoolean(1), reader.GetBoolean(2), reader.GetBoolean(3), reader.GetBoolean(4), reader.GetBoolean(5), reader.GetBoolean(6), reader.GetBoolean(7), reader.GetBoolean(8), reader.GetBoolean(9), reader.GetBoolean(10), reader.GetBoolean(11), reader.GetBoolean(12), reader.GetBoolean(13), reader.GetBoolean(14), reader.GetBoolean(15), reader.GetBoolean(16), reader.GetBoolean(17), reader.GetBoolean(18), reader.GetBoolean(19), reader.GetBoolean(20), reader.GetBoolean(21), reader.GetBoolean(22), reader.GetBoolean(23), reader.GetBoolean(24), reader.GetBoolean(25), reader.GetBoolean(26), reader.GetBoolean(27), reader.GetBoolean(28), reader.GetBoolean(29), reader.GetBoolean(30), reader.GetBoolean(31), reader.GetBoolean(32), reader.GetBoolean(33), reader.GetBoolean(34), reader.GetBoolean(35), reader.GetBoolean(36), reader.GetBoolean(37), reader.GetBoolean(38), reader.GetBoolean(39), reader.GetBoolean(40), reader.GetBoolean(41), reader.GetBoolean(42), reader.GetBoolean(43), reader.GetBoolean(44), reader.GetBoolean(45), reader.GetBoolean(46), reader.GetBoolean(47), reader.GetBoolean(48), reader.GetBoolean(49), reader.GetBoolean(50), reader.GetBoolean(51), reader.GetBoolean(52), reader.GetBoolean(53), reader.GetBoolean(54), reader.GetBoolean(55), reader.GetBoolean(56), reader.GetBoolean(57), reader.GetBoolean(58), reader.GetBoolean(59), reader.GetBoolean(60), reader.GetBoolean(61), reader.GetBoolean(62), reader.GetBoolean(63), reader.GetBoolean(64), reader.GetBoolean(65), reader.GetBoolean(66), reader.GetBoolean(67), reader.GetBoolean(68), reader.GetBoolean(69), reader.GetBoolean(70), reader.GetBoolean(71), reader.GetBoolean(72), reader.GetBoolean(73)); + return MapProbedSchemaVersion(reader.GetBoolean(0), reader.GetBoolean(1), reader.GetBoolean(2), reader.GetBoolean(3), reader.GetBoolean(4), reader.GetBoolean(5), reader.GetBoolean(6), reader.GetBoolean(7), reader.GetBoolean(8), reader.GetBoolean(9), reader.GetBoolean(10), reader.GetBoolean(11), reader.GetBoolean(12), reader.GetBoolean(13), reader.GetBoolean(14), reader.GetBoolean(15), reader.GetBoolean(16), reader.GetBoolean(17), reader.GetBoolean(18), reader.GetBoolean(19), reader.GetBoolean(20), reader.GetBoolean(21), reader.GetBoolean(22), reader.GetBoolean(23), reader.GetBoolean(24), reader.GetBoolean(25), reader.GetBoolean(26), reader.GetBoolean(27), reader.GetBoolean(28), reader.GetBoolean(29), reader.GetBoolean(30), reader.GetBoolean(31), reader.GetBoolean(32), reader.GetBoolean(33), reader.GetBoolean(34), reader.GetBoolean(35), reader.GetBoolean(36), reader.GetBoolean(37), reader.GetBoolean(38), reader.GetBoolean(39), reader.GetBoolean(40), reader.GetBoolean(41), reader.GetBoolean(42), reader.GetBoolean(43), reader.GetBoolean(44), reader.GetBoolean(45), reader.GetBoolean(46), reader.GetBoolean(47), reader.GetBoolean(48), reader.GetBoolean(49), reader.GetBoolean(50), reader.GetBoolean(51), reader.GetBoolean(52), reader.GetBoolean(53), reader.GetBoolean(54), reader.GetBoolean(55), reader.GetBoolean(56), reader.GetBoolean(57), reader.GetBoolean(58), reader.GetBoolean(59), reader.GetBoolean(60), reader.GetBoolean(61), reader.GetBoolean(62), reader.GetBoolean(63), reader.GetBoolean(64), reader.GetBoolean(65), reader.GetBoolean(66), reader.GetBoolean(67), reader.GetBoolean(68), reader.GetBoolean(69), reader.GetBoolean(70), reader.GetBoolean(71), reader.GetBoolean(72), reader.GetBoolean(73), reader.GetBoolean(74)); } return null; @@ -720,7 +721,7 @@ existence cannot separate the rungs and information_schema.columns is the only s /// is unit-tested without a live store; any schema bump past the newest arm trips the pinning test that keeps /// this in step with . /// - internal static int MapProbedSchemaVersion(bool hasConfigControlPlane, bool hasAlertDeliveryOverride, bool hasAnalysisState, bool hasAlertTuningKnobs, bool hasDefaultTraceEvents, bool hasIndexObjectStatsLatestIndex, bool hasCollectionLogHypertableOrPlainPg, bool hasJobHistory, bool hasAgentStatus, bool hasGenericWebhook, bool hasDeadlocksDatabaseName, bool hasQueryStoreReplicaRole, bool hasLongQueryCompletions, bool hasWebDashboardConfig, bool hasCustomViews, bool hasServerTags, bool hasConnectionRefireKnobs = false, bool hasAgCollectors = false, bool hasAgAlertKnobs = false, bool hasAgLatencyColumns = false, bool hasAgDisconnectRefire = false, bool hasPayloadDimensions = false, bool hasDimFloorIndexes = false, bool hasBlockingWaitThreshold = false, bool hasQueryStoreIntervalIdentity = false, bool hasPagerDutyWebhook = false, bool hasPagerDutyProxy = false, bool hasCollectorState = false, bool hasPlanCorrection = false, bool hasPvsStats = false, bool hasPvsPressureKnobs = false, bool hasDatabaseStateAlert = false, bool hasServerTagColour = false, bool hasQueryStatsHostObject = false, bool hasFindingDrillDown = false, bool hasStoreMetrics = false, bool hasPlanDimGzip = false, bool hasSelfAlertKnobs = false, bool hasJobMetricsColumns = false, bool hasJobCadenceKnob = false, bool hasBackfillSwitch = false, bool hasCollectorMemoryKnobs = false, bool hasDatabaseStateEdgeMemory = false, bool hasIncidentOccurrences = false, bool hasPlanXmlCompressionKnob = false, bool hasMonitoredServerEngine = false, bool hasPgBlockingEdges = false, bool hasQueryStorePlanMap = false, bool hasPgStatementText = false, bool hasQueryStoreText = false, bool hasPlanContentRetentionKnob = false, bool hasQueryStoreHealth = false, bool hasQueryStoreTextHash = false, bool hasComposeTimeoutKnob = false, bool hasFileGrowthAlert = false, bool hasCollectionLogFanoutRollup = false, bool hasTempDbMaxSize = false, bool hasServerEngineKind = false, bool hasPgDatabaseStats = false, bool hasPgIndexUsageStats = false, bool hasPgTableBloatStats = false, bool hasPgSessionStates = false, bool hasPgPlanCaptureReadiness = false, bool hasPgWriteStats = false, bool hasPgExtensionAvailability = false, bool hasPgLockStats = false, bool hasPgColumnStats = false, bool hasPgReplicationStats = false, bool hasPgBufferUsage = false, bool hasPgIndexBloat = false, bool hasPgPerDatabaseAttribution = false, bool hasPgWaitSampling = false, bool hasPgKernelStats = false, bool hasPgPredicateStats = false) + internal static int MapProbedSchemaVersion(bool hasConfigControlPlane, bool hasAlertDeliveryOverride, bool hasAnalysisState, bool hasAlertTuningKnobs, bool hasDefaultTraceEvents, bool hasIndexObjectStatsLatestIndex, bool hasCollectionLogHypertableOrPlainPg, bool hasJobHistory, bool hasAgentStatus, bool hasGenericWebhook, bool hasDeadlocksDatabaseName, bool hasQueryStoreReplicaRole, bool hasLongQueryCompletions, bool hasWebDashboardConfig, bool hasCustomViews, bool hasServerTags, bool hasConnectionRefireKnobs = false, bool hasAgCollectors = false, bool hasAgAlertKnobs = false, bool hasAgLatencyColumns = false, bool hasAgDisconnectRefire = false, bool hasPayloadDimensions = false, bool hasDimFloorIndexes = false, bool hasBlockingWaitThreshold = false, bool hasQueryStoreIntervalIdentity = false, bool hasPagerDutyWebhook = false, bool hasPagerDutyProxy = false, bool hasCollectorState = false, bool hasPlanCorrection = false, bool hasPvsStats = false, bool hasPvsPressureKnobs = false, bool hasDatabaseStateAlert = false, bool hasServerTagColour = false, bool hasQueryStatsHostObject = false, bool hasFindingDrillDown = false, bool hasStoreMetrics = false, bool hasPlanDimGzip = false, bool hasSelfAlertKnobs = false, bool hasJobMetricsColumns = false, bool hasJobCadenceKnob = false, bool hasBackfillSwitch = false, bool hasCollectorMemoryKnobs = false, bool hasDatabaseStateEdgeMemory = false, bool hasIncidentOccurrences = false, bool hasPlanXmlCompressionKnob = false, bool hasMonitoredServerEngine = false, bool hasPgBlockingEdges = false, bool hasQueryStorePlanMap = false, bool hasPgStatementText = false, bool hasQueryStoreText = false, bool hasPlanContentRetentionKnob = false, bool hasQueryStoreHealth = false, bool hasQueryStoreTextHash = false, bool hasComposeTimeoutKnob = false, bool hasFileGrowthAlert = false, bool hasCollectionLogFanoutRollup = false, bool hasTempDbMaxSize = false, bool hasServerEngineKind = false, bool hasPgDatabaseStats = false, bool hasPgIndexUsageStats = false, bool hasPgTableBloatStats = false, bool hasPgSessionStates = false, bool hasPgPlanCaptureReadiness = false, bool hasPgWriteStats = false, bool hasPgExtensionAvailability = false, bool hasPgLockStats = false, bool hasPgColumnStats = false, bool hasPgReplicationStats = false, bool hasPgBufferUsage = false, bool hasPgIndexBloat = false, bool hasPgPerDatabaseAttribution = false, bool hasPgWaitSampling = false, bool hasPgKernelStats = false, bool hasPgPredicateStats = false, bool hasPgPlanCapture = false) { /* V71 (the PostgreSQL blocking-edges rung): a table-existence sentinel and now the newest-first arm. A collector table would ordinarily get no arm at all — see the V63-V69 note below — but the TOP @@ -807,9 +808,16 @@ The three comment blocks that used to stack here were moved down onto the arms t (#2530 → V82, #2539 → V83, #2542 → V85). They had drifted upward as each new rung inserted its own block above them, which is how a comment ends up explaining an arm two rungs away from the one it was written for. Keep the block with its arm. */ - /* V98 (#2603): pg_predicate_stats. The TOP rung, so it must map exactly — + /* V99 (#2566): pg_plan_capture. The TOP rung, so it must map exactly — RequiredStoreSchemaVersion is StorageVersion.SchemaVersion and a fully-migrated store has to land - here rather than on V97. */ + here rather than on V98. */ + if (hasPgPlanCapture) + { + return 99; + } + + /* V98 (#2603): pg_predicate_stats. Was the top rung until V99 landed and keeps its own arm, because + a store stopped between the two is a real state during an interrupted upgrade. */ if (hasPgPredicateStats) { return 98; diff --git a/Darling/PerformanceMonitor.Darling.Viewer/ViewerPostgresTabs.cs b/Darling/PerformanceMonitor.Darling.Viewer/ViewerPostgresTabs.cs index fc41ee8cd2..c0e0dcfb56 100644 --- a/Darling/PerformanceMonitor.Darling.Viewer/ViewerPostgresTabs.cs +++ b/Darling/PerformanceMonitor.Darling.Viewer/ViewerPostgresTabs.cs @@ -94,7 +94,7 @@ appears with the reason it is missing. */ ViewerServerTab.PgActivityInnerTabIndex, "activity", "Activity", - new[] { "pg_blocking", "pg_lock_stats", "pg_statement_stats", "pg_database_stats", "pg_kernel_stats" }, + new[] { "pg_blocking", "pg_lock_stats", "pg_statement_stats", "pg_database_stats", "pg_kernel_stats", "pg_plan_capture" }, /* pg_database_stats sits under the statement grid rather than on a tab of its own because it answers the question the statement grid raises and cannot answer: a statement whose time makes no sense from its row count usually spilled, and pg_stat_database's temp counters are diff --git a/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.Postgres.cs b/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.Postgres.cs index 98d82672b6..3e445dcda7 100644 --- a/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.Postgres.cs +++ b/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.Postgres.cs @@ -256,6 +256,7 @@ reason the read carries capture counts from collection_log. */ await LoadPgWaitSamplingAsync(startUtc, endUtc); await LoadPgKernelStatsAsync(startUtc, endUtc); await LoadPgPredicateStatsAsync(startUtc, endUtc); + await LoadPgPlanCaptureAsync(startUtc, endUtc); } /// @@ -416,6 +417,45 @@ private async Task LoadPgPredicateStatsAsync(DateTime startUtc, DateTime endUtc) + "fix a plan built on a wrong row count."; } + /// + /// Plans captured by auto_explain (#2566). + /// + /// An empty grid here almost always means a MISSING GRANT rather than a quiet server, so the + /// note says so: reading the log needs pg_read_server_files plus an explicit EXECUTE on pg_read_file, + /// and on Aurora or RDS the route does not exist at all. + /// + private async Task LoadPgPlanCaptureAsync(DateTime startUtc, DateTime endUtc) + { + if (PgCollectorIsGatedOff("pg_plan_capture")) + { + PgCapturedPlansGrid.ItemsSource = null; + PgCapturedPlansNote.Text = PanelNote("pg_plan_capture", 0, string.Empty); + return; + } + + var rows = await _dataService.GetPgPlanCaptureAsync(_server.ServerId, startUtc, endUtc, PgGridRowLimit); + + PgCapturedPlansGrid.ItemsSource = rows; + + var orphans = rows.Count(r => r.QueryId == 0); + + PgCapturedPlansNote.Text = rows.Count == 0 + ? PanelNote("pg_plan_capture", 0, + "No captured plans. The Plan Capture Readiness panel says which precondition is missing - " + + "usually auto_explain is not loaded, or the monitoring login cannot read the server log. " + + "That read needs pg_read_server_files AND an explicit GRANT EXECUTE on pg_read_file; the " + + "role alone does not carry it. On Aurora and RDS there is no filesystem to read, so this " + + "panel stays empty by design.") + : $"{rows.Count:N0} plan shape(s), ranked by TOTAL time - a plan that takes 40ms constantly " + + "costs more than one that took 900ms once. Captures counts how often the collector SAW " + + "the plan, not how often it ran. Plan JSON is redacted at collection: query text is " + + "dropped and literals are replaced, so nothing here carries customer values." + + (orphans > 0 + ? $" {orphans:N0} plan(s) have no query id, which means log_line_prefix lacks %Q - they " + + "cannot be joined to a statement until that is fixed." + : string.Empty); + } + /// /// Vacuum — the sessions holding a transaction open, the xmin horizon, the autovacuum backlog and the /// freeze headroom, in that causal order. One load for all four: they are one story, and reading them a diff --git a/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.xaml b/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.xaml index c7731b87b0..4f937993ce 100644 --- a/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.xaml +++ b/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.xaml @@ -3809,6 +3809,9 @@ + + + + + + + + + + + + + + + + + + + + + + + + + + diff --git a/Lite.Tests/PgPlanCaptureCollectorDefinitionTests.cs b/Lite.Tests/PgPlanCaptureCollectorDefinitionTests.cs new file mode 100644 index 0000000000..c26f1a7e95 --- /dev/null +++ b/Lite.Tests/PgPlanCaptureCollectorDefinitionTests.cs @@ -0,0 +1,178 @@ +/* + * Copyright (c) 2026 Erik Darling, Darling Data LLC + * + * This file is part of the SQL Server Performance Monitor Lite. + * + * Licensed under the MIT License. See LICENSE file in the project root for full license information. + */ + +using System; +using System.Linq; +using System.Reflection; +using System.Text.Json.Nodes; +using System.Text.RegularExpressions; +using Lite.Tests.Helpers; +using PerformanceMonitor.Collectors; +using Xunit; + +namespace Lite.Tests; + +/// +/// Pins plan capture, and above all the redaction — this is the one collector that reads text a customer +/// wrote, so a regression here publishes their data rather than merely reporting a wrong number. +/// +public class PgPlanCaptureCollectorDefinitionTests +{ + private static readonly RecordingCollectorDeltaCalculator s_deltas = new(); + + private static CollectorContext MakeContext() + => new() + { + ServerId = 42, + ServerName = "test-server", + CollectionTime = new DateTime(2026, 8, 25, 12, 0, 0, DateTimeKind.Utc), + Deltas = s_deltas, + Target = new CollectorTargetInfo + { + Engine = CollectorTargetEngine.PostgreSql, + PostgresMajorVersion = 17, + PostgresVersionNum = 170000, + }, + }; + + private static string Sql => PgPlanCaptureCollector.Instance.BuildQuery(MakeContext()).Text; + + private static JsonObject Redact(string json) + { + var root = (JsonObject)JsonNode.Parse(json)!; + root.Remove("Query Text"); + + typeof(PgPlanCaptureCollector) + .GetMethod("Redact", BindingFlags.NonPublic | BindingFlags.Static)! + .Invoke(null, new object[] { (JsonObject)root["Plan"]! }); + + return root; + } + + [Fact] + public void Identity_IsTheTableAndEngineTheStoreExpects() + { + Assert.Equal("pg_plan_capture", PgPlanCaptureCollector.Instance.Name); + Assert.Equal("pg_plan_capture", PgPlanCaptureCollector.Instance.TargetTable); + Assert.Equal(CollectorTargetEngine.PostgreSql, PgPlanCaptureCollector.Instance.TargetEngine); + } + + /// + /// Query text never becomes a column. auto_explain emits it verbatim — literals and all — and + /// log_parameter_max_length = 0 does not suppress it, because that setting covers bind parameters + /// only (measured on #2565). The statement identity is query_id. + /// + [Fact] + public void ThereIsNoQueryTextColumn() + { + var names = PgPlanCaptureCollector.Instance.PayloadColumns.Select(c => c.Name).ToArray(); + + Assert.DoesNotContain("query_text", names); + Assert.DoesNotContain("statement", names); + Assert.Contains("query_id", names); + } + + /// + /// The header is dropped before anything else touches the tree, and the value that was in it must not + /// survive anywhere else either — it also appears inside Filter. + /// + [Fact] + public void QueryTextAndItsLiterals_AreBothRemoved() + { + var root = Redact(""" + { + "Query Text": "SELECT 1 FROM accounts WHERE email = 'someone@example.com';", + "Plan": { "Node Type": "Seq Scan", "Relation Name": "accounts", + "Filter": "(email = 'someone@example.com'::text)" } + } + """); + + var json = root.ToJsonString(); + + Assert.Null(root["Query Text"]); + Assert.DoesNotContain("someone@example.com", json, StringComparison.Ordinal); + Assert.DoesNotContain("SELECT 1 FROM accounts", json, StringComparison.Ordinal); + } + + /// + /// Redaction must not mangle IDENTITY. A blanket numeric strip would rewrite a relation genuinely named + /// transactionitems1 into transactionitems?, destroying the name to hide a value that was + /// never there — so bare numbers are stripped only inside condition fields. + /// + [Fact] + public void RedactionStripsValues_WithoutDestroyingNames() + { + var root = Redact(""" + { + "Plan": { "Node Type": "Seq Scan", "Relation Name": "transactionitems1", "Alias": "t1", + "Plan Rows": 100, "Filter": "((id > 100) AND (v = 'secret'::text))" } + } + """); + + var plan = (JsonObject)root["Plan"]!; + + Assert.Equal("transactionitems1", plan["Relation Name"]!.GetValue()); + Assert.Equal("t1", plan["Alias"]!.GetValue()); + + var filter = plan["Filter"]!.GetValue(); + Assert.DoesNotContain("100", filter, StringComparison.Ordinal); + Assert.DoesNotContain("secret", filter, StringComparison.Ordinal); + + /* Numeric JSON values are estimates, not customer data, and stay untouched. */ + Assert.Equal(100, plan["Plan Rows"]!.GetValue()); + } + + /// + /// Nested plans and string arrays carry values too — Output and the various key lists are arrays, + /// and a child node's Filter is where most real literals live. + /// + [Fact] + public void RedactionReachesNestedPlansAndArrays() + { + var root = Redact(""" + { + "Plan": { "Node Type": "Limit", "Output": ["id", "'inline-literal'"], + "Plans": [ { "Node Type": "Seq Scan", + "Filter": "(name = 'nested-secret'::text)" } ] } + } + """); + + var json = root.ToJsonString(); + + Assert.DoesNotContain("nested-secret", json, StringComparison.Ordinal); + Assert.DoesNotContain("inline-literal", json, StringComparison.Ordinal); + } + + /// + /// The log read is BOUNDED. #2565 measured 772 MB of log in twenty seconds at capture-everything, and a + /// collector that read the file whole would become the server's largest reader. + /// + [Fact] + public void TheLogReadIsBounded() + { + Assert.Contains("greatest(n.size -", Sql, StringComparison.Ordinal); + Assert.Contains("pg_catalog.pg_read_file", Sql, StringComparison.Ordinal); + + /* The current file is discovered, not configured: log_filename is a strftime pattern. */ + Assert.Contains("pg_catalog.pg_ls_logdir()", Sql, StringComparison.Ordinal); + } + + /// + /// Server-wide, and it claims no database attribution: the log line prefix is not guaranteed to carry + /// %d, so a database column would be a claim the source cannot support (#2599). + /// + [Fact] + public void ItClaimsNoDatabaseAttribution() + { + Assert.False(PgPlanCaptureCollector.Instance.RunsPerDatabase( + new CollectorTargetInfo { Engine = CollectorTargetEngine.PostgreSql, PostgresMajorVersion = 17 })); + + Assert.DoesNotContain("database_name", + PgPlanCaptureCollector.Instance.PayloadColumns.Select(c => c.Name)); + } +} diff --git a/PerformanceMonitor.Collectors/CollectorCatalog.cs b/PerformanceMonitor.Collectors/CollectorCatalog.cs index 53563c1bd6..08e06897aa 100644 --- a/PerformanceMonitor.Collectors/CollectorCatalog.cs +++ b/PerformanceMonitor.Collectors/CollectorCatalog.cs @@ -86,6 +86,7 @@ kept honest by the engine gate in AppliesTo(definition, target). */ PgWaitSamplingCollector.Instance, PgKernelStatsCollector.Instance, PgPredicateStatsCollector.Instance, + PgPlanCaptureCollector.Instance, PgColumnStatsCollector.Instance, PgReplicationStatsCollector.Instance, PgBufferUsageCollector.Instance, diff --git a/PerformanceMonitor.Collectors/CollectorScheduleDefaults.cs b/PerformanceMonitor.Collectors/CollectorScheduleDefaults.cs index b6a487c721..b81a962ae6 100644 --- a/PerformanceMonitor.Collectors/CollectorScheduleDefaults.cs +++ b/PerformanceMonitor.Collectors/CollectorScheduleDefaults.cs @@ -249,6 +249,7 @@ pg_stat_statements get installed" and "when did this extension get upgraded" are ["pg_wait_sampling"] = new(5, 30), ["pg_kernel_stats"] = new(5, 30), ["pg_predicate_stats"] = new(60, 30), + ["pg_plan_capture"] = new(5, 14), ["pg_extension_availability"] = new(1440, 365), /* #2544 lock state. PER-MINUTE and 30 days, matching pg_blocking - this is a SAMPLE of instantaneous state, not a counter, so the cadence IS the resolution. A lock queue that forms and clears inside diff --git a/PerformanceMonitor.Collectors/PgPlanCaptureCollector.cs b/PerformanceMonitor.Collectors/PgPlanCaptureCollector.cs new file mode 100644 index 0000000000..87bd72d888 --- /dev/null +++ b/PerformanceMonitor.Collectors/PgPlanCaptureCollector.cs @@ -0,0 +1,313 @@ +/* + * Copyright (c) 2026 Erik Darling, Darling Data LLC + * + * This file is part of the SQL Server Performance Monitor Lite. + * + * Licensed under the MIT License. See LICENSE file in the project root for full license information. + */ + +using System; +using System.Collections.Generic; +using System.Data.Common; +using System.Globalization; +using System.Security.Cryptography; +using System.Text; +using System.Text.Json; +using System.Text.Json.Nodes; +using System.Linq; +using System.Text.RegularExpressions; +using System.Threading; +using System.Threading.Tasks; + +namespace PerformanceMonitor.Collectors; + +/// +/// Execution plans captured by auto_explain, read out of the server log (#2566, part of #2538). +/// +/// Why the log at all. auto_explain has no view, no function and no table — it writes to +/// the server log and nowhere else. #2565 settled that it is nonetheless the right mechanism: on-demand +/// EXPLAIN ANALYZE was rejected because it EXECUTES the statement (demonstrated there against a +/// DELETE), and plain EXPLAIN returns estimates with no actual rows, which is the information a plan +/// is opened for. +/// +/// This is a SELF-HOSTED capability and the collector says so rather than failing vaguely. +/// Reading the log needs pg_read_server_files AND an explicit +/// GRANT EXECUTE ON FUNCTION pg_read_file — measured: the role alone is NOT enough, because +/// pg_read_file's ACL is postgres=X/postgres and the role does not carry EXECUTE. On Aurora and +/// RDS there is no filesystem and the role is not grantable at all; logs come from the RDS API, which is a +/// different integration entirely (#2538). Where the grant is absent this degrades to a named non-fatal +/// skip, which is the honest outcome — not a hidden failure. +/// +/// No query text, and no literals anywhere. This is the part to not undo. auto_explain +/// emits Query Text verbatim — WHERE datname = 'postgres' — and +/// auto_explain.log_parameter_max_length = 0 does NOT suppress it (that setting only covers bind +/// parameters; measured on #2565). Literals also appear INSIDE the plan tree, in Filter and its +/// relatives: (datname = 'postgres'::name). So Query Text is dropped entirely — the statement +/// identity is query_id, and its normalised text already lives in pg_statement_stats — and +/// every remaining string is redacted before it reaches the store. That matches what this product does +/// everywhere else: pg_session_states carries no query text and pg_column_stats drops +/// most_common_vals, both for this reason. +/// +/// Redaction is deliberately asymmetric. Quoted literals are stripped from EVERY string, which +/// is safe because relation and alias names are not quoted. Bare numbers are stripped only inside known +/// condition fields, because a blanket numeric strip would rewrite a table genuinely named +/// transactionitems1 into transactionitems? — mangling identity to hide a value that was +/// never there. +/// +public sealed class PgPlanCaptureCollector : PostgresCollectorDefinitionBase +{ + public static readonly PgPlanCaptureCollector Instance = new(); + + private PgPlanCaptureCollector() + { + } + + /// From %Q in log_line_prefix, which is the ONLY place auto_explain + /// exposes it — the plan JSON contains no identifier of its own, even with compute_query_id on. + /// Joins pg_statement_stats. Zero means the prefix was not configured, and the plan is an orphan + /// (pg_plan_capture_readiness reports this as the plan_attribution facet). + /// Of the REDACTED plan, so the same shape recurs to the same hash regardless of + /// the values it ran with — which is what makes dedup work at all. + /// Redacted. See the type header. + public readonly record struct Row( + long QueryId, + string PlanHash, + double DurationMs, + int NodeCount, + string? TopNodeType, + string PlanJson); + + /// + /// How much of the log tail to read per cycle. Bounded because the file can reach hundreds of megabytes + /// — #2565 measured 772 MB in twenty seconds at capture-everything — and reading it whole would turn a + /// monitoring collector into the server's biggest reader. + /// + private const int TailBytes = 4 * 1024 * 1024; + + /* Spliced into the query text as a literal. A const string keeps QueryText a compile-time constant, + which every other collector here relies on, and keeps the number in ONE place. */ + private const string TailBytesLiteral = "4194304"; + + /* pg_ls_logdir() to find the CURRENT file rather than a configured name: log_filename is a strftime + pattern, so the actual name is only knowable by asking. pg_monitor can call this one; it is + pg_read_file that needs the extra grant. + + The tail is read from a negative offset via greatest(size - TailBytes, 0), so a fresh small log is + read whole and a large one is read from its end. + + Plans are extracted with regexp_matches rather than parsed line by line because auto_explain writes + the JSON tab-indented under its LOG line, so the block is recognisable as a unit. The tabs are + stripped to make it valid JSON. */ + private const string QueryText = @" +WITH newest AS ( + SELECT name, size + FROM pg_catalog.pg_ls_logdir() + ORDER BY modification DESC + LIMIT 1 +), +tail AS ( + SELECT pg_catalog.pg_read_file( + 'log/' || n.name, + greatest(n.size - " + TailBytesLiteral + @", 0), + " + TailBytesLiteral + @") AS body + FROM newest AS n +) +SELECT + (m[1])::bigint AS query_id, + (m[2])::double precision AS duration_ms, + replace(m[3], chr(9), '') AS plan_json +FROM tail, + regexp_matches( + tail.body, + '\[\d+\] (-?\d+) LOG: duration: ([0-9.]+) ms plan:\s*\n((?:\t[^\n]*\n)+)', + 'g') AS m +LIMIT 2000"; + + public override string Name => "pg_plan_capture"; + + public override string TargetTable => "pg_plan_capture"; + + /// + /// Any PostgreSQL target. Absent grant, absent module or a log directory that cannot be listed all + /// raise errors the host classifies as non-fatal skips, and + /// pg_plan_capture_readiness already reports which precondition is missing. + /// + public override bool AppliesTo(CollectorTargetInfo target) => true; + + /// Server-wide: one log holds every database's plans. + public override bool RunsPerDatabase(CollectorTargetInfo target) => false; + + public override CollectorQuery BuildQuery(CollectorContext context) => new(QueryText); + + public override IReadOnlyList PayloadColumns { get; } = new[] + { + new CollectorColumn("query_id", CollectorColumnType.BigInt), + new CollectorColumn("plan_hash", CollectorColumnType.Varchar), + new CollectorColumn("duration_ms", CollectorColumnType.Double), + new CollectorColumn("node_count", CollectorColumnType.Integer), + new CollectorColumn("top_node_type", CollectorColumnType.Varchar), + /* No database_name and no query_text, both deliberately. The log line prefix is not guaranteed to + carry %d, so a database column would be a claim the source cannot support (#2599); the text is + dropped for the reason in the type header. */ + new CollectorColumn("plan_json", CollectorColumnType.Varchar), + }; + + /* Condition fields, where a bare number is a VALUE rather than part of a name. Enumerated rather than + inferred: getting this list wrong in the safe direction leaves a number in a filter, and in the unsafe + direction rewrites an object's name. */ + private static readonly HashSet s_conditionFields = new(StringComparer.Ordinal) + { + "Filter", "Index Cond", "Recheck Cond", "Join Filter", "Hash Cond", "Merge Cond", + "TID Cond", "One-Time Filter", "Cache Key", "Function Call", "Output", "Group Key", + "Sort Key", "Presorted Key", "Hash Key", "Conflict Filter", "Repeatable Seed", + }; + + private static readonly Regex s_quotedLiteral = new("'(?:[^']|'')*'", RegexOptions.Compiled); + + /* Bare numbers, but NOT ones glued to an identifier character: 'transactionitems1' must survive intact + while '(id > 100)' must not. */ + private static readonly Regex s_bareNumber = new(@"(?> ReadAsync(DbDataReader reader, CollectorContext context, CancellationToken cancellationToken) + { + var rows = new List(); + + while (await reader.ReadAsync(cancellationToken)) + { + var queryId = reader.IsDBNull(0) ? 0 : reader.GetInt64(0); + var durationMs = reader.IsDBNull(1) ? 0 : reader.GetDouble(1); + var rawJson = reader.IsDBNull(2) ? null : reader.GetString(2); + + if (string.IsNullOrWhiteSpace(rawJson)) + { + continue; + } + + JsonNode? parsed; + + try + { + parsed = JsonNode.Parse(rawJson); + } + catch (JsonException) + { + /* A truncated block, which the bounded tail read makes ordinary rather than exceptional: + the window can begin mid-plan. Skipped rather than stored half-parsed, and not logged as + an error, because it is the expected cost of not reading the whole file. */ + continue; + } + + if (parsed is not JsonObject root || root["Plan"] is not JsonObject plan) + { + continue; + } + + /* Dropped BEFORE anything else touches the tree, so no later step can accidentally carry it. */ + root.Remove("Query Text"); + + Redact(plan); + + var nodeCount = CountNodes(plan); + var topNodeType = plan["Node Type"]?.GetValue(); + var json = root.ToJsonString(); + + rows.Add(new Row( + QueryId: queryId, + PlanHash: Hash(json), + DurationMs: durationMs, + NodeCount: nodeCount, + TopNodeType: topNodeType, + PlanJson: json)); + } + + return rows; + } + + /// + /// Strips values from a plan tree in place. Quoted literals go from every string; bare numbers go only + /// from condition fields, for the reason in the type header. + /// + private static void Redact(JsonObject node) + { + foreach (var property in node.ToList()) + { + switch (property.Value) + { + case JsonObject child: + Redact(child); + break; + + case JsonArray array: + foreach (var element in array) + { + if (element is JsonObject arrayChild) + { + Redact(arrayChild); + } + } + + /* Arrays of STRINGS carry values too - Output and the various Key lists are arrays. */ + for (var i = 0; i < array.Count; i++) + { + if (array[i] is JsonValue value && value.TryGetValue(out var text)) + { + array[i] = JsonValue.Create(Scrub(text, property.Key)); + } + } + + break; + + case JsonValue value when value.TryGetValue(out var text): + node[property.Key] = JsonValue.Create(Scrub(text, property.Key)); + break; + } + } + } + + private static string Scrub(string text, string fieldName) + { + var scrubbed = s_quotedLiteral.Replace(text, "'?'"); + + if (s_conditionFields.Contains(fieldName)) + { + scrubbed = s_bareNumber.Replace(scrubbed, "?"); + } + + return scrubbed; + } + + private static int CountNodes(JsonObject plan) + { + var count = 1; + + if (plan["Plans"] is JsonArray children) + { + foreach (var child in children) + { + if (child is JsonObject childPlan) + { + count += CountNodes(childPlan); + } + } + } + + return count; + } + + private static string Hash(string json) + { + var bytes = SHA256.HashData(Encoding.UTF8.GetBytes(json)); + return Convert.ToHexString(bytes, 0, 16); + } + + public override void WritePayload(Row row, ICollectorRowWriter writer, CollectorContext context) + { + writer + .Value(row.QueryId) + .Value(row.PlanHash) + .Value(row.DurationMs) + .Value(row.NodeCount) + .Value(row.TopNodeType) + .Value(row.PlanJson); + } +}