Additional LWLOCK_STATS statistics

*** /tmp/K1hW5V_lwlock.c	2015-09-16 09:53:26.682803203 -0400
--- src/backend/storage/lmgr/lwlock.c	2015-09-16 08:59:11.232712749 -0400
***************
*** 92,97 ****
--- 92,98 ----
  #include "utils/memutils.h"
  
  #ifdef LWLOCK_STATS
+ #include <sys/time.h>
  #include "utils/hsearch.h"
  #endif
  
***************
*** 163,176 ****
--- 164,190 ----
  {
  	lwlock_stats_key key;
  	int			sh_acquire_count;
+ 	int			sh_acquire_max;
  	int			ex_acquire_count;
+ 	int			ex_acquire_max;
  	int			block_count;
+ 	double      block_time;
+ 	double      timestamp;
  	int			dequeue_self_count;
  	int			spin_delay_count;
+ 	int			max_waiters;
  }	lwlock_stats;
  
  static HTAB *lwlock_stats_htab;
  static lwlock_stats lwlock_stats_dummy;
+ 
+ static double
+ GetTimeInMillis()
+ {
+ 	struct timeval t;
+ 	gettimeofday(&t, NULL);
+ 	return (t.tv_sec + (t.tv_usec / 1000000.0)) * 1000.0;
+ }
  #endif
  
  #ifdef LOCK_DEBUG
***************
*** 297,308 ****
  
  	while ((lwstats = (lwlock_stats *) hash_seq_search(&scan)) != NULL)
  	{
! 		fprintf(stderr,
! 				"PID %d lwlock %s %d: shacq %u exacq %u blk %u spindelay %u dequeue self %u\n",
! 				MyProcPid, LWLockTrancheArray[lwstats->key.tranche]->name,
! 				lwstats->key.instance, lwstats->sh_acquire_count,
! 				lwstats->ex_acquire_count, lwstats->block_count,
! 				lwstats->spin_delay_count, lwstats->dequeue_self_count);
  	}
  
  	LWLockRelease(&MainLWLockArray[0].lock);
--- 311,332 ----
  
  	while ((lwstats = (lwlock_stats *) hash_seq_search(&scan)) != NULL)
  	{
! 		if (lwstats->key.tranche == 0 && lwstats->key.instance < NUM_INDIVIDUAL_LWLOCKS)
! 			fprintf(stderr,
! 					"PID %d lwlock %s: shacq %u shmax %u exacq %u exmax %u blk %u blktime %u spindelay %u dequeue self %u maxw %u\n",
! 					MyProcPid, MainLWLockNames[lwstats->key.instance],
! 					lwstats->sh_acquire_count, lwstats->sh_acquire_max,
! 					lwstats->ex_acquire_count, lwstats->ex_acquire_max,
! 					lwstats->block_count, (unsigned int)lwstats->block_time, lwstats->spin_delay_count, lwstats->dequeue_self_count,
! 					lwstats->max_waiters);
! 		else
! 			fprintf(stderr,
! 					"PID %d lwlock %s %d: shacq %u shmax %u exacq %u exmax %u blk %u blktime %u spindelay %u dequeue self %u maxw %u\n",
! 					MyProcPid, LWLockTrancheArray[lwstats->key.tranche]->name,
! 					lwstats->key.instance, lwstats->sh_acquire_count, lwstats->sh_acquire_max,
! 					lwstats->ex_acquire_count, lwstats->ex_acquire_max,
! 					lwstats->block_count, (unsigned int)lwstats->block_time, lwstats->spin_delay_count, lwstats->dequeue_self_count,
! 					lwstats->max_waiters);
  	}
  
  	LWLockRelease(&MainLWLockArray[0].lock);
***************
*** 330,339 ****
--- 354,368 ----
  	if (!found)
  	{
  		lwstats->sh_acquire_count = 0;
+ 		lwstats->sh_acquire_max = 0;
  		lwstats->ex_acquire_count = 0;
+ 		lwstats->ex_acquire_max = 0;
  		lwstats->block_count = 0;
+ 		lwstats->block_time = 0.0;
+ 		lwstats->timestamp = 0.0;
  		lwstats->dequeue_self_count = 0;
  		lwstats->spin_delay_count = 0;
+ 		lwstats->max_waiters = 0;
  	}
  	return lwstats;
  }
