v1-0001-Add-more-statically-defined-tracepoints-around-xl.patch

From 74cfc819e2c4323613191bcbf6c91f128617c353 Mon Sep 17 00:00:00 2001
From: Craig Ringer <craig@2ndquadrant.com>
Date: Mon, 2 Jul 2018 11:33:46 +0800
Subject: [PATCH v1] Add more statically defined tracepoints around xlog
 handling

New tracepoints are added to allow for tracing of WAL flushes and
segment initialization/recycling.

The existing wal_insert tracepoint is renamed to wal_insert_start
and paired with a wal_insert_done, so that insert durations
may be recorded including fsync time.
---
 src/backend/access/transam/xlog.c       | 14 ++++++++++++++
 src/backend/access/transam/xloginsert.c |  4 +++-
 src/backend/utils/probes.d              | 18 +++++++++++++++++-
 3 files changed, 34 insertions(+), 2 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index dcfef36591..b3dead5ac0 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -955,6 +955,8 @@ static void WALInsertLockUpdateInsertingAt(XLogRecPtr insertingAt);
  * (LSN is the XLOG point up to which the XLOG must be flushed to disk
  * before the data page can be written out.  This implements the basic
  * WAL rule "write the log before the data".)
+ *
+ * You want the WAL_INSERT tracepoints if you're looking for activity here.
  */
 XLogRecPtr
 XLogInsertRecord(XLogRecData *rdata,
@@ -2810,6 +2812,8 @@ XLogFlush(XLogRecPtr record)
 			 (uint32) (LogwrtResult.Flush >> 32), (uint32) LogwrtResult.Flush);
 #endif
 
+	TRACE_POSTGRESQL_WAL_FLUSH_START(record);
+
 	START_CRIT_SECTION();
 
 	/*
@@ -2942,6 +2946,8 @@ XLogFlush(XLogRecPtr record)
 			 "xlog flush request %X/%X is not satisfied --- flushed only to %X/%X",
 			 (uint32) (record >> 32), (uint32) record,
 			 (uint32) (LogwrtResult.Flush >> 32), (uint32) LogwrtResult.Flush);
+
+	TRACE_POSTGRESQL_WAL_FLUSH_DONE();
 }
 
 /*
@@ -3190,6 +3196,8 @@ XLogFileInit(XLogSegNo logsegno, bool *use_existent, bool use_lock)
 
 	XLogFilePath(path, ThisTimeLineID, logsegno, wal_segment_size);
 
+	TRACE_POSTGRESQL_WAL_SEG_INIT_START();
+
 	/*
 	 * Try to use existent file (checkpoint maker may have created it already)
 	 */
@@ -3204,7 +3212,10 @@ XLogFileInit(XLogSegNo logsegno, bool *use_existent, bool use_lock)
 						 errmsg("could not open file \"%s\": %m", path)));
 		}
 		else
+		{
+			TRACE_POSTGRESQL_WAL_SEG_INIT_DONE(*use_existent);
 			return fd;
+		}
 	}
 
 	/*
@@ -3327,6 +3338,7 @@ XLogFileInit(XLogSegNo logsegno, bool *use_existent, bool use_lock)
 
 	elog(DEBUG2, "done creating and filling new WAL file");
 
+	TRACE_POSTGRESQL_WAL_SEG_INIT_DONE(*use_existent);
 	return fd;
 }
 
@@ -10156,6 +10168,7 @@ assign_xlog_sync_method(int new_sync_method, void *extra)
 void
 issue_xlog_fsync(int fd, XLogSegNo segno)
 {
+	TRACE_POSTGRESQL_WAL_SYNC_START(fd, segno);
 	switch (sync_method)
 	{
 		case SYNC_METHOD_FSYNC:
@@ -10191,6 +10204,7 @@ issue_xlog_fsync(int fd, XLogSegNo segno)
 			elog(PANIC, "unrecognized wal_sync_method: %d", sync_method);
 			break;
 	}
+	TRACE_POSTGRESQL_WAL_SYNC_DONE();
 }
 
 /*
diff --git a/src/backend/access/transam/xloginsert.c b/src/backend/access/transam/xloginsert.c
index 5bea073a2b..8c9b57b0da 100644
--- a/src/backend/access/transam/xloginsert.c
+++ b/src/backend/access/transam/xloginsert.c
@@ -429,7 +429,7 @@ XLogInsert(RmgrId rmid, uint8 info)
 				  XLR_CHECK_CONSISTENCY)) != 0)
 		elog(PANIC, "invalid xlog info mask %02X", info);
 
-	TRACE_POSTGRESQL_WAL_INSERT(rmid, info);
+	TRACE_POSTGRESQL_WAL_INSERT_START(rmid, info);
 
 	/*
 	 * In bootstrap mode, we don't actually log anything but XLOG resources;
@@ -464,6 +464,8 @@ XLogInsert(RmgrId rmid, uint8 info)
 
 	XLogResetInsertion();
 
+	TRACE_POSTGRESQL_WAL_INSERT_DONE(EndPos);
+
 	return EndPos;
 }
 
diff --git a/src/backend/utils/probes.d b/src/backend/utils/probes.d
index ad06e8e2ea..2be68d99d6 100644
--- a/src/backend/utils/probes.d
+++ b/src/backend/utils/probes.d
@@ -21,6 +21,14 @@
 #define Oid unsigned int
 #define ForkNumber int
 #define bool char
+/*
+ * SystemTap doesn't like 'unsigned long long int', but except on Windows 'long
+ * int' is 64-bit. Windows is LLP64 and will treat it as 32-bit but our stub
+ * macros don't care about typing, and dtrace/stap isn't supported on Windows.
+ * Windows has Event Tracing (ETW) and TraceLogging, but we don't support it right
+ * now, so we'll deal with it if it comes up.
+ */
+#define XLogRecPtr unsigned long int
 
 provider postgresql {
 
@@ -75,6 +83,7 @@ provider postgresql {
 	probe checkpoint__done(int, int, int, int, int);
 	probe clog__checkpoint__start(bool);
 	probe clog__checkpoint__done(bool);
+
 	probe subtrans__checkpoint__start(bool);
 	probe subtrans__checkpoint__done(bool);
 	probe multixact__checkpoint__start(bool);
@@ -87,7 +96,14 @@ provider postgresql {
 	probe smgr__md__write__start(ForkNumber, BlockNumber, Oid, Oid, Oid, int);
 	probe smgr__md__write__done(ForkNumber, BlockNumber, Oid, Oid, Oid, int, int, int);
 
-	probe wal__insert(unsigned char, unsigned char);
+	probe wal__insert__start(unsigned char, unsigned char);
+	probe wal__insert__done(XLogRecPtr);
+	probe wal__seg__init__start();
+	probe wal__seg__init__done(bool);
+	probe wal__flush__start(XLogRecPtr);
+	probe wal__flush__done();
+	probe wal__sync__start(int, int);
+	probe wal__sync__done();
 	probe wal__switch();
 	probe wal__buffer__write__dirty__start();
 	probe wal__buffer__write__dirty__done();
-- 
2.14.3