Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly
Appearance settings

Commit 24d4517

Browse filesBrowse files
tglsfdctglsfdc
committed
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.
1 parent baf3a13 commit 24d4517
Copy full SHA for 24d4517

File tree

Expand file treeCollapse file tree

1 file changed

+74
-48
lines changed
Filter options
  • src/backend/storage/lmgr
Expand file treeCollapse file tree

1 file changed

+74
-48
lines changed

‎src/backend/storage/lmgr/proc.c

Copy file name to clipboardExpand all lines: src/backend/storage/lmgr/proc.c
+74-48Lines changed: 74 additions & 48 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@
88
*
99
*
1010
* IDENTIFICATION
11-
* $PostgreSQL: pgsql/src/backend/storage/lmgr/proc.c,v 1.191 2007/07/16 21:09:50 tgl Exp $
11+
* $PostgreSQL: pgsql/src/backend/storage/lmgr/proc.c,v 1.192 2007/08/28 03:23:44 tgl Exp $
1212
*
1313
*-------------------------------------------------------------------------
1414
*/
@@ -727,6 +727,7 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
727727
PROC_QUEUE *waitQueue = &(lock->waitProcs);
728728
LOCKMASK myHeldLocks = MyProc->heldLocks;
729729
bool early_deadlock = false;
730+
int myWaitStatus;
730731
PGPROC *proc;
731732
int i;
732733

@@ -878,61 +879,86 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
878879
{
879880
PGSemaphoreLock(&MyProc->sem, true);
880881

882+
/*
883+
* waitStatus could change from STATUS_WAITING to something else
884+
* asynchronously. Read it just once per loop to prevent surprising
885+
* behavior (such as missing log messages).
886+
*/
887+
myWaitStatus = MyProc->waitStatus;
888+
881889
/*
882890
* If awoken after the deadlock check interrupt has run, and
883891
* log_lock_waits is on, then report about the wait.
884892
*/
885-
if (log_lock_waits)
893+
if (log_lock_waits && deadlock_state != DS_NOT_YET_CHECKED)
886894
{
887-
switch (deadlock_state)
895+
StringInfoData buf;
896+
const char *modename;
897+
long secs;
898+
int usecs;
899+
long msecs;
900+
901+
initStringInfo(&buf);
902+
DescribeLockTag(&buf, &locallock->tag.lock);
903+
modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid,
904+
lockmode);
905+
TimestampDifference(timeout_start_time, GetCurrentTimestamp(),
906+
&secs, &usecs);
907+
msecs = secs * 1000 + usecs / 1000;
908+
usecs = usecs % 1000;
909+
910+
if (deadlock_state == DS_SOFT_DEADLOCK)
911+
ereport(LOG,
912+
(errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms",
913+
MyProcPid, modename, buf.data, msecs, usecs)));
914+
else if (deadlock_state == DS_HARD_DEADLOCK)
888915
{
889-
case DS_NOT_YET_CHECKED:
890-
/* Lock granted, or spurious wakeup as described above */
891-
break;
892-
case DS_NO_DEADLOCK:
893-
case DS_SOFT_DEADLOCK:
894-
{
895-
StringInfoData buf;
896-
const char *modename;
897-
long secs;
898-
int usecs;
899-
long msecs;
900-
901-
initStringInfo(&buf);
902-
DescribeLockTag(&buf, &locallock->tag.lock);
903-
modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid,
904-
lockmode);
905-
TimestampDifference(timeout_start_time,
906-
GetCurrentTimestamp(),
907-
&secs, &usecs);
908-
msecs = secs * 1000 + usecs / 1000;
909-
usecs = usecs % 1000;
910-
911-
if (deadlock_state == DS_SOFT_DEADLOCK)
912-
ereport(LOG,
913-
(errmsg("deadlock for %s on %s avoided by rearranging queue order after %ld.%03d ms",
914-
modename, buf.data,
915-
msecs, usecs)));
916-
else if (MyProc->waitStatus == STATUS_WAITING)
917-
ereport(LOG,
918-
(errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
919-
MyProcPid, modename, buf.data,
920-
msecs, usecs)));
921-
else if (MyProc->waitStatus == STATUS_OK)
922-
ereport(LOG,
923-
(errmsg("process %d acquired %s on %s after %ld.%03d ms",
924-
MyProcPid, modename, buf.data,
925-
msecs, usecs)));
926-
/* ERROR will be reported later, so no message here */
927-
pfree(buf.data);
928-
break;
929-
}
930-
case DS_HARD_DEADLOCK:
931-
/* ERROR will be reported later, so no message here */
932-
break;
916+
/*
917+
* This message is a bit redundant with the error that will
918+
* be reported subsequently, but in some cases the error
919+
* report might not make it to the log (eg, if it's caught by
920+
* an exception handler), and we want to ensure all long-wait
921+
* events get logged.
922+
*/
923+
ereport(LOG,
924+
(errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms",
925+
MyProcPid, modename, buf.data, msecs, usecs)));
933926
}
927+
928+
if (myWaitStatus == STATUS_WAITING)
929+
ereport(LOG,
930+
(errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
931+
MyProcPid, modename, buf.data, msecs, usecs)));
932+
else if (myWaitStatus == STATUS_OK)
933+
ereport(LOG,
934+
(errmsg("process %d acquired %s on %s after %ld.%03d ms",
935+
MyProcPid, modename, buf.data, msecs, usecs)));
936+
else
937+
{
938+
Assert(myWaitStatus == STATUS_ERROR);
939+
/*
940+
* Currently, the deadlock checker always kicks its own
941+
* process, which means that we'll only see STATUS_ERROR
942+
* when deadlock_state == DS_HARD_DEADLOCK, and there's no
943+
* need to print redundant messages. But for completeness
944+
* and future-proofing, print a message if it looks like
945+
* someone else kicked us off the lock.
946+
*/
947+
if (deadlock_state != DS_HARD_DEADLOCK)
948+
ereport(LOG,
949+
(errmsg("process %d failed to acquire %s on %s after %ld.%03d ms",
950+
MyProcPid, modename, buf.data, msecs, usecs)));
951+
}
952+
953+
/*
954+
* At this point we might still need to wait for the lock.
955+
* Reset state so we don't print the above messages again.
956+
*/
957+
deadlock_state = DS_NO_DEADLOCK;
958+
959+
pfree(buf.data);
934960
}
935-
} while (MyProc->waitStatus == STATUS_WAITING);
961+
} while (myWaitStatus == STATUS_WAITING);
936962

937963
/*
938964
* Disable the timer, if it's still running

0 commit comments

Comments
0 (0)
Morty Proxy This is a proxified and sanitized view of the page, visit original site.