From 24d4517b3b98ad02a47cde09976fcdfd25778fc5 Mon Sep 17 00:00:00 2001 From: Tom Lane Date: Tue, 28 Aug 2007 03:23:44 +0000 Subject: [PATCH] Improve behavior of log_lock_waits patch. Ensure that something gets logged even if the "deadlock detected" ERROR message is suppressed by an exception catcher. Be clearer about the event sequence when a soft deadlock is fixed: the fixing process might or might not still have to wait, so log that separately. Fix race condition when someone releases us from the lock partway through printing all this junk --- we'd not get confused about our state, but the log message sequence could have been misleading, ie, a "still waiting" message with no subsequent "acquired" message. Greg Stark and Tom Lane. --- src/backend/storage/lmgr/proc.c | 122 +++++++++++++++++++------------- 1 file changed, 74 insertions(+), 48 deletions(-) diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c index 6e7efe6d6c..048fa31bcc 100644 --- a/src/backend/storage/lmgr/proc.c +++ b/src/backend/storage/lmgr/proc.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/storage/lmgr/proc.c,v 1.191 2007/07/16 21:09:50 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/storage/lmgr/proc.c,v 1.192 2007/08/28 03:23:44 tgl Exp $ * *------------------------------------------------------------------------- */ @@ -727,6 +727,7 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable) PROC_QUEUE *waitQueue = &(lock->waitProcs); LOCKMASK myHeldLocks = MyProc->heldLocks; bool early_deadlock = false; + int myWaitStatus; PGPROC *proc; int i; @@ -878,61 +879,86 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable) { PGSemaphoreLock(&MyProc->sem, true); + /* + * waitStatus could change from STATUS_WAITING to something else + * asynchronously. Read it just once per loop to prevent surprising + * behavior (such as missing log messages). + */ + myWaitStatus = MyProc->waitStatus; + /* * If awoken after the deadlock check interrupt has run, and * log_lock_waits is on, then report about the wait. */ - if (log_lock_waits) + if (log_lock_waits && deadlock_state != DS_NOT_YET_CHECKED) { - switch (deadlock_state) + StringInfoData buf; + const char *modename; + long secs; + int usecs; + long msecs; + + initStringInfo(&buf); + DescribeLockTag(&buf, &locallock->tag.lock); + modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, + lockmode); + TimestampDifference(timeout_start_time, GetCurrentTimestamp(), + &secs, &usecs); + msecs = secs * 1000 + usecs / 1000; + usecs = usecs % 1000; + + 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))); + else if (deadlock_state == DS_HARD_DEADLOCK) { - case DS_NOT_YET_CHECKED: - /* Lock granted, or spurious wakeup as described above */ - break; - case DS_NO_DEADLOCK: - case DS_SOFT_DEADLOCK: - { - StringInfoData buf; - const char *modename; - long secs; - int usecs; - long msecs; - - initStringInfo(&buf); - DescribeLockTag(&buf, &locallock->tag.lock); - modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, - lockmode); - TimestampDifference(timeout_start_time, - GetCurrentTimestamp(), - &secs, &usecs); - msecs = secs * 1000 + usecs / 1000; - usecs = usecs % 1000; - - if (deadlock_state == DS_SOFT_DEADLOCK) - ereport(LOG, - (errmsg("deadlock for %s on %s avoided by rearranging queue order after %ld.%03d ms", - modename, buf.data, - msecs, usecs))); - else if (MyProc->waitStatus == STATUS_WAITING) - ereport(LOG, - (errmsg("process %d still waiting for %s on %s after %ld.%03d ms", - MyProcPid, modename, buf.data, - msecs, usecs))); - else if (MyProc->waitStatus == STATUS_OK) - ereport(LOG, - (errmsg("process %d acquired %s on %s after %ld.%03d ms", - MyProcPid, modename, buf.data, - msecs, usecs))); - /* ERROR will be reported later, so no message here */ - pfree(buf.data); - break; - } - case DS_HARD_DEADLOCK: - /* ERROR will be reported later, so no message here */ - break; + /* + * This message is a bit redundant with the error that will + * be reported subsequently, but in some cases the error + * report might not make it to the log (eg, if it's caught by + * an exception handler), and we want to ensure all long-wait + * events get logged. + */ + ereport(LOG, + (errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs))); } + + 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))); + else if (myWaitStatus == STATUS_OK) + ereport(LOG, + (errmsg("process %d acquired %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs))); + else + { + Assert(myWaitStatus == STATUS_ERROR); + /* + * Currently, the deadlock checker always kicks its own + * process, which means that we'll only see STATUS_ERROR + * when deadlock_state == DS_HARD_DEADLOCK, and there's no + * need to print redundant messages. But for completeness + * and future-proofing, print a message if it looks like + * someone else kicked us off the lock. + */ + 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))); + } + + /* + * At this point we might still need to wait for the lock. + * Reset state so we don't print the above messages again. + */ + deadlock_state = DS_NO_DEADLOCK; + + pfree(buf.data); } - } while (MyProc->waitStatus == STATUS_WAITING); + } while (myWaitStatus == STATUS_WAITING); /* * Disable the timer, if it's still running -- GitLab