public inbox for [email protected]
help / color / mirror / Atom feedFrom: Hüseyin Demir <[email protected]>
To: Fujii Masao <[email protected]>
Cc: Chao Li <[email protected]>
Cc: [email protected]
Subject: Re: client_connection_check_interval default value
Date: Tue, 17 Mar 2026 20:59:04 +0100
Message-ID: <CAB5wL7amNFF3zA=h5R3Wx1aQZR-EKzv485LyYMLbB9X7dhx2Ew@mail.gmail.com> (raw)
In-Reply-To: <CAHGQGwGV3ufcdXnW6JLBhejfptCJRGs7Jrp03YPoO7V_b-2MFA@mail.gmail.com>
References: <[email protected]>
<CAHGQGwH7c5X4OkPaQ6VDaLGoFgJgwf_-HNwUi2uXoiAhkFkkyA@mail.gmail.com>
<177304694613.1094603.10800724073727441272.pgcf@coridan.postgresql.org>
<CAHGQGwG_Ud-N1zrULv8fE51-CUd2ZF3eDe7jUdNOm-rt_JgcQQ@mail.gmail.com>
<[email protected]>
<CAHGQGwEBvWXU4sdu2DMxaUWdPYQvGesr1VPyX-WnSxtW9nN6UA@mail.gmail.com>
<CAB5wL7YB1my9W5k5i=SY+=sTjeozyJ0YkvGXrVfeDNzuRkoTPg@mail.gmail.com>
<CAHGQGwGV3ufcdXnW6JLBhejfptCJRGs7Jrp03YPoO7V_b-2MFA@mail.gmail.com>
Fujii Masao <[email protected]>, 16 Mar 2026 Pzt, 10:22 tarihinde
şunu yazdı:
>
> On Mon, Mar 16, 2026 at 4:05 PM Hüseyin Demir <[email protected]> wrote:
> > The new v2 patch looks good to me.
> >
> > One open question from my side is should we include a test for this
> > behaviour ? Because we mentioned adding a different GUC in the future
> > to manage this rate-limiting approach. It can be useful in the future
> > once we consider/re-visit this approach. If the tests and other future
> > ideas can be developed later together we can consider adding tests
> > later.
>
> I agree it's worth adding such tests. From a quick look at the regression tests,
> there don't seem to be any tests for log_lock_waits itself. So before adding
> tests for the behavior introduced by the patch, we might first need to add
> some basic tests for log_lock_waits.
>
> Regards,
>
> --
> Fujii Masao
I created a regression test for the behaviour we mentioned before
introducing further possible changes.
You can review it. Basically I tried to simulate the desired behaviour
which the current patch introduced.
Regards.
Attachments:
[application/octet-stream] v1-0001-add-regression-tests-for-still-waiting-on-lock-log-message.patch (5.7K, 2-v1-0001-add-regression-tests-for-still-waiting-on-lock-log-message.patch)
download | inline diff:
From 4d1ccefbe7aa29ff35699be4a063a691c40e8c94 Mon Sep 17 00:00:00 2001
From: Huseyin Demir <[email protected]>
Date: Tue, 17 Mar 2026 20:28:06 +0100
Subject: [PATCH] Add TAP test for log_lock_waits "still waiting" once-per-wait
behavior.
Adds src/test/modules/test_misc/t/011_log_lock_waits.pl, which verifies that
the "still waiting on lock" message is emitted exactly once per lock wait even
when the lock-wait sleep is interrupted frequently by a very short
client_connection_check_interval.
Also registers the test in src/test/modules/test_misc/meson.build.
---
src/test/modules/test_misc/meson.build | 1 +
.../modules/test_misc/t/011_log_lock_waits.pl | 110 ++++++++++++++++++
2 files changed, 111 insertions(+)
create mode 100755 src/test/modules/test_misc/t/011_log_lock_waits.pl
diff --git a/src/test/modules/test_misc/meson.build b/src/test/modules/test_misc/meson.build
index 6e8db1621a7..0c8a9e71ba9 100644
--- a/src/test/modules/test_misc/meson.build
+++ b/src/test/modules/test_misc/meson.build
@@ -19,6 +19,7 @@ tests += {
't/008_replslot_single_user.pl',
't/009_log_temp_files.pl',
't/010_index_concurrently_upsert.pl',
+ 't/011_log_lock_waits.pl',
],
# The injection points are cluster-wide, so disable installcheck
'runningcheck': false,
diff --git a/src/test/modules/test_misc/t/011_log_lock_waits.pl b/src/test/modules/test_misc/t/011_log_lock_waits.pl
new file mode 100755
index 00000000000..bf5df9e4d92
--- /dev/null
+++ b/src/test/modules/test_misc/t/011_log_lock_waits.pl
@@ -0,0 +1,110 @@
+# Copyright (c) 2026, PostgreSQL Global Development Group
+
+# Verify that log_lock_waits emits the "still waiting" message exactly once
+# per lock wait, even when the lock-wait sleep is interrupted by SIGHUP
+# (e.g. via pg_reload_conf()).
+#
+# Background: after deadlock_timeout fires, deadlock_state is set to
+# DS_NO_DEADLOCK, which is != DS_NOT_YET_CHECKED. Every subsequent wakeup
+# from WaitLatch() re-enters the logging block. Without the fix, a SIGHUP
+# wakeup (config reload) would re-emit "still waiting" each time it occurred.
+# With the fix a boolean flag ensures the message is logged at most once per
+# ProcSleep() invocation.
+
+use strict;
+use warnings FATAL => 'all';
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+
+my $node = PostgreSQL::Test::Cluster->new('primary');
+$node->init;
+$node->append_conf(
+ 'postgresql.conf', qq(
+log_lock_waits = on
+deadlock_timeout = '200ms'
+));
+$node->start;
+
+$node->safe_psql('postgres', 'CREATE TABLE lock_test (id int)');
+
+# Session A: hold ACCESS EXCLUSIVE lock
+my $sess_a = $node->background_psql('postgres');
+$sess_a->query_safe(
+ "BEGIN; LOCK TABLE lock_test IN ACCESS EXCLUSIVE MODE;");
+
+# Record log offset before Session B tries to acquire the same lock
+my $log_offset = -s $node->logfile;
+
+# Session B: will block on the same lock.
+# Echo a marker before the blocking LOCK so query_until can return without
+# waiting for lock acquisition. The LOCK command runs (blocking) in the
+# background.
+my $sess_b = $node->background_psql('postgres');
+$sess_b->query_until(
+ qr/blocking_on_lock/,
+ "SET log_lock_waits = on;\n"
+ . "SET deadlock_timeout = '200ms';\n"
+ . "BEGIN;\n"
+ . "\\echo blocking_on_lock\n"
+ . "LOCK TABLE lock_test IN ACCESS EXCLUSIVE MODE;\n");
+
+# Wait until Session B is actually waiting for the lock
+ok( $node->poll_query_until(
+ 'postgres',
+ "SELECT count(*) = 1 FROM pg_stat_activity "
+ . "WHERE wait_event_type = 'Lock' AND state = 'active';"),
+ "session B is waiting for the lock");
+
+# Wait for deadlock_timeout to fire so that "still waiting" is emitted once
+# and deadlock_state transitions out of DS_NOT_YET_CHECKED.
+$node->wait_for_log(qr/still waiting for/, $log_offset);
+
+# Send two SIGHUP wakeups via pg_reload_conf(). Each one wakes up Session B's
+# WaitLatch() call. Without the fix, each wakeup would re-enter the logging
+# block (deadlock_state is now DS_NO_DEADLOCK != DS_NOT_YET_CHECKED) and
+# emit "still waiting" again. With the fix, logged_lock_waits=true suppresses
+# the repeated message.
+#
+# After each reload, poll until B is back in the lock-wait state so we know
+# the SIGHUP wakeup was fully processed before the next one is sent.
+$node->safe_psql('postgres', 'SELECT pg_reload_conf()');
+$node->poll_query_until(
+ 'postgres',
+ "SELECT count(*) = 1 FROM pg_stat_activity "
+ . "WHERE wait_event_type = 'Lock' AND state = 'active';");
+
+$node->safe_psql('postgres', 'SELECT pg_reload_conf()');
+$node->poll_query_until(
+ 'postgres',
+ "SELECT count(*) = 1 FROM pg_stat_activity "
+ . "WHERE wait_event_type = 'Lock' AND state = 'active';");
+
+# Release the lock so Session B can proceed
+$sess_a->query_safe("COMMIT;");
+
+# Wait for Session B to acquire the lock (signalled by "acquired" in log)
+$node->wait_for_log(qr/acquired AccessExclusiveLock/, $log_offset);
+
+$sess_b->quit;
+$sess_a->quit;
+
+# Count "still waiting" messages in the relevant log segment
+my $log_contents =
+ PostgreSQL::Test::Utils::slurp_file($node->logfile, $log_offset);
+my @still_waiting = ($log_contents =~ /still waiting for/g);
+my @acquired = ($log_contents =~ /acquired AccessExclusiveLock/g);
+
+# With the fix: exactly 1 "still waiting" (fired after deadlock_timeout),
+# then suppressed for both subsequent pg_reload_conf() wakeups.
+# Without the fix: 3 messages (one per wakeup that re-entered the logging
+# block).
+is(scalar @still_waiting, 1,
+ "still waiting logged exactly once despite pg_reload_conf() wakeups");
+
+# Sanity check: the "acquired" message must appear exactly once
+is(scalar @acquired, 1, "acquired logged once when lock is granted");
+
+$node->stop('fast');
+
+done_testing();
--
2.50.1 (Apple Git-155)
view thread (22+ messages) latest in thread
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: [email protected]
Cc: [email protected], [email protected], [email protected], [email protected]
Subject: Re: client_connection_check_interval default value
In-Reply-To: <CAB5wL7amNFF3zA=h5R3Wx1aQZR-EKzv485LyYMLbB9X7dhx2Ew@mail.gmail.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox