Hello, hackers. While testing my work on (1) I was struggling with addressing a strange issue with ON CONFLICT UPDATE and REINDEX CONCURRENTLY.
After some time, I have realized the same issue persists on the master branch as well :) I have prepared two TAP tests to reproduce the issues (2), also in attachment. First one, does the next thing: CREATE UNLOGGED TABLE tbl(i int primary key, updated_at timestamp); CREATE INDEX idx ON tbl(i, updated_at); -- it is not required to reproduce but make it to happen faster Then it runs next scripts with pgbench concurrently: 1) INSERT INTO tbl VALUES(13,now()) on conflict(i) do update set updated_at = now(); 2) INSERT INTO tbl VALUES(42,now()) on conflict(i) do update set updated_at = now(); 3) INSERT INTO tbl VALUES(69,now()) on conflict(i) do update set updated_at = now(); Also, during pgbench the next command is run in the loop: REINDEX INDEX CONCURRENTLY tbl_pkey; For some time, everything looks more-less fine (except live locks, but this is the issue for the next test). But after some time, about a minute or so (on ~3000th REINDEX) it just fails like this: make -C src/test/modules/test_misc/ check PROVE_TESTS='t/006_*' # waiting for an about 3000, now is 2174, seconds passed : 84 # waiting for an about 3000, now is 2175, seconds passed : 84 # waiting for an about 3000, now is 2176, seconds passed : 84 # waiting for an about 3000, now is 2177, seconds passed : 84 # waiting for an about 3000, now is 2178, seconds passed : 84 # waiting for an about 3000, now is 2179, seconds passed : 84 # waiting for an about 3000, now is 2180, seconds passed : 84 # waiting for an about 3000, now is 2181, seconds passed : 84 # waiting for an about 3000, now is 2182, seconds passed : 84 # waiting for an about 3000, now is 2183, seconds passed : 84 # waiting for an about 3000, now is 2184, seconds passed : 84 # Failed test 'concurrent INSERTs, UPDATES and RC status (got 2 vs expected 0)' # at t/006_concurrently_unique_fail.pl line 69. # Failed test 'concurrent INSERTs, UPDATES and RC stderr /(?^:^$)/' # at t/006_concurrently_unique_fail.pl line 69. # 'pgbench: error: pgbench: error: client 4 script 0 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey_ccnew" # DETAIL: Key (i)=(13) already exists. # client 15 script 0 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey_ccnew" # DETAIL: Key (i)=(13) already exists. # pgbench: error: client 9 script 0 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey_ccnew" # DETAIL: Key (i)=(13) already exists. # pgbench: error: client 11 script 0 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey_ccnew" # DETAIL: Key (i)=(13) already exists. # pgbench: error: client 8 script 0 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey_ccnew" # DETAIL: Key (i)=(13) already exists. # pgbench: error: client 3 script 2 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey_ccnew" # DETAIL: Key (i)=(69) already exists. # pgbench: error: client 2 script 2 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey_ccnew" # DETAIL: Key (i)=(69) already exists. # pgbench: error: client 12 script 0 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey_ccold" # DETAIL: Key (i)=(13) already exists. # pgbench: error: client 10 script 0 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey_ccold" # DETAIL: Key (i)=(13) already exists. # pgbench: error: client 18 script 2 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey_ccnew" # DETAIL: Key (i)=(69) already exists. # pgbench: error: pgbench:client 14 script 0 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey" # DETAIL: Key (i)=(13) already exists. # error: client 1 script 0 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey" # DETAIL: Key (i)=(13) already exists. # pgbench: error: client 0 script 2 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey" # DETAIL: Key (i)=(69) already exists. # pgbench: error: client 13 script 1 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey_ccnew" # DETAIL: Key (i)=(42) already exists. # pgbench: error: client 16 script 1 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey_ccnew" # DETAIL: Key (i)=(42) already exists. # pgbench: error: client 5 script 1 aborted in command 1 query 0: ERROR: duplicate key value violates unique constraint "tbl_pkey_ccnew" # DETAIL: Key (i)=(42) already exists. # pgbench: error: Run was aborted; the above results are incomplete. # ' Probably something wrong with arbiter index selection for different backends. I am afraid it could be a symptom of a more serious issue. ------------------------------------- The second test shows an interesting live lock state in the similar situation. CREATE UNLOGGED TABLE tbl(i int primary key, n int); CREATE INDEX idx ON tbl(i, n); INSERT INTO tbl VALUES(13,1); pgbench concurrently runs single command INSERT INTO tbl VALUES(13,1) on conflict(i) do update set n = tbl.n + EXCLUDED.n; And also reindexing in the loop REINDEX INDEX CONCURRENTLY tbl_pkey; After the start, a little bit strange issue happens make -C src/test/modules/test_misc/ check PROVE_TESTS='t/007_*' # going to start reindex, num tuples in table is 1 # reindex 0 done in 0.00704598426818848 seconds, num inserted during reindex tuples is 0 speed is 0 per second # going to start reindex, num tuples in table is 7 # reindex 1 done in 0.453176021575928 seconds, num inserted during reindex tuples is 632 speed is 1394.60158947115 per second # going to start reindex, num tuples in table is 647 # current n is 808, 808 per one second # current n is 808, 0 per one second # current n is 808, 0 per one second # current n is 808, 0 per one second # current n is 808, 0 per one second # current n is 811, 3 per one second # current n is 917, 106 per one second # current n is 1024, 107 per one second # reindex 2 done in 8.4104950428009 seconds, num inserted during reindex tuples is 467 speed is 55.5258635340064 per second # going to start reindex, num tuples in table is 1136 # current n is 1257, 233 per one second # current n is 1257, 0 per one second # current n is 1257, 0 per one second # current n is 1257, 0 per one second # current n is 1257, 0 per one second # current n is 1490, 233 per one second # reindex 3 done in 5.21368479728699 seconds, num inserted during reindex tuples is 411 speed is 78.8310026363446 per second # going to start reindex, num tuples in table is 1566 In some moments, all CPUs all hot but 30 connections are unable to do any upsert. I think it may be somehow caused by two arbiter indexes (old and new reindexed one). Best regards, Mikhail. [1]: https://www.postgresql.org/message-id/flat/CANtu0ogBOtd9ravu1CUbuZWgq6qvn1rny38PGKDPk9zzQPH8_A%40mail.gmail.com#d4be02ff70f3002522f9fadbd165d631 [2]: https://github.com/michail-nikolaev/postgres/commit/9446f944b415306d9e5d5ab98f69938d8f5ee87f
From 9446f944b415306d9e5d5ab98f69938d8f5ee87f Mon Sep 17 00:00:00 2001 From: nkey <michail.nikolaev@gmail.com> Date: Sat, 8 Jun 2024 20:54:17 +0200 Subject: [PATCH v1] test for issue with upsert fail make -C src/test/modules/test_misc/ check PROVE_TESTS='t/006_*' test for issue with upsert livelock make -C src/test/modules/test_misc/ check PROVE_TESTS='t/007_*' --- .../t/006_concurrently_unique_fail.pl | 158 +++++++++++++++++ .../t/007_concurrently_unique_stuck.pl | 165 ++++++++++++++++++ 2 files changed, 323 insertions(+) create mode 100644 src/test/modules/test_misc/t/006_concurrently_unique_fail.pl create mode 100644 src/test/modules/test_misc/t/007_concurrently_unique_stuck.pl diff --git a/src/test/modules/test_misc/t/006_concurrently_unique_fail.pl b/src/test/modules/test_misc/t/006_concurrently_unique_fail.pl new file mode 100644 index 0000000000..6e08ff0812 --- /dev/null +++ b/src/test/modules/test_misc/t/006_concurrently_unique_fail.pl @@ -0,0 +1,158 @@ + +# Copyright (c) 2024, PostgreSQL Global Development Group + +# Test REINDEX CONCURRENTLY with concurrent modifications and HOT updates +use strict; +use warnings; + +use Config; +use Errno; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Time::HiRes qw(usleep); +use IPC::SysV; +use threads; +use Time::HiRes qw( time ); +use Test::More; +use Test::Builder; + +if ($@ || $windows_os) +{ + plan skip_all => 'Fork and shared memory are not supported by this platform'; +} + +my ($pid, $shmem_id, $shmem_key, $shmem_size); +eval 'sub IPC_CREAT {0001000}' unless defined &IPC_CREAT; +$shmem_size = 4; +$shmem_key = rand(1000000); +$shmem_id = shmget($shmem_key, $shmem_size, &IPC_CREAT | 0777) or die "Can't shmget: $!"; +shmwrite($shmem_id, "wait", 0, $shmem_size) or die "Can't shmwrite: $!"; + +my $psql_timeout = IPC::Run::timer($PostgreSQL::Test::Utils::timeout_default); +# +# Test set-up +# +my ($node, $result); +$node = PostgreSQL::Test::Cluster->new('RC_test'); +$node->init; +$node->append_conf('postgresql.conf', + 'lock_timeout = ' . (1000 * $PostgreSQL::Test::Utils::timeout_default)); +$node->append_conf('postgresql.conf', 'fsync = off'); +$node->append_conf('postgresql.conf', 'autovacuum = off'); +$node->start; +$node->safe_psql('postgres', q(CREATE UNLOGGED TABLE tbl(i int primary key, updated_at timestamp))); + + +####################################################################################################################### +####################################################################################################################### +####################################################################################################################### + +# IT IS NOT REQUIRED TO REPRODUCE THE ISSUE BUT MAKES IT TO HAPPEN FASTER +$node->safe_psql('postgres', q(CREATE INDEX idx ON tbl(i, updated_at))); + +####################################################################################################################### +####################################################################################################################### +####################################################################################################################### + +my $builder = Test::More->builder; +$builder->use_numbers(0); +$builder->no_plan(); + +my $child = $builder->child("pg_bench"); + +if(!defined($pid = fork())) { + # fork returned undef, so unsuccessful + die "Cannot fork a child: $!"; +} elsif ($pid == 0) { + + $node->pgbench( + '--no-vacuum --client=20 -j 2 --transactions=100000', + 0, + [qr{actually processed}], + [qr{^$}], + 'concurrent INSERTs, UPDATES and RC', + { + # Ensure some HOT updates happen + '002_pgbench_concurrent_transaction_updates' => q( + BEGIN; + INSERT INTO tbl VALUES(13,now()) on conflict(i) do update set updated_at = now(); + COMMIT; + ), + '003_pgbench_concurrent_transaction_updates' => q( + BEGIN; + INSERT INTO tbl VALUES(42,now()) on conflict(i) do update set updated_at = now(); + COMMIT; + ), + '004_pgbench_concurrent_transaction_updates' => q( + BEGIN; + INSERT INTO tbl VALUES(69,now()) on conflict(i) do update set updated_at = now(); + COMMIT; + ), + }); + + if ($child->is_passing()) { + shmwrite($shmem_id, "done", 0, $shmem_size) or die "Can't shmwrite: $!"; + } else { + shmwrite($shmem_id, "fail", 0, $shmem_size) or die "Can't shmwrite: $!"; + } + + my $pg_bench_fork_flag; + while (1) { + shmread($shmem_id, $pg_bench_fork_flag, 0, $shmem_size) or die "Can't shmread: $!"; + sleep(0.1); + last if $pg_bench_fork_flag eq "stop"; + } +} else { + my $pg_bench_fork_flag; + shmread($shmem_id, $pg_bench_fork_flag, 0, $shmem_size) or die "Can't shmread: $!"; + + subtest 'reindex run subtest' => sub { + is($pg_bench_fork_flag, "wait", "pg_bench_fork_flag is correct"); + + my %psql = (stdin => '', stdout => '', stderr => ''); + $psql{run} = IPC::Run::start( + [ 'psql', '-XA', '-f', '-', '-d', $node->connstr('postgres') ], + '<', + \$psql{stdin}, + '>', + \$psql{stdout}, + '2>', + \$psql{stderr}, + $psql_timeout); + + my ($result, $stdout, $stderr, $n, $begin_time, $end_time); + + # IT IS NOT REQUIRED, JUST FOR CONSISTENCY + ($result, $stdout, $stderr) = $node->psql('postgres', q(ALTER TABLE tbl SET (parallel_workers=0);)); + is($result, '0', 'ALTER TABLE is correct'); + + $begin_time = time(); + while (1) + { + my $sql = q(REINDEX INDEX CONCURRENTLY tbl_pkey;); + + ($result, $stdout, $stderr) = $node->psql('postgres', $sql); + is($result, '0', 'REINDEX INDEX CONCURRENTLY is correct'); + + $end_time = time(); + diag('waiting for an about 3000, now is ' . $n++ . ', seconds passed : ' . int($end_time - $begin_time)); + + shmread($shmem_id, $pg_bench_fork_flag, 0, $shmem_size) or die "Can't shmread: $!"; + last if $pg_bench_fork_flag ne "wait"; + } + + # explicitly shut down psql instances gracefully + $psql{stdin} .= "\\q\n"; + $psql{run}->finish; + + is($pg_bench_fork_flag, "done", "pg_bench_fork_flag is correct"); + }; + + $child->finalize(); + $child->summary(); + $node->stop; + done_testing(); + + shmwrite($shmem_id, "stop", 0, $shmem_size) or die "Can't shmwrite: $!"; +} diff --git a/src/test/modules/test_misc/t/007_concurrently_unique_stuck.pl b/src/test/modules/test_misc/t/007_concurrently_unique_stuck.pl new file mode 100644 index 0000000000..2e04b36825 --- /dev/null +++ b/src/test/modules/test_misc/t/007_concurrently_unique_stuck.pl @@ -0,0 +1,165 @@ +# Copyright (c) 2024, PostgreSQL Global Development Group + +# Test REINDEX CONCURRENTLY with concurrent modifications and HOT updates +use strict; +use warnings; + +use Config; +use Errno; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Time::HiRes qw(usleep); +use IPC::SysV; +use threads; +use Time::HiRes qw( time ); +use Test::More; +use Test::Builder; + +if ($@ || $windows_os) +{ + plan skip_all => 'Fork and shared memory are not supported by this platform'; +} + +my ($pid, $shmem_id, $shmem_key, $shmem_size); +eval 'sub IPC_CREAT {0001000}' unless defined &IPC_CREAT; +$shmem_size = 4; +$shmem_key = rand(1000000); +$shmem_id = shmget($shmem_key, $shmem_size, &IPC_CREAT | 0777) or die "Can't shmget: $!"; +shmwrite($shmem_id, "wait", 0, $shmem_size) or die "Can't shmwrite: $!"; + +my $psql_timeout = IPC::Run::timer($PostgreSQL::Test::Utils::timeout_default); +# +# Test set-up +# +my ($node, $result); +$node = PostgreSQL::Test::Cluster->new('RC_test'); +$node->init; +$node->append_conf('postgresql.conf', + 'lock_timeout = ' . (1000 * $PostgreSQL::Test::Utils::timeout_default)); +$node->append_conf('postgresql.conf', 'fsync = off'); +$node->append_conf('postgresql.conf', 'autovacuum = off'); +$node->start; +$node->safe_psql('postgres', q(CREATE UNLOGGED TABLE tbl(i int primary key, n int))); + + +####################################################################################################################### +####################################################################################################################### +####################################################################################################################### + +# IT IS **REQUIRED** TO REPRODUCE THE ISSUE +$node->safe_psql('postgres', q(CREATE INDEX idx ON tbl(i, n))); +$node->safe_psql('postgres', q(INSERT INTO tbl VALUES(13,1))); + +####################################################################################################################### +####################################################################################################################### +####################################################################################################################### + +my $builder = Test::More->builder; +$builder->use_numbers(0); +$builder->no_plan(); + +my $child = $builder->child("pg_bench"); + +if(!defined($pid = fork())) { + # fork returned undef, so unsuccessful + die "Cannot fork a child: $!"; +} elsif ($pid == 0) { + + $pid = fork(); + if ($pid == 0) { + $node->pgbench( + '--no-vacuum --client=30 -j 2 --transactions=1000000', + 0, + [qr{actually processed}], + [qr{^$}], + 'concurrent INSERTs, UPDATES and RC', + { + '002_pgbench_concurrent_transaction_updates' => q( + BEGIN; + INSERT INTO tbl VALUES(13,1) on conflict(i) do update set n = tbl.n + EXCLUDED.n; + COMMIT; + ), + }); + + if ($child->is_passing()) { + shmwrite($shmem_id, "done", 0, $shmem_size) or die "Can't shmwrite: $!"; + } else { + shmwrite($shmem_id, "fail", 0, $shmem_size) or die "Can't shmwrite: $!"; + } + + my $pg_bench_fork_flag; + while (1) { + shmread($shmem_id, $pg_bench_fork_flag, 0, $shmem_size) or die "Can't shmread: $!"; + sleep(0.1); + last if $pg_bench_fork_flag eq "stop"; + } + } + else { + my ($result, $stdout, $stderr, $n, $prev_n, $pg_bench_fork_flag); + while (1) { + sleep(1); + $prev_n = $n; + ($result, $n, $stderr) = $node->psql('postgres', q(SELECT n from tbl WHERE i = 13;)); + diag(" current n is " . $n . ', ' . ($n - $prev_n) . ' per one second'); + shmread($shmem_id, $pg_bench_fork_flag, 0, $shmem_size) or die "Can't shmread: $!"; + last if $pg_bench_fork_flag eq "stop"; + } + } +} else { + my $pg_bench_fork_flag; + shmread($shmem_id, $pg_bench_fork_flag, 0, $shmem_size) or die "Can't shmread: $!"; + + subtest 'reindex run subtest' => sub { + is($pg_bench_fork_flag, "wait", "pg_bench_fork_flag is correct"); + + my %psql = (stdin => '', stdout => '', stderr => ''); + $psql{run} = IPC::Run::start( + [ 'psql', '-XA', '-f', '-', '-d', $node->connstr('postgres') ], + '<', + \$psql{stdin}, + '>', + \$psql{stdout}, + '2>', + \$psql{stderr}, + $psql_timeout); + + my ($result, $stdout, $stderr, $n, $begin_time, $end_time, $before_reindex, $after_reindex); + + # IT IS NOT REQUIRED, JUST FOR CONSISTENCY + ($result, $stdout, $stderr) = $node->psql('postgres', q(ALTER TABLE tbl SET (parallel_workers=0);)); + is($result, '0', 'ALTER TABLE is correct'); + + while (1) + { + my $sql = q(REINDEX INDEX CONCURRENTLY tbl_pkey;); + + ($result, $before_reindex, $stderr) = $node->psql('postgres', q(SELECT n from tbl WHERE i = 13;)); + + diag('going to start reindex, num tuples in table is ' . $before_reindex); + $begin_time = time(); + ($result, $stdout, $stderr) = $node->psql('postgres', $sql); + is($result, '0', 'REINDEX INDEX CONCURRENTLY is correct'); + + $end_time = time(); + ($result, $after_reindex, $stderr) = $node->psql('postgres', q(SELECT n from tbl WHERE i = 13;)); + diag('reindex ' . $n++ . ' done in ' . ($end_time - $begin_time) . ' seconds, num inserted during reindex tuples is ' . (int($after_reindex) - int($before_reindex)) . ' speed is ' . ((int($after_reindex) - int($before_reindex)) / ($end_time - $begin_time)) . ' per second'); + + shmread($shmem_id, $pg_bench_fork_flag, 0, $shmem_size) or die "Can't shmread: $!"; + last if $pg_bench_fork_flag ne "wait"; + } + + # explicitly shut down psql instances gracefully + $psql{stdin} .= "\\q\n"; + $psql{run}->finish; + + is($pg_bench_fork_flag, "done", "pg_bench_fork_flag is correct"); + }; + + $child->finalize(); + $child->summary(); + $node->stop; + done_testing(); + + shmwrite($shmem_id, "stop", 0, $shmem_size) or die "Can't shmwrite: $!"; +} -- 2.34.1