Обсуждение: Logging conflicted queries on deadlocks

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

ITAGAKI Takahiro wrote:

> 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;

Cute.

> 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.

Perhaps it could be shown in CONTEXT, like so:

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

I think it's useful to show the PID of each statement, for the case
where there are more than two processes deadlocked.

-- 
Alvaro Herrera                                http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

ITAGAKI Takahiro wrote:

> 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.

Hm, your patches crashes for me when there are 3 sessions deadlocked.

-- 
Alvaro Herrera                                http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support