Ensure "still waiting on lock" message is logged only once per wait.

When log_lock_waits is enabled, the "still waiting on lock" message is normally
emitted only once while a session continues waiting. However, if the wait is
interrupted, for example by wakeups from client_connection_check_interval,
SIGHUP for configuration reloads, or similar events, the message could be
emitted again each time the wait resumes.

For example, with very small client_connection_check_interval values
(e.g., 100 ms), this behavior could flood the logs with repeated messages,
making them difficult to use.

To prevent this, this commit guards the "still waiting on lock" message so
it is reported at most once during a lock wait, even if the wait is interrupted.
This preserves the intended behavior when no interrupts occur.

Author: Fujii Masao <masao.fujii@gmail.com>
Reviewed-by: Chao Li <li.evan.chao@gmail.com>
Reviewed-by: Hüseyin Demir <huseyin.d3r@gmail.com>
Discussion: https://postgr.es/m/CAHGQGwHZUmg+r4kMcPYt_Z-txxVX+CJJhfra+qemxKXvAxYbpw@mail.gmail.com

diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index d407725e6027eacc1d915a346eed5b0e4237c2fc..8f5ce0e2a8a8223fddc6ed591d6388424d40f344 100644 (file)
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1309,6 +1309,7 @@ ProcSleep(LOCALLOCK *locallock)
        TimestampTz standbyWaitStart = 0;
        bool            allow_autovacuum_cancel = true;
        bool            logged_recovery_conflict = false;
+       bool            logged_lock_wait = false;
        ProcWaitStatus myWaitStatus;
        DeadLockState deadlock_state;
 
@@ -1606,12 +1607,29 @@ ProcSleep(LOCALLOCK *locallock)
                        }
 
                        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))));
+                       {
+                               /*
+                                * 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",