postmortem deadlock debugging in PostgreSQL

Question

I want to collect post-mortem debugging information about both the "winner" transaction and the "loser" transaction(s) in a PostgreSQL deadlock.

• I found this wiki page which includes some good live views that would give hints about what is currently going wrong, but if I understand correctly, by the time the losing transaction is already being rolled back most of the most useful information will already have been removed from these live views.
• I saw options such as deadlock_timeout and log_lock_waits which log information about the losing transaction, but notably not the winning transaction. There doesn't appear to be any way to customize the log output produced to include more detailed information than this (notably, none of these integers mean anything when I'm debugging based on logs after the fact): LOG: process 11367 still waiting for ShareLock on transaction 717 after 1000.108 ms DETAIL: Process holding the lock: 11366. Wait queue: 11367. CONTEXT: while updating tuple (0,2) in relation "foo" STATEMENT: UPDATE foo SET value = 3;

Is there a better data source I can use to collect this information?

Madore

The simplest thing would be to simply log everything about every transaction, and dig up the history of the competing process after the fact. Is that an option? – Actinomorphic

Now that I think about it, by the time you hit the deadlock_timeout, all processes involved should have triggered log_lock_waits. What information are you missing? – Actinomorphic

Answer 1

First, the trace pasted into the question is not a deadlock trace, rather a warning about locks on resources that aren't available since long enough (longer than deadlock_timeout). It's not an error and it does not abort a transaction, whereas a deadlock is fatal to a transaction.

I want to collect post-mortem debugging information about both the "winner" transaction and the "loser" transaction(s) in a PostgreSQL deadlock.

They are in the server log, along with the query that gets terminated.

As an example, here's a deadlock trace with log_line_prefix = '%t [%p] ' for the case mentioned in this question: postgres deadlock without explicit locking

2015-04-09 15:16:42 CEST [21689] ERROR:  deadlock detected
2015-04-09 15:16:42 CEST [21689] DETAIL:  Process 21689 waits for ShareLock on transaction 1866436; blocked by process 21028.
    Process 21028 waits for ShareLock on transaction 1866435; blocked by process 21689.
    Process 21689: insert into b values(1);
    Process 21028: insert into a values(1);
2015-04-09 15:16:42 CEST [21689] HINT:  See server log for query details.
2015-04-09 15:16:42 CEST [21689] STATEMENT:  insert into b values(1);

The "looser" is PID 21689 as the producer of the error. The "winner" is PID 21028 by virtue of just being the other one.

If looking at it from the point of the view of the client, its gets this mesage:

ERROR:  deadlock detected
DETAIL:  Process 21689 waits for ShareLock on transaction 1866436; blocked by process 21028.
Process 21028 waits for ShareLock on transaction 1866435; blocked by process 21689.
HINT:  See server log for query details.

There is no mention of the query, but that's the one that client just sent. There is no mention of the looser, but it's the one which gets this error, the other one doesn't have to notice anything.

Leanto

Thanks, this certainly answers my question about deadlocks. Is there any similar strategy for related classes of issues (i.e. serialization problems when you have isolation level = REPEATABLE READ or SERIALIZABLE)? – Madore

Nothing similar but you'll be interested in reading wiki.postgresql.org/wiki/SSI – Gastroenterology