diff --git a/src/backend/cluster/cluster_debug.c b/src/backend/cluster/cluster_debug.c index 745b40e74d..b9f85d0471 100644 --- a/src/backend/cluster/cluster_debug.c +++ b/src/backend/cluster/cluster_debug.c @@ -1743,6 +1743,21 @@ 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())); + emit_row(rsinfo, "ges", "ges_timeout_master_reject_count", + fmt_int64((int64)cluster_ges_timeout_master_reject_count())); } @@ -1958,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())); } @@ -2794,6 +2813,13 @@ 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())); + 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 6b6db665d0..2bd5e647b4 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,67 @@ 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))); + { + /* 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("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("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))); + } } @@ -2197,17 +2247,39 @@ 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 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)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." + "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 +2290,19 @@ 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 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)tag.forkNum, (int)transition_id, retry_attempt, + (uint64)forens_local_scn, (uint64)forens_local_wm, + forens_own_gen))); granted_storage_fallback = true; } break; @@ -3356,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), @@ -3466,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. */ @@ -3532,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); @@ -3584,22 +3671,72 @@ 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); + /* 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(ERROR, - (errcode(ERRCODE_CLUSTER_LOST_WRITE_DETECTED), - errmsg("cluster_gcs_block: lost write detected on tag " - "spc=%u db=%u relNumber=%u block=%u", + 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 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), - 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 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))); } /* @@ -4555,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). */ @@ -5012,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; @@ -5302,6 +5441,38 @@ 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 the unambiguous {requester, request_id, + * 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); + + ereport( + LOG, + (errmsg_internal( + "cluster_gcs_block: lost-write verdict %s on master-direct ship: tag " + "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_matches_expected=%d", + verdict == GCS_LOST_WRITE_FAIL_STALE ? "STALE" : "ANOMALY", req->tag.spcOid, + 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.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); @@ -6297,6 +6468,25 @@ 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 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, (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; block_payload_lkey = 0; @@ -7968,7 +8158,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); } } @@ -8027,7 +8219,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 f68e407239..aa298b77ad 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 */ @@ -166,6 +167,13 @@ 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); + pg_atomic_init_u64(&cluster_ges_state->timeout_master_reject_count, 0); } } @@ -758,8 +766,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(); @@ -1438,6 +1450,155 @@ 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: + 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: + 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_MASTER_REJECT_TIMEOUT: + /* 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: + 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; +} + +/* 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) +{ + 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"; + 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"; +} + +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); +} + +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. * @@ -1547,12 +1708,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, + ges_forens_elapsed_ms(forens_start), 0, -1, timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -1627,6 +1792,9 @@ 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, + ges_forens_elapsed_ms(forens_start), 0, n_conflict, + timeout_ms); return GES_REJECT_REASON_WORK_QUEUE_FULL; } @@ -1656,7 +1824,10 @@ 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, + ges_forens_elapsed_ms(forens_start), 0, n_conflict, + perpetual ? -1 : effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; /* fail closed */ } @@ -1738,16 +1909,31 @@ 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, + ges_forens_elapsed_ms(forens_start), 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; 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; } @@ -1795,6 +1981,9 @@ 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, + ges_forens_elapsed_ms(forens_start), 0, -1, + effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -1822,6 +2011,9 @@ 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, + ges_forens_elapsed_ms(forens_start), 0, -1, + effective_timeout_ms); return GES_REJECT_REASON_WORK_QUEUE_FULL; } @@ -1903,6 +2095,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, + ges_forens_elapsed_ms(forens_start), attempt, -1, + effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } remaining_ms = (long)((deadline - now) / 1000); @@ -1932,6 +2127,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_RETRANSMIT_EXHAUSTED, master, + ges_forens_elapsed_ms(forens_start), attempt, -1, + effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -1968,6 +2166,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, + ges_forens_elapsed_ms(forens_start), attempt, -1, + effective_timeout_ms); return GES_REJECT_REASON_WORK_QUEUE_FULL; } if (cluster_ges_state != NULL) @@ -1984,6 +2185,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; } @@ -2257,12 +2471,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, + ges_forens_elapsed_ms(forens_start), 0, -1, timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -2283,6 +2501,9 @@ 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, + ges_forens_elapsed_ms(forens_start), 0, -1, + effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } } @@ -2297,6 +2518,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, + ges_forens_elapsed_ms(forens_start), 0, -1, effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } @@ -2323,12 +2547,18 @@ 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, + 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, + ges_forens_elapsed_ms(forens_start), 0, -1, + effective_timeout_ms); return GES_REJECT_REASON_WORK_QUEUE_FULL; } } @@ -2379,6 +2609,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, + ges_forens_elapsed_ms(forens_start), 0, -1, effective_timeout_ms); return GES_REJECT_REASON_TIMEOUT; } remaining_ms = (long)((deadline - now) / 1000); @@ -2393,6 +2626,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_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_pcm_lock.c b/src/backend/cluster/cluster_pcm_lock.c index c55ca14119..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,6 +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 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, @@ -339,6 +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 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); @@ -1000,7 +1041,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 +1112,17 @@ 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; + + 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; + /* 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); + } + } LWLockRelease(&entry->entry_lock.lock); return true; /* holder recorded */ @@ -1098,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; @@ -1129,10 +1179,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; + + 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; + /* 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); + } + } LWLockRelease(&entry->entry_lock.lock); } @@ -1154,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; @@ -1183,10 +1240,17 @@ 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; + + 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; + /* 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); + } + } LWLockRelease(&entry->entry_lock.lock); } @@ -1253,15 +1317,152 @@ cluster_pcm_lock_pi_watermark_lsn_advance(BufferTag tag, XLogRecPtr page_lsn) LWLockRelease(&ClusterPcm->htab_lock.lock); } +/* + * S3 forensics step 1b — per-tag SCN-watermark advance provenance table. + * + * 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, ClusterPcmWmSrc source, + int32 sender_node, uint64 request_id, uint64 epoch) +{ + uint32 start; + uint32 probe; + + if (ClusterPcm == NULL) + return; + 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 * +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"; +} + +/* + * 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 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; + 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; + 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; + } + 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; +} + /* * 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 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) +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,12 +1473,20 @@ 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; + 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; + /* 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); } LWLockRelease(&ClusterPcm->htab_lock.lock); @@ -1875,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) { @@ -3039,6 +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 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_tt_local.c b/src/backend/cluster/cluster_tt_local.c index c5c281ecb8..c3fbd7324c 100644 --- a/src/backend/cluster/cluster_tt_local.c +++ b/src/backend/cluster/cluster_tt_local.c @@ -43,14 +43,17 @@ #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" +#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" #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 */ @@ -253,12 +256,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 @@ -270,16 +280,54 @@ 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) - 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."))); + 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), + 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 + " 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(), + 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_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_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..8fb1b326d7 100644 --- a/src/backend/cluster/cluster_undo_record.c +++ b/src/backend/cluster/cluster_undo_record.c @@ -153,6 +153,15 @@ 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 */ + 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). */ pg_atomic_uint64 extent_claim_count; @@ -496,6 +505,9 @@ 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->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 */ @@ -2065,7 +2077,17 @@ 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); + /* 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; } @@ -2076,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; } @@ -2129,6 +2155,31 @@ 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_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/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..44d7f34dde 100644 --- a/src/include/cluster/cluster_ges.h +++ b/src/include/cluster/cluster_ges.h @@ -83,10 +83,76 @@ 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 */ + /* 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; +/* + * 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 */ + 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 { + 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 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 0180686322..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); @@ -537,7 +544,50 @@ 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/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 that ACTUALLY + * advances the monotone max records {source, sender, request_id, epoch, + * old->new} 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', '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 c0cd50491f..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'}), - '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)'); + '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'}), - '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)'); + '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/024_pcm_lock.pl b/src/test/cluster_tap/t/024_pcm_lock.pl index 5851fef96f..246d9bd3d8 100644 --- a/src/test/cluster_tap/t/024_pcm_lock.pl +++ b/src/test/cluster_tap/t/024_pcm_lock.pl @@ -62,8 +62,8 @@ is($node->safe_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/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/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/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..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, '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, '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 6ae535bbd0..9c13a6921c 100644 --- a/src/test/cluster_tap/t/286_ul_advisory.pl +++ b/src/test/cluster_tap/t/286_ul_advisory.pl @@ -347,16 +347,64 @@ 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). +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)'); + +# 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'); +if ($err11 =~ /elapsed_ms=(\d+)/) +{ + my $elapsed = $1; + + # 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 +{ + 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; @@ -390,5 +438,68 @@ 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 = ''; +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. + $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+)/) +{ + # 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, + "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..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,7 +143,10 @@ 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 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 14fe72bb65..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) @@ -2858,6 +2863,23 @@ 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; +} +uint64 +cluster_undo_tt_rollover_fail_activate_count(void) +{ + return 0; +} + Size cluster_shmem_get_total_bytes(void) { @@ -3645,6 +3667,43 @@ 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; +} +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 * binary doesn't link cluster_grd.o, vacuous stubs. */ 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(), 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 diff --git a/src/test/cluster_unit/test_cluster_pcm_lock.c b/src/test/cluster_unit/test_cluster_pcm_lock.c index f93e9b8da3..527e8a4f33 100644 --- a/src/test/cluster_unit/test_cluster_pcm_lock.c +++ b/src/test/cluster_unit/test_cluster_pcm_lock.c @@ -84,7 +84,10 @@ 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 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 { @@ -1341,6 +1344,73 @@ 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_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 — 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): 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)); + 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); + + /* 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)); + 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_EQ((long)prov.new_scn, 0x3000L); + UT_ASSERT_EQ((uint64)cluster_pcm_lock_pi_watermark_scn_query(tag), (uint64)0x3000); + + /* 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_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) { BufferTag tag = make_tag(96); @@ -1458,7 +1528,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 +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_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);