From af1b0ebcce96c2a81b4a7d88e71ac719477440a8 Mon Sep 17 00:00:00 2001 From: Craig Ringer Date: Thu, 19 Nov 2020 18:05:39 +0800 Subject: [PATCH 2/4] 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 5c8744d316..4c65a30c76 100644 --- a/src/backend/storage/lmgr/lwlock.c +++ b/src/backend/storage/lmgr/lwlock.c @@ -874,6 +874,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 @@ -1237,6 +1240,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 @@ -1389,6 +1395,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 @@ -1453,6 +1462,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 @@ -1635,6 +1647,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 @@ -1745,6 +1760,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; } @@ -1767,6 +1785,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); @@ -1807,6 +1828,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 363839f85d..608a89af91 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.29.2