Re: [HACKERS] Deadlock with pg_dump?

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 <chris(at)bignerdranch(dot)com> 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