Subject: Re: Test to dump and restore objects left behind by regression

From: Alvaro Herrera <[email-masked]>
Date: Thu, 3 Apr 2025 19:14:02 +0200

On 2025-Apr-03, Andres Freund wrote:

> I've increased the timeout even further, but I can't say that I am happy about
> the slowest test getting even slower. Adding test time in the serially slowest
> test is way worse than adding the same time in a concurrent test.

Yeah.  We discussed strategies to shorten the runtime, but the agreement
upthread was that we'd look for more elaborate ways to do that
afterwards.  As I mentioned, I can see adding something like
PG_TEST_EXCLUDE that we could use to suppress this test on slow hosts.
Would that work for you?

(We also discussed the fact that this was part of 002_pg_upgrade.pl
instead of being elsewhere.  The reason is that this depends on the
regression tests having run, and this is the only TAP test that does
that.   Well, this one and 027_stream_regress.pl which is even slower.)

> I suspect that the test will go a bit faster if log_statement weren't forced
> on, printing that many log lines, with context, does make valgrind slower,
> IME. But Cluster.pm forces it to on, and I suspect that putting a global
> log_statement=false into TEMP_CONFIG would have it's own disadvantages.

I'm sure we can make this change as well somehow, overridding the
setting just 002_pg_upgrade.pl, as attached.  I don't think it's
relevant for this particular test.  The log files go from 21 MB to
2.4 MB.  It's not nothing ...

-- 
Álvaro Herrera               48°01'N 7°57'E  —  https://www.EnterpriseDB.com/
"Selbst das größte Genie würde nicht weit kommen, wenn es
alles seinem eigenen Innern verdanken wollte." (Johann Wolfgang von Goethe)
               Ni aún el genio más grande llegaría muy lejos si
                    quisiera sacarlo todo de su propio interior.
diff --git a/src/bin/pg_upgrade/t/002_pg_upgrade.pl b/src/bin/pg_upgrade/t/002_pg_upgrade.pl
index 311391d7acd..46203c55baf 100644
--- a/src/bin/pg_upgrade/t/002_pg_upgrade.pl
+++ b/src/bin/pg_upgrade/t/002_pg_upgrade.pl
@@ -221,6 +221,8 @@ push @old_initdb_params, '-k' if $oldnode->pg_version < 18;
 
 $old_node_params{extra} = \@old_initdb_params;
 $oldnode->init(%old_node_params);
+# Override log_statement set by Cluster.pm; undesirable for this test
+$oldnode->append_conf('postgresql.conf', 'log_statement = none');
 $oldnode->start;
 
 my $result;
@@ -312,6 +314,7 @@ push @new_initdb_params, ('--encoding', 'SQL_ASCII');
 push @new_initdb_params, ('--locale-provider', 'libc');
 $new_node_params{extra} = \@new_initdb_params;
 $newnode->init(%new_node_params);
+$newnode->append_conf('postgresql.conf', 'log_statement=none');	# see above
 
 # Stabilize stats for comparison.
 $newnode->append_conf('postgresql.conf', 'autovacuum = off');
@@ -379,6 +382,7 @@ SKIP:
 	# source cluster to avoid any differences between dumps taken from both the
 	# clusters caused by differences in their configurations.
 	$dstnode->init(%old_node_params);
+	$dstnode->append_conf('postgresql.conf', 'log_statement=none');
 	# Stabilize stats for comparison.
 	$dstnode->append_conf('postgresql.conf', 'autovacuum = off');
 	$dstnode->start;

---

From: Ashutosh Bapat <[email-masked]>
Date: Fri, 4 Apr 2025 16:41:51 +0530

> 2.4 MB.  It's not nothing ...

It doesn't show any time improvement on my laptop, but it may improve
valgrind timing. My valgrind setup is broken, trying to fix it and run
it. I have included this as 0002 in the attached patchset.

0001 is an attempt to reduce runtime of the test by not setting up a
cluster for restoring the database. Instead the test uses the upgraded
node as the target. This works well since we expect the old node and
new node to be running the same version and default install. The only
unpleasantness is 1. dump and restore phases are spatially and
temporally separated 2. The upgraded regression database needs to be
renamed to save its state for diagnosis, if required. But as a result
this saves 3 seconds on my laptop. Earlier we saw that the test added
9 seconds on my laptop and we gained back 3 seconds; doesn't seem bad.
It will show a significant difference in valgrind run.

--
Best Wishes,
Ashutosh Bapat
From ef7880e1f1774c6875f4b265287f70d844e20ca4 Mon Sep 17 00:00:00 2001
From: Ashutosh Bapat <[email-masked]>
Date: Fri, 4 Apr 2025 14:26:48 +0530
Subject: [PATCH 1/2] Reduce time taken by 002_pg_upgrade test to run

