New GUC, track_iotiming, to track I/O timings.

Currently, the only way to see the numbers this gathers is via
EXPLAIN (ANALYZE, BUFFERS), but the plan is to add visibility through
the stats collector and pg_stat_statements in subsequent patches.

Ants Aasma, reviewed by Greg Smith, with some further changes by me.

1 files changed, 18 insertions, 0 deletions

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index a14cae14420..81d63f87f10 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -1236,6 +1236,8 @@ ExplainNode(PlanState *planstate, List *ancestors,
 									 usage->local_blks_written > 0);
 			bool		has_temp = (usage->temp_blks_read > 0 ||
 									usage->temp_blks_written > 0);
+			bool		has_timing = (!INSTR_TIME_IS_ZERO(usage->time_read) ||
+									  !INSTR_TIME_IS_ZERO(usage->time_write));
 
 			/* Show only positive counter values. */
 			if (has_shared || has_local || has_temp)
@@ -1291,6 +1293,20 @@ ExplainNode(PlanState *planstate, List *ancestors,
 				}
 				appendStringInfoChar(es->str, '\n');
 			}
+
+			/* As above, show only positive counter values. */
+			if (has_timing)
+			{
+				appendStringInfoSpaces(es->str, es->indent * 2);
+				appendStringInfoString(es->str, "I/O Timings:");
+				if (!INSTR_TIME_IS_ZERO(usage->time_read))
+					appendStringInfo(es->str, " read=%0.2f",
+								 INSTR_TIME_GET_MILLISEC(usage->time_read));
+				if (!INSTR_TIME_IS_ZERO(usage->time_write))
+					appendStringInfo(es->str, " write=%0.2f",
+								 INSTR_TIME_GET_MILLISEC(usage->time_write));
+				appendStringInfoChar(es->str, '\n');
+			}
 		}
 		else
 		{
@@ -1304,6 +1320,8 @@ ExplainNode(PlanState *planstate, List *ancestors,
 			ExplainPropertyLong("Local Written Blocks", usage->local_blks_written, es);
 			ExplainPropertyLong("Temp Read Blocks", usage->temp_blks_read, es);
 			ExplainPropertyLong("Temp Written Blocks", usage->temp_blks_written, es);
+			ExplainPropertyFloat("I/O Read Time", INSTR_TIME_GET_MILLISEC(usage->time_read), 3, es);
+			ExplainPropertyFloat("I/O Write Time", INSTR_TIME_GET_MILLISEC(usage->time_write), 3, es);
 		}
 	}