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 <[email protected]>
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
