From e67fbc690bc9a6ed7137de4297f2def5cec9a54c Mon Sep 17 00:00:00 2001 From: SqlRush Date: Tue, 14 Jul 2026 08:59:32 +0800 Subject: [PATCH 1/5] test(cluster_tap): t/017 inject baseline 179 -> 180 (stale count) The ownership-generation wave bumped the t/017 fault_type/hits inject counts by 6 to 179, but the wave landed 6 new injection points on top of a 174-point registry: t/015 and t/030 were correctly rolled to 180 while t/017 was left one short. Pre-existing red on main (fails identically at the branch base); align the count and label with the actual registry. --- src/test/cluster_tap/t/017_debug.pl | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/test/cluster_tap/t/017_debug.pl b/src/test/cluster_tap/t/017_debug.pl index c0cd50491f..979c9a4236 100644 --- a/src/test/cluster_tap/t/017_debug.pl +++ b/src/test/cluster_tap/t/017_debug.pl @@ -123,15 +123,15 @@ 'postgres', q{SELECT count(*) FROM pg_cluster_state WHERE category='inject' AND key LIKE '%.fault_type'}), - '179', - 'all 179 injection points have a .fault_type entry (ownership-gen wave +6 cluster-pcm-*; gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-5.22e D5-7 +2; spec-5.22d D4-8 +1; merge sum with 7.x lanes) under inject category (spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5 +2 cluster-relmap-crash-*; spec-6.14 D8 +1 cluster-catalog-services-ready-force-closed; spec-5.6a +1 cluster-recovery-anchor-force-failclosed; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 herding-stall + window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.13 +6 cluster-clean-leave-*; spec-2.41 +1 gcs-block-stale-ship; spec-5.2a +1 clean-xfer stale-holder; spec-4.8ab +2; spec-5.13 H1.0.3 +1 clean-leave-survivor-suppress-preflight-ack; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); + '180', + 'all 180 injection points have a .fault_type entry (ownership-gen wave +6 cluster-pcm-*; gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-5.22e D5-7 +2; spec-5.22d D4-8 +1; merge sum with 7.x lanes) under inject category (spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5 +2 cluster-relmap-crash-*; spec-6.14 D8 +1 cluster-catalog-services-ready-force-closed; spec-5.6a +1 cluster-recovery-anchor-force-failclosed; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 herding-stall + window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.13 +6 cluster-clean-leave-*; spec-2.41 +1 gcs-block-stale-ship; spec-5.2a +1 clean-xfer stale-holder; spec-4.8ab +2; spec-5.13 H1.0.3 +1 clean-leave-survivor-suppress-preflight-ack; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); is( $node->safe_psql( 'postgres', q{SELECT count(*) FROM pg_cluster_state WHERE category='inject' AND key LIKE '%.hits'}), - '179', - 'all 179 injection points have a .hits entry (ownership-gen wave +6 cluster-pcm-*; gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-5.22e D5-7 +2; spec-5.22d D4-8 +1; merge sum with 7.x lanes) under inject category (spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5 +2 cluster-relmap-crash-*; spec-6.14 D8 +1 cluster-catalog-services-ready-force-closed; spec-5.6a +1 cluster-recovery-anchor-force-failclosed; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 herding-stall + window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.13 +6 cluster-clean-leave-*; spec-2.41 +1 gcs-block-stale-ship; spec-5.2a +1 clean-xfer stale-holder; spec-4.8ab +2; spec-5.13 H1.0.3 +1 clean-leave-survivor-suppress-preflight-ack; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); + '180', + 'all 180 injection points have a .hits entry (ownership-gen wave +6 cluster-pcm-*; gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-5.22e D5-7 +2; spec-5.22d D4-8 +1; merge sum with 7.x lanes) under inject category (spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5 +2 cluster-relmap-crash-*; spec-6.14 D8 +1 cluster-catalog-services-ready-force-closed; spec-5.6a +1 cluster-recovery-anchor-force-failclosed; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 herding-stall + window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.13 +6 cluster-clean-leave-*; spec-2.41 +1 gcs-block-stale-ship; spec-5.2a +1 clean-xfer stale-holder; spec-4.8ab +2; spec-5.13 H1.0.3 +1 clean-leave-survivor-suppress-preflight-ack; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); # ---------- From 1e6d93bd7ec6e3c9fece2bb762fd475a222a8724 Mon Sep 17 00:00:00 2001 From: SqlRush Date: Tue, 14 Jul 2026 08:59:50 +0800 Subject: [PATCH 2/5] feat(cluster): S3 forensics step 1 -- 53R93 SCN detail, GES timeout source split, TT retention detail Observability-only instrumentation for the S3 bench triage; no protocol, wire, or on-disk change. 53R93 lost-write (cluster_gcs_block.c): - Producer sites (master-direct ship + holder-forward ship) LOG the verdict (expected pi_watermark_scn, shipped pd_block_scn, holder-local watermark view, requester/master, request_id, epoch) -- the SCN pair is only known on the producer; correlate with the requester by (tag, request_id). - Requester 53R93 ereports (master-direct, local-master X-transfer, storage-fallback verify) gain errdetail with request identity, the local page/watermark view and the per-buffer ownership generation; the fallback detail also separates a stale storage page from a dirty-refused local refresh. GES timeout attribution (cluster_ges.c / cluster_lock_acquire.c / lock.c / cluster_debug.c): - "cluster lock acquire timeout" folds nine failure sites (reply-wait table full, master wait-queue full, outbound ring full, CV deadline, retransmit budget, native probe, convert twins) into one text. A backend-local ClusterGesTimeoutDetail records the fine source at each site, is reset at the seven-step dispatch funnel, and surfaces in the 53R70 errdetail (source/master/elapsed/attempts/conflict_holders/ effective timeout). - Five shmem breakdown counters (true-wait / capacity / send-fail / retransmit-exhausted / native-probe) split how many surfaced timeouts never actually waited; exposed via dump_ges and asserted by the new t/286 L11b/L11c on a real bounded wait. TT retention (cluster_tt_local.c): - The retention-rollover-failed and 48-slots-full ereports gain errdetail with the retention horizon vs current SCN, recycle/skip/wrap counters, segment reuse/switch/hard-cap counters and the pool cap, separating a stalled cleaner from genuine capacity pressure. Unit: stubs for the new symbols in test_cluster_debug.c and test_cluster_lock_acquire.c (standalone link surface). Local gates: cluster_unit 177, cluster_regress 13, PG regress 219/219, TAP t/017 t/108 t/110 t/116 t/280 t/285 t/286 green, check-format 0. --- src/backend/cluster/cluster_debug.c | 13 ++ src/backend/cluster/cluster_gcs_block.c | 179 ++++++++++++++---- src/backend/cluster/cluster_ges.c | 171 ++++++++++++++++- src/backend/cluster/cluster_lock_acquire.c | 8 + src/backend/cluster/cluster_tt_local.c | 59 ++++-- src/backend/storage/lmgr/lock.c | 15 +- src/include/cluster/cluster_ges.h | 56 ++++++ src/test/cluster_tap/t/286_ul_advisory.pl | 19 ++ src/test/cluster_unit/test_cluster_debug.c | 32 ++++ .../cluster_unit/test_cluster_lock_acquire.c | 15 ++ 10 files changed, 513 insertions(+), 54 deletions(-) diff --git a/src/backend/cluster/cluster_debug.c b/src/backend/cluster/cluster_debug.c index 745b40e74d..cd80df5b3e 100644 --- a/src/backend/cluster/cluster_debug.c +++ b/src/backend/cluster/cluster_debug.c @@ -1743,6 +1743,19 @@ dump_ges(ReturnSetInfo *rsinfo) fmt_int64((int64)cluster_txw_get_wakeup_count())); emit_row(rsinfo, "ges", "tx_enqueue_timeout_count", fmt_int64((int64)cluster_txw_get_timeout_count())); + /* S3 forensics step 1 — breakdown of the "cluster lock acquire timeout" + * fold: how many surfaced timeouts genuinely ran out the clock vs failed + * immediately on capacity / send / probe (never waited at all). */ + emit_row(rsinfo, "ges", "ges_timeout_true_wait_count", + fmt_int64((int64)cluster_ges_timeout_true_wait_count())); + emit_row(rsinfo, "ges", "ges_timeout_capacity_count", + fmt_int64((int64)cluster_ges_timeout_capacity_count())); + emit_row(rsinfo, "ges", "ges_timeout_send_fail_count", + fmt_int64((int64)cluster_ges_timeout_send_fail_count())); + emit_row(rsinfo, "ges", "ges_timeout_retransmit_exhausted_count", + fmt_int64((int64)cluster_ges_timeout_retransmit_exhausted_count())); + emit_row(rsinfo, "ges", "ges_timeout_native_probe_count", + fmt_int64((int64)cluster_ges_timeout_native_probe_count())); } diff --git a/src/backend/cluster/cluster_gcs_block.c b/src/backend/cluster/cluster_gcs_block.c index 6b6db665d0..d0b9f2eaf6 100644 --- a/src/backend/cluster/cluster_gcs_block.c +++ b/src/backend/cluster/cluster_gcs_block.c @@ -68,6 +68,7 @@ #include "cluster/cluster_ic_tier1.h" /* PGRAC: spec-7.3 D5 — my DATA channel = worker id */ #include "cluster/cluster_lmon.h" #include "cluster/cluster_pcm_lock.h" +#include "cluster/cluster_pcm_own.h" /* S3 forensics — ownership gen in 53R93 errdetail */ #include "cluster/cluster_shmem.h" #include "cluster/storage/cluster_shared_fs.h" #include "cluster/cluster_sf_dep.h" @@ -1265,6 +1266,7 @@ cluster_gcs_block_fallback_verify_refresh(BufferDesc *buf, BufferTag tag, SCN ex { SCN page_scn; GcsLostWriteVerdict verdict; + bool refreshed = false; /* S3 forensics — storage re-read happened */ if (buf == NULL || !SCN_VALID(expected_scn)) return; @@ -1279,6 +1281,7 @@ cluster_gcs_block_fallback_verify_refresh(BufferDesc *buf, BufferTag tag, SCN ex /* Local copy provably stale (or unstamped on a tracked tag): re-read. */ if (cluster_bufmgr_refresh_block_from_storage_for_gcs(buf, &page_scn)) { pg_atomic_fetch_add_u64(&ClusterGcsBlock->fallback_scn_refresh_count, 1); + refreshed = true; /* Deterministic fail-closed drive (t/348 L7): pretend the storage * copy came back unstamped (ANOMALY) — mirrors the master-direct @@ -1293,20 +1296,38 @@ cluster_gcs_block_fallback_verify_refresh(BufferDesc *buf, BufferTag tag, SCN ex } /* Refresh refused (dirty local copy) or the storage page is itself - * still below the master watermark: fail closed / staging WARN. */ + * still below the master watermark: fail closed / staging WARN. + * S3 forensics step 1 — errdetail carries the verdict pair: refreshed + * distinguishes "shared-storage page itself below the watermark" (a + * true-lost-write signal: no replica reaches expected) from "dirty + * local copy refused refresh" (page_scn is then the pre-refresh local + * read). */ pg_atomic_fetch_add_u64(&ClusterGcsBlock->fallback_scn_failclosed_count, 1); if (cluster_gcs_block_lost_write_action == 0 /* ERROR */) - ereport(ERROR, (errcode(ERRCODE_CLUSTER_LOST_WRITE_DETECTED), - errmsg("cluster_gcs_block: stale storage-fallback copy detected on tag " - "spc=%u db=%u rel=%u block=%u", - tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum), - errhint("The local/storage page pd_block_scn is below the master " - "pi_watermark_scn carried by the GRANTED_STORAGE_FALLBACK " - "reply. Inspect dump_gcs.fallback_scn_failclosed_count. " - "Retry is safe (the next attempt renegotiates)."))); - ereport(WARNING, (errmsg("cluster_gcs_block: stale storage-fallback copy on tag " - "spc=%u db=%u rel=%u block=%u (action=warn)", - tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum))); + ereport( + ERROR, + (errcode(ERRCODE_CLUSTER_LOST_WRITE_DETECTED), + errmsg("cluster_gcs_block: stale storage-fallback copy detected on tag " + "spc=%u db=%u rel=%u block=%u", + tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum), + errdetail("expected pi_watermark_scn=" UINT64_FORMAT " %s pd_block_scn=" UINT64_FORMAT + " local pi_watermark_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT ".", + (uint64)expected_scn, refreshed ? "storage" : "local(dirty-refused)", + (uint64)page_scn, (uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), + cluster_pcm_own_gen_get(buf->buf_id)), + errhint("The local/storage page pd_block_scn is below the master " + "pi_watermark_scn carried by the GRANTED_STORAGE_FALLBACK " + "reply. Inspect dump_gcs.fallback_scn_failclosed_count. " + "Retry is safe (the next attempt renegotiates)."))); + ereport(WARNING, + (errmsg("cluster_gcs_block: stale storage-fallback copy on tag " + "spc=%u db=%u rel=%u block=%u (action=warn)", + tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum), + errdetail("expected pi_watermark_scn=" UINT64_FORMAT " %s pd_block_scn=" UINT64_FORMAT + " local pi_watermark_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT ".", + (uint64)expected_scn, refreshed ? "storage" : "local(dirty-refused)", + (uint64)page_scn, (uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), + cluster_pcm_own_gen_get(buf->buf_id)))); } @@ -2197,17 +2218,38 @@ cluster_gcs_send_block_request_and_wait(BufferDesc *buf, PcmLockTransition trans * GUC cluster.gcs_block_lost_write_action selects ereport(53R93) * for production (default) or WARNING for staging/diagnostic. */ if (final_status == GCS_BLOCK_REPLY_DENIED_LOST_WRITE) { + /* S3 forensics step 1 — requester-side identity + local-view SCNs + * for the three-branch lost-write qualification (true stale ship + * vs true lost write vs watermark false-positive). The verdict's + * (expected, shipped) SCN pair is only known on the PRODUCER + * (master / forwarding holder); its LOG line correlates with this + * errdetail by (tag, request_id). Reads are pre-ereport and + * lock-safe: the content lock is NOT held here (installs above + * take it internally), gen read is a NULL-safe atomic. */ + SCN forens_local_scn = cluster_bufmgr_read_block_scn_for_gcs(buf); + SCN forens_local_wm = cluster_pcm_lock_pi_watermark_scn_query(tag); + uint64 forens_own_gen = cluster_pcm_own_gen_get(buf->buf_id); + if (cluster_gcs_block_lost_write_action == 0 /* ERROR */) { terminal_denied = true; - ereport(ERROR, (errcode(ERRCODE_CLUSTER_LOST_WRITE_DETECTED), - errmsg("cluster_gcs_block: lost write detected on tag " - "spc=%u db=%u rel=%u block=%u", - tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum), - errhint("Shipped block.pd_block_scn is below the master " - "pi_watermark_scn (or the tracked block shipped an " - "unstamped page). Inspect dump_gcs." - "lost_write_detected_count and cluster_pcm_grd " - "to identify the stale source. spec-2.41 D1."))); + ereport(ERROR, + (errcode(ERRCODE_CLUSTER_LOST_WRITE_DETECTED), + errmsg("cluster_gcs_block: lost write detected on tag " + "spc=%u db=%u rel=%u block=%u", + tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum), + errdetail("request_id=" UINT64_FORMAT " request_epoch=" UINT64_FORMAT + " master=%d transition=%d retry_attempt=%d" + " local pd_block_scn=" UINT64_FORMAT + " local pi_watermark_scn=" UINT64_FORMAT + " ownership_gen=" UINT64_FORMAT ".", + request_id, slot->request_epoch, current_master, + (int)transition_id, retry_attempt, (uint64)forens_local_scn, + (uint64)forens_local_wm, forens_own_gen), + errhint("Shipped block.pd_block_scn is below the master " + "pi_watermark_scn (or the tracked block shipped an " + "unstamped page). Inspect dump_gcs." + "lost_write_detected_count and cluster_pcm_grd " + "to identify the stale source. spec-2.41 D1."))); } else { /* WARN action: do NOT error. This diagnostic mode intentionally * lets the caller proceed with the existing/storage-fallback block — @@ -2218,9 +2260,18 @@ cluster_gcs_send_block_request_and_wait(BufferDesc *buf, PcmLockTransition trans * risk, never the production default. Avoid terminal_denied, * otherwise the post-loop switch raises a generic * FEATURE_NOT_SUPPORTED. */ - ereport(WARNING, (errmsg("cluster_gcs_block: lost write detected on tag " - "spc=%u db=%u rel=%u block=%u (action=warn)", - tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum))); + ereport(WARNING, + (errmsg("cluster_gcs_block: lost write detected on tag " + "spc=%u db=%u rel=%u block=%u (action=warn)", + tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum), + errdetail("request_id=" UINT64_FORMAT " request_epoch=" UINT64_FORMAT + " master=%d transition=%d retry_attempt=%d" + " local pd_block_scn=" UINT64_FORMAT + " local pi_watermark_scn=" UINT64_FORMAT + " ownership_gen=" UINT64_FORMAT ".", + request_id, slot->request_epoch, current_master, + (int)transition_id, retry_attempt, (uint64)forens_local_scn, + (uint64)forens_local_wm, forens_own_gen))); granted_storage_fallback = true; } break; @@ -3584,22 +3635,49 @@ cluster_gcs_local_master_x_transfer_and_wait(BufferDesc *buf, int32 holder_node, * possibly-stale storage-fallback block — a staging-only diagnostic risk). */ if (got_reply && reply_status == (uint8)GCS_BLOCK_REPLY_DENIED_LOST_WRITE) { + /* S3 forensics step 1 — THIS node is the master on the local-master + * X-transfer path, so both the expected watermark SENT to the holder + * (fwd payload) and the authoritative watermark NOW are known here; + * the holder's LOG line carries the shipped pd_block_scn it refused + * (correlate by tag + request_id). Three-branch qualification: a + * NOW > SENT drift flags a watermark advance racing the transfer; + * local pd_block_scn is this requester's (pre-transfer) copy. */ + SCN forens_expected_sent = GcsBlockForwardPayloadGetExpectedPiWatermarkScn(&fwd); + SCN forens_master_wm_now = cluster_pcm_lock_pi_watermark_scn_query(tag); + SCN forens_local_scn = cluster_bufmgr_read_block_scn_for_gcs(buf); + uint64 forens_own_gen = cluster_pcm_own_gen_get(buf->buf_id); + if (cluster_gcs_block_lost_write_action == 0 /* ERROR */) - ereport(ERROR, - (errcode(ERRCODE_CLUSTER_LOST_WRITE_DETECTED), - errmsg("cluster_gcs_block: lost write detected on tag " - "spc=%u db=%u relNumber=%u block=%u", - tag.spcOid, tag.dbOid, (unsigned int)BufTagGetRelNumber(&tag), - (unsigned int)tag.blockNum), - errhint("The holder-forward shipped block.pd_block_scn is below the " - "master pi_watermark_scn (or a tracked block shipped an " - "unstamped page). Inspect dump_gcs.lost_write_detected_count " - "and cluster_pcm_grd to find the stale source. spec-2.41 D5."))); + ereport( + ERROR, + (errcode(ERRCODE_CLUSTER_LOST_WRITE_DETECTED), + errmsg("cluster_gcs_block: lost write detected on tag " + "spc=%u db=%u relNumber=%u block=%u", + tag.spcOid, tag.dbOid, (unsigned int)BufTagGetRelNumber(&tag), + (unsigned int)tag.blockNum), + errdetail("request_id=" UINT64_FORMAT " epoch=" UINT64_FORMAT " holder=%d" + " expected pi_watermark_scn sent=" UINT64_FORMAT + " master pi_watermark_scn now=" UINT64_FORMAT + " local pd_block_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT ".", + request_id, fwd.epoch, holder_node, (uint64)forens_expected_sent, + (uint64)forens_master_wm_now, (uint64)forens_local_scn, forens_own_gen), + errhint("The holder-forward shipped block.pd_block_scn is below the " + "master pi_watermark_scn (or a tracked block shipped an " + "unstamped page). Inspect dump_gcs.lost_write_detected_count " + "and cluster_pcm_grd to find the stale source. spec-2.41 D5."))); else ereport(WARNING, (errmsg("cluster_gcs_block: lost write detected on tag " "spc=%u db=%u relNumber=%u block=%u (action=warn)", tag.spcOid, tag.dbOid, (unsigned int)BufTagGetRelNumber(&tag), - (unsigned int)tag.blockNum))); + (unsigned int)tag.blockNum), + errdetail("request_id=" UINT64_FORMAT " epoch=" UINT64_FORMAT + " holder=%d expected pi_watermark_scn sent=" UINT64_FORMAT + " master pi_watermark_scn now=" UINT64_FORMAT + " local pd_block_scn=" UINT64_FORMAT + " ownership_gen=" UINT64_FORMAT ".", + request_id, fwd.epoch, holder_node, + (uint64)forens_expected_sent, (uint64)forens_master_wm_now, + (uint64)forens_local_scn, forens_own_gen))); } /* @@ -5302,6 +5380,19 @@ cluster_gcs_handle_block_request_envelope(const ClusterICEnvelope *env, const vo if (ClusterGcsBlock != NULL) pg_atomic_fetch_add_u64(&ClusterGcsBlock->lost_write_not_scn_tracked_skip_count, 1); } else if (verdict == GCS_LOST_WRITE_FAIL_STALE || verdict == GCS_LOST_WRITE_FAIL_ANOMALY) { + /* S3 forensics step 1 — the (expected, shipped) verdict SCN pair is + * only known on this producer; LOG it so the requester's 53R93 + * errdetail correlates by (tag, request_id) for the three-branch + * lost-write qualification. */ + ereport(LOG, (errmsg_internal( + "cluster_gcs_block: lost-write verdict %s on master-direct ship: tag " + "spc=%u db=%u rel=%u block=%u expected pi_watermark_scn=" UINT64_FORMAT + " shipped pd_block_scn=" UINT64_FORMAT + " requester=%d request_id=" UINT64_FORMAT " transition=%d", + verdict == GCS_LOST_WRITE_FAIL_STALE ? "STALE" : "ANOMALY", + req->tag.spcOid, req->tag.dbOid, req->tag.relNumber, req->tag.blockNum, + (uint64)expected_scn, (uint64)shipped_scn, req->sender_node, + req->request_id, (int)req->transition_id))); status = GCS_BLOCK_REPLY_DENIED_LOST_WRITE; page_lsn = InvalidXLogRecPtr; gcs_block_release_ship_image(block_payload_release_cb, block_payload_release_arg); @@ -6297,6 +6388,24 @@ cluster_gcs_handle_block_forward_envelope(const ClusterICEnvelope *env, const vo verdict = gcs_block_lost_write_verdict(expected_scn, shipped_scn); if (verdict == GCS_LOST_WRITE_FAIL_STALE || verdict == GCS_LOST_WRITE_FAIL_ANOMALY) { + /* S3 forensics step 1 — the (expected, shipped) verdict SCN pair is + * only known on this holder; LOG it so the original requester's + * 53R93 errdetail correlates by (tag, request_id). The holder's + * LOCAL watermark view (usually behind the master's authoritative + * one carried in the forward payload) separates a genuinely stale + * holder copy from a master-side watermark false-positive. */ + ereport( + LOG, + (errmsg_internal( + "cluster_gcs_block: lost-write verdict %s on holder-forward ship: tag " + "spc=%u db=%u rel=%u block=%u expected pi_watermark_scn=" UINT64_FORMAT + " shipped pd_block_scn=" UINT64_FORMAT + " holder-local pi_watermark_scn=" UINT64_FORMAT + " requester=%d master=%d request_id=" UINT64_FORMAT " epoch=" UINT64_FORMAT, + verdict == GCS_LOST_WRITE_FAIL_STALE ? "STALE" : "ANOMALY", fwd->tag.spcOid, + fwd->tag.dbOid, fwd->tag.relNumber, fwd->tag.blockNum, (uint64)expected_scn, + (uint64)shipped_scn, (uint64)cluster_pcm_lock_pi_watermark_scn_query(fwd->tag), + fwd->original_requester_node, fwd->master_node, fwd->request_id, fwd->epoch))); gcs_block_release_ship_image(block_payload_release_cb, block_payload_release_arg); block_payload = NULL; block_payload_lkey = 0; diff --git a/src/backend/cluster/cluster_ges.c b/src/backend/cluster/cluster_ges.c index f68e407239..26f7da7b9c 100644 --- a/src/backend/cluster/cluster_ges.c +++ b/src/backend/cluster/cluster_ges.c @@ -166,6 +166,12 @@ cluster_ges_shmem_init(void) /* spec-2.13 D3 init zero (Q4.1=A all-atomic, no LWLock). */ pg_atomic_init_u64(&cluster_ges_state->request_defer_count, 0); pg_atomic_init_u64(&cluster_ges_state->reply_defer_count, 0); + /* S3 forensics step 1 — timeout-source breakdown counters. */ + pg_atomic_init_u64(&cluster_ges_state->timeout_true_wait_count, 0); + pg_atomic_init_u64(&cluster_ges_state->timeout_capacity_count, 0); + pg_atomic_init_u64(&cluster_ges_state->timeout_send_fail_count, 0); + pg_atomic_init_u64(&cluster_ges_state->timeout_retransmit_exhausted_count, 0); + pg_atomic_init_u64(&cluster_ges_state->timeout_native_probe_count, 0); } } @@ -1438,6 +1444,128 @@ cluster_ges_reply_defer_count(void) } +/* ============================================================ + * S3 forensics step 1 (07-14) — GES timeout-source breakdown. + * + * Backend-local detail of the LAST failure site that will surface as + * FAIL_TIMEOUT / "cluster lock acquire timeout" (see cluster_ges.h). + * The setter also bumps the matching shmem breakdown counter so the + * aggregate split (true wait vs capacity vs send-fail vs retransmit + * vs native-probe) is provable from dump_ges after a bench run. + * ============================================================ */ + +static ClusterGesTimeoutDetail ges_timeout_detail; /* backend-local */ + +void +cluster_ges_timeout_detail_set(ClusterGesTimeoutSrc src, int32 master_node, long elapsed_ms, + int attempts, int conflict_holders, int timeout_ms) +{ + ges_timeout_detail.source = src; + ges_timeout_detail.master_node = master_node; + ges_timeout_detail.elapsed_ms = elapsed_ms; + ges_timeout_detail.attempts = attempts; + ges_timeout_detail.conflict_holders = conflict_holders; + ges_timeout_detail.timeout_ms = timeout_ms; + + if (cluster_ges_state == NULL) + return; + switch (src) { + case CLUSTER_GES_TSRC_CV_WAIT_TIMEOUT: + pg_atomic_fetch_add_u64(&cluster_ges_state->timeout_true_wait_count, 1); + break; + case CLUSTER_GES_TSRC_REPLY_WAIT_TABLE_FULL: + case CLUSTER_GES_TSRC_MASTER_WAIT_QUEUE_FULL: + pg_atomic_fetch_add_u64(&cluster_ges_state->timeout_capacity_count, 1); + break; + case CLUSTER_GES_TSRC_OUTBOUND_RING_FULL: + pg_atomic_fetch_add_u64(&cluster_ges_state->timeout_send_fail_count, 1); + break; + case CLUSTER_GES_TSRC_RETRANSMIT_EXHAUSTED: + pg_atomic_fetch_add_u64(&cluster_ges_state->timeout_retransmit_exhausted_count, 1); + break; + case CLUSTER_GES_TSRC_NATIVE_PROBE_TIMEOUT: + pg_atomic_fetch_add_u64(&cluster_ges_state->timeout_native_probe_count, 1); + break; + case CLUSTER_GES_TSRC_NONE: + case CLUSTER_GES_TSRC_NULL_ARG: + break; + } +} + +void +cluster_ges_timeout_detail_reset(void) +{ + memset(&ges_timeout_detail, 0, sizeof(ges_timeout_detail)); + ges_timeout_detail.master_node = -1; + ges_timeout_detail.conflict_holders = -1; +} + +const ClusterGesTimeoutDetail * +cluster_ges_timeout_detail_get(void) +{ + return &ges_timeout_detail; +} + +const char * +cluster_ges_timeout_src_text(ClusterGesTimeoutSrc src) +{ + switch (src) { + case CLUSTER_GES_TSRC_NONE: + return "unattributed"; + case CLUSTER_GES_TSRC_NULL_ARG: + return "null-argument"; + case CLUSTER_GES_TSRC_REPLY_WAIT_TABLE_FULL: + return "reply-wait-table-full"; + case CLUSTER_GES_TSRC_MASTER_WAIT_QUEUE_FULL: + return "master-wait-queue-full"; + case CLUSTER_GES_TSRC_OUTBOUND_RING_FULL: + return "outbound-ring-full"; + case CLUSTER_GES_TSRC_CV_WAIT_TIMEOUT: + return "cv-wait-timeout"; + case CLUSTER_GES_TSRC_RETRANSMIT_EXHAUSTED: + return "retransmit-exhausted"; + case CLUSTER_GES_TSRC_NATIVE_PROBE_TIMEOUT: + return "native-probe-timeout"; + } + return "unknown"; +} + +uint64 +cluster_ges_timeout_true_wait_count(void) +{ + Assert(cluster_ges_state != NULL); + return pg_atomic_read_u64(&cluster_ges_state->timeout_true_wait_count); +} + +uint64 +cluster_ges_timeout_capacity_count(void) +{ + Assert(cluster_ges_state != NULL); + return pg_atomic_read_u64(&cluster_ges_state->timeout_capacity_count); +} + +uint64 +cluster_ges_timeout_send_fail_count(void) +{ + Assert(cluster_ges_state != NULL); + return pg_atomic_read_u64(&cluster_ges_state->timeout_send_fail_count); +} + +uint64 +cluster_ges_timeout_retransmit_exhausted_count(void) +{ + Assert(cluster_ges_state != NULL); + return pg_atomic_read_u64(&cluster_ges_state->timeout_retransmit_exhausted_count); +} + +uint64 +cluster_ges_timeout_native_probe_count(void) +{ + Assert(cluster_ges_state != NULL); + return pg_atomic_read_u64(&cluster_ges_state->timeout_native_probe_count); +} + + /* ============================================================ * spec-2.21 D8 — GES request/release send-and-wait stubs. * @@ -1553,6 +1681,7 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo if (resid == NULL || holder == NULL) { cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_NULL_ARG, -1, 0, 0, -1, timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -1627,6 +1756,8 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo if (action != CLUSTER_GRD_ENQUEUED_WAITER) { /* WAIT_QUEUE_FULL / NOT_READY / ILLEGAL — fail closed, never grant. */ cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_MASTER_WAIT_QUEUE_FULL, cluster_node_id, + 0, 0, n_conflict, timeout_ms); return GES_REJECT_REASON_WORK_QUEUE_FULL; } @@ -1656,7 +1787,9 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo entry = cluster_ges_reply_wait_insert(&key, deadline); if (entry == NULL) { (void)cluster_grd_cancel_waiter_by_id(resid, holder); - cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ + cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_REPLY_WAIT_TABLE_FULL, cluster_node_id, + 0, 0, n_conflict, perpetual ? -1 : effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; /* fail closed */ } @@ -1738,9 +1871,14 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo * here. cancel_waiter removes a still-queued waiter (OK -> timeout) * or reports NOT_FOUND (already granted -> accept the grant). */ cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ - if (cluster_grd_cancel_waiter_by_id(resid, holder) == CLUSTER_GRD_ENTRY_OK) + if (cluster_grd_cancel_waiter_by_id(resid, holder) == CLUSTER_GRD_ENTRY_OK) { + /* timed_out only sets in finite mode: effective_timeout_ms valid. */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_CV_WAIT_TIMEOUT, cluster_node_id, + (long)effective_timeout_ms, 0, n_conflict, + effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; /* fail closed */ - return GES_REJECT_REASON_NONE; /* grant won the race */ + } + return GES_REJECT_REASON_NONE; /* grant won the race */ } reject_reason = entry->reject_reason; @@ -1795,6 +1933,8 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo "(request_id=" UINT64_FORMAT " dest=%d) — fail closed", request_id, master))); cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_REPLY_WAIT_TABLE_FULL, master, 0, 0, -1, + effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -1822,6 +1962,8 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo /* Outbound ring full — fail closed. Caller may retry. */ cluster_ges_reply_wait_delete(&key); cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_OUTBOUND_RING_FULL, master, 0, 0, -1, + effective_timeout_ms); return GES_REJECT_REASON_WORK_QUEUE_FULL; } @@ -1903,6 +2045,9 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo ConditionVariableCancelSleep(); cluster_xp_end(&xp_wait); /* PGRAC: spec-5.59 D2 profiling */ cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_CV_WAIT_TIMEOUT, master, + (long)effective_timeout_ms, attempt, -1, + effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } remaining_ms = (long)((deadline - now) / 1000); @@ -1928,10 +2073,15 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo } if (!perpetual && max_attempts > 0 && attempt > max_attempts) { + long forens_elapsed_ms + = (long)effective_timeout_ms - (long)((deadline - GetCurrentTimestamp()) / 1000); + ges_abandon_wait_or_release(&key, &req, master, send_opcode); ConditionVariableCancelSleep(); cluster_xp_end(&xp_wait); /* PGRAC: spec-5.59 D2 profiling */ cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_RETRANSMIT_EXHAUSTED, master, + forens_elapsed_ms, attempt, -1, effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -1968,6 +2118,8 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo ConditionVariableCancelSleep(); cluster_xp_end(&xp_wait); /* PGRAC: spec-5.59 D2 profiling */ cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_OUTBOUND_RING_FULL, master, 0, attempt, + -1, effective_timeout_ms); return GES_REJECT_REASON_WORK_QUEUE_FULL; } if (cluster_ges_state != NULL) @@ -2263,6 +2415,7 @@ cluster_ges_send_convert_and_wait(const struct ClusterResId *resid, uint32 reque if (resid == NULL || holder == NULL) { cluster_xp_end(&xp_convert); /* PGRAC: spec-5.59 D2 profiling */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_NULL_ARG, -1, 0, 0, -1, timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -2283,6 +2436,8 @@ cluster_ges_send_convert_and_wait(const struct ClusterResId *resid, uint32 reque if (!cluster_lms_native_probe_wait_clear(resid, (LOCKMODE)requested_mode, holder, effective_timeout_ms)) { cluster_xp_end(&xp_convert); /* PGRAC: spec-5.59 D2 profiling */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_NATIVE_PROBE_TIMEOUT, cluster_node_id, + (long)effective_timeout_ms, 0, -1, effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } } @@ -2297,6 +2452,9 @@ cluster_ges_send_convert_and_wait(const struct ClusterResId *resid, uint32 reque entry = cluster_ges_reply_wait_insert(&key, deadline); if (entry == NULL) { cluster_xp_end(&xp_convert); /* PGRAC: spec-5.59 D2 profiling */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_REPLY_WAIT_TABLE_FULL, + local_master ? cluster_node_id : master, 0, 0, -1, + effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -2323,12 +2481,16 @@ cluster_ges_send_convert_and_wait(const struct ClusterResId *resid, uint32 reque if (!cluster_grd_work_queue_enqueue(cluster_node_id, &req, sizeof(req))) { cluster_ges_reply_wait_delete(&key); cluster_xp_end(&xp_convert); /* PGRAC: spec-5.59 D2 profiling */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_MASTER_WAIT_QUEUE_FULL, cluster_node_id, + 0, 0, -1, effective_timeout_ms); return GES_REJECT_REASON_WORK_QUEUE_FULL; } } else { if (!cluster_grd_outbound_enqueue_backend_request((uint32)master, &req, sizeof(req))) { cluster_ges_reply_wait_delete(&key); cluster_xp_end(&xp_convert); /* PGRAC: spec-5.59 D2 profiling */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_OUTBOUND_RING_FULL, master, 0, 0, -1, + effective_timeout_ms); return GES_REJECT_REASON_WORK_QUEUE_FULL; } } @@ -2379,6 +2541,9 @@ cluster_ges_send_convert_and_wait(const struct ClusterResId *resid, uint32 reque ConditionVariableCancelSleep(); cluster_xp_end(&xp_wait); /* PGRAC: spec-5.59 D2 profiling */ cluster_xp_end(&xp_convert); /* PGRAC: spec-5.59 D2 profiling */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_CV_WAIT_TIMEOUT, + local_master ? cluster_node_id : master, + (long)effective_timeout_ms, 0, -1, effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } remaining_ms = (long)((deadline - now) / 1000); diff --git a/src/backend/cluster/cluster_lock_acquire.c b/src/backend/cluster/cluster_lock_acquire.c index 280d15da80..450054f16c 100644 --- a/src/backend/cluster/cluster_lock_acquire.c +++ b/src/backend/cluster/cluster_lock_acquire.c @@ -264,6 +264,9 @@ cluster_lock_acquire_s3_partition_reservation(const ClusterLockAcquireRequest *r && !cluster_lms_native_probe_wait_clear(&req->resid, req->lockmode, &req->holder, /* timeout_ms */ 0)) { (void)cluster_grd_cancel_reservation_by_id(&req->resid, &req->holder); + /* S3 forensics step 1 — attribute the FAIL_TIMEOUT fold. */ + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_NATIVE_PROBE_TIMEOUT, self_node, 0, 0, + -1, 0); return CLUSTER_LOCK_ACQUIRE_FAIL_TIMEOUT; } pg_atomic_fetch_add_u64(&stub_local_fast_path_count, 1); @@ -677,6 +680,11 @@ cluster_lock_acquire_seven_step(const ClusterLockAcquireRequest *req) { ClusterLockAcquireResult r; + /* S3 forensics step 1 — clear the backend-local timeout-source detail at + * the single dispatch funnel so a FAIL_TIMEOUT surfaced by lock.c never + * reads a stale attribution from a previous acquire. */ + cluster_ges_timeout_detail_reset(); + /* * spec-2.22 D8 / spec-5.9 D3 — cancel check point (a): seven-step top * dispatch entry. cluster_cancel_token_consume() honors the cancel ONLY diff --git a/src/backend/cluster/cluster_tt_local.c b/src/backend/cluster/cluster_tt_local.c index c5c281ecb8..7ed206be30 100644 --- a/src/backend/cluster/cluster_tt_local.c +++ b/src/backend/cluster/cluster_tt_local.c @@ -46,6 +46,7 @@ #include "cluster/cluster_epoch.h" #include "cluster/cluster_guc.h" +#include "cluster/cluster_scn.h" /* S3 forensics — floor-lag vs current SCN in errdetail */ #include "cluster/cluster_shmem.h" #include "cluster/cluster_tt_durable.h" /* spec-3.11 D4 durable commit */ #include "cluster/cluster_tt_local.h" @@ -253,12 +254,19 @@ cluster_tt_local_get_or_create_binding(TransactionId top_xid, uint32 *out_segmen if (off == INVALID_TT_SLOT_OFFSET) { if (!retained_pressure) /* All 48 slots ACTIVE -- genuine in-flight concurrency limit. */ - ereport(ERROR, - (errcode(ERRCODE_PROGRAM_LIMIT_EXCEEDED), - errmsg("cluster TT slot allocator exhausted on segment %u (48 slots full)", - seg), - errhint("All concurrent xacts on this node hold ACTIVE slots; retry after " - "shorter transactions commit or abort."))); + ereport( + ERROR, + (errcode(ERRCODE_PROGRAM_LIMIT_EXCEEDED), + errmsg("cluster TT slot allocator exhausted on segment %u (48 slots full)", + seg), + errdetail("node=%d retention_horizon_scn=" UINT64_FORMAT + " current_scn=" UINT64_FORMAT " retain_skip=" UINT64_FORMAT + " retention_recycle=" UINT64_FORMAT ".", + cluster_node_id, cluster_tt_slot_retention_horizon_scn(), + (uint64)cluster_scn_current(), cluster_tt_slot_retain_skip_count(), + cluster_tt_slot_retention_recycle_count()), + errhint("All concurrent xacts on this node hold ACTIVE slots; retry after " + "shorter transactions commit or abort."))); /* * spec-3.12 D2b / C3b: retained COMMITTED slots (a long reader holds @@ -271,15 +279,36 @@ cluster_tt_local_get_or_create_binding(TransactionId top_xid, uint32 *out_segmen = cluster_undo_tt_rollover_locked(cluster_node_id, seg, &at_hard_cap); if (new_seg == 0) - ereport(ERROR, - (errcode(ERRCODE_PROGRAM_LIMIT_EXCEEDED), - errmsg("cluster TT slot allocator: retention rollover failed for " - "segment %u (%s)", - seg, - at_hard_cap ? "undo segment pool hard cap reached" - : "undo segment autoextend failed"), - errhint("A long-running reader is retaining committed undo; end it, " - "or raise cluster.undo_segments_max_per_instance."))); + /* S3 forensics step 1 — the errdetail separates "cleaner + * stopped reclaiming" (recycle counters flat, horizon far + * behind current_scn) from "pool genuinely at capacity + * under live retention" before anyone reaches for the GUC. */ + ereport( + ERROR, + (errcode(ERRCODE_PROGRAM_LIMIT_EXCEEDED), + errmsg("cluster TT slot allocator: retention rollover failed for " + "segment %u (%s)", + seg, + at_hard_cap ? "undo segment pool hard cap reached" + : "undo segment autoextend failed"), + errdetail( + "node=%d retention_horizon_scn=" UINT64_FORMAT + " current_scn=" UINT64_FORMAT " retain_skip=" UINT64_FORMAT + " retention_recycle=" UINT64_FORMAT + " retention_off_recycle=" UINT64_FORMAT " wrap_retired=" UINT64_FORMAT + " segment_reuse=" UINT64_FORMAT " segment_switch=" UINT64_FORMAT + " hard_cap_fail=" UINT64_FORMAT " segments_max_per_instance=%d.", + cluster_node_id, cluster_tt_slot_retention_horizon_scn(), + (uint64)cluster_scn_current(), cluster_tt_slot_retain_skip_count(), + cluster_tt_slot_retention_recycle_count(), + cluster_tt_slot_retention_off_recycle_count(), + cluster_tt_slot_wrap_retired_count(), + cluster_undo_segment_reuse_count(), + cluster_undo_segment_switch_count(), + cluster_undo_segment_hard_cap_fail_count(), + cluster_undo_segments_max_per_instance), + errhint("A long-running reader is retaining committed undo; end it, " + "or raise cluster.undo_segments_max_per_instance."))); seg = new_seg; off = cluster_tt_slot_alloc(seg, top_xid); diff --git a/src/backend/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c index 7c4900c53d..593367e604 100644 --- a/src/backend/storage/lmgr/lock.c +++ b/src/backend/storage/lmgr/lock.c @@ -1120,10 +1120,23 @@ LockAcquireExtended(const LOCKTAG *locktag, LOCKMODE lockmode, bool sessionLock, errmsg("cluster LMS not ready, fail-closed (spec-2.21 HC1)"), errhint("Wait for cluster_lms_is_ready() == LMS_READY before acquiring " "cluster-aware locks."))); - case CLUSTER_LOCK_ACQUIRE_FAIL_TIMEOUT: + case CLUSTER_LOCK_ACQUIRE_FAIL_TIMEOUT: { + /* PGRAC: S3 forensics step 1 — FAIL_TIMEOUT folds nine distinct + * GES-side failure sites (capacity, send-fail, retransmit budget, + * native probe, true CV wait) into this single message; surface + * the fine-grained attribution recorded at the failing site so a + * timeout storm is diagnosable without guessing. */ + const ClusterGesTimeoutDetail *ges_td = cluster_ges_timeout_detail_get(); + ereport(ERROR, (errcode(ERRCODE_LOCK_NOT_AVAILABLE), errmsg("cluster lock acquire timeout"), + errdetail("source=%s master=%d elapsed_ms=%ld attempts=%d " + "conflict_holders=%d effective_timeout_ms=%d.", + cluster_ges_timeout_src_text(ges_td->source), ges_td->master_node, + ges_td->elapsed_ms, ges_td->attempts, ges_td->conflict_holders, + ges_td->timeout_ms), errhint("Consider increasing cluster.ges_request_timeout_ms."))); + } case CLUSTER_LOCK_ACQUIRE_FAIL_SHARD_REMASTERING: /* PGRAC: spec-4.6 D4 — shard frozen by failure-driven remaster. */ ereport(ERROR, (errcode(ERRCODE_CLUSTER_GRD_SHARD_REMASTERING), diff --git a/src/include/cluster/cluster_ges.h b/src/include/cluster/cluster_ges.h index 2932d851c5..bb71a0270f 100644 --- a/src/include/cluster/cluster_ges.h +++ b/src/include/cluster/cluster_ges.h @@ -83,10 +83,66 @@ typedef struct ClusterGesSharedState { pg_atomic_uint64 request_defer_count; pg_atomic_uint64 reply_defer_count; + /* S3 forensics step 1 (07-14) — fine-grained breakdown of every + * GES-side failure that lock.c folds into the single "cluster lock + * acquire timeout" text. Proves how many "timeouts" never waited + * (capacity / send-fail classes) vs genuinely ran out the clock. */ + pg_atomic_uint64 timeout_true_wait_count; /* CV wait ran out the deadline */ + pg_atomic_uint64 timeout_capacity_count; /* reply-wait table / master wait queue full */ + pg_atomic_uint64 timeout_send_fail_count; /* outbound ring enqueue failed */ + pg_atomic_uint64 timeout_retransmit_exhausted_count; /* retransmit budget burned */ + pg_atomic_uint64 timeout_native_probe_count; /* native-lock probe fail-closed */ /* Future spec-2.14+ adds: GRD shard table, hash routing state, * grant table, convert queue, deadlock graph, etc. */ } ClusterGesSharedState; +/* + * S3 forensics step 1 (07-14) — backend-local detail of the LAST GES-side + * failure that will surface as CLUSTER_LOCK_ACQUIRE_FAIL_TIMEOUT. + * + * GesRejectReason folds nine distinct failure sites into TIMEOUT / + * WORK_QUEUE_FULL, and cluster_lock_acquire.c folds those (plus the + * native-probe and convert paths) into one FAIL_TIMEOUT whose lock.c + * ereport reads "cluster lock acquire timeout". The setter records the + * fine source (and bumps the matching shmem counter) at each site; the + * seven-step dispatcher resets it on entry; lock.c reads it into the + * 53R70-surface errdetail. Backend-local (set and read within one + * synchronous acquire), so no locking. + */ +typedef enum ClusterGesTimeoutSrc { + CLUSTER_GES_TSRC_NONE = 0, /* no GES detail recorded (unattributed) */ + CLUSTER_GES_TSRC_NULL_ARG, /* internal: NULL resid/holder */ + CLUSTER_GES_TSRC_REPLY_WAIT_TABLE_FULL, /* capacity: reply-wait table full */ + CLUSTER_GES_TSRC_MASTER_WAIT_QUEUE_FULL, /* capacity: GRD wait queue / not-ready */ + CLUSTER_GES_TSRC_OUTBOUND_RING_FULL, /* send-fail: outbound ring enqueue failed */ + CLUSTER_GES_TSRC_CV_WAIT_TIMEOUT, /* true wait: CV sleep ran out the deadline */ + CLUSTER_GES_TSRC_RETRANSMIT_EXHAUSTED, /* retransmit budget burned before grant */ + CLUSTER_GES_TSRC_NATIVE_PROBE_TIMEOUT, /* native-lock probe could not prove clear */ +} ClusterGesTimeoutSrc; + +typedef struct ClusterGesTimeoutDetail { + ClusterGesTimeoutSrc source; + int32 master_node; /* target master (self for local-master path); -1 unknown */ + long elapsed_ms; /* wall time actually waited (0 = immediate failure) */ + int attempts; /* retransmit attempts consumed (0 = none) */ + int conflict_holders; /* conflicting holders seen at enqueue; -1 unknown */ + int timeout_ms; /* effective timeout in force (-1 = perpetual) */ +} ClusterGesTimeoutDetail; + +extern void cluster_ges_timeout_detail_set(ClusterGesTimeoutSrc src, int32 master_node, + long elapsed_ms, int attempts, int conflict_holders, + int timeout_ms); +extern void cluster_ges_timeout_detail_reset(void); +extern const ClusterGesTimeoutDetail *cluster_ges_timeout_detail_get(void); +extern const char *cluster_ges_timeout_src_text(ClusterGesTimeoutSrc src); + +/* dump_ges observability getters for the five breakdown counters. */ +extern uint64 cluster_ges_timeout_true_wait_count(void); +extern uint64 cluster_ges_timeout_capacity_count(void); +extern uint64 cluster_ges_timeout_send_fail_count(void); +extern uint64 cluster_ges_timeout_retransmit_exhausted_count(void); +extern uint64 cluster_ges_timeout_native_probe_count(void); + /* * Shmem region lifecycle (mirror cluster_scn / cluster_lmon pattern). * diff --git a/src/test/cluster_tap/t/286_ul_advisory.pl b/src/test/cluster_tap/t/286_ul_advisory.pl index 6ae535bbd0..68000f4278 100644 --- a/src/test/cluster_tap/t/286_ul_advisory.pl +++ b/src/test/cluster_tap/t/286_ul_advisory.pl @@ -357,6 +357,25 @@ sub blocking_grant_after_release isnt($rc11, 0, 'L11: blocking advisory acquire on a held key fails (does not hang)'); like($err11, qr/cluster lock acquire timeout|53R70|not available/i, 'L11: ... with a finite-timeout 53R70 (bounded deadlock resolution)'); + +# S3 forensics step 1 — the folded 53R70 text must carry a fine-grained +# source attribution (errdetail) and bump the matching dump_ges breakdown +# counter on the timing-out node. A genuine bounded wait resolves as either +# the CV deadline or the retransmit budget depending on which node masters +# the key (local- vs remote-master wait loop). +like( + $err11, + qr/source=(cv-wait-timeout|retransmit-exhausted)/, + 'L11b: 53R70 errdetail carries the timeout-source attribution'); +my $to_split_sum = $n1->safe_psql( + 'postgres', q{ + SELECT COALESCE(sum(value::bigint), 0) FROM pg_cluster_state + WHERE category = 'ges' + AND key IN ('ges_timeout_true_wait_count', + 'ges_timeout_retransmit_exhausted_count')}); +cmp_ok($to_split_sum, '>=', 1, + 'L11c: dump_ges timeout-source breakdown counter bumped by the bounded wait'); + $h11->query_safe("SELECT pg_advisory_unlock(73)"); $h11->quit; diff --git a/src/test/cluster_unit/test_cluster_debug.c b/src/test/cluster_unit/test_cluster_debug.c index 14fe72bb65..531c7b2738 100644 --- a/src/test/cluster_unit/test_cluster_debug.c +++ b/src/test/cluster_unit/test_cluster_debug.c @@ -3645,6 +3645,38 @@ cluster_ges_reply_defer_count(void) return 0; } +/* S3 forensics step 1 / L104 stubs: dump_ges timeout-source breakdown + * counters (cluster_ges.o not linked standalone). */ +uint64 +cluster_ges_timeout_true_wait_count(void) +{ + return 0; +} + +uint64 +cluster_ges_timeout_capacity_count(void) +{ + return 0; +} + +uint64 +cluster_ges_timeout_send_fail_count(void) +{ + return 0; +} + +uint64 +cluster_ges_timeout_retransmit_exhausted_count(void) +{ + return 0; +} + +uint64 +cluster_ges_timeout_native_probe_count(void) +{ + return 0; +} + /* spec-2.14 D12 / L104 stubs: cluster_debug dump_grd references 7 new * spec-2.14 cluster_grd module accessors; test_cluster_debug standalone * binary doesn't link cluster_grd.o, vacuous stubs. */ diff --git a/src/test/cluster_unit/test_cluster_lock_acquire.c b/src/test/cluster_unit/test_cluster_lock_acquire.c index a5ca5a719c..d0b9b3904f 100644 --- a/src/test/cluster_unit/test_cluster_lock_acquire.c +++ b/src/test/cluster_unit/test_cluster_lock_acquire.c @@ -216,6 +216,21 @@ bool cluster_advisory_lock_enabled = true; * the existing HC23/HC24/HC27 behaviour for all other tests. */ bool cluster_shared_catalog = false; +/* S3 forensics step 1 stubs — the timeout-source detail setter/reset live in + * cluster_ges.o (not linked standalone); the seven-step reset and the S3 + * native-probe set-point are inert no-ops here. */ +void +cluster_ges_timeout_detail_set(ClusterGesTimeoutSrc src pg_attribute_unused(), + int32 master_node pg_attribute_unused(), + long elapsed_ms pg_attribute_unused(), + int attempts pg_attribute_unused(), + int conflict_holders pg_attribute_unused(), + int timeout_ms pg_attribute_unused()) +{} +void +cluster_ges_timeout_detail_reset(void) +{} + /* spec-5.5 D8 — UL counter stubs: cluster_lock_release() bumps the session- * release counter, but this fixture links neither the advisory shmem region nor * cluster_advisory.o. The real counter behaviour is covered by From 05dd3b0c40e7d5356e579e2603513947b31602bc Mon Sep 17 00:00:00 2001 From: SqlRush Date: Tue, 14 Jul 2026 09:54:52 +0800 Subject: [PATCH 3/5] feat(cluster): S3 forensics step 1a -- watermark provenance, master-reject attribution, true elapsed, TT rollover split Review follow-up on the step-1 instrumentation; observability-only, no protocol / wire / on-disk change. Watermark provenance (the branch-3 discriminator): - Every SCN-watermark feed (redeclare / take-x / grant-x / both invalidate-ACK feeds) records {source, sender, request_id, epoch, old->new, advanced} into a shmem ring (seq-guarded against torn wrap-around reads); the 53R93 emit sites on the master attach the latest record (wm_src=...), so a shipped 181) driving the new t/286 L14 semantic leg: source text asserted, elapsed_ms below the window (the reject never waited), capacity counter delta. True elapsed: - All timeout-detail sites report wall-clock from a send-entry stamp instead of the configured timeout; t/286 L11b2 asserts >= 1s on a genuine 3s bounded wait, L14d asserts the immediate reject stayed under the window. TT rollover split: - tt_rollover_fail_hard_cap/_extend count ONLY the TT rollover path (the previously cited segment_hard_cap_fail_count belongs to the record-extent CLAIM path -- now labeled record_extent_hard_cap_fail); the errdetail adds cleaner status / loop iters / liveness-tick age to separate a stalled cleaner from genuine capacity pressure. Two new dump_undo rows (t/214 68 -> 70). Tests: new UT test_pcm_wm_prov_ring_records_advance (a stale feed is recorded with advanced=false and never regresses the max); t/286 L11 asserts are delta-based; t/116 L11b asserts the requester errdetail and producer-LOG forensic fields. Unit fixtures serving ClusterPcmShared grew their fake shmem block (4096 -> 32768) for the ring. Baselines: t/015 t/017 t/030 inject 181; t/214 undo rows 70. Local gates: cluster_unit 177 (clean), cluster_regress 13, PG regress 219/219, TAP 015/017/030/108/110/116/214/280/285/286, check-format 0. --- src/backend/cluster/cluster_debug.c | 5 + src/backend/cluster/cluster_gcs_block.c | 166 +++++++++++----- src/backend/cluster/cluster_ges.c | 120 ++++++++--- src/backend/cluster/cluster_inject.c | 11 ++ src/backend/cluster/cluster_pcm_lock.c | 187 ++++++++++++++++-- src/backend/cluster/cluster_tt_local.c | 33 +++- src/backend/cluster/cluster_undo_record.c | 33 ++++ src/include/cluster/cluster_ges.h | 20 +- src/include/cluster/cluster_pcm_lock.h | 39 +++- src/include/cluster/cluster_undo_record_api.h | 5 + src/test/cluster_tap/t/015_inject.pl | 6 +- src/test/cluster_tap/t/017_debug.pl | 8 +- src/test/cluster_tap/t/030_acceptance.pl | 6 +- .../t/116_gcs_block_lost_write_2node.pl | 48 ++++- .../t/214_cluster_3_8_undo_lifecycle.pl | 4 +- src/test/cluster_tap/t/286_ul_advisory.pl | 99 ++++++++-- .../test_cluster_bufmgr_pcm_hook.c | 4 +- src/test/cluster_unit/test_cluster_debug.c | 12 ++ src/test/cluster_unit/test_cluster_pcm_lock.c | 60 +++++- 19 files changed, 726 insertions(+), 140 deletions(-) diff --git a/src/backend/cluster/cluster_debug.c b/src/backend/cluster/cluster_debug.c index cd80df5b3e..5636764ba6 100644 --- a/src/backend/cluster/cluster_debug.c +++ b/src/backend/cluster/cluster_debug.c @@ -2807,6 +2807,11 @@ dump_undo(ReturnSetInfo *rsinfo) fmt_int64((int64)cluster_tt_slot_retention_off_recycle_count())); emit_row(rsinfo, "undo", "tt_retention_rollover_count", fmt_int64((int64)cluster_undo_tt_retention_rollover_count())); + /* S3 forensics step 1a — TT-rollover failure split (writer 53R9E family). */ + emit_row(rsinfo, "undo", "tt_rollover_fail_hard_cap_count", + fmt_int64((int64)cluster_undo_tt_rollover_fail_hard_cap_count())); + emit_row(rsinfo, "undo", "tt_rollover_fail_extend_count", + fmt_int64((int64)cluster_undo_tt_rollover_fail_extend_count())); /* spec-6.2: Smart Fusion terminal-authority substrate counters. */ emit_row(rsinfo, "undo", "terminal_authority_check_count", diff --git a/src/backend/cluster/cluster_gcs_block.c b/src/backend/cluster/cluster_gcs_block.c index d0b9f2eaf6..8d920795cb 100644 --- a/src/backend/cluster/cluster_gcs_block.c +++ b/src/backend/cluster/cluster_gcs_block.c @@ -1303,31 +1303,54 @@ cluster_gcs_block_fallback_verify_refresh(BufferDesc *buf, BufferTag tag, SCN ex * local copy refused refresh" (page_scn is then the pre-refresh local * read). */ pg_atomic_fetch_add_u64(&ClusterGcsBlock->fallback_scn_failclosed_count, 1); - if (cluster_gcs_block_lost_write_action == 0 /* ERROR */) + { + /* Step 1a — best-effort local provenance view: authoritative when this + * node masters the tag; otherwise the master's LOG line rules. */ + ClusterPcmWmProv wm_prov; + bool wm_have = cluster_pcm_lock_pi_watermark_prov_query(tag, &wm_prov); + + if (cluster_gcs_block_lost_write_action == 0 /* ERROR */) + ereport( + ERROR, + (errcode(ERRCODE_CLUSTER_LOST_WRITE_DETECTED), + errmsg("cluster_gcs_block: stale storage-fallback copy detected on tag " + "spc=%u db=%u rel=%u block=%u", + tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum), + errdetail( + "expected pi_watermark_scn=" UINT64_FORMAT " %s pd_block_scn=" UINT64_FORMAT + " local pi_watermark_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT + " wm_src=%s wm_sender=%d wm_request_id=" UINT64_FORMAT + " wm_epoch=" UINT64_FORMAT " wm_old=" UINT64_FORMAT " wm_new=" UINT64_FORMAT + " wm_advanced=%d.", + (uint64)expected_scn, refreshed ? "storage" : "local(dirty-refused)", + (uint64)page_scn, (uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), + cluster_pcm_own_gen_get(buf->buf_id), + cluster_pcm_wm_src_text(wm_have ? wm_prov.source : CLUSTER_PCM_WM_SRC_NONE), + wm_have ? wm_prov.sender_node : -1, wm_have ? wm_prov.request_id : 0, + wm_have ? wm_prov.epoch : 0, wm_have ? (uint64)wm_prov.old_scn : 0, + wm_have ? (uint64)wm_prov.new_scn : 0, wm_have ? (int)wm_prov.advanced : -1), + errhint("The local/storage page pd_block_scn is below the master " + "pi_watermark_scn carried by the GRANTED_STORAGE_FALLBACK " + "reply. Inspect dump_gcs.fallback_scn_failclosed_count. " + "Retry is safe (the next attempt renegotiates)."))); ereport( - ERROR, - (errcode(ERRCODE_CLUSTER_LOST_WRITE_DETECTED), - errmsg("cluster_gcs_block: stale storage-fallback copy detected on tag " - "spc=%u db=%u rel=%u block=%u", - tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum), - errdetail("expected pi_watermark_scn=" UINT64_FORMAT " %s pd_block_scn=" UINT64_FORMAT - " local pi_watermark_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT ".", - (uint64)expected_scn, refreshed ? "storage" : "local(dirty-refused)", - (uint64)page_scn, (uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), - cluster_pcm_own_gen_get(buf->buf_id)), - errhint("The local/storage page pd_block_scn is below the master " - "pi_watermark_scn carried by the GRANTED_STORAGE_FALLBACK " - "reply. Inspect dump_gcs.fallback_scn_failclosed_count. " - "Retry is safe (the next attempt renegotiates)."))); - ereport(WARNING, + WARNING, (errmsg("cluster_gcs_block: stale storage-fallback copy on tag " "spc=%u db=%u rel=%u block=%u (action=warn)", tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum), - errdetail("expected pi_watermark_scn=" UINT64_FORMAT " %s pd_block_scn=" UINT64_FORMAT - " local pi_watermark_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT ".", - (uint64)expected_scn, refreshed ? "storage" : "local(dirty-refused)", - (uint64)page_scn, (uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), - cluster_pcm_own_gen_get(buf->buf_id)))); + errdetail( + "expected pi_watermark_scn=" UINT64_FORMAT " %s pd_block_scn=" UINT64_FORMAT + " local pi_watermark_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT + " wm_src=%s wm_sender=%d wm_request_id=" UINT64_FORMAT " wm_epoch=" UINT64_FORMAT + " wm_old=" UINT64_FORMAT " wm_new=" UINT64_FORMAT " wm_advanced=%d.", + (uint64)expected_scn, refreshed ? "storage" : "local(dirty-refused)", + (uint64)page_scn, (uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), + cluster_pcm_own_gen_get(buf->buf_id), + cluster_pcm_wm_src_text(wm_have ? wm_prov.source : CLUSTER_PCM_WM_SRC_NONE), + wm_have ? wm_prov.sender_node : -1, wm_have ? wm_prov.request_id : 0, + wm_have ? wm_prov.epoch : 0, wm_have ? (uint64)wm_prov.old_scn : 0, + wm_have ? (uint64)wm_prov.new_scn : 0, wm_have ? (int)wm_prov.advanced : -1))); + } } @@ -3646,6 +3669,10 @@ cluster_gcs_local_master_x_transfer_and_wait(BufferDesc *buf, int32 holder_node, SCN forens_master_wm_now = cluster_pcm_lock_pi_watermark_scn_query(tag); SCN forens_local_scn = cluster_bufmgr_read_block_scn_for_gcs(buf); uint64 forens_own_gen = cluster_pcm_own_gen_get(buf->buf_id); + /* Step 1a — this node is the master: the provenance of the advance + * that produced the expected watermark is authoritative here. */ + ClusterPcmWmProv wm_prov; + bool wm_have = cluster_pcm_lock_pi_watermark_prov_query(tag, &wm_prov); if (cluster_gcs_block_lost_write_action == 0 /* ERROR */) ereport( @@ -3655,29 +3682,45 @@ cluster_gcs_local_master_x_transfer_and_wait(BufferDesc *buf, int32 holder_node, "spc=%u db=%u relNumber=%u block=%u", tag.spcOid, tag.dbOid, (unsigned int)BufTagGetRelNumber(&tag), (unsigned int)tag.blockNum), - errdetail("request_id=" UINT64_FORMAT " epoch=" UINT64_FORMAT " holder=%d" - " expected pi_watermark_scn sent=" UINT64_FORMAT - " master pi_watermark_scn now=" UINT64_FORMAT - " local pd_block_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT ".", - request_id, fwd.epoch, holder_node, (uint64)forens_expected_sent, - (uint64)forens_master_wm_now, (uint64)forens_local_scn, forens_own_gen), + errdetail( + "request_id=" UINT64_FORMAT " epoch=" UINT64_FORMAT " holder=%d" + " expected pi_watermark_scn sent=" UINT64_FORMAT + " master pi_watermark_scn now=" UINT64_FORMAT + " local pd_block_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT + " wm_src=%s wm_sender=%d wm_request_id=" UINT64_FORMAT + " wm_epoch=" UINT64_FORMAT " wm_old=" UINT64_FORMAT " wm_new=" UINT64_FORMAT + " wm_advanced=%d.", + request_id, fwd.epoch, holder_node, (uint64)forens_expected_sent, + (uint64)forens_master_wm_now, (uint64)forens_local_scn, forens_own_gen, + cluster_pcm_wm_src_text(wm_have ? wm_prov.source : CLUSTER_PCM_WM_SRC_NONE), + wm_have ? wm_prov.sender_node : -1, wm_have ? wm_prov.request_id : 0, + wm_have ? wm_prov.epoch : 0, wm_have ? (uint64)wm_prov.old_scn : 0, + wm_have ? (uint64)wm_prov.new_scn : 0, wm_have ? (int)wm_prov.advanced : -1), errhint("The holder-forward shipped block.pd_block_scn is below the " "master pi_watermark_scn (or a tracked block shipped an " "unstamped page). Inspect dump_gcs.lost_write_detected_count " "and cluster_pcm_grd to find the stale source. spec-2.41 D5."))); else - ereport(WARNING, (errmsg("cluster_gcs_block: lost write detected on tag " - "spc=%u db=%u relNumber=%u block=%u (action=warn)", - tag.spcOid, tag.dbOid, (unsigned int)BufTagGetRelNumber(&tag), - (unsigned int)tag.blockNum), - errdetail("request_id=" UINT64_FORMAT " epoch=" UINT64_FORMAT - " holder=%d expected pi_watermark_scn sent=" UINT64_FORMAT - " master pi_watermark_scn now=" UINT64_FORMAT - " local pd_block_scn=" UINT64_FORMAT - " ownership_gen=" UINT64_FORMAT ".", - request_id, fwd.epoch, holder_node, - (uint64)forens_expected_sent, (uint64)forens_master_wm_now, - (uint64)forens_local_scn, forens_own_gen))); + ereport( + WARNING, + (errmsg("cluster_gcs_block: lost write detected on tag " + "spc=%u db=%u relNumber=%u block=%u (action=warn)", + tag.spcOid, tag.dbOid, (unsigned int)BufTagGetRelNumber(&tag), + (unsigned int)tag.blockNum), + errdetail( + "request_id=" UINT64_FORMAT " epoch=" UINT64_FORMAT + " holder=%d expected pi_watermark_scn sent=" UINT64_FORMAT + " master pi_watermark_scn now=" UINT64_FORMAT + " local pd_block_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT + " wm_src=%s wm_sender=%d wm_request_id=" UINT64_FORMAT + " wm_epoch=" UINT64_FORMAT " wm_old=" UINT64_FORMAT " wm_new=" UINT64_FORMAT + " wm_advanced=%d.", + request_id, fwd.epoch, holder_node, (uint64)forens_expected_sent, + (uint64)forens_master_wm_now, (uint64)forens_local_scn, forens_own_gen, + cluster_pcm_wm_src_text(wm_have ? wm_prov.source : CLUSTER_PCM_WM_SRC_NONE), + wm_have ? wm_prov.sender_node : -1, wm_have ? wm_prov.request_id : 0, + wm_have ? wm_prov.epoch : 0, wm_have ? (uint64)wm_prov.old_scn : 0, + wm_have ? (uint64)wm_prov.new_scn : 0, wm_have ? (int)wm_prov.advanced : -1))); } /* @@ -5382,17 +5425,32 @@ cluster_gcs_handle_block_request_envelope(const ClusterICEnvelope *env, const vo } else if (verdict == GCS_LOST_WRITE_FAIL_STALE || verdict == GCS_LOST_WRITE_FAIL_ANOMALY) { /* S3 forensics step 1 — the (expected, shipped) verdict SCN pair is * only known on this producer; LOG it so the requester's 53R93 - * errdetail correlates by (tag, request_id) for the three-branch - * lost-write qualification. */ - ereport(LOG, (errmsg_internal( - "cluster_gcs_block: lost-write verdict %s on master-direct ship: tag " - "spc=%u db=%u rel=%u block=%u expected pi_watermark_scn=" UINT64_FORMAT - " shipped pd_block_scn=" UINT64_FORMAT - " requester=%d request_id=" UINT64_FORMAT " transition=%d", - verdict == GCS_LOST_WRITE_FAIL_STALE ? "STALE" : "ANOMALY", - req->tag.spcOid, req->tag.dbOid, req->tag.relNumber, req->tag.blockNum, - (uint64)expected_scn, (uint64)shipped_scn, req->sender_node, - req->request_id, (int)req->transition_id))); + * errdetail correlates by the unambiguous {requester, request_id, + * epoch, tag} 4-tuple. Step 1a: THIS node is the master, so the + * provenance of the LAST advance that produced expected_scn is + * queryable here — the branch-3 (watermark false-positive) + * discriminator. */ + ClusterPcmWmProv wm_prov; + bool wm_have = cluster_pcm_lock_pi_watermark_prov_query(req->tag, &wm_prov); + + ereport( + LOG, + (errmsg_internal( + "cluster_gcs_block: lost-write verdict %s on master-direct ship: tag " + "spc=%u db=%u rel=%u block=%u expected pi_watermark_scn=" UINT64_FORMAT + " shipped pd_block_scn=" UINT64_FORMAT " requester=%d request_id=" UINT64_FORMAT + " epoch=" UINT64_FORMAT + " transition=%d wm_src=%s wm_sender=%d wm_request_id=" UINT64_FORMAT + " wm_epoch=" UINT64_FORMAT " wm_old=" UINT64_FORMAT " wm_new=" UINT64_FORMAT + " wm_advanced=%d", + verdict == GCS_LOST_WRITE_FAIL_STALE ? "STALE" : "ANOMALY", req->tag.spcOid, + req->tag.dbOid, req->tag.relNumber, req->tag.blockNum, (uint64)expected_scn, + (uint64)shipped_scn, req->sender_node, req->request_id, + cluster_epoch_get_current(), (int)req->transition_id, + cluster_pcm_wm_src_text(wm_have ? wm_prov.source : CLUSTER_PCM_WM_SRC_NONE), + wm_have ? wm_prov.sender_node : -1, wm_have ? wm_prov.request_id : 0, + wm_have ? wm_prov.epoch : 0, wm_have ? (uint64)wm_prov.old_scn : 0, + wm_have ? (uint64)wm_prov.new_scn : 0, wm_have ? (int)wm_prov.advanced : -1))); status = GCS_BLOCK_REPLY_DENIED_LOST_WRITE; page_lsn = InvalidXLogRecPtr; gcs_block_release_ship_image(block_payload_release_cb, block_payload_release_arg); @@ -8077,7 +8135,9 @@ cluster_gcs_handle_block_invalidate_ack_envelope(const ClusterICEnvelope *env, c SCN pre_scn = GcsBlockInvalidateAckPayloadGetPageScn(ack); if (SCN_VALID(pre_scn)) { - cluster_pcm_lock_pi_watermark_scn_advance(ack->tag, pre_scn); + cluster_pcm_lock_pi_watermark_scn_advance( + ack->tag, pre_scn, CLUSTER_PCM_WM_SRC_ACK_SLOTLESS, ack->sender_node, + ack->request_id, ack->epoch); pg_atomic_fetch_add_u64(&ClusterGcsBlock->pi_watermark_advance_count, 1); } } @@ -8136,7 +8196,9 @@ cluster_gcs_handle_block_invalidate_ack_envelope(const ClusterICEnvelope *env, c * advance the detector's SCN watermark. The redo-coverage LSN * watermark is NOT fed from the ACK: recovery rebuilds it from the * REDECLARE wire (§2.8.2; the F-ACK test at D9 proves this is safe). */ - cluster_pcm_lock_pi_watermark_scn_advance(ack_tag, ack_page_scn); + cluster_pcm_lock_pi_watermark_scn_advance(ack_tag, ack_page_scn, + CLUSTER_PCM_WM_SRC_ACK_SLOT, ack->sender_node, + ack->request_id, ack->epoch); pg_atomic_fetch_add_u64(&ClusterGcsBlock->pi_watermark_advance_count, 1); } ConditionVariableBroadcast(&ClusterGcsBlock->invalidate_broadcast_cv); diff --git a/src/backend/cluster/cluster_ges.c b/src/backend/cluster/cluster_ges.c index 26f7da7b9c..853df9616a 100644 --- a/src/backend/cluster/cluster_ges.c +++ b/src/backend/cluster/cluster_ges.c @@ -40,6 +40,7 @@ #include "cluster/cluster_ges_reply_wait.h" /* spec-2.23 D1 5-tuple wait HTAB */ #include "cluster/cluster_grd.h" #include "cluster/cluster_grd_outbound.h" +#include "cluster/cluster_inject.h" /* S3 forensics — master work-queue-full RED */ #include "cluster/cluster_lmd.h" /* cluster_lmd_is_ready */ #include "cluster/cluster_lmd_probe_collector.h" /* spec-5.8 D8 — shmem REPORT collect_receive */ #include "cluster/cluster_cancel_token.h" /* spec-5.9 D3 cluster_cancel_token_consume */ @@ -764,8 +765,12 @@ cluster_ges_request_handler(const ClusterICEnvelope *env, const void *payload) /* Phase 1 (handler): enqueue into work_queue. Grant decision runs * Phase 2 in LMON tick body (Step 4 D9 wires). work_queue full → - * REJECT_BUSY reply via reserved pool (I46 nofail). */ - if (!cluster_grd_work_queue_enqueue(env->source_node_id, payload, sizeof(*req))) { + * REJECT_BUSY reply via reserved pool (I46 nofail). + * S3 forensics step 1a inject — SKIP forces the full-queue reject so the + * requester-side reply-tail attribution RED is deterministic. */ + CLUSTER_INJECTION_POINT("cluster-ges-master-work-queue-full"); + if (cluster_injection_should_skip("cluster-ges-master-work-queue-full") + || !cluster_grd_work_queue_enqueue(env->source_node_id, payload, sizeof(*req))) { GesReplyPayload reject; cluster_grd_inc_ges_work_queue_full(); @@ -1475,6 +1480,7 @@ cluster_ges_timeout_detail_set(ClusterGesTimeoutSrc src, int32 master_node, long break; case CLUSTER_GES_TSRC_REPLY_WAIT_TABLE_FULL: case CLUSTER_GES_TSRC_MASTER_WAIT_QUEUE_FULL: + case CLUSTER_GES_TSRC_MASTER_REJECT_QUEUE_FULL: pg_atomic_fetch_add_u64(&cluster_ges_state->timeout_capacity_count, 1); break; case CLUSTER_GES_TSRC_OUTBOUND_RING_FULL: @@ -1486,6 +1492,10 @@ cluster_ges_timeout_detail_set(ClusterGesTimeoutSrc src, int32 master_node, long case CLUSTER_GES_TSRC_NATIVE_PROBE_TIMEOUT: pg_atomic_fetch_add_u64(&cluster_ges_state->timeout_native_probe_count, 1); break; + case CLUSTER_GES_TSRC_MASTER_REJECT_TIMEOUT: + /* master-reported timeout: neither a local wait nor a local capacity + * event — visible via the errdetail source text only. */ + break; case CLUSTER_GES_TSRC_NONE: case CLUSTER_GES_TSRC_NULL_ARG: break; @@ -1506,6 +1516,15 @@ cluster_ges_timeout_detail_get(void) return &ges_timeout_detail; } +/* True wall-clock spent in the current send-and-wait (NOT the configured + * timeout): capacity/send failures report the ~0ms they really took, so the + * "surfaced as timeout but never waited" class is provable per incident. */ +static inline long +ges_forens_elapsed_ms(TimestampTz start) +{ + return (long)((GetCurrentTimestamp() - start) / 1000); +} + const char * cluster_ges_timeout_src_text(ClusterGesTimeoutSrc src) { @@ -1526,6 +1545,10 @@ cluster_ges_timeout_src_text(ClusterGesTimeoutSrc src) return "retransmit-exhausted"; case CLUSTER_GES_TSRC_NATIVE_PROBE_TIMEOUT: return "native-probe-timeout"; + case CLUSTER_GES_TSRC_MASTER_REJECT_QUEUE_FULL: + return "master-reject-queue-full"; + case CLUSTER_GES_TSRC_MASTER_REJECT_TIMEOUT: + return "master-reject-timeout"; } return "unknown"; } @@ -1675,13 +1698,16 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo uint32 wait_ev = (wait_event != 0) ? wait_event : WAIT_EVENT_CLUSTER_GES_REPLY_WAIT; ClusterXpScope xp_enqueue; /* PGRAC: spec-5.59 D2 profiling */ ClusterXpScope xp_wait; /* PGRAC: spec-5.59 D2 profiling */ + /* S3 forensics step 1a — wall-clock base for the timeout-source detail. */ + TimestampTz forens_start = GetCurrentTimestamp(); /* PGRAC: spec-5.59 D2 profiling — whole-body REQUEST send -> grant/reject */ cluster_xp_begin(&xp_enqueue, CLXP_W_GES_ENQUEUE); if (resid == NULL || holder == NULL) { cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ - cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_NULL_ARG, -1, 0, 0, -1, timeout_ms); + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_NULL_ARG, -1, + ges_forens_elapsed_ms(forens_start), 0, -1, timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -1757,7 +1783,8 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo /* WAIT_QUEUE_FULL / NOT_READY / ILLEGAL — fail closed, never grant. */ cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_MASTER_WAIT_QUEUE_FULL, cluster_node_id, - 0, 0, n_conflict, timeout_ms); + ges_forens_elapsed_ms(forens_start), 0, n_conflict, + timeout_ms); return GES_REJECT_REASON_WORK_QUEUE_FULL; } @@ -1789,7 +1816,8 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo (void)cluster_grd_cancel_waiter_by_id(resid, holder); cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_REPLY_WAIT_TABLE_FULL, cluster_node_id, - 0, 0, n_conflict, perpetual ? -1 : effective_timeout_ms); + ges_forens_elapsed_ms(forens_start), 0, n_conflict, + perpetual ? -1 : effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; /* fail closed */ } @@ -1874,7 +1902,7 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo if (cluster_grd_cancel_waiter_by_id(resid, holder) == CLUSTER_GRD_ENTRY_OK) { /* timed_out only sets in finite mode: effective_timeout_ms valid. */ cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_CV_WAIT_TIMEOUT, cluster_node_id, - (long)effective_timeout_ms, 0, n_conflict, + ges_forens_elapsed_ms(forens_start), 0, n_conflict, effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; /* fail closed */ } @@ -1885,7 +1913,17 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo cluster_ges_reply_wait_delete(&key); /* GRANT (reject_reason == NONE) -> holder registered by the drain; S5 * verify-only. A non-NONE reject means the drain consumed the waiter - * with a rejection — fail closed with that reason. */ + * with a rejection — fail closed with that reason. + * S3 forensics step 1a — a drain-REPLIED rejection that lock.c folds + * into "cluster lock acquire timeout" must not surface unattributed. */ + if (reject_reason == GES_REJECT_REASON_WORK_QUEUE_FULL) + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_MASTER_REJECT_QUEUE_FULL, + cluster_node_id, ges_forens_elapsed_ms(forens_start), 0, + n_conflict, perpetual ? -1 : effective_timeout_ms); + else if (reject_reason == GES_REJECT_REASON_TIMEOUT) + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_MASTER_REJECT_TIMEOUT, cluster_node_id, + ges_forens_elapsed_ms(forens_start), 0, n_conflict, + perpetual ? -1 : effective_timeout_ms); cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ return reject_reason; } @@ -1933,7 +1971,8 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo "(request_id=" UINT64_FORMAT " dest=%d) — fail closed", request_id, master))); cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ - cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_REPLY_WAIT_TABLE_FULL, master, 0, 0, -1, + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_REPLY_WAIT_TABLE_FULL, master, + ges_forens_elapsed_ms(forens_start), 0, -1, effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -1962,7 +2001,8 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo /* Outbound ring full — fail closed. Caller may retry. */ cluster_ges_reply_wait_delete(&key); cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ - cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_OUTBOUND_RING_FULL, master, 0, 0, -1, + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_OUTBOUND_RING_FULL, master, + ges_forens_elapsed_ms(forens_start), 0, -1, effective_timeout_ms); return GES_REJECT_REASON_WORK_QUEUE_FULL; } @@ -2046,7 +2086,7 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo cluster_xp_end(&xp_wait); /* PGRAC: spec-5.59 D2 profiling */ cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_CV_WAIT_TIMEOUT, master, - (long)effective_timeout_ms, attempt, -1, + ges_forens_elapsed_ms(forens_start), attempt, -1, effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -2073,15 +2113,13 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo } if (!perpetual && max_attempts > 0 && attempt > max_attempts) { - long forens_elapsed_ms - = (long)effective_timeout_ms - (long)((deadline - GetCurrentTimestamp()) / 1000); - ges_abandon_wait_or_release(&key, &req, master, send_opcode); ConditionVariableCancelSleep(); cluster_xp_end(&xp_wait); /* PGRAC: spec-5.59 D2 profiling */ cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_RETRANSMIT_EXHAUSTED, master, - forens_elapsed_ms, attempt, -1, effective_timeout_ms); + ges_forens_elapsed_ms(forens_start), attempt, -1, + effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -2118,8 +2156,9 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo ConditionVariableCancelSleep(); cluster_xp_end(&xp_wait); /* PGRAC: spec-5.59 D2 profiling */ cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ - cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_OUTBOUND_RING_FULL, master, 0, attempt, - -1, effective_timeout_ms); + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_OUTBOUND_RING_FULL, master, + ges_forens_elapsed_ms(forens_start), attempt, -1, + effective_timeout_ms); return GES_REJECT_REASON_WORK_QUEUE_FULL; } if (cluster_ges_state != NULL) @@ -2136,6 +2175,19 @@ ges_send_request_opcode_and_wait(const struct ClusterResId *resid, uint32 lockmo reject_reason = entry->reject_reason; cluster_ges_reply_wait_delete(&key); + /* S3 forensics step 1a — the REMOTE master's replied rejection (dedup + * table / work queue / wait queue full) folds into lock.c's "cluster + * lock acquire timeout"; attribute it here so the dominant S3 error is + * never counted as an unattributed local wait. */ + if (reject_reason == GES_REJECT_REASON_WORK_QUEUE_FULL) + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_MASTER_REJECT_QUEUE_FULL, master, + ges_forens_elapsed_ms(forens_start), attempt, -1, + effective_timeout_ms); + else if (reject_reason == GES_REJECT_REASON_TIMEOUT) + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_MASTER_REJECT_TIMEOUT, master, + ges_forens_elapsed_ms(forens_start), attempt, -1, + effective_timeout_ms); + cluster_xp_end(&xp_enqueue); /* PGRAC: spec-5.59 D2 profiling */ return reject_reason; } @@ -2409,13 +2461,16 @@ cluster_ges_send_convert_and_wait(const struct ClusterResId *resid, uint32 reque bool local_master; ClusterXpScope xp_convert; /* PGRAC: spec-5.59 D2 profiling */ ClusterXpScope xp_wait; /* PGRAC: spec-5.59 D2 profiling */ + /* S3 forensics step 1a — wall-clock base for the timeout-source detail. */ + TimestampTz forens_start = GetCurrentTimestamp(); /* PGRAC: spec-5.59 D2 profiling — whole-body CONVERT send -> grant/reject */ cluster_xp_begin(&xp_convert, CLXP_W_GES_CONVERT); if (resid == NULL || holder == NULL) { cluster_xp_end(&xp_convert); /* PGRAC: spec-5.59 D2 profiling */ - cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_NULL_ARG, -1, 0, 0, -1, timeout_ms); + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_NULL_ARG, -1, + ges_forens_elapsed_ms(forens_start), 0, -1, timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -2437,7 +2492,8 @@ cluster_ges_send_convert_and_wait(const struct ClusterResId *resid, uint32 reque effective_timeout_ms)) { cluster_xp_end(&xp_convert); /* PGRAC: spec-5.59 D2 profiling */ cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_NATIVE_PROBE_TIMEOUT, cluster_node_id, - (long)effective_timeout_ms, 0, -1, effective_timeout_ms); + ges_forens_elapsed_ms(forens_start), 0, -1, + effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } } @@ -2452,9 +2508,9 @@ cluster_ges_send_convert_and_wait(const struct ClusterResId *resid, uint32 reque entry = cluster_ges_reply_wait_insert(&key, deadline); if (entry == NULL) { cluster_xp_end(&xp_convert); /* PGRAC: spec-5.59 D2 profiling */ - cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_REPLY_WAIT_TABLE_FULL, - local_master ? cluster_node_id : master, 0, 0, -1, - effective_timeout_ms); + cluster_ges_timeout_detail_set( + CLUSTER_GES_TSRC_REPLY_WAIT_TABLE_FULL, local_master ? cluster_node_id : master, + ges_forens_elapsed_ms(forens_start), 0, -1, effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -2482,14 +2538,16 @@ cluster_ges_send_convert_and_wait(const struct ClusterResId *resid, uint32 reque cluster_ges_reply_wait_delete(&key); cluster_xp_end(&xp_convert); /* PGRAC: spec-5.59 D2 profiling */ cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_MASTER_WAIT_QUEUE_FULL, cluster_node_id, - 0, 0, -1, effective_timeout_ms); + ges_forens_elapsed_ms(forens_start), 0, -1, + effective_timeout_ms); return GES_REJECT_REASON_WORK_QUEUE_FULL; } } else { if (!cluster_grd_outbound_enqueue_backend_request((uint32)master, &req, sizeof(req))) { cluster_ges_reply_wait_delete(&key); cluster_xp_end(&xp_convert); /* PGRAC: spec-5.59 D2 profiling */ - cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_OUTBOUND_RING_FULL, master, 0, 0, -1, + cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_OUTBOUND_RING_FULL, master, + ges_forens_elapsed_ms(forens_start), 0, -1, effective_timeout_ms); return GES_REJECT_REASON_WORK_QUEUE_FULL; } @@ -2541,9 +2599,9 @@ cluster_ges_send_convert_and_wait(const struct ClusterResId *resid, uint32 reque ConditionVariableCancelSleep(); cluster_xp_end(&xp_wait); /* PGRAC: spec-5.59 D2 profiling */ cluster_xp_end(&xp_convert); /* PGRAC: spec-5.59 D2 profiling */ - cluster_ges_timeout_detail_set(CLUSTER_GES_TSRC_CV_WAIT_TIMEOUT, - local_master ? cluster_node_id : master, - (long)effective_timeout_ms, 0, -1, effective_timeout_ms); + cluster_ges_timeout_detail_set( + CLUSTER_GES_TSRC_CV_WAIT_TIMEOUT, local_master ? cluster_node_id : master, + ges_forens_elapsed_ms(forens_start), 0, -1, effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } remaining_ms = (long)((deadline - now) / 1000); @@ -2558,6 +2616,16 @@ cluster_ges_send_convert_and_wait(const struct ClusterResId *resid, uint32 reque reject_reason = entry->reject_reason; cluster_ges_reply_wait_delete(&key); + /* S3 forensics step 1a — attribute a master-replied CONVERT rejection + * that the S5 mapping folds into FAIL_TIMEOUT (see the REQUEST tails). */ + if (reject_reason == GES_REJECT_REASON_WORK_QUEUE_FULL) + cluster_ges_timeout_detail_set( + CLUSTER_GES_TSRC_MASTER_REJECT_QUEUE_FULL, local_master ? cluster_node_id : master, + ges_forens_elapsed_ms(forens_start), 0, -1, effective_timeout_ms); + else if (reject_reason == GES_REJECT_REASON_TIMEOUT) + cluster_ges_timeout_detail_set( + CLUSTER_GES_TSRC_MASTER_REJECT_TIMEOUT, local_master ? cluster_node_id : master, + ges_forens_elapsed_ms(forens_start), 0, -1, effective_timeout_ms); cluster_xp_end(&xp_convert); /* PGRAC: spec-5.59 D2 profiling */ return reject_reason; } diff --git a/src/backend/cluster/cluster_inject.c b/src/backend/cluster/cluster_inject.c index b59013d2c3..1946fc73e1 100644 --- a/src/backend/cluster/cluster_inject.c +++ b/src/backend/cluster/cluster_inject.c @@ -911,6 +911,17 @@ static ClusterInjectPoint cluster_injection_points[] = { * could fire after the commit record is already durable. */ { .name = "cluster-boc-event-publish" }, + + /* + * S3 forensics step 1a — GES timeout-source semantic RED. + * cluster-ges-master-work-queue-full: fires in the master-side + * GES_REQUEST handler just before the work-queue enqueue; SKIP + * forces the WORK_QUEUE_FULL reject reply so a remote requester + * deterministically exercises the reply-tail attribution + * (source=master-reject-queue-full + capacity counter) that the + * S3 storm's dominant "cluster lock acquire timeout" fold hides. + */ + { .name = "cluster-ges-master-work-queue-full" }, }; #define CLUSTER_INJECTION_COUNT lengthof(cluster_injection_points) diff --git a/src/backend/cluster/cluster_pcm_lock.c b/src/backend/cluster/cluster_pcm_lock.c index c55ca14119..12553fe880 100644 --- a/src/backend/cluster/cluster_pcm_lock.c +++ b/src/backend/cluster/cluster_pcm_lock.c @@ -312,6 +312,24 @@ typedef struct ClusterPcmShared { pg_atomic_uint64 writer_reverify_reacquire_count; pg_atomic_uint64 restore_aba_detected_count; pg_atomic_uint64 invalidate_parked_grant_pending_count; + /* S3 forensics step 1a — SCN-watermark advance provenance ring (see + * cluster_pcm_lock.h ClusterPcmWmProv). Slots are claimed with a + * fetch-add on wm_prov_next; each entry is stamped with its claim seq + * AFTER the payload (write barrier) so a torn wrap-around read is + * detectable. Diagnostic-only: readers tolerate a missed entry. */ + pg_atomic_uint32 wm_prov_next; + struct { + BufferTag tag; /* 20B */ + uint32 seq; /* claim seq + 1 (0 = never written) */ + SCN old_scn; /* watermark before the feed */ + SCN new_scn; /* fed page_scn */ + uint64 request_id; /* wire identity (0 = none) */ + uint64 epoch; /* wire epoch (0 = none) */ + int32 sender_node; /* -1 = local/unknown */ + uint8 source; /* ClusterPcmWmSrc */ + uint8 advanced; /* monotone max actually raised */ + uint16 _pad; + } wm_prov[256]; } ClusterPcmShared; StaticAssertDecl(sizeof(ClusterPcmShared) >= sizeof(LWLockPadded) + 72, @@ -339,6 +357,11 @@ static int pcm_grd_effective = 0; /* Forward decl — file-private HTAB lazy-alloc helper defined below init_fn. */ static struct GrdEntry *pcm_get_or_create_entry(BufferTag tag); +/* S3 forensics step 1a — watermark-advance provenance recorder (defined with + * the watermark helpers below; used by the inline writer sites above them). */ +static void pcm_wm_prov_record(BufferTag tag, SCN old_scn, SCN new_scn, bool advanced, + ClusterPcmWmSrc source, int32 sender_node, uint64 request_id, + uint64 epoch); static struct GrdEntry *pcm_find_entry(BufferTag tag); static void pcm_entry_lock_exclusive(struct GrdEntry *entry); static uint32 pcm_holder_bit(int holder_node_id); @@ -1000,7 +1023,8 @@ cluster_gcs_block_master_rebuild_from_redeclare(BufferTag tag, uint8 held_mode, struct GrdEntry *entry; uint32 holder_bit; - (void)cluster_epoch; /* already gated by the handler (L235/L236); D3 may re-pin */ + /* epoch already gated by the handler (L235/L236); recorded below as the + * re-declare feed's provenance epoch (S3 forensics step 1a). */ if (cluster_pcm_htab == NULL) return false; @@ -1070,10 +1094,18 @@ cluster_gcs_block_master_rebuild_from_redeclare(BufferTag tag, uint8 held_mode, entry->pi_watermark_lsn = (uint64)page_lsn; /* monotone-max by local_scn (scn_time_cmp order); a raw SCN compare would be * node_id-dominated — see cluster_scn.h + gcs_block_lost_write_verdict. */ - if (SCN_VALID(page_scn) - && scn_local(page_scn) - > scn_local(entry->pi_watermark_scn)) /* SCN_CMP_OK: scn_time_cmp via scn_local */ - entry->pi_watermark_scn = page_scn; + if (SCN_VALID(page_scn)) { + SCN wm_old = entry->pi_watermark_scn; + bool wm_advanced = false; + + if (scn_local(page_scn) + > scn_local(entry->pi_watermark_scn)) { /* SCN_CMP_OK: scn_time_cmp via scn_local */ + entry->pi_watermark_scn = page_scn; + wm_advanced = true; + } + pcm_wm_prov_record(tag, wm_old, page_scn, wm_advanced, CLUSTER_PCM_WM_SRC_REDECLARE, + source_node, 0, cluster_epoch); + } LWLockRelease(&entry->entry_lock.lock); return true; /* holder recorded */ @@ -1129,10 +1161,17 @@ cluster_pcm_lock_master_take_x_after_transfer(BufferTag tag, XLogRecPtr page_lsn entry->pi_watermark_lsn = (uint64)page_lsn; /* monotone-max by local_scn (scn_time_cmp order); a raw SCN compare would be * node_id-dominated — see cluster_scn.h + gcs_block_lost_write_verdict. */ - if (SCN_VALID(page_scn) - && scn_local(page_scn) - > scn_local(entry->pi_watermark_scn)) /* SCN_CMP_OK: scn_time_cmp via scn_local */ - entry->pi_watermark_scn = page_scn; + if (SCN_VALID(page_scn)) { + SCN wm_old = entry->pi_watermark_scn; + bool wm_advanced = false; + + if (scn_local(page_scn) + > scn_local(entry->pi_watermark_scn)) { /* SCN_CMP_OK: scn_time_cmp via scn_local */ + entry->pi_watermark_scn = page_scn; + wm_advanced = true; + } + pcm_wm_prov_record(tag, wm_old, page_scn, wm_advanced, CLUSTER_PCM_WM_SRC_TAKE_X, -1, 0, 0); + } LWLockRelease(&entry->entry_lock.lock); } @@ -1183,10 +1222,18 @@ cluster_pcm_lock_master_grant_x_to(BufferTag tag, int32 requester_node, XLogRecP entry->pi_watermark_lsn = (uint64)page_lsn; /* monotone-max by local_scn (scn_time_cmp order); a raw SCN compare would be * node_id-dominated — see cluster_scn.h + gcs_block_lost_write_verdict. */ - if (SCN_VALID(page_scn) - && scn_local(page_scn) - > scn_local(entry->pi_watermark_scn)) /* SCN_CMP_OK: scn_time_cmp via scn_local */ - entry->pi_watermark_scn = page_scn; + if (SCN_VALID(page_scn)) { + SCN wm_old = entry->pi_watermark_scn; + bool wm_advanced = false; + + if (scn_local(page_scn) + > scn_local(entry->pi_watermark_scn)) { /* SCN_CMP_OK: scn_time_cmp via scn_local */ + entry->pi_watermark_scn = page_scn; + wm_advanced = true; + } + pcm_wm_prov_record(tag, wm_old, page_scn, wm_advanced, CLUSTER_PCM_WM_SRC_GRANT_X, + requester_node, 0, 0); + } LWLockRelease(&entry->entry_lock.lock); } @@ -1253,15 +1300,114 @@ cluster_pcm_lock_pi_watermark_lsn_advance(BufferTag tag, XLogRecPtr page_lsn) LWLockRelease(&ClusterPcm->htab_lock.lock); } +/* + * S3 forensics step 1a — SCN-watermark advance provenance ring. + * + * pcm_wm_prov_record claims a slot with a fetch-add, invalidates it + * (seq=0), writes the payload, then stamps seq+1 behind a write barrier; + * the seq1/payload/seq2 read protocol in prov_query detects a torn + * wrap-around rewrite. Diagnostic-only ring: a missed or overwritten + * record degrades to "no provenance", never to a wrong record. + */ +static void +pcm_wm_prov_record(BufferTag tag, SCN old_scn, SCN new_scn, bool advanced, ClusterPcmWmSrc source, + int32 sender_node, uint64 request_id, uint64 epoch) +{ + uint32 seq; + uint32 idx; + + if (ClusterPcm == NULL) + return; + seq = pg_atomic_fetch_add_u32(&ClusterPcm->wm_prov_next, 1); + idx = seq % (uint32)lengthof(ClusterPcm->wm_prov); + ClusterPcm->wm_prov[idx].seq = 0; /* invalidate while rewriting */ + pg_write_barrier(); + ClusterPcm->wm_prov[idx].tag = tag; + ClusterPcm->wm_prov[idx].old_scn = old_scn; + ClusterPcm->wm_prov[idx].new_scn = new_scn; + ClusterPcm->wm_prov[idx].request_id = request_id; + ClusterPcm->wm_prov[idx].epoch = epoch; + ClusterPcm->wm_prov[idx].sender_node = sender_node; + ClusterPcm->wm_prov[idx].source = (uint8)source; + ClusterPcm->wm_prov[idx].advanced = advanced ? 1 : 0; + pg_write_barrier(); + ClusterPcm->wm_prov[idx].seq = seq + 1; +} + +const char * +cluster_pcm_wm_src_text(ClusterPcmWmSrc src) +{ + switch (src) { + case CLUSTER_PCM_WM_SRC_NONE: + return "none"; + case CLUSTER_PCM_WM_SRC_REDECLARE: + return "redeclare"; + case CLUSTER_PCM_WM_SRC_TAKE_X: + return "take-x-after-transfer"; + case CLUSTER_PCM_WM_SRC_GRANT_X: + return "grant-x-ship"; + case CLUSTER_PCM_WM_SRC_ACK_SLOTLESS: + return "invalidate-ack-slotless"; + case CLUSTER_PCM_WM_SRC_ACK_SLOT: + return "invalidate-ack-slot"; + } + return "unknown"; +} + +bool +cluster_pcm_lock_pi_watermark_prov_query(BufferTag tag, ClusterPcmWmProv *out) +{ + uint32 best_seq = 0; + bool found = false; + int i; + + if (ClusterPcm == NULL || out == NULL) + return false; + memset(out, 0, sizeof(*out)); + out->sender_node = -1; + for (i = 0; i < (int)lengthof(ClusterPcm->wm_prov); i++) { + uint32 seq1 = ClusterPcm->wm_prov[i].seq; + BufferTag etag; + ClusterPcmWmProv cand; + uint32 seq2; + + if (seq1 == 0) + continue; + pg_read_barrier(); + etag = ClusterPcm->wm_prov[i].tag; + cand.source = (ClusterPcmWmSrc)ClusterPcm->wm_prov[i].source; + cand.sender_node = ClusterPcm->wm_prov[i].sender_node; + cand.request_id = ClusterPcm->wm_prov[i].request_id; + cand.epoch = ClusterPcm->wm_prov[i].epoch; + cand.old_scn = ClusterPcm->wm_prov[i].old_scn; + cand.new_scn = ClusterPcm->wm_prov[i].new_scn; + cand.advanced = ClusterPcm->wm_prov[i].advanced != 0; + pg_read_barrier(); + seq2 = ClusterPcm->wm_prov[i].seq; + if (seq1 != seq2 || !BufferTagsEqual(&etag, &tag)) + continue; + if (seq1 > best_seq) { + best_seq = seq1; + *out = cand; + found = true; + } + } + return found; +} + /* * PGRAC: spec-2.41 D2 §2.8.1 — SCN watermark (lost-write detector ONLY). * Monotone-max of the cross-node pd_block_scn observed for this tag; the * detector compares a shipped page's pd_block_scn against this (§2.6). Fed * by the local-page sources today; the ack/redeclare wire sources feed it * once D3 carries pd_block_scn on the wire. + * S3 forensics step 1a: every feed records its provenance (source enum + + * wire identity + old->new + advanced?) so a 53R93's expected_scn can be + * traced to the advance that produced it. */ void -cluster_pcm_lock_pi_watermark_scn_advance(BufferTag tag, SCN page_scn) +cluster_pcm_lock_pi_watermark_scn_advance(BufferTag tag, SCN page_scn, ClusterPcmWmSrc source, + int32 sender_node, uint64 request_id, uint64 epoch) { struct GrdEntry *entry; bool found; @@ -1272,13 +1418,21 @@ cluster_pcm_lock_pi_watermark_scn_advance(BufferTag tag, SCN page_scn) LWLockAcquire(&ClusterPcm->htab_lock.lock, LW_SHARED); entry = (struct GrdEntry *)hash_search(cluster_pcm_htab, &tag, HASH_FIND, &found); if (found && entry != NULL) { + SCN wm_old; + bool wm_advanced = false; + LWLockAcquire(&entry->entry_lock.lock, LW_EXCLUSIVE); + wm_old = entry->pi_watermark_scn; /* monotone-max by local_scn (scn_time_cmp order); page_scn already * SCN_VALID-checked above. */ if (scn_local(page_scn) - > scn_local(entry->pi_watermark_scn)) /* SCN_CMP_OK: scn_time_cmp via scn_local */ + > scn_local(entry->pi_watermark_scn)) { /* SCN_CMP_OK: scn_time_cmp via scn_local */ entry->pi_watermark_scn = page_scn; + wm_advanced = true; + } LWLockRelease(&entry->entry_lock.lock); + pcm_wm_prov_record(tag, wm_old, page_scn, wm_advanced, source, sender_node, request_id, + epoch); } LWLockRelease(&ClusterPcm->htab_lock.lock); } @@ -3039,6 +3193,9 @@ cluster_pcm_grd_init(void) pg_atomic_init_u64(&ClusterPcm->writer_reverify_reacquire_count, 0); pg_atomic_init_u64(&ClusterPcm->restore_aba_detected_count, 0); pg_atomic_init_u64(&ClusterPcm->invalidate_parked_grant_pending_count, 0); + /* S3 forensics step 1a — provenance ring (entries zeroed by the + * memset above; seq 0 marks never-written slots). */ + pg_atomic_init_u32(&ClusterPcm->wm_prov_next, 0); } /* diff --git a/src/backend/cluster/cluster_tt_local.c b/src/backend/cluster/cluster_tt_local.c index 7ed206be30..c3fbd7324c 100644 --- a/src/backend/cluster/cluster_tt_local.c +++ b/src/backend/cluster/cluster_tt_local.c @@ -43,6 +43,7 @@ #include "storage/ipc.h" #include "storage/shmem.h" #include "utils/memutils.h" +#include "utils/timestamp.h" /* S3 forensics — cleaner liveness-tick age */ #include "cluster/cluster_epoch.h" #include "cluster/cluster_guc.h" @@ -52,6 +53,7 @@ #include "cluster/cluster_tt_local.h" #include "cluster/cluster_tt_2pc.h" /* ClusterTT2PCBinding export (spec-3.15) */ #include "cluster/cluster_tt_slot.h" /* spec-3.4b D4 real binding */ +#include "cluster/cluster_undo_cleaner.h" /* S3 forensics — cleaner stall state in errdetail */ #include "cluster/cluster_undo_record_api.h" /* spec-3.12 D2b cluster_undo_tt_rollover_locked */ #include "cluster/cluster_tt_status.h" #include "cluster/cluster_tt_status_hint.h" /* spec-3.2 D4 wire emit append */ @@ -278,11 +280,19 @@ cluster_tt_local_get_or_create_binding(TransactionId top_xid, uint32 *out_segmen uint32 new_seg = cluster_undo_tt_rollover_locked(cluster_node_id, seg, &at_hard_cap); - if (new_seg == 0) - /* S3 forensics step 1 — the errdetail separates "cleaner - * stopped reclaiming" (recycle counters flat, horizon far - * behind current_scn) from "pool genuinely at capacity - * under live retention" before anyone reaches for the GUC. */ + if (new_seg == 0) { + /* S3 forensics step 1/1a — the errdetail separates "cleaner + * stopped reclaiming" (cleaner status/iters/liveness stale, + * recycle counters flat, horizon far behind current_scn) + * from "pool genuinely at capacity under live retention" + * before anyone reaches for the GUC. The rollover-failure + * counters are TT-specific; record_extent_hard_cap_fail is + * the OTHER (record-extent CLAIM) path, labeled as such. */ + TimestampTz cleaner_tick = cluster_undo_cleaner_last_liveness_tick_at(); + long cleaner_tick_age_ms + = cleaner_tick > 0 ? (long)((GetCurrentTimestamp() - cleaner_tick) / 1000) + : -1; + ereport( ERROR, (errcode(ERRCODE_PROGRAM_LIMIT_EXCEEDED), @@ -297,7 +307,11 @@ cluster_tt_local_get_or_create_binding(TransactionId top_xid, uint32 *out_segmen " retention_recycle=" UINT64_FORMAT " retention_off_recycle=" UINT64_FORMAT " wrap_retired=" UINT64_FORMAT " segment_reuse=" UINT64_FORMAT " segment_switch=" UINT64_FORMAT - " hard_cap_fail=" UINT64_FORMAT " segments_max_per_instance=%d.", + " tt_rollover_fail_hard_cap=" UINT64_FORMAT + " tt_rollover_fail_extend=" UINT64_FORMAT + " record_extent_hard_cap_fail=" UINT64_FORMAT + " segments_max_per_instance=%d cleaner_status=%s" + " cleaner_loop_iters=" INT64_FORMAT " cleaner_tick_age_ms=%ld.", cluster_node_id, cluster_tt_slot_retention_horizon_scn(), (uint64)cluster_scn_current(), cluster_tt_slot_retain_skip_count(), cluster_tt_slot_retention_recycle_count(), @@ -305,10 +319,15 @@ cluster_tt_local_get_or_create_binding(TransactionId top_xid, uint32 *out_segmen cluster_tt_slot_wrap_retired_count(), cluster_undo_segment_reuse_count(), cluster_undo_segment_switch_count(), + cluster_undo_tt_rollover_fail_hard_cap_count(), + cluster_undo_tt_rollover_fail_extend_count(), cluster_undo_segment_hard_cap_fail_count(), - cluster_undo_segments_max_per_instance), + cluster_undo_segments_max_per_instance, + cluster_undo_cleaner_status_to_string(cluster_undo_cleaner_status()), + cluster_undo_cleaner_main_loop_iters(), cleaner_tick_age_ms), errhint("A long-running reader is retaining committed undo; end it, " "or raise cluster.undo_segments_max_per_instance."))); + } seg = new_seg; off = cluster_tt_slot_alloc(seg, top_xid); diff --git a/src/backend/cluster/cluster_undo_record.c b/src/backend/cluster/cluster_undo_record.c index 4e6cdf31c8..994597a78f 100644 --- a/src/backend/cluster/cluster_undo_record.c +++ b/src/backend/cluster/cluster_undo_record.c @@ -153,6 +153,14 @@ typedef struct ClusterUndoRecordShared { * allocator rebound to a fresh one instead of erroring "48 slots full"). */ pg_atomic_uint64 tt_retention_rollover_count; + /* S3 forensics step 1a: TT-rollover FAILURES, split by cause. The + * record-extent CLAIM path has its own segment_hard_cap_fail_count + * above — these two count ONLY cluster_undo_tt_rollover_locked fails + * (the writer-facing "retention rollover failed" error), so the TT + * errdetail never cites another path's counter. */ + pg_atomic_uint64 tt_rollover_fail_hard_cap_count; /* pool at hard cap */ + pg_atomic_uint64 tt_rollover_fail_extend_count; /* autoextend / FS fail */ + /* spec-3.18 D3: extent claims (one per ~undo_extent_blocks records per * backend instead of one cursor_lock acquire per record). */ pg_atomic_uint64 extent_claim_count; @@ -496,6 +504,8 @@ cluster_undo_record_shmem_init(void) pg_atomic_init_u64(&UndoRecordShared->segment_hard_cap_fail_count, 0); pg_atomic_init_u64(&UndoRecordShared->segment_reuse_count, 0); pg_atomic_init_u64(&UndoRecordShared->tt_retention_rollover_count, 0); + pg_atomic_init_u64(&UndoRecordShared->tt_rollover_fail_hard_cap_count, 0); + pg_atomic_init_u64(&UndoRecordShared->tt_rollover_fail_extend_count, 0); pg_atomic_init_u64(&UndoRecordShared->segment_retain_skip_count, 0); pg_atomic_init_u64(&UndoRecordShared->extent_claim_count, 0); /* spec-3.18 D3 */ @@ -2065,6 +2075,12 @@ cluster_undo_tt_rollover_locked(int node_id, uint32 old_segment_id, bool *out_at } PG_END_TRY(); if (new_segment_id == 0) { + /* S3 forensics step 1a — TT-rollover-specific failure split (the + * record-extent CLAIM path counts its own hard-cap fails). */ + if (out_at_hard_cap != NULL && *out_at_hard_cap) + pg_atomic_fetch_add_u64(&UndoRecordShared->tt_rollover_fail_hard_cap_count, 1); + else + pg_atomic_fetch_add_u64(&UndoRecordShared->tt_rollover_fail_extend_count, 1); LWLockRelease(&UndoRecordShared->lifecycle_lock.lock); return 0; } @@ -2129,6 +2145,23 @@ cluster_undo_tt_retention_rollover_count(void) return pg_atomic_read_u64(&UndoRecordShared->tt_retention_rollover_count); } +/* S3 forensics step 1a — TT-rollover failure split accessors. */ +uint64 +cluster_undo_tt_rollover_fail_hard_cap_count(void) +{ + if (UndoRecordShared == NULL) + return 0; + return pg_atomic_read_u64(&UndoRecordShared->tt_rollover_fail_hard_cap_count); +} + +uint64 +cluster_undo_tt_rollover_fail_extend_count(void) +{ + if (UndoRecordShared == NULL) + return 0; + return pg_atomic_read_u64(&UndoRecordShared->tt_rollover_fail_extend_count); +} + uint64 cluster_undo_segment_retain_skip_count(void) { diff --git a/src/include/cluster/cluster_ges.h b/src/include/cluster/cluster_ges.h index bb71a0270f..0b113af0ff 100644 --- a/src/include/cluster/cluster_ges.h +++ b/src/include/cluster/cluster_ges.h @@ -110,14 +110,18 @@ typedef struct ClusterGesSharedState { * synchronous acquire), so no locking. */ typedef enum ClusterGesTimeoutSrc { - CLUSTER_GES_TSRC_NONE = 0, /* no GES detail recorded (unattributed) */ - CLUSTER_GES_TSRC_NULL_ARG, /* internal: NULL resid/holder */ - CLUSTER_GES_TSRC_REPLY_WAIT_TABLE_FULL, /* capacity: reply-wait table full */ - CLUSTER_GES_TSRC_MASTER_WAIT_QUEUE_FULL, /* capacity: GRD wait queue / not-ready */ - CLUSTER_GES_TSRC_OUTBOUND_RING_FULL, /* send-fail: outbound ring enqueue failed */ - CLUSTER_GES_TSRC_CV_WAIT_TIMEOUT, /* true wait: CV sleep ran out the deadline */ - CLUSTER_GES_TSRC_RETRANSMIT_EXHAUSTED, /* retransmit budget burned before grant */ - CLUSTER_GES_TSRC_NATIVE_PROBE_TIMEOUT, /* native-lock probe could not prove clear */ + CLUSTER_GES_TSRC_NONE = 0, /* no GES detail recorded (unattributed) */ + CLUSTER_GES_TSRC_NULL_ARG, /* internal: NULL resid/holder */ + CLUSTER_GES_TSRC_REPLY_WAIT_TABLE_FULL, /* capacity: reply-wait table full */ + CLUSTER_GES_TSRC_MASTER_WAIT_QUEUE_FULL, /* capacity: GRD wait queue / not-ready */ + CLUSTER_GES_TSRC_OUTBOUND_RING_FULL, /* send-fail: outbound ring enqueue failed */ + CLUSTER_GES_TSRC_CV_WAIT_TIMEOUT, /* true wait: CV sleep ran out the deadline */ + CLUSTER_GES_TSRC_RETRANSMIT_EXHAUSTED, /* retransmit budget burned before grant */ + CLUSTER_GES_TSRC_NATIVE_PROBE_TIMEOUT, /* native-lock probe could not prove clear */ + CLUSTER_GES_TSRC_MASTER_REJECT_QUEUE_FULL, /* capacity: master REPLIED WORK_QUEUE_FULL + * (dedup table / work queue / wait queue full + * on the master — the reply-tail fold) */ + CLUSTER_GES_TSRC_MASTER_REJECT_TIMEOUT, /* master replied TIMEOUT (reply-tail fold) */ } ClusterGesTimeoutSrc; typedef struct ClusterGesTimeoutDetail { diff --git a/src/include/cluster/cluster_pcm_lock.h b/src/include/cluster/cluster_pcm_lock.h index 0180686322..216f18fcfd 100644 --- a/src/include/cluster/cluster_pcm_lock.h +++ b/src/include/cluster/cluster_pcm_lock.h @@ -537,7 +537,44 @@ cluster_pcm_mode_covers(PcmLockMode have, PcmLockMode want) */ extern void cluster_pcm_lock_pi_watermark_lsn_advance(BufferTag tag, XLogRecPtr page_lsn); extern XLogRecPtr cluster_pcm_lock_pi_watermark_lsn_query(BufferTag tag); -extern void cluster_pcm_lock_pi_watermark_scn_advance(BufferTag tag, SCN page_scn); + +/* + * S3 forensics step 1a — SCN-watermark advance PROVENANCE. + * + * The lost-write detector's expected_scn is only as trustworthy as the + * last advance that produced it: a late / wrong-generation invalidate-ACK + * feeding the monotone max would fabricate lost-write verdicts against + * perfectly current pages. Every SCN-watermark feed site therefore + * records {source, sender, request_id, epoch, old->new, advanced?} into a + * small shmem ring; the 53R93 emit sites on the MASTER (the only node + * whose ring is authoritative for its tags) attach the latest record so a + * shippedsafe_psql('postgres', 'SELECT count(*) FROM pg_stat_cluster_injections'), - '180', 'pg_stat_cluster_injections returns 180 rows (ownership-gen wave +6 cluster-pcm-writer-cached-x-stall + cluster-pcm-restore-aba-window + cluster-pcm-grant-finalize-window + cluster-pcm-grant-finalize-deliver-invalidate + cluster-pcm-drop-prepin-window + cluster-pcm-restore-aba-force-round; serve-stall round-6 +1 cluster-gcs-xfer-copy-drop-window; gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-5.22e D5-7 +2 horizon report-drop/epoch-fence; spec-5.22d D4-8 +1 authority-block0-prove; spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5+D8 +3; spec-5.6a +1; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 cluster-xid-herding-stall + cluster-xid-window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.18 +7 cluster-node-remove-*; spec-5.13 +6 cluster-clean-leave-*; spec-5.13 Hardening v1.0.3 +1 cluster-clean-leave-survivor-suppress-preflight-ack; spec-5.53 +1 cluster-cr-skip-epoch-bump; spec-5.7 +1 cluster-ko-peer-skip-ack; spec-2.41 +1 cluster-gcs-block-stale-ship; spec-5.8 +1 cluster-lmd-force-partial-round; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); + '181', 'pg_stat_cluster_injections returns 181 rows (S3 forensics step 1a +1 cluster-ges-master-work-queue-full; ownership-gen wave +6 cluster-pcm-writer-cached-x-stall + cluster-pcm-restore-aba-window + cluster-pcm-grant-finalize-window + cluster-pcm-grant-finalize-deliver-invalidate + cluster-pcm-drop-prepin-window + cluster-pcm-restore-aba-force-round; serve-stall round-6 +1 cluster-gcs-xfer-copy-drop-window; gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-5.22e D5-7 +2 horizon report-drop/epoch-fence; spec-5.22d D4-8 +1 authority-block0-prove; spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5+D8 +3; spec-5.6a +1; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 cluster-xid-herding-stall + cluster-xid-window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.18 +7 cluster-node-remove-*; spec-5.13 +6 cluster-clean-leave-*; spec-5.13 Hardening v1.0.3 +1 cluster-clean-leave-survivor-suppress-preflight-ack; spec-5.53 +1 cluster-cr-skip-epoch-bump; spec-5.7 +1 cluster-ko-peer-skip-ack; spec-2.41 +1 cluster-gcs-block-stale-ship; spec-5.8 +1 cluster-lmd-force-partial-round; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); # ---------- @@ -85,8 +85,8 @@ 'postgres', 'SELECT string_agg(name, \',\' ORDER BY name) FROM pg_stat_cluster_injections' ), - 'cluster-boc-event-publish,cluster-catalog-services-ready-force-closed,cluster-clean-leave-barrier-complete,cluster-clean-leave-escalate-to-failstop,cluster-clean-leave-gcs-flushed,cluster-clean-leave-ges-drained,cluster-clean-leave-quiesce-pre,cluster-clean-leave-request,cluster-clean-leave-survivor-suppress-preflight-ack,cluster-clean-xfer-stale-holder,cluster-collision-detect,cluster-conf-load-success,cluster-conf-parse-fail,cluster-conf-shmem-init,cluster-cr-resolver-memo-suspect,cluster-cr-skip-epoch-bump,cluster-cssd-main-loop-pre-tick,cluster-cssd-mark-peer-dead,cluster-cssd-post-spawn,cluster-cssd-pre-spawn,cluster-cssd-ready-publish,cluster-cssd-shutdown-post,cluster-cssd-shutdown-pre,cluster-debug-dump-entry,cluster-diag-main-loop-iter,cluster-diag-post-spawn,cluster-diag-pre-spawn,cluster-diag-ready-publish,cluster-diag-shutdown-post,cluster-diag-shutdown-pre,cluster-fence-post-thaw-broadcast,cluster-fence-pre-freeze-broadcast,cluster-fence-pre-self-fence-shutdown,cluster-gcs-block-bast-nudge,cluster-gcs-block-done-drop,cluster-gcs-block-drop-reply-before-send,cluster-gcs-block-duplicate-grant-reply,cluster-gcs-block-evict-holder-before-ship,cluster-gcs-block-fallback-refresh-stale,cluster-gcs-block-force-epoch-stale-reply,cluster-gcs-block-forward-master-side,cluster-gcs-block-invalidate-drop-broadcast,cluster-gcs-block-invalidate-stall-ack,cluster-gcs-block-remote-downgrade,cluster-gcs-block-stale-ship,cluster-gcs-block-starvation-force-denied,cluster-gcs-block-x-forward-master-side,cluster-gcs-block-yield-notify-drop,cluster-gcs-xfer-copy-drop-window,cluster-grd-redeclare-skip,cluster-guc-init-pre-define,cluster-ic-mock-send-pre-enqueue,cluster-ic-tier-selected,cluster-init-post-shmem,cluster-init-pre-shmem,cluster-init-top,cluster-ko-peer-skip-ack,cluster-lck-main-loop-iter,cluster-lck-post-spawn,cluster-lck-pre-spawn,cluster-lck-ready-publish,cluster-lck-shutdown-post,cluster-lck-shutdown-pre,cluster-lmd-force-partial-round,cluster-lmon-main-loop-iter,cluster-lmon-post-spawn,cluster-lmon-pre-spawn,cluster-lmon-ready-publish,cluster-lmon-shutdown-post,cluster-lmon-shutdown-pre,cluster-lms-conn-reset,cluster-lms-cr-construct,cluster-lms-cr-fence-recheck,cluster-lms-cr-fence-refuse,cluster-lms-data-dispatch,cluster-lms-undo-fetch,cluster-mxid-halfspace-hard-limit,cluster-node-remove-cleanup-done,cluster-node-remove-escalate,cluster-node-remove-fence-armed,cluster-node-remove-precheck,cluster-node-remove-request,cluster-node-remove-shrink-committed,cluster-node-remove-shrink-committing,cluster-pcm-acquire-entry,cluster-pcm-convert-pre,cluster-pcm-downgrade-pre,cluster-pcm-drop-prepin-window,cluster-pcm-grant-finalize-deliver-invalidate,cluster-pcm-grant-finalize-window,cluster-pcm-release-pre,cluster-pcm-restore-aba-force-round,cluster-pcm-restore-aba-window,cluster-pcm-writer-cached-x-stall,cluster-pgstat-mirror-sync,cluster-quorum-loss-broadcast,cluster-qvotec-marker-service-hold,cluster-qvotec-poll-post,cluster-qvotec-poll-pre,cluster-reconfig-broadcast-procsig-pre,cluster-reconfig-decide-coordinator,cluster-reconfig-epoch-bump-pre,cluster-reconfig-join-commit-marker-durable,cluster-reconfig-tick-entry,cluster-recovery-anchor-force-failclosed,cluster-relmap-crash-after-stage,cluster-relmap-crash-before-publish,cluster-run-shutdown-top,cluster-run-startup-top,cluster-scn-abort-post-advance,cluster-scn-abort-pre-advance,cluster-scn-advance-post,cluster-scn-advance-pre,cluster-scn-boc-sweep-post,cluster-scn-boc-sweep-pre,cluster-scn-commit-post-advance,cluster-scn-commit-pre-advance,cluster-scn-observe-bump-pre,cluster-scn-observe-entry,cluster-scn-replay-observe-pre,cluster-scn-wal-write-pre,cluster-scn-wraparound-warning,cluster-shared-fs-backend-register,cluster-shared-fs-init-top,cluster-shared-fs-local-open,cluster-shmem-region-init-post,cluster-shmem-region-init-pre,cluster-shmem-register-region,cluster-shmem-request,cluster-shmem-views-srf-entry,cluster-shutdown-top,cluster-sinval-ack-drop-send,cluster-sinval-ack-skip-validate,cluster-sinval-broadcast-drop-send,cluster-sinval-receive-skip-validate,cluster-smgr-create-top,cluster-smgr-open-top,cluster-smgr-which-decision,cluster-startup-phase-0-enter,cluster-startup-phase-0-exit,cluster-startup-phase-0-fail,cluster-startup-phase-1-enter,cluster-startup-phase-1-exit,cluster-startup-phase-1-fail,cluster-startup-phase-2-enter,cluster-startup-phase-2-exit,cluster-startup-phase-2-fail,cluster-startup-phase-3-enter,cluster-startup-phase-3-exit,cluster-startup-phase-3-fail,cluster-startup-phase-4-enter,cluster-startup-phase-4-exit,cluster-startup-phase-4-fail,cluster-stats-main-loop-iter,cluster-stats-post-spawn,cluster-stats-pre-spawn,cluster-stats-ready-publish,cluster-stats-shutdown-post,cluster-stats-shutdown-pre,cluster-thread-recovery-drive,cluster-undo-authority-block0-prove,cluster-undo-authority-scan,cluster-undo-horizon-epoch-fence,cluster-undo-horizon-report-drop,cluster-views-srf-entry,cluster-voting-disk-write-fail,cluster-wal-page-init-thread-id,cluster-wal-state-ensure-pre,cluster-wal-state-write-fail,cluster-wal-thread-claim-create-fail,cluster-wal-thread-validate-pre,cluster-xid-herding-stall,cluster-xid-window-hard-limit,cr_construct_delay_us,cr_corruption,cr_cross_instance,cr_force_read_scn,cr_snapshot_too_old,undo-force-wal-before-data-violation,undo-skip-checkpoint-flush-one', - '177 injection point names match the full registry (ownership-gen wave +6 cluster-pcm-*; serve-stall round-6 +1 cluster-gcs-xfer-copy-drop-window; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-5.22e D5-7 +2 cluster-undo-horizon-report-drop + cluster-undo-horizon-epoch-fence; spec-5.22d D4-8 +1 cluster-undo-authority-block0-prove; spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5+D8 +3; spec-5.6a +1; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 cluster-xid-herding-stall + cluster-xid-window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.13 +6 cluster-clean-leave-*; spec-5.13 Hardening v1.0.3 +1 cluster-clean-leave-survivor-suppress-preflight-ack; spec-5.53 +1 cluster-cr-skip-epoch-bump; spec-5.7 +1 cluster-ko-peer-skip-ack; spec-2.41 +1 cluster-gcs-block-stale-ship; spec-5.8 +1 cluster-lmd-force-partial-round; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); + 'cluster-boc-event-publish,cluster-catalog-services-ready-force-closed,cluster-clean-leave-barrier-complete,cluster-clean-leave-escalate-to-failstop,cluster-clean-leave-gcs-flushed,cluster-clean-leave-ges-drained,cluster-clean-leave-quiesce-pre,cluster-clean-leave-request,cluster-clean-leave-survivor-suppress-preflight-ack,cluster-clean-xfer-stale-holder,cluster-collision-detect,cluster-conf-load-success,cluster-conf-parse-fail,cluster-conf-shmem-init,cluster-cr-resolver-memo-suspect,cluster-cr-skip-epoch-bump,cluster-cssd-main-loop-pre-tick,cluster-cssd-mark-peer-dead,cluster-cssd-post-spawn,cluster-cssd-pre-spawn,cluster-cssd-ready-publish,cluster-cssd-shutdown-post,cluster-cssd-shutdown-pre,cluster-debug-dump-entry,cluster-diag-main-loop-iter,cluster-diag-post-spawn,cluster-diag-pre-spawn,cluster-diag-ready-publish,cluster-diag-shutdown-post,cluster-diag-shutdown-pre,cluster-fence-post-thaw-broadcast,cluster-fence-pre-freeze-broadcast,cluster-fence-pre-self-fence-shutdown,cluster-gcs-block-bast-nudge,cluster-gcs-block-done-drop,cluster-gcs-block-drop-reply-before-send,cluster-gcs-block-duplicate-grant-reply,cluster-gcs-block-evict-holder-before-ship,cluster-gcs-block-fallback-refresh-stale,cluster-gcs-block-force-epoch-stale-reply,cluster-gcs-block-forward-master-side,cluster-gcs-block-invalidate-drop-broadcast,cluster-gcs-block-invalidate-stall-ack,cluster-gcs-block-remote-downgrade,cluster-gcs-block-stale-ship,cluster-gcs-block-starvation-force-denied,cluster-gcs-block-x-forward-master-side,cluster-gcs-block-yield-notify-drop,cluster-gcs-xfer-copy-drop-window,cluster-ges-master-work-queue-full,cluster-grd-redeclare-skip,cluster-guc-init-pre-define,cluster-ic-mock-send-pre-enqueue,cluster-ic-tier-selected,cluster-init-post-shmem,cluster-init-pre-shmem,cluster-init-top,cluster-ko-peer-skip-ack,cluster-lck-main-loop-iter,cluster-lck-post-spawn,cluster-lck-pre-spawn,cluster-lck-ready-publish,cluster-lck-shutdown-post,cluster-lck-shutdown-pre,cluster-lmd-force-partial-round,cluster-lmon-main-loop-iter,cluster-lmon-post-spawn,cluster-lmon-pre-spawn,cluster-lmon-ready-publish,cluster-lmon-shutdown-post,cluster-lmon-shutdown-pre,cluster-lms-conn-reset,cluster-lms-cr-construct,cluster-lms-cr-fence-recheck,cluster-lms-cr-fence-refuse,cluster-lms-data-dispatch,cluster-lms-undo-fetch,cluster-mxid-halfspace-hard-limit,cluster-node-remove-cleanup-done,cluster-node-remove-escalate,cluster-node-remove-fence-armed,cluster-node-remove-precheck,cluster-node-remove-request,cluster-node-remove-shrink-committed,cluster-node-remove-shrink-committing,cluster-pcm-acquire-entry,cluster-pcm-convert-pre,cluster-pcm-downgrade-pre,cluster-pcm-drop-prepin-window,cluster-pcm-grant-finalize-deliver-invalidate,cluster-pcm-grant-finalize-window,cluster-pcm-release-pre,cluster-pcm-restore-aba-force-round,cluster-pcm-restore-aba-window,cluster-pcm-writer-cached-x-stall,cluster-pgstat-mirror-sync,cluster-quorum-loss-broadcast,cluster-qvotec-marker-service-hold,cluster-qvotec-poll-post,cluster-qvotec-poll-pre,cluster-reconfig-broadcast-procsig-pre,cluster-reconfig-decide-coordinator,cluster-reconfig-epoch-bump-pre,cluster-reconfig-join-commit-marker-durable,cluster-reconfig-tick-entry,cluster-recovery-anchor-force-failclosed,cluster-relmap-crash-after-stage,cluster-relmap-crash-before-publish,cluster-run-shutdown-top,cluster-run-startup-top,cluster-scn-abort-post-advance,cluster-scn-abort-pre-advance,cluster-scn-advance-post,cluster-scn-advance-pre,cluster-scn-boc-sweep-post,cluster-scn-boc-sweep-pre,cluster-scn-commit-post-advance,cluster-scn-commit-pre-advance,cluster-scn-observe-bump-pre,cluster-scn-observe-entry,cluster-scn-replay-observe-pre,cluster-scn-wal-write-pre,cluster-scn-wraparound-warning,cluster-shared-fs-backend-register,cluster-shared-fs-init-top,cluster-shared-fs-local-open,cluster-shmem-region-init-post,cluster-shmem-region-init-pre,cluster-shmem-register-region,cluster-shmem-request,cluster-shmem-views-srf-entry,cluster-shutdown-top,cluster-sinval-ack-drop-send,cluster-sinval-ack-skip-validate,cluster-sinval-broadcast-drop-send,cluster-sinval-receive-skip-validate,cluster-smgr-create-top,cluster-smgr-open-top,cluster-smgr-which-decision,cluster-startup-phase-0-enter,cluster-startup-phase-0-exit,cluster-startup-phase-0-fail,cluster-startup-phase-1-enter,cluster-startup-phase-1-exit,cluster-startup-phase-1-fail,cluster-startup-phase-2-enter,cluster-startup-phase-2-exit,cluster-startup-phase-2-fail,cluster-startup-phase-3-enter,cluster-startup-phase-3-exit,cluster-startup-phase-3-fail,cluster-startup-phase-4-enter,cluster-startup-phase-4-exit,cluster-startup-phase-4-fail,cluster-stats-main-loop-iter,cluster-stats-post-spawn,cluster-stats-pre-spawn,cluster-stats-ready-publish,cluster-stats-shutdown-post,cluster-stats-shutdown-pre,cluster-thread-recovery-drive,cluster-undo-authority-block0-prove,cluster-undo-authority-scan,cluster-undo-horizon-epoch-fence,cluster-undo-horizon-report-drop,cluster-views-srf-entry,cluster-voting-disk-write-fail,cluster-wal-page-init-thread-id,cluster-wal-state-ensure-pre,cluster-wal-state-write-fail,cluster-wal-thread-claim-create-fail,cluster-wal-thread-validate-pre,cluster-xid-herding-stall,cluster-xid-window-hard-limit,cr_construct_delay_us,cr_corruption,cr_cross_instance,cr_force_read_scn,cr_snapshot_too_old,undo-force-wal-before-data-violation,undo-skip-checkpoint-flush-one', + '178 injection point names match the full registry (S3 forensics step 1a +1 cluster-ges-master-work-queue-full; ownership-gen wave +6 cluster-pcm-*; serve-stall round-6 +1 cluster-gcs-xfer-copy-drop-window; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-5.22e D5-7 +2 cluster-undo-horizon-report-drop + cluster-undo-horizon-epoch-fence; spec-5.22d D4-8 +1 cluster-undo-authority-block0-prove; spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5+D8 +3; spec-5.6a +1; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 cluster-xid-herding-stall + cluster-xid-window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.13 +6 cluster-clean-leave-*; spec-5.13 Hardening v1.0.3 +1 cluster-clean-leave-survivor-suppress-preflight-ack; spec-5.53 +1 cluster-cr-skip-epoch-bump; spec-5.7 +1 cluster-ko-peer-skip-ack; spec-2.41 +1 cluster-gcs-block-stale-ship; spec-5.8 +1 cluster-lmd-force-partial-round; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); # ---------- diff --git a/src/test/cluster_tap/t/017_debug.pl b/src/test/cluster_tap/t/017_debug.pl index 979c9a4236..079a1ca54a 100644 --- a/src/test/cluster_tap/t/017_debug.pl +++ b/src/test/cluster_tap/t/017_debug.pl @@ -123,15 +123,15 @@ 'postgres', q{SELECT count(*) FROM pg_cluster_state WHERE category='inject' AND key LIKE '%.fault_type'}), - '180', - 'all 180 injection points have a .fault_type entry (ownership-gen wave +6 cluster-pcm-*; gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-5.22e D5-7 +2; spec-5.22d D4-8 +1; merge sum with 7.x lanes) under inject category (spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5 +2 cluster-relmap-crash-*; spec-6.14 D8 +1 cluster-catalog-services-ready-force-closed; spec-5.6a +1 cluster-recovery-anchor-force-failclosed; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 herding-stall + window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.13 +6 cluster-clean-leave-*; spec-2.41 +1 gcs-block-stale-ship; spec-5.2a +1 clean-xfer stale-holder; spec-4.8ab +2; spec-5.13 H1.0.3 +1 clean-leave-survivor-suppress-preflight-ack; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); + '181', + 'all 181 injection points have a .fault_type entry (S3 forensics step 1a +1 cluster-ges-master-work-queue-full; ownership-gen wave +6 cluster-pcm-*; gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-5.22e D5-7 +2; spec-5.22d D4-8 +1; merge sum with 7.x lanes) under inject category (spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5 +2 cluster-relmap-crash-*; spec-6.14 D8 +1 cluster-catalog-services-ready-force-closed; spec-5.6a +1 cluster-recovery-anchor-force-failclosed; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 herding-stall + window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.13 +6 cluster-clean-leave-*; spec-2.41 +1 gcs-block-stale-ship; spec-5.2a +1 clean-xfer stale-holder; spec-4.8ab +2; spec-5.13 H1.0.3 +1 clean-leave-survivor-suppress-preflight-ack; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); is( $node->safe_psql( 'postgres', q{SELECT count(*) FROM pg_cluster_state WHERE category='inject' AND key LIKE '%.hits'}), - '180', - 'all 180 injection points have a .hits entry (ownership-gen wave +6 cluster-pcm-*; gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-5.22e D5-7 +2; spec-5.22d D4-8 +1; merge sum with 7.x lanes) under inject category (spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5 +2 cluster-relmap-crash-*; spec-6.14 D8 +1 cluster-catalog-services-ready-force-closed; spec-5.6a +1 cluster-recovery-anchor-force-failclosed; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 herding-stall + window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.13 +6 cluster-clean-leave-*; spec-2.41 +1 gcs-block-stale-ship; spec-5.2a +1 clean-xfer stale-holder; spec-4.8ab +2; spec-5.13 H1.0.3 +1 clean-leave-survivor-suppress-preflight-ack; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); + '181', + 'all 181 injection points have a .hits entry (S3 forensics step 1a +1 cluster-ges-master-work-queue-full; ownership-gen wave +6 cluster-pcm-*; gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-5.22e D5-7 +2; spec-5.22d D4-8 +1; merge sum with 7.x lanes) under inject category (spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5 +2 cluster-relmap-crash-*; spec-6.14 D8 +1 cluster-catalog-services-ready-force-closed; spec-5.6a +1 cluster-recovery-anchor-force-failclosed; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 herding-stall + window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.13 +6 cluster-clean-leave-*; spec-2.41 +1 gcs-block-stale-ship; spec-5.2a +1 clean-xfer stale-holder; spec-4.8ab +2; spec-5.13 H1.0.3 +1 clean-leave-survivor-suppress-preflight-ack; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); # ---------- diff --git a/src/test/cluster_tap/t/030_acceptance.pl b/src/test/cluster_tap/t/030_acceptance.pl index c037ab1c40..cdb839d37b 100644 --- a/src/test/cluster_tap/t/030_acceptance.pl +++ b/src/test/cluster_tap/t/030_acceptance.pl @@ -330,7 +330,7 @@ is($node->safe_psql('postgres', 'SELECT count(*) FROM pg_stat_cluster_injections'), - '180', 'M1 180 injection points (ownership-gen wave +6 cluster-pcm-*; serve-stall round-6 +1 cluster-gcs-xfer-copy-drop-window; gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5 +2 cluster-relmap-crash-*; spec-5.6a +1 cluster-recovery-anchor-force-failclosed; spec-6.14 D8 +1 cluster-catalog-services-ready-force-closed; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 herding-stall + window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.18 +7 cluster-node-remove-*; spec-5.13 +6 cluster-clean-leave-*; spec-5.13 Hardening v1.0.3 +1 clean-leave-survivor-suppress-preflight-ack; spec-2.41 +1 gcs-block-stale-ship; spec-5.7 D6 +1 ko-peer-skip-ack; spec-5.2a +1 clean-xfer stale-holder; spec-4.8ab +2 undo boundary guards; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); + '181', 'M1 181 injection points (S3 forensics step 1a +1 cluster-ges-master-work-queue-full; ownership-gen wave +6 cluster-pcm-*; serve-stall round-6 +1 cluster-gcs-xfer-copy-drop-window; gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5 +2 cluster-relmap-crash-*; spec-5.6a +1 cluster-recovery-anchor-force-failclosed; spec-6.14 D8 +1 cluster-catalog-services-ready-force-closed; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 herding-stall + window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.18 +7 cluster-node-remove-*; spec-5.13 +6 cluster-clean-leave-*; spec-5.13 Hardening v1.0.3 +1 clean-leave-survivor-suppress-preflight-ack; spec-2.41 +1 gcs-block-stale-ship; spec-5.7 D6 +1 ko-peer-skip-ack; spec-5.2a +1 clean-xfer stale-holder; spec-4.8ab +2 undo boundary guards; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); is($node->safe_psql('postgres', q{SELECT string_agg(name, ',' ORDER BY name) FROM pg_stat_cluster_injections WHERE name LIKE 'cluster-init-%'}), @@ -360,8 +360,8 @@ 'postgres', q{SELECT count(DISTINCT key) FROM pg_cluster_state WHERE category='inject' AND (key LIKE '%.fault_type' OR key LIKE '%.hits')} - ) eq '360', - 'M5 inject category has 180×2 = 360 sub-keys (.fault_type + .hits; ownership-gen wave +6 cluster-pcm-*; serve-stall round-6 +1 cluster-gcs-xfer-copy-drop-window; gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5 +2 cluster-relmap-crash-*; spec-5.6a +1 cluster-recovery-anchor-force-failclosed; spec-6.14 D8 +1 cluster-catalog-services-ready-force-closed; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 herding-stall + window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.13 +6 cluster-clean-leave-*; spec-2.41 +1 gcs-block-stale-ship; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); + ) eq '362', + 'M5 inject category has 181×2 = 362 sub-keys (.fault_type + .hits; S3 forensics step 1a +1 cluster-ges-master-work-queue-full; ownership-gen wave +6 cluster-pcm-*; serve-stall round-6 +1 cluster-gcs-xfer-copy-drop-window; gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 cluster-lms-data-dispatch + cluster-lms-conn-reset; spec-6.14 D5 +2 cluster-relmap-crash-*; spec-5.6a +1 cluster-recovery-anchor-force-failclosed; spec-6.14 D8 +1 cluster-catalog-services-ready-force-closed; spec-6.12e2 +1 cluster-gcs-block-bast-nudge; spec-6.15 D3 +2 herding-stall + window-hard-limit; spec-6.12i +1 cluster-lms-undo-fetch; spec-6.12b +1 cluster-lms-cr-construct; spec-6.12a ㉕ +1 cluster-gcs-block-remote-downgrade; spec-5.13 +6 cluster-clean-leave-*; spec-2.41 +1 gcs-block-stale-ship; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); is($node->get_cluster_state_value('inject', 'armed_count'), '0', 'M6 inject.armed_count starts at 0 in fresh backend'); diff --git a/src/test/cluster_tap/t/116_gcs_block_lost_write_2node.pl b/src/test/cluster_tap/t/116_gcs_block_lost_write_2node.pl index 62341324c8..4c532ccbfb 100644 --- a/src/test/cluster_tap/t/116_gcs_block_lost_write_2node.pl +++ b/src/test/cluster_tap/t/116_gcs_block_lost_write_2node.pl @@ -274,15 +274,20 @@ sub arm_stale_ship return; } -# Tolerant nextval: the 53R93 fail-closed is by design; capture its text. +# Tolerant nextval: the 53R93 fail-closed is by design; capture its text +# (S3 forensics step 1a — the errdetail asserts below need the full error). my $saw_53r93 = 0; +my $err_53r93 = ''; sub try_nextval { my ($node) = @_; my ($rc, $out, $err) = $node->psql('postgres', "SELECT nextval('lw_seq')", timeout => 30); - $saw_53r93 = 1 - if defined $err && $err =~ /53R93|lost write detected/i; + if (defined $err && $err =~ /53R93|lost write detected/i) + { + $saw_53r93 = 1; + $err_53r93 = $err; + } return; } @@ -316,6 +321,43 @@ sub try_nextval ok($saw_53r93, 'L11 requester saw 53R93 / "lost write detected" (action=error, fail-closed)'); +# ---------- +# L11b (S3 forensics step 1a): the 53R93 must be QUALIFIABLE, not just +# detected. The requester errdetail carries its local SCN/gen view; the +# producer LOG line carries the verdict (expected, shipped) SCN pair plus +# the {requester, request_id, epoch, tag} correlation identity; the +# master-direct twin additionally carries the provenance of the watermark +# advance that produced expected_scn (wm_src=... — the branch-3 watermark +# false-positive discriminator). +# ---------- +like( + $err_53r93, + qr/pi_watermark_scn[a-z ]*=\d+/, + 'L11b requester errdetail carries a watermark view (local / master-now / sent)'); +like($err_53r93, qr/ownership_gen=\d+/, + 'L11b2 requester errdetail carries the ownership generation'); + +my $prod_line = ''; +for my $node ($pair->node0, $pair->node1) +{ + my $log = PostgreSQL::Test::Utils::slurp_file($node->logfile); + if ($log =~ /(cluster_gcs_block: lost-write verdict [^\n]+)/) + { + $prod_line = $1; + last; + } +} +isnt($prod_line, '', 'L11c producer-side verdict LOG line present'); +like( + $prod_line, + qr/expected pi_watermark_scn=\d+ shipped pd_block_scn=\d+/, + 'L11c2 producer LOG carries the verdict (expected, shipped) SCN pair'); +like($prod_line, qr/request_id=\d+/, 'L11c3 producer LOG carries request_id'); +like($prod_line, qr/epoch=\d+/, 'L11c4 producer LOG carries epoch'); +like($prod_line, qr/wm_src=\S+/, + 'L11c5 master-direct producer LOG carries watermark-advance provenance') + if $prod_line =~ /master-direct/; + # ============================================================ # L12: disarm + cluster stays usable. diff --git a/src/test/cluster_tap/t/214_cluster_3_8_undo_lifecycle.pl b/src/test/cluster_tap/t/214_cluster_3_8_undo_lifecycle.pl index 2d5741c13d..a0af9e302e 100644 --- a/src/test/cluster_tap/t/214_cluster_3_8_undo_lifecycle.pl +++ b/src/test/cluster_tap/t/214_cluster_3_8_undo_lifecycle.pl @@ -87,8 +87,8 @@ # ---------- my $undo_row_count = $node0->safe_psql('postgres', q{SELECT count(*) FROM pg_cluster_state WHERE category='undo'}); -is($undo_row_count, '68', - "L2 undo category has 68 rows (5 record + 4 lifecycle + 3 fsync + 4 smgr + 5 durable-tt + 5 retention + 9 terminal-authority [spec-6.2] + 6 cleaner + 4 buf/extent obs [spec-3.18 D7] + 1 spec-3.22 retention_off_recycle + 4 checkpoint-writeback boundary [spec-4.8ab D7] + 2 record-segment reclaim [spec-4.12a D5] + 1 residual-revalidate-drop [spec-4.12a Hardening v1.0.1] + 1 retention_max_recycle_horizon [spec-6.15 D4] + 6 undo GCS grant-plane [spec-5.22b D2-6] + 8 horizon brake observability [spec-5.22e D5-5, D5 lane 漏更 t/214])" +is($undo_row_count, '70', + "L2 undo category has 70 rows (5 record + 4 lifecycle + 3 fsync + 4 smgr + 5 durable-tt + 5 retention + 9 terminal-authority [spec-6.2] + 6 cleaner + 4 buf/extent obs [spec-3.18 D7] + 1 spec-3.22 retention_off_recycle + 4 checkpoint-writeback boundary [spec-4.8ab D7] + 2 record-segment reclaim [spec-4.12a D5] + 1 residual-revalidate-drop [spec-4.12a Hardening v1.0.1] + 1 retention_max_recycle_horizon [spec-6.15 D4] + 6 undo GCS grant-plane [spec-5.22b D2-6] + 8 horizon brake observability [spec-5.22e D5-5, D5 lane 漏更 t/214] + 2 TT-rollover failure split [S3 forensics step 1a])" ); diff --git a/src/test/cluster_tap/t/286_ul_advisory.pl b/src/test/cluster_tap/t/286_ul_advisory.pl index 68000f4278..8e56c7dac4 100644 --- a/src/test/cluster_tap/t/286_ul_advisory.pl +++ b/src/test/cluster_tap/t/286_ul_advisory.pl @@ -347,6 +347,16 @@ sub blocking_grant_after_release # ---------- my $h11 = $n0->background_psql('postgres', on_error_die => 1); $h11->query_safe("SELECT pg_advisory_lock(73)"); # node0 holds X(73) + +# S3 forensics step 1a — pre-capture the breakdown counters so the asserts +# below are DELTA-based (a prior leg's bump can never satisfy them). +my $split_query = q{ + SELECT COALESCE(sum(value::bigint), 0) FROM pg_cluster_state + WHERE category = 'ges' + AND key IN ('ges_timeout_true_wait_count', + 'ges_timeout_retransmit_exhausted_count')}; +my $split_before = $n1->safe_psql('postgres', $split_query); + # node1 blocks on the held key with a short finite per-session timeout; the wait # must resolve (53R70) rather than hang -- this is the bound that protects a # cross-node deadlock from hanging forever (real detection is forward spec-5.8). @@ -358,23 +368,32 @@ sub blocking_grant_after_release like($err11, qr/cluster lock acquire timeout|53R70|not available/i, 'L11: ... with a finite-timeout 53R70 (bounded deadlock resolution)'); -# S3 forensics step 1 — the folded 53R70 text must carry a fine-grained -# source attribution (errdetail) and bump the matching dump_ges breakdown -# counter on the timing-out node. A genuine bounded wait resolves as either -# the CV deadline or the retransmit budget depending on which node masters -# the key (local- vs remote-master wait loop). +# S3 forensics step 1/1a — the folded 53R70 text must carry a fine-grained +# source attribution (errdetail) whose elapsed_ms is TRUE wall-clock (a +# genuine bounded wait burns >= 1s of the 3s window; a capacity fail would +# read ~0), and bump the matching dump_ges breakdown counter (delta-based). +# The wait resolves as either the CV deadline or the retransmit budget +# depending on which node masters the key (local- vs remote-master loop). like( $err11, qr/source=(cv-wait-timeout|retransmit-exhausted)/, 'L11b: 53R70 errdetail carries the timeout-source attribution'); -my $to_split_sum = $n1->safe_psql( - 'postgres', q{ - SELECT COALESCE(sum(value::bigint), 0) FROM pg_cluster_state - WHERE category = 'ges' - AND key IN ('ges_timeout_true_wait_count', - 'ges_timeout_retransmit_exhausted_count')}); -cmp_ok($to_split_sum, '>=', 1, - 'L11c: dump_ges timeout-source breakdown counter bumped by the bounded wait'); +if ($err11 =~ /elapsed_ms=(\d+)/) +{ + my $elapsed = $1; + cmp_ok($elapsed, '>=', 1000, + "L11b2: errdetail elapsed_ms=$elapsed is true wall-clock (>= 1s of the 3s window)"); + cmp_ok($elapsed, '<=', 40_000, 'L11b3: ... and bounded by the psql timeout'); +} +else +{ + fail('L11b2: errdetail carries elapsed_ms'); + fail('L11b3: errdetail carries elapsed_ms'); +} +my $split_after = $n1->safe_psql('postgres', $split_query); +cmp_ok($split_after, '>', $split_before, + 'L11c: dump_ges timeout-source breakdown counter bumped by THIS bounded wait ' + . "($split_before -> $split_after)"); $h11->query_safe("SELECT pg_advisory_unlock(73)"); $h11->quit; @@ -409,5 +428,59 @@ sub blocking_grant_after_release ok(wait_until_acquirable($n1, 'pg_try_advisory_lock(151)', 15), 'L13: released after backend exit (mixed-owner drain — single holder, no double release)'); +# ---------- +# L14 (S3 forensics step 1a): a MASTER-side capacity rejection must surface +# with source=master-reject-queue-full in the folded 53R70 errdetail and +# bump the capacity breakdown counter — never "unattributed". The inject +# forces node1's GES_REQUEST handler into the WORK_QUEUE_FULL reject reply, +# so node0 trips it only on keys node1 masters (locally-mastered keys grant +# without touching the wire handler and are skipped by the probe loop). +# elapsed_ms must read (near) zero: the reject is immediate — the exact +# "surfaced as timeout but never waited" class the S3 storm hid. +# ---------- +$n1->safe_psql('postgres', + "ALTER SYSTEM SET cluster.injection_points = 'cluster-ges-master-work-queue-full:skip'"); +$n1->safe_psql('postgres', 'SELECT pg_reload_conf()'); + +my $cap_query = q{ + SELECT COALESCE(sum(value::bigint), 0) FROM pg_cluster_state + WHERE category = 'ges' AND key = 'ges_timeout_capacity_count'}; +my $cap_before = $n0->safe_psql('postgres', $cap_query); +my $mr_err = ''; +for my $k (211 .. 226) +{ + my ($rc, $out, $err) = $n0->psql( + 'postgres', + "SET cluster.ges_request_timeout_ms = '3s'; SELECT pg_advisory_lock($k)", + timeout => 30); + if ($rc != 0 && defined $err && $err =~ /master-reject-queue-full/) + { + $mr_err = $err; + last; + } + # Locally-mastered key (granted): release and probe the next key. + $n0->psql('postgres', 'SELECT pg_advisory_unlock_all()'); +} +$n1->safe_psql('postgres', 'ALTER SYSTEM RESET cluster.injection_points'); +$n1->safe_psql('postgres', 'SELECT pg_reload_conf()'); + +isnt($mr_err, '', 'L14: a remote-master capacity reject was driven (inject)'); +like($mr_err, qr/cluster lock acquire timeout/, + 'L14b: ... surfaced through the folded 53R70 text'); +like($mr_err, qr/source=master-reject-queue-full/, + 'L14c: ... with the master-reject attribution (never unattributed)'); +if ($mr_err =~ /elapsed_ms=(\d+)/) +{ + cmp_ok($1, '<', 3000, + "L14d: errdetail elapsed_ms=$1 shows the reject never consumed the 3s window"); +} +else +{ + fail('L14d: errdetail carries elapsed_ms'); +} +my $cap_after = $n0->safe_psql('postgres', $cap_query); +cmp_ok($cap_after, '>', $cap_before, + "L14e: capacity breakdown counter bumped by the master reject ($cap_before -> $cap_after)"); + $pair->stop_pair; done_testing(); diff --git a/src/test/cluster_unit/test_cluster_bufmgr_pcm_hook.c b/src/test/cluster_unit/test_cluster_bufmgr_pcm_hook.c index ce9f4b3e6a..d6dea9b52f 100644 --- a/src/test/cluster_unit/test_cluster_bufmgr_pcm_hook.c +++ b/src/test/cluster_unit/test_cluster_bufmgr_pcm_hook.c @@ -143,7 +143,9 @@ uint32 *my_wait_event_info = &ut_wait_event_info_storage; static union { uint64 force_align; - char data[4096]; + /* Sized above sizeof(ClusterPcmShared): the S3-forensics watermark + * provenance ring (256 x 64B) grew the header past the old 4096. */ + char data[32768]; } fake_pcm_header; static union { diff --git a/src/test/cluster_unit/test_cluster_debug.c b/src/test/cluster_unit/test_cluster_debug.c index 531c7b2738..21b605b2c4 100644 --- a/src/test/cluster_unit/test_cluster_debug.c +++ b/src/test/cluster_unit/test_cluster_debug.c @@ -2858,6 +2858,18 @@ cluster_undo_tt_retention_rollover_count(void) return 0; } +/* S3 forensics step 1a stubs — TT-rollover failure split (dump_undo rows). */ +uint64 +cluster_undo_tt_rollover_fail_hard_cap_count(void) +{ + return 0; +} +uint64 +cluster_undo_tt_rollover_fail_extend_count(void) +{ + return 0; +} + Size cluster_shmem_get_total_bytes(void) { diff --git a/src/test/cluster_unit/test_cluster_pcm_lock.c b/src/test/cluster_unit/test_cluster_pcm_lock.c index f93e9b8da3..5900d82a3c 100644 --- a/src/test/cluster_unit/test_cluster_pcm_lock.c +++ b/src/test/cluster_unit/test_cluster_pcm_lock.c @@ -84,7 +84,9 @@ uint32 *my_wait_event_info = &ut_wait_event_info_storage; static union { uint64 force_align; - char data[4096]; + /* Sized above sizeof(ClusterPcmShared): the S3-forensics watermark + * provenance ring (256 x 64B) grew the header past the old 4096. */ + char data[32768]; } fake_pcm_header; static union { @@ -1341,6 +1343,59 @@ UT_TEST(test_pcm_d3_not_double_x) } } +/* + * S3 forensics step 1a — SCN-watermark advance provenance ring. + * Every feed records {source, sender, request_id, epoch, old->new, + * advanced}; the latest record per tag is queryable. The key semantic: + * a LATE / stale feed is recorded with advanced=false and the watermark + * unchanged — the branch-3 (watermark false-positive) discriminator a + * 53R93 emit site attaches to its errdetail / LOG line. + */ +UT_TEST(test_pcm_wm_prov_ring_records_advance) +{ + BufferTag tag = make_tag(95); + ClusterPcmWmProv prov; + + reset_fake_pcm_runtime(4); + fake_cssd_dead_node = -1; + + /* No feed yet — no provenance for the tag. */ + UT_ASSERT(!cluster_pcm_lock_pi_watermark_prov_query(tag, &prov)); + + /* Redeclare feed (real inline writer path): advanced, sender + epoch. */ + cluster_gcs_block_master_rebuild_from_redeclare(tag, (uint8)PCM_STATE_S, (XLogRecPtr)0x1000, + (SCN)0x2000, 2, 7); + UT_ASSERT(cluster_pcm_lock_pi_watermark_prov_query(tag, &prov)); + UT_ASSERT_EQ((long)prov.source, (long)CLUSTER_PCM_WM_SRC_REDECLARE); + UT_ASSERT_EQ((long)prov.sender_node, 2L); + UT_ASSERT_EQ((long)prov.epoch, 7L); + UT_ASSERT_EQ((long)prov.new_scn, 0x2000L); + UT_ASSERT(prov.advanced); + + /* ACK feed through the advance API: full wire identity recorded. */ + cluster_pcm_lock_pi_watermark_scn_advance(tag, (SCN)0x3000, CLUSTER_PCM_WM_SRC_ACK_SLOT, 3, + 4242, 9); + UT_ASSERT(cluster_pcm_lock_pi_watermark_prov_query(tag, &prov)); + UT_ASSERT_EQ((long)prov.source, (long)CLUSTER_PCM_WM_SRC_ACK_SLOT); + UT_ASSERT_EQ((long)prov.sender_node, 3L); + UT_ASSERT_EQ((long)prov.request_id, 4242L); + UT_ASSERT_EQ((long)prov.epoch, 9L); + UT_ASSERT_EQ((long)prov.old_scn, 0x2000L); + UT_ASSERT(prov.advanced); + UT_ASSERT_EQ((uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), (uint64)0x3000); + + /* A LATE / stale feed is recorded but must NOT advance: the record keeps + * the feed's identity with advanced=false and the watermark holds. */ + cluster_pcm_lock_pi_watermark_scn_advance(tag, (SCN)0x100, CLUSTER_PCM_WM_SRC_ACK_SLOTLESS, 1, + 4243, 5); + UT_ASSERT(cluster_pcm_lock_pi_watermark_prov_query(tag, &prov)); + UT_ASSERT_EQ((long)prov.source, (long)CLUSTER_PCM_WM_SRC_ACK_SLOTLESS); + UT_ASSERT_EQ((long)prov.sender_node, 1L); + UT_ASSERT_EQ((long)prov.new_scn, 0x100L); + UT_ASSERT(!prov.advanced); + UT_ASSERT_EQ((uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), (uint64)0x3000); +} + UT_TEST(test_pcm_acquire_buffer_local_s_nonholder_registers_s_then_upgrades) { BufferTag tag = make_tag(96); @@ -1458,7 +1513,7 @@ UT_TEST(test_clean_page_xfer_arm_is_one_shot) int main(void) { - UT_PLAN(41); + UT_PLAN(42); UT_RUN(test_pcm_lock_mode_constant_aliases_match_pcm_state); UT_RUN(test_pcm_lock_transition_count_is_9); UT_RUN(test_pcm_lock_transition_enum_values_are_1_to_9); @@ -1497,6 +1552,7 @@ main(void) UT_RUN(test_pcm_d1_recovering_gate_fail_closed); UT_RUN(test_pcm_d2_rebuild_from_redeclare); UT_RUN(test_pcm_d3_not_double_x); + UT_RUN(test_pcm_wm_prov_ring_records_advance); UT_RUN(test_pcm_acquire_buffer_local_s_nonholder_registers_s_then_upgrades); UT_RUN(test_pcm_dead_node_cleanup_drops_holder_records); UT_RUN(test_clean_page_xfer_arm_is_one_shot); From 8e0cf0944bf42de8671a6e4ee0188e142fa4d1c2 Mon Sep 17 00:00:00 2001 From: SqlRush Date: Tue, 14 Jul 2026 10:08:21 +0800 Subject: [PATCH 4/5] test(cluster_unit): stub injection symbols for standalone test_cluster_ges link MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit cluster_ges.c now carries the cluster-ges-master-work-queue-full injection point (S3 forensics step 1a), so the standalone test_cluster_ges binary needs cluster_injection_armed_count / _run / _should_skip stubs (cluster_inject.o is not linked). armed_count 0 keeps the macro's fast-path gate closed at runtime. Caught by fast-gate run 29299780419 (Linux enable + macOS, same undefined-reference root cause); the prior local claim was a pipe-masked exit code — re-verified with a direct exit read: cluster_unit 177/177. --- src/test/cluster_unit/test_cluster_ges.c | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/src/test/cluster_unit/test_cluster_ges.c b/src/test/cluster_unit/test_cluster_ges.c index dd2a47185a..c9d104dbd4 100644 --- a/src/test/cluster_unit/test_cluster_ges.c +++ b/src/test/cluster_unit/test_cluster_ges.c @@ -61,6 +61,7 @@ #include "cluster/cluster_ic_envelope.h" #include "cluster/cluster_cssd.h" /* spec-5.7 Direction B stub — peer state */ #include "cluster/cluster_extend_gate.h" /* spec-5.7 Direction B stub — sole-native */ +#include "cluster/cluster_inject.h" /* S3 forensics step 1a stub prototypes */ #include "cluster/cluster_xnode_profile.h" /* spec-5.59 D2 stub — profiling gate */ #include "port/atomics.h" @@ -90,6 +91,22 @@ bool IsUnderPostmaster = false; +/* S3 forensics step 1a stubs — cluster_ges.c now carries the + * cluster-ges-master-work-queue-full injection point; this standalone + * binary links no cluster_inject.o. armed_count 0 keeps the macro's + * fast-path gate closed; the helpers are link-only. */ +int cluster_injection_armed_count = 0; + +void +cluster_injection_run(const char *name pg_attribute_unused()) +{} + +bool +cluster_injection_should_skip(const char *name pg_attribute_unused()) +{ + return false; +} + void ExceptionalCondition(const char *conditionName pg_attribute_unused(), const char *fileName pg_attribute_unused(), From c85b11188bbe4df6bd7047769c22cc231ae8221a Mon Sep 17 00:00:00 2001 From: SqlRush Date: Tue, 14 Jul 2026 11:13:52 +0800 Subject: [PATCH 5/5] feat(cluster): S3 forensics step 1b -- per-tag wm provenance, transfer identity, GES timeout ledger close, TT activate-fail split - pcm: replace the step-1a 256-slot wm_prov ring (recycled in ms under S3 fan-out, so a 53R93 query could return an unrelated late feed) with a per-tag insert-once open-addressed table (8192x64B + wm_prov_lock); only feeds that ACTUALLY advance the monotone-max watermark are recorded, inside the GRD entry_lock critical section, so the record always explains the CURRENT watermark; a missed query distinguishes definite-none from table-full-inconclusive; new pcm dump key wm_prov_insert_fail_count (fill-8192-tags trigger impractical: surface asserted via t/024+t/108 key counts). - gcs: take_x/grant_x carry the transfer wire identity (holder/requester, request_id, epoch) into the provenance record; the master-direct producer LOG prints the WIRE request epoch (req->epoch) instead of cluster_epoch_get_current(); all five forensics lines gain fork=%d; 53R93 emits print wm_matches_expected=(prov.new_scn==expected_scn) instead of wm_advanced; take-X captures the shipped pd_block_scn before the slot release (the old read was use-after-release). - ges: sixth breakdown counter ges_timeout_master_reject_count closes the timeout-source ledger (every detail_set with a real source bumps exactly one bucket) + dump_ges row. - undo: third TT-rollover failure bucket tt_rollover_fail_activate_count (mark_active refused on a fresh segment) + every rollover-fail branch nudges the undo cleaner after releasing lifecycle_lock. - tests: provenance UT rewritten to the per-tag semantics (a late feed never enters the table); fake pcm shmem fixtures 32KB->1MB; t/024 + t/108 pcm keys 27->28; t/024 L6a inject baseline 173->181 (stale catch-up, t/017 family); t/214 undo rows 70->71; t/286 elapsed_ms now asserted against the client wall clock (kills hardcoded fills both directions) and L14 gains the immediate-reject bound + client-clock ceiling. --- src/backend/cluster/cluster_debug.c | 8 + src/backend/cluster/cluster_gcs_block.c | 199 ++++++++------ src/backend/cluster/cluster_ges.c | 14 +- src/backend/cluster/cluster_pcm_lock.c | 260 +++++++++++------- src/backend/cluster/cluster_undo_record.c | 18 ++ src/include/cluster/cluster_ges.h | 8 +- src/include/cluster/cluster_pcm_lock.h | 49 ++-- src/include/cluster/cluster_undo_record_api.h | 1 + src/test/cluster_tap/t/024_pcm_lock.pl | 8 +- .../cluster_tap/t/108_pcm_state_machine.pl | 4 +- .../t/214_cluster_3_8_undo_lifecycle.pl | 4 +- src/test/cluster_tap/t/286_ul_advisory.pl | 29 +- .../test_cluster_bufmgr_pcm_hook.c | 7 +- src/test/cluster_unit/test_cluster_debug.c | 15 + src/test/cluster_unit/test_cluster_pcm_lock.c | 47 ++-- 15 files changed, 432 insertions(+), 239 deletions(-) diff --git a/src/backend/cluster/cluster_debug.c b/src/backend/cluster/cluster_debug.c index 5636764ba6..b9f85d0471 100644 --- a/src/backend/cluster/cluster_debug.c +++ b/src/backend/cluster/cluster_debug.c @@ -1756,6 +1756,8 @@ dump_ges(ReturnSetInfo *rsinfo) fmt_int64((int64)cluster_ges_timeout_retransmit_exhausted_count())); emit_row(rsinfo, "ges", "ges_timeout_native_probe_count", fmt_int64((int64)cluster_ges_timeout_native_probe_count())); + emit_row(rsinfo, "ges", "ges_timeout_master_reject_count", + fmt_int64((int64)cluster_ges_timeout_master_reject_count())); } @@ -1971,6 +1973,10 @@ dump_pcm(ReturnSetInfo *rsinfo) fmt_int64((int64)cluster_pcm_get_restore_aba_detected_count())); emit_row(rsinfo, "pcm", "invalidate_parked_grant_pending_count", fmt_int64((int64)cluster_pcm_get_invalidate_parked_grant_pending_count())); + /* S3 forensics step 1b — watermark-advance provenance table insert drops + * (table full): non-zero means prov_query absence is inconclusive. */ + emit_row(rsinfo, "pcm", "wm_prov_insert_fail_count", + fmt_int64((int64)cluster_pcm_get_wm_prov_insert_fail_count())); } @@ -2812,6 +2818,8 @@ dump_undo(ReturnSetInfo *rsinfo) fmt_int64((int64)cluster_undo_tt_rollover_fail_hard_cap_count())); emit_row(rsinfo, "undo", "tt_rollover_fail_extend_count", fmt_int64((int64)cluster_undo_tt_rollover_fail_extend_count())); + emit_row(rsinfo, "undo", "tt_rollover_fail_activate_count", + fmt_int64((int64)cluster_undo_tt_rollover_fail_activate_count())); /* spec-6.2: Smart Fusion terminal-authority substrate counters. */ emit_row(rsinfo, "undo", "terminal_authority_check_count", diff --git a/src/backend/cluster/cluster_gcs_block.c b/src/backend/cluster/cluster_gcs_block.c index 8d920795cb..2bd5e647b4 100644 --- a/src/backend/cluster/cluster_gcs_block.c +++ b/src/backend/cluster/cluster_gcs_block.c @@ -1316,40 +1316,46 @@ cluster_gcs_block_fallback_verify_refresh(BufferDesc *buf, BufferTag tag, SCN ex errmsg("cluster_gcs_block: stale storage-fallback copy detected on tag " "spc=%u db=%u rel=%u block=%u", tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum), - errdetail( - "expected pi_watermark_scn=" UINT64_FORMAT " %s pd_block_scn=" UINT64_FORMAT - " local pi_watermark_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT - " wm_src=%s wm_sender=%d wm_request_id=" UINT64_FORMAT - " wm_epoch=" UINT64_FORMAT " wm_old=" UINT64_FORMAT " wm_new=" UINT64_FORMAT - " wm_advanced=%d.", - (uint64)expected_scn, refreshed ? "storage" : "local(dirty-refused)", - (uint64)page_scn, (uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), - cluster_pcm_own_gen_get(buf->buf_id), - cluster_pcm_wm_src_text(wm_have ? wm_prov.source : CLUSTER_PCM_WM_SRC_NONE), - wm_have ? wm_prov.sender_node : -1, wm_have ? wm_prov.request_id : 0, - wm_have ? wm_prov.epoch : 0, wm_have ? (uint64)wm_prov.old_scn : 0, - wm_have ? (uint64)wm_prov.new_scn : 0, wm_have ? (int)wm_prov.advanced : -1), + errdetail("fork=%d expected pi_watermark_scn=" UINT64_FORMAT + " %s pd_block_scn=" UINT64_FORMAT + " local pi_watermark_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT + " wm_src=%s wm_sender=%d wm_request_id=" UINT64_FORMAT + " wm_epoch=" UINT64_FORMAT " wm_old=" UINT64_FORMAT + " wm_new=" UINT64_FORMAT " wm_matches_expected=%d.", + (int)tag.forkNum, (uint64)expected_scn, + refreshed ? "storage" : "local(dirty-refused)", (uint64)page_scn, + (uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), + cluster_pcm_own_gen_get(buf->buf_id), + wm_prov.table_full ? "none(prov-table-full)" + : cluster_pcm_wm_src_text(wm_prov.source), + wm_have ? wm_prov.sender_node : -1, wm_have ? wm_prov.request_id : 0, + wm_have ? wm_prov.epoch : 0, wm_have ? (uint64)wm_prov.old_scn : 0, + wm_have ? (uint64)wm_prov.new_scn : 0, + wm_have ? (int)(wm_prov.new_scn == expected_scn) : -1), errhint("The local/storage page pd_block_scn is below the master " "pi_watermark_scn carried by the GRANTED_STORAGE_FALLBACK " "reply. Inspect dump_gcs.fallback_scn_failclosed_count. " "Retry is safe (the next attempt renegotiates)."))); - ereport( - WARNING, - (errmsg("cluster_gcs_block: stale storage-fallback copy on tag " - "spc=%u db=%u rel=%u block=%u (action=warn)", - tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum), - errdetail( - "expected pi_watermark_scn=" UINT64_FORMAT " %s pd_block_scn=" UINT64_FORMAT - " local pi_watermark_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT - " wm_src=%s wm_sender=%d wm_request_id=" UINT64_FORMAT " wm_epoch=" UINT64_FORMAT - " wm_old=" UINT64_FORMAT " wm_new=" UINT64_FORMAT " wm_advanced=%d.", - (uint64)expected_scn, refreshed ? "storage" : "local(dirty-refused)", - (uint64)page_scn, (uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), - cluster_pcm_own_gen_get(buf->buf_id), - cluster_pcm_wm_src_text(wm_have ? wm_prov.source : CLUSTER_PCM_WM_SRC_NONE), - wm_have ? wm_prov.sender_node : -1, wm_have ? wm_prov.request_id : 0, - wm_have ? wm_prov.epoch : 0, wm_have ? (uint64)wm_prov.old_scn : 0, - wm_have ? (uint64)wm_prov.new_scn : 0, wm_have ? (int)wm_prov.advanced : -1))); + ereport(WARNING, + (errmsg("cluster_gcs_block: stale storage-fallback copy on tag " + "spc=%u db=%u rel=%u block=%u (action=warn)", + tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum), + errdetail("fork=%d expected pi_watermark_scn=" UINT64_FORMAT + " %s pd_block_scn=" UINT64_FORMAT + " local pi_watermark_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT + " wm_src=%s wm_sender=%d wm_request_id=" UINT64_FORMAT + " wm_epoch=" UINT64_FORMAT " wm_old=" UINT64_FORMAT + " wm_new=" UINT64_FORMAT " wm_matches_expected=%d.", + (int)tag.forkNum, (uint64)expected_scn, + refreshed ? "storage" : "local(dirty-refused)", (uint64)page_scn, + (uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), + cluster_pcm_own_gen_get(buf->buf_id), + wm_prov.table_full ? "none(prov-table-full)" + : cluster_pcm_wm_src_text(wm_prov.source), + wm_have ? wm_prov.sender_node : -1, wm_have ? wm_prov.request_id : 0, + wm_have ? wm_prov.epoch : 0, wm_have ? (uint64)wm_prov.old_scn : 0, + wm_have ? (uint64)wm_prov.new_scn : 0, + wm_have ? (int)(wm_prov.new_scn == expected_scn) : -1))); } } @@ -2261,13 +2267,14 @@ cluster_gcs_send_block_request_and_wait(BufferDesc *buf, PcmLockTransition trans "spc=%u db=%u rel=%u block=%u", tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum), errdetail("request_id=" UINT64_FORMAT " request_epoch=" UINT64_FORMAT - " master=%d transition=%d retry_attempt=%d" + " master=%d fork=%d transition=%d retry_attempt=%d" " local pd_block_scn=" UINT64_FORMAT " local pi_watermark_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT ".", request_id, slot->request_epoch, current_master, - (int)transition_id, retry_attempt, (uint64)forens_local_scn, - (uint64)forens_local_wm, forens_own_gen), + (int)tag.forkNum, (int)transition_id, retry_attempt, + (uint64)forens_local_scn, (uint64)forens_local_wm, + forens_own_gen), errhint("Shipped block.pd_block_scn is below the master " "pi_watermark_scn (or the tracked block shipped an " "unstamped page). Inspect dump_gcs." @@ -2288,13 +2295,14 @@ cluster_gcs_send_block_request_and_wait(BufferDesc *buf, PcmLockTransition trans "spc=%u db=%u rel=%u block=%u (action=warn)", tag.spcOid, tag.dbOid, tag.relNumber, tag.blockNum), errdetail("request_id=" UINT64_FORMAT " request_epoch=" UINT64_FORMAT - " master=%d transition=%d retry_attempt=%d" + " master=%d fork=%d transition=%d retry_attempt=%d" " local pd_block_scn=" UINT64_FORMAT " local pi_watermark_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT ".", request_id, slot->request_epoch, current_master, - (int)transition_id, retry_attempt, (uint64)forens_local_scn, - (uint64)forens_local_wm, forens_own_gen))); + (int)tag.forkNum, (int)transition_id, retry_attempt, + (uint64)forens_local_scn, (uint64)forens_local_wm, + forens_own_gen))); granted_storage_fallback = true; } break; @@ -3430,6 +3438,7 @@ cluster_gcs_local_master_x_transfer_and_wait(BufferDesc *buf, int32 holder_node, bool read_image = false; /* spec-5.2 D11 — holder deferred (active ITL) */ uint8 reply_status = (uint8)GCS_BLOCK_REPLY_DENIED_INCOMPATIBLE; /* spec-5.2a D3 */ XLogRecPtr installed_page_lsn = InvalidXLogRecPtr; + SCN installed_page_scn = InvalidScn; if (buf == NULL) ereport(ERROR, (errcode(ERRCODE_INTERNAL_ERROR), @@ -3540,6 +3549,10 @@ cluster_gcs_local_master_x_transfer_and_wait(BufferDesc *buf, int32 holder_node, /* leave installed = false: faithful stale holder created. */ } else if (expected == got) { installed_page_lsn = (XLogRecPtr)slot->reply_header.page_lsn; + /* step 1b: capture the shipped pd_block_scn NOW — the slot is + * released before the take-X below, so a later read of + * reply_block_data would be use-after-release. */ + installed_page_scn = (SCN)((PageHeader)slot->reply_block_data)->pd_block_scn; gcs_block_install_reply_block(buf, slot->reply_block_data, installed_page_lsn, slot); /* spec-5.14 D2 class 2: consumed the remote holder's X image. */ @@ -3606,8 +3619,8 @@ cluster_gcs_local_master_x_transfer_and_wait(BufferDesc *buf, int32 holder_node, * THIS node is the master. spec-2.41 D2 — also advance the detector's * SCN watermark from the installed image's pd_block_scn (local-page * source; bytes are slot->reply_block_data). */ - cluster_pcm_lock_master_take_x_after_transfer( - tag, installed_page_lsn, (SCN)((PageHeader)slot->reply_block_data)->pd_block_scn); + cluster_pcm_lock_master_take_x_after_transfer(tag, installed_page_lsn, installed_page_scn, + holder_node, request_id, fwd.epoch); pg_atomic_fetch_add_u64(&ClusterGcsBlock->block_x_granted_from_holder_count, 1); if (clean_eligible) pg_atomic_fetch_add_u64(&ClusterGcsBlock->clean_page_xfer_count, 1); @@ -3682,45 +3695,48 @@ cluster_gcs_local_master_x_transfer_and_wait(BufferDesc *buf, int32 holder_node, "spc=%u db=%u relNumber=%u block=%u", tag.spcOid, tag.dbOid, (unsigned int)BufTagGetRelNumber(&tag), (unsigned int)tag.blockNum), - errdetail( - "request_id=" UINT64_FORMAT " epoch=" UINT64_FORMAT " holder=%d" - " expected pi_watermark_scn sent=" UINT64_FORMAT - " master pi_watermark_scn now=" UINT64_FORMAT - " local pd_block_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT - " wm_src=%s wm_sender=%d wm_request_id=" UINT64_FORMAT - " wm_epoch=" UINT64_FORMAT " wm_old=" UINT64_FORMAT " wm_new=" UINT64_FORMAT - " wm_advanced=%d.", - request_id, fwd.epoch, holder_node, (uint64)forens_expected_sent, - (uint64)forens_master_wm_now, (uint64)forens_local_scn, forens_own_gen, - cluster_pcm_wm_src_text(wm_have ? wm_prov.source : CLUSTER_PCM_WM_SRC_NONE), - wm_have ? wm_prov.sender_node : -1, wm_have ? wm_prov.request_id : 0, - wm_have ? wm_prov.epoch : 0, wm_have ? (uint64)wm_prov.old_scn : 0, - wm_have ? (uint64)wm_prov.new_scn : 0, wm_have ? (int)wm_prov.advanced : -1), + errdetail("request_id=" UINT64_FORMAT " epoch=" UINT64_FORMAT " holder=%d fork=%d" + " expected pi_watermark_scn sent=" UINT64_FORMAT + " master pi_watermark_scn now=" UINT64_FORMAT + " local pd_block_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT + " wm_src=%s wm_sender=%d wm_request_id=" UINT64_FORMAT + " wm_epoch=" UINT64_FORMAT " wm_old=" UINT64_FORMAT + " wm_new=" UINT64_FORMAT " wm_matches_expected=%d.", + request_id, fwd.epoch, holder_node, (int)tag.forkNum, + (uint64)forens_expected_sent, (uint64)forens_master_wm_now, + (uint64)forens_local_scn, forens_own_gen, + wm_prov.table_full ? "none(prov-table-full)" + : cluster_pcm_wm_src_text(wm_prov.source), + wm_have ? wm_prov.sender_node : -1, wm_have ? wm_prov.request_id : 0, + wm_have ? wm_prov.epoch : 0, wm_have ? (uint64)wm_prov.old_scn : 0, + wm_have ? (uint64)wm_prov.new_scn : 0, + wm_have ? (int)(wm_prov.new_scn == forens_expected_sent) : -1), errhint("The holder-forward shipped block.pd_block_scn is below the " "master pi_watermark_scn (or a tracked block shipped an " "unstamped page). Inspect dump_gcs.lost_write_detected_count " "and cluster_pcm_grd to find the stale source. spec-2.41 D5."))); else - ereport( - WARNING, - (errmsg("cluster_gcs_block: lost write detected on tag " - "spc=%u db=%u relNumber=%u block=%u (action=warn)", - tag.spcOid, tag.dbOid, (unsigned int)BufTagGetRelNumber(&tag), - (unsigned int)tag.blockNum), - errdetail( - "request_id=" UINT64_FORMAT " epoch=" UINT64_FORMAT - " holder=%d expected pi_watermark_scn sent=" UINT64_FORMAT - " master pi_watermark_scn now=" UINT64_FORMAT - " local pd_block_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT - " wm_src=%s wm_sender=%d wm_request_id=" UINT64_FORMAT - " wm_epoch=" UINT64_FORMAT " wm_old=" UINT64_FORMAT " wm_new=" UINT64_FORMAT - " wm_advanced=%d.", - request_id, fwd.epoch, holder_node, (uint64)forens_expected_sent, - (uint64)forens_master_wm_now, (uint64)forens_local_scn, forens_own_gen, - cluster_pcm_wm_src_text(wm_have ? wm_prov.source : CLUSTER_PCM_WM_SRC_NONE), - wm_have ? wm_prov.sender_node : -1, wm_have ? wm_prov.request_id : 0, - wm_have ? wm_prov.epoch : 0, wm_have ? (uint64)wm_prov.old_scn : 0, - wm_have ? (uint64)wm_prov.new_scn : 0, wm_have ? (int)wm_prov.advanced : -1))); + ereport(WARNING, + (errmsg("cluster_gcs_block: lost write detected on tag " + "spc=%u db=%u relNumber=%u block=%u (action=warn)", + tag.spcOid, tag.dbOid, (unsigned int)BufTagGetRelNumber(&tag), + (unsigned int)tag.blockNum), + errdetail("request_id=" UINT64_FORMAT " epoch=" UINT64_FORMAT + " holder=%d fork=%d expected pi_watermark_scn sent=" UINT64_FORMAT + " master pi_watermark_scn now=" UINT64_FORMAT + " local pd_block_scn=" UINT64_FORMAT " ownership_gen=" UINT64_FORMAT + " wm_src=%s wm_sender=%d wm_request_id=" UINT64_FORMAT + " wm_epoch=" UINT64_FORMAT " wm_old=" UINT64_FORMAT + " wm_new=" UINT64_FORMAT " wm_matches_expected=%d.", + request_id, fwd.epoch, holder_node, (int)tag.forkNum, + (uint64)forens_expected_sent, (uint64)forens_master_wm_now, + (uint64)forens_local_scn, forens_own_gen, + wm_prov.table_full ? "none(prov-table-full)" + : cluster_pcm_wm_src_text(wm_prov.source), + wm_have ? wm_prov.sender_node : -1, wm_have ? wm_prov.request_id : 0, + wm_have ? wm_prov.epoch : 0, wm_have ? (uint64)wm_prov.old_scn : 0, + wm_have ? (uint64)wm_prov.new_scn : 0, + wm_have ? (int)(wm_prov.new_scn == forens_expected_sent) : -1))); } /* @@ -4676,7 +4692,8 @@ cluster_gcs_handle_block_request_envelope(const ClusterICEnvelope *env, const vo * shipped page's pd_block_scn (local-page source = block_buf). */ cluster_pcm_lock_master_grant_x_to( req->tag, req->sender_node, page_lsn, - (SCN)((PageHeader)block_payload)->pd_block_scn); + (SCN)((PageHeader)block_payload)->pd_block_scn, req->request_id, + req->epoch); /* PGRAC: spec-6.12h D-h2 — if the D-h1 conversion kept our * outgoing copy as a Past Image, record ourselves on the * authoritative PI bitmap (master == self: local note). */ @@ -5133,7 +5150,8 @@ cluster_gcs_handle_block_request_envelope(const ClusterICEnvelope *env, const vo */ if (!requester_is_s_holder && xvs_b2_captured) { cluster_pcm_lock_master_grant_x_to(req->tag, req->sender_node, page_lsn, - (SCN)((PageHeader)block_payload)->pd_block_scn); + (SCN)((PageHeader)block_payload)->pd_block_scn, + req->request_id, req->epoch); (void)cluster_pcm_lock_clear_pending_x_if(req->tag, req->sender_node); pg_atomic_fetch_add_u64(&ClusterGcsBlock->x_vs_s_nonholder_grant_count, 1); status = GCS_BLOCK_REPLY_GRANTED; @@ -5426,10 +5444,12 @@ cluster_gcs_handle_block_request_envelope(const ClusterICEnvelope *env, const vo /* S3 forensics step 1 — the (expected, shipped) verdict SCN pair is * only known on this producer; LOG it so the requester's 53R93 * errdetail correlates by the unambiguous {requester, request_id, - * epoch, tag} 4-tuple. Step 1a: THIS node is the master, so the - * provenance of the LAST advance that produced expected_scn is - * queryable here — the branch-3 (watermark false-positive) - * discriminator. */ + * epoch, tag} 4-tuple (step 1b: epoch is the WIRE request epoch + * req->epoch — the requester correlates by it; a reply-time + * cluster_epoch_get_current() could differ across a reconfig). + * Step 1a/1b: THIS node is the master, so the provenance of the + * advance that produced expected_scn is queryable here — the + * branch-3 (watermark false-positive) discriminator. */ ClusterPcmWmProv wm_prov; bool wm_have = cluster_pcm_lock_pi_watermark_prov_query(req->tag, &wm_prov); @@ -5437,20 +5457,22 @@ cluster_gcs_handle_block_request_envelope(const ClusterICEnvelope *env, const vo LOG, (errmsg_internal( "cluster_gcs_block: lost-write verdict %s on master-direct ship: tag " - "spc=%u db=%u rel=%u block=%u expected pi_watermark_scn=" UINT64_FORMAT + "spc=%u db=%u rel=%u block=%u fork=%d expected pi_watermark_scn=" UINT64_FORMAT " shipped pd_block_scn=" UINT64_FORMAT " requester=%d request_id=" UINT64_FORMAT " epoch=" UINT64_FORMAT " transition=%d wm_src=%s wm_sender=%d wm_request_id=" UINT64_FORMAT " wm_epoch=" UINT64_FORMAT " wm_old=" UINT64_FORMAT " wm_new=" UINT64_FORMAT - " wm_advanced=%d", + " wm_matches_expected=%d", verdict == GCS_LOST_WRITE_FAIL_STALE ? "STALE" : "ANOMALY", req->tag.spcOid, - req->tag.dbOid, req->tag.relNumber, req->tag.blockNum, (uint64)expected_scn, - (uint64)shipped_scn, req->sender_node, req->request_id, - cluster_epoch_get_current(), (int)req->transition_id, - cluster_pcm_wm_src_text(wm_have ? wm_prov.source : CLUSTER_PCM_WM_SRC_NONE), + req->tag.dbOid, req->tag.relNumber, req->tag.blockNum, (int)req->tag.forkNum, + (uint64)expected_scn, (uint64)shipped_scn, req->sender_node, req->request_id, + req->epoch, (int)req->transition_id, + wm_prov.table_full ? "none(prov-table-full)" + : cluster_pcm_wm_src_text(wm_prov.source), wm_have ? wm_prov.sender_node : -1, wm_have ? wm_prov.request_id : 0, wm_have ? wm_prov.epoch : 0, wm_have ? (uint64)wm_prov.old_scn : 0, - wm_have ? (uint64)wm_prov.new_scn : 0, wm_have ? (int)wm_prov.advanced : -1))); + wm_have ? (uint64)wm_prov.new_scn : 0, + wm_have ? (int)(wm_prov.new_scn == expected_scn) : -1))); status = GCS_BLOCK_REPLY_DENIED_LOST_WRITE; page_lsn = InvalidXLogRecPtr; gcs_block_release_ship_image(block_payload_release_cb, block_payload_release_arg); @@ -6456,13 +6478,14 @@ cluster_gcs_handle_block_forward_envelope(const ClusterICEnvelope *env, const vo LOG, (errmsg_internal( "cluster_gcs_block: lost-write verdict %s on holder-forward ship: tag " - "spc=%u db=%u rel=%u block=%u expected pi_watermark_scn=" UINT64_FORMAT + "spc=%u db=%u rel=%u block=%u fork=%d expected pi_watermark_scn=" UINT64_FORMAT " shipped pd_block_scn=" UINT64_FORMAT " holder-local pi_watermark_scn=" UINT64_FORMAT " requester=%d master=%d request_id=" UINT64_FORMAT " epoch=" UINT64_FORMAT, verdict == GCS_LOST_WRITE_FAIL_STALE ? "STALE" : "ANOMALY", fwd->tag.spcOid, - fwd->tag.dbOid, fwd->tag.relNumber, fwd->tag.blockNum, (uint64)expected_scn, - (uint64)shipped_scn, (uint64)cluster_pcm_lock_pi_watermark_scn_query(fwd->tag), + fwd->tag.dbOid, fwd->tag.relNumber, fwd->tag.blockNum, (int)fwd->tag.forkNum, + (uint64)expected_scn, (uint64)shipped_scn, + (uint64)cluster_pcm_lock_pi_watermark_scn_query(fwd->tag), fwd->original_requester_node, fwd->master_node, fwd->request_id, fwd->epoch))); gcs_block_release_ship_image(block_payload_release_cb, block_payload_release_arg); block_payload = NULL; diff --git a/src/backend/cluster/cluster_ges.c b/src/backend/cluster/cluster_ges.c index 853df9616a..aa298b77ad 100644 --- a/src/backend/cluster/cluster_ges.c +++ b/src/backend/cluster/cluster_ges.c @@ -173,6 +173,7 @@ cluster_ges_shmem_init(void) pg_atomic_init_u64(&cluster_ges_state->timeout_send_fail_count, 0); pg_atomic_init_u64(&cluster_ges_state->timeout_retransmit_exhausted_count, 0); pg_atomic_init_u64(&cluster_ges_state->timeout_native_probe_count, 0); + pg_atomic_init_u64(&cluster_ges_state->timeout_master_reject_count, 0); } } @@ -1493,8 +1494,10 @@ cluster_ges_timeout_detail_set(ClusterGesTimeoutSrc src, int32 master_node, long pg_atomic_fetch_add_u64(&cluster_ges_state->timeout_native_probe_count, 1); break; case CLUSTER_GES_TSRC_MASTER_REJECT_TIMEOUT: - /* master-reported timeout: neither a local wait nor a local capacity - * event — visible via the errdetail source text only. */ + /* master-reported timeout (possibly a remote native-probe timeout): + * neither a local wait nor a local capacity event — own bucket so + * the six-way breakdown ledger closes (step 1b). */ + pg_atomic_fetch_add_u64(&cluster_ges_state->timeout_master_reject_count, 1); break; case CLUSTER_GES_TSRC_NONE: case CLUSTER_GES_TSRC_NULL_ARG: @@ -1588,6 +1591,13 @@ cluster_ges_timeout_native_probe_count(void) return pg_atomic_read_u64(&cluster_ges_state->timeout_native_probe_count); } +uint64 +cluster_ges_timeout_master_reject_count(void) +{ + Assert(cluster_ges_state != NULL); + return pg_atomic_read_u64(&cluster_ges_state->timeout_master_reject_count); +} + /* ============================================================ * spec-2.21 D8 — GES request/release send-and-wait stubs. diff --git a/src/backend/cluster/cluster_pcm_lock.c b/src/backend/cluster/cluster_pcm_lock.c index 12553fe880..bfc5f0d4e8 100644 --- a/src/backend/cluster/cluster_pcm_lock.c +++ b/src/backend/cluster/cluster_pcm_lock.c @@ -283,6 +283,26 @@ StaticAssertDecl(sizeof(struct GrdEntry) == 264, * Per-entry locks protect entry-local state after a stable pointer has been * obtained; they do not make concurrent HASH_ENTER_NULL safe by themselves. */ +/* + * S3 forensics step 1b — one advance-provenance slot (64B). Insert-once: + * `used` is never cleared, so open-addressing probe chains stay valid for + * the region's lifetime (mirrors the GRD HTAB's never-freed entries). + */ +#define CLUSTER_PCM_WM_PROV_SLOTS 8192 + +typedef struct ClusterPcmWmProvSlot { + bool used; /* slot claimed (never cleared) */ + uint8 source; /* ClusterPcmWmSrc */ + int16 _pad1; + int32 sender_node; /* -1 = local/unknown */ + BufferTag tag; /* 20B */ + int32 _pad2; + SCN old_scn; /* watermark before the advancing feed */ + SCN new_scn; /* fed page_scn == watermark right after the feed */ + uint64 request_id; /* wire identity (0 = none) */ + uint64 epoch; /* wire epoch (0 = none) */ +} ClusterPcmWmProvSlot; + typedef struct ClusterPcmShared { LWLockPadded htab_lock; pg_atomic_uint64 trans_n_to_s_count; @@ -312,24 +332,22 @@ typedef struct ClusterPcmShared { pg_atomic_uint64 writer_reverify_reacquire_count; pg_atomic_uint64 restore_aba_detected_count; pg_atomic_uint64 invalidate_parked_grant_pending_count; - /* S3 forensics step 1a — SCN-watermark advance provenance ring (see - * cluster_pcm_lock.h ClusterPcmWmProv). Slots are claimed with a - * fetch-add on wm_prov_next; each entry is stamped with its claim seq - * AFTER the payload (write barrier) so a torn wrap-around read is - * detectable. Diagnostic-only: readers tolerate a missed entry. */ - pg_atomic_uint32 wm_prov_next; - struct { - BufferTag tag; /* 20B */ - uint32 seq; /* claim seq + 1 (0 = never written) */ - SCN old_scn; /* watermark before the feed */ - SCN new_scn; /* fed page_scn */ - uint64 request_id; /* wire identity (0 = none) */ - uint64 epoch; /* wire epoch (0 = none) */ - int32 sender_node; /* -1 = local/unknown */ - uint8 source; /* ClusterPcmWmSrc */ - uint8 advanced; /* monotone max actually raised */ - uint16 _pad; - } wm_prov[256]; + /* S3 forensics step 1b — per-tag SCN-watermark advance provenance table + * (see cluster_pcm_lock.h ClusterPcmWmProv). Replaces the step-1a + * 256-slot ring: under S3 fan-out the ring recycled in milliseconds, so + * by the time a 53R93 emitted, the tag's advancing feed was overwritten + * and the query returned an unrelated late feed. Open-addressed, + * insert-once-never-evict; one slot per tag holds the LAST feed that + * actually advanced the monotone-max watermark (non-advancing feeds + * never enter), so new_scn always explains the CURRENT watermark. + * Writers hold the tag's GRD entry_lock and take wm_prov_lock EXCLUSIVE + * around probe+store (entry_lock -> wm_prov_lock, strict leaf); readers + * probe under SHARED. When the table fills, further first-feeds are + * dropped and counted (wm_prov_insert_fail_count) so a query reports + * "absence inconclusive" instead of a false NONE. */ + LWLockPadded wm_prov_lock; + pg_atomic_uint64 wm_prov_insert_fail_count; + ClusterPcmWmProvSlot wm_prov[CLUSTER_PCM_WM_PROV_SLOTS]; } ClusterPcmShared; StaticAssertDecl(sizeof(ClusterPcmShared) >= sizeof(LWLockPadded) + 72, @@ -357,11 +375,11 @@ static int pcm_grd_effective = 0; /* Forward decl — file-private HTAB lazy-alloc helper defined below init_fn. */ static struct GrdEntry *pcm_get_or_create_entry(BufferTag tag); -/* S3 forensics step 1a — watermark-advance provenance recorder (defined with - * the watermark helpers below; used by the inline writer sites above them). */ -static void pcm_wm_prov_record(BufferTag tag, SCN old_scn, SCN new_scn, bool advanced, - ClusterPcmWmSrc source, int32 sender_node, uint64 request_id, - uint64 epoch); +/* S3 forensics step 1b — watermark-advance provenance recorder (defined with + * the watermark helpers below; used by the inline writer sites above them). + * Caller MUST hold the tag's GRD entry_lock and call ONLY on actual advance. */ +static void pcm_wm_prov_record(BufferTag tag, SCN old_scn, SCN new_scn, ClusterPcmWmSrc source, + int32 sender_node, uint64 request_id, uint64 epoch); static struct GrdEntry *pcm_find_entry(BufferTag tag); static void pcm_entry_lock_exclusive(struct GrdEntry *entry); static uint32 pcm_holder_bit(int holder_node_id); @@ -1096,15 +1114,14 @@ cluster_gcs_block_master_rebuild_from_redeclare(BufferTag tag, uint8 held_mode, * node_id-dominated — see cluster_scn.h + gcs_block_lost_write_verdict. */ if (SCN_VALID(page_scn)) { SCN wm_old = entry->pi_watermark_scn; - bool wm_advanced = false; if (scn_local(page_scn) > scn_local(entry->pi_watermark_scn)) { /* SCN_CMP_OK: scn_time_cmp via scn_local */ entry->pi_watermark_scn = page_scn; - wm_advanced = true; + /* step 1b: only an ACTUAL advance is recorded (per-tag table). */ + pcm_wm_prov_record(tag, wm_old, page_scn, CLUSTER_PCM_WM_SRC_REDECLARE, source_node, 0, + cluster_epoch); } - pcm_wm_prov_record(tag, wm_old, page_scn, wm_advanced, CLUSTER_PCM_WM_SRC_REDECLARE, - source_node, 0, cluster_epoch); } LWLockRelease(&entry->entry_lock.lock); @@ -1130,7 +1147,8 @@ cluster_gcs_block_master_rebuild_from_redeclare(BufferTag tag, uint8 held_mode, * Mirrors the X branch of cluster_gcs_block_master_rebuild_from_redeclare. */ void -cluster_pcm_lock_master_take_x_after_transfer(BufferTag tag, XLogRecPtr page_lsn, SCN page_scn) +cluster_pcm_lock_master_take_x_after_transfer(BufferTag tag, XLogRecPtr page_lsn, SCN page_scn, + int32 holder_node, uint64 request_id, uint64 epoch) { struct GrdEntry *entry; @@ -1163,14 +1181,14 @@ cluster_pcm_lock_master_take_x_after_transfer(BufferTag tag, XLogRecPtr page_lsn * node_id-dominated — see cluster_scn.h + gcs_block_lost_write_verdict. */ if (SCN_VALID(page_scn)) { SCN wm_old = entry->pi_watermark_scn; - bool wm_advanced = false; if (scn_local(page_scn) > scn_local(entry->pi_watermark_scn)) { /* SCN_CMP_OK: scn_time_cmp via scn_local */ entry->pi_watermark_scn = page_scn; - wm_advanced = true; + /* step 1b: record the shipping holder's wire identity on advance. */ + pcm_wm_prov_record(tag, wm_old, page_scn, CLUSTER_PCM_WM_SRC_TAKE_X, holder_node, + request_id, epoch); } - pcm_wm_prov_record(tag, wm_old, page_scn, wm_advanced, CLUSTER_PCM_WM_SRC_TAKE_X, -1, 0, 0); } LWLockRelease(&entry->entry_lock.lock); } @@ -1193,7 +1211,7 @@ cluster_pcm_lock_master_take_x_after_transfer(BufferTag tag, XLogRecPtr page_lsn */ void cluster_pcm_lock_master_grant_x_to(BufferTag tag, int32 requester_node, XLogRecPtr page_lsn, - SCN page_scn) + SCN page_scn, uint64 request_id, uint64 epoch) { struct GrdEntry *entry; @@ -1224,15 +1242,14 @@ cluster_pcm_lock_master_grant_x_to(BufferTag tag, int32 requester_node, XLogRecP * node_id-dominated — see cluster_scn.h + gcs_block_lost_write_verdict. */ if (SCN_VALID(page_scn)) { SCN wm_old = entry->pi_watermark_scn; - bool wm_advanced = false; if (scn_local(page_scn) > scn_local(entry->pi_watermark_scn)) { /* SCN_CMP_OK: scn_time_cmp via scn_local */ entry->pi_watermark_scn = page_scn; - wm_advanced = true; + /* step 1b: record the granted requester's wire identity on advance. */ + pcm_wm_prov_record(tag, wm_old, page_scn, CLUSTER_PCM_WM_SRC_GRANT_X, requester_node, + request_id, epoch); } - pcm_wm_prov_record(tag, wm_old, page_scn, wm_advanced, CLUSTER_PCM_WM_SRC_GRANT_X, - requester_node, 0, 0); } LWLockRelease(&entry->entry_lock.lock); } @@ -1301,37 +1318,71 @@ cluster_pcm_lock_pi_watermark_lsn_advance(BufferTag tag, XLogRecPtr page_lsn) } /* - * S3 forensics step 1a — SCN-watermark advance provenance ring. + * S3 forensics step 1b — per-tag SCN-watermark advance provenance table. * - * pcm_wm_prov_record claims a slot with a fetch-add, invalidates it - * (seq=0), writes the payload, then stamps seq+1 behind a write barrier; - * the seq1/payload/seq2 read protocol in prov_query detects a torn - * wrap-around rewrite. Diagnostic-only ring: a missed or overwritten - * record degrades to "no provenance", never to a wrong record. + * pcm_wm_prov_record stores the advancing feed into the tag's single + * insert-once slot (open addressing, linear probe; slots are never + * evicted so probe chains stay valid). The caller holds the tag's GRD + * entry_lock EXCLUSIVE — the advance and its record form one critical + * section, so the slot's new_scn always equals the watermark the feed + * produced (two racing advances cannot store out of order). wm_prov_lock + * is a strict leaf below entry_lock (nothing is acquired under it). + * Table full + unknown tag: drop the record and count — the query then + * reports absence as inconclusive rather than a definite NONE. */ +static uint32 +pcm_wm_prov_hash(const BufferTag *tag) +{ + /* FNV-1a over the tag fields — file-private so the standalone unit + * binaries need no extra hash-library stub. */ + uint32 h = 0x811c9dc5; + +#define PCM_WM_PROV_HASH_MIX(v) \ + do { \ + h ^= (uint32)(v); \ + h *= 0x01000193; \ + } while (0) + PCM_WM_PROV_HASH_MIX(tag->spcOid); + PCM_WM_PROV_HASH_MIX(tag->dbOid); + PCM_WM_PROV_HASH_MIX(tag->relNumber); + PCM_WM_PROV_HASH_MIX(tag->forkNum); + PCM_WM_PROV_HASH_MIX(tag->blockNum); +#undef PCM_WM_PROV_HASH_MIX + return h; +} + static void -pcm_wm_prov_record(BufferTag tag, SCN old_scn, SCN new_scn, bool advanced, ClusterPcmWmSrc source, +pcm_wm_prov_record(BufferTag tag, SCN old_scn, SCN new_scn, ClusterPcmWmSrc source, int32 sender_node, uint64 request_id, uint64 epoch) { - uint32 seq; - uint32 idx; + uint32 start; + uint32 probe; if (ClusterPcm == NULL) return; - seq = pg_atomic_fetch_add_u32(&ClusterPcm->wm_prov_next, 1); - idx = seq % (uint32)lengthof(ClusterPcm->wm_prov); - ClusterPcm->wm_prov[idx].seq = 0; /* invalidate while rewriting */ - pg_write_barrier(); - ClusterPcm->wm_prov[idx].tag = tag; - ClusterPcm->wm_prov[idx].old_scn = old_scn; - ClusterPcm->wm_prov[idx].new_scn = new_scn; - ClusterPcm->wm_prov[idx].request_id = request_id; - ClusterPcm->wm_prov[idx].epoch = epoch; - ClusterPcm->wm_prov[idx].sender_node = sender_node; - ClusterPcm->wm_prov[idx].source = (uint8)source; - ClusterPcm->wm_prov[idx].advanced = advanced ? 1 : 0; - pg_write_barrier(); - ClusterPcm->wm_prov[idx].seq = seq + 1; + start = pcm_wm_prov_hash(&tag) % (uint32)CLUSTER_PCM_WM_PROV_SLOTS; + LWLockAcquire(&ClusterPcm->wm_prov_lock.lock, LW_EXCLUSIVE); + for (probe = 0; probe < (uint32)CLUSTER_PCM_WM_PROV_SLOTS; probe++) { + ClusterPcmWmProvSlot *slot + = &ClusterPcm->wm_prov[(start + probe) % (uint32)CLUSTER_PCM_WM_PROV_SLOTS]; + + if (slot->used && !BufferTagsEqual(&slot->tag, &tag)) + continue; + /* a free slot (first advance for the tag) or the tag's own slot */ + slot->used = true; + slot->tag = tag; + slot->old_scn = old_scn; + slot->new_scn = new_scn; + slot->request_id = request_id; + slot->epoch = epoch; + slot->sender_node = sender_node; + slot->source = (uint8)source; + LWLockRelease(&ClusterPcm->wm_prov_lock.lock); + return; + } + /* table full and the tag has no slot: the advance goes unrecorded */ + pg_atomic_fetch_add_u64(&ClusterPcm->wm_prov_insert_fail_count, 1); + LWLockRelease(&ClusterPcm->wm_prov_lock.lock); } const char * @@ -1354,45 +1405,49 @@ cluster_pcm_wm_src_text(ClusterPcmWmSrc src) return "unknown"; } +/* + * S3 forensics step 1b — query the tag's advance-provenance slot. + * + * Returns true + the record of the LAST advancing feed for the tag. + * Returns false with out->table_full=false for a definite "no advance + * ever recorded", or out->table_full=true when the table has dropped + * inserts (the tag's advance may simply have gone unrecorded). + */ bool cluster_pcm_lock_pi_watermark_prov_query(BufferTag tag, ClusterPcmWmProv *out) { - uint32 best_seq = 0; - bool found = false; - int i; + uint32 start; + uint32 probe; + bool full_seen; if (ClusterPcm == NULL || out == NULL) return false; memset(out, 0, sizeof(*out)); + out->source = CLUSTER_PCM_WM_SRC_NONE; out->sender_node = -1; - for (i = 0; i < (int)lengthof(ClusterPcm->wm_prov); i++) { - uint32 seq1 = ClusterPcm->wm_prov[i].seq; - BufferTag etag; - ClusterPcmWmProv cand; - uint32 seq2; - - if (seq1 == 0) + start = pcm_wm_prov_hash(&tag) % (uint32)CLUSTER_PCM_WM_PROV_SLOTS; + LWLockAcquire(&ClusterPcm->wm_prov_lock.lock, LW_SHARED); + for (probe = 0; probe < (uint32)CLUSTER_PCM_WM_PROV_SLOTS; probe++) { + ClusterPcmWmProvSlot *slot + = &ClusterPcm->wm_prov[(start + probe) % (uint32)CLUSTER_PCM_WM_PROV_SLOTS]; + + if (!slot->used) + break; /* insert-once: an unused slot terminates the probe chain */ + if (!BufferTagsEqual(&slot->tag, &tag)) continue; - pg_read_barrier(); - etag = ClusterPcm->wm_prov[i].tag; - cand.source = (ClusterPcmWmSrc)ClusterPcm->wm_prov[i].source; - cand.sender_node = ClusterPcm->wm_prov[i].sender_node; - cand.request_id = ClusterPcm->wm_prov[i].request_id; - cand.epoch = ClusterPcm->wm_prov[i].epoch; - cand.old_scn = ClusterPcm->wm_prov[i].old_scn; - cand.new_scn = ClusterPcm->wm_prov[i].new_scn; - cand.advanced = ClusterPcm->wm_prov[i].advanced != 0; - pg_read_barrier(); - seq2 = ClusterPcm->wm_prov[i].seq; - if (seq1 != seq2 || !BufferTagsEqual(&etag, &tag)) - continue; - if (seq1 > best_seq) { - best_seq = seq1; - *out = cand; - found = true; - } + out->source = (ClusterPcmWmSrc)slot->source; + out->sender_node = slot->sender_node; + out->request_id = slot->request_id; + out->epoch = slot->epoch; + out->old_scn = slot->old_scn; + out->new_scn = slot->new_scn; + LWLockRelease(&ClusterPcm->wm_prov_lock.lock); + return true; } - return found; + full_seen = pg_atomic_read_u64(&ClusterPcm->wm_prov_insert_fail_count) > 0; + LWLockRelease(&ClusterPcm->wm_prov_lock.lock); + out->table_full = full_seen; + return false; } /* @@ -1401,9 +1456,9 @@ cluster_pcm_lock_pi_watermark_prov_query(BufferTag tag, ClusterPcmWmProv *out) * detector compares a shipped page's pd_block_scn against this (§2.6). Fed * by the local-page sources today; the ack/redeclare wire sources feed it * once D3 carries pd_block_scn on the wire. - * S3 forensics step 1a: every feed records its provenance (source enum + - * wire identity + old->new + advanced?) so a 53R93's expected_scn can be - * traced to the advance that produced it. + * S3 forensics step 1b: every feed that ACTUALLY advances the max records + * its provenance (source enum + wire identity + old->new) into the per-tag + * table so a 53R93's expected_scn traces to the advance that produced it. */ void cluster_pcm_lock_pi_watermark_scn_advance(BufferTag tag, SCN page_scn, ClusterPcmWmSrc source, @@ -1419,7 +1474,6 @@ cluster_pcm_lock_pi_watermark_scn_advance(BufferTag tag, SCN page_scn, ClusterPc entry = (struct GrdEntry *)hash_search(cluster_pcm_htab, &tag, HASH_FIND, &found); if (found && entry != NULL) { SCN wm_old; - bool wm_advanced = false; LWLockAcquire(&entry->entry_lock.lock, LW_EXCLUSIVE); wm_old = entry->pi_watermark_scn; @@ -1428,11 +1482,12 @@ cluster_pcm_lock_pi_watermark_scn_advance(BufferTag tag, SCN page_scn, ClusterPc if (scn_local(page_scn) > scn_local(entry->pi_watermark_scn)) { /* SCN_CMP_OK: scn_time_cmp via scn_local */ entry->pi_watermark_scn = page_scn; - wm_advanced = true; + /* step 1b: record INSIDE the entry_lock critical section so the + * per-tag slot's new_scn always equals the watermark this feed + * produced; non-advancing (late) feeds are never recorded. */ + pcm_wm_prov_record(tag, wm_old, page_scn, source, sender_node, request_id, epoch); } LWLockRelease(&entry->entry_lock.lock); - pcm_wm_prov_record(tag, wm_old, page_scn, wm_advanced, source, sender_node, request_id, - epoch); } LWLockRelease(&ClusterPcm->htab_lock.lock); } @@ -2029,6 +2084,14 @@ cluster_pcm_get_invalidate_parked_grant_pending_count(void) : 0; } +/* S3 forensics step 1b — advance-provenance table insert drops (table full + * with no slot for the tag; absence of a record is then inconclusive). */ +uint64 +cluster_pcm_get_wm_prov_insert_fail_count(void) +{ + return ClusterPcm != NULL ? pg_atomic_read_u64(&ClusterPcm->wm_prov_insert_fail_count) : 0; +} + uint64 cluster_pcm_get_trans_x_to_n_downgrade_count(void) { @@ -3193,9 +3256,10 @@ cluster_pcm_grd_init(void) pg_atomic_init_u64(&ClusterPcm->writer_reverify_reacquire_count, 0); pg_atomic_init_u64(&ClusterPcm->restore_aba_detected_count, 0); pg_atomic_init_u64(&ClusterPcm->invalidate_parked_grant_pending_count, 0); - /* S3 forensics step 1a — provenance ring (entries zeroed by the - * memset above; seq 0 marks never-written slots). */ - pg_atomic_init_u32(&ClusterPcm->wm_prov_next, 0); + /* S3 forensics step 1b — per-tag advance-provenance table (slots + * zeroed by the memset above; used=false marks free slots). */ + LWLockInitialize(&ClusterPcm->wm_prov_lock.lock, LWTRANCHE_CLUSTER_PCM); + pg_atomic_init_u64(&ClusterPcm->wm_prov_insert_fail_count, 0); } /* diff --git a/src/backend/cluster/cluster_undo_record.c b/src/backend/cluster/cluster_undo_record.c index 994597a78f..8fb1b326d7 100644 --- a/src/backend/cluster/cluster_undo_record.c +++ b/src/backend/cluster/cluster_undo_record.c @@ -160,6 +160,7 @@ typedef struct ClusterUndoRecordShared { * errdetail never cites another path's counter. */ pg_atomic_uint64 tt_rollover_fail_hard_cap_count; /* pool at hard cap */ pg_atomic_uint64 tt_rollover_fail_extend_count; /* autoextend / FS fail */ + pg_atomic_uint64 tt_rollover_fail_activate_count; /* mark_active refused (step 1b) */ /* spec-3.18 D3: extent claims (one per ~undo_extent_blocks records per * backend instead of one cursor_lock acquire per record). */ @@ -506,6 +507,7 @@ cluster_undo_record_shmem_init(void) pg_atomic_init_u64(&UndoRecordShared->tt_retention_rollover_count, 0); pg_atomic_init_u64(&UndoRecordShared->tt_rollover_fail_hard_cap_count, 0); pg_atomic_init_u64(&UndoRecordShared->tt_rollover_fail_extend_count, 0); + pg_atomic_init_u64(&UndoRecordShared->tt_rollover_fail_activate_count, 0); pg_atomic_init_u64(&UndoRecordShared->segment_retain_skip_count, 0); pg_atomic_init_u64(&UndoRecordShared->extent_claim_count, 0); /* spec-3.18 D3 */ @@ -2082,6 +2084,10 @@ cluster_undo_tt_rollover_locked(int node_id, uint32 old_segment_id, bool *out_at else pg_atomic_fetch_add_u64(&UndoRecordShared->tt_rollover_fail_extend_count, 1); LWLockRelease(&UndoRecordShared->lifecycle_lock.lock); + /* step 1b: a rollover failure is EXACTLY when RECYCLABLE supply is the + * bottleneck — nudge the cleaner now instead of waiting out its tick + * (lifecycle_lock already released; wakeup is a latch set, lock-free). */ + cluster_undo_cleaner_wakeup(); return 0; } @@ -2092,7 +2098,11 @@ cluster_undo_tt_rollover_locked(int node_id, uint32 old_segment_id, bool *out_at * ACTIVE -> COMMITTED -> RECYCLABLE. */ if (!cluster_undo_segment_mark_active(new_segment_id, owner_instance)) { + /* step 1b: activation refused on a fresh segment — its own bucket (the + * extend/hard-cap split above cannot see this failure). */ + pg_atomic_fetch_add_u64(&UndoRecordShared->tt_rollover_fail_activate_count, 1); LWLockRelease(&UndoRecordShared->lifecycle_lock.lock); + cluster_undo_cleaner_wakeup(); return 0; } @@ -2162,6 +2172,14 @@ cluster_undo_tt_rollover_fail_extend_count(void) return pg_atomic_read_u64(&UndoRecordShared->tt_rollover_fail_extend_count); } +uint64 +cluster_undo_tt_rollover_fail_activate_count(void) +{ + if (UndoRecordShared == NULL) + return 0; + return pg_atomic_read_u64(&UndoRecordShared->tt_rollover_fail_activate_count); +} + uint64 cluster_undo_segment_retain_skip_count(void) { diff --git a/src/include/cluster/cluster_ges.h b/src/include/cluster/cluster_ges.h index 0b113af0ff..44d7f34dde 100644 --- a/src/include/cluster/cluster_ges.h +++ b/src/include/cluster/cluster_ges.h @@ -92,6 +92,11 @@ typedef struct ClusterGesSharedState { pg_atomic_uint64 timeout_send_fail_count; /* outbound ring enqueue failed */ pg_atomic_uint64 timeout_retransmit_exhausted_count; /* retransmit budget burned */ pg_atomic_uint64 timeout_native_probe_count; /* native-lock probe fail-closed */ + /* S3 forensics step 1b — master replied TIMEOUT (its own wait/probe ran + * out remotely); neither a local wait nor a local capacity event, so it + * gets its own ledger bucket: every detail_set with a real source bumps + * EXACTLY one of the six breakdown counters. */ + pg_atomic_uint64 timeout_master_reject_count; /* Future spec-2.14+ adds: GRD shard table, hash routing state, * grant table, convert queue, deadlock graph, etc. */ } ClusterGesSharedState; @@ -140,12 +145,13 @@ extern void cluster_ges_timeout_detail_reset(void); extern const ClusterGesTimeoutDetail *cluster_ges_timeout_detail_get(void); extern const char *cluster_ges_timeout_src_text(ClusterGesTimeoutSrc src); -/* dump_ges observability getters for the five breakdown counters. */ +/* dump_ges observability getters for the six breakdown counters. */ extern uint64 cluster_ges_timeout_true_wait_count(void); extern uint64 cluster_ges_timeout_capacity_count(void); extern uint64 cluster_ges_timeout_send_fail_count(void); extern uint64 cluster_ges_timeout_retransmit_exhausted_count(void); extern uint64 cluster_ges_timeout_native_probe_count(void); +extern uint64 cluster_ges_timeout_master_reject_count(void); /* * Shmem region lifecycle (mirror cluster_scn / cluster_lmon pattern). diff --git a/src/include/cluster/cluster_pcm_lock.h b/src/include/cluster/cluster_pcm_lock.h index 216f18fcfd..e94a985198 100644 --- a/src/include/cluster/cluster_pcm_lock.h +++ b/src/include/cluster/cluster_pcm_lock.h @@ -288,14 +288,19 @@ extern bool cluster_pcm_clean_page_xfer_consume(void); extern void cluster_pcm_lock_unlock_content_buffer(BufferDesc *buf, PcmLockMode mode); extern void cluster_pcm_lock_release_buffer_for_eviction(BufferDesc *buf, PcmLockMode mode); /* PGRAC: spec-5.2 D11 — local master records self as new X holder after a - * writer-transfer (the remote holder shipped + released its X). */ + * writer-transfer (the remote holder shipped + released its X). S3 forensics + * step 1b: the shipping holder + wire request_id/epoch ride along so the + * watermark-advance provenance table records WHO produced the advance. */ extern void cluster_pcm_lock_master_take_x_after_transfer(BufferTag tag, XLogRecPtr page_lsn, - SCN page_scn); + SCN page_scn, int32 holder_node, + uint64 request_id, uint64 epoch); /* PGRAC: spec-5.2 D11 path B — master==holder==self ships its X image to a * remote requester and records the requester as the new X holder (single-phase - * writer-transfer-revoke; caller drops self's copy no-wire before calling). */ + * writer-transfer-revoke; caller drops self's copy no-wire before calling). + * S3 forensics step 1b: request_id/epoch ride along for advance provenance. */ extern void cluster_pcm_lock_master_grant_x_to(BufferTag tag, int32 requester_node, - XLogRecPtr page_lsn, SCN page_scn); + XLogRecPtr page_lsn, SCN page_scn, uint64 request_id, + uint64 epoch); /* * PGRAC: spec-2.35 D3 (HC110) — master_holder lookup for forward routing. @@ -384,6 +389,8 @@ extern void cluster_pcm_note_restore_aba_detected(void); extern uint64 cluster_pcm_get_restore_aba_detected_count(void); extern void cluster_pcm_note_invalidate_parked_grant_pending(void); extern uint64 cluster_pcm_get_invalidate_parked_grant_pending_count(void); +/* S3 forensics step 1b — advance-provenance table insert drops (table full). */ +extern uint64 cluster_pcm_get_wm_prov_insert_fail_count(void); extern uint64 cluster_pcm_get_trans_x_to_n_downgrade_count(void); extern uint64 cluster_pcm_get_trans_x_to_n_release_count(void); extern uint64 cluster_pcm_get_trans_s_to_n_invalidate_count(void); @@ -539,17 +546,21 @@ extern void cluster_pcm_lock_pi_watermark_lsn_advance(BufferTag tag, XLogRecPtr extern XLogRecPtr cluster_pcm_lock_pi_watermark_lsn_query(BufferTag tag); /* - * S3 forensics step 1a — SCN-watermark advance PROVENANCE. + * S3 forensics step 1a/1b — SCN-watermark advance PROVENANCE. * * The lost-write detector's expected_scn is only as trustworthy as the * last advance that produced it: a late / wrong-generation invalidate-ACK * feeding the monotone max would fabricate lost-write verdicts against - * perfectly current pages. Every SCN-watermark feed site therefore - * records {source, sender, request_id, epoch, old->new, advanced?} into a - * small shmem ring; the 53R93 emit sites on the MASTER (the only node - * whose ring is authoritative for its tags) attach the latest record so a - * shippednew} into a per-tag shmem table (step 1b: one insert-once slot per + * tag holding the LAST advancing feed — non-advancing late feeds never + * enter, so the record always explains the CURRENT watermark; the step-1a + * ring recycled under load and could return an unrelated late feed). The + * 53R93 emit sites on the MASTER (the only node whose table is + * authoritative for its tags) attach the record so a shippedsafe_psql( 'postgres', q{SELECT count(*) FROM pg_cluster_state WHERE category='pcm'}), - '27', - 'L1 pg_cluster_state.pcm category has 27 keys (spec-2.30 surface + spec-6.14a D5 + spec-6.14 D5 + spec-4.6a D12 + ownership-gen wave 4: writer_cover_stale_detected + writer_reverify_reacquire + restore_aba_detected + invalidate_parked_grant_pending)'); + '28', + 'L1 pg_cluster_state.pcm category has 28 keys (spec-2.30 surface + spec-6.14a D5 + spec-6.14 D5 + spec-4.6a D12 + ownership-gen wave 4: writer_cover_stale_detected + writer_reverify_reacquire + restore_aba_detected + invalidate_parked_grant_pending + S3-forensics wm_prov_insert_fail_count)'); # ---------- @@ -163,8 +163,8 @@ is($node->safe_psql( 'postgres', 'SELECT count(*) FROM pg_stat_cluster_injections'), - '173', - 'L6a pg_stat_cluster_injections has 173 entries (gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; D5 lane 漏更本文件含 spec-5.22d D4-8 +1 + spec-5.22e D5-7 +2; spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 lms data-dispatch/conn-reset; spec-6.14 D5+D8 +3; spec-5.6a +1; spec-5.13 +6 cluster-clean-leave-* + Hardening v1.0.3 +1 suppress-preflight-ack) (spec-5.2a +1 clean-xfer stale-holder; spec-4.8ab +2 undo boundary guards; spec-5.7 +1 cluster-ko-peer-skip-ack; spec-2.41 +1 cluster-gcs-block-stale-ship; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); + '181', + 'L6a pg_stat_cluster_injections has 181 entries (stale-baseline catch-up, t/017-family: ownership-gen wave +6 cluster-pcm-*; +1 earlier-wave undercount; S3 forensics step 1a +1 cluster-ges-master-work-queue-full) (gcs-race-round4c +2 cluster-gcs-block-fallback-refresh-stale + cluster-gcs-block-yield-notify-drop; gcs-race-fix-2 +1 cluster-gcs-block-done-drop; gcs-race-fix +1 cluster-gcs-block-duplicate-grant-reply; spec-5.22d Hardening +1 cluster-undo-authority-scan; D5 lane 漏更本文件含 spec-5.22d D4-8 +1 + spec-5.22e D5-7 +2; spec-7.3 review P1-1 +1 cluster-lms-cr-fence-recheck; spec-7.1 D3-a +1 cluster-mxid-halfspace-hard-limit; spec-7.3 D7 +1 cluster-lms-cr-fence-refuse; spec-7.2 D6 +2 lms data-dispatch/conn-reset; spec-6.14 D5+D8 +3; spec-5.6a +1; spec-5.13 +6 cluster-clean-leave-* + Hardening v1.0.3 +1 suppress-preflight-ack) (spec-5.2a +1 clean-xfer stale-holder; spec-4.8ab +2 undo boundary guards; spec-5.7 +1 cluster-ko-peer-skip-ack; spec-2.41 +1 cluster-gcs-block-stale-ship; spec-5.55 Hardening v1.1 +1 cluster-cr-resolver-memo-suspect; spec-5.15 Hardening v1.1 +1 cluster-reconfig-join-commit-marker-durable; spec-2.29a +1 cluster-qvotec-marker-service-hold)'); is($node->safe_psql( 'postgres', diff --git a/src/test/cluster_tap/t/108_pcm_state_machine.pl b/src/test/cluster_tap/t/108_pcm_state_machine.pl index 0332357db1..8a68afef21 100644 --- a/src/test/cluster_tap/t/108_pcm_state_machine.pl +++ b/src/test/cluster_tap/t/108_pcm_state_machine.pl @@ -48,8 +48,8 @@ my $pcm_category_rows = $node_default->safe_psql( 'postgres', "SELECT count(*) FROM pg_cluster_state WHERE category = 'pcm'"); -is($pcm_category_rows, '27', - 'L1 pg_cluster_state pcm category has 27 rows (spec-2.30 D9 surface + spec-6.14a D5 + spec-6.14 D5 KO-aux-defer counter + spec-4.6a D12 dead_cleanup_entries + ownership-gen wave 4: writer_cover_stale_detected + writer_reverify_reacquire + restore_aba_detected + invalidate_parked_grant_pending)'); +is($pcm_category_rows, '28', + 'L1 pg_cluster_state pcm category has 28 rows (spec-2.30 D9 surface + spec-6.14a D5 + spec-6.14 D5 KO-aux-defer counter + spec-4.6a D12 dead_cleanup_entries + ownership-gen wave 4: writer_cover_stale_detected + writer_reverify_reacquire + restore_aba_detected + invalidate_parked_grant_pending + S3-forensics wm_prov_insert_fail_count)'); # L3 — api_state shows "active" when GUC=-1 default my $api_state_default = $node_default->safe_psql( diff --git a/src/test/cluster_tap/t/214_cluster_3_8_undo_lifecycle.pl b/src/test/cluster_tap/t/214_cluster_3_8_undo_lifecycle.pl index a0af9e302e..51a1674f88 100644 --- a/src/test/cluster_tap/t/214_cluster_3_8_undo_lifecycle.pl +++ b/src/test/cluster_tap/t/214_cluster_3_8_undo_lifecycle.pl @@ -87,8 +87,8 @@ # ---------- my $undo_row_count = $node0->safe_psql('postgres', q{SELECT count(*) FROM pg_cluster_state WHERE category='undo'}); -is($undo_row_count, '70', - "L2 undo category has 70 rows (5 record + 4 lifecycle + 3 fsync + 4 smgr + 5 durable-tt + 5 retention + 9 terminal-authority [spec-6.2] + 6 cleaner + 4 buf/extent obs [spec-3.18 D7] + 1 spec-3.22 retention_off_recycle + 4 checkpoint-writeback boundary [spec-4.8ab D7] + 2 record-segment reclaim [spec-4.12a D5] + 1 residual-revalidate-drop [spec-4.12a Hardening v1.0.1] + 1 retention_max_recycle_horizon [spec-6.15 D4] + 6 undo GCS grant-plane [spec-5.22b D2-6] + 8 horizon brake observability [spec-5.22e D5-5, D5 lane 漏更 t/214] + 2 TT-rollover failure split [S3 forensics step 1a])" +is($undo_row_count, '71', + "L2 undo category has 71 rows (5 record + 4 lifecycle + 3 fsync + 4 smgr + 5 durable-tt + 5 retention + 9 terminal-authority [spec-6.2] + 6 cleaner + 4 buf/extent obs [spec-3.18 D7] + 1 spec-3.22 retention_off_recycle + 4 checkpoint-writeback boundary [spec-4.8ab D7] + 2 record-segment reclaim [spec-4.12a D5] + 1 residual-revalidate-drop [spec-4.12a Hardening v1.0.1] + 1 retention_max_recycle_horizon [spec-6.15 D4] + 6 undo GCS grant-plane [spec-5.22b D2-6] + 8 horizon brake observability [spec-5.22e D5-5, D5 lane 漏更 t/214] + 3 TT-rollover failure split [S3 forensics step 1a/1b])" ); diff --git a/src/test/cluster_tap/t/286_ul_advisory.pl b/src/test/cluster_tap/t/286_ul_advisory.pl index 8e56c7dac4..9c13a6921c 100644 --- a/src/test/cluster_tap/t/286_ul_advisory.pl +++ b/src/test/cluster_tap/t/286_ul_advisory.pl @@ -360,10 +360,12 @@ sub blocking_grant_after_release # node1 blocks on the held key with a short finite per-session timeout; the wait # must resolve (53R70) rather than hang -- this is the bound that protects a # cross-node deadlock from hanging forever (real detection is forward spec-5.8). +my $t11_start = Time::HiRes::time(); my ($rc11, $out11, $err11) = $n1->psql( 'postgres', "SET cluster.ges_request_timeout_ms = '3s'; SELECT pg_advisory_lock(73)", timeout => 40); +my $client11_ms = int((Time::HiRes::time() - $t11_start) * 1000); isnt($rc11, 0, 'L11: blocking advisory acquire on a held key fails (does not hang)'); like($err11, qr/cluster lock acquire timeout|53R70|not available/i, 'L11: ... with a finite-timeout 53R70 (bounded deadlock resolution)'); @@ -381,9 +383,17 @@ sub blocking_grant_after_release if ($err11 =~ /elapsed_ms=(\d+)/) { my $elapsed = $1; - cmp_ok($elapsed, '>=', 1000, - "L11b2: errdetail elapsed_ms=$elapsed is true wall-clock (>= 1s of the 3s window)"); - cmp_ok($elapsed, '<=', 40_000, 'L11b3: ... and bounded by the psql timeout'); + + # S3 forensics step 1b — qualify elapsed_ms against the CLIENT-observed + # wall clock instead of hardcoded bounds. client - elapsed >= 0 catches + # a filled-in configured value (a hardcoded 3000 fails on the retransmit + # path where the client only saw ~1.7s); the <= 1500 slack catches a + # stale/zero fill (psql spawn + SET + connect overhead stay well under + # 1.5s), so elapsed_ms must genuinely track this wait's wall clock. + cmp_ok($client11_ms - $elapsed, '>=', 0, + "L11b2: elapsed_ms=$elapsed never exceeds the client wall clock (client=${client11_ms}ms)"); + cmp_ok($client11_ms - $elapsed, '<=', 1500, + "L11b3: elapsed_ms=$elapsed tracks the client wall clock (client=${client11_ms}ms)"); } else { @@ -447,15 +457,19 @@ sub blocking_grant_after_release WHERE category = 'ges' AND key = 'ges_timeout_capacity_count'}; my $cap_before = $n0->safe_psql('postgres', $cap_query); my $mr_err = ''; +my $mr_client_ms = 0; for my $k (211 .. 226) { + my $t0 = Time::HiRes::time(); my ($rc, $out, $err) = $n0->psql( 'postgres', "SET cluster.ges_request_timeout_ms = '3s'; SELECT pg_advisory_lock($k)", timeout => 30); + my $probe_ms = int((Time::HiRes::time() - $t0) * 1000); if ($rc != 0 && defined $err && $err =~ /master-reject-queue-full/) { $mr_err = $err; + $mr_client_ms = $probe_ms; last; } # Locally-mastered key (granted): release and probe the next key. @@ -471,12 +485,17 @@ sub blocking_grant_after_release 'L14c: ... with the master-reject attribution (never unattributed)'); if ($mr_err =~ /elapsed_ms=(\d+)/) { - cmp_ok($1, '<', 3000, - "L14d: errdetail elapsed_ms=$1 shows the reject never consumed the 3s window"); + # step 1b: an immediate reject reads near-zero on ITS OWN clock — and can + # never exceed the client-observed wall time for the same statement. + cmp_ok($1, '<=', 500, + "L14d: errdetail elapsed_ms=$1 shows the reject was immediate"); + cmp_ok($1, '<=', $mr_client_ms, + "L14d2: elapsed_ms=$1 within the client wall clock (client=${mr_client_ms}ms)"); } else { fail('L14d: errdetail carries elapsed_ms'); + fail('L14d2: errdetail carries elapsed_ms'); } my $cap_after = $n0->safe_psql('postgres', $cap_query); cmp_ok($cap_after, '>', $cap_before, diff --git a/src/test/cluster_unit/test_cluster_bufmgr_pcm_hook.c b/src/test/cluster_unit/test_cluster_bufmgr_pcm_hook.c index d6dea9b52f..24ca2b2573 100644 --- a/src/test/cluster_unit/test_cluster_bufmgr_pcm_hook.c +++ b/src/test/cluster_unit/test_cluster_bufmgr_pcm_hook.c @@ -143,9 +143,10 @@ uint32 *my_wait_event_info = &ut_wait_event_info_storage; static union { uint64 force_align; - /* Sized above sizeof(ClusterPcmShared): the S3-forensics watermark - * provenance ring (256 x 64B) grew the header past the old 4096. */ - char data[32768]; + /* Sized above sizeof(ClusterPcmShared): the S3-forensics step-1b + * per-tag watermark provenance table (8192 x 64B slots + lock) grew + * the header past 512KB; the fake ShmemInitStruct asserts fit. */ + char data[1048576]; } fake_pcm_header; static union { diff --git a/src/test/cluster_unit/test_cluster_debug.c b/src/test/cluster_unit/test_cluster_debug.c index 21b605b2c4..73f80b2ba6 100644 --- a/src/test/cluster_unit/test_cluster_debug.c +++ b/src/test/cluster_unit/test_cluster_debug.c @@ -1408,6 +1408,11 @@ cluster_pcm_get_invalidate_parked_grant_pending_count(void) { return 0; } +uint64 +cluster_pcm_get_wm_prov_insert_fail_count(void) +{ + return 0; +} /* spec-6.14 D10b catalog counters (cluster_catalog_stats.o not linked) */ uint64 cluster_catalog_stats_vis_resolve_count(void) @@ -2869,6 +2874,11 @@ cluster_undo_tt_rollover_fail_extend_count(void) { return 0; } +uint64 +cluster_undo_tt_rollover_fail_activate_count(void) +{ + return 0; +} Size cluster_shmem_get_total_bytes(void) @@ -3688,6 +3698,11 @@ cluster_ges_timeout_native_probe_count(void) { return 0; } +uint64 +cluster_ges_timeout_master_reject_count(void) +{ + return 0; +} /* spec-2.14 D12 / L104 stubs: cluster_debug dump_grd references 7 new * spec-2.14 cluster_grd module accessors; test_cluster_debug standalone diff --git a/src/test/cluster_unit/test_cluster_pcm_lock.c b/src/test/cluster_unit/test_cluster_pcm_lock.c index 5900d82a3c..527e8a4f33 100644 --- a/src/test/cluster_unit/test_cluster_pcm_lock.c +++ b/src/test/cluster_unit/test_cluster_pcm_lock.c @@ -84,9 +84,10 @@ uint32 *my_wait_event_info = &ut_wait_event_info_storage; static union { uint64 force_align; - /* Sized above sizeof(ClusterPcmShared): the S3-forensics watermark - * provenance ring (256 x 64B) grew the header past the old 4096. */ - char data[32768]; + /* Sized above sizeof(ClusterPcmShared): the S3-forensics step-1b + * per-tag watermark provenance table (8192 x 64B slots + lock) grew + * the header past 512KB; the fake ShmemInitStruct asserts fit. */ + char data[1048576]; } fake_pcm_header; static union { @@ -1351,18 +1352,21 @@ UT_TEST(test_pcm_d3_not_double_x) * unchanged — the branch-3 (watermark false-positive) discriminator a * 53R93 emit site attaches to its errdetail / LOG line. */ -UT_TEST(test_pcm_wm_prov_ring_records_advance) +UT_TEST(test_pcm_wm_prov_table_keeps_last_advance) { BufferTag tag = make_tag(95); + BufferTag other = make_tag(96); ClusterPcmWmProv prov; reset_fake_pcm_runtime(4); fake_cssd_dead_node = -1; - /* No feed yet — no provenance for the tag. */ + /* No feed yet — a definite NONE (no insert has ever been dropped). */ UT_ASSERT(!cluster_pcm_lock_pi_watermark_prov_query(tag, &prov)); + UT_ASSERT_EQ((long)prov.source, (long)CLUSTER_PCM_WM_SRC_NONE); + UT_ASSERT(!prov.table_full); - /* Redeclare feed (real inline writer path): advanced, sender + epoch. */ + /* Redeclare feed (real inline writer path): advancing feed recorded. */ cluster_gcs_block_master_rebuild_from_redeclare(tag, (uint8)PCM_STATE_S, (XLogRecPtr)0x1000, (SCN)0x2000, 2, 7); UT_ASSERT(cluster_pcm_lock_pi_watermark_prov_query(tag, &prov)); @@ -1370,9 +1374,9 @@ UT_TEST(test_pcm_wm_prov_ring_records_advance) UT_ASSERT_EQ((long)prov.sender_node, 2L); UT_ASSERT_EQ((long)prov.epoch, 7L); UT_ASSERT_EQ((long)prov.new_scn, 0x2000L); - UT_ASSERT(prov.advanced); - /* ACK feed through the advance API: full wire identity recorded. */ + /* ACK feed advances further: the tag's single slot is updated in place + * with the new advance's full wire identity. */ cluster_pcm_lock_pi_watermark_scn_advance(tag, (SCN)0x3000, CLUSTER_PCM_WM_SRC_ACK_SLOT, 3, 4242, 9); UT_ASSERT(cluster_pcm_lock_pi_watermark_prov_query(tag, &prov)); @@ -1381,19 +1385,30 @@ UT_TEST(test_pcm_wm_prov_ring_records_advance) UT_ASSERT_EQ((long)prov.request_id, 4242L); UT_ASSERT_EQ((long)prov.epoch, 9L); UT_ASSERT_EQ((long)prov.old_scn, 0x2000L); - UT_ASSERT(prov.advanced); + UT_ASSERT_EQ((long)prov.new_scn, 0x3000L); UT_ASSERT_EQ((uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), (uint64)0x3000); - /* A LATE / stale feed is recorded but must NOT advance: the record keeps - * the feed's identity with advanced=false and the watermark holds. */ + /* A LATE / stale feed must NOT enter the table (step 1b): the query + * still returns the ACK_SLOT advance that produced the CURRENT + * watermark, and its new_scn equals that watermark. */ cluster_pcm_lock_pi_watermark_scn_advance(tag, (SCN)0x100, CLUSTER_PCM_WM_SRC_ACK_SLOTLESS, 1, 4243, 5); UT_ASSERT(cluster_pcm_lock_pi_watermark_prov_query(tag, &prov)); - UT_ASSERT_EQ((long)prov.source, (long)CLUSTER_PCM_WM_SRC_ACK_SLOTLESS); - UT_ASSERT_EQ((long)prov.sender_node, 1L); - UT_ASSERT_EQ((long)prov.new_scn, 0x100L); - UT_ASSERT(!prov.advanced); + UT_ASSERT_EQ((long)prov.source, (long)CLUSTER_PCM_WM_SRC_ACK_SLOT); + UT_ASSERT_EQ((long)prov.sender_node, 3L); + UT_ASSERT_EQ((long)prov.request_id, 4242L); + UT_ASSERT_EQ((long)prov.new_scn, 0x3000L); UT_ASSERT_EQ((uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), (uint64)0x3000); + UT_ASSERT_EQ((uint64)prov.new_scn, (uint64)cluster_pcm_lock_pi_watermark_scn_query(tag)); + + /* A second tag gets its own slot (open addressing, insert-once). */ + cluster_gcs_block_master_rebuild_from_redeclare(other, (uint8)PCM_STATE_S, (XLogRecPtr)0x1000, + (SCN)0x5000, 1, 7); + UT_ASSERT(cluster_pcm_lock_pi_watermark_prov_query(other, &prov)); + UT_ASSERT_EQ((long)prov.source, (long)CLUSTER_PCM_WM_SRC_REDECLARE); + UT_ASSERT_EQ((long)prov.new_scn, 0x5000L); + UT_ASSERT(cluster_pcm_lock_pi_watermark_prov_query(tag, &prov)); + UT_ASSERT_EQ((long)prov.new_scn, 0x3000L); } UT_TEST(test_pcm_acquire_buffer_local_s_nonholder_registers_s_then_upgrades) @@ -1552,7 +1567,7 @@ main(void) UT_RUN(test_pcm_d1_recovering_gate_fail_closed); UT_RUN(test_pcm_d2_rebuild_from_redeclare); UT_RUN(test_pcm_d3_not_double_x); - UT_RUN(test_pcm_wm_prov_ring_records_advance); + UT_RUN(test_pcm_wm_prov_table_keeps_last_advance); UT_RUN(test_pcm_acquire_buffer_local_s_nonholder_registers_s_then_upgrades); UT_RUN(test_pcm_dead_node_cleanup_drops_holder_records); UT_RUN(test_clean_page_xfer_arm_is_one_shot);