From: | Alexander Lakhin <exclusion(at)gmail(dot)com> |
---|---|
To: | pgsql-hackers <pgsql-hackers(at)postgresql(dot)org> |
Subject: | Regression test postgres_fdw might fail due to autovacuum |
Date: | 2025-03-23 14:00:00 |
Message-ID: | 867266ef-3dd1-44a9-a203-27cb5d2be58d@gmail.com |
Views: | Raw Message | Whole Thread | Download mbox | Resend email |
Thread: | |
Lists: | pgsql-hackers |
Hello hackers,
A recent buildfarm failure [1] with the following diagnostics:
72/72 postgresql:postgres_fdw-running / postgres_fdw-running/regress ERROR 19.04s exit status 1
postgres_fdw-running/regress/results/postgres_fdw.out
--- /home/bf/bf-build/culicidae/HEAD/pgsql/contrib/postgres_fdw/expected/postgres_fdw.out 2025-03-11 15:21:27.681846597
+0000
+++ /home/bf/bf-build/culicidae/HEAD/pgsql.build/testrun/postgres_fdw-running/regress/results/postgres_fdw.out
2025-03-14 04:02:32.573999799 +0000
@@ -6392,6 +6392,7 @@
UPDATE ft2 SET c3 = 'bar' WHERE postgres_fdw_abs(c1) > 2000 RETURNING *;
c1 | c2 | c3 | c4 | c5 | c6 | c7 | c8
------+----+-----+----+----+----+------------+----
+ 2010 | 0 | bar | | | | ft2 |
2001 | 1 | bar | | | | ft2 |
2002 | 2 | bar | | | | ft2 |
2003 | 3 | bar | | | | ft2 |
@@ -6401,7 +6402,6 @@
2007 | 7 | bar | | | | ft2 |
2008 | 8 | bar | | | | ft2 |
2009 | 9 | bar | | | | ft2 |
- 2010 | 0 | bar | | | | ft2 |
(10 rows)
EXPLAIN (verbose, costs off)
shows that the UPDATE ... RETURNING query might be unstable due to lack of
ORDER BY.
I managed to reproduce this failure locally with the attached patch
applied to make the test repeatable and with:
sed 's/REGRESS = postgres_fdw.*/REGRESS = $(shell printf "postgres_fdw %.0s" `seq 50`)/' -i contrib/postgres_fdw/Makefile
(Running 10 instances of the test in parallel eases reproducing as well.)
I also added SELECT ctid, * FROM ft2; just after the query in question and
found out that the results of the SELECT more unstable, but for the UPDATE
to produce the difference, the tuple with c1 == 2010 must reside on a new
page. For example:
--- /home/vagrant/postgresql/contrib/postgres_fdw_2/expected/postgres_fdw.out 2025-03-22 05:21:39.414773284 +0000
+++ /home/vagrant/postgresql/contrib/postgres_fdw_2/results/postgres_fdw.out 2025-03-23 04:43:34.608281935 +0000
@@ -6399,6 +6399,7 @@
UPDATE ft2 SET c3 = 'bar' WHERE postgres_fdw_abs(c1) > 2000 RETURNING *;
c1 | c2 | c3 | c4 | c5 | c6 | c7 | c8
------+----+-----+----+----+----+------------+----
+ 2010 | 0 | bar | | | | ft2 |
2001 | 1 | bar | | | | ft2 |
2002 | 2 | bar | | | | ft2 |
2003 | 3 | bar | | | | ft2 |
@@ -6408,7 +6409,6 @@
2007 | 7 | bar | | | | ft2 |
2008 | 8 | bar | | | | ft2 |
2009 | 9 | bar | | | | ft2 |
- 2010 | 0 | bar | | | | ft2 |
SELECT ctid, * FROM ft2;
@@ -6470,15 +6470,6 @@
(0,103) | 57 | 407 | 00057_update7 | Fri Feb 27 00:00:00 1970 PST | Fri Feb 27 00:00:00 1970 | 7 | 7
| foo
(0,104) | 67 | 407 | 00067_update7 | Mon Mar 09 00:00:00 1970 PST | Mon Mar 09 00:00:00 1970 | 7 | 7
| foo
(0,105) | 77 | 407 | 00077_update7 | Thu Mar 19 00:00:00 1970 PST | Thu Mar 19 00:00:00 1970 | 7 | 7
| foo
- (0,106) | 9 | 509 | 00009_update9 | Sat Jan 10 00:00:00 1970 PST | Sat Jan 10 00:00:00 1970 | 9 | ft2
| foo
- (0,107) | 19 | 509 | 00019_update9 | Tue Jan 20 00:00:00 1970 PST | Tue Jan 20 00:00:00 1970 | 9 | ft2
| foo
- (0,108) | 29 | 509 | 00029_update9 | Fri Jan 30 00:00:00 1970 PST | Fri Jan 30 00:00:00 1970 | 9 | ft2
| foo
- (0,109) | 39 | 509 | 00039_update9 | Mon Feb 09 00:00:00 1970 PST | Mon Feb 09 00:00:00 1970 | 9 | ft2
| foo
- (0,110) | 49 | 509 | 00049_update9 | Thu Feb 19 00:00:00 1970 PST | Thu Feb 19 00:00:00 1970 | 9 | ft2
| foo
- (0,111) | 59 | 509 | 00059_update9 | Sun Mar 01 00:00:00 1970 PST | Sun Mar 01 00:00:00 1970 | 9 | ft2
| foo
- (0,112) | 69 | 509 | 00069_update9 | Wed Mar 11 00:00:00 1970 PST | Wed Mar 11 00:00:00 1970 | 9 | ft2
| foo
- (0,113) | 79 | 509 | 00079_update9 | Sat Mar 21 00:00:00 1970 PST | Sat Mar 21 00:00:00 1970 | 9 | ft2
| foo
- (0,114) | 89 | 509 | 00089_update9 | Tue Mar 31 00:00:00 1970 PST | Tue Mar 31 00:00:00 1970 | 9 | ft2
| foo
(1,1) | 98 | 8 | 00098 | Thu Apr 09 00:00:00 1970 PST | Thu Apr 09 00:00:00 1970 | 8 | 8
| foo
(1,3) | 100 | 0 | 00100 | Thu Jan 01 00:00:00 1970 PST | Thu Jan 01 00:00:00 1970 | 0 | 0
| foo
(1,4) | 101 | 1 | 00101 | Fri Jan 02 00:00:00 1970 PST | Fri Jan 02 00:00:00 1970 | 1 | 1
| foo
...
- (12,137) | 2007 | 7 | bar | | | | ft2 |
- (12,138) | 2008 | 8 | bar | | | | ft2 |
- (12,139) | 2009 | 9 | bar | | | | ft2 |
- (12,140) | 2010 | 0 | bar | | | | ft2 |
+ (11,80) | 9 | 509 | 00009_update9 | Sat Jan 10 00:00:00 1970 PST | Sat Jan 10 00:00:00 1970 | 9 | ft2
| foo
+ (11,81) | 19 | 509 | 00019_update9 | Tue Jan 20 00:00:00 1970 PST | Tue Jan 20 00:00:00 1970 | 9 | ft2
| foo
+ (11,82) | 29 | 509 | 00029_update9 | Fri Jan 30 00:00:00 1970 PST | Fri Jan 30 00:00:00 1970 | 9 | ft2
| foo
+ (11,83) | 39 | 509 | 00039_update9 | Mon Feb 09 00:00:00 1970 PST | Mon Feb 09 00:00:00 1970 | 9 | ft2
| foo
...
+ (13,126) | 1013 | 403 | 0001300013_update3 | | | | ft2 |
+ (13,127) | 1019 | 609 | 0001900019_update9 | | | | ft2 |
+ (13,128) | 1103 | 503 | ccc_update3 | | | | ft2 |
+ (14,1) | 2010 | 0 | bar | | | | ft2 |
(829 rows)
That is, for all the UPDATE failures I could see, the tuple with c1 == 2010
has ctid == (14, 1).
Interestingly enough, with "log_autovacuum_min_duration = 0" added to
TEMP_CONFIG, I can't see "automatic vacuum/analyze" messages related
to ft2/ "S 1"."T 1", so autovacuum somehow affects contents of this table
indirectly.
With autovacuum = off, all of these fluctuations go away.
[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=culicidae&dt=2025-03-14%2003%3A47%3A50
Best regards,
Alexander Lakhin
Neon (https://neon.tech)
Attachment | Content-Type | Size |
---|---|---|
postgres_fdw-repeatable.patch | text/x-patch | 2.2 KB |
From | Date | Subject | |
---|---|---|---|
Next Message | Fujii Masao | 2025-03-23 14:04:29 | Re: Add “FOR UPDATE NOWAIT” lock details to the log. |
Previous Message | Kevin K Biju | 2025-03-23 13:41:10 | Fix infinite loop from setting scram_iterations to INT_MAX |