I have applied a modified version of this patch, attached. I trimmed
down the description of log_lock_waits to be more concise, and moved the
idea of using this to tune deadlock_timeout to the deadlock_timeout
section of the manual.
---------------------------------------------------------------------------
Simon Riggs wrote:
> 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
>
[ Attachment, skipping... ]
--
Bruce Momjian <[EMAIL PROTECTED]> http://momjian.us
EnterpriseDB http://www.enterprisedb.com
+ If your life is a hard drive, Christ can be your backup. +
Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.113
diff -c -c -r1.113 config.sgml
*** doc/src/sgml/config.sgml 2 Mar 2007 23:37:22 -0000 1.113
--- doc/src/sgml/config.sgml 3 Mar 2007 18:41:13 -0000
***************
*** 2946,2951 ****
--- 2946,2966 ----
</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 a log message is produced when a statement waits
+ longer than <xref linkend="guc-deadlock-timeout"> to acquire a
+ lock. This is useful in determining if lock waits are causing
+ poor performance. The default is <literal>off</>.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry id="guc-log-temp-files" xreflabel="log_temp_files">
<term><varname>log_temp_files</varname> (<type>integer</type>)</term>
<indexterm>
***************
*** 3980,3996 ****
This is the amount of time, in milliseconds, to wait on a lock
before checking to see if there is a deadlock condition. The
check for deadlock is relatively slow, so the server doesn't run
! it every time it waits for a lock. We (optimistically?) assume
that deadlocks are not common in production applications and
just wait on the lock for a while before starting the check for a
deadlock. Increasing this value reduces the amount of time
wasted in needless deadlock checks, but slows down reporting of
real deadlock errors. The default is one second (<literal>1s</>),
which is probably about the smallest value you would want in
! 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.
</para>
</listitem>
</varlistentry>
--- 3995,4012 ----
This is the amount of time, in milliseconds, to wait on a lock
before checking to see if there is a deadlock condition. The
check for deadlock is relatively slow, so the server doesn't run
! it every time it waits for a lock. We optimistically assume
that deadlocks are not common in production applications and
just wait on the lock for a while before starting the check for a
deadlock. Increasing this value reduces the amount of time
wasted in needless deadlock checks, but slows down reporting of
real deadlock errors. The default is one second (<literal>1s</>),
which is probably about the smallest value you would want in
! practice. Set <xref linkend="guc-log-lock-waits"> to log deadlock
! checks. 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.
</para>
</listitem>
</varlistentry>
Index: src/backend/storage/lmgr/deadlock.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/storage/lmgr/deadlock.c,v
retrieving revision 1.44
diff -c -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 3 Mar 2007 18:41:13 -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: /cvsroot/pgsql/src/backend/storage/lmgr/proc.c,v
retrieving revision 1.184
diff -c -c -r1.184 proc.c
*** src/backend/storage/lmgr/proc.c 15 Feb 2007 23:23:23 -0000 1.184
--- src/backend/storage/lmgr/proc.c 3 Mar 2007 18:41:14 -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(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;
+ }
+ }
}
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/misc/guc.c,v
retrieving revision 1.377
diff -c -c -r1.377 guc.c
*** src/backend/utils/misc/guc.c 23 Feb 2007 21:36:18 -0000 1.377
--- src/backend/utils/misc/guc.c 3 Mar 2007 18:41:16 -0000
***************
*** 812,817 ****
--- 812,825 ----
#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: /cvsroot/pgsql/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.210
diff -c -c -r1.210 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample 2 Mar 2007 23:37:23 -0000 1.210
--- src/backend/utils/misc/postgresql.conf.sample 3 Mar 2007 18:41:16 -0000
***************
*** 340,346 ****
# 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
--- 340,346 ----
# 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: /cvsroot/pgsql/src/include/storage/lock.h,v
retrieving revision 1.103
diff -c -c -r1.103 lock.h
*** src/include/storage/lock.h 5 Jan 2007 22:19:58 -0000 1.103
--- src/include/storage/lock.h 3 Mar 2007 18:41:17 -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: /cvsroot/pgsql/src/include/storage/proc.h,v
retrieving revision 1.94
diff -c -c -r1.94 proc.h
*** src/include/storage/proc.h 15 Feb 2007 23:23:23 -0000 1.94
--- src/include/storage/proc.h 3 Mar 2007 18:41:17 -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 6: explain analyze is your friend
