From ba2885baff611dc4e471f057fd2b3348fc491a57 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 (Separately for first and second LWLockAttemptLock calls) --- src/backend/storage/ipc/procarray.c | 13 +++- src/backend/storage/lmgr/lwlock.c | 93 ++++++++++++++++++++++++++--- 2 files changed, 97 insertions(+), 9 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 a8a439ad516..7042882c95f 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 @@ -263,8 +265,14 @@ typedef struct lwlock_stats lwlock_stats_key key; int sh_acquire_count; int ex_acquire_count; + int ex_attempt_count1[3]; + int sh_attempt_count1[3]; + int ex_attempt_count2[3]; + int sh_attempt_count2[3]; + int shared_wake_calls; + int shared_wakes; int block_count; - int dequeue_self_count; + int dequeue_self_count; int spin_delay_count; } lwlock_stats; @@ -371,11 +379,16 @@ 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 dequeue self %u ex_attempt1[0] %u ex_attemp1[1] %u ex_attempt1[2] %u sh_attempt1[0] %u sh_attempt1[1] %u sh_attempt1[2] %u ex_attempt2[0] %u ex_attempt2[1] %u ex_attempt2[2] %u sh_attempt2[0] %u sh_attempt2[1] %u sh_attempt2[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->dequeue_self_count, + lwstats->ex_attempt_count1[0], lwstats->ex_attempt_count1[1], lwstats->ex_attempt_count1[2], + lwstats->sh_attempt_count1[0], lwstats->sh_attempt_count1[1], lwstats->sh_attempt_count1[2], + lwstats->ex_attempt_count2[0], lwstats->ex_attempt_count2[1], lwstats->ex_attempt_count2[2], + lwstats->sh_attempt_count2[0], lwstats->sh_attempt_count2[1], lwstats->sh_attempt_count2[2], + lwstats->shared_wake_calls, lwstats->shared_wakes); } LWLockRelease(&MainLWLockArray[0].lock); @@ -408,6 +421,12 @@ get_lwlock_stats_entry(LWLock *lock) lwstats->block_count = 0; lwstats->dequeue_self_count = 0; lwstats->spin_delay_count = 0; + memset(lwstats->ex_attempt_count1, 0, sizeof(lwstats->ex_attempt_count1)); + memset(lwstats->sh_attempt_count1, 0, sizeof(lwstats->sh_attempt_count1)); + memset(lwstats->ex_attempt_count2, 0, sizeof(lwstats->ex_attempt_count2)); + memset(lwstats->sh_attempt_count2, 0, sizeof(lwstats->sh_attempt_count2)); + lwstats->shared_wake_calls = 0; + lwstats->shared_wakes = 0; } return lwstats; } @@ -948,7 +967,7 @@ LWLockWaitListUnlock(LWLock *lock) * Wakeup all the lockers that currently have a chance to acquire the lock. */ static void -LWLockWakeup(LWLock *lock) +LWLockWakeup(LWLock *lock, lwlock_stats *lwstats) { bool new_release_ok; bool wokeup_somebody = false; @@ -1038,6 +1057,12 @@ LWLockWakeup(LWLock *lock) { PGPROC *waiter = GetPGProcByNumber(iter.cur); +#ifdef LWLOCK_STATS + if(lwstats) + { + lwstats->shared_wakes++; + } +#endif LOG_LWDEBUG("LWLockRelease", lock, "release waiter"); proclist_delete(&wakeup, iter.cur, lwWaitLink); @@ -1202,6 +1227,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 @@ -1264,7 +1290,14 @@ LWLockAcquire(LWLock *lock, LWLockMode mode) if (!mustwait) { - LOG_LWDEBUG("LWLockAcquire", lock, "immediately acquired lock"); +#ifdef LWLOCK_STATS + if (mode == LW_EXCLUSIVE) + lwstats->ex_attempt_count1[nsema]++; + else + lwstats->sh_attempt_count1[nsema]++; + +#endif + LOG_LWDEBUG("LWLockAcquire", lock, "immediately acquired lock"); break; /* got the lock */ } @@ -1288,6 +1321,13 @@ LWLockAcquire(LWLock *lock, LWLockMode mode) /* ok, grabbed the lock the second time round, need to undo queueing */ if (!mustwait) { +#ifdef LWLOCK_STATS + if (mode == LW_EXCLUSIVE) + lwstats->ex_attempt_count2[nsema]++; + else + lwstats->sh_attempt_count2[nsema]++; +#endif + LOG_LWDEBUG("LWLockAcquire", lock, "acquired, undoing queue"); LWLockDequeueSelf(lock); @@ -1306,6 +1346,10 @@ LWLockAcquire(LWLock *lock, LWLockMode mode) #ifdef LWLOCK_STATS lwstats->block_count++; + nsema++; + + if (nsema > 2) + nsema = 2; #endif LWLockReportWaitStart(lock); @@ -1320,6 +1364,7 @@ LWLockAcquire(LWLock *lock, LWLockMode mode) extraWaits++; } + /* Retrying, allow LWLockRelease to release waiters again. */ pg_atomic_fetch_or_u32(&lock->state, LW_FLAG_RELEASE_OK); @@ -1430,6 +1475,7 @@ LWLockAcquireOrWait(LWLock *lock, LWLockMode mode) int extraWaits = 0; #ifdef LWLOCK_STATS lwlock_stats *lwstats; + int nsema = 0; lwstats = get_lwlock_stats_entry(lock); #endif @@ -1471,6 +1517,10 @@ LWLockAcquireOrWait(LWLock *lock, LWLockMode mode) #ifdef LWLOCK_STATS lwstats->block_count++; + nsema++; + + if (nsema > 2) + nsema = 2; #endif LWLockReportWaitStart(lock); @@ -1501,6 +1551,12 @@ LWLockAcquireOrWait(LWLock *lock, LWLockMode mode) } else { +#ifdef LWLOCK_STATS + if (mode == LW_EXCLUSIVE) + lwstats->ex_attempt_count2[nsema]++; + else + lwstats->sh_attempt_count2[nsema]++; +#endif LOG_LWDEBUG("LWLockAcquireOrWait", lock, "acquired, undoing queue"); /* @@ -1512,6 +1568,15 @@ LWLockAcquireOrWait(LWLock *lock, LWLockMode mode) LWLockDequeueSelf(lock); } } + else + { +#ifdef LWLOCK_STATS + if (mode == LW_EXCLUSIVE) + lwstats->ex_attempt_count1[nsema]++; + else + lwstats->sh_attempt_count1[nsema]++; +#endif + } /* * Fix the process wait semaphore's count for any absorbed wakeups. @@ -1733,7 +1798,6 @@ LWLockWaitForVar(LWLock *lock, uint64 *valptr, uint64 oldval, uint64 *newval) return result; } - /* * LWLockUpdateVar - Update a variable and wake up waiters atomically * @@ -1796,7 +1860,6 @@ LWLockUpdateVar(LWLock *lock, uint64 *valptr, uint64 val) } } - /* * LWLockRelease - release a previously acquired lock */ @@ -1807,7 +1870,11 @@ LWLockRelease(LWLock *lock) uint32 oldstate; bool check_waiters; int i; +#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 * be the latest-acquired lock; so search array backwards. @@ -1861,7 +1928,17 @@ LWLockRelease(LWLock *lock) { /* XXX: remove before commit? */ LOG_LWDEBUG("LWLockRelease", lock, "releasing waiters"); - LWLockWakeup(lock); +#ifdef LWLOCK_STATS + if (mode == LW_SHARED) + { + lwstats->shared_wake_calls++; + LWLockWakeup(lock, lwstats); + } + else + LWLockWakeup(lock, NULL); +#else + LWLockWakeup(lock, NULL); +#endif } /* -- 2.24.3 (Apple Git-128)