Skip to content

Capture PostgreSQL execution plans, without capturing customer data (#2566) - #2613

Merged
erikdarlingdata merged 2 commits into
devfrom
feature/2566-pg-plan-capture
Aug 25, 2026
Merged

erikdarlingdata merged 2 commits into
devfrom
feature/2566-pg-plan-capture

Conversation

@erikdarlingdata

Copy link
Copy Markdown
Owner

Implements #2566's storage decision and gives #2538 a working producer. Schema v99 adds collect.pg_plan_capture, reading auto_explain's JSON out of the server log.

Its own table, not query_plan_dim

That was the call on #2566 and it is not cosmetic. query_plan_dim holds SQL Server plan XML, and plan_xml_compression = none is a documented contract with direct-SQL consumers reading that column as XML. JSON rows there would break their dashboards with no schema change to notice, no error, and no version to key off — the worst failure shape available. The compression and retention machinery is shared; the table is not.

No query text and no literals reach the store

auto_explain emits this verbatim:

"Query Text": "SELECT 1 FROM pg_database WHERE datname = 'postgres' ;",
"Filter": "(datname = 'postgres'::name)"

auto_explain.log_parameter_max_length = 0 does not suppress it — that setting covers bind parameters only (measured on #2565) — and literals sit inside the plan tree as well as the header.

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. This is what the product does everywhere else: pg_session_states carries no query text, pg_column_stats drops most_common_vals.

Redaction is asymmetric on purpose

Quoted literals go from every string. Bare numbers go only from condition fields. A blanket numeric strip would rewrite a relation genuinely named transactionitems1 into transactionitems? — destroying identity to hide a value that was never there.

in : "Relation Name":"transactionitems1", "Filter":"((id > 100) AND (v = 'secret'::text))"
out: "Relation Name":"transactionitems1", "Filter":"((id > ?) AND (v = '?'::text))"

Verified against 25 real captured plans from a live server: zero literals survived, name intact. Nested plans and string arrays (Output, the key lists) are covered too — that is where most real literals live.

plan_hash is taken of the redacted plan, so a shape recurs to the same hash whatever values it ran with. Hashing raw text would defeat dedup exactly where it matters most.

Bounded read

4 MB tail, because #2565 measured 772 MB of log in twenty seconds at capture-everything. Blocks truncated by the window edge are skipped rather than stored half-parsed — an ordinary consequence of not reading the whole file, not an error.

The current log file is discovered via pg_ls_logdir() rather than configured: log_filename is a strftime pattern, so the real name is only knowable by asking.

Self-hosted in practice, and it degrades honestly

Measured at three privilege levels against a live server:

grant result
pg_monitor permission denied for function pg_read_file
+ pg_read_server_files still denied — the role does not carry EXECUTE
+ explicit GRANT EXECUTE works

The middle row is the one worth knowing: pg_read_file's ACL is postgres=X/postgres. On Aurora and RDS there is no filesystem at all — that route needs the RDS API, which is a separate integration (raised on #2538). Where the grant is absent this is a named non-fatal skip, and the panel's empty-state note says which precondition is missing rather than implying a quiet server.

Registration

Catalog (66), schedule, worker dispatch, V99 rung + StorageVersion 99, probe (75 columns / 75 params, ordinals 0–74), reader, wrapper, panel under the statement grid, rung-parity list, definition tests, CI sizing to 69/80. All four of V96–V99 verified against the generator, and the #2599 invariant re-checked catalog-wide: no per-database collector is missing database_name.

Panel names are PgCapturedPlans* — PgPlanCapture* already belongs to the readiness panel from #2564, and the compiler caught the collision.

Schema v99 adds collect.pg_plan_capture, reading auto_explain's JSON out
of the server log. #2565 settled the mechanism; this is #2566's storage,
in its own table rather than query_plan_dim.

That separation is the decision from #2566 and it is not cosmetic:
query_plan_dim holds SQL Server plan XML, and plan_xml_compression=none
is a documented contract with direct-SQL consumers reading the column AS
XML. JSON rows there 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. auto_explain emits Query
Text verbatim and log_parameter_max_length=0 does NOT suppress it - that
setting covers bind parameters only. Literals also sit inside the plan
tree in Filter and its relatives. So the text is dropped outright, and
every remaining string is redacted before storage.

Redaction is asymmetric on purpose: quoted literals go from every
string, bare numbers only from condition fields. 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 captured plans: zero literals survived and
the digit-bearing name survived intact.

plan_hash is taken of the REDACTED plan, so a shape recurs to the same
hash whatever values it ran with. Hashing raw text would defeat dedup
exactly where it matters most.

The log read is bounded to a 4 MB tail - #2565 measured 772 MB of log in
twenty seconds at capture-everything - and blocks truncated by 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 is not enough because the function's ACL is postgres=X/postgres.
Aurora and RDS have no filesystem, so this degrades to a named skip and
the panel says why.

CI worker sizing follows the hypertable count to 69/80.

Refs #2566, #2538.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
FROM tail,
regexp_matches(
tail.body,
'\[\d+\] (-?\d+) LOG: duration: ([0-9.]+) ms plan:\s*\n((?:\t[^\n]*\n)+)',

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Correctness: the capture regex is far stricter than what readiness validates — many "ready" configs will silently capture zero plans.

This pattern requires the log text immediately preceding LOG: duration: to be exactly [<pid>] <query_id> — i.e. log_line_prefix must literally end in [%p] %Q with nothing else between %p and %Q.

PgPlanCaptureReadinessCollector (the plan_attribution facet) only checks strpos(line_prefix, '%Q') > 0 — it doesn't verify adjacency to %p or the absence of other fields in between. So a very plausible real prefix like '%m [%p] %q%u@%d %Q ' (timestamp + user/db before the query id) passes readiness ("log_line_prefix carries %Q, so each captured plan is stamped...") but will never match this regex, since user@db sits between ] and the digits. The result is a permanently-empty pg_plan_capture on a target readiness reports as fully capable — and the panel's empty-state message ("usually auto_explain is not loaded, or the monitoring login cannot read the server log") points at the wrong cause.

Related: pg_ls_logdir() ORDER BY modification DESC LIMIT 1 picks the most-recently-modified file with no filter on extension. If log_destination includes csvlog (common on RDS-style setups) alongside stderr, this can pick the .csv file, whose message field never contains the literal LOG: duration: text this regex looks for — same silent-empty failure mode.

Nowhere in the repo is the required [%p] %Q adjacency documented as a precondition, and there's no live/integration test that feeds a realistic log line (with a plausible full log_line_prefix, or a mixed stderr+csvlog destination) through this query to confirm extraction actually works — the unit tests only assert the SQL text contains certain substrings, never exercise the regex against sample log output.

Worth either loosening the regex to tolerate arbitrary prefix content before %Q ' LOG: (e.g. anchor only on (-?\d+) LOG: duration: and drop the \[\d+\] requirement, or make the readiness check confirm the exact adjacency it needs), or filtering pg_ls_logdir() to the plain-text log file when multiple destinations are configured.

@claude

claude Bot commented Aug 25, 2026

Copy link
Copy Markdown

Reviewed this PR (schema v99, collect.pg_plan_capture via auto_explain). Overall the redaction design is solid and well-tested: Query Text is dropped, quoted literals are stripped from every string, bare numbers are scoped to condition fields only (verified against the transactionitems1-style identity-preservation test), and plan_hash is correctly taken over the redacted JSON rather than the raw text. The self-hosted/Aurora-RDS degradation story and the bounded 4 MB tail read are both reasonable and match the PR description's stated measurements.

Checked for Lite/Darling parity: this collector follows the same pattern as the other recent Postgres-only collectors (V96–V98) — Lite's DuckDbSchemaGenerator filters CollectorCatalog.All to TargetEngine == SqlServer only, so PostgreSQL collectors intentionally don't get Lite DuckDB tables or UI wiring. No parity drift here.

One correctness concern worth a look before merge — left as an inline comment on PerformanceMonitor.Collectors/PgPlanCaptureCollector.cs line 122: the log-parsing regex hardcodes an assumption that log_line_prefix ends in exactly [%p] %Q (pid-bracket immediately followed by query id), which is materially stricter than what PgPlanCaptureReadinessCollector's plan_attribution facet actually validates (just "does the prefix contain %Q anywhere"). Several realistic prefixes that pass readiness would still produce zero captured rows, with the UI's empty-state message pointing at the wrong root cause. No test exercises the regex against a realistic log line, so this wouldn't be caught by the existing suite.

Everything else — schema migration, rung/probe wiring (75 params, arm ordering), catalog/schedule registration, CI hypertable sizing bump, XAML panel/grid naming collision fix — looks consistent and correctly threaded through.

The new captured-plans panel needed different element names, because
PgPlanCaptureNote/Grid already belong to the readiness panel from #2564.
I renamed mine with a replace over everything after my loader - which
also rewrote the READINESS loader's two references, since it sits later
in the file.

Result: PgPlanCaptureNote was declared in the XAML and never filled, so
the readiness panel could render blank with no explanation.
EveryPostgresPanel_ExplainsItsOwnEmptyState caught it, which is exactly
what that test is for.

Both references restored. Verified across the whole file: 28 note
elements, none unfilled; 26 grids, none unbound.

Refs #2566.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
<TextBlock Grid.Row="8" Text="Captured execution plans - grouped by plan shape" FontWeight="SemiBold" Margin="0,10,0,2"/>
<TextBlock Grid.Row="9" x:Name="PgCapturedPlansNote" FontSize="12" Margin="0,0,0,6" TextWrapping="Wrap"
Foreground="{DynamicResource ForegroundMutedBrush}"/>
<DataGrid Grid.Row="10" x:Name="PgCapturedPlansGrid" Style="{StaticResource DarkGrid}"

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

PgCapturedPlansGrid is placed at Grid.Row="10", but the Query Shapes tab's Grid.RowDefinitions (lines 3803-3815) only declares 10 rows, i.e. valid indices 0-9. Counting the definitions added by this PR:

0: Auto   1: 2*    2: Auto   3: Auto   4: *
5: Auto   6: *     7: Auto   8: Auto   9: *

Content now needs indices 0-10 (11 rows: the pre-existing statement/database/kernel-stats rows through PgKernelStatsGrid at row 7, then the three new captured-plans rows — header TextBlock at 8, PgCapturedPlansNote at 9, PgCapturedPlansGrid at 10). Only 3 RowDefinitions were added, but 3 rows plus the pre-existing off-by-one deficit needed 4.

PgCapturedPlansGrid has no row definition of its own and will collide with PgCapturedPlansNote (row 9) in whatever WPF does with an out-of-range Grid.Row (clip/overlap) — the new panel won't get the dedicated space every other panel in this grid gets. Needs one more <RowDefinition Height="*"/> before the closing </Grid.RowDefinitions>.

FROM tail,
regexp_matches(
tail.body,
'\[\d+\] (-?\d+) LOG: duration: ([0-9.]+) ms plan:\s*\n((?:\t[^\n]*\n)+)',

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This regex requires the log line to contain the literal substring [<pid>] <query_id> LOG: duration: — i.e. log_line_prefix must end with exactly [%p] %Q (brackets around %p, then %Q, then a space) immediately before Postgres appends the LOG: level tag.

pg_plan_capture_readiness (the panel this feature leans on for "which precondition is missing") only checks that log_line_prefix contains %Q anywhere (strpos(..., '%Q') > 0 per PgPlanCaptureReadinessCollector) — it doesn't check that %p is bracketed and immediately followed by %Q. A perfectly valid, %Q-carrying prefix like 'user=%u,pid=%p,qid=%Q ' or '%Q [%p] ' (different order) would pass readiness as "ready" but this regex would never match, so the collector would silently return zero rows every cycle.

The empty-state copy in ViewerServerTab.Postgres.cs (LoadPgPlanCaptureAsync) attributes an empty grid to "auto_explain is not loaded, or the monitoring login cannot read the server log" — the log_line_prefix format requirement isn't mentioned as a possible cause anywhere, so this failure mode would be hard to diagnose from the UI. Worth either loosening the regex to tolerate %p/%Q in other positions, or having readiness (and the empty-state note) check for this exact ordering rather than just %Q's presence.

@claude

claude Bot commented Aug 25, 2026

Copy link
Copy Markdown

Review summary

Reviewed the diff (dev...56345a5, 17 files / +754/-17). This is Darling-only (PostgreSQL/TimescaleDB store) — Lite has no PostgreSQL support at all, so there's no Lite/Darling parity drift to flag here.

Registration/version bookkeeping checked and consistent: CollectorCatalog, CollectorScheduleDefaults, DarlingWorker dispatch, StorageVersion (98→99), PgMigrations V99 rung, MapProbedSchemaVersion new arm + parameter, PgSchemaGeneratorTests count/rung-parity list, CI max_background_workers/max_worker_processes sizing (68/79→69/80) — all move together correctly. PayloadColumns order, WritePayload order, and the V99 table's column order all line up. The redaction logic has solid, well-targeted unit test coverage (Lite.Tests/PgPlanCaptureCollectorDefinitionTests.cs) including the nested-plan and array cases.

Left two inline comments on things that look like real bugs:

  1. XAML row/RowDefinitions mismatch — the new PgCapturedPlansGrid is assigned Grid.Row="10" but only 10 rows (indices 0-9) are declared in that grid's RowDefinitions, so it has no dedicated row and will collide with PgCapturedPlansNote.
  2. Readiness/regex mismatch — the log-parsing regex requires log_line_prefix to end with exactly [%p] %Q (bracketed pid immediately followed by query id), but pg_plan_capture_readiness only checks that the prefix contains %Q anywhere. A valid %Q-carrying prefix in a different order/format would pass readiness yet silently capture zero plans, and the empty-state copy doesn't mention this as a possible cause.

No SQL-injection, secrets, or missing-index-DMV concerns — pg_ls_logdir()/pg_read_file() inputs aren't user-controlled, and all reader parameters are bound positionally through Npgsql.

@erikdarlingdata
erikdarlingdata merged commit 58b5efc into dev Aug 25, 2026
6 checks passed
@erikdarlingdata
erikdarlingdata deleted the feature/2566-pg-plan-capture branch September 12, 2026 20:32
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant