From 7c697ae06dff02bcd306c55aa6a79eabd58284fc Mon Sep 17 00:00:00 2001 From: Craig Ringer Date: Thu, 19 Nov 2020 18:05:39 +0800 Subject: [PATCH v1 3/5] Add to the tracepoints in LWLock routines The existing tracepoints in lwlock.c didn't mark the start of LWLock acquisition, so timing of the full LWLock acquire cycle wasn't possible without relying on debuginfo. Since this can be quite relevant for production performance issues, emit tracepoints at the start of LWLock acquire. Also add a tracepoint that's fired for all LWLock acquisitions at the moment the shared memory state changes, whether done by LWLockAcquire or LWLockConditionalAcquire. This lets tools reliably track which backends hold which LWLocks even if we add new functions that acquire LWLocks in future. Add tracepoints in LWLockWaitForVar and LWLockUpdateVar so process interaction around LWLock variable waits can be observed from trace tooling. They can cause long waits and/or deadlocks, so it's worth being able to time and track them. --- src/backend/storage/lmgr/lwlock.c | 24 ++++++++++++++++++++++++ src/backend/utils/probes.d | 8 ++++++++ 2 files changed, 32 insertions(+) diff --git a/src/backend/storage/lmgr/lwlock.c b/src/backend/storage/lmgr/lwlock.c index 92de34a399..d63119931b 100644 --- a/src/backend/storage/lmgr/lwlock.c +++ b/src/backend/storage/lmgr/lwlock.c @@ -876,6 +876,9 @@ LWLockAttemptLock(LWLock *lock, LWLockMode mode) if (mode == LW_EXCLUSIVE) lock->owner = MyProc; #endif + /* All LWLock acquires must hit this tracepoint */ + TRACE_POSTGRESQL_LWLOCK_ACQUIRED(T_NAME(lock), mode, lock, + lock->tranche); return false; } else @@ -1239,6 +1242,9 @@ LWLockAcquire(LWLock *lock, LWLockMode mode) if (num_held_lwlocks >= MAX_SIMUL_LWLOCKS) elog(ERROR, "too many LWLocks taken"); + TRACE_POSTGRESQL_LWLOCK_ACQUIRE_START(T_NAME(lock), mode, lock, + lock->tranche); + /* * Lock out cancel/die interrupts until we exit the code section protected * by the LWLock. This ensures that interrupts will not interfere with @@ -1391,6 +1397,9 @@ LWLockConditionalAcquire(LWLock *lock, LWLockMode mode) if (num_held_lwlocks >= MAX_SIMUL_LWLOCKS) elog(ERROR, "too many LWLocks taken"); + TRACE_POSTGRESQL_LWLOCK_CONDACQUIRE_START(T_NAME(lock), mode, lock, + lock->tranche); + /* * Lock out cancel/die interrupts until we exit the code section protected * by the LWLock. This ensures that interrupts will not interfere with @@ -1455,6 +1464,9 @@ LWLockAcquireOrWait(LWLock *lock, LWLockMode mode) if (num_held_lwlocks >= MAX_SIMUL_LWLOCKS) elog(ERROR, "too many LWLocks taken"); + TRACE_POSTGRESQL_LWLOCK_ACQUIRE_OR_WAIT_START(T_NAME(lock), mode, lock, + lock->tranche); + /* * Lock out cancel/die interrupts until we exit the code section protected * by the LWLock. This ensures that interrupts will not interfere with @@ -1637,6 +1649,9 @@ LWLockWaitForVar(LWLock *lock, uint64 *valptr, uint64 oldval, uint64 *newval) PRINT_LWDEBUG("LWLockWaitForVar", lock, LW_WAIT_UNTIL_FREE); + TRACE_POSTGRESQL_LWLOCK_WAITFORVAR_START(T_NAME(lock), lock, + lock->tranche, valptr, oldval, *valptr); + /* * Lock out cancel/die interrupts while we sleep on the lock. There is no * cleanup mechanism to remove us from the wait queue if we got @@ -1747,6 +1762,9 @@ LWLockWaitForVar(LWLock *lock, uint64 *valptr, uint64 oldval, uint64 *newval) */ RESUME_INTERRUPTS(); + TRACE_POSTGRESQL_LWLOCK_WAITFORVAR_DONE(T_NAME(lock), lock, lock->tranche, + valptr, oldval, *newval, result); + return result; } @@ -1769,6 +1787,9 @@ LWLockUpdateVar(LWLock *lock, uint64 *valptr, uint64 val) PRINT_LWDEBUG("LWLockUpdateVar", lock, LW_EXCLUSIVE); + TRACE_POSTGRESQL_LWLOCK_UPDATEVAR_START(T_NAME(lock), lock, lock->tranche, valptr, + val); + proclist_init(&wakeup); LWLockWaitListLock(lock); @@ -1809,6 +1830,9 @@ LWLockUpdateVar(LWLock *lock, uint64 *valptr, uint64 val) waiter->lwWaiting = false; PGSemaphoreUnlock(waiter->sem); } + + TRACE_POSTGRESQL_LWLOCK_UPDATEVAR_DONE(T_NAME(lock), lock, lock->tranche, + valptr, val); } diff --git a/src/backend/utils/probes.d b/src/backend/utils/probes.d index 89805c3a89..a62fdf61df 100644 --- a/src/backend/utils/probes.d +++ b/src/backend/utils/probes.d @@ -29,14 +29,22 @@ provider postgresql { probe transaction__commit(LocalTransactionId); probe transaction__abort(LocalTransactionId); + probe lwlock__acquired(const char *, LWLockMode, LWLock*, int); + probe lwlock__acquire__start(const char *, LWLockMode, LWLock*, int); probe lwlock__acquire(const char *, LWLockMode, LWLock*, int); probe lwlock__release(const char *, LWLockMode, LWLock*, int); probe lwlock__wait__start(const char *, LWLockMode, LWLock*, int); probe lwlock__wait__done(const char *, LWLockMode, LWLock*, int); + probe lwlock__condacquire__start(const char *, LWLockMode, LWLock*, int); probe lwlock__condacquire(const char *, LWLockMode, LWLock*, int); probe lwlock__condacquire__fail(const char *, LWLockMode, LWLock*, int); + probe lwlock__acquire__or__wait__start(const char *, LWLockMode, LWLock*, int); probe lwlock__acquire__or__wait(const char *, LWLockMode, LWLock*, int); probe lwlock__acquire__or__wait__fail(const char *, LWLockMode, LWLock*, int); + probe lwlock__waitforvar__start(const char *, LWLock*, int, uint64, uint64, uint64); + probe lwlock__waitforvar__done(const char *, LWLock*, int, uint64, uint64, uint64, bool); + probe lwlock__updatevar__start(const char *, LWLock*, int, uint64, uint64); + probe lwlock__updatevar__done(const char *, LWLock*, int, uint64, uint64); probe lock__wait__start(unsigned int, unsigned int, unsigned int, unsigned int, unsigned int, LOCKMODE); -- 2.26.2