Subject: Add “FOR UPDATE NOWAIT” lock details to the log.

From: Seino Yuki <[email-masked]>
Date: Fri, 13 Sep 2024 20:49:36 +0900

Hello,

I would like to add the information of the PID that caused the failure
when acquiring a lock with "FOR UPDATE NOWAIT".

When "FOR UPDATE" is executed and interrupted by lock_timeout,
xid and PID are output in the logs, but in the case of "FOR UPDATE 
NOWAIT",
no information is output, making it impossible to identify the cause of 
the lock failure.
Therefore, I would like to output information in the logs in the same 
way as
when "FOR UPDATE" is executed and interrupted by lock_timeout.

The patch is attached as well.

Regards,
--
Yuki Seino
NTT DATA CORPORATION

commit 2c3b10a75d2ade1ba8d229dd93c5aa4c142e1298
Author: Yuki Seino <[email-masked]>
Date:   Fri Sep 13 20:24:33 2024 +0900

    Add the information of the PID, which caused the failure to acquire the lock, to the log when using 'FOR UPDATE NOWAIT.'

diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index ac66da8638..a77929d463 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1085,6 +1085,13 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable, bool dontWait)
 	bool		logged_recovery_conflict = false;
 	ProcWaitStatus myWaitStatus;
 	PGPROC	   *leader = MyProc->lockGroupLeader;
+	StringInfoData buf,
+			lock_waiters_sbuf,
+			lock_holders_sbuf;
+	const char *modename;
+	bool		first_holder = true,
+				first_waiter = true;
+	int			lockHoldersNum = 0;
 
 	/*
 	 * If group locking is in use, locks held by members of my locking group
@@ -1186,8 +1193,27 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable, bool dontWait)
 	 * At this point we know that we'd really need to sleep. If we've been
 	 * commanded not to do that, bail out.
 	 */
-	if (dontWait)
+	if (dontWait){
+		initStringInfo(&buf);
+		initStringInfo(&lock_waiters_sbuf);
+		initStringInfo(&lock_holders_sbuf);
+
+		DescribeLockTag(&buf, &locallock->tag.lock);
+		modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid,
+									lockmode);
+
+		/* Collect lock holders and waiters */
+		CollectLockHoldersAndWaiters(proclock, lock, &lock_holders_sbuf, &lock_waiters_sbuf, &lockHoldersNum);
+
+		ereport(LOG,
+						(errmsg("process %d could not obtain %s on %s",
+								MyProcPid, modename, buf.data),
+						 (errdetail_log_plural("Process holding the lock: %s. Wait: %s.",
+											   "Processes holding the lock: %s. Wait: %s.",
+											   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+
 		return PROC_WAIT_STATUS_ERROR;
+	}
 
 	/*
 	 * Insert self into queue, at the position determined above.
@@ -1466,18 +1492,9 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable, bool dontWait)
 		 */
 		if (log_lock_waits && deadlock_state != DS_NOT_YET_CHECKED)
 		{
-			StringInfoData buf,
-						lock_waiters_sbuf,
-						lock_holders_sbuf;
-			const char *modename;
 			long		secs;
 			int			usecs;
 			long		msecs;
-			dlist_iter	proc_iter;
-			PROCLOCK   *curproclock;
-			bool		first_holder = true,
-						first_waiter = true;
-			int			lockHoldersNum = 0;
 
 			initStringInfo(&buf);
 			initStringInfo(&lock_waiters_sbuf);
@@ -1492,53 +1509,10 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable, bool dontWait)
 			msecs = secs * 1000 + usecs / 1000;
 			usecs = usecs % 1000;
 
-			/*
-			 * we loop over the lock's procLocks to gather a list of all
-			 * holders and waiters. Thus we will be able to provide more
-			 * detailed information for lock debugging purposes.
-			 *
-			 * lock->procLocks contains all processes which hold or wait for
-			 * this lock.
-			 */
-
 			LWLockAcquire(partitionLock, LW_SHARED);
 
-			dlist_foreach(proc_iter, &lock->procLocks)
-			{
-				curproclock =
-					dlist_container(PROCLOCK, lockLink, proc_iter.cur);
-
-				/*
-				 * we are a waiter if myProc->waitProcLock == curproclock; we
-				 * are a holder if it is NULL or something different
-				 */
-				if (curproclock->tag.myProc->waitProcLock == curproclock)
-				{
-					if (first_waiter)
-					{
-						appendStringInfo(&lock_waiters_sbuf, "%d",
-										 curproclock->tag.myProc->pid);
-						first_waiter = false;
-					}
-					else
-						appendStringInfo(&lock_waiters_sbuf, ", %d",
-										 curproclock->tag.myProc->pid);
-				}
-				else
-				{
-					if (first_holder)
-					{
-						appendStringInfo(&lock_holders_sbuf, "%d",
-										 curproclock->tag.myProc->pid);
-						first_holder = false;
-					}
-					else
-						appendStringInfo(&lock_holders_sbuf, ", %d",
-										 curproclock->tag.myProc->pid);
-
-					lockHoldersNum++;
-				}
-			}
+			/* Collect lock holders and waiters */
+			CollectLockHoldersAndWaiters(NULL, lock, &lock_holders_sbuf, &lock_waiters_sbuf, &lockHoldersNum);
 
 			LWLockRelease(partitionLock);
 
@@ -1961,3 +1935,58 @@ BecomeLockGroupMember(PGPROC *leader, int pid)
 
 	return ok;
 }
+
+/*
+ * we loop over the lock's procLocks to gather a list of all
+ * holders and waiters. Thus we will be able to provide more
+ * detailed information for lock debugging purposes.
+ *
+ * lock->procLocks contains all processes which hold or wait for
+ * this lock.
+ */
+void
+CollectLockHoldersAndWaiters(PROCLOCK *waitProcLock, LOCK *lock, StringInfo lock_holders_sbuf, StringInfo lock_waiters_sbuf, int *lockHoldersNum)
+{
+	bool first_holder = true;
+	bool first_waiter = true;
+	dlist_iter proc_iter;
+	PROCLOCK *curproclock;
+
+	dlist_foreach(proc_iter, &lock->procLocks)
+	{
+		curproclock =
+			dlist_container(PROCLOCK, lockLink, proc_iter.cur);
+
+		/*
+			* we are a waiter if myProc->waitProcLock == curproclock; we
+			* are a holder if it is NULL or something different
+			*/
+		if ((waitProcLock == NULL && curproclock->tag.myProc->waitProcLock == curproclock) ||
+			(waitProcLock != NULL && waitProcLock == curproclock))
+		{
+			if (first_waiter)
+			{
+				appendStringInfo(lock_waiters_sbuf, "%d",
+									curproclock->tag.myProc->pid);
+				first_waiter = false;
+			}
+			else
+				appendStringInfo(lock_waiters_sbuf, ", %d",
+									curproclock->tag.myProc->pid);
+		}
+		else
+		{
+			if (first_holder)
+			{
+				appendStringInfo(lock_holders_sbuf, "%d",
+									curproclock->tag.myProc->pid);
+				first_holder = false;
+			}
+			else
+				appendStringInfo(lock_holders_sbuf, ", %d",
+									curproclock->tag.myProc->pid);
+
+			(*lockHoldersNum)++;
+		}
+	}
+}
\ No newline at end of file