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
This commit is contained in:
Fujii Masao 2026-03-16 18:10:57 +09:00
parent c336133c65
commit fd6ecbfa75

View file

@ -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",