From b25a8d4201e20ec457685502420db22805c584ac Mon Sep 17 00:00:00 2001 From: Bertrand Drouvot Date: Wed, 25 Mar 2026 09:28:39 +0000 Subject: [PATCH v1] Add new tests for lock stats 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. This commit adds a new query_until_stderr() subroutine in BackgroundPsql.pm. It does the same as query_until() except that it is waiting for a desired stderr (and not stdout). Thanks to it the session can wait until it gets the injection point notice. Then the new tests follow this workflow: - session 1 holds a lock - session 2 attaches to the new injection point with the notice action - session 2 is blocked by session 1 and waits until the injection point notice is received - 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 than the deadlock timeout (thanks to the new injection point notice) then we can poll pg_stat_lock to get the updated stats. Author: Bertrand Drouvot 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 | 205 ++++++++++++++++++ .../perl/PostgreSQL/Test/BackgroundPsql.pm | 33 +++ 4 files changed, 241 insertions(+) 82.8% src/test/modules/test_misc/t/ 15.0% src/test/perl/PostgreSQL/Test/ diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c index 5c47cf13473..b857a10354f 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 6e8db1621a7..1b25d98f7f3 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 00000000000..c693a2ed268 --- /dev/null +++ b/src/test/modules/test_misc/t/011_lock_stats.pl @@ -0,0 +1,205 @@ + +# 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', 'notice'); + ]); +} + +# 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" +} + +# 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 blocks +$s2->query_until_stderr(qr/deadlock-timeout-fired/, q( +BEGIN; +SELECT pg_stat_force_next_flush(); +LOCK TABLE test_stat_tab; +)); + +# deadlock_timeout fired, now commit in s1 and s2 +$s1->query_safe(q(COMMIT)); +$s2->query(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 blocks +$s2->query_until_stderr(qr/deadlock-timeout-fired/, q( +SET log_lock_waits = on; +BEGIN; +SELECT pg_stat_force_next_flush(); +UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1'; +)); + +# deadlock_timeout fired, now commit in s1 and s2 +$s1->query_safe(q(COMMIT)); +$s2->query(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 blocks +$s2->query_until_stderr(qr/deadlock-timeout-fired/, q( +SET log_lock_waits = on; +BEGIN; +SELECT pg_stat_force_next_flush(); +SELECT pg_advisory_lock(1); +)); + +# deadlock_timeout fired, now unlock and commit s2 +$s1->query_safe(q(SELECT pg_advisory_unlock(1))); +$s2->query( + 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 blocks +$s2->query_until_stderr(qr/deadlock-timeout-fired/, q( +SET log_lock_waits = off; +BEGIN; +SELECT pg_stat_force_next_flush(); +LOCK TABLE test_stat_tab; +)); + +# deadlock_timeout fired, now commit in s1 and s2 +$s1->query_safe(q(COMMIT)); +$s2->query(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(); diff --git a/src/test/perl/PostgreSQL/Test/BackgroundPsql.pm b/src/test/perl/PostgreSQL/Test/BackgroundPsql.pm index c6ff2dbde4c..2c8dc3f66b7 100644 --- a/src/test/perl/PostgreSQL/Test/BackgroundPsql.pm +++ b/src/test/perl/PostgreSQL/Test/BackgroundPsql.pm @@ -357,6 +357,39 @@ sub query_until =pod +=item $session->query_until_stderr(until, query) + +Issue C and wait for C appearing in stderr rather than stdout. +C needs to end with newline and semicolon (if applicable, interactive +psql input may not require it) for psql to process the input. This can be useful +when using injection points with a notice action. + +=cut + +sub query_until_stderr +{ + my ($self, $until, $query) = @_; + my $ret; + local $Test::Builder::Level = $Test::Builder::Level + 1; + + $self->{timeout}->start() if (defined($self->{query_timer_restart})); + $self->{stdin} .= $query; + + pump_until($self->{run}, $self->{timeout}, \$self->{stderr}, $until); + + die "psql query timed out" if $self->{timeout}->is_expired; + + $ret = $self->{stdout}; + + # clear out output and stderr for the next query + $self->{stdout} = ''; + $self->{stderr} = ''; + + return $ret; +} + +=pod + =item $session->set_query_timer_restart() Configures the timer to be restarted before each query such that the defined -- 2.34.1