From aa9e5748f055b9ca76eff9a5e57f7cbfc01ca4aa Mon Sep 17 00:00:00 2001 From: Fujii Masao Date: Wed, 18 Feb 2026 00:58:02 +0900 Subject: [PATCH v1] Rate-limit repeated "still waiting on lock" log messages. 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 rate-limits the "still waiting on lock" message to at most once every 10 seconds. The interval is now hardcoded, as making it configurable is not considered necessary. --- src/backend/storage/lmgr/proc.c | 36 +++++++++++++++++++++++++-------- 1 file changed, 28 insertions(+), 8 deletions(-) diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c index fd8318bdf3d..10f612549f6 100644 --- a/src/backend/storage/lmgr/proc.c +++ b/src/backend/storage/lmgr/proc.c @@ -1305,6 +1305,7 @@ ProcSleep(LOCALLOCK *locallock) TimestampTz standbyWaitStart = 0; bool allow_autovacuum_cancel = true; bool logged_recovery_conflict = false; + TimestampTz last_logged = 0; ProcWaitStatus myWaitStatus; DeadLockState deadlock_state; @@ -1553,6 +1554,7 @@ ProcSleep(LOCALLOCK *locallock) lock_waiters_sbuf, lock_holders_sbuf; const char *modename; + TimestampTz now; long secs; int usecs; long msecs; @@ -1565,9 +1567,9 @@ ProcSleep(LOCALLOCK *locallock) DescribeLockTag(&buf, &locallock->tag.lock); modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, lockmode); + now = GetCurrentTimestamp(); TimestampDifference(get_timeout_start_time(DEADLOCK_TIMEOUT), - GetCurrentTimestamp(), - &secs, &usecs); + now, &secs, &usecs); msecs = secs * 1000 + usecs / 1000; usecs = usecs % 1000; @@ -1602,12 +1604,30 @@ 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)))); + { + /* + * Rate-limit the "still waiting on lock" log message to at + * most once every 10 seconds. XXX: This interval is + * hardcoded, as making it configurable is unnecessary. + * + * Without this limit, 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 (TimestampDifferenceExceeds(last_logged, now, 10000)) + { + 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)))); + last_logged = now; + } + } else if (myWaitStatus == PROC_WAIT_STATUS_OK) ereport(LOG, (errmsg("process %d acquired %s on %s after %ld.%03d ms", -- 2.51.2