Skip to content

Part of #2894 - #2975

Merged
erikdarlingdata merged 2 commits into
devfrom
fix/2894-holder-bound-assessment
Sep 5, 2026
Merged

erikdarlingdata merged 2 commits into
devfrom
fix/2894-holder-bound-assessment

Conversation

@erikdarlingdata

@erikdarlingdata erikdarlingdata commented Sep 5, 2026 •

Copy link
Copy Markdown
Owner

Closes the last residual of #2894 by measuring it rather than building for it. MigrationCommandTimeoutSeconds (300 s) turns out to bound the migration-lock HOLDER after all — the question #2935 left open — and the part of it that does not bound is a rung SHAPE, not a missing mechanism. Doc comments carry the measurement; one pin covers the shape that escapes the bound silently. No SQL, no runtime path, no schema bump.

Can a rung exceed its own 300 s? Not by ignoring the cancel — that was measured, not reasoned about

CommandTimeout is a client-side cancel REQUEST, so whether it BINDS is an empirical question. Rig: timescale/timescaledb:latest-pg17 (PostgreSQL 17.11 / TimescaleDB 2.29.2), the real 109-rung ladder applied through the real MigrateAsync (0.303 s on an empty store), then the four floor-setting rungs' targets converted to hypertables the way the runtime does and seeded to 13.5 M rows / 90 chunks each — ~14.7 GB, with maintenance_work_mem squeezed to force the external sorts a cold busy store does. Unbounded durations there: V22 6.08 s, V39 4.28 s, V104 10.57 s, V23 25.61 s.

Each rung then applied through the applier's exact command shape — one NpgsqlCommand carrying the whole rung SQL, in its own transaction — at a scaled budget:

rung budget 1 s budget 2 s D/T at 2 s wait state at the last sample before it vanished
V22 1.04 s 2.05 s 3.0x IO/DataFileRead
V39 1.05 s 2.04 s 2.1x none (sampled in IO/DataFileRead mid-run)
V104 1.05 s 2.05 s 5.2x none
V23 1.06 s 2.07 s 12.4x IO/BuffileRead

Every one aborts within ~50 ms of the budget; a second connection polling pg_stat_activity every 150 ms shows the backend gone inside 0.4 s; the transaction rolls back whole and the client connection stays usable. Two of the four were in an I/O wait at the instant the cancel landed, which is the phase a client-side bound is most often assumed not to reach.

The realistic overrun was then run at the real constant through the real applier. A rung parked behind a peer's table lock is what a second instance collecting into the same store produces — CREATE INDEX needs ShareLock, an open INSERT holds RowExclusiveLock. V22 sat in Lock/relation for the entire budget (1944 samples, continuous) and gave up at 300.06 s, nothing applied and nothing stamped. So the lock-wait floor is a ceiling on real holds too, one budget per rung.

What it actually bounds is SILENCE, and that is where the residual lives

Npgsql implements CommandTimeout as a socket READ timeout: every backend message restarts it. Matched pair, same statement and the same 40 s of work both times, same 5 s budget —

  • one RAISE NOTICE per second: ran to completion at 40.18 s, the budget never fired
  • silent: cancelled at 5.02 s

That also explains the only deviation in the table above: V23 overshoots by exactly 3.00 s at both a 5 s and a 15 s budget, and 3.00 s is when create_hypertable's own last message arrives. Rollback cost 0.00 s, so it is the read timer restarting, not cleanup.

Today's ladder is quiet — no rung contains a LOOP, and V23's is its only RAISE, inside an exception handler that runs only when the rung is already failing. So V23's real ceiling is 303 s and the other three are 300.05 s. A rung that instrumented its own progress would not be cancelled at all.

The pin: no rung may trap its own cancellation

WHEN OTHERS deliberately does not match query_canceled, which is exactly what makes V23's DO block safe. Naming the condition reverses it, and the consequence is the silent one:

handler applier saw committed the rung's own work
WHEN OTHERS NpgsqlException <- TimeoutException no not done, not stamped
WHEN query_canceled SUCCESS yes not done — stamped anyway

So a rung one keyword from a shape the ladder already contains leaves the store permanently stamped at a version whose rung did nothing — destroying the "a stamp of N proves rung N committed" property MigrationLockWaitTimeoutSeconds' expiry split reads. MigrationDataMovingRungCensusPins.NoRungTrapsItsOwnCancellation fails the build on it: a token search over every rung's comment-stripped shipped SQL, deliberately not an attempt to parse a condition list, since WHEN OTHERS OR query_canceled and WHEN SQLSTATE '57014' are both the same defect and a rung's executable SQL has no legitimate reason to name its own cancellation. Zero occurrences today.

