From: r.zharkov@postgrespro.ru
To: Andres Freund <andres@anarazel.de>
Cc: Alvaro Herrera <alvherre@2ndquadrant.com>
Cc: Tom Lane <tgl@sss.pgh.pa.us>
Cc: pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #15727: PANIC: cannot abort transaction 295144144, it was already committed
Date: Wed, 03 Apr 2019 00:04:15 +0700
Message-ID: <b5d89910ec01a657530d1a49ff0e05dc@postgrespro.ru> (raw)
In-Reply-To: <20190402161320.o5wkbp7evuzqe4c2@alap3.anarazel.de>
References: <30650.1554219866@sss.pgh.pa.us>
<20190402155108.GA17787@alvherre.pgsql>
<20190402161320.o5wkbp7evuzqe4c2@alap3.anarazel.de>
On 2019-04-02 23:13, Andres Freund wrote:
> Hi,
>
> On 2019-04-02 12:51:08 -0300, Alvaro Herrera wrote:
>> On 2019-Apr-02, Tom Lane wrote:
>>
>> > Andres Freund <andres@anarazel.de> writes:
>> > >> 2019-04-01 15:27:38.829 +07 [7524] STATEMENT: UPDATE pgbench_accounts SET
>> > >> abalance = 1 WHERE aid = 1;
>> > >> 2019-04-01 15:27:38.829 +07 [7524] PANIC: cannot abort transaction
>> > >> 400048276, it was already committed
>> >
>> > > But that's probably a separate issue.
>> >
>> > What that seems to indicate is that the "unexpected table_lock_tuple
>> > status" error was thrown during commit, which seems pretty odd.
>>
>> AFAICS this error can only come from ExecDelete(), because the value 1
>> is TM_Invisible and the other callsites where the "unexpected
>> table_lock_tuple" error appears use different wording for that one.
>
> Hm? Why couldn't it be the ExecUpdate() case?
>
>
>> Maybe it's the result of a deferred constraint being checked at that
>> time ... maybe it's trying to honor an "on cascade delete" setting for
>> an FK, and the affected tuple has already been updated or deleted?
>
> Then it ought to get TM_Deleted, no? We ought to wait till that
> transaction commits, and then roll back. So there's something odd
> happening here. I suspect there has to be some additional log output
> or
> such to explain this.
>
> Greetings,
>
> Andres Freund
I made the new core file:
[New LWP 5967]
[Thread debugging using libthread_db enabled]
Using host libthread_db library
"/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `postgres: zharkov test 127.0.0.1(35888) UPDATE
'.
Program terminated with signal SIGABRT, Aborted.
#0 0x00007fe194769428 in __GI_raise (sig=sig@entry=6) at
../sysdeps/unix/sysv/linux/raise.c:54
54 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0 0x00007fe194769428 in __GI_raise (sig=sig@entry=6) at
../sysdeps/unix/sysv/linux/raise.c:54
#1 0x00007fe19476b02a in __GI_abort () at abort.c:89
#2 0x0000000000a9c0ac in errfinish (dummy=0) at elog.c:552
#3 0x0000000000a9e653 in elog_finish (elevel=22, fmt=0xb695a0 "cannot
abort transaction %u, it was already committed") at elog.c:1365
#4 0x0000000000562c87 in RecordTransactionAbort (isSubXact=false) at
xact.c:1644
#5 0x0000000000563c93 in AbortTransaction () at xact.c:2670
#6 0x0000000000564516 in AbortCurrentTransaction () at xact.c:3191
#7 0x00000000009145b9 in PostgresMain (argc=1, argv=0x255d970,
dbname=0x255d950 "test", username=0x252dd88 "zharkov") at
postgres.c:4033
#8 0x000000000086406c in BackendRun (port=0x2556020) at
postmaster.c:4399
#9 0x00000000008637cd in BackendStartup (port=0x2556020) at
postmaster.c:4090
#10 0x000000000085facf in ServerLoop () at postmaster.c:1703
#11 0x000000000085f2dd in PostmasterMain (argc=3, argv=0x252bcf0) at
postmaster.c:1376
#12 0x000000000077aeba in main (argc=3, argv=0x252bcf0) at main.c:228
Log:
2019-04-02 21:51:19.639 +07 [5967] STATEMENT: UPDATE pgbench_accounts
SET abalance = 1 WHERE aid = 1;
2019-04-02 21:51:19.639 +07 [5967] PANIC: cannot abort transaction
200011850, it was already committed
2019-04-02 21:53:57.924 +07 [2473] LOG: server process (PID 5967) was
terminated by signal 6: Aborted
2019-04-02 21:53:57.924 +07 [2473] DETAIL: Failed process was running:
UPDATE pgbench_accounts SET abalance = 1 WHERE aid = 1;
2019-04-02 21:53:57.924 +07 [2473] LOG: terminating any other active
server processes
We run pgbench with two custom scripts.
First:
\set i random_zipfian(1, 100000 * :scale, 1.01)
SELECT abalance FROM pgbench_accounts WHERE aid = :i;
Second:
\set i random_zipfian(1, 100000 * :scale, 1.01)
UPDATE pgbench_accounts SET abalance = 1 WHERE aid = :i;
pgbench connects to the database through the connection pooller called
Odyssey.
We use pool of 16 or 32 backends.
We run four series of pgbench tests with different connections count (
100, 150, 200, ... , 1000 )
Three series with pool size 16 runs normally.
But fourth series fails with 200-300 connections. It took about five
hours to reproduce the error this time.
Here is the little piece of the pgbench log:
Bench start
Tue Apr 2 14:43:12 UTC 2019
Timestamp 1554216192
transaction type: multiple scripts
scaling factor: 1
query mode: simple
number of clients: 200
number of threads: 32
duration: 300 s
number of transactions actually processed: 8062981
latency average = 7.442 ms
tps = 26875.375100 (including connections establishing)
tps = 26875.694564 (excluding connections establishing)
SQL script 1: ./sql/ycsb_read_zipf.sql
- weight: 1 (targets 50.0% of total)
- 4019635 transactions (49.9% of total, tps = 13398.171023)
- latency average = 6.955 ms
- latency stddev = 8.366 ms
SQL script 2: ./sql/ycsb_update_zipf.sql
- weight: 1 (targets 50.0% of total)
- 4021508 transactions (49.9% of total, tps = 13404.414071)
- latency average = 7.909 ms
- latency stddev = 8.478 ms
Bench end
Tue Apr 2 14:48:12 UTC 2019
Timestamp 1554216492
Bench start
Tue Apr 2 14:48:12 UTC 2019
Timestamp 1554216492
client 220 script 1 aborted in command 1 query 0: PANIC: cannot abort
transaction 200011850, it was already committed
WARNING: terminating connection because of crash of another server
process
--
regards,
Roman Zharkov
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-bugs@postgresql.org
Cc: r.zharkov@postgrespro.ru, andres@anarazel.de, alvherre@2ndquadrant.com, tgl@sss.pgh.pa.us, pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #15727: PANIC: cannot abort transaction 295144144, it was already committed
In-Reply-To: <b5d89910ec01a657530d1a49ff0e05dc@postgrespro.ru>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox