From 48997d34c1bcc3d8199f300be3b99776bb84ffa8 Mon Sep 17 00:00:00 2001 From: Andres Freund Date: Wed, 14 Mar 2018 10:50:58 -0700 Subject: [PATCH v2 2/2] Add 'unit' parameter to ExplainProperty{Integer,Float}. This allows to deduplicate some existing code, but mainly allows to avoid duplication in some upcoming code. Author: Andres Freund Discussion: https://postgr.es/m/20180314002740.cah3mdsonz5mxney@alap3.anarazel.de --- contrib/file_fdw/file_fdw.c | 2 +- src/backend/commands/explain.c | 199 ++++++++++++++++++++++------------------- src/include/commands/explain.h | 8 +- 3 files changed, 113 insertions(+), 96 deletions(-) diff --git a/contrib/file_fdw/file_fdw.c b/contrib/file_fdw/file_fdw.c index bf72a9108af..dce3be26179 100644 --- a/contrib/file_fdw/file_fdw.c +++ b/contrib/file_fdw/file_fdw.c @@ -622,7 +622,7 @@ fileExplainForeignScan(ForeignScanState *node, ExplainState *es) if (!is_program && stat(filename, &stat_buf) == 0) - ExplainPropertyInteger("Foreign File Size", + ExplainPropertyInteger("Foreign File Size", "b", (int64) stat_buf.st_size, es); } } diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index a0f5114928c..10dd5fdfa09 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -123,8 +123,8 @@ static void ExplainSubPlans(List *plans, List *ancestors, const char *relationship, ExplainState *es); static void ExplainCustomChildren(CustomScanState *css, List *ancestors, ExplainState *es); -static void ExplainProperty(const char *qlabel, const char *value, - bool numeric, ExplainState *es); +static void ExplainProperty(const char *qlabel, const char *unit, + const char *value, bool numeric, ExplainState *es); static void ExplainDummyGroup(const char *objtype, const char *labelname, ExplainState *es); static void ExplainXMLTag(const char *tagname, int flags, ExplainState *es); @@ -549,11 +549,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, { double plantime = INSTR_TIME_GET_DOUBLE(*planduration); - if (es->format == EXPLAIN_FORMAT_TEXT) - appendStringInfo(es->str, "Planning time: %.3f ms\n", - 1000.0 * plantime); - else - ExplainPropertyFloat("Planning Time", 1000.0 * plantime, 3, es); + ExplainPropertyFloat("Planning Time", "ms", 1000.0 * plantime, 3, es); } /* Print info about runtime of triggers */ @@ -585,14 +581,8 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, * the output). By default, ANALYZE sets SUMMARY to true. */ if (es->summary && es->analyze) - { - if (es->format == EXPLAIN_FORMAT_TEXT) - appendStringInfo(es->str, "Execution time: %.3f ms\n", - 1000.0 * totaltime); - else - ExplainPropertyFloat("Execution Time", 1000.0 * totaltime, - 3, es); - } + ExplainPropertyFloat("Execution Time", "ms", 1000.0 * totaltime, 3, + es); ExplainCloseGroup("Query", NULL, true, es); } @@ -764,8 +754,9 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es) ExplainPropertyText("Constraint Name", conname, es); ExplainPropertyText("Relation", relname, es); if (es->timing) - ExplainPropertyFloat("Time", 1000.0 * instr->total, 3, es); - ExplainPropertyFloat("Calls", instr->ntuples, 0, es); + ExplainPropertyFloat("Time", "ms", 1000.0 * instr->total, 3, + es); + ExplainPropertyFloat("Calls", NULL, instr->ntuples, 0, es); } if (conname) @@ -1280,10 +1271,14 @@ ExplainNode(PlanState *planstate, List *ancestors, } else { - ExplainPropertyFloat("Startup Cost", plan->startup_cost, 2, es); - ExplainPropertyFloat("Total Cost", plan->total_cost, 2, es); - ExplainPropertyFloat("Plan Rows", plan->plan_rows, 0, es); - ExplainPropertyInteger("Plan Width", plan->plan_width, es); + ExplainPropertyFloat("Startup Cost", NULL, plan->startup_cost, + 2, es); + ExplainPropertyFloat("Total Cost", NULL, plan->total_cost, + 2, es); + ExplainPropertyFloat("Plan Rows", NULL, plan->plan_rows, + 0, es); + ExplainPropertyInteger("Plan Width", NULL, plan->plan_width, + es); } } @@ -1304,8 +1299,8 @@ ExplainNode(PlanState *planstate, List *ancestors, planstate->instrument && planstate->instrument->nloops > 0) { double nloops = planstate->instrument->nloops; - double startup_sec = 1000.0 * planstate->instrument->startup / nloops; - double total_sec = 1000.0 * planstate->instrument->total / nloops; + double startup_ms = 1000.0 * planstate->instrument->startup / nloops; + double total_ms = 1000.0 * planstate->instrument->total / nloops; double rows = planstate->instrument->ntuples / nloops; if (es->format == EXPLAIN_FORMAT_TEXT) @@ -1313,7 +1308,7 @@ ExplainNode(PlanState *planstate, List *ancestors, if (es->timing) appendStringInfo(es->str, " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)", - startup_sec, total_sec, rows, nloops); + startup_ms, total_ms, rows, nloops); else appendStringInfo(es->str, " (actual rows=%.0f loops=%.0f)", @@ -1323,11 +1318,13 @@ ExplainNode(PlanState *planstate, List *ancestors, { if (es->timing) { - ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es); - ExplainPropertyFloat("Actual Total Time", total_sec, 3, es); + ExplainPropertyFloat("Actual Startup Time", "s", startup_ms, + 3, es); + ExplainPropertyFloat("Actual Total Time", "s", total_ms, + 3, es); } - ExplainPropertyFloat("Actual Rows", rows, 0, es); - ExplainPropertyFloat("Actual Loops", nloops, 0, es); + ExplainPropertyFloat("Actual Rows", NULL, rows, 0, es); + ExplainPropertyFloat("Actual Loops", NULL, nloops, 0, es); } } else if (es->analyze) @@ -1338,11 +1335,11 @@ ExplainNode(PlanState *planstate, List *ancestors, { if (es->timing) { - ExplainPropertyFloat("Actual Startup Time", 0.0, 3, es); - ExplainPropertyFloat("Actual Total Time", 0.0, 3, es); + ExplainPropertyFloat("Actual Startup Time", "ms", 0.0, 3, es); + ExplainPropertyFloat("Actual Total Time", "ms", 0.0, 3, es); } - ExplainPropertyFloat("Actual Rows", 0.0, 0, es); - ExplainPropertyFloat("Actual Loops", 0.0, 0, es); + ExplainPropertyFloat("Actual Rows", NULL, 0.0, 0, es); + ExplainPropertyFloat("Actual Loops", NULL, 0.0, 0, es); } } @@ -1400,9 +1397,12 @@ ExplainNode(PlanState *planstate, List *ancestors, show_instrumentation_count("Rows Removed by Filter", 1, planstate, es); if (es->analyze) - ExplainPropertyInteger("Heap Fetches", - ((IndexOnlyScanState *) planstate)->ioss_HeapFetches, - es); + { + long heapFetches = + ((IndexOnlyScanState *) planstate)->ioss_HeapFetches; + + ExplainPropertyInteger("Heap Fetches", NULL, heapFetches, es); + } break; case T_BitmapIndexScan: show_scan_qual(((BitmapIndexScan *) plan)->indexqualorig, @@ -1444,7 +1444,7 @@ ExplainNode(PlanState *planstate, List *ancestors, if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, planstate, es); - ExplainPropertyInteger("Workers Planned", + ExplainPropertyInteger("Workers Planned", NULL, gather->num_workers, es); /* Show params evaluated at gather node */ @@ -1456,7 +1456,7 @@ ExplainNode(PlanState *planstate, List *ancestors, int nworkers; nworkers = ((GatherState *) planstate)->nworkers_launched; - ExplainPropertyInteger("Workers Launched", + ExplainPropertyInteger("Workers Launched", NULL, nworkers, es); } if (gather->single_copy || es->format != EXPLAIN_FORMAT_TEXT) @@ -1471,7 +1471,7 @@ ExplainNode(PlanState *planstate, List *ancestors, if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, planstate, es); - ExplainPropertyInteger("Workers Planned", + ExplainPropertyInteger("Workers Planned", NULL, gm->num_workers, es); /* Show params evaluated at gather-merge node */ @@ -1483,7 +1483,7 @@ ExplainNode(PlanState *planstate, List *ancestors, int nworkers; nworkers = ((GatherMergeState *) planstate)->nworkers_launched; - ExplainPropertyInteger("Workers Launched", + ExplainPropertyInteger("Workers Launched", NULL, nworkers, es); } } @@ -1653,14 +1653,14 @@ ExplainNode(PlanState *planstate, List *ancestors, { Instrumentation *instrument = &w->instrument[n]; double nloops = instrument->nloops; - double startup_sec; - double total_sec; + double startup_ms; + double total_ms; double rows; if (nloops <= 0) continue; - startup_sec = 1000.0 * instrument->startup / nloops; - total_sec = 1000.0 * instrument->total / nloops; + startup_ms = 1000.0 * instrument->startup / nloops; + total_ms = 1000.0 * instrument->total / nloops; rows = instrument->ntuples / nloops; if (es->format == EXPLAIN_FORMAT_TEXT) @@ -1670,7 +1670,7 @@ ExplainNode(PlanState *planstate, List *ancestors, if (es->timing) appendStringInfo(es->str, "actual time=%.3f..%.3f rows=%.0f loops=%.0f\n", - startup_sec, total_sec, rows, nloops); + startup_ms, total_ms, rows, nloops); else appendStringInfo(es->str, "actual rows=%.0f loops=%.0f\n", @@ -1688,15 +1688,17 @@ ExplainNode(PlanState *planstate, List *ancestors, opened_group = true; } ExplainOpenGroup("Worker", NULL, true, es); - ExplainPropertyInteger("Worker Number", n, es); + ExplainPropertyInteger("Worker Number", NULL, n, es); if (es->timing) { - ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es); - ExplainPropertyFloat("Actual Total Time", total_sec, 3, es); + ExplainPropertyFloat("Actual Startup Time", "ms", + startup_ms, 3, es); + ExplainPropertyFloat("Actual Total Time", "ms", + total_ms, 3, es); } - ExplainPropertyFloat("Actual Rows", rows, 0, es); - ExplainPropertyFloat("Actual Loops", nloops, 0, es); + ExplainPropertyFloat("Actual Rows", NULL, rows, 0, es); + ExplainPropertyFloat("Actual Loops", NULL, nloops, 0, es); if (es->buffers) show_buffer_usage(es, &instrument->bufusage); @@ -2326,7 +2328,7 @@ show_sort_info(SortState *sortstate, ExplainState *es) else { ExplainPropertyText("Sort Method", sortMethod, es); - ExplainPropertyInteger("Sort Space Used", spaceUsed, es); + ExplainPropertyInteger("Sort Space Used", "kB", spaceUsed, es); ExplainPropertyText("Sort Space Type", spaceType, es); } } @@ -2365,9 +2367,9 @@ show_sort_info(SortState *sortstate, ExplainState *es) opened_group = true; } ExplainOpenGroup("Worker", NULL, true, es); - ExplainPropertyInteger("Worker Number", n, es); + ExplainPropertyInteger("Worker Number", NULL, n, es); ExplainPropertyText("Sort Method", sortMethod, es); - ExplainPropertyInteger("Sort Space Used", spaceUsed, es); + ExplainPropertyInteger("Sort Space Used", "kB", spaceUsed, es); ExplainPropertyText("Sort Space Type", spaceType, es); ExplainCloseGroup("Worker", NULL, true, es); } @@ -2446,13 +2448,16 @@ show_hash_info(HashState *hashstate, ExplainState *es) if (es->format != EXPLAIN_FORMAT_TEXT) { - ExplainPropertyInteger("Hash Buckets", hinstrument.nbuckets, es); - ExplainPropertyInteger("Original Hash Buckets", - hinstrument.nbuckets_original, es); - ExplainPropertyInteger("Hash Batches", hinstrument.nbatch, es); - ExplainPropertyInteger("Original Hash Batches", - hinstrument.nbatch_original, es); - ExplainPropertyInteger("Peak Memory Usage", spacePeakKb, es); + ExplainPropertyInteger("Hash Buckets", NULL, + hinstrument.nbuckets, es); + ExplainPropertyInteger("Original Hash Buckets", NULL, + hinstrument.nbuckets_original, es); + ExplainPropertyInteger("Hash Batches", NULL, + hinstrument.nbatch, es); + ExplainPropertyInteger("Original Hash Batches", NULL, + hinstrument.nbatch_original, es); + ExplainPropertyInteger("Peak Memory Usage", "kB", + spacePeakKb, es); } else if (hinstrument.nbatch_original != hinstrument.nbatch || hinstrument.nbuckets_original != hinstrument.nbuckets) @@ -2485,9 +2490,9 @@ show_tidbitmap_info(BitmapHeapScanState *planstate, ExplainState *es) { if (es->format != EXPLAIN_FORMAT_TEXT) { - ExplainPropertyInteger("Exact Heap Blocks", + ExplainPropertyInteger("Exact Heap Blocks", NULL, planstate->exact_pages, es); - ExplainPropertyInteger("Lossy Heap Blocks", + ExplainPropertyInteger("Lossy Heap Blocks", NULL, planstate->lossy_pages, es); } else @@ -2530,9 +2535,9 @@ show_instrumentation_count(const char *qlabel, int which, if (nfiltered > 0 || es->format != EXPLAIN_FORMAT_TEXT) { if (nloops > 0) - ExplainPropertyFloat(qlabel, nfiltered / nloops, 0, es); + ExplainPropertyFloat(qlabel, NULL, nfiltered / nloops, 0, es); else - ExplainPropertyFloat(qlabel, 0.0, 0, es); + ExplainPropertyFloat(qlabel, NULL, 0.0, 0, es); } } @@ -2698,30 +2703,34 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage) } else { - ExplainPropertyInteger("Shared Hit Blocks", + ExplainPropertyInteger("Shared Hit Blocks", NULL, usage->shared_blks_hit, es); - ExplainPropertyInteger("Shared Read Blocks", + ExplainPropertyInteger("Shared Read Blocks", NULL, usage->shared_blks_read, es); - ExplainPropertyInteger("Shared Dirtied Blocks", + ExplainPropertyInteger("Shared Dirtied Blocks", NULL, usage->shared_blks_dirtied, es); - ExplainPropertyInteger("Shared Written Blocks", + ExplainPropertyInteger("Shared Written Blocks", NULL, usage->shared_blks_written, es); - ExplainPropertyInteger("Local Hit Blocks", + ExplainPropertyInteger("Local Hit Blocks", NULL, usage->local_blks_hit, es); - ExplainPropertyInteger("Local Read Blocks", + ExplainPropertyInteger("Local Read Blocks", NULL, usage->local_blks_read, es); - ExplainPropertyInteger("Local Dirtied Blocks", + ExplainPropertyInteger("Local Dirtied Blocks", NULL, usage->local_blks_dirtied, es); - ExplainPropertyInteger("Local Written Blocks", + ExplainPropertyInteger("Local Written Blocks", NULL, usage->local_blks_written, es); - ExplainPropertyInteger("Temp Read Blocks", + ExplainPropertyInteger("Temp Read Blocks", NULL, usage->temp_blks_read, es); - ExplainPropertyInteger("Temp Written Blocks", + ExplainPropertyInteger("Temp Written Blocks", NULL, usage->temp_blks_written, es); if (track_io_timing) { - ExplainPropertyFloat("I/O Read Time", INSTR_TIME_GET_MILLISEC(usage->blk_read_time), 3, es); - ExplainPropertyFloat("I/O Write Time", INSTR_TIME_GET_MILLISEC(usage->blk_write_time), 3, es); + ExplainPropertyFloat("I/O Read Time", "ms", + INSTR_TIME_GET_MILLISEC(usage->blk_read_time), + 3, es); + ExplainPropertyFloat("I/O Write Time", "ms", + INSTR_TIME_GET_MILLISEC(usage->blk_write_time), + 3, es); } } } @@ -3021,10 +3030,10 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors, if (node->onConflictAction != ONCONFLICT_NONE) { - ExplainProperty("Conflict Resolution", - node->onConflictAction == ONCONFLICT_NOTHING ? - "NOTHING" : "UPDATE", - false, es); + ExplainPropertyText("Conflict Resolution", + node->onConflictAction == ONCONFLICT_NOTHING ? + "NOTHING" : "UPDATE", + es); /* * Don't display arbiter indexes at all when DO NOTHING variant @@ -3055,8 +3064,10 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors, other_path = mtstate->ps.instrument->nfiltered2; insert_path = total - other_path; - ExplainPropertyFloat("Tuples Inserted", insert_path, 0, es); - ExplainPropertyFloat("Conflicting Tuples", other_path, 0, es); + ExplainPropertyFloat("Tuples Inserted", NULL, + insert_path, 0, es); + ExplainPropertyFloat("Conflicting Tuples", NULL, + other_path, 0, es); } } @@ -3259,18 +3270,23 @@ ExplainPropertyListNested(const char *qlabel, List *data, ExplainState *es) * If "numeric" is true, the value is a number (or other value that * doesn't need quoting in JSON). * + * If unit is is non-NULL the text format will display it after the value. + * * This usually should not be invoked directly, but via one of the datatype * specific routines ExplainPropertyText, ExplainPropertyInteger, etc. */ static void -ExplainProperty(const char *qlabel, const char *value, bool numeric, - ExplainState *es) +ExplainProperty(const char *qlabel, const char *unit, const char *value, + bool numeric, ExplainState *es) { switch (es->format) { case EXPLAIN_FORMAT_TEXT: appendStringInfoSpaces(es->str, es->indent * 2); - appendStringInfo(es->str, "%s: %s\n", qlabel, value); + if (unit) + appendStringInfo(es->str, "%s: %s %s\n", qlabel, value, unit); + else + appendStringInfo(es->str, "%s: %s\n", qlabel, value); break; case EXPLAIN_FORMAT_XML: @@ -3315,19 +3331,20 @@ ExplainProperty(const char *qlabel, const char *value, bool numeric, void ExplainPropertyText(const char *qlabel, const char *value, ExplainState *es) { - ExplainProperty(qlabel, value, false, es); + ExplainProperty(qlabel, NULL, value, false, es); } /* * Explain an integer-valued property. */ void -ExplainPropertyInteger(const char *qlabel, int64 value, ExplainState *es) +ExplainPropertyInteger(const char *qlabel, const char *unit, int64 value, + ExplainState *es) { char buf[32]; snprintf(buf, sizeof(buf), INT64_FORMAT, value); - ExplainProperty(qlabel, buf, true, es); + ExplainProperty(qlabel, unit, buf, true, es); } /* @@ -3335,13 +3352,13 @@ ExplainPropertyInteger(const char *qlabel, int64 value, ExplainState *es) * fractional digits. */ void -ExplainPropertyFloat(const char *qlabel, double value, int ndigits, - ExplainState *es) +ExplainPropertyFloat(const char *qlabel, const char *unit, double value, + int ndigits, ExplainState *es) { char buf[256]; snprintf(buf, sizeof(buf), "%.*f", ndigits, value); - ExplainProperty(qlabel, buf, true, es); + ExplainProperty(qlabel, unit, buf, true, es); } /* @@ -3350,7 +3367,7 @@ ExplainPropertyFloat(const char *qlabel, double value, int ndigits, void ExplainPropertyBool(const char *qlabel, bool value, ExplainState *es) { - ExplainProperty(qlabel, value ? "true" : "false", true, es); + ExplainProperty(qlabel, NULL, value ? "true" : "false", true, es); } /* diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index 22a2004381b..6d3d94cae26 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -93,10 +93,10 @@ extern void ExplainPropertyListNested(const char *qlabel, List *data, ExplainState *es); extern void ExplainPropertyText(const char *qlabel, const char *value, ExplainState *es); -extern void ExplainPropertyInteger(const char *qlabel, int64 value, - ExplainState *es); -extern void ExplainPropertyFloat(const char *qlabel, double value, int ndigits, - ExplainState *es); +extern void ExplainPropertyInteger(const char *qlabel, const char *unit, + int64 value, ExplainState *es); +extern void ExplainPropertyFloat(const char *qlabel, const char *unit, + double value, int ndigits, ExplainState *es); extern void ExplainPropertyBool(const char *qlabel, bool value, ExplainState *es); -- 2.15.1.354.g95ec6b1b33.dirty