agora inbox for pgsql-hackers@postgresql.org  

help / color / mirror / Atom feed

[PATCH v3] Use open file description locks for lockfiles
5+ messages / 2 participants
[nested] [flat]

* [PATCH v3] Use open file description locks for lockfiles
@ 2025-12-18 17:21  Dmitrii Dolgov <9erthalion6@gmail.com>
  0 siblings, 0 replies; 5+ messages in thread

From: Dmitrii Dolgov @ 2025-12-18 17:21 UTC (permalink / raw)

When starting up, postmaster checks for an existing data directory lockfile. If
this file contains current process PID, it's assumed to be stale. Turns out
there is another possibility: we might be running in a PID namespace, and there
is another postgres running inside another PID namespace using the same data
directory. The result is that we don't see another process due to namespace
isolation and start concurrently with the other.

To prevent such situations, at startup use fcntl to get an exclusive open file
description lock for data directory lockfile. Since such locks are associated
with open file descriptors, meaning they're not affected by PID namespace
isolation. It's a "best effort" locking, intended to work with already existing
mechanism, not replace it.

This approach was discussed multiple times in the past, and usually was
rejected as the main work horse for the data directory lockfile due to:

* Portability issues. Open file description lock was a non-POSIX extension in
  Linux and similar flock is from BSD standard. But looks like everybody agrees
  that such locks make more sense than a typical advisory locks, and
  F_OFD_SETLK made its way into POSIX.1 2024 [1].

* Issues with NFS. The current state of things here looks like this:

  - NFSv3 doesn't implement open file description locks, they're converted to
    advisory locks instead. Advisory locks are subject to namespace isolation,
    meaning that processes in different PID namespaces will not see each other
    advisory lock, and it's still possible to run multiple postgres
    instances on the same data directory.

  - NFSv4 uses a lease system for locking, I haven't found any mention of
    conversion to advisory locks neither in the man page nor in RFC [2].

To summarize, the approach is now considered POSIX and should fix the described
problem everywhere, except NFSv3.

Use open file description lock for both data directory and socker
lockfiles, since both are affected in the same way.

[1]: https://pubs.opengroup.org/onlinepubs/9799919799/functions/fcntl.html
[2]: https://www.rfc-editor.org/rfc/rfc7530

Reviewed-by: Ilmar Yunusov <tanswis42@gmail.com>
---
 configure                         |  14 +++
 configure.ac                      |   3 +
 meson.build                       |   1 +
 src/backend/utils/init/miscinit.c | 136 ++++++++++++++++++++++++------
 src/include/pg_config.h.in        |   4 +
 src/tools/pgindent/typedefs.list  |   1 +
 6 files changed, 134 insertions(+), 25 deletions(-)

diff --git a/configure b/configure
index 5f77f3cac29..15bda6c6413 100755
--- a/configure
+++ b/configure
@@ -16444,6 +16444,20 @@ cat >>confdefs.h <<_ACEOF
 _ACEOF
 
 
+# Linux open file descriptor locks
+ac_fn_c_check_decl "$LINENO" "F_OFD_SETLK" "ac_cv_have_decl_F_OFD_SETLK" "#include <fcntl.h>
+"
+if test "x$ac_cv_have_decl_F_OFD_SETLK" = xyes; then :
+  ac_have_decl=1
+else
+  ac_have_decl=0
+fi
+
+cat >>confdefs.h <<_ACEOF
+#define HAVE_DECL_F_OFD_SETLK $ac_have_decl
+_ACEOF
+
+
 ac_fn_c_check_func "$LINENO" "explicit_bzero" "ac_cv_func_explicit_bzero"
 if test "x$ac_cv_func_explicit_bzero" = xyes; then :
   $as_echo "#define HAVE_EXPLICIT_BZERO 1" >>confdefs.h