***************
*** 774,779 ****
--- 803,811 ----
  LWLockQueueSelf(LWLock *lock, LWLockMode mode)
  {
  #ifdef LWLOCK_STATS
+ 	bool include;
+ 	int counter, size;
+ 	dlist_iter iter;
  	lwlock_stats *lwstats;
  
  	lwstats = get_lwlock_stats_entry(lock);
***************
*** 791,797 ****
--- 823,870 ----
  		elog(PANIC, "queueing for lock while waiting on another one");
  
  #ifdef LWLOCK_STATS
+ 	lwstats->timestamp = GetTimeInMillis();
  	lwstats->spin_delay_count += SpinLockAcquire(&lock->mutex);
+ 
+ 	/*
+ 	 * We scan the list of waiters from the back in order to find
+ 	 * out how many of the same lock type are waiting for a lock.
+ 	 * Similar types have the potential to be groupped together.
+ 	 *
+ 	 * We also count the number of waiters, including ourself.
+ 	 */
+ 	include = true;
+ 	size = 1;
+ 	counter = 1;
+ 
+ 	dlist_reverse_foreach(iter, &lock->waiters)
+ 	{
+ 		if (include)
+ 		{
+ 			PGPROC	   *waiter = dlist_container(PGPROC, lwWaitLink, iter.cur);
+ 
+ 			if (waiter->lwWaitMode == mode)
+ 				counter += 1;
+ 			else
+ 				include = false;
+ 		}
+ 		
+ 		size += 1;
+ 	}
+ 
+ 	if (mode == LW_EXCLUSIVE || mode == LW_WAIT_UNTIL_FREE)
+ 	{
+ 		if (counter > lwstats->ex_acquire_max)
+ 			lwstats->ex_acquire_max = counter;
+ 	}
+ 	else if (mode == LW_SHARED)
+ 	{
+ 		if (counter > lwstats->sh_acquire_max)
+ 			lwstats->sh_acquire_max = counter;
+ 	}
+ 
+ 	if (size > lwstats->max_waiters)
+ 		lwstats->max_waiters = size;
  #else
  	SpinLockAcquire(&lock->mutex);
  #endif
***************
*** 943,951 ****
--- 1016,1032 ----
  #ifdef LWLOCK_STATS
  	/* Count lock acquisition attempts */
  	if (mode == LW_EXCLUSIVE)
+ 	{
  		lwstats->ex_acquire_count++;
+ 		if (lwstats->ex_acquire_max == 0)
+ 			lwstats->ex_acquire_max = 1;
+ 	}
  	else
+ 	{
  		lwstats->sh_acquire_count++;
+ 		if (lwstats->sh_acquire_max == 0)
+ 			lwstats->sh_acquire_max = 1;
+ 	}
  #endif   /* LWLOCK_STATS */
  
  	/*
***************
*** 1021,1026 ****
--- 1102,1110 ----
  			LOG_LWDEBUG("LWLockAcquire", lock, "acquired, undoing queue");
  
  			LWLockDequeueSelf(lock);
+ #ifdef LWLOCK_STATS
+ 			lwstats->block_time += (GetTimeInMillis() - lwstats->timestamp);
+ #endif
  			break;
  		}
  
***************
*** 1068,1073 ****
--- 1152,1160 ----
  
  		LOG_LWDEBUG("LWLockAcquire", lock, "awakened");
  
+ #ifdef LWLOCK_STATS
+ 		lwstats->block_time += (GetTimeInMillis() - lwstats->timestamp);
+ #endif
  		/* Now loop back and try to acquire lock again. */
  		result = false;
  	}

*** /tmp/NTwtmh_lwlock.c	2015-09-16 10:34:02.955957192 -0400
--- src/backend/storage/lmgr/lwlock.c	2015-09-16 10:32:18.088843413 -0400
***************
*** 163,172 ****
--- 163,175 ----
  {
  	lwlock_stats_key key;
  	int			sh_acquire_count;
+ 	int			sh_acquire_max;
  	int			ex_acquire_count;
+ 	int			ex_acquire_max;
  	int			block_count;
  	int			dequeue_self_count;
  	int			spin_delay_count;
+ 	int			max_waiters;
  }	lwlock_stats;
  
  static HTAB *lwlock_stats_htab;
