On 2025/03/23 23:00, Alexander Lakhin wrote:
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.
Thanks for reporting and investigating this issue!
With autovacuum = off, all of these fluctuations go away.
So you are suggesting disabling autovacuum during the postgres_fdw regression
test?
Just my idea to stabilize the test with "RETURNING *" is to use WITH, like this:
WITH tmp AS (UPDATE ... RETURNING *) SELECT * FROM tmp ORDER BY ...
Thought?
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
