ecpg test thread/alloc hangs on sidewinder running NetBSD 9.3

On 2025-08-30 22:00, Alexander Lakhin wrote:

Upgrade to NetBSD 9.4 fixed the issue for me.

It reproduced even on a commit from 2017-01-01, so it's not clear why
there were no such timeouts before...

[1]
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=sidewinder&dt=2025-08-22%2011%3A29%3A27
[2]
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=sidewinder&dt=2025-08-27%2016%3A35%3A01
[3]
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=sidewinder&dt=2025-08-29%2012%3A35%3A01
[4] https://portal.cloud.hashicorp.com/vagrant/discover/generic/netbsd9
[5] https://github.com/jemalloc/jemalloc/issues/2402

Hi,

One change I did pretty recently is that I upgraded the build farm
client from 14 to 19.1 a couple of weeks ago.

I might have lowered wait_timeout initially but now it's higher (14400)
than before (10800).

I also have note that there are stuck processes some times.  Like:

netbsd9_3-pgbf# ps aux | grep ^pgbf
pgbf     1610  0.0  0.1   34068  2200 ?     I    Wed07PM   0:00.00 gmake
NO_LOCALE=1 NO_TEMP_INSTALL=yes check
pgbf     3083  0.0  0.3 1903704  6164 ?     Il   22Aug25   0:00.04
/home/pgbf/buildroot/HEAD/pgsql.build/src/interfaces/ecpg/test/thr
pgbf     3101  0.0  0.2   57892  4160 ?     I    Fri03PM   0:00.01
postdrop -r
pgbf     4490  0.0  0.3 1902676  6068 ?     Il   Wed07PM   0:00.04
/home/pgbf/buildroot/REL_18_STABLE/pgsql.build/src/interfaces/ecpg
pgbf     8739  0.0  0.1   18948  2196 ?     I    22Aug25   0:00.00 gmake
-C test check
pgbf     8927  0.0  0.1   20008  1780 ?     I    22Aug25   0:00.00 sh -c
{ cd  pgsql.build/src/interfaces/ecpg && gmake NO_LOCALE=1 N
pgbf    10380  0.0  0.2   57876  4184 ?     Is   Wed07PM   0:00.00
sendmail -FCronDaemon -odi -oem -oi -t
pgbf    10579  0.0  0.3 1900136  6172 ?     Il   Fri03PM   0:00.04
/home/pgbf/buildroot/HEAD/pgsql.build/src/interfaces/ecpg/test/thr
pgbf    11374  0.0  0.2   57872  4180 ?     Is   Fri03PM   0:00.01
sendmail -FCronDaemon -odi -oem -oi -t
pgbf    13147  0.0  0.2   43260  3804 ?     I    Fri03PM   0:00.34
./pg_regress --expecteddir=. --dbname=ecpg1_regression,ecpg2_regre
pgbf    14484  0.0  0.0       0     0 ?     Z          -   0:00.00 (ksh)
pgbf    14711  0.0  0.0       0     0 ?     Z          -   0:00.00 (ksh)
pgbf    16040  0.0  0.2   57896  4160 ?     I    Wed07PM   0:00.01
postdrop -r
pgbf    17707  0.0  0.1   32400  2196 ?     I    22Aug25   0:00.00 gmake
NO_LOCALE=1 NO_TEMP_INSTALL=yes check
pgbf    18244  0.0  0.1   30100  2204 ?     I    Fri03PM   0:00.00 gmake
-C test check
pgbf    20348  0.0  0.1   20008  1780 ?     I    Fri03PM   0:00.00 sh -c
{ cd  pgsql.build/src/interfaces/ecpg && gmake NO_LOCALE=1 N
pgbf    22704  0.0  0.2   57896  4164 ?     I    22Aug25   0:00.01
postdrop -r
pgbf    23701  0.0  0.2   48960  3788 ?     I    Wed07PM   0:00.29
./pg_regress --expecteddir=. --dbname=ecpg1_regression,ecpg2_regre
pgbf    24016  0.0  0.2   39292  3792 ?     I    22Aug25   0:00.29
./pg_regress --expecteddir=. --dbname=ecpg1_regression,ecpg2_regre
pgbf    24387  0.0  0.1   30888  2200 ?     I    Fri03PM   0:00.00 gmake
NO_LOCALE=1 NO_TEMP_INSTALL=yes check
pgbf    24945  0.0  0.2   57876  4176 ?     Is   22Aug25   0:00.01
sendmail -FCronDaemon -odi -oem -oi -t
pgbf    25730  0.0  0.1   18852  2216 ?     I    Wed07PM   0:00.00 gmake
-C test check
pgbf    26757  0.0  0.1   22684  1776 ?     I    Wed07PM   0:00.00 sh -c
{ cd  pgsql.build/src/interfaces/ecpg && gmake NO_LOCALE=1 N
pgbf    29079  0.0  0.0       0     0 ?     Z          -   0:00.00 (ksh)

/Mikael

=?UTF-8?Q?Mikael_Kjellstr=C3=B6m?= <mikael.kjellstrom@mksoft.nu> writes:

On 2025-08-30 22:00, Alexander Lakhin wrote:

Upgrade to NetBSD 9.4 fixed the issue for me.

I also have note that there are stuck processes some times.  Like:

Yeah, this printout is consistent with Alexander's observation that
it's ecpg threading tests that are getting stuck:

pgbf     3083  0.0  0.3 1903704  6164 ?     Il   22Aug25   0:00.04
/home/pgbf/buildroot/HEAD/pgsql.build/src/interfaces/ecpg/test/thr

pgbf    10579  0.0  0.3 1900136  6172 ?     Il   Fri03PM   0:00.04
/home/pgbf/buildroot/HEAD/pgsql.build/src/interfaces/ecpg/test/thr

All the other processes belonging to pgbf are test driver processes
that would be waiting for these two.

Since we're not seeing comparable failures on other animals,
I tend to agree with his diagnosis of a bug in 9.3's malloc library.

regards, tom lane

On 2025-08-31 16:52, Tom Lane wrote:

All the other processes belonging to pgbf are test driver processes
that would be waiting for these two.

Since we're not seeing comparable failures on other animals,
I tend to agree with his diagnosis of a bug in 9.3's malloc library.

Yes, I will upgrade that animal to the latest release of NetBSD 10.1 I
think.

NetBSD 9.3 is EOL anyway.

/Mikael

Hello Mikael,

31.08.2025 22:55, Mikael Kjellström wrote:

Yes, I will upgrade that animal to the latest release of NetBSD 10.1 I think.

[ a bit off-topic, but still related to sidewinder ]

I've noticed an interesting failure on sidewinder occurred recently [1]https://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=sidewinder&amp;dt=2026-02-19%2021%3A35%3A01&amp;stg=recovery-check:
#   Failed test 'get an error when running within another function'
#   at t/049_wait_for_lsn.pl line 218.
# Looks like you failed 1 test of 33.
[23:19:49] t/049_wait_for_lsn.pl .................
Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/33 subtests

The corresponding code in the test:
$node_standby->psql(
    'postgres',
    "SELECT pg_wal_replay_wait_wrap('${lsn3}');",
    stderr => \$stderr);
ok( $stderr =~
      /WAIT FOR must be called without an active or registered snapshot/,
    "get an error when running within another function");

But 049_wait_for_lsn_standby.log in fact contains:
2026-02-19 23:19:42.251 CET [7417:4] 049_wait_for_lsn.pl LOG: statement: SELECT pg_wal_replay_wait_wrap('2/570C0FC0');
2026-02-19 23:19:42.252 CET [7417:5] 049_wait_for_lsn.pl ERROR: WAIT FOR must be called without an active or registered
snapshot
2026-02-19 23:19:42.252 CET [7417:6] 049_wait_for_lsn.pl DETAIL: WAIT FOR cannot be executed from a function or
procedure, nor within a transaction with an isolation level higher than READ COMMITTED.
2026-02-19 23:19:42.252 CET [7417:7] 049_wait_for_lsn.pl CONTEXT: SQL statement "WAIT FOR LSN '2/570C0FC0';"
    PL/pgSQL function pg_wal_replay_wait_wrap(pg_lsn) line 3 at EXECUTE
2026-02-19 23:19:42.252 CET [7417:8] 049_wait_for_lsn.pl STATEMENT: SELECT pg_wal_replay_wait_wrap('2/570C0FC0');
2026-02-19 23:19:42.253 CET [7417:9] 049_wait_for_lsn.pl LOG: disconnection: session time: 0:00:00.005 user=pgbf
database=postgres host=[local]

That is, the server returned the expected error, but the test didn't
receive it.

I've managed to reproduce this failure locally, on NetBSD 10.1, with the
following modification:
--- a/src/test/recovery/t/049_wait_for_lsn.pl
+++ b/src/test/recovery/t/049_wait_for_lsn.pl
@@ -211,13 +211,20 @@ LANGUAGE plpgsql;
  ]);

  $node_primary->wait_for_catchup($node_standby);
+
+for (my $i=1; $i<=50; $i++)
+{
+my $stdout;
  $node_standby->psql(
         'postgres',
-       "SELECT pg_wal_replay_wait_wrap('${lsn3}');",
+       "SELECT pg_wal_replay_wait_wrap('${lsn3}') /*$i*/;",
+        stdout => \$stdout,
         stderr => \$stderr);
+print("stdout: [$stdout]; stderr: [$stderr]\n");
  ok( $stderr =~
           /WAIT FOR must be called without an active or registered snapshot/,
-       "get an error when running within another function");
+       "get an error when running within another function ($i)");
+}

 # 6. Check parameter validation error cases on standby before promotion
 my $test_lsn =

