Skip to content

State the tail-overlap condition where the recovery claim is made, and pin it to the cadence - #3047

Merged
erikdarlingdata merged 2 commits into
devfrom
fix/plan-capture-tail-overlap-claim
Sep 5, 2026
Merged

erikdarlingdata merged 2 commits into
devfrom
fix/plan-capture-tail-overlap-claim

Conversation

@erikdarlingdata

Copy link
Copy Markdown
Owner

The schedule table described pg_deadlocks as "Every 5 minutes against a 4 MB tail, matching pg_plan_capture." pg_plan_capture runs every sixty minutes. The two do read the same file the same way — same pg_read_file call, same 4 MB tail, no resume marker on either — which is what makes the twelvefold cadence difference matter rather than merely be untidy.

What the overlap claim actually requires

Three doc comments explain truncation recovery in terms of consecutive reads overlapping: PgDeadlockLogParser's "re-reads an overlapping byte-window tail every cycle, so a report cut at one read's edge arrives whole in the next", PgPlanLogParser.Extract's "a block cut in half at the edge is an ordinary consequence", and PgPlanCaptureCollector's TailBytes summary.

The read is always the last TailBytes of the current file, so two cycles see overlapping text only while the log grows by less than one tail between them:

collector interval tail overlap holds below
pg_deadlocks 5 min 4 MiB ~13.7 KB/s
pg_plan_capture 60 min 4 MiB ~1.14 KB/s

Above that the windows stop touching and the span between them is read by no cycle. That is a different outcome from the one those comments describe: not a report cut at an edge and completed next time, but whole reports and whole plans never read at all. It is silent in both directions — nothing measures the log's write rate, so neither collector can distinguish a quiet server from a truncated view of a busy one, and downstream it reads as a target with no slow queries.

1.14 KB/s is about 98 MB/day. That is a low bar; a server doing nothing but logging connections can clear it.

The two transports fail in opposite directions, and one schedule number serves both

pg_plan_capture's schedule key dispatches on target type (DarlingWorker, the IsAurora || IsAwsRds branch):

  • Aurora and RDS reach the table through the log API, which is consume-once with a resume marker per (instance, file). An hour there batches more text per call and loses nothing. This is the case the 60 was chosen for, and it is correct for it.
  • Self-hosted is the bounded tail above, with no marker. An hour is where the arithmetic stops working.

The same is true of pg_deadlocks, which is already at five minutes.

pg_plan_capture also sits inside a comment justifying an hourly group on the grounds that "every one of these reads a CUMULATIVE counter ... or an append-only log, so a longer interval loses no events — it only widens the window each delta covers." That reasoning is sound for pg_wait_sampling, pg_kernel_stats and pg_predicate_stats, which are genuinely cumulative counters. It does not hold for a bounded-window read of a log, where "append-only" is not the property that governs coverage — how much of it a read can see is. Plan capture was the fourth member of a group whose stated justification excludes it.

What this changes, and what it deliberately does not

It states the condition at each place that leans on it, and pins the arithmetic. No cadence moves and the tail does not grow.

Why not drop pg_plan_capture to five minutes. It would make the parity claim true, and it does move the threshold to a comfortable place. But the cadence is shared with the consume-once transport that has no such exposure, and read-time dedup on (query_id, plan_hash) is a read concern — collect.pg_plan_capture has no unique constraint and every read groups, so twelve times the reads is twelve times the stored rows of full plan JSON against a 14-day retention, paid on every target to fix a threshold only self-hosted ones cross. That is a trade worth making deliberately rather than as a side effect of correcting a comment.

Why not grow the tail. It moves the threshold without establishing one. TailBytes' own summary cites #2565's measurement of 772 MB of log in twenty seconds at capture-everything — roughly 38 MB/s, about 34,000x the hourly threshold and 2,800x the five-minute one. No fixed tail bounds that.

What the real fix is, and why it is not here. The gap is not the size of the window, it is that the collector cannot say it missed anything. The query already selects the file's size; a stored previous size would make the skipped span a measurement instead of an absence. That is a new collector behaviour and a schema addition, so it belongs in its own change rather than riding a comment correction. Until then the interval is overridable per server (config.collector_schedule), and the comments say so.

The pin

Lite.Tests/LogTailOverlapThresholdPinTests.cs. The thresholds are derived from CollectorScheduleDefaults and each collector's own TailBytesLiteral, then compared against the figure the prose states — so changing a cadence or the tail fails rather than leaving a stale number behind. It also asserts both collectors read the same tail, that the two cadences are not equal, and that no comment claims they are.

Three things it does deliberately:

  • The parity detector has its own control. TheParityDetector_FiresOnTheClaimItGuardsAgainst feeds it the exact sentence being removed and a reworded variant, in both name directions. Without it the assertion would pass on any source that simply never says the word — an absence with no positive control behind it, which is the same shape as the drift.
  • Every threshold assertion is floored on the population it matched. A comment that stopped stating its threshold would otherwise satisfy the check by having nothing to check.
  • The theory is block-aware, not file-level. CollectorScheduleDefaults.cs legitimately states both thresholds, so each file must contain its own collector's figure and every figure stated must be one of the two the arithmetic produces. A first version asserted file-level and failed on the schedule table for the wrong reason.

