I will send the version with the GUC parameter added from the previous patch.
I made some minor code refactoring.
Regards, -- Yuki Seino NTT DATA CORPORATION
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 934ef5e469..ff6bde0b49 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -7674,6 +7674,22 @@ log_line_prefix = '%m [%p] %q%u@%d/%a ' </listitem> </varlistentry> + <varlistentry id="guc-log-lock-nowaits" xreflabel="log_lock_nowaits"> + <term><varname>log_lock_nowaits</varname> (<type>boolean</type>) + <indexterm> + <primary><varname>log_lock_nowaits</varname> configuration parameter</primary> + </indexterm> + </term> + <listitem> + <para> + Controls whether a log message is produced when acquire a lock with NOWAIT + has failed. The default is <literal>off</literal>. + Only superusers and users with the appropriate <literal>SET</literal> + privilege can change this setting. + </para> + </listitem> + </varlistentry> + <varlistentry id="guc-log-recovery-conflict-waits" xreflabel="log_recovery_conflict_waits"> <term><varname>log_recovery_conflict_waits</varname> (<type>boolean</type>) <indexterm> diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c index eaf3916f28..0717c4cc1c 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 = false; +bool log_lock_nowaits = false; /* Pointer to this process's PGPROC struct, if any */ PGPROC *MyProc = NULL; @@ -1119,6 +1120,11 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable, bool dontWait) bool logged_recovery_conflict = false; ProcWaitStatus myWaitStatus; PGPROC *leader = MyProc->lockGroupLeader; + StringInfoData buf, + lock_waiters_sbuf, + lock_holders_sbuf; + const char *modename; + int lockHoldersNum = 0; /* * If group locking is in use, locks held by members of my locking group @@ -1218,10 +1224,33 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable, bool dontWait) /* * At this point we know that we'd really need to sleep. If we've been - * commanded not to do that, bail out. + * commanded not to do that, bail out. Output lock information only + * if log_lock_nowaits is set. */ if (dontWait) + { + if (log_lock_nowaits) + { + initStringInfo(&buf); + initStringInfo(&lock_waiters_sbuf); + initStringInfo(&lock_holders_sbuf); + + DescribeLockTag(&buf, &locallock->tag.lock); + modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, + lockmode); + + /* Collect lock holders and waiters */ + CollectLockHoldersAndWaiters(proclock, lock, &lock_holders_sbuf, &lock_waiters_sbuf, &lockHoldersNum); + + ereport(LOG, + (errmsg("process %d could not obtain %s on %s", + MyProcPid, modename, buf.data), + (errdetail_log_plural("Process holding the lock: %s. Wait: %s.", + "Processes holding the lock: %s. Wait: %s.", + lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + } return PROC_WAIT_STATUS_ERROR; + } /* * Insert self into queue, at the position determined above. @@ -1500,18 +1529,9 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable, bool dontWait) */ if (log_lock_waits && deadlock_state != DS_NOT_YET_CHECKED) { - StringInfoData buf, - lock_waiters_sbuf, - lock_holders_sbuf; - const char *modename; long secs; int usecs; long msecs; - dlist_iter proc_iter; - PROCLOCK *curproclock; - bool first_holder = true, - first_waiter = true; - int lockHoldersNum = 0; initStringInfo(&buf); initStringInfo(&lock_waiters_sbuf); @@ -1526,53 +1546,10 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable, bool dontWait) msecs = secs * 1000 + usecs / 1000; usecs = usecs % 1000; - /* - * we loop over the lock's procLocks to gather a list of all - * holders and waiters. Thus we will be able to provide more - * detailed information for lock debugging purposes. - * - * lock->procLocks contains all processes which hold or wait for - * this lock. - */ - LWLockAcquire(partitionLock, LW_SHARED); - dlist_foreach(proc_iter, &lock->procLocks) - { - curproclock = - dlist_container(PROCLOCK, lockLink, proc_iter.cur); - - /* - * we are a waiter if myProc->waitProcLock == curproclock; we - * are a holder if it is NULL or something different - */ - if (curproclock->tag.myProc->waitProcLock == curproclock) - { - if (first_waiter) - { - appendStringInfo(&lock_waiters_sbuf, "%d", - curproclock->tag.myProc->pid); - first_waiter = false; - } - else - appendStringInfo(&lock_waiters_sbuf, ", %d", - curproclock->tag.myProc->pid); - } - else - { - if (first_holder) - { - appendStringInfo(&lock_holders_sbuf, "%d", - curproclock->tag.myProc->pid); - first_holder = false; - } - else - appendStringInfo(&lock_holders_sbuf, ", %d", - curproclock->tag.myProc->pid); - - lockHoldersNum++; - } - } + /* Collect lock holders and waiters */ + CollectLockHoldersAndWaiters(NULL, lock, &lock_holders_sbuf, &lock_waiters_sbuf, &lockHoldersNum); LWLockRelease(partitionLock); @@ -1995,3 +1972,58 @@ BecomeLockGroupMember(PGPROC *leader, int pid) return ok; } + +/* + * we loop over the lock's procLocks to gather a list of all + * holders and waiters. Thus we will be able to provide more + * detailed information for lock debugging purposes. + * + * lock->procLocks contains all processes which hold or wait for + * this lock. + */ +void +CollectLockHoldersAndWaiters(PROCLOCK *waitProcLock, LOCK *lock, StringInfo lock_holders_sbuf, StringInfo lock_waiters_sbuf, int *lockHoldersNum) +{ + bool first_holder = true; + bool first_waiter = true; + dlist_iter proc_iter; + PROCLOCK *curproclock; + + dlist_foreach(proc_iter, &lock->procLocks) + { + curproclock = + dlist_container(PROCLOCK, lockLink, proc_iter.cur); + + /* + * we are a waiter if myProc->waitProcLock == curproclock; we + * are a holder if it is NULL or something different + */ + if ((waitProcLock == NULL && curproclock->tag.myProc->waitProcLock == curproclock) || + (waitProcLock != NULL && waitProcLock == curproclock)) + { + if (first_waiter) + { + appendStringInfo(lock_waiters_sbuf, "%d", + curproclock->tag.myProc->pid); + first_waiter = false; + } + else + appendStringInfo(lock_waiters_sbuf, ", %d", + curproclock->tag.myProc->pid); + } + else + { + if (first_holder) + { + appendStringInfo(lock_holders_sbuf, "%d", + curproclock->tag.myProc->pid); + first_holder = false; + } + else + appendStringInfo(lock_holders_sbuf, ", %d", + curproclock->tag.myProc->pid); + + (*lockHoldersNum)++; + } + } +} \ No newline at end of file diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c index 2c4cc8cd41..41de8ada76 100644 --- a/src/backend/utils/misc/guc_tables.c +++ b/src/backend/utils/misc/guc_tables.c @@ -1561,6 +1561,15 @@ struct config_bool ConfigureNamesBool[] = false, NULL, NULL, NULL }, + { + {"log_lock_nowaits", PGC_SUSET, LOGGING_WHAT, + gettext_noop("Logs lock info when nowait fails."), + NULL + }, + &log_lock_nowaits, + false, + NULL, NULL, NULL + }, { {"log_recovery_conflict_waits", PGC_SIGHUP, LOGGING_WHAT, gettext_noop("Logs standby recovery conflict waits."), diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index 667e0dc40a..6d0d93ab57 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -606,6 +606,7 @@ # %% = '%' # e.g. '<%u%%%d> ' #log_lock_waits = off # log lock waits >= deadlock_timeout +#log_lock_nowaits = off # Enable logging lock info when nowait fails #log_recovery_conflict_waits = off # log standby recovery conflict waits # >= deadlock_timeout #log_parameter_max_length = -1 # when logging statements, limit logged diff --git a/src/include/storage/proc.h b/src/include/storage/proc.h index ebcf0ad403..541f68c3f6 100644 --- a/src/include/storage/proc.h +++ b/src/include/storage/proc.h @@ -457,6 +457,7 @@ extern PGDLLIMPORT int IdleInTransactionSessionTimeout; extern PGDLLIMPORT int TransactionTimeout; extern PGDLLIMPORT int IdleSessionTimeout; extern PGDLLIMPORT bool log_lock_waits; +extern PGDLLIMPORT bool log_lock_nowaits; #ifdef EXEC_BACKEND extern PGDLLIMPORT slock_t *ProcStructLock; @@ -496,5 +497,6 @@ extern PGPROC *AuxiliaryPidGetProc(int pid); extern void BecomeLockGroupLeader(void); extern bool BecomeLockGroupMember(PGPROC *leader, int pid); +extern void CollectLockHoldersAndWaiters(PROCLOCK *waitProcLock, LOCK *lock, StringInfo lock_holders_sbuf, StringInfo lock_waiters_sbuf, int *lockHoldersNum); #endif /* _PROC_H_ */ diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c index 5157629b1c..c8b01faf24 100644 --- a/src/test/regress/pg_regress.c +++ b/src/test/regress/pg_regress.c @@ -2398,6 +2398,7 @@ regression_main(int argc, char *argv[], fputs("log_checkpoints = on\n", pg_conf); fputs("log_line_prefix = '%m %b[%p] %q%a '\n", pg_conf); fputs("log_lock_waits = on\n", pg_conf); + fputs("log_lock_nowaits = on\n", pg_conf); fputs("log_temp_files = 128kB\n", pg_conf); fputs("max_prepared_transactions = 2\n", pg_conf); diff --git a/src/tools/ci/pg_ci_base.conf b/src/tools/ci/pg_ci_base.conf index d8faa9c26c..71d8949963 100644 --- a/src/tools/ci/pg_ci_base.conf +++ b/src/tools/ci/pg_ci_base.conf @@ -12,3 +12,4 @@ log_connections = true log_disconnections = true log_line_prefix = '%m [%p][%b] %q[%a][%v:%x] ' log_lock_waits = true +log_lock_nowaits = true