Logging conflicted queries on deadlocks

From: ITAGAKI Takahiro <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp>
To: pgsql-hackers(at)postgresql(dot)org
Subject: Logging conflicted queries on deadlocks
Date: 2008-02-28 08:46:04
Message-ID: 20080228165156.5F4E.52131E4D@oss.ntt.co.jp
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers pgsql-patches

Hello,

We see error logs something like following on deadlocks:

| ERROR: deadlock detected
| DETAIL: Process 1612 waits for ShareLock on transaction 407; blocked by process 3388.
| Process 3388 waits for ShareLock on transaction 406; blocked by process 1612.
| STATEMENT: UPDATE test SET i = i WHERE i = 2;

It shows which query is killed, but we cannot get which query is conflicted.
The opponent's queries are useful for deadlock debug, but the only thing
we can do for now is polling pg_locks and pg_stat_sctivity with hope to
take a snapshot of the system just on deadlocks.

I wrote a small patch to log conflicted queries.
With my patch, deadlock message will change as following:

| ERROR: deadlock detected
| DETAIL: Process 3468 waits for ShareLock on transaction 451; blocked by process 4068.
| STATEMENT: UPDATE test SET i = i WHERE i = 1; <- ***conflicted query***
| Process 4068 waits for ShareLock on transaction 450; blocked by process 3468.
| STATEMENT: UPDATE test SET i = i WHERE i = 2;

There are some open issues. One of the issues is that the killed query is
logged by log_min_error_statement, but conflicted query is logged in DETAIL.
Killed query is logged only on server but conflicted queries are
sent to both server and client. In addition, if log_min_error_statement
is less than ERROR level, only the conflicted queries are logged.
-- it's inconsistent and unsymmetric.

Are there any better format to dump conflicted queries?
Comments welcome.

[[10-line patch to log conflicted query on deadlocks]]
Index: src/backend/storage/lmgr/deadlock.c
===================================================================
--- src/backend/storage/lmgr/deadlock.c (HEAD)
+++ src/backend/storage/lmgr/deadlock.c (working copy)
@@ -911,6 +913,18 @@
info->lockmode),
buf2.data,
nextpid);
+
+ if (nextpid != MyProcPid)
+ {
+ PGPROC* proc = BackendPidGetProc(nextpid);
+ if (proc != NULL && (superuser() || proc->roleId == GetUserId()))
+ {
+ PgBackendStatus *beentry;
+ beentry = pgstat_fetch_stat_beentry(proc->backendId);
+ if (beentry && beentry->st_activity[0] != '\0')
+ appendStringInfo(&buf, "\nSTATEMENT: %s", beentry->st_activity);
+ }
+ }
}
ereport(ERROR,
(errcode(ERRCODE_T_R_DEADLOCK_DETECTED),

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Pavan Deolasee 2008-02-28 09:08:51 CREATE TABLE, load and freezing
Previous Message ITAGAKI Takahiro 2008-02-28 07:14:23 Re: Batch update of indexes on data loading

Browse pgsql-patches by date

  From Date Subject
Next Message Zdeněk Kotala 2008-02-28 11:54:11 Re: lc_time and localized dates
Previous Message Robert Lor 2008-02-28 04:26:46 Re: DTrace probe patch for OS X Leopard