This test is one of the longest running tests and
172259afb563d35001410dc6daad78b250924038 makes it even longer by adding a test
to dump/restore roundtrip of regression database.

The test already creates two clusters for pg_upgrade test. When these clusters
have same version and do not use custom installation, we run dump/restore test.
The new upgraded cluster could be used as target of restore instead of creating
a new cluster.

But this separates the dump and restore phases of the test spatially and
temporaly since the dump needs to be taken while the old cluster is running and
it can be restored only after new upgraded cluster is running; in-between we run
upgrade test. This separation affects readability of the test and hence wasn't
attempted before. But since runtime of test seems to be more important, we take
a hit on readability. We have added additional comments so as to link the two
phases and improve readability.

Author: Ashutosh Bapat <[email-masked]>
Reported-by: Andres Freund <[email-masked]>
---
 src/bin/pg_upgrade/t/002_pg_upgrade.pl | 72 ++++++++++++++++----------
 1 file changed, 46 insertions(+), 26 deletions(-)

diff --git a/src/bin/pg_upgrade/t/002_pg_upgrade.pl b/src/bin/pg_upgrade/t/002_pg_upgrade.pl
index 311391d7acd..8e7ccd2dad0 100644
--- a/src/bin/pg_upgrade/t/002_pg_upgrade.pl
+++ b/src/bin/pg_upgrade/t/002_pg_upgrade.pl
@@ -359,30 +359,34 @@ if (defined($ENV{oldinstall}))
 $oldnode->append_conf('postgresql.conf', 'autovacuum = off');
 $oldnode->restart;
 
+# Dump/restore Test.
+#
 # Test that dump/restore of the regression database roundtrips cleanly.  This
 # doesn't work well when the nodes are different versions, so skip it in that
 # case.  Note that this isn't a pg_upgrade test, but it's convenient to do it
 # here because we've gone to the trouble of creating the regression database.
 #
-# Do this while the old cluster is running before it is shut down by the
-# upgrade test but after turning its autovacuum off for stable statistics.
+# We execute this in two parts as follows:
+#
+# Part 1: Take dump from the old cluster while it is running before being shut
+# down by the upgrade test but after turning its autovacuum off for stable
+# statistics. If this part succeeds and is not skipped, it will leave behind
+# dump to be restored and a dump file for comparison.
+#
+# Part 2: The dump is restored on the upgraded cluster once it is running.
+#
+# Though this separates the two parts spatially and temporally, it avoids
+# creating a new cluster, thus saving time (and resources) in this already long
+# running test.
+my $regress_dump_file;
+my $src_dump;
 SKIP:
 {
-	my $dstnode = PostgreSQL::Test::Cluster->new('dst_node');
-
 	skip "different Postgres versions"
-	  if ($oldnode->pg_version != $dstnode->pg_version);
+	  if ($oldnode->pg_version != $newnode->pg_version);
 	skip "source node not using default install"
 	  if (defined $oldnode->install_path);
 
-	# Setup destination database cluster with the same configuration as the
-	# source cluster to avoid any differences between dumps taken from both the
-	# clusters caused by differences in their configurations.
-	$dstnode->init(%old_node_params);
-	# Stabilize stats for comparison.
-	$dstnode->append_conf('postgresql.conf', 'autovacuum = off');
-	$dstnode->start;
-
 	# Use --create in dump and restore commands so that the restored
 	# database has the same configurable variable settings as the original
 	# database so that the dumps taken from both databases taken do not
@@ -390,27 +394,18 @@ SKIP:
 	# coverage for --create option.
 	#
 	# Use directory format so that we can use parallel dump/restore.
-	my $dump_file = "$tempdir/regression.dump";
+	$regress_dump_file = "$tempdir/regression.dump";
 	$oldnode->command_ok(
 		[
 			'pg_dump', '-Fd', '-j2', '--no-sync',
 			'-d' => $oldnode->connstr('regression'),
-			'--create', '-f' => $dump_file
+			'--create', '-f' => $regress_dump_file
 		],
 		'pg_dump on source instance');
 
-	$dstnode->command_ok(
-		[ 'pg_restore', '--create', '-j2', '-d' => 'postgres', $dump_file ],
-		'pg_restore to destination instance');
-
-	# Dump original and restored database for comparison.
-	my $src_dump =
+	# Dump original database for comparison.
+	$src_dump =
 	  get_dump_for_comparison($oldnode, 'regression', 'src_dump', 1);
-	my $dst_dump =
-	  get_dump_for_comparison($dstnode, 'regression', 'dest_dump', 0);
-
-	compare_files($src_dump, $dst_dump,
-		'dump outputs from original and restored regression databases match');
 }
 
 # Take a dump before performing the upgrade as a base comparison. Note
