lwlock_instrumentation.patch

diff --git a/src/backend/storage/lmgr/lwlock.c b/src/backend/storage/lmgr/lwlock.c
index f2ccbe1..729c6d8 100644
*** a/src/backend/storage/lmgr/lwlock.c
--- b/src/backend/storage/lmgr/lwlock.c
***************
*** 29,34 ****
--- 29,55 ----
  #include "storage/ipc.h"
  #include "storage/proc.h"
  #include "storage/spin.h"
+ #include "portability/instr_time.h"
+ 
+ /* displays counters (number of lock acquires, etc)
+  * on process exit */
+ #define LWLOCK_STATS
+ 
+ #ifdef LWLOCK_STATS
+ 
+ /* also displays cumulative timings of time spent
+  * waiting and holding locks
+  * (depends on LWLOCK_STATS)
+  */
+ #define LWLOCK_TIMING_STATS
+ 
+ /* displays only locks which were waited on more than
+  * this amount of seconds (set to 0 to display all)
+  * (depends on LWLOCK_TIMING_STATS)
+  */
+ #define LWLOCKS_STATS_TIME_DISPLAY_THRESHOLD 0.1
+ #endif /* LWLOCK_STATS */
+ 
  
  
  /* We use the ShmemLock spinlock to protect LWLockAssign */
