Show PIDs of lock holders and waiters in log_lock_waits log message.

Christian Kruse, reviewed by Kumar Rajeev Rastogi.

diff --git a/doc/src/sgml/sources.sgml b/doc/src/sgml/sources.sgml
index 881b0c31a75a92029d5c91d3c2af52d83a154226..aa2080742d48329d277e9766f88f9d4348b7980d 100644 (file)
--- 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 f595a0747c1f775ae021bf2bf6d2a4f65ae236fb..5cd8fcec45064b1c0c7ed99471c086ca8716f174 100644 (file)
--- 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 8705586d5659415ce9ce7df3f656f2f222ada292..d28b74941152673d9d24c51af267fe788c121e6a 100644 (file)
--- 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 d7916c22f97154c206a161b25dc4e0fc149e1174..427d52d878cec4003975abcad7b1a93bea549c7d 100644 (file)
--- 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,...)