Repeated, never-ending deadlock

From: andrew cooke <andrew(at)acooke(dot)org>
To: pgsql-general(at)postgresql(dot)org
Subject: Repeated, never-ending deadlock
Date: 2022-04-19 20:28:51
Message-ID: 20220419202851.5utfi4pangkyt4sd@acooke.org
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general


Hi All,

OK, apologies in advance, I feel like this is a rather unintelligent
question that I probably know the answer to, but I am banging my head
against a wall trying to understand what is happening.

I have an ETL program, written in Python, that uses mutiple processes
to read and load a bunch of files into a database. Sometimes
(especially early on, when the database is new) common information
that occurs in several files, and which is normalized out into
sub-tables, causes deadlocks. That's OK; the code should receive an
exception, back off, try again, reading first, etc. And I see
exceptions occuring in the Python code log as expected.

However, today, I saw the same deadlock error repeated in the Postgres
log every second for minutes. The same two processes, with the same
data, and the same tables. I can't work out how this can happen
without a crazy tight loop in the Python code that's just repeatedly
trying to commit a value (which afaik doesn't exist!) A fragment of
the Postgres log is below. The Python logs show nothing.

So my question is - is there some circumstance where instead of
raising an error to the calling code, Postgres instead goes round in
circles?

An answer of "nope, it must be a bug in your code" is fine / expected.
It's just one of those days...

This is Postgres 14 with a fairly default config (except that logical
replication is enabled).

Thanks,
Andrew

2022-04-19 19:55:54.482 UTC [28560] ERROR: deadlock detected
2022-04-19 19:55:54.482 UTC [28560] DETAIL: Process 28560 waits for ShareLock on transaction 609318483; blocked by process 28559.
Process 28559 waits for ShareLock on transaction 609318682; blocked by process 28560.
Process 28560: INSERT INTO channel_nscl (net, sta, chan, loc) VALUES ('AZ', 'KNW', 'HHZ', '--') RETURNING channel_nscl.rowid, channel_nscl.publisher
Process 28559: INSERT INTO channel_nscl (net, sta, chan, loc) VALUES ('AZ', 'CRY', 'HNZ', '--') RETURNING channel_nscl.rowid, channel_nscl.publisher
2022-04-19 19:55:54.482 UTC [28560] HINT: See server log for query details.
2022-04-19 19:55:54.482 UTC [28560] CONTEXT: while inserting index tuple (25,3) in relation "channel_nscl_nscl_idx"
2022-04-19 19:55:54.482 UTC [28560] STATEMENT: INSERT INTO channel_nscl (net, sta, chan, loc) VALUES ('AZ', 'KNW', 'HHZ', '--') RETURNING channel_nscl.rowid, channel_nscl.publisher
2022-04-19 19:55:55.488 UTC [28560] ERROR: deadlock detected
2022-04-19 19:55:55.488 UTC [28560] DETAIL: Process 28560 waits for ShareLock on transaction 609318483; blocked by process 28559.
Process 28559 waits for ShareLock on transaction 609318682; blocked by process 28560.
Process 28560: INSERT INTO channel_nscl (net, sta, chan, loc) VALUES ('AZ', 'KNW', 'HHZ', '--') RETURNING channel_nscl.rowid, channel_nscl.publisher
Process 28559: INSERT INTO channel_nscl (net, sta, chan, loc) VALUES ('AZ', 'CRY', 'HNZ', '--') RETURNING channel_nscl.rowid, channel_nscl.publisher
2022-04-19 19:55:55.488 UTC [28560] HINT: See server log for query details.
2022-04-19 19:55:55.488 UTC [28560] CONTEXT: while inserting index tuple (25,4) in relation "channel_nscl_nscl_idx"
2022-04-19 19:55:55.488 UTC [28560] STATEMENT: INSERT INTO channel_nscl (net, sta, chan, loc) VALUES ('AZ', 'KNW', 'HHZ', '--') RETURNING channel_nscl.rowid, channel_nscl.publisher
2022-04-19 19:55:56.495 UTC [28560] ERROR: deadlock detected
2022-04-19 19:55:56.495 UTC [28560] DETAIL: Process 28560 waits for ShareLock on transaction 609318483; blocked by process 28559.
Process 28559 waits for ShareLock on transaction 609318682; blocked by process 28560.
Process 28560: INSERT INTO channel_nscl (net, sta, chan, loc) VALUES ('AZ', 'KNW', 'HHZ', '--') RETURNING channel_nscl.rowid, channel_nscl.publisher
Process 28559: INSERT INTO channel_nscl (net, sta, chan, loc) VALUES ('AZ', 'CRY', 'HNZ', '--') RETURNING channel_nscl.rowid, channel_nscl.publisher
2022-04-19 19:55:56.495 UTC [28560] HINT: See server log for query details.
2022-04-19 19:55:56.495 UTC [28560] CONTEXT: while inserting index tuple (25,5) in relation "channel_nscl_nscl_idx"
2022-04-19 19:55:56.495 UTC [28560] STATEMENT: INSERT INTO channel_nscl (net, sta, chan, loc) VALUES ('AZ', 'KNW', 'HHZ', '--') RETURNING channel_nscl.rowid, channel_nscl.publisher

Browse pgsql-general by date

  From Date Subject
Next Message Michael Lewis 2022-04-19 20:48:33 LwLocks contention
Previous Message Rob Sargent 2022-04-19 19:29:04 psql timeout: who's waiting for whom