From 588fb5071545ce6e8ffb6a88e146789560e6c879 Mon Sep 17 00:00:00 2001
From: Fujii Masao <fujii@postgresql.org>
Date: Thu, 13 Mar 2014 03:26:47 +0900
Subject: [PATCH] Show PIDs of lock holders and waiters in log_lock_waits log
message.
Christian Kruse, reviewed by Kumar Rajeev Rastogi.
---
doc/src/sgml/sources.sgml | 9 ++++
src/backend/storage/lmgr/proc.c | 88 +++++++++++++++++++++++++++++++--
src/backend/utils/error/elog.c | 22 +++++++++
src/include/utils/elog.h | 8 +++
4 files changed, 122 insertions(+), 5 deletions(-)
diff --git a/doc/src/sgml/sources.sgml b/doc/src/sgml/sources.sgml
index 881b0c31a75..aa2080742d4 100644
--- a/doc/src/sgml/sources.sgml
+++ b/doc/src/sgml/sources.sgml
@@ -249,6 +249,15 @@ ereport(ERROR,
sent to the client.
</para>
</listitem>
+ <listitem>
+ <para>
+ <function>errdetail_log_plural(const char *fmt_singuar, const char
+ *fmt_plural, unsigned long n, ...)</function> is like
+ <function>errdetail_log</>, but with support for various plural forms of
+ the message.
+ For more information see <xref linkend="nls-guidelines">.
+ </para>
+ </listitem>
<listitem>
<para>
<function>errhint(const char *msg, ...)</function> supplies an optional
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index f595a0747c1..5cd8fcec450 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1208,13 +1208,23 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
if (log_lock_waits && deadlock_state != DS_NOT_YET_CHECKED)
{
- StringInfoData buf;
+ StringInfoData buf,
+ lock_waiters_sbuf,
+ lock_holders_sbuf;
const char *modename;
long secs;
int usecs;
long msecs;
+ SHM_QUEUE *procLocks;
+ PROCLOCK *proclock;
+ bool first_holder = true,
+ first_waiter = true;
+ int lockHoldersNum = 0;
initStringInfo(&buf);
+ initStringInfo(&lock_waiters_sbuf);
+ initStringInfo(&lock_holders_sbuf);
+
DescribeLockTag(&buf, &locallock->tag.lock);
modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid,
lockmode);
@@ -1224,10 +1234,67 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
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);
+
+ procLocks = &(lock->procLocks);
+ proclock = (PROCLOCK *) SHMQueueNext(procLocks, procLocks,
+ offsetof(PROCLOCK, lockLink));
+
+ while (proclock)
+ {
+ /*
+ * we are a waiter if myProc->waitProcLock == proclock; we are
+ * a holder if it is NULL or something different
+ */
+ if (proclock->tag.myProc->waitProcLock == proclock)
+ {
+ if (first_waiter)
+ {
+ appendStringInfo(&lock_waiters_sbuf, "%d",
+ proclock->tag.myProc->pid);
+ first_waiter = false;
+ }
+ else
+ appendStringInfo(&lock_waiters_sbuf, ", %d",
+ proclock->tag.myProc->pid);
+ }
+ else
+ {
+ if (first_holder)
+ {
+ appendStringInfo(&lock_holders_sbuf, "%d",
+ proclock->tag.myProc->pid);
+ first_holder = false;
+ }
+ else
+ appendStringInfo(&lock_holders_sbuf, ", %d",
+ proclock->tag.myProc->pid);
+
+ lockHoldersNum++;
+ }
+
+ proclock = (PROCLOCK *) SHMQueueNext(procLocks, &proclock->lockLink,
+ offsetof(PROCLOCK, lockLink));
+ }
+
+ LWLockRelease(partitionLock);
+
if (deadlock_state == DS_SOFT_DEADLOCK)
ereport(LOG,
(errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms",
- MyProcPid, modename, buf.data, msecs, usecs)));
+ 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))));
else if (deadlock_state == DS_HARD_DEADLOCK)
{
/*
@@ -1239,13 +1306,19 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
ereport(LOG,
(errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms",
- MyProcPid, modename, buf.data, msecs, usecs)));
+ 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))));
}
if (myWaitStatus == STATUS_WAITING)
ereport(LOG,
(errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
- MyProcPid, modename, buf.data, msecs, usecs)));
+ 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))));
else if (myWaitStatus == STATUS_OK)
ereport(LOG,
(errmsg("process %d acquired %s on %s after %ld.%03d ms",
@@ -1265,7 +1338,10 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
if (deadlock_state != DS_HARD_DEADLOCK)
ereport(LOG,
(errmsg("process %d failed to acquire %s on %s after %ld.%03d ms",
- MyProcPid, modename, buf.data, msecs, usecs)));
+ 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))));
}
/*
@@ -1275,6 +1351,8 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
deadlock_state = DS_NO_DEADLOCK;
pfree(buf.data);
+ pfree(lock_holders_sbuf.data);
+ pfree(lock_waiters_sbuf.data);
}
} while (myWaitStatus == STATUS_WAITING);
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 8705586d565..d28b7494115 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -937,6 +937,28 @@ errdetail_log(const char *fmt,...)
return 0; /* return value does not matter */
}
+/*
+ * errdetail_log_plural --- add a detail_log error message text to the current error
+ * with support for pluralization of the message text
+ */
+int
+errdetail_log_plural(const char *fmt_singular, const char *fmt_plural,
+ unsigned long n,...)
+{
+ ErrorData *edata = &errordata[errordata_stack_depth];
+ MemoryContext oldcontext;
+
+ recursion_depth++;
+ CHECK_STACK_DEPTH();
+ oldcontext = MemoryContextSwitchTo(edata->assoc_context);
+
+ EVALUATE_MESSAGE_PLURAL(edata->domain, detail_log, false);
+
+ MemoryContextSwitchTo(oldcontext);
+ recursion_depth--;
+ return 0; /* return value does not matter */
+}
+
/*
* errdetail_plural --- add a detail error message text to the current error,
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index d7916c22f97..427d52d878c 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -181,6 +181,14 @@ errdetail_log(const char *fmt,...)
the supplied arguments. */
__attribute__((format(PG_PRINTF_ATTRIBUTE, 1, 2)));
+extern int
+errdetail_log_plural(const char *fmt_singular, const char *fmt_plural,
+ unsigned long n,...)
+/* This extension allows gcc to check the format string for consistency with
+ the supplied arguments. */
+__attribute__((format(PG_PRINTF_ATTRIBUTE, 1, 4)))
+__attribute__((format(PG_PRINTF_ATTRIBUTE, 2, 4)));
+
extern int
errdetail_plural(const char *fmt_singular, const char *fmt_plural,
unsigned long n,...)
--
GitLab