lwhistogram-v2.patch

diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 1dac695..fbe2b78 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -4183,6 +4183,8 @@ SubPostmasterMain(int argc, char *argv[])
 static void
 ExitPostmaster(int status)
 {
+	LWLockDumpHistograms();
+
 	/* should cleanup shared memory and kill all backends */
 
 	/*
diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c
index 4de6a72..a20638b 100644
--- a/src/backend/storage/buffer/bufmgr.c
+++ b/src/backend/storage/buffer/bufmgr.c
@@ -2436,7 +2436,7 @@ UnlockBuffers(void)
  * Acquire or release the content_lock for the buffer.
  */
 void
-LockBuffer(Buffer buffer, int mode)
+LockBufferReally(Buffer buffer, int mode, const char *file, int line)
 {
 	volatile BufferDesc *buf;
 
@@ -2449,9 +2449,9 @@ LockBuffer(Buffer buffer, int mode)
 	if (mode == BUFFER_LOCK_UNLOCK)
 		LWLockRelease(buf->content_lock);
 	else if (mode == BUFFER_LOCK_SHARE)
-		LWLockAcquire(buf->content_lock, LW_SHARED);
+		LWLockAcquireReally(buf->content_lock, LW_SHARED, file, line);
 	else if (mode == BUFFER_LOCK_EXCLUSIVE)
-		LWLockAcquire(buf->content_lock, LW_EXCLUSIVE);
+		LWLockAcquireReally(buf->content_lock, LW_EXCLUSIVE, file, line);
 	else
 		elog(ERROR, "unrecognized buffer lock mode: %d", mode);
 }
diff --git a/src/backend/storage/lmgr/lwlock.c b/src/backend/storage/lmgr/lwlock.c
index f152376..a469d8b 100644
--- a/src/backend/storage/lmgr/lwlock.c
+++ b/src/backend/storage/lmgr/lwlock.c
@@ -27,6 +27,7 @@
 #include "commands/async.h"
 #include "miscadmin.h"
 #include "pg_trace.h"
+#include "portability/instr_time.h"
 #include "storage/ipc.h"
 #include "storage/predicate.h"
 #include "storage/proc.h"
@@ -45,6 +46,9 @@ typedef struct LWLock
 	int			shared;			/* # of shared holders (0..MaxBackends) */
 	PGPROC	   *head;			/* head of list of waiting PGPROCs */
 	PGPROC	   *tail;			/* tail of list of waiting PGPROCs */
+	const char *file;			/* file of lock holder */
+	int			line;			/* line of lock holder */
+	uint64		histogram[33];	/* gigantic! */
 	/* tail is undefined when head is NULL */
 } LWLock;
 
@@ -60,7 +64,7 @@ typedef struct LWLock
  * LWLock is between 16 and 32 bytes on all known platforms, so these two
  * cases are sufficient.
  */
