Thread: How to investigate deadlocks

How to investigate deadlocks

From

Matthias Apitz

Date:

02 October 2023, 14:27:42

Hello,

One of our clients running our LMS on top of PostgreSQL 13.1 created a
ticket with these messages:

2023-09-30 16:50:50.951 CEST [18117] ERROR:  deadlock detected
2023-09-30 16:50:50.951 CEST [18117] DETAIL:  Process 18117 waits for ShareLock on transaction 150396154; blocked by
process18187.
 
    Process 18187 waits for ShareLock on transaction 150396155; blocked by process 18117.
    Process 18117: fetch hc_d03geb
    Process 18187: fetch hc_d02ben
2023-09-30 16:50:50.951 CEST [18117] HINT:  See server log for query details.
2023-09-30 16:50:50.951 CEST [18117] CONTEXT:  while locking tuple (38,57) in relation "d03geb"
2023-09-30 16:50:50.951 CEST [18117] STATEMENT:  fetch hc_d03geb

The shown PIDs for sure are the ones of the Pos backend proc (on Linux).
Is there any chance to investigate it further?

Thanks

    matthias

-- 
Matthias Apitz, ✉ guru@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub

Re: How to investigate deadlocks

From

Andreas Kretschmer

Date:

02 October 2023, 14:36:02


Am 02.10.23 um 13:27 schrieb Matthias Apitz:
> Hello,
>
> One of our clients running our LMS on top of PostgreSQL 13.1 created a
> ticket with these messages:
>
> 2023-09-30 16:50:50.951 CEST [18117] ERROR:  deadlock detected
> 2023-09-30 16:50:50.951 CEST [18117] DETAIL:  Process 18117 waits for ShareLock on transaction 150396154; blocked by
process18187.
 
>     Process 18187 waits for ShareLock on transaction 150396155; blocked by process 18117.
>     Process 18117: fetch hc_d03geb
>     Process 18187: fetch hc_d02ben
> 2023-09-30 16:50:50.951 CEST [18117] HINT:  See server log for query details.
> 2023-09-30 16:50:50.951 CEST [18117] CONTEXT:  while locking tuple (38,57) in relation "d03geb"
> 2023-09-30 16:50:50.951 CEST [18117] STATEMENT:  fetch hc_d03geb


have you checked the server log?

See server log for query details.



Regards, Andreas

-- 
Andreas Kretschmer
Technical Account Manager (TAM)
www.enterprisedb.com

Re: How to investigate deadlocks

From

Andreas Kretschmer

Date:

02 October 2023, 14:39:00


Am 02.10.23 um 13:27 schrieb Matthias Apitz:
> Hello,
>
> One of our clients running our LMS on top of PostgreSQL 13.1 created a
> ticket with these messages:
>
> 2023-09-30 16:50:50.951 CEST [18117] ERROR:  deadlock detected
> 2023-09-30 16:50:50.951 CEST [18117] DETAIL:  Process 18117 waits for ShareLock on transaction 150396154; blocked by
process18187.
 
>     Process 18187 waits for ShareLock on transaction 150396155; blocked by process 18117.
>     Process 18117: fetch hc_d03geb
>     Process 18187: fetch hc_d02ben
> 2023-09-30 16:50:50.951 CEST [18117] HINT:  See server log for query details.
> 2023-09-30 16:50:50.951 CEST [18117] CONTEXT:  while locking tuple (38,57) in relation "d03geb"
> 2023-09-30 16:50:50.951 CEST [18117] STATEMENT:  fetch hc_d03geb
>
> The shown PIDs for sure are the ones of the Pos backend proc (on Linux).
> Is there any chance to investigate it further?

please also check 
https://www.cybertec-postgresql.com/en/postgresql-understanding-deadlocks/


Andreas

-- 
Andreas Kretschmer
Technical Account Manager (TAM)
www.enterprisedb.com

Re: How to investigate deadlocks

From

Laurenz Albe

Date:

02 October 2023, 17:01:48