when running multiple paralled test instances in a loop:
stdout: []; stderr: [psql:<stdin>:1: ERROR:  WAIT FOR must be called without an active or registered snapshot
DETAIL:  WAIT FOR cannot be executed from a function or procedure, nor within a transaction with an isolation level
higher than READ COMMITTED.
CONTEXT:  SQL statement "WAIT FOR LSN '2/570C0FF8';"
PL/pgSQL function pg_wal_replay_wait_wrap(pg_lsn) line 3 at EXECUTE]
[09:33:27.469](0.062s) ok 25 - get an error when running within another function (14)
stdout: []; stderr: []
[09:33:27.636](0.168s) not ok 26 - get an error when running within another function (15)
[09:33:27.651](0.015s)
[09:33:27.652](0.001s) #   Failed test 'get an error when running within another function (15)'
#   at t/049_wait_for_lsn.pl line 225.
stdout: []; stderr: [psql:<stdin>:1: ERROR:  WAIT FOR must be called without an active or registered snapshot
DETAIL:  WAIT FOR cannot be executed from a function or procedure, nor within a transaction with an isolation level
higher than READ COMMITTED.
CONTEXT:  SQL statement "WAIT FOR LSN '2/570C0FF8';"
PL/pgSQL function pg_wal_replay_wait_wrap(pg_lsn) line 3 at EXECUTE]