***************
*** 297,308 ****
  
  	while ((lwstats = (lwlock_stats *) hash_seq_search(&scan)) != NULL)
  	{
! 		fprintf(stderr,
! 				"PID %d lwlock %s %d: shacq %u exacq %u blk %u spindelay %u dequeue self %u\n",
! 				MyProcPid, LWLockTrancheArray[lwstats->key.tranche]->name,
! 				lwstats->key.instance, lwstats->sh_acquire_count,
! 				lwstats->ex_acquire_count, lwstats->block_count,
! 				lwstats->spin_delay_count, lwstats->dequeue_self_count);
  	}
  
  	LWLockRelease(&MainLWLockArray[0].lock);
--- 300,325 ----
  
  	while ((lwstats = (lwlock_stats *) hash_seq_search(&scan)) != NULL)
  	{
! 		if (lwstats->key.tranche == 0 && lwstats->key.instance < NUM_INDIVIDUAL_LWLOCKS)
! 		{
! 			/* We ignore information from MainLWLockArray[0] since it isn't in real use */
! 			if (lwstats->key.instance != 0)
! 				fprintf(stderr,
! 						"PID %d lwlock %s: shacq %u shmax %u exacq %u exmax %u blk %u spindelay %u dequeue self %u maxw %u\n",
! 						MyProcPid, MainLWLockNames[lwstats->key.instance],
! 						lwstats->sh_acquire_count, lwstats->sh_acquire_max,
! 						lwstats->ex_acquire_count, lwstats->ex_acquire_max,
! 						lwstats->block_count, lwstats->spin_delay_count, lwstats->dequeue_self_count,
! 						lwstats->max_waiters);
! 		}
! 		else
! 			fprintf(stderr,
! 					"PID %d lwlock %s %d: shacq %u shmax %u exacq %u exmax %u blk %u spindelay %u dequeue self %u maxw %u\n",
! 					MyProcPid, LWLockTrancheArray[lwstats->key.tranche]->name,
! 					lwstats->key.instance, lwstats->sh_acquire_count, lwstats->sh_acquire_max,
! 					lwstats->ex_acquire_count, lwstats->ex_acquire_max,
! 					lwstats->block_count, lwstats->spin_delay_count, lwstats->dequeue_self_count,
! 					lwstats->max_waiters);
  	}
  
  	LWLockRelease(&MainLWLockArray[0].lock);
***************
*** 330,339 ****
--- 347,359 ----
  	if (!found)
  	{
  		lwstats->sh_acquire_count = 0;
+ 		lwstats->sh_acquire_max = 0;
  		lwstats->ex_acquire_count = 0;
+ 		lwstats->ex_acquire_max = 0;
  		lwstats->block_count = 0;
  		lwstats->dequeue_self_count = 0;
  		lwstats->spin_delay_count = 0;
+ 		lwstats->max_waiters = 0;
  	}
  	return lwstats;
  }
