On Thu, Apr 23, 2015 at 1:08 PM, Heikki Linnakangas <[email protected]> wrote:
> That said, I'd actually like to see a separate heap_super_delete() function
> for that, rather than piggybacking on heap_delete(). It's a quite different
> operation. There'll be some duplication, but seems better than a maze of
> if-else's in heap_delete.
I found a bug that seems to be down to commit
e3144183562d08e347f832f0b29daefe8bac617b on Github:
"""
commit e3144183562d08e347f832f0b29daefe8bac617b
Author: Heikki Linnakangas <[email protected]>
Date: Thu Apr 23 18:38:11 2015 +0300
Minor cleanup of check_exclusion_or_unique_constraint.
To improve readability.
"""
At least, that's what a "git bisect" session showed.
Basically, at high client counts (128 clients only), after a few
iterations of the B-Tree test, the latest version of jjanes_upsert
would see this happen (error originates fromExecOnConflictUpdate(),
with custom instrumentation added to identify invisible tuple):
2015-04-23 15:10:48 PDT [ txid: 0 ]: LOG: database system was shut
down at 2015-04-23 15:10:09 PDT
2015-04-23 15:10:48 PDT [ txid: 0 ]: LOG: database system is ready
to accept connections
2015-04-23 15:12:55 PDT [ txid: 472418 ]: ERROR: attempted to lock
invisible tuple (140,39)
2015-04-23 15:12:55 PDT [ txid: 472418 ]: STATEMENT: insert into
upsert_race_test (index, filler, count) values ('3896',
random_characters(), '1') on conflict (index)
update set count=TARGET.count + EXCLUDED.count, filler =
EXCLUDED.filler
where TARGET.index = EXCLUDED.index
returning count
This seemed to only show up when fsync = on on my laptop, whereas in
the past some race conditions that I've found were easier to recreate
with fsync = off.
I attach some notes from my bisect/debugging session, including
pg_xlogdump output (from a psql session - I like to manipulate
pg_xlogdump output using SQL). That's probably not all that
interesting, but I attach it all the same. Hopefully this is something
that Heikki can easily debug, since the commit implicated here only
concerned readability. A simple oversight? If you want, Heikki, I can
try and debug it, but it seems like something we're better off having
you sign off on if possible.
Thanks
--
Peter Geoghegan
error for dump:
pg@hamster:~/postgresql/src/backend/executor$ postgres
(git)-[insert_conflict_ignore]
2015-04-23 15:10:48 PDT [ txid: 0 ]: LOG: database system was shut down at
2015-04-23 15:10:09 PDT
2015-04-23 15:10:48 PDT [ txid: 0 ]: LOG: database system is ready to accept
connections
2015-04-23 15:12:55 PDT [ txid: 472418 ]: ERROR: attempted to lock invisible
tuple (140,39)
2015-04-23 15:12:55 PDT [ txid: 472418 ]: STATEMENT: insert into
upsert_race_test (index, filler, count) values ('3896', random_characters(),
'1') on conflict (index)
update set count=TARGET.count + EXCLUDED.count, filler =
EXCLUDED.filler
where TARGET.index = EXCLUDED.index
returning count
This was after 3 full iterations of jjanes_upsert, B-Tree only with 128 clients
only (fsync = on, the default). Settings:
max_connections = 150
shared_buffers = 6GB
work_mem = 5GB
maintenance_work_mem = 5GB
autovacuum = off
max_wal_size=10GB
wal_level = logical
max_replication_slots = 4
#log_min_duration_statement=0
#log_error_verbosity=verbose
log_line_prefix='%t [ %x ]: '
wal_keep_segments=500
max_prepared_transactions=5
shared_preload_libraries='pg_stat_statements'
pg_xlogdump output up to and including the above xact's abort:
(18545) /postgres=# select * from xlogdump_records where r_lsn <= '0/82F7F10'
order by r_lsn desc limit 50;
rmgr | len_rec | len_tot | tx | r_lsn | prev_lsn |
descr
| relation
-------------+---------+---------+--------+-----------+-----------+----------------------------------------------------------------------------------------------------------------+-----------------------
Transaction | 8 | 34 | 472418 | 0/82F7F10 | 0/82F7EE0 | ABORT
2015-04-23 15:12:55.784621 PDT
| [null]
Heap | 2 | 48 | 472420 | 0/82F7EE0 | 0/82F7EA0 |
HEAP_CONFIRM off 144 blkref #0: rel 1663/12488/16427 blk 33
| upsert_race_test
Btree | 2 | 64 | 472420 | 0/82F7EA0 | 0/82F7E48 | INSERT_LEAF
off 313 blkref #0: rel 1663/12488/16433 blk 22
| upsert_race_test_pkey
Heap | 3 | 83 | 472420 | 0/82F7E48 | 0/82F7E18 | INSERT off
144 blkref #0: rel 1663/12488/16427 blk 33
| upsert_race_test
Transaction | 20 | 46 | 472419 | 0/82F7E18 | 0/82F7DD8 | COMMIT
2015-04-23 15:12:55.784507 PDT
| [null]
Heap | 18 | 64 | 472418 | 0/82F7DD8 | 0/82F7D98 | DELETE off
50 blkref #0: rel 1663/12488/16427 blk 80
| upsert_race_test
Btree | 2 | 64 | 472418 | 0/82F7D98 | 0/82F7D68 | INSERT_LEAF
off 316 blkref #0: rel 1663/12488/16433 blk 13
| upsert_race_test_pkey
Heap | 2 | 48 | 472419 | 0/82F7D68 | 0/82F7D28 |
HEAP_CONFIRM off 39 blkref #0: rel 1663/12488/16427 blk 140
| upsert_race_test
Btree | 2 | 64 | 472419 | 0/82F7D28 | 0/82F7CB0 | INSERT_LEAF
off 316 blkref #0: rel 1663/12488/16433 blk 13
| upsert_race_test_pkey
Heap | 3 | 115 | 472419 | 0/82F7CB0 | 0/82F7C68 | INSERT off
39 blkref #0: rel 1663/12488/16427 blk 140
| upsert_race_test
Heap | 3 | 71 | 472418 | 0/82F7C68 | 0/82F7C38 | INSERT off
50 blkref #0: rel 1663/12488/16427 blk 80
| upsert_race_test
Transaction | 20 | 46 | 472417 | 0/82F7C38 | 0/82F7C08 | COMMIT
2015-04-23 15:12:55.784423 PDT
| [null]
Heap | 2 | 48 | 472417 | 0/82F7C08 | 0/82F7BC8 |
HEAP_CONFIRM off 59 blkref #0: rel 1663/12488/16427 blk 59
| upsert_race_test
Btree | 2 | 64 | 472417 | 0/82F7BC8 | 0/82F7B48 | INSERT_LEAF
off 163 blkref #0: rel 1663/12488/16433 blk 4
| upsert_race_test_pkey
Heap | 3 | 123 | 472417 | 0/82F7B48 | 0/82F7B18 | INSERT off
59 blkref #0: rel 1663/12488/16427 blk 59
| upsert_race_test
Transaction | 20 | 46 | 472416 | 0/82F7B18 | 0/82F7AB0 | COMMIT
2015-04-23 15:12:55.784161 PDT
| [null]
Heap | 14 | 98 | 472416 | 0/82F7AB0 | 0/82F7A78 | HOT_UPDATE
off 99 xmax 472416 KEYS_UPDATED ; new off 108 xmax 472416 blkref #0: rel
1663/12488/16427 blk 75 | upsert_race_test
Heap | 7 | 53 | 472416 | 0/82F7A78 | 0/82F7A48 | LOCK off
99: xid 472416 LOCK_ONLY EXCL_LOCK KEYS_UPDATED blkref #0: rel 1663/12488/16427
blk 75 | upsert_race_test
Transaction | 20 | 46 | 472414 | 0/82F7A48 | 0/82F7A18 | COMMIT
2015-04-23 15:12:55.783995 PDT
| [null]
Transaction | 20 | 46 | 472415 | 0/82F7A18 | 0/82F79A8 | COMMIT
2015-04-23 15:12:55.783995 PDT
| [null]
Heap | 14 | 106 | 472415 | 0/82F79A8 | 0/82F7930 | HOT_UPDATE
off 90 xmax 472415 KEYS_UPDATED ; new off 86 xmax 472415 blkref #0: rel
1663/12488/16427 blk 103 | upsert_race_test
Heap | 14 | 114 | 472414 | 0/82F7930 | 0/82F78F8 | HOT_UPDATE
off 22 xmax 472414 KEYS_UPDATED ; new off 117 xmax 472414 blkref #0: rel
1663/12488/16427 blk 101 | upsert_race_test
Heap | 7 | 53 | 472415 | 0/82F78F8 | 0/82F78C0 | LOCK off
90: xid 472415 LOCK_ONLY EXCL_LOCK KEYS_UPDATED blkref #0: rel 1663/12488/16427
blk 103 | upsert_race_test
Heap | 7 | 53 | 472414 | 0/82F78C0 | 0/82F7890 | LOCK off
22: xid 472414 LOCK_ONLY EXCL_LOCK KEYS_UPDATED blkref #0: rel 1663/12488/16427
blk 101 | upsert_race_test
Transaction | 20 | 46 | 472413 | 0/82F7890 | 0/82F7838 | COMMIT
2015-04-23 15:12:55.783793 PDT
| [null]
Heap | 14 | 86 | 472413 | 0/82F7838 | 0/82F7800 | HOT_UPDATE
off 130 xmax 472413 KEYS_UPDATED ; new off 135 xmax 472413 blkref #0: rel
1663/12488/16427 blk 37 | upsert_race_test
Heap | 7 | 53 | 472413 | 0/82F7800 | 0/82F77D0 | LOCK off
130: xid 472413 LOCK_ONLY EXCL_LOCK KEYS_UPDATED blkref #0: rel
1663/12488/16427 blk 37 | upsert_race_test
Transaction | 20 | 46 | 472412 | 0/82F77D0 | 0/82F77A0 | COMMIT
2015-04-23 15:12:55.783477 PDT
| [null]
Heap | 2 | 48 | 472412 | 0/82F77A0 | 0/82F7760 |
HEAP_CONFIRM off 120 blkref #0: rel 1663/12488/16427 blk 14
| upsert_race_test
Btree | 2 | 64 | 472412 | 0/82F7760 | 0/82F7730 | INSERT_LEAF
off 42 blkref #0: rel 1663/12488/16433 blk 29
| upsert_race_test_pkey
Transaction | 20 | 46 | 472411 | 0/82F7730 | 0/82F76E8 | COMMIT
2015-04-23 15:12:55.783436 PDT
| [null]
Heap | 3 | 67 | 472412 | 0/82F76E8 | 0/82F7670 | INSERT off
120 blkref #0: rel 1663/12488/16427 blk 14
| upsert_race_test
Heap | 14 | 114 | 472411 | 0/82F7670 | 0/82F7638 | HOT_UPDATE
off 124 xmax 472411 KEYS_UPDATED ; new off 80 xmax 472411 blkref #0: rel
1663/12488/16427 blk 38 | upsert_race_test
Heap | 7 | 53 | 472411 | 0/82F7638 | 0/82F75E8 | LOCK off
124: xid 472411 LOCK_ONLY EXCL_LOCK KEYS_UPDATED blkref #0: rel
1663/12488/16427 blk 38 | upsert_race_test
Heap2 | 8 | 74 | 0 | 0/82F75E8 | 0/82F75B8 | CLEAN
remxid 472264 blkref #0: rel 1663/12488/16427 blk 38
| upsert_race_test
Transaction | 20 | 46 | 472410 | 0/82F75B8 | 0/82F7518 | COMMIT
2015-04-23 15:12:55.783255 PDT
| [null]
Heap | 14 | 154 | 472410 | 0/82F7518 | 0/82F74E0 | HOT_UPDATE
off 74 xmax 472410 KEYS_UPDATED ; new off 120 xmax 472410 blkref #0: rel
1663/12488/16427 blk 81 | upsert_race_test
Heap | 7 | 53 | 472410 | 0/82F74E0 | 0/82F74B0 | LOCK off
74: xid 472410 LOCK_ONLY EXCL_LOCK KEYS_UPDATED blkref #0: rel 1663/12488/16427
blk 81 | upsert_race_test
Transaction | 20 | 46 | 472409 | 0/82F74B0 | 0/82F7428 | COMMIT
2015-04-23 15:12:55.783002 PDT
| [null]
Heap | 14 | 134 | 472409 | 0/82F7428 | 0/82F73F0 | HOT_UPDATE
off 44 xmax 472409 KEYS_UPDATED ; new off 115 xmax 472409 blkref #0: rel
1663/12488/16427 blk 94 | upsert_race_test
Heap | 7 | 53 | 472409 | 0/82F73F0 | 0/82F73C0 | LOCK off
44: xid 472409 LOCK_ONLY EXCL_LOCK KEYS_UPDATED blkref #0: rel 1663/12488/16427
blk 94 | upsert_race_test
Transaction | 20 | 46 | 472408 | 0/82F73C0 | 0/82F7360 | COMMIT
2015-04-23 15:12:55.782789 PDT
| [null]
Heap | 14 | 94 | 472408 | 0/82F7360 | 0/82F7330 | HOT_UPDATE
off 133 xmax 472408 KEYS_UPDATED ; new off 160 xmax 472408 blkref #0: rel
1663/12488/16427 blk 58 | upsert_race_test
Transaction | 20 | 46 | 472407 | 0/82F7330 | 0/82F72F8 | COMMIT
2015-04-23 15:12:55.782728 PDT
| [null]
Heap | 7 | 53 | 472408 | 0/82F72F8 | 0/82F7280 | LOCK off
133: xid 472408 LOCK_ONLY EXCL_LOCK KEYS_UPDATED blkref #0: rel
1663/12488/16427 blk 58 | upsert_race_test
Heap | 14 | 118 | 472407 | 0/82F7280 | 0/82F7248 | HOT_UPDATE
off 53 xmax 472407 KEYS_UPDATED ; new off 135 xmax 472407 blkref #0: rel
1663/12488/16427 blk 21 | upsert_race_test
Heap | 7 | 53 | 472407 | 0/82F7248 | 0/82F7218 | LOCK off
53: xid 472407 LOCK_ONLY EXCL_LOCK KEYS_UPDATED blkref #0: rel 1663/12488/16427
blk 21 | upsert_race_test
Transaction | 20 | 46 | 472406 | 0/82F7218 | 0/82F71E8 | COMMIT
2015-04-23 15:12:55.782512 PDT
| [null]
Heap | 2 | 48 | 472406 | 0/82F71E8 | 0/82F71A8 |
HEAP_CONFIRM off 129 blkref #0: rel 1663/12488/16427 blk 112
| upsert_race_test
Btree | 2 | 64 | 472406 | 0/82F71A8 | 0/82F7108 | INSERT_LEAF
off 28 blkref #0: rel 1663/12488/16433 blk 1
| upsert_race_test_pkey
(50 row)
e3144183562d08e347f832f0b29daefe8bac617b is the first bad commit
commit e3144183562d08e347f832f0b29daefe8bac617b
Author: Heikki Linnakangas <[email protected]>
Date: Thu Apr 23 18:38:11 2015 +0300
Minor cleanup of check_exclusion_or_unique_constraint.
To improve readability.
:040000 040000 826e53de0bbcacff67a298be7d9b416f5f8631fe
62d17e216497f224189f35de867fbecb190484ab M src
--
Sent via pgsql-hackers mailing list ([email protected])
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