-#define LWLOCK_PADDED_SIZE	(sizeof(LWLock) <= 16 ? 16 : 32)
+#define LWLOCK_PADDED_SIZE	512
 
 typedef union LWLockPadded
 {
@@ -84,6 +88,8 @@ NON_EXEC_STATIC LWLockPadded *LWLockArray = NULL;
  */
 #define MAX_SIMUL_LWLOCKS	100
 
+#define LWLOCK_GRIPE_TIME 1000
+
 static int	num_held_lwlocks = 0;
 static LWLockId held_lwlocks[MAX_SIMUL_LWLOCKS];
 
@@ -336,14 +342,20 @@ LWLockAssign(void)
  * Side effect: cancel/die interrupts are held off until lock release.
  */
 void
-LWLockAcquire(LWLockId lockid, LWLockMode mode)
+LWLockAcquireReally(LWLockId lockid, LWLockMode mode, const char *file,
+					int line)
 {
 	volatile LWLock *lock = &(LWLockArray[lockid].lock);
 	PGPROC	   *proc = MyProc;
 	bool		retry = false;
 	int			extraWaits = 0;
+	instr_time	start_time;
+	const char *blocked_by_file = "_fail_";
+	int			blocked_by_line = 0;
+	int64		time_elapsed = 0;
 
 	PRINT_LWDEBUG("LWLockAcquire", lockid, lock);
+	INSTR_TIME_SET_ZERO(start_time);
 
 #ifdef LWLOCK_STATS
 	/* Set up local count state first time through in a given process */
@@ -407,20 +419,33 @@ LWLockAcquire(LWLockId lockid, LWLockMode mode)
 			if (lock->exclusive == 0 && lock->shared == 0)
 			{
 				lock->exclusive++;
+				lock->file = file;
+				lock->line = line;
 				mustwait = false;
 			}
 			else
+			{
 				mustwait = true;
+				blocked_by_file = lock->file;
+				blocked_by_line = lock->line;
+			}
 		}
 		else
 		{
 			if (lock->exclusive == 0)
 			{
 				lock->shared++;
+				lock->file = file;
+				lock->line = line;
 				mustwait = false;
 			}
 			else
+			{
 				mustwait = true;
+				blocked_by_file = lock->file;
+				blocked_by_line = lock->line;
+			}
+				
 		}
 
 		if (!mustwait)
@@ -462,6 +487,9 @@ LWLockAcquire(LWLockId lockid, LWLockMode mode)
 		 */
 		LOG_LWDEBUG("LWLockAcquire", lockid, "waiting");
 
+		if (INSTR_TIME_IS_ZERO(start_time))
+			INSTR_TIME_SET_CURRENT(start_time);
+
 #ifdef LWLOCK_STATS
 		block_counts[lockid]++;
 #endif
@@ -485,9 +513,29 @@ LWLockAcquire(LWLockId lockid, LWLockMode mode)
 		retry = true;
 	}
 
+	if (!INSTR_TIME_IS_ZERO(start_time))
+	{
+		instr_time	end_time;
+		int			f;
+
+		INSTR_TIME_SET_CURRENT(end_time);
+		INSTR_TIME_SUBTRACT(end_time, start_time);
+		time_elapsed = INSTR_TIME_GET_MICROSEC(end_time);
+		f = fls((int) time_elapsed);
+		lock->histogram[f]++;
+	}
+
 	/* We are done updating shared state of the lock itself. */
 	SpinLockRelease(&lock->mutex);
 
+	if (!INSTR_TIME_IS_ZERO(start_time))
+	{
+		if (time_elapsed >= LWLOCK_GRIPE_TIME)
+			elog(LOG, "lock %d: waited %.3f ms at %s:%d blocked by %s:%d",
+				 lockid, ((double) time_elapsed) / 1000.0,
+				 file, line, blocked_by_file, blocked_by_line);
+	}
+
 	TRACE_POSTGRESQL_LWLOCK_ACQUIRE(lockid, mode);
 
 	/* Add lock to list of locks held by this backend */
@@ -508,10 +556,13 @@ LWLockAcquire(LWLockId lockid, LWLockMode mode)
  * If successful, cancel/die interrupts are held off until lock release.
  */
 bool
-LWLockConditionalAcquire(LWLockId lockid, LWLockMode mode)
+LWLockConditionalAcquireReally(LWLockId lockid, LWLockMode mode,
+							   const char *file, int line)
 {
 	volatile LWLock *lock = &(LWLockArray[lockid].lock);
 	bool		mustwait;
+	const char *blocked_by_file;
+	int			blocked_by_line;
 
 	PRINT_LWDEBUG("LWLockConditionalAcquire", lockid, lock);
 
@@ -535,20 +586,32 @@ LWLockConditionalAcquire(LWLockId lockid, LWLockMode mode)
 		if (lock->exclusive == 0 && lock->shared == 0)
 		{
 			lock->exclusive++;
+			lock->file = file;
+			lock->line = line;
 			mustwait = false;
 		}
 		else
+		{
 			mustwait = true;
+			blocked_by_file = lock->file;
+			blocked_by_line = lock->line;
+		}
 	}
 	else
 	{
 		if (lock->exclusive == 0)
 		{
 			lock->shared++;
+			lock->file = file;
+			lock->line = line;
 			mustwait = false;
 		}
 		else
+		{
 			mustwait = true;
+			blocked_by_file = lock->file;
+			blocked_by_line = lock->line;
+		}
 	}
 
 	/* We are done updating shared state of the lock itself. */