***************
*** 774,779 ****
--- 794,802 ----
  LWLockQueueSelf(LWLock *lock, LWLockMode mode)
  {
  #ifdef LWLOCK_STATS
+ 	bool include;
+ 	int counter, size;
+ 	dlist_iter iter;
  	lwlock_stats *lwstats;
  
  	lwstats = get_lwlock_stats_entry(lock);
***************
*** 792,797 ****
--- 815,860 ----
  
  #ifdef LWLOCK_STATS
  	lwstats->spin_delay_count += SpinLockAcquire(&lock->mutex);
+ 
+ 	/*
+ 	 * We scan the list of waiters from the back in order to find
+ 	 * out how many of the same lock type are waiting for a lock.
+ 	 * Similar types have the potential to be groupped together.
+ 	 *
+ 	 * We also count the number of waiters, including ourself.
+ 	 */
+ 	include = true;
+ 	size = 1;
+ 	counter = 1;
+ 
+ 	dlist_reverse_foreach(iter, &lock->waiters)
+ 	{
+ 		if (include)
+ 		{
+ 			PGPROC	   *waiter = dlist_container(PGPROC, lwWaitLink, iter.cur);
+ 
+ 			if (waiter->lwWaitMode == mode)
+ 				counter += 1;
+ 			else
+ 				include = false;
+ 		}
+ 		
+ 		size += 1;
+ 	}
+ 
+ 	if (mode == LW_EXCLUSIVE || mode == LW_WAIT_UNTIL_FREE)
+ 	{
+ 		if (counter > lwstats->ex_acquire_max)
+ 			lwstats->ex_acquire_max = counter;
+ 	}
+ 	else if (mode == LW_SHARED)
+ 	{
+ 		if (counter > lwstats->sh_acquire_max)
+ 			lwstats->sh_acquire_max = counter;
+ 	}
+ 
+ 	if (size > lwstats->max_waiters)
+ 		lwstats->max_waiters = size;
  #else
  	SpinLockAcquire(&lock->mutex);
  #endif
***************
*** 943,951 ****
--- 1006,1022 ----
  #ifdef LWLOCK_STATS
  	/* Count lock acquisition attempts */
  	if (mode == LW_EXCLUSIVE)
+ 	{
  		lwstats->ex_acquire_count++;
+ 		if (lwstats->ex_acquire_max == 0)
+ 			lwstats->ex_acquire_max = 1;
+ 	}
  	else
+ 	{
  		lwstats->sh_acquire_count++;
+ 		if (lwstats->sh_acquire_max == 0)
+ 			lwstats->sh_acquire_max = 1;
+ 	}
  #endif   /* LWLOCK_STATS */
  
  	/*

>From 6f03263910713b66af548b86389ce842cb048caa Mon Sep 17 00:00:00 2001
From: Jesper Pedersen <jesper.pedersen@redhat.com>
Date: Fri, 11 Dec 2015 05:52:29 -0500
Subject: [PATCH] Additional LWLOCK_STATS statistics

---
 src/backend/storage/lmgr/lwlock.c | 83 ++++++++++++++++++++++++++++++++++++---
 1 file changed, 77 insertions(+), 6 deletions(-)

diff --git a/src/backend/storage/lmgr/lwlock.c b/src/backend/storage/lmgr/lwlock.c
index d43fb61..50d8465 100644
--- a/src/backend/storage/lmgr/lwlock.c
+++ b/src/backend/storage/lmgr/lwlock.c
@@ -158,10 +158,13 @@ typedef struct lwlock_stats
 {
 	lwlock_stats_key key;
 	int			sh_acquire_count;
+	int			sh_acquire_max;
 	int			ex_acquire_count;
+	int			ex_acquire_max;
 	int			block_count;
 	int			dequeue_self_count;
 	int			spin_delay_count;
+	int			max_waiters;
 }	lwlock_stats;
 
 static HTAB *lwlock_stats_htab;
@@ -292,12 +295,26 @@ print_lwlock_stats(int code, Datum arg)
 
 	while ((lwstats = (lwlock_stats *) hash_seq_search(&scan)) != NULL)
 	{
-		fprintf(stderr,
-				"PID %d lwlock %s %d: shacq %u exacq %u blk %u spindelay %u dequeue self %u\n",
-				MyProcPid, LWLockTrancheArray[lwstats->key.tranche]->name,
-				lwstats->key.instance, lwstats->sh_acquire_count,
-				lwstats->ex_acquire_count, lwstats->block_count,
-				lwstats->spin_delay_count, lwstats->dequeue_self_count);
+		if (lwstats->key.tranche == 0 && lwstats->key.instance < NUM_INDIVIDUAL_LWLOCKS)
+		{
+			/* We ignore information from MainLWLockArray[0] since it isn't in real use */
+			if (lwstats->key.instance != 0)
+				fprintf(stderr,
+						"PID %d lwlock %s: shacq %u shmax %u exacq %u exmax %u blk %u spindelay %u dequeue self %u maxw %u\n",
+						MyProcPid, MainLWLockNames[lwstats->key.instance],
+						lwstats->sh_acquire_count, lwstats->sh_acquire_max,
+						lwstats->ex_acquire_count, lwstats->ex_acquire_max,
+						lwstats->block_count, lwstats->spin_delay_count, lwstats->dequeue_self_count,
+						lwstats->max_waiters);
+		}
+		else
+			fprintf(stderr,
+					"PID %d lwlock %s %d: shacq %u shmax %u exacq %u exmax %u blk %u spindelay %u dequeue self %u maxw %u\n",
+					MyProcPid, LWLockTrancheArray[lwstats->key.tranche]->name,
+					lwstats->key.instance, lwstats->sh_acquire_count, lwstats->sh_acquire_max,
+					lwstats->ex_acquire_count, lwstats->ex_acquire_max,
+					lwstats->block_count, lwstats->spin_delay_count, lwstats->dequeue_self_count,
+					lwstats->max_waiters);
 	}
 
 	LWLockRelease(&MainLWLockArray[0].lock);
