Repository navigation
Capture PostgreSQL execution plans, without capturing customer data (#2566) - #2613
Conversation
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)+)', |
There was a problem hiding this comment.
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.
|
Reviewed this PR (schema v99, Checked for Lite/Darling parity: this collector follows the same pattern as the other recent Postgres-only collectors (V96–V98) — One correctness concern worth a look before merge — left as an inline comment on 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}" |
There was a problem hiding this comment.
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)+)', |
There was a problem hiding this comment.
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.
Review summaryReviewed 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: Left two inline comments on things that look like real bugs:
No SQL-injection, secrets, or missing-index-DMV concerns — |
Implements #2566's storage decision and gives #2538 a working producer. Schema v99 adds
collect.pg_plan_capture, readingauto_explain's JSON out of the server log.Its own table, not
query_plan_dimThat was the call on #2566 and it is not cosmetic.
query_plan_dimholds SQL Server plan XML, andplan_xml_compression = noneis 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_explainemits this verbatim:auto_explain.log_parameter_max_length = 0does 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 inpg_statement_stats) and every remaining string is redacted before storage. This is what the product does everywhere else:pg_session_statescarries no query text,pg_column_statsdropsmost_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
transactionitems1intotransactionitems?— destroying identity to hide a value that was never there.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_hashis 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_filenameis 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:
pg_monitorpermission denied for function pg_read_file+ pg_read_server_files+ explicit GRANT EXECUTEThe middle row is the one worth knowing:
pg_read_file's ACL ispostgres=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 +
StorageVersion99, 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 missingdatabase_name.Panel names are
PgCapturedPlans*—PgPlanCapture*already belongs to the readiness panel from #2564, and the compiler caught the collision.