On Mon, 2007-02-19 at 19:38 +0000, Simon Riggs wrote:
> On Tue, 2007-02-13 at 22:19 -0500, Bruce Momjian wrote:
> > Simon Riggs wrote:
> > > On Thu, 2006-10-26 at 18:45 -0400, Tom Lane wrote:
> > > > Chris Campbell <[EMAIL PROTECTED]> writes:
> > > > > Is there additional logging information I can turn on to get more
> > > > > details? I guess I need to see exactly what locks both processes
> > > > > hold, and what queries they were running when the deadlock occurred?
> > > > > Is that easily done, without turning on logging for *all* statements?
> > > >
> > > > log_min_error_statement = error would at least get you the statements
> > > > reporting the deadlocks, though not what they're conflicting against.
> > >
> > > Yeh, we need a much better locking logger for performance analysis.
> > >
> > > We really need to dump the whole wait-for graph for deadlocks, since
> > > this might be more complex than just two statements involved. Deadlocks
> > > ought to be so infrequent that we can afford the log space to do this -
> > > plus if we did this it would likely lead to fewer deadlocks.
> > >
> > > For 8.3 I'd like to have a log_min_duration_lockwait (secs) parameter
> > > that would allow you to dump the wait-for graph for any data-level locks
> > > that wait too long, rather than just those that deadlock. Many
> > > applications experience heavy locking because of lack of holistic
> > > design. That will also show up the need for other utilities to act
> > > CONCURRENTLY, if possible.
> >
> > Old email, but I don't see how our current output is not good enough?
> >
> > test=> lock a;
> > ERROR: deadlock detected
> > DETAIL: Process 6855 waits for AccessExclusiveLock on relation 16394 of
> > database 16384; blocked by process 6795.
> > Process 6795 waits for AccessExclusiveLock on relation 16396 of database
> > 16384; blocked by process 6855.
>
> This detects deadlocks, but it doesn't detect lock waits.
>
> When I wrote that it was previous experience driving me. Recent client
> experience has highlighted the clear need for this. We had a lock wait
> of 50 hours because of an RI check; thats the kind of thing I'd like to
> show up in the logs somewhere.
>
> Lock wait detection can be used to show up synchronisation points that
> have been inadvertently designed into an application, so its a useful
> tool in investigating performance issues.
>
> I have a patch implementing the logging as agreed with Tom, will post to
> patches later tonight.
Patch for discussion, includes doc entries at top of patch, so its
fairly clear how it works.
Output is an INFO message, to allow this to trigger
log_min_error_statement when it generates a message, to allow us to see
the SQL statement that is waiting. This allows it to generate a message
prior to the statement completing, which is important because it may not
ever complete, in some cases, so simply logging a list of pids won't
always tell you what the SQL was that was waiting.
Other approaches are possible...
Comments?
--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com
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 ----
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-lock-waits" xreflabel="log_lock_waits">
+ <term><varname>log_lock_waits</varname> (<type>boolean</type>)</term>
+ <indexterm>
+ <primary><varname>log_lock_waits</> configuration parameter</primary>
+ </indexterm>
+ <listitem>
+ <para>
+ 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 <xref linkend="guc-deadlock-timeout"> 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 <varname>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 <varname>deadlock_timeout</>
+ could be set higher. Log messages might also indicate that certain
+ deadlocks have been avoided. In those cases, decreasing the value of
+ <varname>deadlock_timeout</> might resolve lock wait situations faster,
+ thereby reducing contention. By default, this form of logging is <literal>off</>.
+ </para>
+ </listitem>
+ </varlistentry>
+
</variablelist>
</sect2>
</sect1>
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;
---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?
http://archives.postgresql.org