The tokens are word-bounded, and that is load-bearing in the FALSE-POSITIVE direction: unbounded, 57014 matches inside any longer digit run and query_canceled inside any longer identifier, so a rung carrying an unrelated numeric literal or a column named for the condition would fail the build accused of trapping a cancel. Measured against both forms, the boundaries cost nothing on any of the five real condition spellings — the quotes around '57014' already satisfy them — and turn 5701400, 157014, 570140 and my_query_canceled_flag from findings into misses.

Four controls, each red for a different reason: the pattern fires on a rung that does trap the cancel; the ladder still holds a real exception handler for the scan to be looking at (V23's — and after stripping it is the handler rather than the sentence in V23's own comment describing it, which is why stripping is not cosmetic here); a rung carrying the token in executable text is still found with a comment beside it; and each of the five condition spellings matches while each of the four innocent literals does not, so the pattern cannot be loosened back to a substring search with every other assertion still passing.

The three mechanisms NOT built, each declined on a measurement

  • A pg_cancel_backend / pg_terminate_backend watchdog buys nothing. Signalled at t+2 s against an infinite CommandTimeout, pg_cancel_backend stopped the same four rungs at 2.01-2.03 s and pg_terminate_backend at 2.01-2.05 s — against this applier's own 2.04-2.07 s on the identical rungs. All three arrive through the same CHECK_FOR_INTERRUPTS, so nothing one can stop is beyond the others. Terminate is worse than redundant: it reports 57P01, which StartupFailureTriage holds retryable, turning a rung that can never apply into one that is retried.
  • Splitting the expensive rungs for a per-statement budget helps one of four. V22, V23 and V104 are each a single statement. It buys that by raising the floor here from four multiples to five.
  • Server-side timeouts still have the wrong unit or reach, unchanged from Part of #2894 #2935: statement_timeout is per statement, transaction_timeout is 17+ and FATALs the session.

Two stale claims corrected

  • #2894's "no retry" is no longer the mechanism. A transient store outage at startup ends collection for the process lifetime — migrate failures are all terminal, with no retry and no triage #2936 added a retry loop around this MigrateAsync call, and StartupFailureTriage does classify the expiry's bare TimeoutException as retryable — but gates retries on a 120 s wall-clock budget, an order of magnitude under one spend of a 1500 s wait, deliberately so 25 attempts cannot become ten hours. The first expiry has already exhausted it and lands in the terminal arm. Same outcome, and it matters that the reason is by design rather than by omission, because "no retry" invites adding one.
  • "The holder stays unbounded" was too pessimistic, and the paragraph asserting it is replaced by what was measured.

Not changed, deliberately

MigrationLockWaitTimeoutSeconds stays 5 * MigrationCommandTimeoutSeconds and the census keeps its four floor-setting rungs, so TheLockWaitMultiple_IsOneMoreThanTheFloorContributingRungCount still derives 5 == 4 + 1 and needed no new reasoning: this changes what is known about whether the rung bound BINDS, not how many rungs spend it or what the floor is counted in.

Verification

Eleven mutations through redproof.sh, one at a time, each asserted applied by anchor count AND sha256 before/after, each confirmed to move behaviour, tree byte-clean after every restore: planting WHEN query_canceled and WHEN SQLSTATE '57014' into a real rung (both caught); neutering the pattern (the pattern control fires); an over-eager comment stripper (the liveness control fires); the token in a rung COMMENT only (stays green — the precision direction); planting predates this rung inside the 2864 slice and removing the 2864 anchor (both fire); and = 1500 and 6 * on the lock-wait constant (the derived-form pin fires on each), re-proving that coupling is still live after this edit. Loosening the word-bounded pattern back to a substring search fires the fourth control, so the hardening is itself pinned. Every mutation touching the pin file was re-run after the hardening; one refused to apply on a stale anchor rather than proving nothing silently, which is the anchor control doing its job.

Test count in MigrationDataMovingRungCensusPins: 27 -> 28.

CollectionLogDrainForensicsStoreTests' anchor re-verified: 2864 still resolves (one occurrence, line 2412), the edited doc comment sits inside the slice — asserted positively, not assumed — both DoesNotContain assertions hold, and the planted-phrase control proves they can still fail.

Darling.Tests compiles clean (-p:EnableWindowsTargeting=true, 0 errors, 0 warnings in either touched file); the 28 cases ran in a throwaway net10.0 host compiling the real pin file, and CI is the arbiter.

Container pg2894holder on port 5694, torn down.

Not verified

No production store — this adds no SQL and no runtime path. The rig is local NVMe, so the absolute rung durations are floors, which is the point of taking the bound from the constant rather than from timings. The "phase that never reaches an interrupt check" could not be produced on this rig, which is itself evidence about how reachable it is; the measurement shows only that no phase of these four rungs is one. transaction_timeout was not re-measured, being quoted from #2935.

…he shape that escapes it

