Skip to content

4053 part b2: pg_plan_capture reads csvlog when it's on (self-hosted) - #4137

Merged
erikdarlingdata merged 4 commits into
devfrom
fix/4053-csvlog-plan-capture
Sep 24, 2026
Merged

erikdarlingdata merged 4 commits into
devfrom
fix/4053-csvlog-plan-capture

Conversation

@erikdarlingdata

@erikdarlingdata erikdarlingdata commented Sep 24, 2026 •

Copy link
Copy Markdown
Owner

Part of #4053 (plan capture on csvlog; depends on #4124)

What changed

PgPlanCaptureCollector now reads auto_explain plans out of a .csv log file when the target's
log_destination includes csvlog — the same flag PgLogEventsCollector already reads for its own csvlog
branch (context.PgLogUsesCsvlog, from #4124). Three pieces:

  1. BuildQuery sends a new csv statement pair — CsvQueryText/CsvBinaryQueryText, opened on
    PgServerLogTail.TailCsvCteSql/TailCsvCteBinarySql — instead of the existing stderr pair, once
    context.PgLogUsesCsvlog is set. The two existing stderr statements are byte-identical to before this
    change
    ; only the new csv pair is added. Their marker arm carries PgNoCsvlogFileException.Marker
    (not PgNoStderrLogFileException.Marker), so the fault this route throws names csvlog rather than
    stderr, matching PgLogEventsCollector's own csv branch.

  2. ReadAsync dispatches to a new private ReadCsvAsync when context.PgLogUsesCsvlog is set. It:

    • decodes the binary route the same way PgLogEventsCollector's csv branch does (PgBinaryTailText.DecodeWhole);
    • calls PgServerLogCsvParser.Parse on the raw body (the shared csvlog parser from Wire the csvlog parser into pg_log_events on the self-hosted route (#4053 part a1b) #4124/part a1);
    • keeps only records whose Message starts with a csvlog-specific plan marker literal. Verified on a
      live pg18 rig with logging_collector=on, log_destination=csvlog, auto_explain loaded
      : csvlog
      carries severity in its own column, never glued onto Message the way the stderr route's
      log_line_prefix glues "LOG: " on — a captured record's message reads
      duration: N ms plan:\n{json}, not LOG: duration: N ms plan:\n{json}. The marker literal used
      here (PlanMarkerCsvLiteral = "duration: ") is the stderr literal minus that head.
    • takes the query id from csvlog's own query_id column (the last of the 26 fields, PG14+) rather than
      parsing any prefix text — csvlog carries no %Q-rendered prefix at all;
    • takes the duration from the message with the same guarded shape the stderr SQL casts under its CASE
      chain (^[0-9]{1,15}(\.[0-9]{1,9})?$, done in C# as s_csvDurationShape), so a duration shaped like
      1.2.3 is skipped and counted rather than trusted to double.TryParse's more permissive grammar;
    • builds each row through the shared PgPlanLogParser.FromBlock, the same redaction and hashing path
      both existing transports use.
    • a record whose id or duration doesn't fit is skipped and counted under the existing
      forged_captures_skipped measurement; a record the csv parser itself discarded (a resync fragment or
      bad shape) is counted under csv_records_discarded, reusing
      PgLogEventsCollector.CsvRecordsDiscardedMeasurement's exact label.
  3. Tests:

    • PgPlanCaptureCsvUnitTests (new, Darling.Tests): a FakeReader over the csv statement's two columns.
      One real auto_explain csvlog record (captured live, put into a const string fixture, not pasted into
      prose) → one row with the right query id and duration, redacted; a quoted user field carrying a
      forged newline plus a fake plan-shaped line → no extra row; a duration shaped 1.2.3 → skipped and
      counted under forged_captures_skipped; the no-csvlog-file marker → throws PgNoCsvlogFileException.
    • PgPlanCaptureCsvLiveTests (new, Darling.Tests): gated on DARLING_TEST_PG_CSVLOG_AUTOEXPLAIN. Runs a
      real query over the threshold against a rig started with logging_collector=on,
      log_destination=csvlog, sets context.PgLogUsesCsvlog = true directly, runs the csv statement plus
      ReadAsync through both the text and binary route, and asserts one plan row for that query.

What I ran

  • dotnet build on PerformanceMonitor.Collectors and Darling.Tests: clean, 0 warnings/errors.
  • dotnet build on Lite.Tests: clean (execution is CI's, per the Mac rig note — WPF).
  • Unit tests (Darling.Tests.dll -class Darling.Tests.PgPlanCaptureCsvUnitTests): Total: 4, Failed: 0.
  • PgLogEventsPipelineTests + PgServerLogCsvParserTests (untouched files this branch reuses):
    Total: 73, Failed: 0.
  • Live test against a timescale/timescaledb:2.28.1-pg18 rig
    (docker run ... -c logging_collector=on -c log_destination=csvlog -c compute_query_id=on -c shared_preload_libraries=timescaledb,auto_explain -c auto_explain.log_min_duration=0), both the text and
    binary (pg_read_binary_file) route: Total: 1, Failed: 0. Container removed before this push.
  • Full Darling.Tests.dll run (no filter, DARLING_TEST_PG* unset): Total: 13421, Failed: 215, Skipped: 717. Every failure is in the known Windows-only set this Mac rig cannot run (ViewerHistoryWindowTests,
    ViewerDrillDownTests, ViewerSettingsTests, ViewerConfigDiagnosticsTests,
    ViewerServerSummaryDisplayTests, DarlingInstallLocationTests, DarlingFileSecurityTests,
    DarlingRuntimePreflightTests, DarlingConfigTests.ConnectionString_MirrorsLitePosture_Integrated) — 215
    vs the brief's quoted 214 baseline, no new class outside that set, and nothing in
    PgPlanCapture*/PgLogEvents*/PgServerLogCsvParser* failed.
  • scrubcheck on the staged diff: 0 hit(s), 17/17 controls fired before commit.

What I did NOT verify

  • I did not verify the query-id-overflow-guard interaction on the csvlog route specifically (the guard is
    C#-side s_csvDurationShape plus long.TryParse, not a SQL CASE chain like the stderr route, since
    csvlog's own query_id column is already a well-typed bigint from PostgreSQL — there is no forged-prefix
    text to guard against on that column the way stderr's %Q needs guarding).
  • I did not exercise PostgreSQL 14/15/16 live for this specific branch (only 18, via the pinned
    timescale/timescaledb:2.28.1-pg18 image); the csv statement shares PgServerLogTail's CTEs unmodified,
    which Wire the csvlog parser into pg_log_events on the self-hosted route (#4053 part a1b) #4124's own tests already cover across versions.

Coordinator verification (branch head e1f5263, rebased onto dev after #4136)

  • Rebuilt on 4053 part b1: pg_deadlocks reads csvlog when it's on #4136. It adds pg_plan_capture to PgLogFormatCapability.RoutedCollectors, so the runner probes the log format for it and its no-file fault can clear the cached verdict. PgReadBinaryFileCapabilityTests expects 2 probes for it.
  • Review round 1 (Opus): two changes, both made:
    • The csv branch now requires LOG severity, as the stderr regex does. Before, a client's NOTICE or WARNING whose message starts with the marker reached the parse.
    • A duration record with no plan (a genuine log_min_duration_statement or log_duration record) is skipped without being counted as forged. Before, forged_captures_skipped grew with every slow statement.
    • Each has a unit test, and PgPlanCaptureCsvUnitTests passes (6/6).
  • The reviewer confirmed the rest: trusting the query_id column (0 is stored, as on stderr), the duration guard, taking the plan JSON from the message field, and the discard accounting. The stderr route's byte-pinned SQL is untouched.
  • On a fresh csvlog rig, PgPlanCaptureCsvLiveTests passes (1/1) at this head: a real Seq Scan plan row on both read routes. Before the review fix, the deadlocks and log-events live classes also passed on one rig.
  • The full Darling suite equals dev's baseline. It ran before the review fix; the fix touches only this collector's csv loop and its tests.
  • Deferred to Postgres log readers: the planted-input paths the #4051 review left open #4058: RAISE-shaped records that imitate a capture, where no discriminator covers every procedural language.

CHANGELOG entry

@erikdarlingdata erikdarlingdata changed the title 4053 part b2: pg_plan_capture reads csvlog when it's on (self-hosted) DO NOT MERGE (stacked; the client-site coordinator arms it): 4053 part b2: pg_plan_capture reads csvlog when it's on (self-hosted) Sep 24, 2026
@erikdarlingdata
erikdarlingdata force-pushed the fix/4053-csvlog-plan-capture branch from 70b78f6 to 6cb4a12 Compare September 24, 2026 05:25
Adds the csvlog branch to PgPlanCaptureCollector: BuildQuery sends the
csv statement pair (PgServerLogTail.TailCsvCteSql/TailCsvCteBinarySql)
when context.PgLogUsesCsvlog is set, and ReadAsync dispatches to a new
ReadCsvAsync that runs PgServerLogCsvParser.Parse on the raw body and
keeps only records whose Message is an auto_explain duration-plan
message. The stderr statements are untouched.
… the log format for it and its no-file fault can invalidate the verdict
… count a plan-less duration record as forged
@erikdarlingdata
erikdarlingdata force-pushed the fix/4053-csvlog-plan-capture branch from 7481f10 to e1f5263 Compare September 24, 2026 05:44
@erikdarlingdata erikdarlingdata changed the title DO NOT MERGE (stacked; the client-site coordinator arms it): 4053 part b2: pg_plan_capture reads csvlog when it's on (self-hosted) 4053 part b2: pg_plan_capture reads csvlog when it's on (self-hosted) Sep 24, 2026
@erikdarlingdata
erikdarlingdata marked this pull request as ready for review September 24, 2026 05:44
@erikdarlingdata
erikdarlingdata enabled auto-merge (squash) September 24, 2026 05:44
@erikdarlingdata
erikdarlingdata merged commit d74b74c into dev Sep 24, 2026
16 of 18 checks passed
@erikdarlingdata
erikdarlingdata deleted the fix/4053-csvlog-plan-capture branch September 24, 2026 05:57
erikdarlingdata added a commit that referenced this pull request Sep 24, 2026
…ut was missed

#4137 (pg_plan_capture reads csvlog) merged at 05:57Z with a CHANGELOG entry section in its
body. It was neither spliced nor listed as needing no entry. Its entry goes under Fixed, right
after #4136's, and #4136's last sentence now points to it instead of saying plan capture is
unchanged.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01NUU29PuGg9TUFBsACgZg2K
erikdarlingdata added a commit that referenced this pull request Sep 24, 2026
* Add 48 buffered CHANGELOG entries in one splice

Adds 48 entries and 48 link refs (#4057, #4077, #4079, #4081, #4082, #4083, #4084, #4085, #4086, #4087, #4088, #4089, #4090, #4091, #4092, #4093, #4095, #4096, #4099, #4100, #4101, #4103, #4105, #4106, #4107, #4108, #4109, #4110, #4111, #4113, #4114, #4115, #4116, #4117, #4118, #4119, #4120, #4121, #4122, #4123, #4124, #4125, #4126, #4127, #4131, #4133, #4136, #4141). Each PR's entry was buffered, and this lands every entry whose PR was merged on origin/dev when it ran.

Entries found under a bare section line (none unless the old script ran again) move into the matching ### section, below the new entries.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01QQh8LczP1HGLXQYAx4oTZC

* Changelog splice: add #4137's entry, which merged before the splice but was missed

#4137 (pg_plan_capture reads csvlog) merged at 05:57Z with a CHANGELOG entry section in its
body. It was neither spliced nor listed as needing no entry. Its entry goes under Fixed, right
after #4136's, and #4136's last sentence now points to it instead of saying plan capture is
unchanged.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01NUU29PuGg9TUFBsACgZg2K

---------

Co-authored-by: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
erikdarlingdata added a commit that referenced this pull request Sep 24, 2026
…ql innermost-frame parse

- CollectorMeasurementSeamTests: add PgDeadlocksCollector.RaiseShapedDeadlocksSkippedMeasurement
  to the fixed label list (review round 1, critical item).
- PgPlanCaptureCollector.PlanRowsFromCsvEntries: move the RAISE-shaped provenance guard BELOW the
  no-plan-text (msIndex < 0) skip, so a genuine log_min_duration_statement/log_duration record
  under verbose logging is skipped uncounted rather than counted as forged (review round 1 of
  #4137's ruling). Add a unit test for that ordering.
- ForgedCaptureNote: name RAISE-shaped captures explicitly.
- PgLogEntryProvenance.RaisedByPlpgsql: replace the first-physical-line " at RAISE" suffix test
  with a quote-aware parse of the innermost Context frame (function signature or inline_code_block,
  then " line N at KIND"), closing the bypass where a quoted function name containing a newline
  or " line 1 at SQL statement"-shaped text could defeat the old first-line split.

Part of #4058.
erikdarlingdata added a commit that referenced this pull request Sep 24, 2026
…#4153)

* PgLogEntry: carry the reporting function Location (#4058 plumbing)

* 4058 r2: PgLogEntryProvenance, the RAISE-shaped/reported-by-other check

* 4058 r2: IsRaiseShaped guards for deadlocks and plan captures

* 4058 r2: RDS deadlock ingestor counts and skips RAISE-shaped entries

* 4058 r3: PgLogEntryProvenanceTests (RaisedByPlpgsql/ReportedByOther units)

* 4058 r3: FromEntry/IsRaiseShaped units + csvlog raise-shaped-skipped test

* 4058 r3: PlanRowsFromCsvEntries raise-shaped-vs-real unit tests

* 4058 r3: RDS deadlock ingestor raise-shaped-skipped unit test

* 4058 live: RAISE-shaped deadlock and plan-capture records are not stored

Adds Darling/Darling.Tests/PgRaiseShapedRecordsLiveTests.cs, gated on
DARLING_TEST_PG_CSVLOG, proving against the collectors' own csv statement
plus ReadAsync:

1. A PL/pgSQL RAISE EXCEPTION shaped as a deadlock (message, DETAIL,
   ERRCODE 40P01) is skipped by PgDeadlocksCollector and counted under
   raise_shaped_deadlocks_skipped.
2. A REAL deadlock inside a function frame still comes out, matched to
   the victim's own pg_backend_pid().
3. A PL/pgSQL RAISE LOG shaped as an auto_explain plan capture is skipped
   by PgPlanCaptureCollector and counted under forged_captures_skipped.

* 4058 review round 1: seam list, provenance-guard order, RaisedByPlpgsql innermost-frame parse

- CollectorMeasurementSeamTests: add PgDeadlocksCollector.RaiseShapedDeadlocksSkippedMeasurement
  to the fixed label list (review round 1, critical item).
- PgPlanCaptureCollector.PlanRowsFromCsvEntries: move the RAISE-shaped provenance guard BELOW the
  no-plan-text (msIndex < 0) skip, so a genuine log_min_duration_statement/log_duration record
  under verbose logging is skipped uncounted rather than counted as forged (review round 1 of
  #4137's ruling). Add a unit test for that ordering.
- ForgedCaptureNote: name RAISE-shaped captures explicitly.
- PgLogEntryProvenance.RaisedByPlpgsql: replace the first-physical-line " at RAISE" suffix test
  with a quote-aware parse of the innermost Context frame (function signature or inline_code_block,
  then " line N at KIND"), closing the bypass where a quoted function name containing a newline
  or " line 1 at SQL statement"-shaped text could defeat the old first-line split.

Part of #4058.

* 4058: a function named inline_code_block is parsed as a signature, not a DO block (its RAISE failed open); the innermost-frame parser's unit tests

* 4058 review round 2: remarks say innermost frame, that terse logging loses both signals, and that a translated lc_messages fails open; a genuine duration record's Location is exec_simple_query/exec_execute_message
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