@@ -629,4 +624,29 @@ my $dump2_filtered = filter_dump(0, $oldnode->pg_version, $dump2_file);
 compare_files($dump1_filtered, $dump2_filtered,
 	'old and new dumps match after pg_upgrade');
 
+# Execute Part 2 of Dump/restore Test.
+SKIP:
+{
+	# Skip Part 2 if the dump to be restored and the dump file for comparison do
+	# not exist.  Part 1 was not executed or did not succeed.
+	skip "no dump/restore test"
+	  if not defined $regress_dump_file or not defined $src_dump;
+
+	# Use --create option as explained in Part 1. Rename upgraded regression
+	# database so that pg_restore can succeed and the so that it's available for
+	# diagnosing problems if any.
+	$newnode->safe_psql('postgres', 'ALTER DATABASE regression RENAME TO
+	regression_upgraded');
+	$newnode->command_ok(
+		[ 'pg_restore', '--create', '-j2', '-d' => 'postgres', $regress_dump_file ],
+		'pg_restore to destination instance');
+
+	# Dump restored database for comparison.
+	my $dst_dump =
+	  get_dump_for_comparison($newnode, 'regression', 'dest_dump', 0);
+
+	compare_files($src_dump, $dst_dump,
+		'dump outputs from original and restored regression databases match');
+}
+
 done_testing();

base-commit: 7afca7edef751b8d7c0f5b6402ffcefc11c67fdd
-- 
2.34.1

From 262fcdab9568e447fade2fba886503aef27dcda7 Mon Sep 17 00:00:00 2001
From: Ashutosh Bapat <[email-masked]>
Date: Fri, 4 Apr 2025 16:28:20 +0530
Subject: [PATCH 2/2] Turn off log_statement to save CPU cycles

The test tests pg_dump and pg_upgrade utilities. Hence logging actual statements
executed on the server is not worth the CPU cycles spent for that. This
is significant in valgrind environment which slows tests down
considerably.

Author: Alvaro Herrera <[email-masked]>
Reviewed-by: Ashutosh Bapat <[email-masked]>
Suggested-by: Andres Freund <[email-masked]>
---
 src/bin/pg_upgrade/t/002_pg_upgrade.pl | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/src/bin/pg_upgrade/t/002_pg_upgrade.pl b/src/bin/pg_upgrade/t/002_pg_upgrade.pl
index 8e7ccd2dad0..96fc0b4dc73 100644
--- a/src/bin/pg_upgrade/t/002_pg_upgrade.pl
+++ b/src/bin/pg_upgrade/t/002_pg_upgrade.pl
@@ -221,6 +221,9 @@ push @old_initdb_params, '-k' if $oldnode->pg_version < 18;
 
 $old_node_params{extra} = \@old_initdb_params;
 $oldnode->init(%old_node_params);
+# Override log_statement set by Cluster.pm; logged statements are not as useful
+# and consume CPU cycles unnecessarily.
+$oldnode->append_conf('postgresql.conf', 'log_statement = none');
 $oldnode->start;
 
 my $result;
@@ -312,6 +315,8 @@ push @new_initdb_params, ('--encoding', 'SQL_ASCII');
 push @new_initdb_params, ('--locale-provider', 'libc');
 $new_node_params{extra} = \@new_initdb_params;
 $newnode->init(%new_node_params);
+# Override log_statement set by Cluster.pm; as explained in case of oldnode.
+$newnode->append_conf('postgresql.conf', 'log_statement=none');
 
2.34.1

---

From: Ashutosh Bapat <[email-masked]>
Date: Fri, 4 Apr 2025 16:47:13 +0530

> It will show a significant difference in valgrind run.

Forgot to mention that I made sure that the test is still doing its
work correct by reverting fd41ba93e463 and checking that it brings
back the failure. Also tested export'ing LC_MONETARY to make sure that
the locales in original and restored database remain the same.

-- 
Best Wishes,
Ashutosh Bapat

---

From: Andres Freund <[email-masked]>
Date: Fri, 4 Apr 2025 12:01:16 -0400

Hi,

On 2025-04-03 19:14:02 +0200, Alvaro Herrera wrote:
> afterwards.

I think it's not good to just say "we'll maybe somehow fix it in the future",
particularly if the solution is by no means agreed to.  If this were a test
that wasn't already the bottleneck for test cycles, it'd would be a different
story, but it is.

I'm already unhappy that 002_pg_upgrade got noticeably slower due to the stats
dump changes. This made it even worse.

> As I mentioned, I can see adding something like PG_TEST_EXCLUDE that we
> could use to suppress this test on slow hosts.  Would that work for you?

Not particularly well. For one I don't actually think it's good to exclude it
from something like valgrind testing. But it's also something that wouldn't
really be usable locally, I think, given that we'd be expected to keep the
test working.  As outlined below, it really affects the test-hack-test loop
times.

> that.   Well, this one and 027_stream_regress.pl which is even slower.)

