diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index 61da6a2..967cbd9 100644 --- a/contrib/auto_explain/auto_explain.c +++ b/contrib/auto_explain/auto_explain.c @@ -23,6 +23,7 @@ static int auto_explain_log_min_duration = -1; /* msec or -1 */ static bool auto_explain_log_analyze = false; static bool auto_explain_log_verbose = false; static bool auto_explain_log_buffers = false; +static bool auto_explain_log_rows = false; static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT; static bool auto_explain_log_nested_statements = false; @@ -133,6 +134,17 @@ _PG_init(void) NULL, NULL); + DefineCustomBoolVariable("auto_explain.log_rows", + "Collect row counts.", + NULL, + &auto_explain_log_rows, + true, + PGC_SUSET, + 0, + NULL, + NULL, + NULL); + EmitWarningsOnPlaceholders("auto_explain"); /* Install hooks. */ @@ -168,9 +180,13 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags) if (auto_explain_enabled()) { /* Enable per-node instrumentation iff log_analyze is required. */ - if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0) + if ((eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0) { - queryDesc->instrument_options |= INSTRUMENT_TIMER; + if (auto_explain_log_analyze) + queryDesc->instrument_options |= INSTRUMENT_TIMER; + else if (auto_explain_log_rows) + queryDesc->instrument_options |= INSTRUMENT_ROWS; + if (auto_explain_log_buffers) queryDesc->instrument_options |= INSTRUMENT_BUFFERS; } diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index 8a9c9de..dc373e7 100644 --- a/doc/src/sgml/ref/explain.sgml +++ b/doc/src/sgml/ref/explain.sgml @@ -40,6 +40,7 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] statementboolean ] COSTS [ boolean ] BUFFERS [ boolean ] + ROWS [ boolean ] FORMAT { TEXT | XML | JSON | YAML } @@ -172,6 +173,18 @@ ROLLBACK; + ROWS + + + Include information on the number of rows produced by node. This + information is also displayed when ANALYZE is used, + but using only ROWS without ANALYZE + involves less overhead. It defaults to FALSE. + + + + + FORMAT diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index e35ac59..5b01bc3 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -133,6 +133,8 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString, es.costs = defGetBoolean(opt); else if (strcmp(opt->defname, "buffers") == 0) es.buffers = defGetBoolean(opt); + else if (strcmp(opt->defname, "rows") == 0) + es.rows = defGetBoolean(opt); else if (strcmp(opt->defname, "format") == 0) { char *p = defGetString(opt); @@ -362,6 +364,9 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ExplainState *es, if (es->analyze) instrument_option |= INSTRUMENT_TIMER; + else if (es->rows) + instrument_option |= INSTRUMENT_ROWS; + if (es->buffers) instrument_option |= INSTRUMENT_BUFFERS; @@ -380,7 +385,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ExplainState *es, None_Receiver, params, instrument_option); /* Select execution options */ - if (es->analyze) + if (instrument_option != 0) eflags = 0; /* default run-to-completion flags */ else eflags = EXEC_FLAG_EXPLAIN_ONLY; @@ -389,7 +394,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ExplainState *es, ExecutorStart(queryDesc, eflags); /* Execute the plan for statistics if asked for */ - if (es->analyze) + if (instrument_option != 0) { /* run the plan */ ExecutorRun(queryDesc, ForwardScanDirection, 0L); @@ -956,29 +961,42 @@ ExplainNode(PlanState *planstate, List *ancestors, if (es->format == EXPLAIN_FORMAT_TEXT) { - appendStringInfo(es->str, - " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)", - startup_sec, total_sec, rows, nloops); + if (planstate->instrument->need_timer) + appendStringInfo(es->str, + " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)", + startup_sec, total_sec, rows, nloops); + else + appendStringInfo(es->str, + " (actual rows=%.0f loops=%.0f)", + rows, nloops); } else { - ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es); - ExplainPropertyFloat("Actual Total Time", total_sec, 3, es); + if (planstate->instrument->need_timer) + { + ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es); + ExplainPropertyFloat("Actual Total Time", total_sec, 3, es); + } ExplainPropertyFloat("Actual Rows", rows, 0, es); ExplainPropertyFloat("Actual Loops", nloops, 0, es); } } else if (es->analyze) { + if (es->format == EXPLAIN_FORMAT_TEXT) appendStringInfo(es->str, " (never executed)"); - else + else if (planstate->instrument->need_timer) { ExplainPropertyFloat("Actual Startup Time", 0.0, 3, es); ExplainPropertyFloat("Actual Total Time", 0.0, 3, es); + } + else + { ExplainPropertyFloat("Actual Rows", 0.0, 0, es); ExplainPropertyFloat("Actual Loops", 0.0, 0, es); } + } /* in text format, first line ends here */ diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index dde73b7..ec15656 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -29,17 +29,19 @@ InstrAlloc(int n, int instrument_options) { Instrumentation *instr; - /* timer is always required for now */ - Assert(instrument_options & INSTRUMENT_TIMER); - /* initialize all fields to zeroes, then modify as needed */ instr = palloc0(n * sizeof(Instrumentation)); - if (instrument_options & INSTRUMENT_BUFFERS) + if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER)) { int i; + bool need_buffers = instrument_options & INSTRUMENT_BUFFERS; + bool need_timer = instrument_options & INSTRUMENT_TIMER; for (i = 0; i < n; i++) - instr[i].need_bufusage = true; + { + instr[i].need_bufusage = need_buffers; + instr[i].need_timer = need_timer; + } } return instr; @@ -49,7 +51,7 @@ InstrAlloc(int n, int instrument_options) void InstrStartNode(Instrumentation *instr) { - if (INSTR_TIME_IS_ZERO(instr->starttime)) + if (instr->need_timer && INSTR_TIME_IS_ZERO(instr->starttime)) INSTR_TIME_SET_CURRENT(instr->starttime); else elog(DEBUG2, "InstrStartNode called twice in a row"); @@ -68,16 +70,20 @@ InstrStopNode(Instrumentation *instr, double nTuples) /* count the returned tuples */ instr->tuplecount += nTuples; - if (INSTR_TIME_IS_ZERO(instr->starttime)) + /* let's update the time only if the timer was requested */ + if (instr->need_timer) { - elog(DEBUG2, "InstrStopNode called without start"); - return; - } + if (INSTR_TIME_IS_ZERO(instr->starttime)) + { + elog(DEBUG2, "InstrStopNode called without start"); + return; + } - INSTR_TIME_SET_CURRENT(endtime); - INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime); + INSTR_TIME_SET_CURRENT(endtime); + INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime); - INSTR_TIME_SET_ZERO(instr->starttime); + INSTR_TIME_SET_ZERO(instr->starttime); + } /* Add delta of buffer usage since entry to node's totals */ if (instr->need_bufusage) diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index 3443259..a64889c 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -28,7 +28,8 @@ typedef struct ExplainState StringInfo str; /* output buffer */ /* options */ bool verbose; /* be verbose */ - bool analyze; /* print actual times */ + bool analyze; /* print actual times and row counts */ + bool rows; /* print actual row counts */ bool costs; /* print costs */ bool buffers; /* print buffer usage */ ExplainFormat format; /* output format */ diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index 9ecb544..084302e 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -31,14 +31,16 @@ typedef struct BufferUsage /* Flag bits included in InstrAlloc's instrument_options bitmask */ typedef enum InstrumentOption { - INSTRUMENT_TIMER = 1 << 0, /* needs timer */ + INSTRUMENT_TIMER = 1 << 0, /* needs timer (and row counts) */ INSTRUMENT_BUFFERS = 1 << 1, /* needs buffer usage */ + INSTRUMENT_ROWS = 1 << 2, /* needs row count */ INSTRUMENT_ALL = 0x7FFFFFFF } InstrumentOption; typedef struct Instrumentation { /* Parameters set at node creation: */ + bool need_timer; /* TRUE if we need timer data */ bool need_bufusage; /* TRUE if we need buffer usage data */ /* Info about current plan cycle: */ bool running; /* TRUE if we've completed first tuple */