From 41fab24a04202bb28b407913de50e56661f32133 Mon Sep 17 00:00:00 2001 From: Pavel Borisov Date: Tue, 1 Nov 2022 14:36:05 +0400 Subject: [PATCH] Print extended lwlock_stats and proc_stats on CAS repeats (Separately for exclusive, shared, and wait-until-free lockers) --- src/backend/storage/ipc/procarray.c | 13 ++- src/backend/storage/lmgr/lwlock.c | 169 +++++++++++++++++++++++++--- 2 files changed, 167 insertions(+), 15 deletions(-) diff --git a/src/backend/storage/ipc/procarray.c b/src/backend/storage/ipc/procarray.c index 207c4b27fdf..6e3ef86c3b9 100644 --- a/src/backend/storage/ipc/procarray.c +++ b/src/backend/storage/ipc/procarray.c @@ -68,6 +68,8 @@ #include "utils/snapmgr.h" #define UINT32_ACCESS_ONCE(var) ((uint32)(*((volatile uint32 *)&(var)))) +#define PROC_STATS + /* Our shared memory area */ typedef struct ProcArrayStruct @@ -97,11 +99,15 @@ typedef struct ProcArrayStruct TransactionId replication_slot_xmin; /* oldest catalog xmin of any replication slot */ TransactionId replication_slot_catalog_xmin; - /* indexes into allProcs[], has PROCARRAY_MAXPROCS entries */ int pgprocnos[FLEXIBLE_ARRAY_MEMBER]; } ProcArrayStruct; +#ifdef PROC_STATS + static int group_clear_xid_calls; + static int end_trans_internal_calls; +#endif + /* * State for the GlobalVisTest* family of functions. Those functions can * e.g. be used to decide if a deleted row can be removed without violating @@ -565,6 +571,9 @@ ProcArrayRemove(PGPROC *proc, TransactionId latestXid) if (proc->pid != 0) DisplayXidCache(); #endif +#ifdef PROC_STATS + fprintf(stderr, "proc_stats: GroupClearXid %u, EndTransactionInternal: %u\n", group_clear_xid_calls, end_trans_internal_calls); +#endif /* See ProcGlobal comment explaining why both locks are held */ LWLockAcquire(ProcArrayLock, LW_EXCLUSIVE); @@ -736,6 +745,7 @@ ProcArrayEndTransactionInternal(PGPROC *proc, TransactionId latestXid) proc->xid = InvalidTransactionId; proc->lxid = InvalidLocalTransactionId; proc->xmin = InvalidTransactionId; + end_trans_internal_calls++; /* be sure this is cleared in abort */ proc->delayChkptFlags = 0; @@ -790,6 +800,7 @@ ProcArrayGroupClearXid(PGPROC *proc, TransactionId latestXid) /* We should definitely have an XID to clear. */ Assert(TransactionIdIsValid(proc->xid)); + group_clear_xid_calls++; /* Add ourselves to the list of processes needing a group XID clear. */ proc->procArrayGroupMember = true; proc->procArrayGroupMemberXid = latestXid; diff --git a/src/backend/storage/lmgr/lwlock.c b/src/backend/storage/lmgr/lwlock.c index f5a149b4f42..418bfa7d703 100644 --- a/src/backend/storage/lmgr/lwlock.c +++ b/src/backend/storage/lmgr/lwlock.c @@ -89,6 +89,8 @@ #include "storage/spin.h" #include "utils/memutils.h" +#define LWLOCK_STATS + #ifdef LWLOCK_STATS #include "utils/hsearch.h" #endif @@ -288,8 +290,17 @@ typedef struct lwlock_stats lwlock_stats_key key; int sh_acquire_count; int ex_acquire_count; + int acq_sh_cas_repeat; + int rel_sh_cas_repeat; + int acq_ex_cas_repeat; + int rel_ex_cas_repeat; + int acq_wuf_cas_repeat; + int rel_wuf_cas_repeat; + int ex_attempt_count[3]; + int sh_attempt_count[3]; + int shared_wake_calls; + int shared_wakes; int block_count; - int dequeue_self_count; int spin_delay_count; } lwlock_stats; @@ -396,11 +407,17 @@ print_lwlock_stats(int code, Datum arg) while ((lwstats = (lwlock_stats *) hash_seq_search(&scan)) != NULL) { fprintf(stderr, - "PID %d lwlock %s %p: shacq %u exacq %u blk %u spindelay %u dequeue self %u\n", + "PID %d lwlock %s %p: shacq %u exacq %u blk %u spindelay %u acq_sh_cas_repeat %u rel_sh_cas_repeat %u acq_ex_cas_repeat %u rel_ex_cas_repeat %u acq_wuf_cas_repeat %u rel_wuf_cas_repeat %u ex_attempt[0] %u ex_attempt[1] %u ex_attempt[2] %u sh_attempt[0] %u sh_attempt[1] %u sh_attempt[2] %u sh_wake_calls %u sh_wakes %u\n", MyProcPid, GetLWTrancheName(lwstats->key.tranche), lwstats->key.instance, lwstats->sh_acquire_count, lwstats->ex_acquire_count, lwstats->block_count, - lwstats->spin_delay_count, lwstats->dequeue_self_count); + lwstats->spin_delay_count, + lwstats->acq_sh_cas_repeat, lwstats->rel_sh_cas_repeat, + lwstats->acq_ex_cas_repeat, lwstats->rel_ex_cas_repeat, + lwstats->acq_wuf_cas_repeat, lwstats->rel_wuf_cas_repeat, + lwstats->ex_attempt_count[0], lwstats->ex_attempt_count[1], lwstats->ex_attempt_count[2], + lwstats->sh_attempt_count[0], lwstats->sh_attempt_count[1], lwstats->sh_attempt_count[2], + lwstats->shared_wake_calls, lwstats->shared_wakes); } LWLockRelease(&MainLWLockArray[0].lock); @@ -431,8 +448,17 @@ get_lwlock_stats_entry(LWLock *lock) lwstats->sh_acquire_count = 0; lwstats->ex_acquire_count = 0; lwstats->block_count = 0; - lwstats->dequeue_self_count = 0; lwstats->spin_delay_count = 0; + lwstats->acq_sh_cas_repeat = 0; + lwstats->rel_sh_cas_repeat = 0; + lwstats->acq_ex_cas_repeat = 0; + lwstats->rel_ex_cas_repeat = 0; + lwstats->acq_wuf_cas_repeat = 0; + lwstats->rel_wuf_cas_repeat = 0; + memset(lwstats->ex_attempt_count, 0, sizeof(lwstats->ex_attempt_count)); + memset(lwstats->sh_attempt_count, 0, sizeof(lwstats->sh_attempt_count)); + lwstats->shared_wake_calls = 0; + lwstats->shared_wakes = 0; } return lwstats; } @@ -837,7 +863,7 @@ GetLWLockIdentifier(uint32 classId, uint16 eventId) */ static bool LWLockAttemptLock(LWLock *lock, LWLockMode mode, LWLockMode waitMode, - bool queue_ok, bool wakeup) + bool queue_ok, bool wakeup, void *lwstats) { uint64 old_state; @@ -965,7 +991,22 @@ LWLockAttemptLock(LWLock *lock, LWLockMode mode, LWLockMode waitMode, } } else + { +#ifdef LWLOCK_STATS + switch(waitMode) + { + case LW_EXCLUSIVE: + ((lwlock_stats*)lwstats)->acq_ex_cas_repeat++; + break; + case LW_SHARED: + ((lwlock_stats*)lwstats)->acq_sh_cas_repeat++; + break; + case LW_WAIT_UNTIL_FREE: + ((lwlock_stats*)lwstats)->acq_wuf_cas_repeat++; + } +#endif MyProc->lwWaiting = false; + } } pg_unreachable(); } @@ -988,6 +1029,7 @@ LWLockAcquire(LWLock *lock, LWLockMode mode) int extraWaits = 0; #ifdef LWLOCK_STATS lwlock_stats *lwstats; + int nsema = 0; lwstats = get_lwlock_stats_entry(lock); #endif @@ -1040,9 +1082,19 @@ LWLockAcquire(LWLock *lock, LWLockMode mode) */ for (;;) { - if (!LWLockAttemptLock(lock, mode, mode, true, wakeup)) +#ifdef LWLOCK_STATS + if (!LWLockAttemptLock(lock, mode, mode, true, wakeup, lwstats)) +#else + if (!LWLockAttemptLock(lock, mode, mode, true, wakeup, NULL)) +#endif { - LOG_LWDEBUG("LWLockAcquire", lock, "immediately acquired lock"); +#ifdef LWLOCK_STATS + if (mode == LW_EXCLUSIVE) + lwstats->ex_attempt_count[nsema]++; + else + lwstats->sh_attempt_count[nsema]++; +#endif + LOG_LWDEBUG("LWLockAcquire", lock, "immediately acquired lock"); break; /* got the lock */ } @@ -1058,6 +1110,9 @@ LWLockAcquire(LWLock *lock, LWLockMode mode) #ifdef LWLOCK_STATS lwstats->block_count++; + nsema++; + if (nsema > 2) + nsema = 2; #endif LWLockReportWaitStart(lock); @@ -1119,6 +1174,11 @@ bool LWLockConditionalAcquire(LWLock *lock, LWLockMode mode) { bool mustwait; +#ifdef LWLOCK_STATS + lwlock_stats *lwstats; + + lwstats = get_lwlock_stats_entry(lock); +#endif Assert(mode == LW_SHARED || mode == LW_EXCLUSIVE); @@ -1136,7 +1196,12 @@ LWLockConditionalAcquire(LWLock *lock, LWLockMode mode) HOLD_INTERRUPTS(); /* Check for the lock */ - mustwait = LWLockAttemptLock(lock, mode, mode, false, false); +#ifdef LWLOCK_STATS + mustwait = LWLockAttemptLock(lock, mode, mode, false, false, lwstats); +#else + mustwait = LWLockAttemptLock(lock, mode, mode, false, false, NULL); +#endif + if (mustwait) { @@ -1203,7 +1268,11 @@ LWLockAcquireOrWait(LWLock *lock, LWLockMode mode) * NB: We're using nearly the same twice-in-a-row lock acquisition * protocol as LWLockAcquire(). Check its comments for details. */ - mustwait = LWLockAttemptLock(lock, mode, LW_WAIT_UNTIL_FREE, true, false); +#ifdef LWLOCK_STATS + mustwait = LWLockAttemptLock(lock, mode, LW_WAIT_UNTIL_FREE, true, false, lwstats); +#else + mustwait = LWLockAttemptLock(lock, mode, LW_WAIT_UNTIL_FREE, true, false, NULL); +#endif if (mustwait) { @@ -1318,7 +1387,7 @@ LWLockConflictsWithVar(LWLock *lock, old_state = pg_atomic_read_u64(&lock->state); } #ifdef LWLOCK_STATS - delays += delayStatus.delays; +// delays += delayStatus.delays; #endif finish_spin_delay(&delayStatus); } @@ -1521,7 +1590,7 @@ lockVar(LWLock *lock) oldState = pg_atomic_read_u64(&lock->state); } #ifdef LWLOCK_STATS - delays += delayStatus.delays; +// delays += delayStatus.delays; #endif finish_spin_delay(&delayStatus); @@ -1559,7 +1628,7 @@ waitForQueueRelink(uint32 pgprocno) /* awakenWaiters - Awaken all waiters from the wake queue */ static inline void -awakenWaiters(uint32 pgprocno, LWLock *lock) +awakenWaiters(uint32 pgprocno, LWLock *lock, lwlock_stats *lwstats) { while (pgprocno != INVALID_LOCK_PROCNO) { @@ -1574,6 +1643,12 @@ awakenWaiters(uint32 pgprocno, LWLock *lock) PGSemaphoreUnlock(CurSem(pgprocno)); pgprocno = nextlink; +#ifdef LWLOCK_STATS + if(lwstats) + { + lwstats->shared_wakes++; + } +#endif } } @@ -1598,6 +1673,11 @@ LWLockUpdateVar(LWLock *lock, uint64 *valptr, uint64 val) oldTail = INVALID_LOCK_PROCNO, oldReplaceHead = INVALID_LOCK_PROCNO, wakeupTail = INVALID_LOCK_PROCNO; + LWLockMode waitMode; +#ifdef LWLOCK_STATS + lwlock_stats *lwstats; + lwstats = get_lwlock_stats_entry(lock); +#endif PRINT_LWDEBUG("LWLockUpdateVar", lock, LW_EXCLUSIVE); @@ -1621,6 +1701,7 @@ LWLockUpdateVar(LWLock *lock, uint64 *valptr, uint64 val) * processes from release queue. */ + while (true) { uint64 newState = oldState; @@ -1704,6 +1785,7 @@ LWLockUpdateVar(LWLock *lock, uint64 *valptr, uint64 val) /* Remove LW_WAIT_UNTIL_FREE from the list head */ if (CurWaitMode(pgprocno) == LW_WAIT_UNTIL_FREE) { + waitMode = LW_WAIT_UNTIL_FREE; newHead = nextPgprocno; if (newHead == INVALID_LOCK_PROCNO) newTail = newHead; @@ -1719,6 +1801,7 @@ LWLockUpdateVar(LWLock *lock, uint64 *valptr, uint64 val) * At the tail part of a list there could be only LW_EXCLUSIVE * or LW_SHARED */ + waitMode = CurWaitMode(pgprocno); break; } @@ -1734,10 +1817,38 @@ LWLockUpdateVar(LWLock *lock, uint64 *valptr, uint64 val) { break; } + else + { +#ifdef LWLOCK_STATS + { + switch(waitMode) + { + case LW_EXCLUSIVE: + lwstats->rel_ex_cas_repeat++; + break; + case LW_SHARED: + lwstats->rel_sh_cas_repeat++; + break; + case LW_WAIT_UNTIL_FREE: + lwstats->rel_wuf_cas_repeat++; + } + } +#endif + } } /* Awaken any waiters removed from the queue. */ - awakenWaiters(wakeupTail, lock); +#ifdef LWLOCK_STATS + if (waitMode == LW_SHARED) + { + lwstats->shared_wake_calls++; + awakenWaiters(wakeupTail, lock, lwstats); + } + else + awakenWaiters(wakeupTail, lock, NULL); +#else + awakenWaiters(wakeupTail, lock, NULL); +#endif } /* @@ -1761,6 +1872,10 @@ LWLockRelease(LWLock *lock) bool new_release_ok = true; bool wakeup = false; LWLockMode lastMode = LW_WAIT_UNTIL_FREE; +#ifdef LWLOCK_STATS + lwlock_stats *lwstats; + lwstats = get_lwlock_stats_entry(lock); +#endif /* * Remove lock from list of locks held. Usually, but not always, it will @@ -2037,10 +2152,36 @@ LWLockRelease(LWLock *lock) if (pg_atomic_compare_exchange_u64(&lock->state, &oldState, newState)) break; + else + { +#ifdef LWLOCK_STATS + switch(lastMode) + { + case LW_EXCLUSIVE: + lwstats->rel_ex_cas_repeat++; + break; + case LW_SHARED: + lwstats->rel_sh_cas_repeat++; + break; + case LW_WAIT_UNTIL_FREE: + lwstats->rel_wuf_cas_repeat++; + } +#endif + } } /* Awaken any waiters removed from the queue. */ - awakenWaiters(wakeupTail, lock); +#ifdef LWLOCK_STATS + if(lastMode == LW_SHARED) + { + lwstats->shared_wake_calls++; + awakenWaiters(wakeupTail, lock, lwstats); + } + else + awakenWaiters(wakeupTail, lock, NULL); +#else + awakenWaiters(wakeupTail, lock, NULL); +#endif /* Now okay to allow cancel/die interrupts. */ RESUME_INTERRUPTS(); -- 2.24.3 (Apple Git-128)