src/backend/access/transam/xlog.c | 3 ++ src/backend/postmaster/pgstat.c | 31 +++++++++++++++ src/backend/storage/ipc/procsignal.c | 36 ++++++++++++++++++ src/backend/storage/ipc/standby.c | 73 ++++++++++++++++++++++++++++++++++++ src/backend/tcop/postgres.c | 56 +++++++++++++++++++++++++++ src/include/access/xlog.h | 1 + src/include/pgstat.h | 1 + src/include/storage/procsignal.h | 1 + 8 files changed, 202 insertions(+) diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index 55cac186dc..d3f923f951 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -880,6 +880,8 @@ static bool holdingAllLocks = false; #ifdef WAL_DEBUG static MemoryContext walDebugCxt = NULL; #endif +/* For LogBlockedWalRecordInfo */ +XLogReaderState *current_replayed_xlog = NULL; static void readRecoverySignalFile(void); static void validateRecoveryParameters(void); @@ -7319,6 +7321,7 @@ StartupXLOG(void) TransactionIdIsValid(record->xl_xid)) RecordKnownAssignedTransactionIds(record->xl_xid); + current_replayed_xlog = xlogreader; /* Now apply the WAL record itself */ RmgrTable[record->xl_rmid].rm_redo(xlogreader); diff --git a/src/backend/postmaster/pgstat.c b/src/backend/postmaster/pgstat.c index 309378ae54..513c9cd643 100644 --- a/src/backend/postmaster/pgstat.c +++ b/src/backend/postmaster/pgstat.c @@ -6633,6 +6633,37 @@ pgstat_db_requested(Oid databaseid) return false; } +/* ---------- + * pgstat_get_state_name() - + * + * Return a string representing the current backend state. + * ---------- + */ +const char * +pgstat_get_state_name(BackendState backend_state) +{ + switch (backend_state) + { + case STATE_IDLE: + return "idle"; + case STATE_RUNNING: + return "active"; + case STATE_IDLEINTRANSACTION: + return "idle in transaction"; + case STATE_FASTPATH: + return "fastpath function call"; + case STATE_IDLEINTRANSACTION_ABORTED: + return "idle in transaction (aborted)"; + case STATE_DISABLED: + return "disabled"; + case STATE_UNDEFINED: + return ""; + default: + Assert(0); + } + return ""; +} + /* * Convert a potentially unsafely truncated activity string (see * PgBackendStatus.st_activity_raw's documentation) into a correctly truncated diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c index c809196d06..2d5886ff80 100644 --- a/src/backend/storage/ipc/procsignal.c +++ b/src/backend/storage/ipc/procsignal.c @@ -576,3 +576,39 @@ procsignal_sigusr1_handler(SIGNAL_ARGS) errno = save_errno; } + +extern const char *get_procsignal_reason_desc(ProcSignalReason reason) + { + const char *reasonDesc = "unknown reason"; + + switch (reason) + { + case PROCSIG_RECOVERY_CONFLICT_BUFFERPIN: + reasonDesc = "User was holding shared buffer pin for too long."; + break; + case PROCSIG_RECOVERY_CONFLICT_LOCK: + reasonDesc = "User was holding a relation lock for too long."; + break; + case PROCSIG_RECOVERY_CONFLICT_TABLESPACE: + reasonDesc = "User was or might have been using tablespace that must be dropped."; + break; + case PROCSIG_RECOVERY_CONFLICT_SNAPSHOT: + reasonDesc = "User query might have needed to see row versions that must be removed."; + break; + case PROCSIG_RECOVERY_CONFLICT_STARTUP_DEADLOCK: + reasonDesc = "User transaction caused buffer deadlock with recovery."; + break; + case PROCSIG_RECOVERY_CONFLICT_DATABASE: + reasonDesc = "User was connected to a database that must be dropped."; + break; + case PROCSIG_CATCHUP_INTERRUPT: + case PROCSIG_NOTIFY_INTERRUPT: + case PROCSIG_PARALLEL_MESSAGE: + case PROCSIG_WALSND_INIT_STOPPING: + case NUM_PROCSIGNALS: + break; + default: + break; + } + return reasonDesc; +} diff --git a/src/backend/storage/ipc/standby.c b/src/backend/storage/ipc/standby.c index 9e0d5ec257..ac85211be0 100644 --- a/src/backend/storage/ipc/standby.c +++ b/src/backend/storage/ipc/standby.c @@ -16,6 +16,7 @@ *------------------------------------------------------------------------- */ #include "postgres.h" +#include "access/rmgr.h" #include "access/transam.h" #include "access/twophase.h" #include "access/xact.h" @@ -34,6 +35,7 @@ #include "utils/ps_status.h" #include "utils/timeout.h" #include "utils/timestamp.h" +#include "access/xlog_internal.h" /* User-settable GUC parameters */ int vacuum_defer_cleanup_age; @@ -215,6 +217,57 @@ WaitExceedsMaxStandbyDelay(uint32 wait_event_info) return false; } +/* + * Display information about the wal record + * apply being blocked + */ +static void +LogBlockedWalRecordInfo(int num_waitlist_entries, ProcSignalReason reason) +{ + RelFileNode rnode; + ForkNumber forknum; + BlockNumber blknum; + uint64 wal_record_lsn; + TimestampTz rtime; + bool fromStream; + char *receipt_time_str; + RmgrId rmgrId = -1; + uint8 info = 0; + const char *rm_name; + const char *rm_info; + char *wal_record_info_str; + + if (num_waitlist_entries > 0) + ereport(LOG, (errmsg("wal record apply is blocked by %d connection(s), reason: %s", + num_waitlist_entries, get_procsignal_reason_desc(reason)))); + else + ereport(LOG, (errmsg("wal record apply is blocked, reason: %s", + get_procsignal_reason_desc(reason)))); + + wal_record_lsn = current_replayed_xlog->ReadRecPtr; + rmgrId = XLogRecGetRmid(current_replayed_xlog); + info = XLogRecGetInfo(current_replayed_xlog) & ~XLR_INFO_MASK; + + rm_name = RmgrTable[rmgrId].rm_name; + rm_info = RmgrTable[rmgrId].rm_identify(info); + + GetXLogReceiptTime(&rtime, &fromStream); + receipt_time_str = pstrdup(timestamptz_to_str(rtime)); + wal_record_info_str = psprintf("blocked wal record rmgr: %s, lsn: %X/%08X, received at: %s, desc: %s", rm_name, (uint32) (wal_record_lsn >> 32), (uint32) wal_record_lsn, receipt_time_str, rm_info); + + if (XLogRecGetBlockTag(current_replayed_xlog, 0, &rnode, &forknum, &blknum)) + ereport(LOG, (errmsg("%s, relation: rel %u/%u/%u fork %s blk %u", + wal_record_info_str, + rnode.spcNode, rnode.dbNode, rnode.relNode, + forkNames[forknum], + blknum))); + else + ereport(LOG, (errmsg("%s", wal_record_info_str))); + + pfree(wal_record_info_str); + pfree(receipt_time_str); +} + /* * This is the main executioner for any query backend that conflicts with * recovery processing. Judgement has already been passed on it within @@ -232,6 +285,8 @@ ResolveRecoveryConflictWithVirtualXIDs(VirtualTransactionId *waitlist, { TimestampTz waitStart = 0; char *new_status; + VirtualTransactionId *tmpWaitlist; + int num_waitlist_entries; /* Fast exit, to avoid a kernel call if there's no work to be done. */ if (!VirtualTransactionIdIsValid(*waitlist)) @@ -241,6 +296,17 @@ ResolveRecoveryConflictWithVirtualXIDs(VirtualTransactionId *waitlist, waitStart = GetCurrentTimestamp(); new_status = NULL; /* we haven't changed the ps display */ + tmpWaitlist = waitlist; + while (VirtualTransactionIdIsValid(*tmpWaitlist)) + { + tmpWaitlist++; + } + + num_waitlist_entries = (tmpWaitlist - waitlist); + + /* display wal record information */ + LogBlockedWalRecordInfo(num_waitlist_entries, reason); + while (VirtualTransactionIdIsValid(*waitlist)) { /* reset standbyWait_us for each xact we wait for */ @@ -370,6 +436,10 @@ ResolveRecoveryConflictWithDatabase(Oid dbid) * block during InitPostgres() and then disconnect when they see the * database has been removed. */ + + /* display wal record information */ + LogBlockedWalRecordInfo(CountDBBackends(dbid), PROCSIG_RECOVERY_CONFLICT_DATABASE); + while (CountDBBackends(dbid) > 0) { CancelDBBackends(dbid, PROCSIG_RECOVERY_CONFLICT_DATABASE, true); @@ -609,6 +679,9 @@ StandbyTimeoutHandler(void) /* forget any pending STANDBY_DEADLOCK_TIMEOUT request */ disable_timeout(STANDBY_DEADLOCK_TIMEOUT, false); + /* display wal record information */ + LogBlockedWalRecordInfo(-1, PROCSIG_RECOVERY_CONFLICT_BUFFERPIN); + SendRecoveryConflictWithBufferPin(PROCSIG_RECOVERY_CONFLICT_BUFFERPIN); } diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index c9424f167c..192aa1dc52 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -126,6 +126,8 @@ char *stack_base_ptr = NULL; char *register_stack_base_ptr = NULL; #endif +#define UINT32_ACCESS_ONCE(var) ((uint32)(*((volatile uint32 *)&(var)))) + /* * Flag to keep track of whether we have started a transaction. * For extended query protocol this has to be remembered across messages. @@ -191,6 +193,7 @@ static void drop_unnamed_stmt(void); static void log_disconnections(int code, Datum arg); static void enable_statement_timeout(void); static void disable_statement_timeout(void); +static void LogBlockingWalRecordApplyInfo(void); /* ---------------------------------------------------------------- @@ -2886,6 +2889,58 @@ FloatExceptionHandler(SIGNAL_ARGS) "invalid operation, such as division by zero."))); } +/* + * Display information about the backend + * about to be interrupted due to recovery conflict + */ +void +LogBlockingWalRecordApplyInfo(void) +{ + + PgBackendStatus *beentry; + int num_backends = pgstat_fetch_stat_numbackends(); + int curr_backend; + uint32 raw_wait_event; + const char *wait_event = NULL; + const char *wait_event_type = NULL; + char *clipped_activity; + const char *activity_start; + const char *backend_state_name; + const char *backend_type; + + Assert(MyProc != NULL); + /* + * Make sure any stats snapshot is thrown away + */ + pgstat_clear_snapshot(); + + for (curr_backend = 1; curr_backend <= num_backends; curr_backend++) + { + beentry = pgstat_fetch_stat_beentry(curr_backend); + if (beentry->st_procpid != MyProc->pid) + continue; + + backend_state_name = pgstat_get_state_name(beentry->st_state); + backend_type = GetBackendTypeDesc(beentry->st_backendType); + activity_start = timestamptz_to_str(beentry->st_activity_start_timestamp); + clipped_activity = pgstat_clip_activity(beentry->st_activity_raw); + + raw_wait_event = UINT32_ACCESS_ONCE(MyProc->wait_event_info); + wait_event = pgstat_get_wait_event(raw_wait_event); + wait_event_type = pgstat_get_wait_event_type(raw_wait_event); + + ereport(LOG, + (errmsg("about to interrupt pid: %d, backend_type: %s, state: %s, wait_event_type: %s, wait_event: %s, query_start: %s", + MyProc->pid, backend_type, backend_state_name, wait_event_type ? wait_event_type : "none", wait_event ? wait_event : "none", activity_start), + errdetail("statement: %s", clipped_activity))); + pfree(clipped_activity); + } + /* + * Make sure any stats snapshot is thrown away + */ + pgstat_clear_snapshot(); +} + /* * RecoveryConflictInterrupt: out-of-line portion of recovery conflict * handling following receipt of SIGUSR1. Designed to be similar to die() @@ -2986,6 +3041,7 @@ RecoveryConflictInterrupt(ProcSignalReason reason) (int) reason); } + LogBlockingWalRecordApplyInfo(); Assert(RecoveryConflictPending && (QueryCancelPending || ProcDiePending)); /* diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h index e917dfe92d..eafd4201db 100644 --- a/src/include/access/xlog.h +++ b/src/include/access/xlog.h @@ -100,6 +100,7 @@ typedef enum extern XLogRecPtr ProcLastRecPtr; extern XLogRecPtr XactLastRecEnd; extern PGDLLIMPORT XLogRecPtr XactLastCommitEnd; +extern XLogReaderState *current_replayed_xlog; extern bool reachedConsistency; diff --git a/src/include/pgstat.h b/src/include/pgstat.h index c55dc1481c..2fca769bc9 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -1334,6 +1334,7 @@ extern PgStat_TableStatus *find_tabstat_entry(Oid rel_id); extern PgStat_BackendFunctionEntry *find_funcstat_entry(Oid func_id); extern void pgstat_initstats(Relation rel); +extern const char *pgstat_get_state_name(BackendState backend_state); extern char *pgstat_clip_activity(const char *raw_activity); diff --git a/src/include/storage/procsignal.h b/src/include/storage/procsignal.h index a0c0bc3ce5..c57413b06d 100644 --- a/src/include/storage/procsignal.h +++ b/src/include/storage/procsignal.h @@ -70,5 +70,6 @@ extern void WaitForProcSignalBarrier(uint64 generation); extern void ProcessProcSignalBarrier(void); extern void procsignal_sigusr1_handler(SIGNAL_ARGS); +extern const char *get_procsignal_reason_desc(ProcSignalReason reason); #endif /* PROCSIGNAL_H */