diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 03dccd47f5..1d806bf1b7 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -1,4 +1,4 @@ - + Server Configuration @@ -2947,7 +2947,7 @@ SELECT * FROM parent WHERE key = 2400; - Controls whether a log message is produced when a statement waits + Controls whether a log message is produced when a session waits longer than to acquire a lock. This is useful in determining if lock waits are causing poor performance. The default is off. @@ -4084,11 +4084,18 @@ dynamic_library_path = 'C:\tools\postgresql;H:\my_project\lib;$libdir' wasted in needless deadlock checks, but slows down reporting of real deadlock errors. The default is one second (1s), which is probably about the smallest value you would want in - practice. Set to log deadlock - checks. On a heavily loaded server you might want to raise it. + practice. On a heavily loaded server you might want to raise it. Ideally the setting should exceed your typical transaction time, - so as to improve the odds that a lock will be released before the - waiter decides to check for deadlock. + so as to improve the odds that a lock will be released before + the waiter decides to check for deadlock. + + + + When is set, + this parameter also determines the length of time to wait before + a log message is issued about the lock wait. If you are trying + to investigate locking delays you might want to set a shorter than + normal deadlock_timeout. diff --git a/src/backend/storage/lmgr/deadlock.c b/src/backend/storage/lmgr/deadlock.c index e767de4165..36e1b84a08 100644 --- a/src/backend/storage/lmgr/deadlock.c +++ b/src/backend/storage/lmgr/deadlock.c @@ -12,7 +12,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/storage/lmgr/deadlock.c,v 1.47 2007/04/20 20:15:52 momjian Exp $ + * $PostgreSQL: pgsql/src/backend/storage/lmgr/deadlock.c,v 1.48 2007/06/19 20:13:21 tgl Exp $ * * Interface: * @@ -25,8 +25,8 @@ */ #include "postgres.h" -#include "lib/stringinfo.h" #include "miscadmin.h" +#include "storage/lmgr.h" #include "storage/proc.h" #include "utils/memutils.h" @@ -117,8 +117,9 @@ static int nDeadlockDetails; * allocation of working memory for DeadLockCheck. We do this per-backend * since there's no percentage in making the kernel do copy-on-write * inheritance of workspace from the postmaster. We want to allocate the - * space at startup because the deadlock checker might be invoked when there's - * no free memory left. + * space at startup because (a) the deadlock checker might be invoked when + * there's no free memory left, and (b) the checker is normally run inside a + * signal handler, which is a very dangerous place to invoke palloc from. */ void InitDeadLockChecking(void) @@ -184,17 +185,17 @@ InitDeadLockChecking(void) * * This code looks for deadlocks involving the given process. If any * are found, it tries to rearrange lock wait queues to resolve the - * deadlock. If resolution is impossible, return TRUE --- the caller - * is then expected to abort the given proc's transaction. + * deadlock. If resolution is impossible, return DS_HARD_DEADLOCK --- + * the caller is then expected to abort the given proc's transaction. * - * Caller must already have locked all partitions of the lock tables, - * so standard error logging/reporting code is handled by caller. + * Caller must already have locked all partitions of the lock tables. * * On failure, deadlock details are recorded in deadlockDetails[] for * subsequent printing by DeadLockReport(). That activity is separate - * because we don't want to do it while holding all those LWLocks. + * because (a) we don't want to do it while holding all those LWLocks, + * and (b) we are typically invoked inside a signal handler. */ -DeadlockState +DeadLockState DeadLockCheck(PGPROC *proc) { int i, @@ -205,11 +206,6 @@ DeadLockCheck(PGPROC *proc) nPossibleConstraints = 0; nWaitOrders = 0; -#ifdef LOCK_DEBUG - if (Debug_deadlocks) - DumpAllLocks(); -#endif - /* Search for deadlocks and possible fixes */ if (DeadLockCheckRecurse(proc)) { @@ -256,10 +252,11 @@ DeadLockCheck(PGPROC *proc) ProcLockWakeup(GetLocksMethodTable(lock), lock); } + /* Return code tells caller if we had to escape a deadlock or not */ if (nWaitOrders > 0) return DS_SOFT_DEADLOCK; else - return DS_DEADLOCK_NOT_FOUND; + return DS_NO_DEADLOCK; } /* @@ -833,82 +830,7 @@ PrintLockQueue(LOCK *lock, const char *info) #endif /* - * Append a description of a lockable object to buf. - * - * XXX probably this should be exported from lmgr.c or some such place. - * Ideally we would print names for the numeric values, but that requires - * getting locks on system tables, which might cause problems. - */ -static void -DescribeLockTag(StringInfo buf, const LOCKTAG *lock) -{ - switch (lock->locktag_type) - { - case LOCKTAG_RELATION: - appendStringInfo(buf, - _("relation %u of database %u"), - lock->locktag_field2, - lock->locktag_field1); - break; - case LOCKTAG_RELATION_EXTEND: - appendStringInfo(buf, - _("extension of relation %u of database %u"), - lock->locktag_field2, - lock->locktag_field1); - break; - case LOCKTAG_PAGE: - appendStringInfo(buf, - _("page %u of relation %u of database %u"), - lock->locktag_field3, - lock->locktag_field2, - lock->locktag_field1); - break; - case LOCKTAG_TUPLE: - appendStringInfo(buf, - _("tuple (%u,%u) of relation %u of database %u"), - lock->locktag_field3, - lock->locktag_field4, - lock->locktag_field2, - lock->locktag_field1); - break; - case LOCKTAG_TRANSACTION: - appendStringInfo(buf, - _("transaction %u"), - lock->locktag_field1); - break; - case LOCKTAG_OBJECT: - appendStringInfo(buf, - _("object %u of class %u of database %u"), - lock->locktag_field3, - lock->locktag_field2, - lock->locktag_field1); - break; - case LOCKTAG_USERLOCK: - /* reserved for old contrib code, now on pgfoundry */ - appendStringInfo(buf, - _("user lock [%u,%u,%u]"), - lock->locktag_field1, - lock->locktag_field2, - lock->locktag_field3); - break; - case LOCKTAG_ADVISORY: - appendStringInfo(buf, - _("advisory lock [%u,%u,%u,%u]"), - lock->locktag_field1, - lock->locktag_field2, - lock->locktag_field3, - lock->locktag_field4); - break; - default: - appendStringInfo(buf, - _("unrecognized locktag type %d"), - lock->locktag_type); - break; - } -} - -/* - * Report a detected DS_HARD_DEADLOCK, with available details. + * Report a detected deadlock, with available details. */ void DeadLockReport(void) diff --git a/src/backend/storage/lmgr/lmgr.c b/src/backend/storage/lmgr/lmgr.c index bfcf388943..6f6c609f53 100644 --- a/src/backend/storage/lmgr/lmgr.c +++ b/src/backend/storage/lmgr/lmgr.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/storage/lmgr/lmgr.c,v 1.90 2007/01/05 22:19:38 momjian Exp $ + * $PostgreSQL: pgsql/src/backend/storage/lmgr/lmgr.c,v 1.91 2007/06/19 20:13:21 tgl Exp $ * *------------------------------------------------------------------------- */ @@ -635,3 +635,79 @@ LockTagIsTemp(const LOCKTAG *tag) } return false; /* default case */ } + + +/* + * Append a description of a lockable object to buf. + * + * Ideally we would print names for the numeric values, but that requires + * getting locks on system tables, which might cause problems since this is + * typically used to report deadlock situations. + */ +void +DescribeLockTag(StringInfo buf, const LOCKTAG *tag) +{ + switch (tag->locktag_type) + { + case LOCKTAG_RELATION: + appendStringInfo(buf, + _("relation %u of database %u"), + tag->locktag_field2, + tag->locktag_field1); + break; + case LOCKTAG_RELATION_EXTEND: + appendStringInfo(buf, + _("extension of relation %u of database %u"), + tag->locktag_field2, + tag->locktag_field1); + break; + case LOCKTAG_PAGE: + appendStringInfo(buf, + _("page %u of relation %u of database %u"), + tag->locktag_field3, + tag->locktag_field2, + tag->locktag_field1); + break; + case LOCKTAG_TUPLE: + appendStringInfo(buf, + _("tuple (%u,%u) of relation %u of database %u"), + tag->locktag_field3, + tag->locktag_field4, + tag->locktag_field2, + tag->locktag_field1); + break; + case LOCKTAG_TRANSACTION: + appendStringInfo(buf, + _("transaction %u"), + tag->locktag_field1); + break; + case LOCKTAG_OBJECT: + appendStringInfo(buf, + _("object %u of class %u of database %u"), + tag->locktag_field3, + tag->locktag_field2, + tag->locktag_field1); + break; + case LOCKTAG_USERLOCK: + /* reserved for old contrib code, now on pgfoundry */ + appendStringInfo(buf, + _("user lock [%u,%u,%u]"), + tag->locktag_field1, + tag->locktag_field2, + tag->locktag_field3); + break; + case LOCKTAG_ADVISORY: + appendStringInfo(buf, + _("advisory lock [%u,%u,%u,%u]"), + tag->locktag_field1, + tag->locktag_field2, + tag->locktag_field3, + tag->locktag_field4); + break; + default: + appendStringInfo(buf, + _("unrecognized locktag type %d"), + tag->locktag_type); + break; + } +} diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c index e2b8f22d35..d8cc9e1175 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.188 2007/04/16 18:29:53 alvherre Exp $ + * $PostgreSQL: pgsql/src/backend/storage/lmgr/proc.c,v 1.189 2007/06/19 20:13:21 tgl Exp $ * *------------------------------------------------------------------------- */ @@ -40,6 +40,7 @@ #include "miscadmin.h" #include "postmaster/autovacuum.h" #include "storage/ipc.h" +#include "storage/lmgr.h" #include "storage/proc.h" #include "storage/procarray.h" #include "storage/spin.h" @@ -72,8 +73,12 @@ static LOCALLOCK *lockAwaited = NULL; /* Mark these volatile because they can be changed by signal handler */ static volatile bool statement_timeout_active = false; static volatile bool deadlock_timeout_active = false; +static volatile DeadLockState deadlock_state = DS_NOT_YET_CHECKED; volatile bool cancel_from_timeout = false; +/* timeout_start_time is set when log_lock_waits is true */ +static TimestampTz timeout_start_time; + /* statement_fin_time is valid only if statement_timeout_active is true */ static TimestampTz statement_fin_time; @@ -837,6 +842,9 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable) */ LWLockRelease(partitionLock); + /* Reset deadlock_state before enabling the signal handler */ + deadlock_state = DS_NOT_YET_CHECKED; + /* * Set timer so we can wake up after awhile and check for a deadlock. If a * deadlock is detected, the handler releases the process's semaphore and @@ -869,6 +877,60 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable) do { PGSemaphoreLock(&MyProc->sem, true); + + /* + * If awoken after the deadlock check interrupt has run, and + * log_lock_waits is on, then report about the wait. + */ + if (log_lock_waits) + { + switch (deadlock_state) + { + case DS_NOT_YET_CHECKED: + /* 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 + ereport(LOG, + (errmsg("process %d acquired %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, + msecs, usecs))); + pfree(buf.data); + break; + } + case DS_HARD_DEADLOCK: + /* ERROR will be reported below, so no message here */ + break; + } + } } while (MyProc->waitStatus == STATUS_WAITING); /* @@ -1011,14 +1073,17 @@ ProcLockWakeup(LockMethod lockMethodTable, LOCK *lock) * We only get to this routine if we got SIGALRM after DeadlockTimeout * while waiting for a lock to be released by some other process. Look * to see if there's a deadlock; if not, just return and continue waiting. + * (But signal ProcSleep to log a message, if log_lock_waits is true.) * If we have a real deadlock, remove ourselves from the lock's wait queue * and signal an error to ProcSleep. + * + * NB: this is run inside a signal handler, so be very wary about what is done + * here or in called routines. */ static void CheckDeadLock(void) { int i; - DeadlockState deadlock_state = DS_DEADLOCK_NOT_FOUND; /* * Acquire exclusive lock on the entire shared lock data structures. Must @@ -1044,22 +1109,31 @@ CheckDeadLock(void) * This is quicker than checking our semaphore's state, since no kernel * call is needed, and it is safe because we hold the lock partition lock. */ - if (MyProc->links.prev != INVALID_OFFSET && - MyProc->links.next != INVALID_OFFSET) - deadlock_state = DeadLockCheck(MyProc); - + if (MyProc->links.prev == INVALID_OFFSET || + MyProc->links.next == INVALID_OFFSET) + goto check_done; + +#ifdef LOCK_DEBUG + if (Debug_deadlocks) + DumpAllLocks(); +#endif + + /* Run the deadlock check, and set deadlock_state for use by ProcSleep */ + deadlock_state = DeadLockCheck(MyProc); + if (deadlock_state == DS_HARD_DEADLOCK) { /* * Oops. We have a deadlock. * - * Get this process out of wait state. (Note: we could do this more - * efficiently by relying on lockAwaited, but use this coding to preserve - * the flexibility to kill some other transaction than the one detecting - * the deadlock.) + * Get this process out of wait state. (Note: we could do this more + * efficiently by relying on lockAwaited, but use this coding to + * preserve the flexibility to kill some other transaction than the + * one detecting the deadlock.) * * RemoveFromWaitQueue sets MyProc->waitStatus to STATUS_ERROR, so - * ProcSleep will report an error after we return from the signal handler. + * ProcSleep will report an error after we return from the signal + * handler. */ Assert(MyProc->waitLock != NULL); RemoveFromWaitQueue(MyProc, LockTagHashCode(&(MyProc->waitLock->tag))); @@ -1071,50 +1145,35 @@ CheckDeadLock(void) PGSemaphoreUnlock(&MyProc->sem); /* - * We're done here. Transaction abort caused by the error that ProcSleep - * will raise will cause any other locks we hold to be released, thus - * allowing other processes to wake up; we don't need to do that here. - * NOTE: an exception is that releasing locks we hold doesn't consider the - * possibility of waiters that were blocked behind us on the lock we just - * failed to get, and might now be wakable because we're not in front of - * them anymore. However, RemoveFromWaitQueue took care of waking up any - * such processes. + * We're done here. Transaction abort caused by the error that + * ProcSleep will raise will cause any other locks we hold to be + * released, thus allowing other processes to wake up; we don't need + * to do that here. NOTE: an exception is that releasing locks we + * hold doesn't consider the possibility of waiters that were blocked + * behind us on the lock we just failed to get, and might now be + * wakable because we're not in front of them anymore. However, + * RemoveFromWaitQueue took care of waking up any such processes. */ } + else if (log_lock_waits) + { + /* + * Unlock my semaphore so that the interrupted ProcSleep() call can + * print the log message (we daren't do it here because we are inside + * a signal handler). It will then sleep again until someone + * releases the lock. + */ + PGSemaphoreUnlock(&MyProc->sem); + } /* * Release locks acquired at head of routine. Order is not critical, so * do it back-to-front to avoid waking another CheckDeadLock instance * before it can get all the locks. */ +check_done: for (i = NUM_LOCK_PARTITIONS; --i >= 0;) LWLockRelease(FirstLockMgrLock + i); - - /* - * Issue any log messages requested. - * - * Deadlock ERROR messages are issued as part of transaction abort, so - * these messages should not raise error states intentionally. - */ - if (log_lock_waits) - { - switch (deadlock_state) - { - case DS_SOFT_DEADLOCK: - ereport(LOG, - (errmsg("deadlock avoided by rearranging lock order"))); - break; - case DS_DEADLOCK_NOT_FOUND: - ereport(LOG, - (errmsg("statement waiting for lock for at least %d ms", - DeadlockTimeout))); - break; - case DS_HARD_DEADLOCK: - break; /* ERROR message handled during abort */ - default: - break; - } - } } @@ -1211,8 +1270,8 @@ enable_sig_alarm(int delayms, bool is_statement_timeout) * to the state variables. The deadlock checker may get run earlier * than normal, but that does no harm. */ - fin_time = GetCurrentTimestamp(); - fin_time = TimestampTzPlusMilliseconds(fin_time, delayms); + timeout_start_time = GetCurrentTimestamp(); + fin_time = TimestampTzPlusMilliseconds(timeout_start_time, delayms); deadlock_timeout_active = true; if (fin_time >= statement_fin_time) return true; @@ -1221,6 +1280,9 @@ enable_sig_alarm(int delayms, bool is_statement_timeout) { /* Begin deadlock timeout with no statement-level timeout */ deadlock_timeout_active = true; + /* GetCurrentTimestamp can be expensive, so only do it if we must */ + if (log_lock_waits) + timeout_start_time = GetCurrentTimestamp(); } /* If we reach here, okay to set the timer interrupt */ diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c index f801c060d7..c1e9d8e721 100644 --- a/src/backend/utils/misc/guc.c +++ b/src/backend/utils/misc/guc.c @@ -10,7 +10,7 @@ * Written by Peter Eisentraut . * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/utils/misc/guc.c,v 1.398 2007/06/18 10:02:57 mha Exp $ + * $PostgreSQL: pgsql/src/backend/utils/misc/guc.c,v 1.399 2007/06/19 20:13:22 tgl Exp $ * *-------------------------------------------------------------------- */ @@ -825,13 +825,14 @@ static struct config_bool ConfigureNamesBool[] = #endif { - {"log_lock_waits", PGC_SIGHUP, LOGGING_WHAT, - gettext_noop("Logs long lock wait events."), + {"log_lock_waits", PGC_SUSET, LOGGING_WHAT, + gettext_noop("Logs long lock waits."), NULL }, &log_lock_waits, false, NULL, NULL }, + { {"log_hostname", PGC_SIGHUP, LOGGING_WHAT, gettext_noop("Logs the host name in the connection logs."), diff --git a/src/include/storage/lmgr.h b/src/include/storage/lmgr.h index 19cb9095ad..36474cd278 100644 --- a/src/include/storage/lmgr.h +++ b/src/include/storage/lmgr.h @@ -7,13 +7,14 @@ * Portions Copyright (c) 1996-2007, PostgreSQL Global Development Group * Portions Copyright (c) 1994, Regents of the University of California * - * $PostgreSQL: pgsql/src/include/storage/lmgr.h,v 1.57 2007/01/05 22:19:58 momjian Exp $ + * $PostgreSQL: pgsql/src/include/storage/lmgr.h,v 1.58 2007/06/19 20:13:22 tgl Exp $ * *------------------------------------------------------------------------- */ #ifndef LMGR_H #define LMGR_H +#include "lib/stringinfo.h" #include "storage/lock.h" #include "utils/rel.h" @@ -69,4 +70,7 @@ extern void UnlockSharedObject(Oid classid, Oid objid, uint16 objsubid, /* Knowledge about which locktags describe temp objects */ extern bool LockTagIsTemp(const LOCKTAG *tag); +/* Describe a locktag for error messages */ +extern void DescribeLockTag(StringInfo buf, const LOCKTAG *tag); + #endif /* LMGR_H */ diff --git a/src/include/storage/lock.h b/src/include/storage/lock.h index 559ea1cec3..e2a5bc7b6f 100644 --- a/src/include/storage/lock.h +++ b/src/include/storage/lock.h @@ -7,7 +7,7 @@ * Portions Copyright (c) 1996-2007, PostgreSQL Global Development Group * Portions Copyright (c) 1994, Regents of the University of California * - * $PostgreSQL: pgsql/src/include/storage/lock.h,v 1.105 2007/05/30 16:16:32 tgl Exp $ + * $PostgreSQL: pgsql/src/include/storage/lock.h,v 1.106 2007/06/19 20:13:22 tgl Exp $ * *------------------------------------------------------------------------- */ @@ -397,10 +397,12 @@ typedef enum /* Deadlock states identified by DeadLockCheck() */ typedef enum { - DS_DEADLOCK_NOT_FOUND, /* no deadlock found within database server */ - DS_SOFT_DEADLOCK, /* deadlock, but lock queues rearrangeable */ + DS_NOT_YET_CHECKED, /* no deadlock check has run yet */ + DS_NO_DEADLOCK, /* no deadlock detected */ + DS_SOFT_DEADLOCK, /* deadlock avoided by queue rearrangement */ DS_HARD_DEADLOCK /* deadlock, no way out but ERROR */ -} DeadlockState; +} DeadLockState; + /* * The lockmgr's shared hash tables are partitioned to reduce contention. @@ -449,7 +451,7 @@ extern void lock_twophase_postcommit(TransactionId xid, uint16 info, extern void lock_twophase_postabort(TransactionId xid, uint16 info, void *recdata, uint32 len); -extern DeadlockState DeadLockCheck(PGPROC *proc); +extern DeadLockState DeadLockCheck(PGPROC *proc); extern void DeadLockReport(void); extern void RememberSimpleDeadLock(PGPROC *proc1, LOCKMODE lockmode,