freelist_wait_stats.v2.patch

diff --git a/src/backend/storage/buffer/freelist.c b/src/backend/storage/buffer/freelist.c
index 3e62448..36b0160 100644
--- a/src/backend/storage/buffer/freelist.c
+++ b/src/backend/storage/buffer/freelist.c
@@ -17,6 +17,7 @@
 
 #include "storage/buf_internals.h"
 #include "storage/bufmgr.h"
+#include "utils/timestamp.h"
 
 
 /*
@@ -41,6 +42,21 @@ typedef struct
 	 */
 	uint32		completePasses; /* Complete cycles of the clock sweep */
 	uint32		numBufferAllocs;	/* Buffers allocated since last reset */
+
+	/*
+	 * Wait Statistics
+	 */
+	long	waitBufferAllocSecs;
+	int		waitBufferAllocUSecs;
+	int		waitBufferAlloc;
+
+	long	waitBufferFreeSecs;
+	int		waitBufferFreeUSecs;
+	int		waitBufferFree;
+
+	long	waitSyncStartSecs;
+	int		waitSyncStartUSecs;
+	int		waitSyncStart;
 } BufferStrategyControl;
 
 /* Pointers to shared state */
@@ -125,7 +141,29 @@ StrategyGetBuffer(BufferAccessStrategy strategy, bool *lock_held)
 
 	/* Nope, so lock the freelist */
 	*lock_held = true;