@@ -586,12 +649,15 @@ LWLockConditionalAcquire(LWLockId lockid, LWLockMode mode)
  * wake up, observe that their records have already been flushed, and return.
  */
 bool
-LWLockAcquireOrWait(LWLockId lockid, LWLockMode mode)
+LWLockAcquireOrWaitReally(LWLockId lockid, LWLockMode mode,
+						  const char *file, int line)
 {
 	volatile LWLock *lock = &(LWLockArray[lockid].lock);
 	PGPROC	   *proc = MyProc;
 	bool		mustwait;
 	int			extraWaits = 0;
+	const char *blocked_by_file;
+	int			blocked_by_line;
 
 	PRINT_LWDEBUG("LWLockAcquireOrWait", lockid, lock);
 
@@ -621,24 +687,41 @@ LWLockAcquireOrWait(LWLockId lockid, LWLockMode mode)
 		if (lock->exclusive == 0 && lock->shared == 0)
 		{
 			lock->exclusive++;
+			lock->file = file;
+			lock->line = line;
 			mustwait = false;
 		}
 		else
+		{
 			mustwait = true;
+			blocked_by_file = lock->file;
+			blocked_by_line = lock->line;
+		}
 	}
 	else
 	{
 		if (lock->exclusive == 0)
 		{
 			lock->shared++;
+			lock->file = file;
+			lock->line = line;
 			mustwait = false;
 		}
 		else
+		{
 			mustwait = true;
+			blocked_by_file = lock->file;
+			blocked_by_line = lock->line;
+		}
 	}
 
 	if (mustwait)
 	{
+		instr_time	start_time;
+		instr_time	end_time;
+		int64		time_elapsed;
+		int			f;
+
 		/*
 		 * Add myself to wait queue.
 		 *
@@ -667,6 +750,8 @@ LWLockAcquireOrWait(LWLockId lockid, LWLockMode mode)
 		 */
 		LOG_LWDEBUG("LWLockAcquireOrWait", lockid, "waiting");
 
+		INSTR_TIME_SET_CURRENT(start_time);
+
 #ifdef LWLOCK_STATS
 		block_counts[lockid]++;
 #endif
@@ -682,6 +767,19 @@ LWLockAcquireOrWait(LWLockId lockid, LWLockMode mode)
 			extraWaits++;
 		}
 
+		INSTR_TIME_SET_CURRENT(end_time);
+		INSTR_TIME_SUBTRACT(end_time, start_time);
+		time_elapsed = INSTR_TIME_GET_MICROSEC(end_time);
+		f = fls((int) time_elapsed);
+		SpinLockAcquire(&lock->mutex);
+		lock->histogram[f]++;
+		SpinLockRelease(&lock->mutex);
+
+		if (time_elapsed >= LWLOCK_GRIPE_TIME)
+			elog(LOG, "lock %d: waited %.3f ms at %s:%d blocked by %s:%d",
+				 lockid, ((double) time_elapsed) / 1000.0,
+				 file, line, blocked_by_file, blocked_by_line);
+
 		TRACE_POSTGRESQL_LWLOCK_WAIT_DONE(lockid, mode);
 
 		LOG_LWDEBUG("LWLockAcquireOrWait", lockid, "awakened");
