Subject: Patch: Show queries of processes holding a lock

From: Alexey Orlov <[email-masked]>
Date: Mon, 30 Sep 2024 23:15:38 +0300

Hi, there!

I created patch improving the log messages generated by
log_lock_waits.

Sample output (log_lock_waits=on required):

session 1:
CREATE TABLE foo (val integer);
INSERT INTO foo (val) VALUES (1);
BEGIN;
UPDATE foo SET val = 3;

session 2:
BEGIN;
UPDATE TABLE foo SET val = 2;

Output w/o patch:

LOG: process 3133043 still waiting for ShareLock on transaction 758
after 1000.239 ms
DETAIL: Process holding the lock: 3132855. Wait queue: 3133043.
CONTEXT: while updating tuple (0,7) in relation "foo"
STATEMENT: update foo SET val = 2;

Output with path

LOG: process 3133043 still waiting for ShareLock on transaction 758
after 1000.239 ms
DETAIL: Process holding the lock: 3132855. Wait queue: 3133043.
Process 3132855: update foo SET val = 3;
CONTEXT: while updating tuple (0,7) in relation "foo"
STATEMENT: update foo SET val = 2;

As you can see information about query that holds the lock goes into log.

If this approach proves unacceptable, we can make the log_lock_waits
parameter as an enum
and display the query if the log_lock_waits=verbose (for example).

What do you think?

Regards,

--
Orlov Alexey
From a317cd40303975c90c2daf222deb7dc80a44aa11 Mon Sep 17 00:00:00 2001
From: Alexey Orlov <[email-masked]>
Date: Mon, 30 Sep 2024 22:11:25 +0300
Subject: [PATCH v=1] Show queries in log_lock_wait_log

---
 src/backend/storage/lmgr/proc.c | 20 ++++++++++++++++----
 1 file changed, 16 insertions(+), 4 deletions(-)

diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index 0d8162a2cc..8c187bd6dc 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1514,7 +1514,8 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable, bool dontWait)
 		{
 			StringInfoData buf,
 						lock_waiters_sbuf,
-						lock_holders_sbuf;
+						lock_holders_sbuf,
+						lock_queries_sbuf;
 			const char *modename;
 			long		secs;
 			int			usecs;
@@ -1528,6 +1529,7 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable, bool dontWait)
 			initStringInfo(&buf);
 			initStringInfo(&lock_waiters_sbuf);
 			initStringInfo(&lock_holders_sbuf);
+			initStringInfo(&lock_queries_sbuf);
 
 			DescribeLockTag(&buf, &locallock->tag.lock);
 			modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid,
@@ -1572,6 +1574,15 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable, bool dontWait)
 				}
 				else
 				{
+					if (myWaitStatus == PROC_WAIT_STATUS_WAITING)
+					{
+						appendStringInfoChar(&lock_queries_sbuf, '\n');
+
+						appendStringInfo(&lock_queries_sbuf,
+										 _("Process %d: %s"),
+										 curproclock->tag.myProc->pid,
+										 pgstat_get_backend_current_activity(curproclock->tag.myProc->pid, false));
+					}
 					if (first_holder)
 					{
 						appendStringInfo(&lock_holders_sbuf, "%d",
@@ -1616,9 +1627,9 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable, bool dontWait)
 				ereport(LOG,
 						(errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
 								MyProcPid, modename, buf.data, msecs, usecs),
-						 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
-											   "Processes holding the lock: %s. Wait queue: %s.",
-											   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+						 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.%s",
+											   "Processes holding the lock: %s. Wait queue: %s.%s",
+											   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data, lock_queries_sbuf.data))));
 			else if (myWaitStatus == PROC_WAIT_STATUS_OK)
 				ereport(LOG,
 						(errmsg("process %d acquired %s on %s after %ld.%03d ms",
@@ -1654,6 +1665,7 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable, bool dontWait)
 			pfree(buf.data);
 			pfree(lock_holders_sbuf.data);
 			pfree(lock_waiters_sbuf.data);
+			pfree(lock_queries_sbuf.data);
 		}
 	} while (myWaitStatus == PROC_WAIT_STATUS_WAITING);
 
-- 
2.44.0