@@ -325,10 +342,13 @@ get_lwlock_stats_entry(LWLock *lock)
 	if (!found)
 	{
 		lwstats->sh_acquire_count = 0;
+		lwstats->sh_acquire_max = 0;
 		lwstats->ex_acquire_count = 0;
+		lwstats->ex_acquire_max = 0;
 		lwstats->block_count = 0;
 		lwstats->dequeue_self_count = 0;
 		lwstats->spin_delay_count = 0;
+		lwstats->max_waiters = 0;
 	}
 	return lwstats;
 }
@@ -753,6 +773,9 @@ static void
 LWLockQueueSelf(LWLock *lock, LWLockMode mode)
 {
 #ifdef LWLOCK_STATS
+	bool include;
+	int counter, size;
+	dlist_iter iter;
 	lwlock_stats *lwstats;
 
 	lwstats = get_lwlock_stats_entry(lock);
@@ -771,6 +794,46 @@ LWLockQueueSelf(LWLock *lock, LWLockMode mode)
 
 #ifdef LWLOCK_STATS
 	lwstats->spin_delay_count += SpinLockAcquire(&lock->mutex);
+
+	/*
+	 * We scan the list of waiters from the back in order to find
+	 * out how many of the same lock type are waiting for a lock.
+	 * Similar types have the potential to be groupped together.
+	 *
+	 * We also count the number of waiters, including ourself.
+	 */
+	include = true;
+	size = 1;
+	counter = 1;
+
+	dlist_reverse_foreach(iter, &lock->waiters)
+	{
+		if (include)
+		{
+			PGPROC	   *waiter = dlist_container(PGPROC, lwWaitLink, iter.cur);
+
+			if (waiter->lwWaitMode == mode)
+				counter += 1;
+			else
+				include = false;
+		}
+		
+		size += 1;
+	}
+
+	if (mode == LW_EXCLUSIVE || mode == LW_WAIT_UNTIL_FREE)
+	{
+		if (counter > lwstats->ex_acquire_max)
+			lwstats->ex_acquire_max = counter;
+	}
+	else if (mode == LW_SHARED)
+	{
+		if (counter > lwstats->sh_acquire_max)
+			lwstats->sh_acquire_max = counter;
+	}
+
+	if (size > lwstats->max_waiters)
+		lwstats->max_waiters = size;
 #else
 	SpinLockAcquire(&lock->mutex);
 #endif
@@ -922,9 +985,17 @@ LWLockAcquire(LWLock *lock, LWLockMode mode)
 #ifdef LWLOCK_STATS
 	/* Count lock acquisition attempts */
 	if (mode == LW_EXCLUSIVE)
+	{
 		lwstats->ex_acquire_count++;
+		if (lwstats->ex_acquire_max == 0)
+			lwstats->ex_acquire_max = 1;
+	}
 	else
+	{
 		lwstats->sh_acquire_count++;
+		if (lwstats->sh_acquire_max == 0)
+			lwstats->sh_acquire_max = 1;
+	}
 #endif   /* LWLOCK_STATS */
 
 	/*
-- 
2.1.0