diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index a8866292d4..68fcc80c29 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -7589,6 +7589,25 @@ log_line_prefix = '%m [%p] %q%u@%d/%a ' + + log_lock_failure (boolean) + + log_lock_failure configuration parameter + + + + + Controls whether a log message is produced when a lock acquisition + fails. This is useful for analyzing the causes of lock failures. + Currently, only lock failures due to NOWAIT and + SKIP LOCKED are supported. The default is + off. Only superusers and users with the + appropriate SET privilege can change this setting. + + + + + log_recovery_conflict_waits (boolean) diff --git a/src/backend/storage/lmgr/lmgr.c b/src/backend/storage/lmgr/lmgr.c index 68271cb640..73cf835c93 100644 --- a/src/backend/storage/lmgr/lmgr.c +++ b/src/backend/storage/lmgr/lmgr.c @@ -1332,3 +1332,59 @@ GetLockNameFromTagType(uint16 locktag_type) return "???"; return LockTagTypeNames[locktag_type]; } + +/* + * CollectLockHoldersAndWaiters + * + * 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(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 (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)++; + } + } +} \ No newline at end of file diff --git a/src/backend/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c index 3e2f98b371..eee3c3f585 100644 --- a/src/backend/storage/lmgr/lock.c +++ b/src/backend/storage/lmgr/lock.c @@ -39,6 +39,7 @@ #include "access/xlogutils.h" #include "miscadmin.h" #include "pg_trace.h" +#include "storage/lmgr.h" #include "storage/proc.h" #include "storage/procarray.h" #include "storage/spin.h" @@ -47,9 +48,10 @@ #include "utils/ps_status.h" #include "utils/resowner.h" +/* GUC variables. */ +int max_locks_per_xact; /* This configuration variable is used to set the lock table size */ +bool log_lock_failure = false; -/* This configuration variable is used to set the lock table size */ -int max_locks_per_xact; /* set by guc.c */ #define NLOCKENTS() \ mul_size(max_locks_per_xact, add_size(MaxBackends, max_prepared_xacts)) @@ -1145,6 +1147,37 @@ LockAcquireExtended(const LOCKTAG *locktag, if (dontWait) { + if (log_lock_failure) + { + StringInfoData buf, + lock_waiters_sbuf, + lock_holders_sbuf; + const char *modename; + int lockHoldersNum = 0; + initStringInfo(&buf); + initStringInfo(&lock_waiters_sbuf); + initStringInfo(&lock_holders_sbuf); + + LWLockAcquire(partitionLock, LW_SHARED); + DescribeLockTag(&buf, &locallock->tag.lock); + modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, + lockmode); + + /* Collect lock holders and waiters */ + CollectLockHoldersAndWaiters(lock, &lock_holders_sbuf, &lock_waiters_sbuf, &lockHoldersNum); + + if (lock_waiters_sbuf.len == 0) + { + appendStringInfoString(&lock_waiters_sbuf, "None"); + } + ereport(LOG, + (errmsg("process %d could not obtain %s on %s", + MyProcPid, modename, buf.data), + (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)))); + LWLockRelease(partitionLock); + } if (locallockp) *locallockp = NULL; return LOCKACQUIRE_NOT_AVAIL; diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c index 49204f91a2..a4c0bf70e8 100644 --- a/src/backend/storage/lmgr/proc.c +++ b/src/backend/storage/lmgr/proc.c @@ -1514,10 +1514,6 @@ ProcSleep(LOCALLOCK *locallock) long secs; int usecs; long msecs; - dlist_iter proc_iter; - PROCLOCK *curproclock; - bool first_holder = true, - first_waiter = true; int lockHoldersNum = 0; initStringInfo(&buf); @@ -1533,53 +1529,10 @@ ProcSleep(LOCALLOCK *locallock) 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(lock, &lock_holders_sbuf, &lock_waiters_sbuf, &lockHoldersNum); LWLockRelease(partitionLock); diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c index 38cb9e970d..3aa4cdac26 100644 --- a/src/backend/utils/misc/guc_tables.c +++ b/src/backend/utils/misc/guc_tables.c @@ -1572,6 +1572,15 @@ struct config_bool ConfigureNamesBool[] = false, NULL, NULL, NULL }, + { + {"log_lock_failure", PGC_SUSET, LOGGING_WHAT, + gettext_noop("Logs lock failed."), + NULL + }, + &log_lock_failure, + 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 079efa1baa..7f17f0ca1e 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -601,6 +601,7 @@ # %% = '%' # e.g. '<%u%%%d> ' #log_lock_waits = off # log lock waits >= deadlock_timeout +#log_lock_failure = off # log lock failed #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/lmgr.h b/src/include/storage/lmgr.h index 728260c1cc..57a8f3992e 100644 --- a/src/include/storage/lmgr.h +++ b/src/include/storage/lmgr.h @@ -123,4 +123,7 @@ extern void DescribeLockTag(StringInfo buf, const LOCKTAG *tag); extern const char *GetLockNameFromTagType(uint16 locktag_type); +/* Collect LockHolders and Waiters for error messages */ +extern void CollectLockHoldersAndWaiters(LOCK *lock, StringInfo lock_holders_sbuf, StringInfo lock_waiters_sbuf, int *lockHoldersNum); + #endif /* LMGR_H */ diff --git a/src/include/storage/lock.h b/src/include/storage/lock.h index 1076995518..f023656ea3 100644 --- a/src/include/storage/lock.h +++ b/src/include/storage/lock.h @@ -30,6 +30,7 @@ typedef struct PGPROC PGPROC; /* GUC variables */ extern PGDLLIMPORT int max_locks_per_xact; +extern PGDLLIMPORT bool log_lock_failure; #ifdef LOCK_DEBUG extern PGDLLIMPORT int Trace_lock_oidmin; diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c index 61a234ae21..cefd24f16c 100644 --- a/src/test/regress/pg_regress.c +++ b/src/test/regress/pg_regress.c @@ -2404,6 +2404,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_failure = on\n", pg_conf); fputs("log_temp_files = 128kB\n", pg_conf); fputs("max_prepared_transactions = 2\n", pg_conf);