doc/src/sgml/config.sgml | 22 +++
doc/src/sgml/high-availability.sgml | 6 +
src/backend/storage/buffer/bufmgr.c | 18 +++
src/backend/storage/ipc/standby.c | 216 +++++++++++++++++++++-----
src/backend/storage/lmgr/proc.c | 35 ++++-
src/backend/utils/misc/guc.c | 10 +-
src/backend/utils/misc/postgresql.conf.sample | 2 +
src/include/storage/standby.h | 6 +-
8 files changed, 276 insertions(+), 39 deletions(-)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index ee914740cc..3aa892c0f3 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6839,6 +6839,28 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
+
+ log_recovery_conflict_waits (boolean)
+
+ log_recovery_conflict_waits configuration parameter
+
+
+
+
+ Controls whether a log message is produced when the startup process
+ is waiting longer than deadlock_timeout
+ for recovery conflicts. This is useful in determining if recovery
+ conflicts prevent the recovery from applying WAL.
+
+
+
+ The default is off. This parameter can only be set
+ in the postgresql.conf file or on the server
+ command line.
+
+
+
+
log_parameter_max_length (integer)
diff --git a/doc/src/sgml/high-availability.sgml b/doc/src/sgml/high-availability.sgml
index 86da84fce7..3dcb34143a 100644
--- a/doc/src/sgml/high-availability.sgml
+++ b/doc/src/sgml/high-availability.sgml
@@ -2104,6 +2104,12 @@ if (!triggered)
server. The pg_stat_database system view also contains
summary information.
+
+
+ Users can control whether a log message is produced when WAL replay is waiting
+ longer than deadlock_timeout for conflicts. This
+ is controlled by the parameter.
+
diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c
index e549fa1d30..5a9740ab6f 100644
--- a/src/backend/storage/buffer/bufmgr.c
+++ b/src/backend/storage/buffer/bufmgr.c
@@ -3808,6 +3808,8 @@ LockBufferForCleanup(Buffer buffer)
{
BufferDesc *bufHdr;
char *new_status = NULL;
+ TimestampTz waitStart = 0;
+ bool logged_recovery_conflict = false;
Assert(BufferIsPinned(buffer));
Assert(PinCountWaitBuf == NULL);
@@ -3829,6 +3831,10 @@ LockBufferForCleanup(Buffer buffer)
bufHdr = GetBufferDescriptor(buffer - 1);
+ /* Set wait start timestamp if logging is enabled */
+ if (log_recovery_conflict_waits)
+ waitStart = GetCurrentTimestamp();
+
for (;;)
{
uint32 buf_state;
@@ -3881,6 +3887,18 @@ LockBufferForCleanup(Buffer buffer)
new_status[len] = '\0'; /* truncate off " waiting" */
}
+ if (waitStart > 0 && !logged_recovery_conflict)
+ {
+ TimestampTz cur_ts = GetCurrentTimestamp();
+ if (TimestampDifferenceExceeds(waitStart, cur_ts,
+ DeadlockTimeout))
+ {
+ Assert(log_recovery_conflict_waits);
+ LogRecoveryConflict(PROCSIG_RECOVERY_CONFLICT_BUFFERPIN,
+ waitStart, cur_ts, NULL);
+ logged_recovery_conflict = true;
+ }
+ }
/* Publish the bufid that Startup process waits on */
SetStartupBufferPinWaitBufId(buffer - 1);
/* Set alarm and then wait to be signaled by UnpinBuffer() */
diff --git a/src/backend/storage/ipc/standby.c b/src/backend/storage/ipc/standby.c
index 52b2809dac..098fe35802 100644
--- a/src/backend/storage/ipc/standby.c
+++ b/src/backend/storage/ipc/standby.c
@@ -39,6 +39,7 @@
int vacuum_defer_cleanup_age;
int max_standby_archive_delay = 30 * 1000;
int max_standby_streaming_delay = 30 * 1000;
+bool log_recovery_conflict_waits = false;
static HTAB *RecoveryLockLists;
@@ -49,6 +50,7 @@ static void ResolveRecoveryConflictWithVirtualXIDs(VirtualTransactionId *waitlis
static void SendRecoveryConflictWithBufferPin(ProcSignalReason reason);
static XLogRecPtr LogCurrentRunningXacts(RunningTransactions CurrRunningXacts);
static void LogAccessExclusiveLocks(int nlocks, xl_standby_lock *locks);
+static const char *get_recovery_conflict_desc(ProcSignalReason reason);
/*
* Keep track of all the locks owned by a given transaction.
@@ -215,15 +217,85 @@ WaitExceedsMaxStandbyDelay(uint32 wait_event_info)
return false;
}
+/*
+ * Log the recovery conflict.
+ *
+ * waitStart is the timestamp when the caller started to wait. This function also
+ * reports the details about the conflicting process ids if *waitlist is not NULL.
+ */
+void
+LogRecoveryConflict(ProcSignalReason reason, TimestampTz waitStart,
+ TimestampTz cur_ts, VirtualTransactionId *waitlist)
+{
+ long secs;
+ int usecs;
+ long msecs;
+
+ TimestampDifference(waitStart, cur_ts, &secs, &usecs);
+ msecs = secs * 1000 + usecs / 1000;
+ usecs = usecs % 1000;
+
+ if (waitlist)
+ {
+ VirtualTransactionId *vxids;
+ StringInfoData buf;
+ int nprocs = 0;
+
+ initStringInfo(&buf);
+
+ /* construct a string of list of the conflicted processes */
+ vxids = waitlist;
+ while (VirtualTransactionIdIsValid(*vxids))
+ {
+ PGPROC *proc = BackendIdGetProc(vxids->backendId);
+
+ if (proc)
+ {
+ if (nprocs == 0)
+ appendStringInfo(&buf, "%d", proc->pid);
+ else
+ appendStringInfo(&buf, ", %d", proc->pid);
+
+ nprocs++;
+ }
+
+ vxids++;
+ }
+
+ if (nprocs > 0)
+ {
+ ereport(LOG,
+ (errmsg("%s after %ld.%03d ms",
+ get_recovery_conflict_desc(reason), msecs, usecs),
+ (errdetail_log_plural("Conflicting process: %s.",
+ "Conflicting processes: %s.",
+ nprocs, buf.data))));
+ }
+ else
+ {
+ ereport(LOG,
+ (errmsg("%s after %ld.%03d ms",
+ get_recovery_conflict_desc(reason), msecs, usecs)));
+ }
+
+ pfree(buf.data);
+ }
+ else
+ ereport(LOG,
+ (errmsg("%s after %ld.%03d ms",
+ get_recovery_conflict_desc(reason), msecs, usecs)));
+}
+
/*
* This is the main executioner for any query backend that conflicts with
* recovery processing. Judgement has already been passed on it within
* a specific rmgr. Here we just issue the orders to the procs. The procs
* then throw the required error as instructed.
*
- * If report_waiting is true, "waiting" is reported in PS display if necessary.
- * If the caller has already reported that, report_waiting should be false.
- * Otherwise, "waiting" is reported twice unexpectedly.
+ * If report_waiting is true, "waiting" is reported in PS display and log
+ * the waits for the recovery conflict if necessary. If the caller has already
+ * reported that, report_waiting should be false. Otherwise, both are reported
+ * twice unexpectedly.
*/
static void
ResolveRecoveryConflictWithVirtualXIDs(VirtualTransactionId *waitlist,
@@ -232,12 +304,14 @@ ResolveRecoveryConflictWithVirtualXIDs(VirtualTransactionId *waitlist,
{
TimestampTz waitStart = 0;
char *new_status;
+ bool logged_recovery_conflict = false;
/* Fast exit, to avoid a kernel call if there's no work to be done. */
if (!VirtualTransactionIdIsValid(*waitlist))
return;
- if (report_waiting)
+ /* Set the wait start timestamp for reporting */
+ if (report_waiting && (logged_recovery_conflict || update_process_title))
waitStart = GetCurrentTimestamp();
new_status = NULL; /* we haven't changed the ps display */
@@ -249,23 +323,43 @@ ResolveRecoveryConflictWithVirtualXIDs(VirtualTransactionId *waitlist,
/* wait until the virtual xid is gone */
while (!VirtualXactLock(*waitlist, false))
{
- /*
- * Report via ps if we have been waiting for more than 500 msec
- * (should that be configurable?)
- */
- if (update_process_title && new_status == NULL && report_waiting &&
- TimestampDifferenceExceeds(waitStart, GetCurrentTimestamp(),
- 500))
+ if (waitStart > 0)
{
- const char *old_status;
- int len;
-
- old_status = get_ps_display(&len);
- new_status = (char *) palloc(len + 8 + 1);
- memcpy(new_status, old_status, len);
- strcpy(new_status + len, " waiting");
- set_ps_display(new_status);
- new_status[len] = '\0'; /* truncate off " waiting" */
+ TimestampTz cur_ts = 0;
+ bool maybe_log_conflict =
+ (log_recovery_conflict_waits && !logged_recovery_conflict);
+ bool maybe_update_pstitle =
+ (update_process_title && new_status == NULL);
+
+ /* Get the current timestamp if not report yet */
+ if (maybe_log_conflict || maybe_update_pstitle)
+ cur_ts = GetCurrentTimestamp();
+
+ /* Log the recovery conflict if necessary */
+ if (maybe_log_conflict &&
+ TimestampDifferenceExceeds(waitStart, cur_ts, DeadlockTimeout))
+ {
+ LogRecoveryConflict(reason, waitStart, cur_ts, waitlist);
+ logged_recovery_conflict = true;
+ }
+
+ /*
+ * Report via ps if we have been waiting for more than 500 msec
+ * (should that be configurable?)
+ */
+ if (maybe_update_pstitle &&
+ TimestampDifferenceExceeds(waitStart, cur_ts, 500))
+ {
+ const char *old_status;
+ int len;
+
+ old_status = get_ps_display(&len);
+ new_status = (char *) palloc(len + 8 + 1);
+ memcpy(new_status, old_status, len);
+ strcpy(new_status + len, " waiting");
+ set_ps_display(new_status);
+ new_status[len] = '\0'; /* truncate off " waiting" */
+ }
}
/* Is it time to kill it? */
@@ -400,7 +494,7 @@ ResolveRecoveryConflictWithDatabase(Oid dbid)
* will be detected by the deadlock detector within the ordinary backend.
*/
void
-ResolveRecoveryConflictWithLock(LOCKTAG locktag)
+ResolveRecoveryConflictWithLock(LOCKTAG locktag, bool logged_recovery_conflict)
{
TimestampTz ltime;
@@ -408,7 +502,35 @@ ResolveRecoveryConflictWithLock(LOCKTAG locktag)
ltime = GetStandbyLimitTime();
- if (GetCurrentTimestamp() >= ltime)
+ if (ltime == 0 || GetCurrentTimestamp() < ltime)
+ {
+ EnableTimeoutParams timeouts[2];
+ int cnt = 0;
+
+ /*
+ * Wait (or wait again) until ltime
+ */
+ if (ltime != 0)
+ {
+ timeouts[cnt].id = STANDBY_LOCK_TIMEOUT;
+ timeouts[cnt].type = TMPARAM_AT;
+ timeouts[cnt].fin_time = ltime;
+ cnt++;
+ }
+
+ /* Also, set deadlock timeout for logging purpose if necessary */
+ if (log_recovery_conflict_waits && !logged_recovery_conflict)
+ {
+ timeouts[cnt].id = STANDBY_TIMEOUT;
+ timeouts[cnt].type = TMPARAM_AFTER;
+ timeouts[cnt].delay_ms = DeadlockTimeout;
+ cnt++;
+ }
+
+ if (cnt > 0)
+ enable_timeouts(timeouts, cnt);
+ }
+ else
{
/*
* We're already behind, so clear a path as quickly as possible.
@@ -419,26 +541,15 @@ ResolveRecoveryConflictWithLock(LOCKTAG locktag)
/*
* Prevent ResolveRecoveryConflictWithVirtualXIDs() from reporting
- * "waiting" in PS display by disabling its argument report_waiting
- * because the caller, WaitOnLock(), has already reported that.
+ * "waiting" in PS display and logging recovery conflict by disabling
+ * its argument report_waiting because the callers may have already
+ * reported that.
*/
ResolveRecoveryConflictWithVirtualXIDs(backends,
PROCSIG_RECOVERY_CONFLICT_LOCK,
PG_WAIT_LOCK | locktag.locktag_type,
false);
}
- else
- {
- /*
- * Wait (or wait again) until ltime
- */
- EnableTimeoutParams timeouts[1];
-
- timeouts[0].id = STANDBY_LOCK_TIMEOUT;
- timeouts[0].type = TMPARAM_AT;
- timeouts[0].fin_time = ltime;
- enable_timeouts(timeouts, 1);
- }
/* Wait to be signaled by the release of the Relation Lock */
ProcWaitForSignal(PG_WAIT_LOCK | locktag.locktag_type);
@@ -1116,3 +1227,36 @@ LogStandbyInvalidations(int nmsgs, SharedInvalidationMessage *msgs,
nmsgs * sizeof(SharedInvalidationMessage));
XLogInsert(RM_STANDBY_ID, XLOG_INVALIDATIONS);
}
+
+/* Return the description of recovery conflict */
+static const char *
+get_recovery_conflict_desc(ProcSignalReason reason)
+{
+ const char *reasonDesc = gettext_noop("unknown reason");
+
+ switch (reason)
+ {
+ case PROCSIG_RECOVERY_CONFLICT_BUFFERPIN:
+ reasonDesc = gettext_noop("recovery is still waiting for recovery conflict on buffer pin");
+ break;
+ case PROCSIG_RECOVERY_CONFLICT_LOCK:
+ reasonDesc = gettext_noop("recovery is still waiting for recovery conflict on lock");
+ break;
+ case PROCSIG_RECOVERY_CONFLICT_TABLESPACE:
+ reasonDesc = gettext_noop("recovery is still waiting for recovery conflict on tablespace");
+ break;
+ case PROCSIG_RECOVERY_CONFLICT_SNAPSHOT:
+ reasonDesc = gettext_noop("recovery is still waiting for recovery conflict on snapshot");
+ break;
+ case PROCSIG_RECOVERY_CONFLICT_STARTUP_DEADLOCK:
+ reasonDesc = gettext_noop("recovery is still waiting for recovery conflict on buffer deadlock");
+ break;
+ case PROCSIG_RECOVERY_CONFLICT_DATABASE:
+ reasonDesc = gettext_noop("recovery is still waiting for recovery conflict on database");
+ break;
+ default:
+ break;
+ }
+
+ return reasonDesc;
+}
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index 88566bd9fa..6d08726be9 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1063,8 +1063,10 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
LWLock *partitionLock = LockHashPartitionLock(hashcode);
PROC_QUEUE *waitQueue = &(lock->waitProcs);
LOCKMASK myHeldLocks = MyProc->heldLocks;
+ TimestampTz standbyWaitStart = 0;
bool early_deadlock = false;
bool allow_autovacuum_cancel = true;
+ bool logged_recovery_conflict = false;
ProcWaitStatus myWaitStatus;
PGPROC *proc;
PGPROC *leader = MyProc->lockGroupLeader;
@@ -1260,6 +1262,11 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
else
enable_timeout_after(DEADLOCK_TIMEOUT, DeadlockTimeout);
}
+ else if (log_recovery_conflict_waits)
+ {
+ /* Set wait start timestamp if logging is enabled */
+ standbyWaitStart = GetCurrentTimestamp();
+ }
/*
* If somebody wakes us between LWLockRelease and WaitLatch, the latch
@@ -1280,7 +1287,33 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
if (InHotStandby)
{
/* Set a timer and wait for that or for the Lock to be granted */
- ResolveRecoveryConflictWithLock(locallock->tag.lock);
+ ResolveRecoveryConflictWithLock(locallock->tag.lock, logged_recovery_conflict);
+
+ if (standbyWaitStart > 0 && !logged_recovery_conflict)
+ {
+ TimestampTz cur_ts = GetCurrentTimestamp();
+ if (TimestampDifferenceExceeds(standbyWaitStart, cur_ts,
+ DeadlockTimeout))
+ {
+ VirtualTransactionId *vxids;
+ int cnt;
+
+ Assert(log_recovery_conflict_waits);
+ vxids = GetLockConflicts(&locallock->tag.lock,
+ AccessExclusiveLock, &cnt);
+
+ /*
+ * Log the recovery conflict if there is still virtual transaction
+ * conflicting with the lock.
+ */
+ if (cnt > 0)
+ {
+ LogRecoveryConflict(PROCSIG_RECOVERY_CONFLICT_LOCK,
+ standbyWaitStart, cur_ts, vxids);
+ logged_recovery_conflict = true;
+ }
+ }
+ }
}
else
{
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 596bcb7b84..e55a28b1cd 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -1570,7 +1570,15 @@ static struct config_bool ConfigureNamesBool[] =
false,
NULL, NULL, NULL
},
-
+ {
+ {"log_recovery_conflict_waits", PGC_SIGHUP, LOGGING_WHAT,
+ gettext_noop("Logs standby recovery conflict waits."),
+ NULL
+ },
+ &log_recovery_conflict_waits,
+ false,
+ NULL, NULL, NULL
+ },
{
{"log_hostname", PGC_SIGHUP, LOGGING_WHAT,
gettext_noop("Logs the host name in the connection logs."),
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index 9cb571f7cc..5625681e8a 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -553,6 +553,8 @@
# %% = '%'
# e.g. '<%u%%%d> '
#log_lock_waits = off # log lock waits >= deadlock_timeout
+#log_recovery_conflict_waits = off # log standby recovery conflict waits
+ # >= deadlock_timeout
#log_parameter_max_length = -1 # when logging statements, limit logged
# bind-parameter values to N bytes;
# -1 means print in full, 0 disables
diff --git a/src/include/storage/standby.h b/src/include/storage/standby.h
index faaf1d3817..c4fb42b1e4 100644
--- a/src/include/storage/standby.h
+++ b/src/include/storage/standby.h
@@ -23,6 +23,7 @@
extern int vacuum_defer_cleanup_age;
extern int max_standby_archive_delay;
extern int max_standby_streaming_delay;
+extern bool log_recovery_conflict_waits;
extern void InitRecoveryTransactionEnvironment(void);
extern void ShutdownRecoveryTransactionEnvironment(void);
@@ -32,12 +33,15 @@ extern void ResolveRecoveryConflictWithSnapshot(TransactionId latestRemovedXid,
extern void ResolveRecoveryConflictWithTablespace(Oid tsid);
extern void ResolveRecoveryConflictWithDatabase(Oid dbid);
-extern void ResolveRecoveryConflictWithLock(LOCKTAG locktag);
+extern void ResolveRecoveryConflictWithLock(LOCKTAG locktag,
+ bool logged_recovery_conflict);
extern void ResolveRecoveryConflictWithBufferPin(void);
extern void CheckRecoveryConflictDeadlock(void);
extern void StandbyDeadLockHandler(void);
extern void StandbyTimeoutHandler(void);
extern void StandbyLockTimeoutHandler(void);
+extern void LogRecoveryConflict(ProcSignalReason reason, TimestampTz waitStart,
+ TimestampTz cur_ts, VirtualTransactionId *waitlist);
/*
* Standby Rmgr (RM_STANDBY_ID)