log-sync-v2.patch

diff --git a/src/backend/storage/smgr/md.c b/src/backend/storage/smgr/md.c
index 1219fcf..c72da72 100644
--- a/src/backend/storage/smgr/md.c
+++ b/src/backend/storage/smgr/md.c
@@ -20,6 +20,7 @@
 
 #include "catalog/catalog.h"
 #include "miscadmin.h"
+#include "portability/instr_time.h"
 #include "postmaster/bgwriter.h"
 #include "storage/fd.h"
 #include "storage/bufmgr.h"
@@ -29,6 +30,11 @@
 #include "utils/memutils.h"
 #include "pg_trace.h"
 
+/*
+ * For now just leave this on all the time, eventually this will
+ * need to be a full compiler flag like DEBUG_DEADLOCK
+ */
+#define DEBUG_FSYNC	1
 
 /* interval for calling AbsorbFsyncRequests in mdsync */
 #define FSYNCS_PER_ABSORB		10
@@ -927,6 +933,15 @@ mdsync(void)
 	PendingOperationEntry *entry;
 	int			absorb_counter;
 
+#ifdef DEBUG_FSYNC
+	/* Statistics on sync times */
+	int processed = 0;
+	instr_time sync_start,sync_end,diff;
+	double elapsed;
+	double longest = 0;
+	double total_elapsed = 0;
+#endif
+
 	/*
 	 * This is only called during checkpoints, and checkpoints should only
 	 * occur in processes that have created a pendingOpsTable.
@@ -1069,9 +1084,32 @@ mdsync(void)
 				seg = _mdfd_getseg(reln, entry->tag.forknum,
 							  entry->tag.segno * ((BlockNumber) RELSEG_SIZE),
 								   false, EXTENSION_RETURN_NULL);
+
+#ifdef DEBUG_FSYNC
+				if (log_checkpoints)
+					INSTR_TIME_SET_CURRENT(sync_start);
+#endif
 				if (seg != NULL &&
 					FileSync(seg->mdfd_vfd) >= 0)
+				{
+
+#ifdef DEBUG_FSYNC
+					if (log_checkpoints)
+					{
+						INSTR_TIME_SET_CURRENT(sync_end);
+						diff=sync_end;
+						INSTR_TIME_SUBTRACT(diff, sync_start);
+						elapsed = (double) INSTR_TIME_GET_MICROSEC(diff) / 1000.0;
+						if (elapsed > longest)
+							longest = elapsed;
+						total_elapsed+=elapsed;
+						processed++;
+						/* Reduce the log level here to DEBUG2 in final patch? */
+						elog(DEBUG1, "checkpoint sync: file=%d time=%f msec", processed, elapsed);
+					}
+#endif
 					break;		/* success; break out of retry loop */
+					}
 
 				/*
 				 * XXX is there any point in allowing more than one retry?
@@ -1113,6 +1151,13 @@ mdsync(void)
 			elog(ERROR, "pendingOpsTable corrupted");
 	}							/* end loop over hashtable entries */
 
+#ifdef DEBUG_FSYNC
+	/* Report on sync performance metrics */
+	if (log_checkpoints && (processed > 0))
+		elog(LOG, "checkpoint sync: files=%d longest=%f msec average=%f msec",
+			processed, longest, total_elapsed / processed);
+#endif
+
 	/* Flag successful completion of mdsync */
 	mdsync_in_progress = false;
 }