The migration rung bound is honoured: measured against a seeded store, all four
floor-setting rungs abort within 50 ms of their budget, including from inside I/O
waits and from a full-budget heavyweight lock wait, so the lock-wait floor is a
ceiling on real holds too. What the bound covers is backend SILENCE rather than
wall clock, because Npgsql restarts it on every message, and the one rung shape
that escapes it silently -- a plpgsql handler naming query_canceled, which unlike
WHEN OTHERS does catch the cancel -- makes the applier commit and stamp a rung
whose work never happened. That shape now fails the build.
Comment thread Darling/Darling.Tests/MigrationDataMovingRungCensusPins.cs Outdated
@claude

claude Bot commented Sep 5, 2026

Copy link
Copy Markdown

Reviewed. This PR is doc-comments on two existing constants (MigrationCommandTimeoutSeconds, MigrationLockWaitTimeoutSeconds) plus one new pinned regression test (NoRungTrapsItsOwnCancellation) in the existing census-pin file — no new migration rung, no StorageVersion bump, no runtime code path changed. That matches the PR description's claim.

  • Parity: Postgres/Npgsql migration-timeout mechanics have no Lite counterpart (Lite is DuckDB-backed; its only references to PgMigrations are comments cross-linking schema parity). Nothing here needs a Lite twin — confirmed no parity gap.
  • T-SQL style: N/A, no T-SQL added or touched.
  • Test correctness: Walked through the new test's three controls against the real ladder — V23's EXCEPTION WHEN OTHERS (Darling/PerformanceMonitor.Darling.Storage/PgMigrations.cs:3898) is the only exception handler today and correctly satisfies control 2 only after StripComments removes the block comment that also happens to say "WHEN OTHERS" a few lines above it. Confirmed no rung currently contains 57014 or query_canceled in its executable SQL, so the new assertion is green for the right reason, not by accident.
  • Left one inline nit on the new s_cancelTrap regex (missing \b word boundaries around the numeric SQLSTATE code) — low severity, doesn't affect correctness of this PR today, just a hardening suggestion for the pin's failure mode.

No correctness, security, or performance concerns beyond that nit.

…build

Without word boundaries 57014 matches inside any longer digit run and
query_canceled inside any longer identifier, so a rung carrying an unrelated
numeric literal, or a column named for the condition, would fail the build
accused of trapping its own cancel. Measured against both forms: the boundaries
cost nothing on any of the five real condition spellings, since the quotes around
'57014' already satisfy them, and they turn 5701400, 157014, 570140 and
my_query_canceled_flag from findings into misses. A fourth control asserts both
halves, so the pattern cannot be loosened back with every other assertion still
passing.
@claude

claude Bot commented Sep 5, 2026

Copy link
Copy Markdown

Reviewed. This PR is doc-comments plus one new regression test - no runtime code, schema, or SQL path changes (confirmed via diff: only PgMigrations.cs XML-doc updates and the new NoRungTrapsItsOwnCancellation test in MigrationDataMovingRungCensusPins.cs).

Spot-checks performed rather than taking the doc claims at face value:

  • s_cancelTrap = \bquery_canceled\b|\b57014\b - manually traced word-boundary behavior against all 4 innocent cases (5701400, 157014, 570140, my_query_canceled_flag) and all 4 trap spellings in the test; the boundaries behave as documented (no false positives on longer digit runs/identifiers, no false negatives on any condition spelling including SQLSTATE '57014' since the surrounding quotes are non-word chars).
  • Control 2 (s_exceptionHandler liveness check) - confirmed V23's actual shipped SQL (PgMigrations.cs ~line 3898) contains EXCEPTION WHEN OTHERS THEN inside the real string literal (not just in the adjacent block comment above it), so StripComments plus the handler regex genuinely exercises real executable text, not a comment.
  • Cross-checked the new doc claims about StartupFailureTriage (120s RetryBudget, bare TimeoutException classified retryable, default-deny) against StartupFailureTriage.cs - matches. The order-of-magnitude claim against MigrationLockWaitTimeoutSeconds (1500s) also checks out (1500/120 = 12.5x).

No correctness bugs, no Lite/Darling parity drift (Lite has no Postgres migration ladder, so there is no counterpart to update), no security concerns (no new SQL execution, no input handling changes), no performance regressions (test-only, and the regex runs once per rung against a fixed, small script list).

Nothing further to flag.

@erikdarlingdata
erikdarlingdata merged commit 2bd7ad2 into dev Sep 5, 2026
9 of 10 checks passed
@erikdarlingdata
erikdarlingdata deleted the fix/2894-holder-bound-assessment branch September 5, 2026 02:18
erikdarlingdata added a commit that referenced this pull request Sep 5, 2026
…sproved (#2984)

The existing #2894 entry said the lock-wait expiry reaches the critical-log
stand-down "with no retry until an operator restarts it". #2936 has since made
that false in mechanism: there is a retry loop and the expiry does classify as
retryable. The outcome the entry describes still holds, but for a different
reason -- a deliberate 120s wall-clock budget that a single 1500s wait already
exceeds -- and "no retry" invites someone adding one.
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