MIME-Version: 1.0
References: 
 <CAA5RZ0s+kZZRMSF4HW7tZ9W2jS1o4B+Fg8dr5a-T6mANX+mdQA@mail.gmail.com>
 <525d0f48-93f7-493f-a988-f39b460a79bc@gmail.com>
In-Reply-To: <525d0f48-93f7-493f-a988-f39b460a79bc@gmail.com>
From: Masahiko Sawada <sawada.mshk@gmail.com>
Date: Thu, 9 Apr 2026 11:25:41 -0700
Message-ID: 
 <CAD21AoCj=OSxoh3RBw0VWJ7Y7c9EipRhpatcZaHuXKGLWyKgdQ@mail.gmail.com>
Subject: Re: test_autovacuum/001_parallel_autovacuum is broken
To: Alexander Lakhin <exclusion@gmail.com>
Cc: Sami Imseih <samimseih@gmail.com>,
 pgsql-hackers <pgsql-hackers@postgresql.org>,
	Daniil Davydov <3danissimo@gmail.com>
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Archived-At: 
 <https://www.postgresql.org/message-id/CAD21AoCj%3DOSxoh3RBw0VWJ7Y7c9EipRhpatcZaHuXKGLWyKgdQ%40mail.gmail.com>
Precedence: bulk

On Thu, Apr 9, 2026 at 11:00=E2=80=AFAM Alexander Lakhin <exclusion@gmail.c=
om> wrote:
>
> Hello,
>
> 07.04.2026 05:23, Sami Imseih wrote:
>
> I noticed that the test introduced in parallel autovacuum in 1ff3180ca01 =
was
> very slow, but eventually succeeded. I tracked it down to the point in
> the test that is waiting for "parallel autovacuum worker updated cost par=
ams".
>
>
> I've found another issue with the test manifested on buildfarm, at least
> at [1]:
> [06:54:07.738](4.121s) not ok 1
> [06:54:07.769](0.031s) #   Failed test at /home/bf/bf-build/flaviventris/=
HEAD/pgsql/src/test/modules/test_autovacuum/t/001_parallel_autovacuum.pl li=
ne 133.
> ### Stopping node "main" using mode fast
>
> The corresponding test code:
> # Wait until the parallel autovacuum on table is completed. At the same t=
ime,
> # we check that the required number of parallel workers has been started.
> wait_for_autovacuum_complete($node, $av_count);
> ok( $node->log_contains(
>         qr/parallel workers: index vacuum: 2 planned, 2 launched in total=
/,
>         $log_offset));
>
> but regress_log_001_parallel_autovacuum contains this string:
> 2026-04-07 06:54:07.736 CEST [1825954][autovacuum worker][102/5:0] LOG:  =
automatic vacuum of table "postgres.public.test_autovac": index scans: 1
> ...
>     parallel workers: index vacuum: 2 planned, 2 launched in total
>
> though the timestamp difference is only 2 ms. I tried the following
> modification:
> @@ -1222,6 +1222,7 @@ heap_vacuum_rel(Relation rel, const VacuumParams *p=
arams,
>                               (double) dead_items_max_bytes / (1024 * 102=
4));
>              appendStringInfo(&buf, _("system usage: %s"), pg_rusage_show=
(&ru0));
>
> +pg_usleep(300000);
>              ereport(verbose ? INFO : LOG,
>                      (errmsg_internal("%s", buf.data)));
>              pfree(buf.data);
>
> and it makes the test fail for me on each run.
> Could you please look if this can be fixed too?
>

Thank you for the report.

The root cause seems to me that it's not guaranteed that we can see
the autovacuum logs after checking the statistics (i.e.,
pg_stat_user_tables) as we update the statistics and then write the
log.

One way to fix the test is to replace log_contains() with
wait_for_log(). We can also remove wait_for_autovacuum_complete()
logic altogether.

Regards,

--=20
Masahiko Sawada
Amazon Web Services: https://aws.amazon.com