Currently, we are discussing two improvements:
1. Log output when NOWAIT fails.
2. Adding control via GUC parameters (NOWAIT, lock_timeout,
cancellation).
I'm not sure why it's challenging to provide detailed log messages for
lock waits canceled
by lock_timeout or user cancellation, while it's considered feasible
for the NOWAIT case.
Does this statement mean that for 2, why can NOWAIT but
lock_timeout,cancellation cannot?
For item 2, the lock_timeout and cancellation will log outputs after the
deadlock_timeout(e.g. 1s) has elapsed (by log_lock_waits).
At the time this log is output, it is unclear whether the lock will be
cancellation or lock_timeout.
This means that the timing at "error is determined" and "output logged"
do not match.
However, I think it's reasonable to implement this feature step by
step. We can start
by adding support for the NOWAIT case and consider extending it to
handle lock_timeout and
cancellation scenarios later if possible.
+1.
I will send the version with the GUC parameter added from the previous
patch.
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..4f0bddc94a 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,31 @@ 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 (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 +1527,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 +1544,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 +1970,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
