On Wed, Mar 25, 2026 at 07:54:42PM +0000, Bertrand Drouvot wrote: > If you like the idea, maybe we could introduce query_until_stderr() in a > separate > commit. If you don't, then we could switch to looking in the server logfile > instead of the session stderr.
I like the patch, but I happen to not like my initial idea of relying on a NOTICE in an injection point combined with your new API in BackgroundPsql because we can already achieve the same with a wait injection point and use BackgroundPsql::query_until() with an \echo to detect that the command is blocked. The updated version attached uses this method (edited quickly your commit message). Like your patch there is no need for hardcoded sleeps and the CI's first impressions are actually good, but I am going to need more runs to gain more confidence. Note I should be able to do something here in 10 days or so. If you could confirm the stability on your side for the time being with more runs, that would help, of course. -- Michael
From fd56d27596834eb019460bffb038aebfa0fa94a4 Mon Sep 17 00:00:00 2001 From: Michael Paquier <[email protected]> Date: Thu, 26 Mar 2026 08:03:31 +0900 Subject: [PATCH v2] Add tests for lock stats, take two commit 7c64d56fd97 removed isolation test lock-stats because it was unstable in the CI for Windows, at least. This commit creates a new test for the lock stats using an injection point. This new injection point is created in ProcSleep() when we know that the deadlock timeout fired. Then the new tests follow this workflow: - session 1 holds a lock - session 2 attaches to the new injection point with the wait action. - session 2 is blocked by session 1 and waits until the injection point wait is reached. - session 1 releases its lock, session 2 commits - pg_stat_lock is polled until we get the counters for the lock type or die with a timeout. That way there is no sleep at all. Once we know that session 2 has waited longer the deadlock_timeout (thanks to the new injection point wait) then we can poll pg_stat_lock to get the updated stats. Author: Bertrand Drouvot <[email protected]> Discussion: https://postgr.es/m/acNTR1lLHwQJ0o%2BP%40ip-10-97-1-34.eu-west-3.compute.internal --- src/backend/storage/lmgr/proc.c | 2 + src/test/modules/test_misc/meson.build | 1 + .../modules/test_misc/t/011_lock_stats.pl | 249 ++++++++++++++++++ 3 files changed, 252 insertions(+) create mode 100644 src/test/modules/test_misc/t/011_lock_stats.pl diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c index 5c47cf13473e..b857a10354f7 100644 --- a/src/backend/storage/lmgr/proc.c +++ b/src/backend/storage/lmgr/proc.c @@ -52,6 +52,7 @@ #include "storage/procsignal.h" #include "storage/spin.h" #include "storage/standby.h" +#include "utils/injection_point.h" #include "utils/timeout.h" #include "utils/timestamp.h" #include "utils/wait_event.h" @@ -1560,6 +1561,7 @@ ProcSleep(LOCALLOCK *locallock) int usecs; long msecs; + INJECTION_POINT("deadlock-timeout-fired", NULL); TimestampDifference(get_timeout_start_time(DEADLOCK_TIMEOUT), GetCurrentTimestamp(), &secs, &usecs); diff --git a/src/test/modules/test_misc/meson.build b/src/test/modules/test_misc/meson.build index 6e8db1621a74..1b25d98f7f33 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_lock_stats.pl', ], # The injection points are cluster-wide, so disable installcheck 'runningcheck': false, diff --git a/src/test/modules/test_misc/t/011_lock_stats.pl b/src/test/modules/test_misc/t/011_lock_stats.pl new file mode 100644 index 000000000000..4281e842c981 --- /dev/null +++ b/src/test/modules/test_misc/t/011_lock_stats.pl @@ -0,0 +1,249 @@ + +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Test for the lock statistics +# +# 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. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +plan skip_all => 'Injection points not supported by this build' + unless $ENV{enable_injection_points} eq 'yes'; + +my $deadlock_timeout = 10; +my $s1; +my $s2; +my $node; + +# Setup the 2 sessions +sub setup_sessions +{ + $s1 = $node->background_psql('postgres'); + $s2 = $node->background_psql('postgres', on_error_stop => 0); + + # Setup injection points for the waiting session + $s2->query_safe(q[ + SELECT injection_points_set_local(); + SELECT injection_points_attach('deadlock-timeout-fired', 'wait'); + ]); +} + +# Fetch waits and wait_time from pg_stat_lock for a given lock type +# until they reached expected values: at least one wait and waiting longer +# than the deadlock_timeout. +sub wait_for_pg_stat_lock +{ + my ($node, $lock_type) = @_; + + $node->poll_query_until( + 'postgres', qq[ + SELECT waits > 0 AND wait_time >= $deadlock_timeout + FROM pg_stat_lock + WHERE locktype = '$lock_type'; + ]) or die "Timed out waiting for pg_stat_lock for $lock_type" +} + +# Convenience wrapper to wait for a point, then detach it. +sub wait_and_detach +{ + my ($node, $point_name) = @_; + + $node->wait_for_event('client backend', $point_name); + $node->safe_psql('postgres', + "SELECT injection_points_detach('$point_name');"); + $node->safe_psql('postgres', + "SELECT injection_points_wakeup('$point_name');"); +} + +# Node initialization +$node = PostgreSQL::Test::Cluster->new('node'); +$node->init(); +$node->append_conf('postgresql.conf', "deadlock_timeout = ${deadlock_timeout}ms"); +$node->start(); + +# Check if the extension injection_points is available +plan skip_all => 'Extension injection_points not installed' + unless $node->check_extension('injection_points'); + +$node->safe_psql('postgres', 'CREATE EXTENSION injection_points;'); + +$node->safe_psql( + 'postgres', q[ +CREATE TABLE test_stat_tab(key text not null, value int); +INSERT INTO test_stat_tab(key, value) VALUES('k0', 1); +]); + +############################################################################ + +####### Relation lock + +setup_sessions(); + +$s1->query_safe( + q[ +SELECT pg_stat_reset_shared('lock'); +BEGIN; +LOCK TABLE test_stat_tab; +]); + +# s2 setup +$s2->query_safe( + q[ +BEGIN; +SELECT pg_stat_force_next_flush(); +]); +# s2 blocks on LOCK. +$s2->query_until( + qr/lock_s2/, q[ +\echo lock_s2 +LOCK TABLE test_stat_tab; +]); + +wait_and_detach($node, 'deadlock-timeout-fired'); + +# deadlock_timeout fired, now commit in s1 and s2 +$s1->query_safe(q(COMMIT)); +$s2->query_safe(q(COMMIT)); + +# check that pg_stat_lock has been updated +wait_for_pg_stat_lock($node, 'relation'); +ok(1, "Lock stats ok for relation"); + +# close sessions +$s1->quit; +$s2->quit; + +####### transaction lock + +setup_sessions(); + +$s1->query_safe( + q[ +SELECT pg_stat_reset_shared('lock'); +INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1); +BEGIN; +UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1'; +]); + +# s2 setup +$s2->query_safe( + q[ +SET log_lock_waits = on; +BEGIN; +SELECT pg_stat_force_next_flush(); +]); +# s2 blocks here on UPDATE +$s2->query_until( + qr/lock_s2/, q[ +\echo lock_s2 +UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1'; +]); + +wait_and_detach($node, 'deadlock-timeout-fired'); + +# deadlock_timeout fired, now commit in s1 and s2 +$s1->query_safe(q(COMMIT)); +$s2->query_safe(q(COMMIT)); + +# check that pg_stat_lock has been updated +wait_for_pg_stat_lock($node, 'transactionid'); +ok(1, "Lock stats ok for transactionid"); + +# Close sessions +$s1->quit; +$s2->quit; + +####### advisory lock + +setup_sessions(); + +$s1->query_safe( + q[ +SELECT pg_stat_reset_shared('lock'); +SELECT pg_advisory_lock(1); +]); + +# s2 setup +$s2->query_safe( + q[ +SET log_lock_waits = on; +BEGIN; +SELECT pg_stat_force_next_flush(); +]); +# s2 blocks on the advisory lock. +$s2->query_until( + qr/lock_s2/, q[ +\echo lock_s2 +SELECT pg_advisory_lock(1); +]); + +wait_and_detach($node, 'deadlock-timeout-fired'); + +# deadlock_timeout fired, now unlock and commit s2 +$s1->query_safe(q(SELECT pg_advisory_unlock(1))); +$s2->query_safe( + q[ +SELECT pg_advisory_unlock(1); +COMMIT; +]); + +# check that pg_stat_lock has been updated +wait_for_pg_stat_lock($node, 'advisory'); +ok(1, "Lock stats ok for advisory"); + +# Close sessions +$s1->quit; +$s2->quit; + +####### Ensure log_lock_waits has no impact + +setup_sessions(); + +$s1->query_safe( + q[ +SELECT pg_stat_reset_shared('lock'); +BEGIN; +LOCK TABLE test_stat_tab; +]); + +# s2 setup +$s2->query_safe( + q[ +SET log_lock_waits = off; +BEGIN; +SELECT pg_stat_force_next_flush(); +]); +# s2 blocks on LOCK. +$s2->query_until( + qr/lock_s2/, q[ +\echo lock_s2 +LOCK TABLE test_stat_tab; +]); + +wait_and_detach($node, 'deadlock-timeout-fired'); + +# deadlock_timeout fired, now commit in s1 and s2 +$s1->query_safe(q(COMMIT)); +$s2->query_safe(q(COMMIT)); + +# check that pg_stat_lock has been updated +wait_for_pg_stat_lock($node, 'relation'); +ok(1, "log_lock_waits has no impact on Lock stats"); + +# close sessions +$s1->quit; +$s2->quit; + +# cleanup +$node->safe_psql('postgres', q[DROP TABLE test_stat_tab;]); + +done_testing(); -- 2.53.0
signature.asc
Description: PGP signature