-	LWLockAcquire(BufFreelistLock, LW_EXCLUSIVE);
+	if (!LWLockConditionalAcquire(BufFreelistLock, LW_EXCLUSIVE))
+	{
+		TimestampTz waitStart = GetCurrentTimestamp();
+		TimestampTz waitEnd;
+		long		wait_secs;
+		int			wait_usecs;
+
+		LWLockAcquire(BufFreelistLock, LW_EXCLUSIVE);
+
+		waitEnd = GetCurrentTimestamp();
+
+		TimestampDifference(waitStart, waitEnd,
+						&wait_secs, &wait_usecs);
+
+		StrategyControl->waitBufferAllocSecs += wait_secs;
+		StrategyControl->waitBufferAllocUSecs += wait_usecs;
+		if (StrategyControl->waitBufferAllocUSecs > 1000000)
+		{
+			StrategyControl->waitBufferAllocUSecs -= 1000000;
+			StrategyControl->waitBufferAllocSecs += 1;
+		}
+		StrategyControl->waitBufferAlloc++;
+	}
 
 	/*
 	 * We count buffer allocation requests so that the bgwriter can estimate
@@ -223,7 +261,29 @@ StrategyGetBuffer(BufferAccessStrategy strategy, bool *lock_held)
 void
 StrategyFreeBuffer(volatile BufferDesc *buf)
 {
-	LWLockAcquire(BufFreelistLock, LW_EXCLUSIVE);
+	if (!LWLockConditionalAcquire(BufFreelistLock, LW_EXCLUSIVE))
+	{
+		TimestampTz waitStart = GetCurrentTimestamp();
+		TimestampTz waitEnd;
+		long		wait_secs;
+		int			wait_usecs;
+
+		LWLockAcquire(BufFreelistLock, LW_EXCLUSIVE);
+
+		waitEnd = GetCurrentTimestamp();
+
+		TimestampDifference(waitStart, waitEnd,
+						&wait_secs, &wait_usecs);
+
+		StrategyControl->waitBufferFreeSecs += wait_secs;
+		StrategyControl->waitBufferFreeUSecs += wait_usecs;
+		if (StrategyControl->waitBufferFreeUSecs > 1000000)
+		{
+			StrategyControl->waitBufferFreeUSecs -= 1000000;
+			StrategyControl->waitBufferFreeSecs += 1;
+		}
+		StrategyControl->waitBufferFree++;
+	}
 
 	/*
 	 * It is possible that we are told to put something in the freelist that
@@ -256,7 +316,30 @@ StrategySyncStart(uint32 *complete_passes, uint32 *num_buf_alloc)
 {
 	int			result;
 
-	LWLockAcquire(BufFreelistLock, LW_EXCLUSIVE);
+	if (!LWLockConditionalAcquire(BufFreelistLock, LW_EXCLUSIVE))
+	{
+		TimestampTz waitStart = GetCurrentTimestamp();
+		TimestampTz waitEnd;
+		long		wait_secs;
+		int			wait_usecs;
+
+		LWLockAcquire(BufFreelistLock, LW_EXCLUSIVE);
+
+		waitEnd = GetCurrentTimestamp();
+
+		TimestampDifference(waitStart, waitEnd,
+						&wait_secs, &wait_usecs);
+
+		StrategyControl->waitSyncStartSecs += wait_secs;
+		StrategyControl->waitSyncStartUSecs += wait_usecs;
+		if (StrategyControl->waitSyncStartUSecs > 1000000)
+		{
+			StrategyControl->waitSyncStartUSecs -= 1000000;
+			StrategyControl->waitSyncStartSecs += 1;
+		}
+		StrategyControl->waitSyncStart++;
+	}
+
 	result = StrategyControl->nextVictimBuffer;
 	if (complete_passes)
 		*complete_passes = StrategyControl->completePasses;
@@ -265,7 +348,59 @@ StrategySyncStart(uint32 *complete_passes, uint32 *num_buf_alloc)
 		*num_buf_alloc = StrategyControl->numBufferAllocs;
 		StrategyControl->numBufferAllocs = 0;
 	}
+	else
+	{
+		long	waitBufferAllocSecs;
+		int		waitBufferAllocUSecs;
+		int		waitBufferAlloc;
+
+		long	waitBufferFreeSecs;
+		int		waitBufferFreeUSecs;
+		int		waitBufferFree;
+
+		long	waitSyncStartSecs;
+		int		waitSyncStartUSecs;
+		int		waitSyncStart;
+
+		waitBufferAllocSecs = StrategyControl->waitBufferAllocSecs;
+		waitBufferAllocUSecs = StrategyControl->waitBufferAllocUSecs;
+		waitBufferAlloc = StrategyControl->waitBufferAlloc;
+
+		waitBufferFreeSecs = StrategyControl->waitBufferFreeSecs;
+		waitBufferFreeUSecs = StrategyControl->waitBufferFreeUSecs;
+		waitBufferFree = StrategyControl->waitBufferFree;
+
+		waitSyncStartSecs = StrategyControl->waitSyncStartSecs;
+		waitSyncStartUSecs = StrategyControl->waitSyncStartUSecs;
+		waitSyncStart = StrategyControl->waitSyncStart;
+
+		StrategyControl->waitBufferAllocSecs = 0;
+		StrategyControl->waitBufferAllocUSecs = 0;
+		StrategyControl->waitBufferAlloc = 0;
+
+		StrategyControl->waitBufferFreeSecs = 0;
+		StrategyControl->waitBufferFreeUSecs = 0;
+		StrategyControl->waitBufferFree = 0;
+
+		StrategyControl->waitSyncStartSecs = 0;
+		StrategyControl->waitSyncStartUSecs = 0;
+		StrategyControl->waitSyncStart = 0;
+
+		LWLockRelease(BufFreelistLock);
+
+		elog(LOG, "BufFreelistLock stats: "
+			 "BufferAlloc waits %d total wait time=%ld.%03d s; "
+			 "BufferFree waits %d total wait time=%ld.%03d s; "
+			 "SyncStart waits %d total wait time=%ld.%03d s; ",
+			waitBufferAlloc, waitBufferAllocSecs, waitBufferAllocUSecs,
+			waitBufferFree, waitBufferFreeSecs, waitBufferFreeUSecs,
+			waitSyncStart, waitSyncStartSecs, waitSyncStartUSecs);
+
+		return result;
+	}
+
 	LWLockRelease(BufFreelistLock);
+
 	return result;
 }