Date: Sat, 26 Oct 2024 21:09:28 -0700
From: Noah Misch <noah@leadboat.com>
To: pgsql-hackers@postgresql.org
Subject: Re: heap_inplace_lock vs. autovacuum w/ LOCKTAG_TUPLE
Message-ID: <20241027040928.9e.nmisch@google.com>
References: <20241026184936.ae.nmisch@google.com>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="hES+ImyeVGoQ3LG+"
Content-Disposition: inline
In-Reply-To: <20241026184936.ae.nmisch@google.com>
User-Agent: Mutt/2.2.12 (2023-09-09)
Archived-At: 
 <https://www.postgresql.org/message-id/20241027040928.9e.nmisch%40google.com>
Precedence: bulk


--hES+ImyeVGoQ3LG+
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

On Sat, Oct 26, 2024 at 11:49:36AM -0700, Noah Misch wrote:
> intra-grant-inplace-db.spec got a novel failure today:
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=sarus&dt=2024-10-26%2014%3A08%3A58
> 
> The isolationtester_waiting query is supposed to detect that step vac2 is
> blocked.  vac2 didn't finish within the timeout, but isolationtester_waiting
> never considered it blocked.

> ... work on reproducing this.

I'm running loops of three workloads that might reproduce this, on s390x:

- A buildfarm config like buildfarm member sarus.

- A workload where autovacuum vac_update_datfrozenxid() takes >10s, but
  non-auto "VACUUM (ONLY_DATABASE_STATS)" runs in a loop under
  lock_timeout=5s.  This notices if the non-auto VACUUM ever fails to cancel
  autovacuum.  I apply the attached inplace200-bench-vac-v0.1.patch, then run
  contrib/amcheck/t/089_vac.pl.

- A workload to make vac2's deadlock detector run when an autovacuum worker is
  starting.  That's one of my candidate explanations of the events behind the
  failure log.  I apply the attached inplace190-repro-autovacuum-v0.1.patch,
  then run intra-grant-inplace-db.spec with debug_parallel_query=regress and
  autovacuum_naptime=1s.  This regularly gets vac2 to cancel autovacuum.

So far, those have seen nothing like the failed run.

I'm inclined to make isolationtester log pg_stat_activity and pg_locks
whenever a step times out.  That would have ruled out many explanations for
what happened on sarus.  However, logging on timeout won't help much until
something can reproduce the timeout.

> It's odd that a new
> auto-analyze starts every minute, each of which exits due to blocking vac2.

Every autovacuum_naptime, a new worker cancels the old one due to wanting the
old worker's LOCKTAG_DATABASE_FROZEN_IDS.  One can see this with "BEGIN; GRANT
TEMP ON DATABASE postgres TO pg_monitor;".  That open transaction's xmax
prevents vac_update_datfrozenxid() from finishing.  While that transaction
remains open, every autovacuum_naptime after the first will log a cancellation
of the previous autovacuum worker.  (This assumes each autovacuum worker,
having negligible real work to do, reaches vac_update_datfrozenxid() before
the next autovacuum_naptime.)  That's likely not ideal, but it doesn't explain
the sarus failure.

--hES+ImyeVGoQ3LG+
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment; filename="inplace200-bench-vac-v0.1.patch"