diff --git a/configure.ac b/configure.ac
index 61cee42daa7..e24cb7a6f01 100644
--- a/configure.ac
+++ b/configure.ac
@@ -1913,6 +1913,9 @@ AC_CHECK_DECLS([memset_s], [], [], [#define __STDC_WANT_LIB_EXT1__ 1
 # This is probably only present on macOS, but may as well check always
 AC_CHECK_DECLS(F_FULLFSYNC, [], [], [#include <fcntl.h>])
 
+# Linux open file descriptor locks
+AC_CHECK_DECLS([F_OFD_SETLK], [], [], [#include <fcntl.h>])
+
 AC_REPLACE_FUNCS(m4_normalize([
 	explicit_bzero
 	getopt
diff --git a/meson.build b/meson.build
index 568e0e150bf..3d641dc0403 100644
--- a/meson.build
+++ b/meson.build
@@ -2901,6 +2901,7 @@ decl_checks = [
   ['strlcpy', 'string.h'],
   ['strsep',  'string.h'],
   ['timingsafe_bcmp',  'string.h'],
+  ['F_OFD_SETLK', 'fcntl.h'],
 ]
 
 # Need to check for function declarations for these functions, because
diff --git a/src/backend/utils/init/miscinit.c b/src/backend/utils/init/miscinit.c
index 7ffc808073a..26c3324542c 100644
--- a/src/backend/utils/init/miscinit.c
+++ b/src/backend/utils/init/miscinit.c
@@ -69,6 +69,15 @@ static List *lock_files = NIL;
 
 static Latch LocalLatchData;
 
+typedef struct
+{
+	/* LockFile name. */
+	const char *filename;
+
+	/* File descriptor for open file description lock. */
+	int			fd;
+} LockFile;
+
 /* ----------------------------------------------------------------
  *		ignoring system indexes support stuff
  *
@@ -1119,6 +1128,48 @@ RestoreClientConnectionInfo(char *conninfo)
  *-------------------------------------------------------------------------
  */
 
+/*
+ * OFD lock the specified lockfile.
+ *
+ * Lock the lockfile with an open file description lock. If the lock is already
+ * taken, it's a hard stop. It's only a best effort test, and any other errors
+ * are ignored. On succes the file descriptor is duplicated, to make sure there
+ * will be at least one open copy of it to keep the lock.
+ *
+ * filename argument is used only for reporting purposes.
+ */
+static int
+OFDLockFile(int fd, const char *filename)
+{
+#if HAVE_DECL_F_OFD_SETLK
+	struct flock lock;
+
+	lock.l_type = F_WRLCK;
+	lock.l_whence = SEEK_SET;
+	lock.l_start = 0;
+	lock.l_len = 0;
+	lock.l_pid = 0;
+
+	if (fcntl(fd, F_OFD_SETLK, &lock) == -1)
+	{
+		if (errno == EAGAIN)
+			ereport(FATAL,
+					(errcode(ERRCODE_LOCK_FILE_EXISTS),
+					 errmsg("cannot lock the lock file \"%s\"", filename),
+					 errhint("Another server is starting.")));
+		else
+		{
+			elog(WARNING, "Failed locking file \"%s\", %m", filename);
+			return -1;
+		}
+	}
+	else
+		return dup(fd);
+#else
+	return -1
+#endif
+}
+
 /*
  * proc_exit callback to remove lockfiles.
  */
@@ -1129,9 +1180,16 @@ UnlinkLockFiles(int status, Datum arg)
 
 	foreach(l, lock_files)
 	{
-		char	   *curfile = (char *) lfirst(l);
+		LockFile   *lock_file = (LockFile *) lfirst(l);
 
-		unlink(curfile);
+		/*
+		 * Close the file descriptor, which keeps the open file description
+		 * lock.
+		 */
+		if (lock_file->fd > 0)
+			close(lock_file->fd);
+
+		unlink(lock_file->filename);
 		/* Should we complain if the unlink fails? */
 	}
 	/* Since we're about to exit, no need to reclaim storage */
@@ -1161,7 +1219,9 @@ CreateLockFile(const char *filename, bool amPostmaster,
 			   const char *socketDir,
 			   bool isDDLock, const char *refName)
 {
-	int			fd;
+	int			fd,
+				flock_fd = -1;
+	LockFile   *lock_file;
 	char		buffer[MAXPGPATH * 2 + 256];
 	int			ntries;
 	int			len;
@@ -1173,22 +1233,32 @@ CreateLockFile(const char *filename, bool amPostmaster,
 	const char *envvar;
 
 	/*
-	 * If the PID in the lockfile is our own PID or our parent's or
-	 * grandparent's PID, then the file must be stale (probably left over from
-	 * a previous system boot cycle).  We need to check this because of the
-	 * likelihood that a reboot will assign exactly the same PID as we had in
-	 * the previous reboot, or one that's only one or two counts larger and
-	 * hence the lockfile's PID now refers to an ancestor shell process.  We
-	 * allow pg_ctl to pass down its parent shell PID (our grandparent PID)
-	 * via the environment variable PG_GRANDPARENT_PID; this is so that
-	 * launching the postmaster via pg_ctl can be just as reliable as
-	 * launching it directly.  There is no provision for detecting
-	 * further-removed ancestor processes, but if the init script is written
-	 * carefully then all but the immediate parent shell will be root-owned
-	 * processes and so the kill test will fail with EPERM.  Note that we
-	 * cannot get a false negative this way, because an existing postmaster
-	 * would surely never launch a competing postmaster or pg_ctl process
-	 * directly.
+	 * If we find an already existing lockfile containing our own PID, there
+	 * are few options:
+	 *
+	 * - There is another process, that we don't see due to PID namespace
+	 * isolation, which is already running in this data directory.
+	 *
+	 * To prevent two concurrent processes working with the same data
+	 * directory, we first try to lock the lockfile exclusively.
+	 *
+	 * - The file must be stale, probably left over from a previous system
+	 * boot cycle. The same if the lockfile contains our parent's or
+	 * grandparent's PID.
+	 *
+	 * We need to check this because of the likelihood that a reboot will
+	 * assign exactly the same PID as we had in the previous reboot, or one
+	 * that's only one or two counts larger and hence the lockfile's PID now
+	 * refers to an ancestor shell process.  We allow pg_ctl to pass down its
+	 * parent shell PID (our grandparent PID) via the environment variable
+	 * PG_GRANDPARENT_PID; this is so that launching the postmaster via pg_ctl
+	 * can be just as reliable as launching it directly.  There is no
+	 * provision for detecting further-removed ancestor processes, but if the
+	 * init script is written carefully then all but the immediate parent
+	 * shell will be root-owned processes and so the kill test will fail with
+	 * EPERM.  Note that we cannot get a false negative this way, because an
+	 * existing postmaster would surely never launch a competing postmaster or
+	 * pg_ctl process directly.
 	 */
 	my_pid = getpid();
 
@@ -1224,7 +1294,11 @@ CreateLockFile(const char *filename, bool amPostmaster,
 		 */
 		fd = open(filename, O_RDWR | O_CREAT | O_EXCL, pg_file_create_mode);
 		if (fd >= 0)
-			break;				/* Success; exit the retry loop */
+		{
+			/* Success; lock and exit the retry loop */
+			flock_fd = OFDLockFile(fd, filename);
+			break;
+		}
 
 		/*
 		 * Couldn't create the pid file. Probably it already exists.
@@ -1238,8 +1312,12 @@ CreateLockFile(const char *filename, bool amPostmaster,
 		/*
 		 * Read the file to get the old owner's PID.  Note race condition
 		 * here: file might have been deleted since we tried to create it.
+		 *
+		 * We're going to use the same fd for flock, and want to create a
+		 * write lock for the latter one. Since both fd and the lock have to
+		 * be of the same type, open the file for read and write.
 		 */
-		fd = open(filename, O_RDONLY, pg_file_create_mode);
+		fd = open(filename, O_RDWR, pg_file_create_mode);
 		if (fd < 0)
 		{
 			if (errno == ENOENT)
@@ -1249,6 +1327,10 @@ CreateLockFile(const char *filename, bool amPostmaster,
 					 errmsg("could not open lock file \"%s\": %m",
 							filename)));
 		}
+
+		/* Try to lock the file. We stop here, if it's already locked. */
+		flock_fd = OFDLockFile(fd, filename);
+
 		pgstat_report_wait_start(WAIT_EVENT_LOCK_FILE_CREATE_READ);
 		if ((len = read(fd, buffer, sizeof(buffer) - 1)) < 0)
 			ereport(FATAL,
@@ -1448,7 +1530,11 @@ CreateLockFile(const char *filename, bool amPostmaster,
 	 * Use lcons so that the lock files are unlinked in reverse order of
 	 * creation; this is critical!
 	 */
-	lock_files = lcons(pstrdup(filename), lock_files);
+	lock_file = palloc0_object(LockFile);
+	lock_file->filename = pstrdup(filename);
+	lock_file->fd = flock_fd;
+
+	lock_files = lcons(lock_file, lock_files);
 }
 
 /*
@@ -1495,14 +1581,14 @@ TouchSocketLockFiles(void)
 
 	foreach(l, lock_files)
 	{
-		char	   *socketLockFile = (char *) lfirst(l);
+		LockFile   *lock_file = (LockFile *) lfirst(l);
 
 		/* No need to touch the data directory lock file, we trust */
-		if (strcmp(socketLockFile, DIRECTORY_LOCK_FILE) == 0)
+		if (strcmp(lock_file->filename, DIRECTORY_LOCK_FILE) == 0)
 			continue;
 
 		/* we just ignore any error here */
-		(void) utime(socketLockFile, NULL);
+		(void) utime(lock_file->filename, NULL);
 	}
 }
 
diff --git a/src/include/pg_config.h.in b/src/include/pg_config.h.in
index 4f8113c144b..cc38c06dc13 100644
--- a/src/include/pg_config.h.in
+++ b/src/include/pg_config.h.in
@@ -85,6 +85,10 @@
    don't. */
 #undef HAVE_DECL_F_FULLFSYNC
 
+/* Define to 1 if you have the declaration of `F_OFD_SETLK', and to 0 if you
+   don't. */
+#undef HAVE_DECL_F_OFD_SETLK
+
 /* Define to 1 if you have the declaration of `memset_s', and to 0 if you
    don't. */
 #undef HAVE_DECL_MEMSET_S
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index 1969d467c1d..185d69b5520 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -1653,6 +1653,7 @@ LocationLen
 LockAcquireResult
 LockClauseStrength
 LockData
+LockFile
 LockInfoData
 LockInstanceData
 LockMethod

base-commit: 031904048aa22e7c70dc8e9c170e2743f9b0f090
-- 
2.52.0


--zdel3ow7bygx53fm--





^ permalink  raw  reply  [nested|flat] 5+ messages in thread

* [PATCH v7 3/3] Introduce a new track_lock_timing GUC
@ 2026-02-20 06:13  Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
  0 siblings, 0 replies; 5+ messages in thread

From: Bertrand Drouvot @ 2026-02-20 06:13 UTC (permalink / raw)

A new GUC (track_lock_timing) is added and defaults to on. If on, timed_waits and
wait_time counters are incremented if the session waited longer than deadlock_timeout
to acquire the lock. It's on by default, as this is the same idea as 2aac62be8cb.
---
 doc/src/sgml/config.sgml                      |  19 ++
 doc/src/sgml/monitoring.sgml                  |   4 +-
 src/backend/storage/lmgr/proc.c               | 165 ++++++++++--------
 src/backend/utils/misc/guc_parameters.dat     |   6 +
 src/backend/utils/misc/postgresql.conf.sample |   1 +
 src/include/pgstat.h                          |   1 +
 src/test/isolation/expected/stats.out         |  24 +--
 src/test/isolation/expected/stats_1.out       |  24 +--
 src/test/isolation/specs/stats.spec           |  24 +--
 9 files changed, 153 insertions(+), 115 deletions(-)
   7.5% doc/src/sgml/
  48.4% src/backend/storage/lmgr/
  35.8% src/test/isolation/expected/
   6.0% src/test/isolation/specs/

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 20dbcaeb3ee..1e6778576ea 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -8841,6 +8841,25 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-track-lock-timing" xreflabel="track_lock_timing">
+      <term><varname>track_lock_timing</varname> (<type>boolean</type>)
+      <indexterm>
+       <primary><varname>track_lock_timing</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+      <listitem>
+       <para>
+        Enables timing of lock waits. This parameter is on by default, as it tracks
+        only the timings for successful acquisitions that waited longer than
+        <xref linkend="guc-deadlock-timeout"/>. Lock timing information is
+        displayed in the <link linkend="monitoring-pg-stat-lock-view">
+        <structname>pg_stat_lock</structname></link> view.
+        Only superusers and users with the appropriate <literal>SET</literal>
+        privilege can change this setting.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry id="guc-track-wal-io-timing" xreflabel="track_wal_io_timing">
       <term><varname>track_wal_io_timing</varname> (<type>boolean</type>)
       <indexterm>
diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml
index cfcb8189418..277275fdcb5 100644
--- a/doc/src/sgml/monitoring.sgml
+++ b/doc/src/sgml/monitoring.sgml
@@ -3193,7 +3193,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage
        </para>
        <para>
         Number of times a lock of this type had to wait because of a
-        conflicting lock. Only incremented when <xref linkend="guc-log-lock-waits"/>
+        conflicting lock. Only incremented when <xref linkend="guc-track-lock-timing"/>
         is enabled and the lock was successfully acquired after waiting longer
         than <xref linkend="guc-deadlock-timeout"/>.
        </para>
@@ -3207,7 +3207,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage
        </para>
        <para>
         Total time spent waiting for locks of this type, in milliseconds.
-        Only incremented when <xref linkend="guc-log-lock-waits"/> is enabled and
+        Only incremented when <xref linkend="guc-track-lock-timing"/> is enabled and
         the lock was successfully acquired after waiting longer than
         <xref linkend="guc-deadlock-timeout"/>.
        </para>
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index bee4a3c2b89..18e42959e96 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -62,6 +62,7 @@ int			IdleInTransactionSessionTimeout = 0;
 int			TransactionTimeout = 0;
 int			IdleSessionTimeout = 0;
 bool		log_lock_waits = true;
+bool		track_lock_timing = true;
 
 /* Pointer to this process's PGPROC struct, if any */
 PGPROC	   *MyProc = NULL;
@@ -1545,99 +1546,110 @@ ProcSleep(LOCALLOCK *locallock)
 
 		/*
 		 * If awoken after the deadlock check interrupt has run, and
-		 * log_lock_waits is on, then report about the wait.
+		 * log_lock_waits or track_lock_timing is on, then report or track
+		 * about the wait.
 		 */
-		if (log_lock_waits && deadlock_state != DS_NOT_YET_CHECKED)
+		if ((log_lock_waits || track_lock_timing) &&
+			deadlock_state != DS_NOT_YET_CHECKED)
 		{
-			StringInfoData buf,
-						lock_waiters_sbuf,
-						lock_holders_sbuf;
-			const char *modename;
 			long		secs;
 			int			usecs;
 			long		msecs;
-			int			lockHoldersNum = 0;
 
-			initStringInfo(&buf);
-			initStringInfo(&lock_waiters_sbuf);
-			initStringInfo(&lock_holders_sbuf);
-
-			DescribeLockTag(&buf, &locallock->tag.lock);
-			modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid,
-									   lockmode);
 			TimestampDifference(get_timeout_start_time(DEADLOCK_TIMEOUT),
 								GetCurrentTimestamp(),
 								&secs, &usecs);
 			msecs = secs * 1000 + usecs / 1000;
 			usecs = usecs % 1000;
 
-			/* Gather a list of all lock holders and waiters */
-			LWLockAcquire(partitionLock, LW_SHARED);
-			GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf,
-									 &lock_waiters_sbuf, &lockHoldersNum);
-			LWLockRelease(partitionLock);
-
-			if (deadlock_state == DS_SOFT_DEADLOCK)
-				ereport(LOG,
-						(errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs),
-						 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
-											   "Processes holding the lock: %s. Wait queue: %s.",
-											   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
-			else if (deadlock_state == DS_HARD_DEADLOCK)
-			{
-				/*
-				 * This message is a bit redundant with the error that will be
-				 * reported subsequently, but in some cases the error report
-				 * might not make it to the log (eg, if it's caught by an
-				 * exception handler), and we want to ensure all long-wait
-				 * events get logged.
-				 */
-				ereport(LOG,
-						(errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs),
-						 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
-											   "Processes holding the lock: %s. Wait queue: %s.",
-											   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
-			}
-
-			if (myWaitStatus == PROC_WAIT_STATUS_WAITING)
-				ereport(LOG,
-						(errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs),
-						 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
-											   "Processes holding the lock: %s. Wait queue: %s.",
-											   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
-			else if (myWaitStatus == PROC_WAIT_STATUS_OK)
-			{
-				/* Increment the timed lock statistics counters */
+			/* Increment the timed lock statistics counters */
+			if (track_lock_timing && myWaitStatus == PROC_WAIT_STATUS_OK)
 				pgstat_count_lock_timed_wait(locallock->tag.lock.locktag_type,
 											 msecs);
 
-				ereport(LOG,
-						(errmsg("process %d acquired %s on %s after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs)));
-			}
-			else
+			if (log_lock_waits)
 			{
-				Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR);
-
-				/*
-				 * Currently, the deadlock checker always kicks its own
-				 * process, which means that we'll only see
-				 * PROC_WAIT_STATUS_ERROR when deadlock_state ==
-				 * DS_HARD_DEADLOCK, and there's no need to print redundant
-				 * messages.  But for completeness and future-proofing, print
-				 * a message if it looks like someone else kicked us off the
-				 * lock.
-				 */
-				if (deadlock_state != DS_HARD_DEADLOCK)
+				StringInfoData buf,
+							lock_waiters_sbuf,
+							lock_holders_sbuf;
+				const char *modename;
+				int			lockHoldersNum = 0;
+
+				initStringInfo(&buf);
+				initStringInfo(&lock_waiters_sbuf);
+				initStringInfo(&lock_holders_sbuf);
+
+				DescribeLockTag(&buf, &locallock->tag.lock);
+				modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid,
+										   lockmode);
+
+				/* Gather a list of all lock holders and waiters */
+				LWLockAcquire(partitionLock, LW_SHARED);
+				GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf,
+										 &lock_waiters_sbuf, &lockHoldersNum);
+				LWLockRelease(partitionLock);
+
+				if (deadlock_state == DS_SOFT_DEADLOCK)
 					ereport(LOG,
-							(errmsg("process %d failed to acquire %s on %s after %ld.%03d ms",
+							(errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms",
 									MyProcPid, modename, buf.data, msecs, usecs),
 							 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
 												   "Processes holding the lock: %s. Wait queue: %s.",
 												   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+				else if (deadlock_state == DS_HARD_DEADLOCK)
+				{
+					/*
+					 * This message is a bit redundant with the error that
+					 * will be reported subsequently, but in some cases the
+					 * error report might not make it to the log (eg, if it's
+					 * caught by an exception handler), and we want to ensure
+					 * all long-wait events get logged.
+					 */
+					ereport(LOG,
+							(errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms",
+									MyProcPid, modename, buf.data, msecs, usecs),
+							 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
+												   "Processes holding the lock: %s. Wait queue: %s.",
+												   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+				}
+
+				if (myWaitStatus == PROC_WAIT_STATUS_WAITING)
+					ereport(LOG,
+							(errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
+									MyProcPid, modename, buf.data, msecs, usecs),
+							 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
+												   "Processes holding the lock: %s. Wait queue: %s.",
+												   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+
+				else if (myWaitStatus == PROC_WAIT_STATUS_OK)
+					ereport(LOG,
+							(errmsg("process %d acquired %s on %s after %ld.%03d ms",
+									MyProcPid, modename, buf.data, msecs, usecs)));
+				else
+				{
+					Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR);
+
+					/*
+					 * Currently, the deadlock checker always kicks its own
+					 * process, which means that we'll only see
+					 * PROC_WAIT_STATUS_ERROR when deadlock_state ==
+					 * DS_HARD_DEADLOCK, and there's no need to print
+					 * redundant messages.  But for completeness and
+					 * future-proofing, print a message if it looks like
+					 * someone else kicked us off the lock.
+					 */
+					if (deadlock_state != DS_HARD_DEADLOCK)
+						ereport(LOG,
+								(errmsg("process %d failed to acquire %s on %s after %ld.%03d ms",
+										MyProcPid, modename, buf.data, msecs, usecs),
+								 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
+													   "Processes holding the lock: %s. Wait queue: %s.",
+													   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+				}
+
+				pfree(buf.data);
+				pfree(lock_holders_sbuf.data);
+				pfree(lock_waiters_sbuf.data);
 			}
 
 			/*
@@ -1645,14 +1657,13 @@ ProcSleep(LOCALLOCK *locallock)
 			 * state so we don't print the above messages again.
 			 */
 			deadlock_state = DS_NO_DEADLOCK;
-
-			pfree(buf.data);
-			pfree(lock_holders_sbuf.data);
-			pfree(lock_waiters_sbuf.data);
 		}
 	} while (myWaitStatus == PROC_WAIT_STATUS_WAITING);
 
-	/* Count lock waits unconditionally, regardless of log_lock_waits */
+	/*
+	 * Count lock waits unconditionally, regardless of log_lock_waits or
+	 * track_lock_timing.
+	 */
 	pgstat_count_lock_waits(locallock->tag.lock.locktag_type);
 
 	/*
diff --git a/src/backend/utils/misc/guc_parameters.dat b/src/backend/utils/misc/guc_parameters.dat
index 9507778415d..c21e6c6ea4e 100644
--- a/src/backend/utils/misc/guc_parameters.dat
+++ b/src/backend/utils/misc/guc_parameters.dat
@@ -3110,6 +3110,12 @@
   boot_val => 'false',
 },
 
+{ name => 'track_lock_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE',
+  short_desc => 'Collects timing statistics for lock acquisition.',
+  variable => 'track_lock_timing',
+  boot_val => 'true',
+},
+
 { name => 'track_wal_io_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE',
   short_desc => 'Collects timing statistics for WAL I/O activity.',
   variable => 'track_wal_io_timing',
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index f938cc65a3a..8a3a704aaa5 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -685,6 +685,7 @@
 #track_counts = on
 #track_cost_delay_timing = off
 #track_io_timing = off
+#track_lock_timing = on
 #track_wal_io_timing = off
 #track_functions = none                 # none, pl, all
 #stats_fetch_consistency = cache        # cache, none, snapshot
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index a4cc006794d..62a9dc1b35e 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -840,6 +840,7 @@ extern PgStat_WalStats *pgstat_fetch_stat_wal(void);
 extern PGDLLIMPORT bool pgstat_track_counts;
 extern PGDLLIMPORT int pgstat_track_functions;
 extern PGDLLIMPORT int pgstat_fetch_consistency;
+extern PGDLLIMPORT bool track_lock_timing;
 
 
 /*
diff --git a/src/test/isolation/expected/stats.out b/src/test/isolation/expected/stats.out
index 86d70a0705c..f9cd78f03b3 100644
--- a/src/test/isolation/expected/stats.out
+++ b/src/test/isolation/expected/stats.out
@@ -3752,7 +3752,7 @@ test_stat_func|                         1|t               |t
 
 step s1_commit: COMMIT;
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3765,9 +3765,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
@@ -3794,7 +3794,7 @@ t       |t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3807,9 +3807,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1);
 step s1_begin: BEGIN;
 step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1';
@@ -3837,7 +3837,7 @@ t       |t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3850,9 +3850,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_lock_advisory_lock: SELECT pg_advisory_lock(1);
 pg_advisory_lock
 ----------------
@@ -3899,7 +3899,7 @@ t       |t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3912,9 +3912,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_unset_log_lock_waits: SET log_lock_waits = off;
+step s2_unset_track_lock_timing: SET track_lock_timing = off;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
diff --git a/src/test/isolation/expected/stats_1.out b/src/test/isolation/expected/stats_1.out
index 4e4c68b4525..955f6ff5ec0 100644
--- a/src/test/isolation/expected/stats_1.out
+++ b/src/test/isolation/expected/stats_1.out
@@ -3776,7 +3776,7 @@ test_stat_func|                         1|t               |t
 
 step s1_commit: COMMIT;
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3789,9 +3789,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
@@ -3818,7 +3818,7 @@ t       |t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3831,9 +3831,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1);
 step s1_begin: BEGIN;
 step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1';
@@ -3861,7 +3861,7 @@ t       |t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3874,9 +3874,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_lock_advisory_lock: SELECT pg_advisory_lock(1);
 pg_advisory_lock
 ----------------
@@ -3923,7 +3923,7 @@ t       |t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3936,9 +3936,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_unset_log_lock_waits: SET log_lock_waits = off;
+step s2_unset_track_lock_timing: SET track_lock_timing = off;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
diff --git a/src/test/isolation/specs/stats.spec b/src/test/isolation/specs/stats.spec
index d4b53545198..7c8e2a9214e 100644
--- a/src/test/isolation/specs/stats.spec
+++ b/src/test/isolation/specs/stats.spec
@@ -132,7 +132,7 @@ step s1_slru_check_stats {
 
 # Lock stats steps
 step s1_set_deadlock_timeout { SET deadlock_timeout = '10ms'; }
-step s1_set_log_lock_waits { SET log_lock_waits = on; }
+step s1_set_track_lock_timing { SET track_lock_timing = on; }
 step s1_reset_stat_lock { SELECT pg_stat_reset_shared('lock'); }
 step s1_sleep { SELECT pg_sleep(0.5); }
 step s1_lock_relation { LOCK TABLE test_stat_tab; }
@@ -174,8 +174,8 @@ step s2_big_notify { SELECT pg_notify('stats_test_use',
 
 # Lock stats steps
 step s2_set_deadlock_timeout { SET deadlock_timeout = '10ms'; }
-step s2_set_log_lock_waits { SET log_lock_waits = on; }
-step s2_unset_log_lock_waits { SET log_lock_waits = off; }
+step s2_set_track_lock_timing { SET track_lock_timing = on; }
+step s2_unset_track_lock_timing { SET track_lock_timing = off; }
 step s2_report_stat_lock_relation { SELECT waits > 0, timed_waits = waits, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'relation'; }
 step s2_report_stat_lock_transactionid { SELECT waits > 0, timed_waits = waits, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'transactionid'; }
 step s2_report_stat_lock_advisory { SELECT waits > 0, timed_waits = waits, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'advisory'; }
@@ -793,9 +793,9 @@ permutation
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_set_log_lock_waits
+  s2_set_track_lock_timing
   s1_begin
   s1_lock_relation
   s2_begin
@@ -811,9 +811,9 @@ permutation
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_set_log_lock_waits
+  s2_set_track_lock_timing
   s1_table_insert
   s1_begin
   s1_table_update_k1
@@ -830,9 +830,9 @@ permutation
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_set_log_lock_waits
+  s2_set_track_lock_timing
   s1_lock_advisory_lock
   s2_begin
   s2_ff
@@ -843,14 +843,14 @@ permutation
   s2_commit
   s2_report_stat_lock_advisory
 
-# Ensure log_lock_waits behaves correctly
+# Ensure track_lock_timing behaves correctly
 
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_unset_log_lock_waits
+  s2_unset_track_lock_timing
   s1_begin
   s1_lock_relation
   s2_begin
-- 
2.34.1


--gJ14Jcshhoq1cFBD--





^ permalink  raw  reply  [nested|flat] 5+ messages in thread

* [PATCH v8 3/3] Introduce a new track_lock_timing GUC
@ 2026-02-20 06:13  Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
  0 siblings, 0 replies; 5+ messages in thread

From: Bertrand Drouvot @ 2026-02-20 06:13 UTC (permalink / raw)

A new GUC (track_lock_timing) is added and defaults to on. If on, waits and
wait_time counters are incremented if the session waited longer than deadlock_timeout
to acquire the lock. It's on by default, as this is the same idea as 2aac62be8cb.
---
 doc/src/sgml/config.sgml                      |  19 +++
 doc/src/sgml/monitoring.sgml                  |   4 +-
 src/backend/storage/lmgr/proc.c               | 160 +++++++++---------
 src/backend/utils/misc/guc_parameters.dat     |   6 +
 src/backend/utils/misc/postgresql.conf.sample |   1 +
 src/include/pgstat.h                          |   1 +
 src/test/isolation/expected/stats.out         |  24 +--
 src/test/isolation/expected/stats_1.out       |  24 +--
 src/test/isolation/specs/stats.spec           |  24 +--
 9 files changed, 149 insertions(+), 114 deletions(-)
   7.6% doc/src/sgml/
  47.7% src/backend/storage/lmgr/
  36.3% src/test/isolation/expected/
   6.1% src/test/isolation/specs/

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index f670e2d4c31..1d3acb697da 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -8842,6 +8842,25 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-track-lock-timing" xreflabel="track_lock_timing">
+      <term><varname>track_lock_timing</varname> (<type>boolean</type>)
+      <indexterm>
+       <primary><varname>track_lock_timing</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+      <listitem>
+       <para>
+        Enables timing of lock waits. This parameter is on by default, as it tracks
+        only the timings for successful acquisitions that waited longer than
+        <xref linkend="guc-deadlock-timeout"/>. Lock timing information is
+        displayed in the <link linkend="monitoring-pg-stat-lock-view">
+        <structname>pg_stat_lock</structname></link> view.
+        Only superusers and users with the appropriate <literal>SET</literal>
+        privilege can change this setting.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry id="guc-track-wal-io-timing" xreflabel="track_wal_io_timing">
       <term><varname>track_wal_io_timing</varname> (<type>boolean</type>)
       <indexterm>
diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml
index 3a196bc305c..75c3e036860 100644
--- a/doc/src/sgml/monitoring.sgml
+++ b/doc/src/sgml/monitoring.sgml
@@ -3181,7 +3181,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage
        </para>
        <para>
         Number of times a lock of this type had to wait because of a
-        conflicting lock. Only incremented when <xref linkend="guc-log-lock-waits"/>
+        conflicting lock. Only incremented when <xref linkend="guc-track-lock-timing"/>
         is enabled and the lock was successfully acquired after waiting longer
         than <xref linkend="guc-deadlock-timeout"/>.
        </para>
@@ -3195,7 +3195,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage
        </para>
        <para>
         Total time spent waiting for locks of this type, in milliseconds.
-        Only incremented when <xref linkend="guc-log-lock-waits"/> is enabled and
+        Only incremented when <xref linkend="guc-track-lock-timing"/> is enabled and
         the lock was successfully acquired after waiting longer than
         <xref linkend="guc-deadlock-timeout"/>.
        </para>
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index e38c8820103..7681f87f078 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -62,6 +62,7 @@ int			IdleInTransactionSessionTimeout = 0;
 int			TransactionTimeout = 0;
 int			IdleSessionTimeout = 0;
 bool		log_lock_waits = true;
+bool		track_lock_timing = true;
 
 /* Pointer to this process's PGPROC struct, if any */
 PGPROC	   *MyProc = NULL;
@@ -1547,99 +1548,110 @@ ProcSleep(LOCALLOCK *locallock)
 
 		/*
 		 * If awoken after the deadlock check interrupt has run, and
-		 * log_lock_waits is on, then report about the wait.
+		 * log_lock_waits or track_lock_timing is on, then report or track
+		 * about the wait.
 		 */
-		if (log_lock_waits && deadlock_state != DS_NOT_YET_CHECKED)
+		if ((log_lock_waits || track_lock_timing) &&
+			deadlock_state != DS_NOT_YET_CHECKED)
 		{
-			StringInfoData buf,
-						lock_waiters_sbuf,
-						lock_holders_sbuf;
-			const char *modename;
 			long		secs;
 			int			usecs;
 			long		msecs;
-			int			lockHoldersNum = 0;
 
-			initStringInfo(&buf);
-			initStringInfo(&lock_waiters_sbuf);
-			initStringInfo(&lock_holders_sbuf);
-
-			DescribeLockTag(&buf, &locallock->tag.lock);
-			modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid,
-									   lockmode);
 			TimestampDifference(get_timeout_start_time(DEADLOCK_TIMEOUT),
 								GetCurrentTimestamp(),
 								&secs, &usecs);
 			msecs = secs * 1000 + usecs / 1000;
 			usecs = usecs % 1000;
 
-			/* Gather a list of all lock holders and waiters */
-			LWLockAcquire(partitionLock, LW_SHARED);
-			GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf,
-									 &lock_waiters_sbuf, &lockHoldersNum);
-			LWLockRelease(partitionLock);
-
-			if (deadlock_state == DS_SOFT_DEADLOCK)
-				ereport(LOG,
-						(errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs),
-						 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
-											   "Processes holding the lock: %s. Wait queue: %s.",
-											   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
-			else if (deadlock_state == DS_HARD_DEADLOCK)
-			{
-				/*
-				 * This message is a bit redundant with the error that will be
-				 * reported subsequently, but in some cases the error report
-				 * might not make it to the log (eg, if it's caught by an
-				 * exception handler), and we want to ensure all long-wait
-				 * events get logged.
-				 */
-				ereport(LOG,
-						(errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs),
-						 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
-											   "Processes holding the lock: %s. Wait queue: %s.",
-											   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
-			}
-
-			if (myWaitStatus == PROC_WAIT_STATUS_WAITING)
-				ereport(LOG,
-						(errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs),
-						 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
-											   "Processes holding the lock: %s. Wait queue: %s.",
-											   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
-			else if (myWaitStatus == PROC_WAIT_STATUS_OK)
-			{
-				/* Increment the lock statistics counters */
+			/* Increment the lock statistics counters */
+			if (track_lock_timing && myWaitStatus == PROC_WAIT_STATUS_OK)
 				pgstat_count_lock_waits(locallock->tag.lock.locktag_type,
 										msecs);
 
-				ereport(LOG,
-						(errmsg("process %d acquired %s on %s after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs)));
-			}
-			else
+			if (log_lock_waits)
 			{
-				Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR);
-
-				/*
-				 * Currently, the deadlock checker always kicks its own
-				 * process, which means that we'll only see
-				 * PROC_WAIT_STATUS_ERROR when deadlock_state ==
-				 * DS_HARD_DEADLOCK, and there's no need to print redundant
-				 * messages.  But for completeness and future-proofing, print
-				 * a message if it looks like someone else kicked us off the
-				 * lock.
-				 */
-				if (deadlock_state != DS_HARD_DEADLOCK)
+				StringInfoData buf,
+							lock_waiters_sbuf,
+							lock_holders_sbuf;
+				const char *modename;
+				int			lockHoldersNum = 0;
+
+				initStringInfo(&buf);
+				initStringInfo(&lock_waiters_sbuf);
+				initStringInfo(&lock_holders_sbuf);
+
+				DescribeLockTag(&buf, &locallock->tag.lock);
+				modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid,
+										   lockmode);
+
+				/* Gather a list of all lock holders and waiters */
+				LWLockAcquire(partitionLock, LW_SHARED);
+				GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf,
+										 &lock_waiters_sbuf, &lockHoldersNum);
+				LWLockRelease(partitionLock);
+
+				if (deadlock_state == DS_SOFT_DEADLOCK)
+					ereport(LOG,
+							(errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms",
+									MyProcPid, modename, buf.data, msecs, usecs),
+							 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
+												   "Processes holding the lock: %s. Wait queue: %s.",
+												   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+				else if (deadlock_state == DS_HARD_DEADLOCK)
+				{
+					/*
+					 * This message is a bit redundant with the error that
+					 * will be reported subsequently, but in some cases the
+					 * error report might not make it to the log (eg, if it's
+					 * caught by an exception handler), and we want to ensure
+					 * all long-wait events get logged.
+					 */
 					ereport(LOG,
-							(errmsg("process %d failed to acquire %s on %s after %ld.%03d ms",
+							(errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms",
 									MyProcPid, modename, buf.data, msecs, usecs),
 							 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
 												   "Processes holding the lock: %s. Wait queue: %s.",
 												   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+				}
+
+				if (myWaitStatus == PROC_WAIT_STATUS_WAITING)
+					ereport(LOG,
+							(errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
+									MyProcPid, modename, buf.data, msecs, usecs),
+							 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
+												   "Processes holding the lock: %s. Wait queue: %s.",
+												   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+
+				else if (myWaitStatus == PROC_WAIT_STATUS_OK)
+					ereport(LOG,
+							(errmsg("process %d acquired %s on %s after %ld.%03d ms",
+									MyProcPid, modename, buf.data, msecs, usecs)));
+				else
+				{
+					Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR);
+
+					/*
+					 * Currently, the deadlock checker always kicks its own
+					 * process, which means that we'll only see
+					 * PROC_WAIT_STATUS_ERROR when deadlock_state ==
+					 * DS_HARD_DEADLOCK, and there's no need to print
+					 * redundant messages.  But for completeness and
+					 * future-proofing, print a message if it looks like
+					 * someone else kicked us off the lock.
+					 */
+					if (deadlock_state != DS_HARD_DEADLOCK)
+						ereport(LOG,
+								(errmsg("process %d failed to acquire %s on %s after %ld.%03d ms",
+										MyProcPid, modename, buf.data, msecs, usecs),
+								 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
+													   "Processes holding the lock: %s. Wait queue: %s.",
+													   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+				}
+
+				pfree(buf.data);
+				pfree(lock_holders_sbuf.data);
+				pfree(lock_waiters_sbuf.data);
 			}
 
 			/*
@@ -1647,10 +1659,6 @@ ProcSleep(LOCALLOCK *locallock)
 			 * state so we don't print the above messages again.
 			 */
 			deadlock_state = DS_NO_DEADLOCK;
-
-			pfree(buf.data);
-			pfree(lock_holders_sbuf.data);
-			pfree(lock_waiters_sbuf.data);
 		}
 	} while (myWaitStatus == PROC_WAIT_STATUS_WAITING);
 
diff --git a/src/backend/utils/misc/guc_parameters.dat b/src/backend/utils/misc/guc_parameters.dat
index 9507778415d..c21e6c6ea4e 100644
--- a/src/backend/utils/misc/guc_parameters.dat
+++ b/src/backend/utils/misc/guc_parameters.dat
@@ -3110,6 +3110,12 @@
   boot_val => 'false',
 },
 
+{ name => 'track_lock_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE',
+  short_desc => 'Collects timing statistics for lock acquisition.',
+  variable => 'track_lock_timing',
+  boot_val => 'true',
+},
+
 { name => 'track_wal_io_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE',
   short_desc => 'Collects timing statistics for WAL I/O activity.',
   variable => 'track_wal_io_timing',
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index f938cc65a3a..8a3a704aaa5 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -685,6 +685,7 @@
 #track_counts = on
 #track_cost_delay_timing = off
 #track_io_timing = off
+#track_lock_timing = on
 #track_wal_io_timing = off
 #track_functions = none                 # none, pl, all
 #stats_fetch_consistency = cache        # cache, none, snapshot
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index 1c261e2c7a8..1ba7d98d06b 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -843,6 +843,7 @@ extern PgStat_WalStats *pgstat_fetch_stat_wal(void);
 extern PGDLLIMPORT bool pgstat_track_counts;
 extern PGDLLIMPORT int pgstat_track_functions;
 extern PGDLLIMPORT int pgstat_fetch_consistency;
+extern PGDLLIMPORT bool track_lock_timing;
 
 
 /*
diff --git a/src/test/isolation/expected/stats.out b/src/test/isolation/expected/stats.out
index 3cae3052e40..4f7ad061549 100644
--- a/src/test/isolation/expected/stats.out
+++ b/src/test/isolation/expected/stats.out
@@ -3752,7 +3752,7 @@ test_stat_func|                         1|t               |t
 
 step s1_commit: COMMIT;
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3765,9 +3765,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
@@ -3794,7 +3794,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3807,9 +3807,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1);
 step s1_begin: BEGIN;
 step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1';
@@ -3837,7 +3837,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3850,9 +3850,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_lock_advisory_lock: SELECT pg_advisory_lock(1);
 pg_advisory_lock
 ----------------
@@ -3899,7 +3899,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3912,9 +3912,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_unset_log_lock_waits: SET log_lock_waits = off;
+step s2_unset_track_lock_timing: SET track_lock_timing = off;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
diff --git a/src/test/isolation/expected/stats_1.out b/src/test/isolation/expected/stats_1.out
index ea4fd97a9a5..e1a60d41bad 100644
--- a/src/test/isolation/expected/stats_1.out
+++ b/src/test/isolation/expected/stats_1.out
@@ -3776,7 +3776,7 @@ test_stat_func|                         1|t               |t
 
 step s1_commit: COMMIT;
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3789,9 +3789,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
@@ -3818,7 +3818,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3831,9 +3831,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1);
 step s1_begin: BEGIN;
 step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1';
@@ -3861,7 +3861,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3874,9 +3874,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_lock_advisory_lock: SELECT pg_advisory_lock(1);
 pg_advisory_lock
 ----------------
@@ -3923,7 +3923,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3936,9 +3936,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_unset_log_lock_waits: SET log_lock_waits = off;
+step s2_unset_track_lock_timing: SET track_lock_timing = off;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
diff --git a/src/test/isolation/specs/stats.spec b/src/test/isolation/specs/stats.spec
index 42be68c545f..81b45a801d9 100644
--- a/src/test/isolation/specs/stats.spec
+++ b/src/test/isolation/specs/stats.spec
@@ -132,7 +132,7 @@ step s1_slru_check_stats {
 
 # Lock stats steps
 step s1_set_deadlock_timeout { SET deadlock_timeout = '10ms'; }
-step s1_set_log_lock_waits { SET log_lock_waits = on; }
+step s1_set_track_lock_timing { SET track_lock_timing = on; }
 step s1_reset_stat_lock { SELECT pg_stat_reset_shared('lock'); }
 step s1_sleep { SELECT pg_sleep(0.5); }
 step s1_lock_relation { LOCK TABLE test_stat_tab; }
@@ -174,8 +174,8 @@ step s2_big_notify { SELECT pg_notify('stats_test_use',
 
 # Lock stats steps
 step s2_set_deadlock_timeout { SET deadlock_timeout = '10ms'; }
-step s2_set_log_lock_waits { SET log_lock_waits = on; }
-step s2_unset_log_lock_waits { SET log_lock_waits = off; }
+step s2_set_track_lock_timing { SET track_lock_timing = on; }
+step s2_unset_track_lock_timing { SET track_lock_timing = off; }
 step s2_report_stat_lock_relation { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'relation'; }
 step s2_report_stat_lock_transactionid { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'transactionid'; }
 step s2_report_stat_lock_advisory { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'advisory'; }
@@ -793,9 +793,9 @@ permutation
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_set_log_lock_waits
+  s2_set_track_lock_timing
   s1_begin
   s1_lock_relation
   s2_begin
@@ -811,9 +811,9 @@ permutation
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_set_log_lock_waits
+  s2_set_track_lock_timing
   s1_table_insert
   s1_begin
   s1_table_update_k1
@@ -830,9 +830,9 @@ permutation
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_set_log_lock_waits
+  s2_set_track_lock_timing
   s1_lock_advisory_lock
   s2_begin
   s2_ff
@@ -843,14 +843,14 @@ permutation
   s2_commit
   s2_report_stat_lock_advisory
 
-# Ensure log_lock_waits behaves correctly
+# Ensure track_lock_timing behaves correctly
 
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_unset_log_lock_waits
+  s2_unset_track_lock_timing
   s1_begin
   s1_lock_relation
   s2_begin
-- 
2.34.1


--CwwtKyeZcJiDzEBE--





^ permalink  raw  reply  [nested|flat] 5+ messages in thread

* [PATCH v8 3/3] Introduce a new track_lock_timing GUC
@ 2026-02-20 06:13  Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
  0 siblings, 0 replies; 5+ messages in thread

From: Bertrand Drouvot @ 2026-02-20 06:13 UTC (permalink / raw)

A new GUC (track_lock_timing) is added and defaults to on. If on, waits and
wait_time counters are incremented if the session waited longer than deadlock_timeout
to acquire the lock. It's on by default, as this is the same idea as 2aac62be8cb.
---
 doc/src/sgml/config.sgml                      |  19 +++
 doc/src/sgml/monitoring.sgml                  |   4 +-
 src/backend/storage/lmgr/proc.c               | 160 +++++++++---------
 src/backend/utils/misc/guc_parameters.dat     |   6 +
 src/backend/utils/misc/postgresql.conf.sample |   1 +
 src/include/pgstat.h                          |   1 +
 src/test/isolation/expected/stats.out         |  24 +--
 src/test/isolation/expected/stats_1.out       |  24 +--
 src/test/isolation/specs/stats.spec           |  24 +--
 9 files changed, 149 insertions(+), 114 deletions(-)
   7.6% doc/src/sgml/
  47.7% src/backend/storage/lmgr/
  36.3% src/test/isolation/expected/
   6.1% src/test/isolation/specs/

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index f670e2d4c31..1d3acb697da 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -8842,6 +8842,25 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-track-lock-timing" xreflabel="track_lock_timing">
+      <term><varname>track_lock_timing</varname> (<type>boolean</type>)
+      <indexterm>
+       <primary><varname>track_lock_timing</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+      <listitem>
+       <para>
+        Enables timing of lock waits. This parameter is on by default, as it tracks
+        only the timings for successful acquisitions that waited longer than
+        <xref linkend="guc-deadlock-timeout"/>. Lock timing information is
+        displayed in the <link linkend="monitoring-pg-stat-lock-view">
+        <structname>pg_stat_lock</structname></link> view.
+        Only superusers and users with the appropriate <literal>SET</literal>
+        privilege can change this setting.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry id="guc-track-wal-io-timing" xreflabel="track_wal_io_timing">
       <term><varname>track_wal_io_timing</varname> (<type>boolean</type>)
       <indexterm>
diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml
index 3a196bc305c..75c3e036860 100644
--- a/doc/src/sgml/monitoring.sgml
+++ b/doc/src/sgml/monitoring.sgml
@@ -3181,7 +3181,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage
        </para>
        <para>
         Number of times a lock of this type had to wait because of a
-        conflicting lock. Only incremented when <xref linkend="guc-log-lock-waits"/>
+        conflicting lock. Only incremented when <xref linkend="guc-track-lock-timing"/>
         is enabled and the lock was successfully acquired after waiting longer
         than <xref linkend="guc-deadlock-timeout"/>.
        </para>
@@ -3195,7 +3195,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage
        </para>
        <para>
         Total time spent waiting for locks of this type, in milliseconds.
-        Only incremented when <xref linkend="guc-log-lock-waits"/> is enabled and
+        Only incremented when <xref linkend="guc-track-lock-timing"/> is enabled and
         the lock was successfully acquired after waiting longer than
         <xref linkend="guc-deadlock-timeout"/>.
        </para>
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index e38c8820103..7681f87f078 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -62,6 +62,7 @@ int			IdleInTransactionSessionTimeout = 0;
 int			TransactionTimeout = 0;
 int			IdleSessionTimeout = 0;
 bool		log_lock_waits = true;
+bool		track_lock_timing = true;
 
 /* Pointer to this process's PGPROC struct, if any */
 PGPROC	   *MyProc = NULL;
@@ -1547,99 +1548,110 @@ ProcSleep(LOCALLOCK *locallock)
 
 		/*
 		 * If awoken after the deadlock check interrupt has run, and
-		 * log_lock_waits is on, then report about the wait.
+		 * log_lock_waits or track_lock_timing is on, then report or track
+		 * about the wait.
 		 */
-		if (log_lock_waits && deadlock_state != DS_NOT_YET_CHECKED)
+		if ((log_lock_waits || track_lock_timing) &&
+			deadlock_state != DS_NOT_YET_CHECKED)
 		{
-			StringInfoData buf,
-						lock_waiters_sbuf,
-						lock_holders_sbuf;
-			const char *modename;
 			long		secs;
 			int			usecs;
 			long		msecs;
-			int			lockHoldersNum = 0;
 
-			initStringInfo(&buf);
-			initStringInfo(&lock_waiters_sbuf);
-			initStringInfo(&lock_holders_sbuf);
-
-			DescribeLockTag(&buf, &locallock->tag.lock);
-			modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid,
-									   lockmode);
 			TimestampDifference(get_timeout_start_time(DEADLOCK_TIMEOUT),
 								GetCurrentTimestamp(),
 								&secs, &usecs);
 			msecs = secs * 1000 + usecs / 1000;
 			usecs = usecs % 1000;
 
-			/* Gather a list of all lock holders and waiters */
-			LWLockAcquire(partitionLock, LW_SHARED);
-			GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf,
-									 &lock_waiters_sbuf, &lockHoldersNum);
-			LWLockRelease(partitionLock);
-
-			if (deadlock_state == DS_SOFT_DEADLOCK)
-				ereport(LOG,
-						(errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs),
-						 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
-											   "Processes holding the lock: %s. Wait queue: %s.",
-											   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
-			else if (deadlock_state == DS_HARD_DEADLOCK)
-			{
-				/*
-				 * This message is a bit redundant with the error that will be
-				 * reported subsequently, but in some cases the error report
-				 * might not make it to the log (eg, if it's caught by an
-				 * exception handler), and we want to ensure all long-wait
-				 * events get logged.
-				 */
-				ereport(LOG,
-						(errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs),
-						 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
-											   "Processes holding the lock: %s. Wait queue: %s.",
-											   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
-			}
-
-			if (myWaitStatus == PROC_WAIT_STATUS_WAITING)
-				ereport(LOG,
-						(errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs),
-						 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
-											   "Processes holding the lock: %s. Wait queue: %s.",
-											   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
-			else if (myWaitStatus == PROC_WAIT_STATUS_OK)
-			{
-				/* Increment the lock statistics counters */
+			/* Increment the lock statistics counters */
+			if (track_lock_timing && myWaitStatus == PROC_WAIT_STATUS_OK)
 				pgstat_count_lock_waits(locallock->tag.lock.locktag_type,
 										msecs);
 
-				ereport(LOG,
-						(errmsg("process %d acquired %s on %s after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs)));
-			}
-			else
+			if (log_lock_waits)
 			{
-				Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR);
-
-				/*
-				 * Currently, the deadlock checker always kicks its own
-				 * process, which means that we'll only see
-				 * PROC_WAIT_STATUS_ERROR when deadlock_state ==
-				 * DS_HARD_DEADLOCK, and there's no need to print redundant
-				 * messages.  But for completeness and future-proofing, print
-				 * a message if it looks like someone else kicked us off the
-				 * lock.
-				 */
-				if (deadlock_state != DS_HARD_DEADLOCK)
+				StringInfoData buf,
+							lock_waiters_sbuf,
+							lock_holders_sbuf;
+				const char *modename;
+				int			lockHoldersNum = 0;
+
+				initStringInfo(&buf);
+				initStringInfo(&lock_waiters_sbuf);
+				initStringInfo(&lock_holders_sbuf);
+
+				DescribeLockTag(&buf, &locallock->tag.lock);
+				modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid,
+										   lockmode);
+
+				/* Gather a list of all lock holders and waiters */
+				LWLockAcquire(partitionLock, LW_SHARED);
+				GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf,
+										 &lock_waiters_sbuf, &lockHoldersNum);
+				LWLockRelease(partitionLock);
+
+				if (deadlock_state == DS_SOFT_DEADLOCK)
+					ereport(LOG,
+							(errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms",
+									MyProcPid, modename, buf.data, msecs, usecs),
+							 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
+												   "Processes holding the lock: %s. Wait queue: %s.",
+												   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+				else if (deadlock_state == DS_HARD_DEADLOCK)
+				{
+					/*
+					 * This message is a bit redundant with the error that
+					 * will be reported subsequently, but in some cases the
+					 * error report might not make it to the log (eg, if it's
+					 * caught by an exception handler), and we want to ensure
+					 * all long-wait events get logged.
+					 */
 					ereport(LOG,
-							(errmsg("process %d failed to acquire %s on %s after %ld.%03d ms",
+							(errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms",
 									MyProcPid, modename, buf.data, msecs, usecs),
 							 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
 												   "Processes holding the lock: %s. Wait queue: %s.",
 												   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+				}
+
+				if (myWaitStatus == PROC_WAIT_STATUS_WAITING)
+					ereport(LOG,
+							(errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
+									MyProcPid, modename, buf.data, msecs, usecs),
+							 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
+												   "Processes holding the lock: %s. Wait queue: %s.",
+												   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+
+				else if (myWaitStatus == PROC_WAIT_STATUS_OK)
+					ereport(LOG,
+							(errmsg("process %d acquired %s on %s after %ld.%03d ms",
+									MyProcPid, modename, buf.data, msecs, usecs)));
+				else
+				{
+					Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR);
+
+					/*
+					 * Currently, the deadlock checker always kicks its own
+					 * process, which means that we'll only see
+					 * PROC_WAIT_STATUS_ERROR when deadlock_state ==
+					 * DS_HARD_DEADLOCK, and there's no need to print
+					 * redundant messages.  But for completeness and
+					 * future-proofing, print a message if it looks like
+					 * someone else kicked us off the lock.
+					 */
+					if (deadlock_state != DS_HARD_DEADLOCK)
+						ereport(LOG,
+								(errmsg("process %d failed to acquire %s on %s after %ld.%03d ms",
+										MyProcPid, modename, buf.data, msecs, usecs),
+								 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
+													   "Processes holding the lock: %s. Wait queue: %s.",
+													   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+				}
+
+				pfree(buf.data);
+				pfree(lock_holders_sbuf.data);
+				pfree(lock_waiters_sbuf.data);
 			}
 
 			/*
@@ -1647,10 +1659,6 @@ ProcSleep(LOCALLOCK *locallock)
 			 * state so we don't print the above messages again.
 			 */
 			deadlock_state = DS_NO_DEADLOCK;
-
-			pfree(buf.data);
-			pfree(lock_holders_sbuf.data);
-			pfree(lock_waiters_sbuf.data);
 		}
 	} while (myWaitStatus == PROC_WAIT_STATUS_WAITING);
 
diff --git a/src/backend/utils/misc/guc_parameters.dat b/src/backend/utils/misc/guc_parameters.dat
index 9507778415d..c21e6c6ea4e 100644
--- a/src/backend/utils/misc/guc_parameters.dat
+++ b/src/backend/utils/misc/guc_parameters.dat
@@ -3110,6 +3110,12 @@
   boot_val => 'false',
 },
 
+{ name => 'track_lock_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE',
+  short_desc => 'Collects timing statistics for lock acquisition.',
+  variable => 'track_lock_timing',
+  boot_val => 'true',
+},
+
 { name => 'track_wal_io_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE',
   short_desc => 'Collects timing statistics for WAL I/O activity.',
   variable => 'track_wal_io_timing',
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index f938cc65a3a..8a3a704aaa5 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -685,6 +685,7 @@
 #track_counts = on
 #track_cost_delay_timing = off
 #track_io_timing = off
+#track_lock_timing = on
 #track_wal_io_timing = off
 #track_functions = none                 # none, pl, all
 #stats_fetch_consistency = cache        # cache, none, snapshot
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index 1c261e2c7a8..1ba7d98d06b 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -843,6 +843,7 @@ extern PgStat_WalStats *pgstat_fetch_stat_wal(void);
 extern PGDLLIMPORT bool pgstat_track_counts;
 extern PGDLLIMPORT int pgstat_track_functions;
 extern PGDLLIMPORT int pgstat_fetch_consistency;
+extern PGDLLIMPORT bool track_lock_timing;
 
 
 /*
diff --git a/src/test/isolation/expected/stats.out b/src/test/isolation/expected/stats.out
index 3cae3052e40..4f7ad061549 100644
--- a/src/test/isolation/expected/stats.out
+++ b/src/test/isolation/expected/stats.out
@@ -3752,7 +3752,7 @@ test_stat_func|                         1|t               |t
 
 step s1_commit: COMMIT;
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3765,9 +3765,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
@@ -3794,7 +3794,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3807,9 +3807,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1);
 step s1_begin: BEGIN;
 step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1';
@@ -3837,7 +3837,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3850,9 +3850,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_lock_advisory_lock: SELECT pg_advisory_lock(1);
 pg_advisory_lock
 ----------------
@@ -3899,7 +3899,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3912,9 +3912,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_unset_log_lock_waits: SET log_lock_waits = off;
+step s2_unset_track_lock_timing: SET track_lock_timing = off;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
diff --git a/src/test/isolation/expected/stats_1.out b/src/test/isolation/expected/stats_1.out
index ea4fd97a9a5..e1a60d41bad 100644
--- a/src/test/isolation/expected/stats_1.out
+++ b/src/test/isolation/expected/stats_1.out
@@ -3776,7 +3776,7 @@ test_stat_func|                         1|t               |t
 
 step s1_commit: COMMIT;
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3789,9 +3789,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
@@ -3818,7 +3818,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3831,9 +3831,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1);
 step s1_begin: BEGIN;
 step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1';
@@ -3861,7 +3861,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3874,9 +3874,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_lock_advisory_lock: SELECT pg_advisory_lock(1);
 pg_advisory_lock
 ----------------
@@ -3923,7 +3923,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3936,9 +3936,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_unset_log_lock_waits: SET log_lock_waits = off;
+step s2_unset_track_lock_timing: SET track_lock_timing = off;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
diff --git a/src/test/isolation/specs/stats.spec b/src/test/isolation/specs/stats.spec
index 42be68c545f..81b45a801d9 100644
--- a/src/test/isolation/specs/stats.spec
+++ b/src/test/isolation/specs/stats.spec
@@ -132,7 +132,7 @@ step s1_slru_check_stats {
 
 # Lock stats steps
 step s1_set_deadlock_timeout { SET deadlock_timeout = '10ms'; }
-step s1_set_log_lock_waits { SET log_lock_waits = on; }
+step s1_set_track_lock_timing { SET track_lock_timing = on; }
 step s1_reset_stat_lock { SELECT pg_stat_reset_shared('lock'); }
 step s1_sleep { SELECT pg_sleep(0.5); }
 step s1_lock_relation { LOCK TABLE test_stat_tab; }
@@ -174,8 +174,8 @@ step s2_big_notify { SELECT pg_notify('stats_test_use',
 
 # Lock stats steps
 step s2_set_deadlock_timeout { SET deadlock_timeout = '10ms'; }
-step s2_set_log_lock_waits { SET log_lock_waits = on; }
-step s2_unset_log_lock_waits { SET log_lock_waits = off; }
+step s2_set_track_lock_timing { SET track_lock_timing = on; }
+step s2_unset_track_lock_timing { SET track_lock_timing = off; }
 step s2_report_stat_lock_relation { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'relation'; }
 step s2_report_stat_lock_transactionid { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'transactionid'; }
 step s2_report_stat_lock_advisory { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'advisory'; }
@@ -793,9 +793,9 @@ permutation
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_set_log_lock_waits
+  s2_set_track_lock_timing
   s1_begin
   s1_lock_relation
   s2_begin
@@ -811,9 +811,9 @@ permutation
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_set_log_lock_waits
+  s2_set_track_lock_timing
   s1_table_insert
   s1_begin
   s1_table_update_k1
@@ -830,9 +830,9 @@ permutation
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_set_log_lock_waits
+  s2_set_track_lock_timing
   s1_lock_advisory_lock
   s2_begin
   s2_ff
@@ -843,14 +843,14 @@ permutation
   s2_commit
   s2_report_stat_lock_advisory
 
-# Ensure log_lock_waits behaves correctly
+# Ensure track_lock_timing behaves correctly
 
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_unset_log_lock_waits
+  s2_unset_track_lock_timing
   s1_begin
   s1_lock_relation
   s2_begin
-- 
2.34.1


--CwwtKyeZcJiDzEBE--





^ permalink  raw  reply  [nested|flat] 5+ messages in thread

* [PATCH v9 3/3] Introduce a new track_lock_timing GUC
@ 2026-02-20 06:13  Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
  0 siblings, 0 replies; 5+ messages in thread

From: Bertrand Drouvot @ 2026-02-20 06:13 UTC (permalink / raw)

A new GUC (track_lock_timing) is added and defaults to on. If on, waits and
wait_time counters are incremented if the session waited longer than deadlock_timeout
to acquire the lock. It's on by default, as this is the same idea as 2aac62be8cb.
---
 doc/src/sgml/config.sgml                      |  19 ++
 doc/src/sgml/monitoring.sgml                  |   4 +-
 src/backend/storage/lmgr/proc.c               | 185 +++++++++---------
 src/backend/utils/misc/guc_parameters.dat     |   6 +
 src/backend/utils/misc/postgresql.conf.sample |   1 +
 src/include/pgstat.h                          |   1 +
 src/test/isolation/expected/stats.out         |  24 +--
 src/test/isolation/expected/stats_1.out       |  24 +--
 src/test/isolation/specs/stats.spec           |  24 +--
 9 files changed, 161 insertions(+), 127 deletions(-)
   7.3% doc/src/sgml/
  50.0% src/backend/storage/lmgr/
  34.7% src/test/isolation/expected/
   5.8% src/test/isolation/specs/

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 8cdd826fbd3..69938ba3cdc 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -8857,6 +8857,25 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-track-lock-timing" xreflabel="track_lock_timing">
+      <term><varname>track_lock_timing</varname> (<type>boolean</type>)
+      <indexterm>
+       <primary><varname>track_lock_timing</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+      <listitem>
+       <para>
+        Enables timing of lock waits. This parameter is on by default, as it tracks
+        only the timings for successful acquisitions that waited longer than
+        <xref linkend="guc-deadlock-timeout"/>. Lock timing information is
+        displayed in the <link linkend="monitoring-pg-stat-lock-view">
+        <structname>pg_stat_lock</structname></link> view.
+        Only superusers and users with the appropriate <literal>SET</literal>
+        privilege can change this setting.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry id="guc-track-wal-io-timing" xreflabel="track_wal_io_timing">
       <term><varname>track_wal_io_timing</varname> (<type>boolean</type>)
       <indexterm>
diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml
index 221ee28cc7b..6ae9cc7635d 100644
--- a/doc/src/sgml/monitoring.sgml
+++ b/doc/src/sgml/monitoring.sgml
@@ -3340,7 +3340,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage
        </para>
        <para>
         Number of times a lock of this type had to wait because of a
-        conflicting lock. Only incremented when <xref linkend="guc-log-lock-waits"/>
+        conflicting lock. Only incremented when <xref linkend="guc-track-lock-timing"/>
         is enabled and the lock was successfully acquired after waiting longer
         than <xref linkend="guc-deadlock-timeout"/>.
        </para>
@@ -3354,7 +3354,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage
        </para>
        <para>
         Total time spent waiting for locks of this type, in milliseconds.
-        Only incremented when <xref linkend="guc-log-lock-waits"/> is enabled and
+        Only incremented when <xref linkend="guc-track-lock-timing"/> is enabled and
         the lock was successfully acquired after waiting longer than
         <xref linkend="guc-deadlock-timeout"/>.
        </para>
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index 263dc88b735..e9b7b5fd4c9 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -63,6 +63,7 @@ int			IdleInTransactionSessionTimeout = 0;
 int			TransactionTimeout = 0;
 int			IdleSessionTimeout = 0;
 bool		log_lock_waits = true;
+bool		track_lock_timing = true;
 
 /* Pointer to this process's PGPROC struct, if any */
 PGPROC	   *MyProc = NULL;
@@ -1550,115 +1551,125 @@ ProcSleep(LOCALLOCK *locallock)
 
 		/*
 		 * If awoken after the deadlock check interrupt has run, and
-		 * log_lock_waits is on, then report about the wait.
+		 * log_lock_waits or track_lock_timing is on, then report or track
+		 * about the wait.
 		 */
-		if (log_lock_waits && deadlock_state != DS_NOT_YET_CHECKED)
+		if ((log_lock_waits || track_lock_timing) &&
+			deadlock_state != DS_NOT_YET_CHECKED)
 		{
-			StringInfoData buf,
-						lock_waiters_sbuf,
-						lock_holders_sbuf;
-			const char *modename;
 			long		secs;
 			int			usecs;
 			long		msecs;
-			int			lockHoldersNum = 0;
 
-			initStringInfo(&buf);
-			initStringInfo(&lock_waiters_sbuf);
-			initStringInfo(&lock_holders_sbuf);
-
-			DescribeLockTag(&buf, &locallock->tag.lock);
-			modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid,
-									   lockmode);
 			TimestampDifference(get_timeout_start_time(DEADLOCK_TIMEOUT),
 								GetCurrentTimestamp(),
 								&secs, &usecs);
 			msecs = secs * 1000 + usecs / 1000;
 			usecs = usecs % 1000;
 
-			/* Gather a list of all lock holders and waiters */
-			LWLockAcquire(partitionLock, LW_SHARED);
-			GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf,
-									 &lock_waiters_sbuf, &lockHoldersNum);
-			LWLockRelease(partitionLock);
-
-			if (deadlock_state == DS_SOFT_DEADLOCK)
-				ereport(LOG,
-						(errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs),
-						 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
-											   "Processes holding the lock: %s. Wait queue: %s.",
-											   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
-			else if (deadlock_state == DS_HARD_DEADLOCK)
-			{
-				/*
-				 * This message is a bit redundant with the error that will be
-				 * reported subsequently, but in some cases the error report
-				 * might not make it to the log (eg, if it's caught by an
-				 * exception handler), and we want to ensure all long-wait
-				 * events get logged.
-				 */
-				ereport(LOG,
-						(errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs),
-						 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
-											   "Processes holding the lock: %s. Wait queue: %s.",
-											   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
-			}
+			/* Increment the lock statistics counters */
+			if (track_lock_timing && myWaitStatus == PROC_WAIT_STATUS_OK)
+				pgstat_count_lock_waits(locallock->tag.lock.locktag_type, msecs);
 
-			if (myWaitStatus == PROC_WAIT_STATUS_WAITING)
+			if (log_lock_waits)
 			{
-				/*
-				 * Guard the "still waiting on lock" log message so it is
-				 * reported at most once while waiting for the lock.
-				 *
-				 * Without this guard, the message can be emitted whenever the
-				 * lock-wait sleep is interrupted (for example by SIGHUP for
-				 * config reload or by client_connection_check_interval). For
-				 * example, if client_connection_check_interval is set very
-				 * low (e.g., 100 ms), the message could be logged repeatedly,
-				 * flooding the log and making it difficult to use.
-				 */
-				if (!logged_lock_wait)
-				{
+				StringInfoData buf,
+							lock_waiters_sbuf,
+							lock_holders_sbuf;
+				const char *modename;
+				int			lockHoldersNum = 0;
+
+				initStringInfo(&buf);
+				initStringInfo(&lock_waiters_sbuf);
+				initStringInfo(&lock_holders_sbuf);
+
+				DescribeLockTag(&buf, &locallock->tag.lock);
+				modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid,
+										   lockmode);
+
+				/* Gather a list of all lock holders and waiters */
+				LWLockAcquire(partitionLock, LW_SHARED);
+				GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf,
+										 &lock_waiters_sbuf, &lockHoldersNum);
+				LWLockRelease(partitionLock);
+
+				if (deadlock_state == DS_SOFT_DEADLOCK)
 					ereport(LOG,
-							(errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
+							(errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms",
 									MyProcPid, modename, buf.data, msecs, usecs),
 							 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
 												   "Processes holding the lock: %s. Wait queue: %s.",
 												   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
-					logged_lock_wait = true;
-				}
-			}
-			else if (myWaitStatus == PROC_WAIT_STATUS_OK)
-			{
-				/* Increment the lock statistics counters */
-				pgstat_count_lock_waits(locallock->tag.lock.locktag_type, msecs);
-
-				ereport(LOG,
-						(errmsg("process %d acquired %s on %s after %ld.%03d ms",
-								MyProcPid, modename, buf.data, msecs, usecs)));
-			}
-			else
-			{
-				Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR);
-
-				/*
-				 * Currently, the deadlock checker always kicks its own
-				 * process, which means that we'll only see
-				 * PROC_WAIT_STATUS_ERROR when deadlock_state ==
-				 * DS_HARD_DEADLOCK, and there's no need to print redundant
-				 * messages.  But for completeness and future-proofing, print
-				 * a message if it looks like someone else kicked us off the
-				 * lock.
-				 */
-				if (deadlock_state != DS_HARD_DEADLOCK)
+				else if (deadlock_state == DS_HARD_DEADLOCK)
+				{
+					/*
+					 * This message is a bit redundant with the error that
+					 * will be reported subsequently, but in some cases the
+					 * error report might not make it to the log (eg, if it's
+					 * caught by an exception handler), and we want to ensure
+					 * all long-wait events get logged.
+					 */
 					ereport(LOG,
-							(errmsg("process %d failed to acquire %s on %s after %ld.%03d ms",
+							(errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms",
 									MyProcPid, modename, buf.data, msecs, usecs),
 							 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
 												   "Processes holding the lock: %s. Wait queue: %s.",
 												   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+				}
+				if (myWaitStatus == PROC_WAIT_STATUS_WAITING)
+				{
+					/*
+					 * Guard the "still waiting on lock" log message so it is
+					 * reported at most once while waiting for the lock.
+					 *
+					 * Without this guard, the message can be emitted whenever
+					 * the lock-wait sleep is interrupted (for example by
+					 * SIGHUP for config reload or by
+					 * client_connection_check_interval). For example, if
+					 * client_connection_check_interval is set very low (e.g.,
+					 * 100 ms), the message could be logged repeatedly,
+					 * flooding the log and making it difficult to use.
+					 */
+					if (!logged_lock_wait)
+					{
+						ereport(LOG,
+								(errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
+										MyProcPid, modename, buf.data, msecs, usecs),
+								 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
+													   "Processes holding the lock: %s. Wait queue: %s.",
+													   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+						logged_lock_wait = true;
+					}
+				}
+				else if (myWaitStatus == PROC_WAIT_STATUS_OK)
+					ereport(LOG,
+							(errmsg("process %d acquired %s on %s after %ld.%03d ms",
+									MyProcPid, modename, buf.data, msecs, usecs)));
+				else
+				{
+					Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR);
+
+					/*
+					 * Currently, the deadlock checker always kicks its own
+					 * process, which means that we'll only see
+					 * PROC_WAIT_STATUS_ERROR when deadlock_state ==
+					 * DS_HARD_DEADLOCK, and there's no need to print
+					 * redundant messages.  But for completeness and
+					 * future-proofing, print a message if it looks like
+					 * someone else kicked us off the lock.
+					 */
+					if (deadlock_state != DS_HARD_DEADLOCK)
+						ereport(LOG,
+								(errmsg("process %d failed to acquire %s on %s after %ld.%03d ms",
+										MyProcPid, modename, buf.data, msecs, usecs),
+								 (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.",
+													   "Processes holding the lock: %s. Wait queue: %s.",
+													   lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data))));
+				}
+
+				pfree(buf.data);
+				pfree(lock_holders_sbuf.data);
+				pfree(lock_waiters_sbuf.data);
 			}
 
 			/*
@@ -1666,10 +1677,6 @@ ProcSleep(LOCALLOCK *locallock)
 			 * state so we don't print the above messages again.
 			 */
 			deadlock_state = DS_NO_DEADLOCK;
-
-			pfree(buf.data);
-			pfree(lock_holders_sbuf.data);
-			pfree(lock_waiters_sbuf.data);
 		}
 	} while (myWaitStatus == PROC_WAIT_STATUS_WAITING);
 
diff --git a/src/backend/utils/misc/guc_parameters.dat b/src/backend/utils/misc/guc_parameters.dat
index a5a0edf2534..7055dc88e0d 100644
--- a/src/backend/utils/misc/guc_parameters.dat
+++ b/src/backend/utils/misc/guc_parameters.dat
@@ -3110,6 +3110,12 @@
   boot_val => 'false',
 },
 
+{ name => 'track_lock_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE',
+  short_desc => 'Collects timing statistics for lock acquisition.',
+  variable => 'track_lock_timing',
+  boot_val => 'true',
+},
+
 { name => 'track_wal_io_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE',
   short_desc => 'Collects timing statistics for WAL I/O activity.',
   variable => 'track_wal_io_timing',
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index e686d88afc4..5d057608fe1 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -685,6 +685,7 @@
 #track_counts = on
 #track_cost_delay_timing = off
 #track_io_timing = off
+#track_lock_timing = on
 #track_wal_io_timing = off
 #track_functions = none                 # none, pl, all
 #stats_fetch_consistency = cache        # cache, none, snapshot
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index 06e2638e788..95006dc139c 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -842,6 +842,7 @@ extern PgStat_WalStats *pgstat_fetch_stat_wal(void);
 extern PGDLLIMPORT bool pgstat_track_counts;
 extern PGDLLIMPORT int pgstat_track_functions;
 extern PGDLLIMPORT int pgstat_fetch_consistency;
+extern PGDLLIMPORT bool track_lock_timing;
 
 
 /*
diff --git a/src/test/isolation/expected/stats.out b/src/test/isolation/expected/stats.out
index 3cae3052e40..4f7ad061549 100644
--- a/src/test/isolation/expected/stats.out
+++ b/src/test/isolation/expected/stats.out
@@ -3752,7 +3752,7 @@ test_stat_func|                         1|t               |t
 
 step s1_commit: COMMIT;
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3765,9 +3765,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
@@ -3794,7 +3794,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3807,9 +3807,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1);
 step s1_begin: BEGIN;
 step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1';
@@ -3837,7 +3837,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3850,9 +3850,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_lock_advisory_lock: SELECT pg_advisory_lock(1);
 pg_advisory_lock
 ----------------
@@ -3899,7 +3899,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3912,9 +3912,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_unset_log_lock_waits: SET log_lock_waits = off;
+step s2_unset_track_lock_timing: SET track_lock_timing = off;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
diff --git a/src/test/isolation/expected/stats_1.out b/src/test/isolation/expected/stats_1.out
index ea4fd97a9a5..e1a60d41bad 100644
--- a/src/test/isolation/expected/stats_1.out
+++ b/src/test/isolation/expected/stats_1.out
@@ -3776,7 +3776,7 @@ test_stat_func|                         1|t               |t
 
 step s1_commit: COMMIT;
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3789,9 +3789,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
@@ -3818,7 +3818,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3831,9 +3831,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1);
 step s1_begin: BEGIN;
 step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1';
@@ -3861,7 +3861,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3874,9 +3874,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_set_log_lock_waits: SET log_lock_waits = on;
+step s2_set_track_lock_timing: SET track_lock_timing = on;
 step s1_lock_advisory_lock: SELECT pg_advisory_lock(1);
 pg_advisory_lock
 ----------------
@@ -3923,7 +3923,7 @@ t       |t
 (1 row)
 
 
-starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
+starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation
 pg_stat_force_next_flush
 ------------------------
                         
@@ -3936,9 +3936,9 @@ pg_stat_reset_shared
                     
 (1 row)
 
-step s1_set_log_lock_waits: SET log_lock_waits = on;
+step s1_set_track_lock_timing: SET track_lock_timing = on;
 step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms';
-step s2_unset_log_lock_waits: SET log_lock_waits = off;
+step s2_unset_track_lock_timing: SET track_lock_timing = off;
 step s1_begin: BEGIN;
 step s1_lock_relation: LOCK TABLE test_stat_tab;
 step s2_begin: BEGIN;
diff --git a/src/test/isolation/specs/stats.spec b/src/test/isolation/specs/stats.spec
index 42be68c545f..81b45a801d9 100644
--- a/src/test/isolation/specs/stats.spec
+++ b/src/test/isolation/specs/stats.spec
@@ -132,7 +132,7 @@ step s1_slru_check_stats {
 
 # Lock stats steps
 step s1_set_deadlock_timeout { SET deadlock_timeout = '10ms'; }
-step s1_set_log_lock_waits { SET log_lock_waits = on; }
+step s1_set_track_lock_timing { SET track_lock_timing = on; }
 step s1_reset_stat_lock { SELECT pg_stat_reset_shared('lock'); }
 step s1_sleep { SELECT pg_sleep(0.5); }
 step s1_lock_relation { LOCK TABLE test_stat_tab; }
@@ -174,8 +174,8 @@ step s2_big_notify { SELECT pg_notify('stats_test_use',
 
 # Lock stats steps
 step s2_set_deadlock_timeout { SET deadlock_timeout = '10ms'; }
-step s2_set_log_lock_waits { SET log_lock_waits = on; }
-step s2_unset_log_lock_waits { SET log_lock_waits = off; }
+step s2_set_track_lock_timing { SET track_lock_timing = on; }
+step s2_unset_track_lock_timing { SET track_lock_timing = off; }
 step s2_report_stat_lock_relation { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'relation'; }
 step s2_report_stat_lock_transactionid { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'transactionid'; }
 step s2_report_stat_lock_advisory { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'advisory'; }
@@ -793,9 +793,9 @@ permutation
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_set_log_lock_waits
+  s2_set_track_lock_timing
   s1_begin
   s1_lock_relation
   s2_begin
@@ -811,9 +811,9 @@ permutation
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_set_log_lock_waits
+  s2_set_track_lock_timing
   s1_table_insert
   s1_begin
   s1_table_update_k1
@@ -830,9 +830,9 @@ permutation
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_set_log_lock_waits
+  s2_set_track_lock_timing
   s1_lock_advisory_lock
   s2_begin
   s2_ff
@@ -843,14 +843,14 @@ permutation
   s2_commit
   s2_report_stat_lock_advisory
 
-# Ensure log_lock_waits behaves correctly
+# Ensure track_lock_timing behaves correctly
 
 permutation
   s1_set_deadlock_timeout
   s1_reset_stat_lock
-  s1_set_log_lock_waits
+  s1_set_track_lock_timing
   s2_set_deadlock_timeout
-  s2_unset_log_lock_waits
+  s2_unset_track_lock_timing
   s1_begin
   s1_lock_relation
   s2_begin
-- 
2.34.1


--nK2xgkLTeiiswcxd--





^ permalink  raw  reply  [nested|flat] 5+ messages in thread

end of thread, other threads:[~2026-02-20 06:13 UTC | newest]

Thread overview: 5+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2025-12-18 17:21 [PATCH v3] Use open file description locks for lockfiles Dmitrii Dolgov <9erthalion6@gmail.com>
2026-02-20 06:13 [PATCH v7 3/3] Introduce a new track_lock_timing GUC Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
2026-02-20 06:13 [PATCH v8 3/3] Introduce a new track_lock_timing GUC Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
2026-02-20 06:13 [PATCH v8 3/3] Introduce a new track_lock_timing GUC Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
2026-02-20 06:13 [PATCH v9 3/3] Introduce a new track_lock_timing GUC Bertrand Drouvot <bertranddrouvot.pg@gmail.com>

This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox