lwhistogram.patch

application/octet-stream

Filename: lwhistogram.patch
Type: application/octet-stream
Part: 0
Message: measuring lwlock-related latency spikes

Patch

Same data as JSON: GET /api/v1/attachments/:id/patch the parsed metadata as JSON — format, series position, per-file stats; never the diff bytes. API reference →
Format: unified
File+
src/backend/postmaster/postmaster.c 2 0
src/backend/storage/lmgr/lwlock.c 55 1
src/include/storage/lwlock.h 1 0
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/lmgr/lwlock.c b/src/backend/storage/lmgr/lwlock.c
index f152376..acbf70b 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,7 @@ 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 */
+	uint64		histogram[33];	/* gigantic! */
 	/* tail is undefined when head is NULL */
 } LWLock;
 
@@ -60,7 +62,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
 {
@@ -342,8 +344,10 @@ LWLockAcquire(LWLockId lockid, LWLockMode mode)
 	PGPROC	   *proc = MyProc;
 	bool		retry = false;
 	int			extraWaits = 0;
+	instr_time	start_time;
 
 	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 */
@@ -462,6 +466,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,6 +492,19 @@ LWLockAcquire(LWLockId lockid, LWLockMode mode)
 		retry = true;
 	}
 
+	if (!INSTR_TIME_IS_ZERO(start_time))
+	{
+		instr_time	end_time;
+		int64		time_elapsed;
+		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);
 
@@ -878,3 +898,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(buffer);
+		}
+		if (s != buffer)
+			elog(LOG, "lock %d: %s", i, buffer);
+	}
+}
diff --git a/src/include/storage/lwlock.h b/src/include/storage/lwlock.h
index 57a4f66..ddfa524 100644
--- a/src/include/storage/lwlock.h
+++ b/src/include/storage/lwlock.h
@@ -118,5 +118,6 @@ extern Size LWLockShmemSize(void);
 extern void CreateLWLocks(void);
 
 extern void RequestAddinLWLocks(int n);
+extern void LWLockDumpHistograms(void);
 
 #endif   /* LWLOCK_H */