@@ -878,3 +976,37 @@ LWLockHeldByMe(LWLockId lockid)
 	}
 	return false;
 }
+
+void
+LWLockDumpHistograms(void)
+{
+	int			i;
+	int			k;
+	char		buffer[2048];
+	char	   *s;
+	int		   *LWLockCounter = (int *) ((char *) LWLockArray - 2 * sizeof(int));
+	int			numLocks = LWLockCounter[1];
+
+	for (i = 0; i < numLocks; i++)
+	{
+		volatile LWLock *lock = &(LWLockArray[i].lock);
+		buffer[0] = '\0';
+		s = buffer;
+
+		for (k = 0; k < 32; ++k)
+		{
+			if (!lock->histogram[k])
+				continue;
+			if (s != buffer)
+			{
+				*s++ = ',';
+				*s++ = ' ';
+			}
+			sprintf(s, "%d:%llu", k,
+				(long long unsigned) lock->histogram[k]);
+			s += strlen(s);
+		}
+		if (s != buffer)
+			elog(LOG, "lock %d: %s", i, buffer);
+	}
+}
diff --git a/src/include/storage/bufmgr.h b/src/include/storage/bufmgr.h
index d72bad9..21f1fa8 100644
--- a/src/include/storage/bufmgr.h
+++ b/src/include/storage/bufmgr.h
@@ -204,8 +204,12 @@ extern void BufferGetTag(Buffer buffer, RelFileNode *rnode,
 
 extern void SetBufferCommitInfoNeedsSave(Buffer buffer);
 
+#define LockBuffer(b, m) \
+	LockBufferReally(b, m, __FILE__, __LINE__)
+
 extern void UnlockBuffers(void);
-extern void LockBuffer(Buffer buffer, int mode);
+extern void LockBufferReally(Buffer buffer, int mode, const char *file,
+	int line);
 extern bool ConditionalLockBuffer(Buffer buffer);
 extern void LockBufferForCleanup(Buffer buffer);
 extern bool ConditionalLockBufferForCleanup(Buffer buffer);
diff --git a/src/include/storage/lwlock.h b/src/include/storage/lwlock.h
index 57a4f66..db9dfa5 100644
--- a/src/include/storage/lwlock.h
+++ b/src/include/storage/lwlock.h
@@ -106,9 +106,20 @@ extern bool Trace_lwlocks;
 #endif
 
 extern LWLockId LWLockAssign(void);
-extern void LWLockAcquire(LWLockId lockid, LWLockMode mode);
-extern bool LWLockConditionalAcquire(LWLockId lockid, LWLockMode mode);
-extern bool LWLockAcquireOrWait(LWLockId lockid, LWLockMode mode);
+
+#define LWLockAcquire(l, m) \
+	LWLockAcquireReally(l, m, __FILE__, __LINE__)
+#define LWLockConditionalAcquire(l, m) \
+	LWLockConditionalAcquireReally(l, m, __FILE__, __LINE__)
+#define LWLockAcquireOrWait(l, m) \
+	LWLockAcquireOrWaitReally(l, m, __FILE__, __LINE__)
+
+extern void LWLockAcquireReally(LWLockId lockid, LWLockMode mode,
+	const char *file, int line);
+extern bool LWLockConditionalAcquireReally(LWLockId lockid, LWLockMode mode,
+	const char *file, int line);
+extern bool LWLockAcquireOrWaitReally(LWLockId lockid, LWLockMode mode,
+	const char *file, int line);
 extern void LWLockRelease(LWLockId lockid);
 extern void LWLockReleaseAll(void);
 extern bool LWLockHeldByMe(LWLockId lockid);
@@ -118,5 +129,6 @@ extern Size LWLockShmemSize(void);
 extern void CreateLWLocks(void);
 
 extern void RequestAddinLWLocks(int n);
+extern void LWLockDumpHistograms(void);
 
 #endif   /* LWLOCK_H */