Feedback-ID: i0fe9450f:Fastmail
Date: Thu, 26 Mar 2026 08:06:20 +0900
From: Michael Paquier <michael@paquier.xyz>
To: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
Cc: Andres Freund <andres@anarazel.de>, Jeff Davis <pgsql@j-davis.com>,
	Greg Sabino Mullane <htamfids@gmail.com>,
	pgsql-hackers@lists.postgresql.org
Subject: Re: Adding locks statistics
Message-ID: <acRqbLtT-aJDRSRl@paquier.xyz>
References: <abq71eL7qIdWAxMD@ip-10-97-1-34.eu-west-3.compute.internal>
 <abufUya2oK-_PJ3E@paquier.xyz>
 <abvrRZo52Yx9ZzWQ@ip-10-97-1-34.eu-west-3.compute.internal>
 <ab4y1UQUsSS7bSVd@paquier.xyz>
 <acI3H5aucJNS2w78@paquier.xyz>
 <hlkdrplgrmudbspibsuq6xooxrqxqsgwo6x5b6x5ptvkgjbe7w@xogt6xgua6dz>
 <acMiT69EEGKHWGM5@paquier.xyz>
 <acNTR1lLHwQJ0o+P@ip-10-97-1-34.eu-west-3.compute.internal>
 <acNxrWn2bvDARnC3@paquier.xyz>
 <acQ9gnE84897xHfQ@ip-10-97-1-34.eu-west-3.compute.internal>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="7dMuQNfOHt/KNA9S"
Content-Disposition: inline
In-Reply-To: <acQ9gnE84897xHfQ@ip-10-97-1-34.eu-west-3.compute.internal>
Archived-At: 
 <https://www.postgresql.org/message-id/acRqbLtT-aJDRSRl%40paquier.xyz>
Precedence: bulk


--7dMuQNfOHt/KNA9S
Content-Type: multipart/mixed; boundary="Q2ZM9caff9qnV3QK"
Content-Disposition: inline


--Q2ZM9caff9qnV3QK
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

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

--Q2ZM9caff9qnV3QK
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment;
	filename=v2-0001-Add-tests-for-lock-stats-take-two.patch
Content-Transfer-Encoding: quoted-printable

=46rom fd56d27596834eb019460bffb038aebfa0fa94a4 Mon Sep 17 00:00:00 2001
=46rom: Michael Paquier <michael@paquier.xyz>
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 <bertranddrouvot.pg@gmail.com>
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/pro=
c.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;
=20
+			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 +=3D {
       '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/modu=
les/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 te=
st a
+# dedicated lock type.
+# The last one checks that log_lock_waits has no impact on the statistics
+# counters.
+
+use strict;
+use warnings FATAL =3D> 'all';
+
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+
+plan skip_all =3D> 'Injection points not supported by this build'
+  unless $ENV{enable_injection_points} eq 'yes';
+
+my $deadlock_timeout =3D 10;
+my $s1;
+my $s2;
+my $node;
+
+# Setup the 2 sessions
+sub setup_sessions
+{
+	$s1 =3D $node->background_psql('postgres');
+	$s2 =3D $node->background_psql('postgres', on_error_stop =3D> 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) =3D @_;
+
+	$node->poll_query_until(
+		'postgres', qq[
+		SELECT waits > 0 AND wait_time >=3D $deadlock_timeout
+		FROM pg_stat_lock
+		WHERE locktype =3D '$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)  =3D @_;
+
+	$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 =3D PostgreSQL::Test::Cluster->new('node');
+$node->init();
+$node->append_conf('postgresql.conf', "deadlock_timeout =3D ${deadlock_tim=
eout}ms");
+$node->start();
+
+# Check if the extension injection_points is available
+plan skip_all =3D> '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 =3D value + 1 WHERE key =3D 'k1';
+]);
+
+# s2 setup
+$s2->query_safe(
+	q[
+SET log_lock_waits =3D 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 =3D value + 1 WHERE key =3D '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 =3D 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 =3D 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();
--=20
2.53.0


--Q2ZM9caff9qnV3QK--

--7dMuQNfOHt/KNA9S
Content-Type: application/pgp-signature; name=signature.asc

-----BEGIN PGP SIGNATURE-----

iQIzBAEBCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAmnEamwACgkQnvQgOdby
QH1lPw/7BoCHz7P7w94PrY9R3FgN04xe37qtO2fmFjQ/5co9ERV9mVKM2tNKTe2J
o5PMJR3etn51w2lQFcwltcGPSXzeUChaGNf0RfgAq/5JYTACARAK39hcAPbf8gTH
Vkini6TPJrJmVc77/vteu5rXc6MFWRargwgkljrgKCx0ro8vvojGGw26l/j0GwDC
9hkt9SkfxhN2V86UKS75i6pFCr4ikqNrxDBy0Uj3dD2TCq4NKUnfAfh8DzRKinUF
TvtA2TEeWTB2q68eu6Mv8qphgSEn/2faAWmzNmGX9+dQZBXhdz25BvGOtWiJ8pGm
WBXa6tkI3BAJflOH6nxqBKevuQS48kjljC9s8v9xA0PiKXnnBsSXjM1s5kEynrD1
XSeI6F2xVcBo4fuGFl/iZAFD0du3hYdMnLeOKcoJQDisgTG6PucsmD+PsDnih2O9
b/BfyNA7bsxFzizHEqPEvBL/tTfl3tlK62ExFnXiUNyd/FH1B0cGbonLfTM4PQ8f
tIqncz5a0VKQpIicDP23n9zR9Avkdy6LtKik0Ajqb6H0m13fayjUw3vjD+S04rAA
ZJUycKLidGjjpPX3j6dfIjEWPndpdqMUDCVfLCA9sahpG5WERd+78j/AYvC9IpkC
/vwV6XJQH29J/4UJPzsdIaFbKj2JdAdBw53MxBuZtFJeadFvYtg=
=LAcL
-----END PGP SIGNATURE-----

--7dMuQNfOHt/KNA9S--