Index: doc/src/sgml/config.sgml =================================================================== RCS file: /projects/cvsroot/pgsql/doc/src/sgml/config.sgml,v retrieving revision 1.108 diff -c -r1.108 config.sgml *** doc/src/sgml/config.sgml 1 Feb 2007 00:28:16 -0000 1.108 --- doc/src/sgml/config.sgml 6 Feb 2007 12:31:49 -0000 *************** *** 2936,2941 **** --- 2936,2965 ---- + + log_lock_waits (boolean) + + log_lock_waits configuration parameter + + + + Controls whether log messages are produced when a statement is forced + to wait when trying to acquire locks on database objects. The threshold + time is the value of the parameter. + The log messages generated are intended for use during specific + investigations into application performance issues and subsequent tuning. + It is designed for use in conjunction with log_min_error_statement. + Log messages indicating long lock waits might indicate problems with + applications accessing the database or possibly disconnection issues. + If no such problem exist it might indicate that deadlock_timeout + could be set higher. Log messages might also indicate that certain + deadlocks have been avoided. In those cases, decreasing the value of + deadlock_timeout might resolve lock wait situations faster, + thereby reducing contention. By default, this form of logging is off. + + + + Index: src/backend/storage/lmgr/deadlock.c =================================================================== RCS file: /projects/cvsroot/pgsql/src/backend/storage/lmgr/deadlock.c,v retrieving revision 1.44 diff -c -r1.44 deadlock.c *** src/backend/storage/lmgr/deadlock.c 5 Jan 2007 22:19:38 -0000 1.44 --- src/backend/storage/lmgr/deadlock.c 6 Feb 2007 12:31:55 -0000 *************** *** 187,199 **** * deadlock. If resolution is impossible, return TRUE --- the caller * is then expected to abort the given proc's transaction. * ! * 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. */ ! bool DeadLockCheck(PGPROC *proc) { int i, --- 187,200 ---- * deadlock. If resolution is impossible, return TRUE --- 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. * * 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. */ ! DeadlockState DeadLockCheck(PGPROC *proc) { int i, *************** *** 204,209 **** --- 205,215 ---- nPossibleConstraints = 0; nWaitOrders = 0; + #ifdef LOCK_DEBUG + if (Debug_deadlocks) + DumpAllLocks(); + #endif + /* Search for deadlocks and possible fixes */ if (DeadLockCheckRecurse(proc)) { *************** *** 217,223 **** if (!FindLockCycle(proc, possibleConstraints, &nSoftEdges)) elog(FATAL, "deadlock seems to have disappeared"); ! return true; /* cannot find a non-deadlocked state */ } /* Apply any needed rearrangements of wait queues */ --- 223,229 ---- if (!FindLockCycle(proc, possibleConstraints, &nSoftEdges)) elog(FATAL, "deadlock seems to have disappeared"); ! return DS_HARD_DEADLOCK; /* cannot find a non-deadlocked state */ } /* Apply any needed rearrangements of wait queues */ *************** *** 249,255 **** /* See if any waiters for the lock can be woken up now */ ProcLockWakeup(GetLocksMethodTable(lock), lock); } ! return false; } /* --- 255,265 ---- /* See if any waiters for the lock can be woken up now */ ProcLockWakeup(GetLocksMethodTable(lock), lock); } ! ! if (nWaitOrders > 0) ! return DS_SOFT_DEADLOCK; ! else ! return DS_DEADLOCK_NOT_FOUND; } /* *************** *** 896,902 **** } /* ! * Report a detected deadlock, with available details. */ void DeadLockReport(void) --- 906,912 ---- } /* ! * Report a detected DS_HARD_DEADLOCK, with available details. */ void DeadLockReport(void) Index: src/backend/storage/lmgr/proc.c =================================================================== RCS file: /projects/cvsroot/pgsql/src/backend/storage/lmgr/proc.c,v retrieving revision 1.183 diff -c -r1.183 proc.c *** src/backend/storage/lmgr/proc.c 16 Jan 2007 13:28:56 -0000 1.183 --- src/backend/storage/lmgr/proc.c 6 Feb 2007 12:31:55 -0000 *************** *** 48,53 **** --- 48,54 ---- /* GUC variables */ int DeadlockTimeout = 1000; int StatementTimeout = 0; + bool log_lock_waits = false; /* Pointer to this process's PGPROC struct, if any */ PGPROC *MyProc = NULL; *************** *** 979,984 **** --- 980,986 ---- CheckDeadLock(void) { int i; + DeadlockState deadlock_state = DS_DEADLOCK_NOT_FOUND; /* * Acquire exclusive lock on the entire shared lock data structures. Must *************** *** 1004,1063 **** * 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) ! goto check_done; ! ! #ifdef LOCK_DEBUG ! if (Debug_deadlocks) ! DumpAllLocks(); ! #endif ! ! if (!DeadLockCheck(MyProc)) { ! /* No deadlock, so keep waiting */ ! goto check_done; ! } ! ! /* ! * 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.) ! * ! * RemoveFromWaitQueue sets MyProc->waitStatus to STATUS_ERROR, so ! * ProcSleep will report an error after we return from the signal handler. ! */ ! Assert(MyProc->waitLock != NULL); ! RemoveFromWaitQueue(MyProc, LockTagHashCode(&(MyProc->waitLock->tag))); ! /* ! * Unlock my semaphore so that the interrupted ProcSleep() call can ! * finish. ! */ ! 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. ! */ /* * 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); } --- 1006,1082 ---- * 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 (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.) ! * ! * RemoveFromWaitQueue sets MyProc->waitStatus to STATUS_ERROR, so ! * ProcSleep will report an error after we return from the signal handler. ! */ ! Assert(MyProc->waitLock != NULL); ! RemoveFromWaitQueue(MyProc, LockTagHashCode(&(MyProc->waitLock->tag))); ! /* ! * Unlock my semaphore so that the interrupted ProcSleep() call can ! * finish. ! */ ! 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. ! */ ! } /* * 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. */ 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(INFO, + (errmsg("deadlock avoided by rearrangement of lock order"))); + break; + case DS_DEADLOCK_NOT_FOUND: + ereport(INFO, + (errmsg("statement waiting for lock for at least %d ms", + DeadlockTimeout))); + break; + case DS_HARD_DEADLOCK: + break; /* ERROR message handled during abort */ + default: + break; + } + } } Index: src/backend/utils/misc/guc.c =================================================================== RCS file: /projects/cvsroot/pgsql/src/backend/utils/misc/guc.c,v retrieving revision 1.372 diff -c -r1.372 guc.c *** src/backend/utils/misc/guc.c 1 Feb 2007 19:10:28 -0000 1.372 --- src/backend/utils/misc/guc.c 6 Feb 2007 12:32:01 -0000 *************** *** 807,812 **** --- 807,820 ---- #endif { + {"log_lock_waits", PGC_SIGHUP, LOGGING_WHAT, + gettext_noop("Logs long lock wait events."), + NULL + }, + &log_lock_waits, + false, NULL, NULL + }, + { {"log_hostname", PGC_SIGHUP, LOGGING_WHAT, gettext_noop("Logs the host name in the connection logs."), gettext_noop("By default, connection logs only show the IP address " Index: src/backend/utils/misc/postgresql.conf.sample =================================================================== RCS file: /projects/cvsroot/pgsql/src/backend/utils/misc/postgresql.conf.sample,v retrieving revision 1.207 diff -c -r1.207 postgresql.conf.sample *** src/backend/utils/misc/postgresql.conf.sample 25 Jan 2007 15:05:15 -0000 1.207 --- src/backend/utils/misc/postgresql.conf.sample 6 Feb 2007 12:32:01 -0000 *************** *** 335,341 **** # e.g. '<%u%%%d> ' #log_statement = 'none' # none, ddl, mod, all #log_hostname = off ! #log_temp_files = -1 # Log temporary files equal or larger # than the specified number of kilobytes. # -1 disables; 0 logs all temp files --- 335,341 ---- # e.g. '<%u%%%d> ' #log_statement = 'none' # none, ddl, mod, all #log_hostname = off ! #log_lock_waits = off # Log lock waits longer than deadlock_timeout #log_temp_files = -1 # Log temporary files equal or larger # than the specified number of kilobytes. # -1 disables; 0 logs all temp files Index: src/include/storage/lock.h =================================================================== RCS file: /projects/cvsroot/pgsql/src/include/storage/lock.h,v retrieving revision 1.103 diff -c -r1.103 lock.h *** src/include/storage/lock.h 5 Jan 2007 22:19:58 -0000 1.103 --- src/include/storage/lock.h 6 Feb 2007 12:32:07 -0000 *************** *** 394,399 **** --- 394,406 ---- LOCKACQUIRE_ALREADY_HELD /* incremented count for lock already held */ } LockAcquireResult; + /* 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_HARD_DEADLOCK /* deadlock, no way out but ERROR */ + } DeadlockState; /* * The lockmgr's shared hash tables are partitioned to reduce contention. *************** *** 442,448 **** extern void lock_twophase_postabort(TransactionId xid, uint16 info, void *recdata, uint32 len); ! extern bool DeadLockCheck(PGPROC *proc); extern void DeadLockReport(void); extern void RememberSimpleDeadLock(PGPROC *proc1, LOCKMODE lockmode, --- 449,455 ---- extern void lock_twophase_postabort(TransactionId xid, uint16 info, void *recdata, uint32 len); ! extern DeadlockState DeadLockCheck(PGPROC *proc); extern void DeadLockReport(void); extern void RememberSimpleDeadLock(PGPROC *proc1, LOCKMODE lockmode, Index: src/include/storage/proc.h =================================================================== RCS file: /projects/cvsroot/pgsql/src/include/storage/proc.h,v retrieving revision 1.93 diff -c -r1.93 proc.h *** src/include/storage/proc.h 16 Jan 2007 13:28:57 -0000 1.93 --- src/include/storage/proc.h 6 Feb 2007 12:32:07 -0000 *************** *** 127,132 **** --- 127,133 ---- /* configurable options */ extern int DeadlockTimeout; extern int StatementTimeout; + extern bool log_lock_waits; extern volatile bool cancel_from_timeout;