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 <apor...@tender.pro>
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
