Add TAP tests for log_lock_waits

This commit updates 011_lock_stats.pl to verify log_lock_waits behavior.

The tests check that messages are emitted both when a wait occurs and
when the lock is acquired, and that the "still waiting for" message is logged
exactly once per wait, even if the backend wakes up during the wait.

The latter covers the behavior introduced by commit fd6ecbfa75f.

Author: Hüseyin Demir <huseyin.d3r@gmail.com>
Co-authored-by: Fujii Masao <masao.fujii@gmail.com>
Discussion: https://postgr.es/m/CAB5wL7YB1my9W5k5i=SY+=sTjeozyJ0YkvGXrVfeDNzuRkoTPg@mail.gmail.com

diff --git a/src/test/modules/test_misc/t/011_lock_stats.pl b/src/test/modules/test_misc/t/011_lock_stats.pl
index 58a0046a52c3d32a2e986d64e34bec5967eb43f7..7662db160173a924667a682d4a28095321c2bdfd 100644 (file)
--- a/src/test/modules/test_misc/t/011_lock_stats.pl
+++ b/src/test/modules/test_misc/t/011_lock_stats.pl
@@ -1,13 +1,18 @@
 
 # Copyright (c) 2026, PostgreSQL Global Development Group
 
-# Test for the lock statistics
+# Test for the lock statistics and log_lock_waits
 #
 # This test creates multiple locking situations when a session (s2) has to
 # wait on a lock for longer than deadlock_timeout. The first tests each test a
 # dedicated lock type.
 # The last one checks that log_lock_waits has no impact on the statistics
 # counters.
+#
+# This test also checks that log_lock_waits messages are emitted both when
+# a wait occurs and when the lock is acquired, and that the "still waiting for"
+# message is logged exactly once per wait, even if the backend wakes due
+# to signals.
 
 use strict;
 use warnings FATAL => 'all';
@@ -90,6 +95,8 @@ INSERT INTO test_stat_tab(key, value) VALUES('k0', 1);
 
 setup_sessions();
 
+my $log_offset = -s $node->logfile;
+
 $s1->query_safe(
        q[
 SELECT pg_stat_reset_shared('lock');
@@ -112,6 +119,21 @@ LOCK TABLE test_stat_tab;
 
 wait_and_detach($node, 'deadlock-timeout-fired');
 
+# Check that log_lock_waits message is emitted during a lock wait.
+$node->wait_for_log(qr/still waiting for AccessExclusiveLock on relation/,
+       $log_offset);
+
+# Wake the backend waiting on the lock and confirm it woke by calling
+# pg_log_backend_memory_contexts() and checking for the logged memory
+# contexts. This is necessary to test later that the "still waiting for"
+# message is logged exactly once per wait, even if the backend wakes
+# during the wait.
+$node->safe_psql(
+       'postgres', q[SELECT pg_log_backend_memory_contexts(pid)
+       FROM pg_locks WHERE locktype = 'relation' AND
+       relation = 'test_stat_tab'::regclass AND NOT granted;]);
+$node->wait_for_log(qr/logging memory contexts/, $log_offset);
+
 # deadlock_timeout fired, now commit in s1 and s2
 $s1->query_safe(q(COMMIT));
 $s2->query_safe(q(COMMIT));
@@ -120,6 +142,20 @@ $s2->query_safe(q(COMMIT));
 wait_for_pg_stat_lock($node, 'relation');
 ok(1, "Lock stats ok for relation");
 
+# Check that log_lock_waits message is emitted when the lock is acquired
+# after waiting.
+$node->wait_for_log(qr/acquired AccessExclusiveLock on relation/,
+       $log_offset);
+
+# Check that the "still waiting for" message is logged exactly once per wait,
+# even if the backend wakes during the wait.
+my $log_contents = slurp_file($node->logfile, $log_offset);
+my @still_waiting = ($log_contents =~ /still waiting for/g);
+is( scalar @still_waiting,
+       1,
+       "still waiting logged exactly once despite wakeups from pg_log_backend_memory_contexts()"
+);
+
 # close sessions
 $s1->quit;
 $s2->quit;
@@ -128,6 +164,8 @@ $s2->quit;
 
 setup_sessions();
 
+$log_offset = -s $node->logfile;
+
 $s1->query_safe(
        q[
 SELECT pg_stat_reset_shared('lock');
@@ -152,6 +190,10 @@ UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1';
 
 wait_and_detach($node, 'deadlock-timeout-fired');
 
+# Check that log_lock_waits message is emitted during a lock wait.
+$node->wait_for_log(qr/still waiting for ShareLock on transaction/,
+       $log_offset);
+
 # deadlock_timeout fired, now commit in s1 and s2
 $s1->query_safe(q(COMMIT));
 $s2->query_safe(q(COMMIT));
@@ -160,6 +202,10 @@ $s2->query_safe(q(COMMIT));
 wait_for_pg_stat_lock($node, 'transactionid');
 ok(1, "Lock stats ok for transactionid");
 
+# Check that log_lock_waits message is emitted when the lock is acquired
+# after waiting.
+$node->wait_for_log(qr/acquired ShareLock on transaction/, $log_offset);
+
 # Close sessions
 $s1->quit;
 $s2->quit;
@@ -168,6 +214,8 @@ $s2->quit;
 
 setup_sessions();
 
+$log_offset = -s $node->logfile;
+
 $s1->query_safe(
        q[
 SELECT pg_stat_reset_shared('lock');
@@ -190,6 +238,10 @@ SELECT pg_advisory_lock(1);
 
 wait_and_detach($node, 'deadlock-timeout-fired');
 
+# Check that log_lock_waits message is emitted during a lock wait.
+$node->wait_for_log(qr/still waiting for ExclusiveLock on advisory lock/,
+       $log_offset);
+
 # deadlock_timeout fired, now unlock and commit s2
 $s1->query_safe(q(SELECT pg_advisory_unlock(1)));
 $s2->query_safe(
@@ -202,6 +254,10 @@ COMMIT;
 wait_for_pg_stat_lock($node, 'advisory');
 ok(1, "Lock stats ok for advisory");
 
+# Check that log_lock_waits message is emitted when the lock is acquired
+# after waiting.
+$node->wait_for_log(qr/acquired ExclusiveLock on advisory lock/, $log_offset);
+
 # Close sessions
 $s1->quit;
 $s2->quit;
@@ -210,6 +266,8 @@ $s2->quit;
 
 setup_sessions();
 
+$log_offset = -s $node->logfile;
+
 $s1->query_safe(
        q[
 SELECT pg_stat_reset_shared('lock');
@@ -241,6 +299,15 @@ $s2->query_safe(q(COMMIT));
 wait_for_pg_stat_lock($node, 'relation');
 ok(1, "log_lock_waits has no impact on Lock stats");
 
+# Check that no log_lock_waits messages are emitted
+ok( !$node->log_contains(
+               "still waiting for AccessExclusiveLock on relation", $log_offset),
+       'check that no log_lock_waits message is emitted during a lock wait');
+ok( !$node->log_contains(
+               "acquired AccessExclusiveLock on relation", $log_offset),
+       'check that no log_lock_waits message is emitted when the lock is acquired after waiting'
+);
+
 # close sessions
 $s1->quit;
 $s2->quit;