*************** static LWLockId held_lwlocks[MAX_SIMUL_L
*** 88,100 ****
  static int	lock_addin_request = 0;
  static bool lock_addin_request_allowed = true;
  
- #ifdef LWLOCK_STATS
- static int	counts_for_pid = 0;
- static int *sh_acquire_counts;
- static int *ex_acquire_counts;
- static int *block_counts;
- #endif
- 
  #ifdef LOCK_DEBUG
  bool		Trace_lwlocks = false;
  
--- 109,114 ----
*************** LOG_LWDEBUG(const char *where, LWLockId 
*** 121,146 ****
  
  #ifdef LWLOCK_STATS
  
  static void
  print_lwlock_stats(int code, Datum arg)
  {
! 	int			i;
  	int		   *LWLockCounter = (int *) ((char *) LWLockArray - 2 * sizeof(int));
  	int			numLocks = LWLockCounter[1];
  
  	/* Grab an LWLock to keep different backends from mixing reports */
  	LWLockAcquire(0, LW_EXCLUSIVE);
  
  	for (i = 0; i < numLocks; i++)
  	{
! 		if (sh_acquire_counts[i] || ex_acquire_counts[i] || block_counts[i])
! 			fprintf(stderr, "PID %d lwlock %d: shacq %u exacq %u blk %u\n",
! 					MyProcPid, i, sh_acquire_counts[i], ex_acquire_counts[i],
! 					block_counts[i]);
  	}
  
  	LWLockRelease(0);
  }
  #endif   /* LWLOCK_STATS */
  
  
--- 135,282 ----
  
  #ifdef LWLOCK_STATS
  
+ typedef struct
+ {
+ 	/* Process-local Counters for the number of times the lock has been ... */
+ 	int		count_acquired_share;			/* acquired in SHARE mode */
+ 	int		count_waited_share;				/* and it needed to wait */
+ 	
+ 	int		count_acquired_exclusive;		/*	acquired in EXCLUSIVEmode */
+ 	int		count_waited_exclusive;			/* and it needed to wait */
+ 	
+ #ifdef LWLOCK_TIMING_STATS
+ 	/* Process local sum of time during which ... */
+ 	instr_time		time_waited_share;		/* we waited to get a SHARE lock */
+ 	instr_time		time_held_share;		/* we held the SHARE lock */
+ 	instr_time		time_waited_exclusive;	/* we waited to get an EXCLUSIVE lock */
+ 	instr_time		time_held_exclusive;	/* we held the EXCLUSIVE lock */
+ 	
+ 	instr_time		ta, th;	/* temp variables */
+ #endif
+ } LWLockStatsData;
+ 
+ static int	counts_for_pid = 0;
+ static LWLockStatsData *lwlock_stats;
+ #ifdef LWLOCK_TIMING_STATS
+ static instr_time lwlock_stats_begin_time;
+ #endif
+ 
+ static const char* lwlock_stats_lock_name( LWLockId id )
+ {
+ 	static const char * names[] = {
+ 	"BufFreelist",
+ 	"ShmemIndex",
+ 	"OidGen",
+ 	"XidGen",
+ 	"ProcArray",
+ 	"SInvalRead",
+ 	"SInvalWrite",
+ 	"WALInsert",
+ 	"WALWrite",
+ 	"ControlFile",
+ 	"Checkpoint",
+ 	"CLogControl",
+ 	"SubtransControl",
+ 	"MultiXactGen",
+ 	"MultiXactOffsetControl",
+ 	"MultiXactMemberControl",
+ 	"RelCacheInit",
+ 	"BgWriterComm",
+ 	"TwoPhaseState",
+ 	"TablespaceCreate",
+ 	"BtreeVacuum",
+ 	"AddinShmemInit",
+ 	"Autovacuum",
+ 	"AutovacuumSchedule",
+ 	"SyncScan" };
+ 	
+ 	if( id >= 0 && id < (sizeof( names )/sizeof( names[0] )))
+ 		return names[id];
+ 	else
+ 		return "";
+ }
+ 
  static void
  print_lwlock_stats(int code, Datum arg)
  {
! 	int			i, lines=0;
  	int		   *LWLockCounter = (int *) ((char *) LWLockArray - 2 * sizeof(int));
  	int			numLocks = LWLockCounter[1];
+ #ifdef LWLOCK_TIMING_STATS
+ 	instr_time	end_time;
+ 	double		total_percents;
+ 	INSTR_TIME_SET_CURRENT( end_time );
+ 	INSTR_TIME_SUBTRACT( end_time, lwlock_stats_begin_time );
+ 	total_percents = 100.0 / INSTR_TIME_GET_DOUBLE( end_time );
+ #endif
  
+ 	fprintf( stderr, "\n-------- Lock stats for PID %d\n", MyProcPid );
+ 	
  	/* Grab an LWLock to keep different backends from mixing reports */
  	LWLockAcquire(0, LW_EXCLUSIVE);
  
  	for (i = 0; i < numLocks; i++)
  	{
! 		LWLockStatsData *p = &lwlock_stats[i];
! #ifdef LWLOCK_TIMING_STATS
! 		double	time_waited_share		= INSTR_TIME_GET_DOUBLE(p->time_waited_share	);
! 		double	time_held_share			= INSTR_TIME_GET_DOUBLE(p->time_held_share		);		
! 		double	time_waited_exclusive	= INSTR_TIME_GET_DOUBLE(p->time_waited_exclusive);	
! 		double	time_held_exclusive		= INSTR_TIME_GET_DOUBLE(p->time_held_exclusive	);	
! #endif
! 		
! 		if( !( p->count_waited_share || p->count_waited_exclusive ))
! 			continue;		
! 		
! #ifdef LWLOCK_TIMING_STATS
! 		if(    time_waited_share		< LWLOCKS_STATS_TIME_DISPLAY_THRESHOLD
! 			&& time_waited_exclusive	< LWLOCKS_STATS_TIME_DISPLAY_THRESHOLD )
! 			continue;
! #endif		
! 		
! #ifdef LWLOCK_TIMING_STATS
! 		if( !(lines++ & 15) )
! 			fprintf( stderr, "    PID    Lock      ShAcq     ShWait     ShWaitT     ShHeldT      ExAcq     "
! 							 "ExWait             ExWaitT                ExHeldT     Name\n" );
! 		
! 		fprintf( stderr,
! 			"%7d %7d %10d %10d %11.02f %11.02f %10d %10d %11.02f (%6.02f %%) %11.02f (%6.02f %%)  %s\n",
! 			MyProcPid, i, 
! 			p->count_acquired_share, p->count_waited_share, time_waited_share, time_held_share,
! 			p->count_acquired_exclusive, p->count_waited_exclusive, 
! 			time_waited_exclusive, 	time_waited_exclusive * total_percents,
! 			time_held_exclusive,	time_held_exclusive * total_percents,
! 			lwlock_stats_lock_name( i ));
! #else
! 		if( !(lines++ & 15) )
! 			fprintf( stderr, "    PID    Lock      ShAcq     ShWait     ExAcq     ExWait     Name\n" );
! 		
! 		fprintf( stderr,
! 			"%7d %7d %10d %10d %10d %10d    %s\n",
! 			MyProcPid, i, 
! 			p->count_acquired_share, p->count_waited_share, 
! 			p->count_acquired_exclusive, p->count_waited_exclusive, 
! 			lwlock_stats_lock_name( i ));
! #endif		
  	}
  
  	LWLockRelease(0);
  }
+ 
+ static void lock_stats_setup( void )
+ {
+ 	int		   *LWLockCounter = (int *) ((char *) LWLockArray - 2 * sizeof(int));
+ 	int			numLocks = LWLockCounter[1];
+ 
+ 	lwlock_stats = calloc(numLocks, sizeof(LWLockStatsData));
+ 	counts_for_pid = MyProcPid;
+ 
+ #ifdef LWLOCK_TIMING_STATS
+ 	INSTR_TIME_SET_CURRENT( lwlock_stats_begin_time );
+ #endif
+ 
+ 	on_shmem_exit(print_lwlock_stats, 0);
+ }
  #endif   /* LWLOCK_STATS */
  
  
*************** LWLockAcquire(LWLockId lockid, LWLockMod
*** 321,341 ****
  #ifdef LWLOCK_STATS
  	/* Set up local count state first time through in a given process */
  	if (counts_for_pid != MyProcPid)
! 	{
! 		int		   *LWLockCounter = (int *) ((char *) LWLockArray - 2 * sizeof(int));
! 		int			numLocks = LWLockCounter[1];
! 
! 		sh_acquire_counts = calloc(numLocks, sizeof(int));
! 		ex_acquire_counts = calloc(numLocks, sizeof(int));
! 		block_counts = calloc(numLocks, sizeof(int));
! 		counts_for_pid = MyProcPid;
! 		on_shmem_exit(print_lwlock_stats, 0);
! 	}
  	/* Count lock acquisition attempts */
! 	if (mode == LW_EXCLUSIVE)
! 		ex_acquire_counts[lockid]++;
! 	else
! 		sh_acquire_counts[lockid]++;
  #endif   /* LWLOCK_STATS */
  
  	/*
--- 457,471 ----
  #ifdef LWLOCK_STATS
  	/* Set up local count state first time through in a given process */
  	if (counts_for_pid != MyProcPid)
! 		lock_stats_setup();
! 	
  	/* Count lock acquisition attempts */
! 	if (mode == LW_EXCLUSIVE)	lwlock_stats[lockid].count_acquired_exclusive++;
! 	else						lwlock_stats[lockid].count_acquired_share++;
! #ifdef LWLOCK_TIMING_STATS
! 	/* record start of wait time and lock mode */
! 	INSTR_TIME_SET_CURRENT( lwlock_stats[lockid].ta );
! #endif
  #endif   /* LWLOCK_STATS */
  
  	/*
*************** LWLockAcquire(LWLockId lockid, LWLockMod
*** 445,451 ****
  		LOG_LWDEBUG("LWLockAcquire", lockid, "waiting");
  
  #ifdef LWLOCK_STATS
! 		block_counts[lockid]++;
  #endif
  
  		TRACE_POSTGRESQL_LWLOCK_WAIT_START(lockid, mode);
--- 575,583 ----
  		LOG_LWDEBUG("LWLockAcquire", lockid, "waiting");
  
  #ifdef LWLOCK_STATS
! 		/* count lock waits */
! 		if (mode == LW_EXCLUSIVE)	lwlock_stats[lockid].count_waited_exclusive++;
! 		else						lwlock_stats[lockid].count_waited_share++;
  #endif
  
  		TRACE_POSTGRESQL_LWLOCK_WAIT_START(lockid, mode);
*************** LWLockAcquire(LWLockId lockid, LWLockMod
*** 480,485 ****
--- 612,625 ----
  	 */
  	while (extraWaits-- > 0)
  		PGSemaphoreUnlock(&proc->sem);
+ 	
+ #ifdef LWLOCK_TIMING_STATS
+ 	/* record end of wait time and start of hold time */
+ 	INSTR_TIME_SET_CURRENT( lwlock_stats[lockid].th );
+ 	
+ 	if (mode == LW_EXCLUSIVE)	INSTR_TIME_ACCUM_DIFF( lwlock_stats[lockid].time_waited_exclusive, lwlock_stats[lockid].th, lwlock_stats[lockid].ta );
+ 	else						INSTR_TIME_ACCUM_DIFF( lwlock_stats[lockid].time_waited_share,     lwlock_stats[lockid].th, lwlock_stats[lockid].ta );
+ #endif
  }
  
  /*
*************** LWLockConditionalAcquire(LWLockId lockid
*** 548,553 ****
--- 688,707 ----
  		/* Add lock to list of locks held by this backend */
  		held_lwlocks[num_held_lwlocks++] = lockid;
  		TRACE_POSTGRESQL_LWLOCK_CONDACQUIRE(lockid, mode);
+ 		
+ #ifdef LWLOCK_STATS
+ 		/* Set up local count state first time through in a given process */
+ 		if (counts_for_pid != MyProcPid)
+ 			lock_stats_setup();
+ 		
+ 		/* Count lock acquisition attempts */
+ 		if (mode == LW_EXCLUSIVE)	lwlock_stats[lockid].count_acquired_exclusive++;
+ 		else						lwlock_stats[lockid].count_acquired_share++;
+ #ifdef LWLOCK_TIMING_STATS
+ 		/* record start of hold time */
+ 		INSTR_TIME_SET_CURRENT( lwlock_stats[lockid].th );
+ #endif
+ #endif   /* LWLOCK_STATS */
  	}
  
  	return !mustwait;
*************** LWLockRelease(LWLockId lockid)
*** 563,568 ****
--- 717,725 ----
  	PGPROC	   *head;
  	PGPROC	   *proc;
  	int			i;
+ #ifdef LWLOCK_TIMING_STATS
+ 	bool		was_exclusive = false;
+ #endif
  
  	PRINT_LWDEBUG("LWLockRelease", lockid, lock);
  
*************** LWLockRelease(LWLockId lockid)
*** 586,592 ****
--- 743,754 ----
  
  	/* Release my hold on lock */
  	if (lock->exclusive > 0)
+ 	{
  		lock->exclusive--;
+ #ifdef LWLOCK_TIMING_STATS
+ 		was_exclusive = true;
+ #endif
+ 	}
  	else
  	{
  		Assert(lock->shared > 0);
*************** LWLockRelease(LWLockId lockid)
*** 651,656 ****
--- 813,825 ----
  	 * Now okay to allow cancel/die interrupts.
  	 */
  	RESUME_INTERRUPTS();
+ #ifdef LWLOCK_TIMING_STATS
+ 	/* record end of hold time */
+ 	INSTR_TIME_SET_CURRENT( lwlock_stats[lockid].ta );
+ 	
+ 	if (was_exclusive)	INSTR_TIME_ACCUM_DIFF( lwlock_stats[lockid].time_held_exclusive, lwlock_stats[lockid].ta, lwlock_stats[lockid].th );
+ 	else				INSTR_TIME_ACCUM_DIFF( lwlock_stats[lockid].time_held_share,     lwlock_stats[lockid].ta, lwlock_stats[lockid].th );
+ #endif
  }