v9-0008-Log-the-standby-recovery-conflict-waits.patch

 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             | 211 +++++++++++++++++++++-----
 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                 |   5 +-
 8 files changed, 270 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 '
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-log-recovery-conflict-waits" xreflabel="log_recovery_conflict_waits">
+      <term><varname>log_recovery_conflict_waits</varname> (<type>boolean</type>)
+      <indexterm>
+       <primary><varname>log_recovery_conflict_waits</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+      <listitem>
+       <para>
+        Controls whether a log message is produced when the startup process
+        is waiting longer than <varname>deadlock_timeout</varname>
+        for recovery conflicts.  This is useful in determining if recovery
+        conflicts prevent the recovery from applying WAL.
+       </para>
+
+       <para>
+        The default is <literal>off</literal>.  This parameter can only be set
+        in the <filename>postgresql.conf</filename> file or on the server
+        command line.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry id="guc-log-parameter-max-length" xreflabel="log_parameter_max_length">
       <term><varname>log_parameter_max_length</varname> (<type>integer</type>)
       <indexterm>
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 <structname>pg_stat_database</structname> system view also contains
     summary information.
    </para>
+
+   <para>
+    Users can control whether a log message is produced when WAL replay is waiting
+    longer than <varname>deadlock_timeout</varname> for conflicts. This
+    is controlled by the <xref linkend="guc-log-recovery-conflict-waits"/> parameter.
+   </para>
   </sect2>
 
   <sect2 id="hot-standby-admin">
diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c
index e549fa1d30..06cd5cdba5 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 and in hot standby */
+	if (log_recovery_conflict_waits && InHotStandby)
+		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..25372b600a 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,77 @@ WaitExceedsMaxStandbyDelay(uint32 wait_event_info)
 	return false;
 }
 
+/*
+ * Log the recovery conflict.
+ *
+ * wait_start is the timestamp when the caller started to wait.
+ * cur_ts is the timestamp when this function has been called.
+ * This function also reports the details about the conflicting
+ * process ids if any.
+ */
+void
+LogRecoveryConflict(ProcSignalReason reason, TimestampTz wait_start,
+					TimestampTz cur_ts, VirtualTransactionId *wait_list)
+{
+	long		secs;
+	int			usecs;
+	long		msecs;
+	StringInfoData buf;
+	int	nprocs = 0;
+
+	TimestampDifference(wait_start, cur_ts, &secs, &usecs);
+	msecs = secs * 1000 + usecs / 1000;
+	usecs = usecs % 1000;
+
+	if (wait_list)
+	{
+		VirtualTransactionId *vxids;
+
+
+		/* construct a string of list of the conflicted processes */
+		vxids = wait_list;
+		while (VirtualTransactionIdIsValid(*vxids))
+		{
+			PGPROC *proc = BackendIdGetProc(vxids->backendId);
+
+			if (proc)
+			{
+				if (nprocs == 0)
+				{
+					initStringInfo(&buf);
+					appendStringInfo(&buf, "%d", proc->pid);
+				}
+				else
+					appendStringInfo(&buf, ", %d", proc->pid);
+
+				nprocs++;
+			}
+
+			vxids++;
+		}
+
+	}
+
+	ereport(LOG,
+			errmsg("recovery still waiting after %ld.%03d ms: %s",
+					msecs, usecs, _(get_recovery_conflict_desc(reason))),
+			wait_list > 0 ? errdetail_log_plural("Conflicting process: %s.",
+													"Conflicting processes: %s.",
+													nprocs, buf.data) : 0);
+	if (nprocs > 0)
+		pfree(buf.data);
+}
+
 /*
  * 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 +296,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 +315,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? */
@@ -398,9 +484,12 @@ ResolveRecoveryConflictWithDatabase(Oid dbid)
  *
  * Deadlocks involving the Startup process and an ordinary backend process
  * will be detected by the deadlock detector within the ordinary backend.
+ *
+ * already_logged is used to set the deadlock timeout for logging purpose
+ * only when the message has not been logged yet.
  */
 void
-ResolveRecoveryConflictWithLock(LOCKTAG locktag)
+ResolveRecoveryConflictWithLock(LOCKTAG locktag, bool already_logged)
 {
 	TimestampTz ltime;
 
@@ -408,7 +497,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 && !already_logged)
+		{
+			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 +536,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 +1222,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 conflict on buffer pin");
+			break;
+		case PROCSIG_RECOVERY_CONFLICT_LOCK:
+			reasonDesc = gettext_noop("recovery conflict on lock");
+			break;
+		case PROCSIG_RECOVERY_CONFLICT_TABLESPACE:
+			reasonDesc = gettext_noop("recovery conflict on tablespace");
+			break;
+		case PROCSIG_RECOVERY_CONFLICT_SNAPSHOT:
+			reasonDesc = gettext_noop("recovery conflict on snapshot");
+			break;
+		case PROCSIG_RECOVERY_CONFLICT_STARTUP_DEADLOCK:
+			reasonDesc = gettext_noop("recovery conflict on buffer deadlock");
+			break;
+		case PROCSIG_RECOVERY_CONFLICT_DATABASE:
+			reasonDesc = gettext_noop("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..857aa1f81d 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,14 @@ 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 already_logged);
 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 wait_start,
+								TimestampTz cur_ts, VirtualTransactionId *wait_list);
 
 /*
  * Standby Rmgr (RM_STANDBY_ID)