From 942e36fb368352f2a3c9c93f7f191ec5d5ef5bf7 Mon Sep 17 00:00:00 2001
From: Craig Ringer <craig.ringer@2ndquadrant.com>
Date: Thu, 19 Nov 2020 18:05:39 +0800
Subject: [PATCH v1 3/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 63f1a619b0..cfdfa7f328 100644
--- a/src/backend/storage/lmgr/lwlock.c
+++ b/src/backend/storage/lmgr/lwlock.c
@@ -875,6 +875,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
@@ -1238,6 +1241,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
@@ -1390,6 +1396,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
@@ -1454,6 +1463,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
@@ -1636,6 +1648,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
@@ -1746,6 +1761,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;
 }
 
@@ -1768,6 +1786,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);
@@ -1808,6 +1829,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.29.2

