Hi, On 22/01/14 12:40, Simon Riggs wrote: > > 1. I find a issue in following scenario: > > > > session 1 with process id X: BEGIN; LOCK TABLE foo IN SHARE MODE; > > session 2 with process id Y: BEGIN; LOCK TABLE foo IN EXCLUSIVE > > MODE; > > session 3 with process id Z: BEGIN; LOCK TABLE foo IN SHARE MODE; > > > > On execution of LOCK in session-3, as part of log it will display > > as: > > processes owning lock: X, Y > > But actually if we see Y has not yet own the lock, it is still > > waiting with higher priority. > > It may mislead user. > > May be we should change message to give all meaning i.e. which > > process is owning lock and > > Which process is already in queue. > > Perhaps this? > > CONTEXT: lock owner XXXX request queue XXX, XXX, XXX, etc
Fixed. > > 2. Can we give a better name to new variable 'buf1'? Fixed. > > 3. Do we need to take performance reading to see if any impact? > > Don't think so. Diagnosing problems will help performance, not hinder it I agree. And this code path will only get executed when log_lock_waits = on, which seems to be a debugging method to me. Best regards, -- Christian Kruse http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index ee6c24c..588c4ef 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1195,13 +1195,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);
@@ -1211,10 +1221,58 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
msecs = secs * 1000 + usecs / 1000;
usecs = usecs % 1000;
+ 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),
+ (errcontext(ngettext("process owning lock: %s request queue: %s",
+ "processes owning lock: %s request queue: %s",
+ lockHoldersNum), lock_holders_sbuf.data, lock_waiters_sbuf.data))));
else if (deadlock_state == DS_HARD_DEADLOCK)
{
/*
@@ -1226,13 +1284,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),
+ (errcontext(ngettext("process owning lock: %s request queue: %s",
+ "processes owning lock: %s request 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),
+ (errcontext(ngettext("process owning lock: %s request queue: %s",
+ "processes owning lock: %s request 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",
@@ -1252,7 +1316,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),
+ (errcontext(ngettext("process owning lock: %s request queue: %s",
+ "processes owning lock: %s request queue: %s",
+ lockHoldersNum), lock_holders_sbuf.data, lock_waiters_sbuf.data))));
}
/*
@@ -1262,6 +1329,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);
pgpXJt_sUnnsf.pgp
Description: PGP signature