On Mon, 2023-10-02 at 13:27 +0200, Matthias Apitz wrote:
> One of our clients running our LMS on top of PostgreSQL 13.1 created a
> ticket with these messages:
>
> 2023-09-30 16:50:50.951 CEST [18117] ERROR:  deadlock detected
> 2023-09-30 16:50:50.951 CEST [18117] DETAIL:  Process 18117 waits for ShareLock on transaction 150396154; blocked by
process18187. 
>         Process 18187 waits for ShareLock on transaction 150396155; blocked by process 18117.
>         Process 18117: fetch hc_d03geb
>         Process 18187: fetch hc_d02ben
> 2023-09-30 16:50:50.951 CEST [18117] HINT:  See server log for query details.
> 2023-09-30 16:50:50.951 CEST [18117] CONTEXT:  while locking tuple (38,57) in relation "d03geb"
> 2023-09-30 16:50:50.951 CEST [18117] STATEMENT:  fetch hc_d03geb
>
> The shown PIDs for sure are the ones of the Pos backend proc (on Linux).
> Is there any chance to investigate it further?

See the line:

  HINT:  See server log for query details.

Other than that, it is difficult to figure out the exact cause of a deadlock.
You need to know all the statements that were run in these transactions,
which probably requires deeper knowledge of the application.

Yours,
Laurenz Albe

Re: How to investigate deadlocks

From

Tom Lane

Date:

02 October 2023, 17:16:18

Matthias Apitz <guru@unixarea.de> writes:
> One of our clients running our LMS on top of PostgreSQL 13.1 created a
> ticket with these messages:

> 2023-09-30 16:50:50.951 CEST [18117] ERROR:  deadlock detected
> 2023-09-30 16:50:50.951 CEST [18117] DETAIL:  Process 18117 waits for ShareLock on transaction 150396154; blocked by
process18187. 
>     Process 18187 waits for ShareLock on transaction 150396155; blocked by process 18117.
>     Process 18117: fetch hc_d03geb
>     Process 18187: fetch hc_d02ben
> 2023-09-30 16:50:50.951 CEST [18117] HINT:  See server log for query details.
> 2023-09-30 16:50:50.951 CEST [18117] CONTEXT:  while locking tuple (38,57) in relation "d03geb"
> 2023-09-30 16:50:50.951 CEST [18117] STATEMENT:  fetch hc_d03geb

> The shown PIDs for sure are the ones of the Pos backend proc (on Linux).
> Is there any chance to investigate it further?

Well, not with this amount of info.  But it seems like a fairly
safe bet that the locks being contended for arise from trying to
SELECT-FOR-UPDATE the same two rows in different orders.
You'd need to look at the cursors being fetched from and see
what you can do to make their row locking orders be reliably
consistent.  Or see if you can avoid needing exclusive row
locks in the first place.

            regards, tom lane

Re: How to investigate deadlocks

From

"David G. Johnston"

Date:

03 October 2023, 01:25:02

On Monday, October 2, 2023, Matthias Apitz <guru@unixarea.de> wrote:

Hello,

One of our clients running our LMS on top of PostgreSQL 13.1 created a
ticket with these messages:

2023-09-30 16:50:50.951 CEST [18117] ERROR: deadlock detected
2023-09-30 16:50:50.951 CEST [18117] DETAIL: Process 18117 waits for ShareLock on transaction 150396154; blocked by process 18187.
Process 18187 waits for ShareLock on transaction 150396155; blocked by process 18117.
Process 18117: fetch hc_d03geb
Process 18187: fetch hc_d02ben
2023-09-30 16:50:50.951 CEST [18117] HINT: See server log for query details.
2023-09-30 16:50:50.951 CEST [18117] CONTEXT: while locking tuple (38,57) in relation "d03geb"
2023-09-30 16:50:50.951 CEST [18117] STATEMENT: fetch hc_d03geb

The shown PIDs for sure are the ones of the Pos backend proc (on Linux).
Is there any chance to investigate it further?

Presuming you control the software performing the fetches, sure. But the database has pretty much told you all it can from its perspective. Start from the two fetches, work out the table/row access ordering, and figure out where you have the same pairs of tables being accessed but in different orders.

David J.