Author:     Noah Misch <noah@leadboat.com>
Commit:     Noah Misch <noah@leadboat.com>

    
diff --git a/contrib/amcheck/t/089_vac.pl b/contrib/amcheck/t/089_vac.pl
new file mode 100644
index 0000000..a28ebd9
--- /dev/null
+++ b/contrib/amcheck/t/089_vac.pl
@@ -0,0 +1,50 @@
+
+# Copyright (c) 2021-2024, PostgreSQL Global Development Group
+
+# Test VACUUM vs. slow autovac
+use strict;
+use warnings FATAL => 'all';
+
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+
+use Test::More;
+
+my ($node, $result);
+
+#
+# Test set-up
+#
+$node = PostgreSQL::Test::Cluster->new('main');
+$node->init;
+$node->append_conf('postgresql.conf', 'autovacuum_naptime = 1s');
+$node->append_conf('postgresql.conf', 'log_lock_waits = on');
+$node->append_conf('postgresql.conf', 'deadlock_timeout = 10ms');
+$node->append_conf('postgresql.conf', q{backtrace_functions = 'ProcessInterrupts'});
+$node->start;
+
+my $grant_h = $node->background_psql('postgres');
+
+# This running would block all vac_update_datfrozenxid => lock_timeout always
+# $grant_h->query_safe(
+# 	q(
+# BEGIN;
+# GRANT TEMP ON DATABASE postgres TO pg_monitor;
+# ));
+
+{
+	local $ENV{PGOPTIONS} = '-clock_timeout=5s';
+$node->pgbench(
+	'--no-vacuum --client=1 --time=600',
+	0,
+	[qr{actually processed}],
+	[qr{^$}],
+	'vac',
+	{
+		'vac' => 'VACUUM (ONLY_DATABASE_STATS);',
+	});
+}
+
+$grant_h->quit;
+$node->stop;
+done_testing();
diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c
index ac8f5d9..20fe426 100644
--- a/src/backend/commands/vacuum.c
+++ b/src/backend/commands/vacuum.c
@@ -1582,6 +1582,7 @@ vac_update_relstats(Relation relation,
  *		commits.  As with vac_update_relstats, this avoids leaving dead tuples
  *		behind after a VACUUM.
  */
+#include "utils/fmgrprotos.h"
 void
 vac_update_datfrozenxid(void)
 {
@@ -1607,6 +1608,9 @@ vac_update_datfrozenxid(void)
 	 */
 	LockDatabaseFrozenIds(ExclusiveLock);
 
+	if (AmAutoVacuumWorkerProcess())
+		DirectFunctionCall1(pg_sleep, Float8GetDatum(10.0));
+
 	/*
 	 * Initialize the "min" calculation with
 	 * GetOldestNonRemovableTransactionId(), which is a reasonable

--hES+ImyeVGoQ3LG+
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment;
	filename="inplace190-repro-autovacuum-v0.1.patch"

Author:     Noah Misch <noah@leadboat.com>
Commit:     Noah Misch <noah@leadboat.com>

    
diff --git a/src/test/isolation/Makefile b/src/test/isolation/Makefile
index ade2256..ca487de 100644
--- a/src/test/isolation/Makefile
+++ b/src/test/isolation/Makefile
@@ -64,6 +64,9 @@ installcheck: all
 check: all
 	$(pg_isolation_regress_check) --schedule=$(srcdir)/isolation_schedule
 
+nmcheck: all temp-install
+	$(pg_isolation_regress_check) intra-grant-inplace-db
+
 # Non-default tests.  It only makes sense to run these if set up to use
 # prepared transactions, via TEMP_CONFIG for the check case, or via the
 # postgresql.conf for the installcheck case.
diff --git a/src/test/isolation/expected/intra-grant-inplace-db.out b/src/test/isolation/expected/intra-grant-inplace-db.out
index a91402c..118cbaa 100644
--- a/src/test/isolation/expected/intra-grant-inplace-db.out
+++ b/src/test/isolation/expected/intra-grant-inplace-db.out
@@ -8,6 +8,12 @@ step snap3:
 step b1: BEGIN;
 step grant1: 
 	GRANT TEMP ON DATABASE isolation_regression TO regress_temp_grantee;
+	SELECT pg_sleep(random(0.000, 1.200));
+
+pg_sleep
+--------
+        
+(1 row)
 
 step vac2: VACUUM (FREEZE); <waiting ...>
 step snap3: 
diff --git a/src/test/isolation/isolationtester.c b/src/test/isolation/isolationtester.c
index 0b342b5..8a5e585 100644
--- a/src/test/isolation/isolationtester.c
+++ b/src/test/isolation/isolationtester.c
@@ -863,7 +863,7 @@ try_complete_step(TestSpec *testspec, PermutationStep *pstep, int flags)
 	while (PQisBusy(conn))
 	{
 		FD_SET(sock, &read_set);
-		timeout.tv_sec = 0;
+		timeout.tv_sec = 8;
 		timeout.tv_usec = 10000;	/* Check for lock waits every 10ms. */
 
 		ret = select(sock + 1, &read_set, NULL, NULL, &timeout);
diff --git a/src/test/isolation/specs/intra-grant-inplace-db.spec b/src/test/isolation/specs/intra-grant-inplace-db.spec
index 9de40ec..408e23f 100644
--- a/src/test/isolation/specs/intra-grant-inplace-db.spec
+++ b/src/test/isolation/specs/intra-grant-inplace-db.spec
@@ -18,6 +18,7 @@ session s1
 step b1	{ BEGIN; }
 step grant1	{
 	GRANT TEMP ON DATABASE isolation_regression TO regress_temp_grantee;
+	SELECT pg_sleep(random(0.000, 1.200));
 }
 step c1	{ COMMIT; }
 

--hES+ImyeVGoQ3LG+--