It reminded me of [2]/messages/by-id/fb666566-32bb-9c36-9c2e-3949b7a061bc@gmail.com. In my system, I found p5-IPC-Run-20231003.0nb1
installed. So I tried to update it with:
sudo pkg_delete p5-IPC-Run
git clone https://github.com/cpan-authors/IPC-Run.git
(cd IPC-Run*/ && perl Makefile.PL && make && sudo make install)
and it really helped -- no failure reproduced with many more runs. (I can
share my repro if needed.)

So maybe you could consider updating IPC::Run on sidewinder too...

[1]: https://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=sidewinder&amp;dt=2026-02-19%2021%3A35%3A01&amp;stg=recovery-check
[2]: /messages/by-id/fb666566-32bb-9c36-9c2e-3949b7a061bc@gmail.com

Best regards,
Alexander

On 2026-02-21 19:00, Alexander Lakhin wrote:

It reminded me of [2]. In my system, I found p5-IPC-Run-20231003.0nb1
installed. So I tried to update it with:
sudo pkg_delete p5-IPC-Run
git clone https://github.com/cpan-authors/IPC-Run.git
(cd IPC-Run*/ && perl Makefile.PL && make && sudo make install)
and it really helped -- no failure reproduced with many more runs. (I can
share my repro if needed.)

So maybe you could consider updating IPC::Run on sidewinder too...

I haven't done an upgrade of the packages in a while and I just ran a
pkgin update and saw that it wanted to upgrade to
"p5-IPC-Run-20250809.0" so I can maybe try that first and see if that helps.

Anyway I have now upgraded all the packages so they should be up to
date.  Let's see if that makes a difference.

Otherwise I could do a manual install of IPC-Run.

/Mikael