From 4d1ccefbe7aa29ff35699be4a063a691c40e8c94 Mon Sep 17 00:00:00 2001 From: Huseyin Demir 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)