Verification

Lite.Tests targets net10.0-windows and cannot execute on macOS (Microsoft.WindowsDesktop.App is absent for osx-arm64), so:

  • It compiles against real xunit.v3: dotnet build Lite.Tests -p:EnableWindowsTargeting=true → 0 errors, and none of the 9 warnings come from this file. Assert.Fail and the Equal(double, double, int) overload are real, not shimmed.
  • The logic executes 9/9 in a net10.0 console harness that Compile Includes the actual test source unmodified with an xunit shim, and a symlink so the pin's upward file walk resolves to the branch under test rather than to the main checkout.
  • 8 red-proof mutations, all red, across 3 distinct assertions — plan cadence to 5, deadlock cadence to 60, the false parity sentence restored, the two tails made to disagree, each threshold figure dropped, a bogus third figure inserted, and TailBytesLiteral renamed. Three of them fail different arms of the same theory (the floor, the own-threshold arm, the known-set arm).
  • Mutations ran against a copied sandbox, never the worktree, and the worktree was git status --porcelain clean afterwards. The harness asserts each variant produced a test summary, because a variant that never compiled is indistinguishable from one that passed.

Not verified: no live self-hosted PostgreSQL target exists in this fleet to observe the gap on — the arithmetic and the transport split are read from source and from #2565's recorded measurement, not from a target that lost a plan. The 772 MB/20s figure is quoted from the existing comment, not re-measured.

CHANGELOG entry text

Fixed — The pg_deadlocks schedule comment claimed a cadence match with pg_plan_capture; they run five and sixty minutes apart. The comments that rely on consecutive log-tail reads overlapping now state the condition that makes that true — log growth below one tail per interval, about 14 KB/s at five minutes and 1.2 KB/s at sixty — and a new pin derives each rate from the schedule table and the collectors' tail constants so a cadence or tail change cannot leave a stale figure behind.

…d pin it to the cadence

The schedule table described pg_deadlocks as matching pg_plan_capture; they run five minutes and sixty
minutes apart. Both read the same file through the same pg_read_file call with the same 4 MB tail, so the
overlap those comments rely on for truncation recovery holds only while the log grows by less than one
tail per interval - about 14 KB/s at five minutes and 1.2 KB/s at sixty. Past it consecutive reads stop
touching and the span between them is read by nobody.

The four comments that lean on that overlap now state the condition and the rate it holds under.
LogTailOverlapThresholdPinTests derives each rate from the schedule table and the collectors' own tail
constants and compares it against the figure the prose states, so changing a cadence or the tail fails
rather than leaving a stale number behind.
@claude

claude Bot commented Sep 5, 2026

Copy link
Copy Markdown

Reviewed. This PR is comment-only (no query/behavior changes) plus a new pin test, and it holds up:

  • Arithmetic checks out. 4 MiB / 300s / 1024 ≈ 13.65 KB/s and 4 MiB / 3600s / 1024 ≈ 1.14 KB/s — matches every "~14 KB/s" / "~1.2 KB/s" figure stated in CollectorScheduleDefaults.cs, PgDeadlockLogParser.cs, PgPlanCaptureCollector.cs, and PgPlanLogParser.cs.
  • TailBytesLiteral exists in both PgDeadlocksCollector.cs and PgPlanCaptureCollector.cs as "4194304" pre-PR, so the test's regex extraction isn't reading a constant the PR invented — it's reading what's actually spliced into the SQL.
  • The false parity claim ("matching pg_plan_capture" / "same as pg_deadlocks") is fully removed from source and only survives in the test's own positive-control strings for TheParityDetector_FiresOnTheClaimItGuardsAgainst — correct, that's the control proving the detector isn't vacuous.
  • No Lite/Darling parity drift: CollectorScheduleDefaults.cs is shared source consumed directly by both SKUs, and I confirmed no Darling file duplicates the "matching pg_plan_capture" comment, so there's nothing on the Darling side that also needed correcting.
  • One caveat worth knowing rather than fixing: ClaimsOfParity's regex ([^.\r\n]*...) can't span a line break, so it only catches the claim because it currently sits on one physical line in the block comment. If someone later rewraps that comment across lines, the detector goes quiet without the pin test noticing. Not a blocker given the wrapping convention in this file, just a latent gap in the guard itself.

One gap: the PR description drafts a CHANGELOG.md entry ("Fixed — The pg_deadlocks schedule comment claimed a cadence match with pg_plan_capture..."), but CHANGELOG.md isn't touched in the diff. The [Unreleased] section currently only has an ### Added subsection, so this would need a new ### Fixed subsection. Worth adding before merge if this repo's convention is changelog-per-PR (recent Unreleased entries suggest it is).

No correctness, security, or SQL-style issues — no T-SQL/query changes at all in this diff.

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