FWIW, for me 027 is actually considerably faster. In an cassert -O0 build (my
normal development env, I find even -Og too problematic for debugging):

pg_upgrade/002_pg_upgrade    96.61s
recovery/027_stream_regress  66.04s

After
  git revert 8806e4e8deb1e21715e031e17181d904825a410e abe56227b2e213755dd3e194c530f5f06467bd7c 172259afb563d35001410dc6daad78b250924038

pg_upgrade/002_pg_upgrade    75.09s

Slower by 29%, far from the 3s increased time I saw mentioned somewhere.

And this really affects the overall test time:

All tests before:
	real	1m38.173s
	user	5m52.500s
	sys	4m23.574s

All tests after:
	real	2m0.397s
	user	5m53.625s
	sys	4m30.518s

The CPU time increase is rather minimal, but the wall clock time increase is
22%.

17:
	real	1m14.822s
	user	4m2.630s
	sys	3m22.384s

We regressed wall clock time *60%* from 17->18. Some test cycle increase is
reasonable and can largely be compensated with hardware, but this cycle we're
growing way faster than hardware gets faster.  I don't think that's
sustainable.

On valgrind it's also is very much true that 002_pg_upgrade is slower:

https://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=skink&dt=2025-04-04%2006%3A53%3A47&stg=recovery-check

276/333 postgresql:pg_upgrade / pg_upgrade/002_pg_upgrade                               OK             10337.79s   22 subtests passed
233/333 postgresql:recovery / recovery/027_stream_regress                               OK              7642.90s   9 subtests passed

To look at the times in a bit more detail:

[09:19:31.371](6146.167s) ok 5 - regression tests pass
...
# Running: pg_dump -Fd -j2 --no-sync -d port=31947 host=/tmp/HlLiWBwv6T dbname='regression' --create -f /home/bf/bf-build/skink-master/HEAD/pgsql.build/testrun/pg_upgrade/002_pg_upgrade/data/tmp_test_lFqZ/regression.dump
[09:26:35.178](201.199s) ok 6 - pg_dump on source instance
# Running: pg_restore --create -j2 -d postgres /home/bf/bf-build/skink-master/HEAD/pgsql.build/testrun/pg_upgrade/002_pg_upgrade/data/tmp_test_lFqZ/regression.dump
[09:35:53.079](557.901s) ok 7 - pg_restore to destination instance
# Running: pg_dump --no-sync -d port=31947 host=/tmp/HlLiWBwv6T dbname='regression' -f /home/bf/bf-build/skink-master/HEAD/pgsql.build/testrun/pg_upgrade/002_pg_upgrade/data/tmp_test_lFqZ/src_dump.sql
# Running: pg_dump --no-sync -d port=31949 host=/tmp/HlLiWBwv6T dbname='regression' -f /home/bf/bf-build/skink-master/HEAD/pgsql.build/testrun/pg_upgrade/002_pg_upgrade/data/tmp_test_lFqZ/dest_dump.sql
[09:43:18.485](445.407s) ok 8 - dump outputs from original and restored regression databases match
# Running: pg_dumpall --no-sync --dbname port=31947 host=/tmp/HlLiWBwv6T dbname='postgres' --file /home/bf/bf-build/skink-master/HEAD/pgsql.build/testrun/pg_upgrade/002_pg_upgrade/data/tmp_test_lFqZ/dump1.sql
[09:43:45.895](27.410s) ok 9 - dump before running pg_upgrade

I think the time for "pg_dump on source instance" is somewhat misleading, it
includes initdb and starting the server.

But it's pretty obvious that the newly added steps cost quite a bit of time.

> 2.4 MB.  It's not nothing ...

That is a nice improvement. I have to run a few errands, can check how that
affects valgrind times of a dump and restore of the regression db.

Greetings,

Andres Freund

---

From: Andres Freund <[email-masked]>
Date: Fri, 4 Apr 2025 12:07:08 -0400

Hi,

> growing way faster than hardware gets faster.  I don't think that's

FWIW, with cassert and -O2, it's:

17:
	real	0m53.981s
	user	3m22.837s
	sys	3m24.237s

HEAD:
	real	1m19.749s
	user	4m54.526s
	sys	4m15.657s

so this isn't just due to me using -O0. A 48% increase is better than a 60%
increase, but it's still not sustainable.

Greetings,

Andres Freund