diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index 2a184ed..d2f46bb 100644 --- a/contrib/auto_explain/auto_explain.c +++ b/contrib/auto_explain/auto_explain.c @@ -288,7 +288,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc) * Make sure stats accumulation is done. (Note: it's okay if several * levels of hook all do this.) */ - InstrEndLoop(queryDesc->totaltime); + InstrEndLoop(queryDesc->totaltime, false); /* Log plan if duration is exceeded. */ msec = queryDesc->totaltime->total * 1000.0; diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c index 59b8a2e..d90fc6d 100644 --- a/contrib/pg_stat_statements/pg_stat_statements.c +++ b/contrib/pg_stat_statements/pg_stat_statements.c @@ -926,7 +926,7 @@ pgss_ExecutorEnd(QueryDesc *queryDesc) * Make sure stats accumulation is done. (Note: it's okay if several * levels of hook all do this.) */ - InstrEndLoop(queryDesc->totaltime); + InstrEndLoop(queryDesc->totaltime, false); pgss_store(queryDesc->sourceText, queryId, diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 5d06fa4..e5a28a9 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -654,7 +654,7 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es) char *conname = NULL; /* Must clean up instrumentation state */ - InstrEndLoop(instr); + InstrEndLoop(instr, false); /* * We ignore triggers that were never invoked; they likely aren't @@ -1233,62 +1233,75 @@ ExplainNode(PlanState *planstate, List *ancestors, } } - /* - * We have to forcibly clean up the instrumentation state because we - * haven't done ExecutorEnd yet. This is pretty grotty ... - * - * Note: contrib/auto_explain could cause instrumentation to be set up - * even though we didn't ask for it here. Be careful not to print any - * instrumentation results the user didn't ask for. But we do the - * InstrEndLoop call anyway, if possible, to reduce the number of cases - * auto_explain has to contend with. - */ if (planstate->instrument) - InstrEndLoop(planstate->instrument); - - if (es->analyze && - 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 rows = planstate->instrument->ntuples / nloops; + /* + * We have to forcibly clean up the instrumentation state because we + * haven't done ExecutorEnd yet. This is pretty grotty ... + * + * Note: contrib/auto_explain could cause instrumentation to be set up + * even though we didn't ask for it here. Be careful not to print any + * instrumentation results the user didn't ask for. But we do the + * InstrEndLoop call anyway, if possible, to reduce the number of cases + * auto_explain has to contend with. + */ + InstrEndLoop(planstate->instrument, es->running); - if (es->format == EXPLAIN_FORMAT_TEXT) - { - if (es->timing) - 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 + if (es->analyze) { - if (es->timing) + double nloops = planstate->instrument->nloops; + + if (es->running && planstate->instrument->running) + nloops += 1; /* so we can display something */ + + if (nloops > 0) { - ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es); - ExplainPropertyFloat("Actual Total Time", total_sec, 3, es); + double startup_sec = 1000.0 * planstate->instrument->startup / nloops; + double total_sec = 1000.0 * planstate->instrument->total / nloops; + double rows = planstate->instrument->ntuples / nloops; + double percent_done = 100.0 * rows / plan->plan_rows; + + if (es->format == EXPLAIN_FORMAT_TEXT) + { + if (es->timing) + appendStringInfo(es->str, + " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)", + startup_sec, total_sec, rows, + planstate->instrument->nloops); + else + appendStringInfo(es->str, + " (actual rows=%.0f loops=%.0f)", + rows, planstate->instrument->nloops); + + if (es->running) + appendStringInfo(es->str, " %.1f%%", percent_done); + } + else + { + if (es->timing) + { + 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", planstate->instrument->nloops, 0, es); + } } - ExplainPropertyFloat("Actual Rows", rows, 0, es); - ExplainPropertyFloat("Actual Loops", nloops, 0, es); - } - } - else if (es->analyze) - { - if (es->format == EXPLAIN_FORMAT_TEXT) - appendStringInfoString(es->str, " (never executed)"); - else - { - if (es->timing) + else { - ExplainPropertyFloat("Actual Startup Time", 0.0, 3, es); - ExplainPropertyFloat("Actual Total Time", 0.0, 3, es); + if (es->format == EXPLAIN_FORMAT_TEXT) + appendStringInfoString(es->str, " (never executed)"); + else + { + if (es->timing) + { + ExplainPropertyFloat("Actual Startup Time", 0.0, 3, es); + ExplainPropertyFloat("Actual Total Time", 0.0, 3, es); + } + ExplainPropertyFloat("Actual Rows", 0.0, 0, es); + ExplainPropertyFloat("Actual Loops", 0.0, 0, es); + } } - ExplainPropertyFloat("Actual Rows", 0.0, 0, es); - ExplainPropertyFloat("Actual Loops", 0.0, 0, es); } } @@ -2650,7 +2663,7 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors, double insert_path; double other_path; - InstrEndLoop(mtstate->mt_plans[0]->instrument); + InstrEndLoop(mtstate->mt_plans[0]->instrument, es->running); /* count the number of source rows */ total = mtstate->mt_plans[0]->instrument->ntuples; diff --git a/src/backend/executor/execAmi.c b/src/backend/executor/execAmi.c index 93e1e9a..33162f2 100644 --- a/src/backend/executor/execAmi.c +++ b/src/backend/executor/execAmi.c @@ -72,7 +72,7 @@ ExecReScan(PlanState *node) { /* If collecting timing stats, update them */ if (node->instrument) - InstrEndLoop(node->instrument); + InstrEndLoop(node->instrument, false); /* * If we have changed parameters, propagate that info. diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index f5351eb..132153e 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -100,7 +100,7 @@ InstrStopNode(Instrumentation *instr, double nTuples) /* Finish a run cycle for a plan node */ void -InstrEndLoop(Instrumentation *instr) +InstrEndLoop(Instrumentation *instr, bool partial_run) { double totaltime; @@ -108,7 +108,7 @@ InstrEndLoop(Instrumentation *instr) if (!instr->running) return; - if (!INSTR_TIME_IS_ZERO(instr->starttime)) + if (!INSTR_TIME_IS_ZERO(instr->starttime) && !partial_run) elog(ERROR, "InstrEndLoop called on running node"); /* Accumulate per-cycle statistics into totals */ @@ -117,11 +117,15 @@ InstrEndLoop(Instrumentation *instr) instr->startup += instr->firsttuple; instr->total += totaltime; instr->ntuples += instr->tuplecount; - instr->nloops += 1; /* Reset for next cycle (if any) */ - instr->running = false; - INSTR_TIME_SET_ZERO(instr->starttime); + if (!partial_run) + { + instr->nloops += 1; + + instr->running = false; + INSTR_TIME_SET_ZERO(instr->starttime); + } INSTR_TIME_SET_ZERO(instr->counter); instr->firsttuple = 0; instr->tuplecount = 0; diff --git a/src/backend/utils/adt/cmdstatus.c b/src/backend/utils/adt/cmdstatus.c index 5078100..b969907 100644 --- a/src/backend/utils/adt/cmdstatus.c +++ b/src/backend/utils/adt/cmdstatus.c @@ -95,7 +95,12 @@ typedef struct CmdInfoStack { } CmdInfoStack; +/* GUCs */ int cmdstatus_interrupt_timeout = CMD_STATUS_DEFAULT_INTERRUPT_TIMEOUT; +bool cmdstatus_analyze = false; +bool cmdstatus_instrument_timer = false; +bool cmdstatus_instrument_rows = false; +bool cmdstatus_instrument_buffers = false; /* The array of slots pre-allocated on shared memory. */ static volatile dsm_handle *CmdStatusSlots = NULL; @@ -106,8 +111,10 @@ static volatile dsm_handle *MyCmdStatusSlot = NULL; static CmdInfoStack *current_query_stack = NULL; static int query_stack_size = 0; /* XXX not really used */ +static ExecutorStart_hook_type prev_ExecutorStart = NULL; static ExecutorRun_hook_type prev_ExecutorRun = NULL; +static void cmdstatus_ExecutorStart(QueryDesc *queryDesc, int eflags); static void cmdstatus_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, long count); @@ -162,12 +169,42 @@ CmdStatusInit(int css_idx) on_shmem_exit(CleanupCmdStatusSlot, (Datum) 0); /* also install executor hooks */ + prev_ExecutorStart = ExecutorStart_hook; + ExecutorStart_hook = cmdstatus_ExecutorStart; + prev_ExecutorRun = ExecutorRun_hook; ExecutorRun_hook = cmdstatus_ExecutorRun; } + +/* + * The ExecutorStart hook. + * + * Turns on query instrumentation options based on configuration setting. + */ +static void +cmdstatus_ExecutorStart(QueryDesc *queryDesc, int eflags) +{ + if (cmdstatus_analyze) + { + if (cmdstatus_instrument_timer) + queryDesc->instrument_options |= INSTRUMENT_TIMER; + + if (cmdstatus_instrument_rows) + queryDesc->instrument_options |= INSTRUMENT_ROWS; + + if (cmdstatus_instrument_buffers) + queryDesc->instrument_options |= INSTRUMENT_BUFFERS; + } + + if (prev_ExecutorStart) + prev_ExecutorStart(queryDesc, eflags); + else + standard_ExecutorStart(queryDesc, eflags); +} + /* - * The executor hook. + * The ExecutorRun hook. * * Accumulates the query descriptors on the program stack and takes care of * popping the current frame when leaving the function ab-/normally. @@ -217,9 +254,11 @@ explain_query(QueryDesc *queryDesc) ExplainState *es; es = NewExplainState(); - es->analyze = false; + es->running = true; + es->analyze = cmdstatus_analyze; + es->timing = cmdstatus_instrument_timer; es->verbose = false; - es->buffers = false; + es->buffers = cmdstatus_instrument_buffers; es->format = EXPLAIN_FORMAT_TEXT; ExplainBeginOutput(es); diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c index 7cac9d3..21054de 100644 --- a/src/backend/utils/misc/guc.c +++ b/src/backend/utils/misc/guc.c @@ -1619,6 +1619,46 @@ static struct config_bool ConfigureNamesBool[] = NULL, NULL, NULL }, + { + {"cmdstatus_analyze", PGC_USERSET, STATS, + gettext_noop("Automatically instrument all queries for extraction of EXPLAIN ANALYZE plans with pg_cmdstatus() function."), + NULL, + }, + &cmdstatus_analyze, + false, + NULL, NULL, NULL + }, + + { + {"cmdstatus_instrument_timer", PGC_USERSET, STATS, + gettext_noop("Automatically instrument all queries for timing, requires cmdstatus_analyze=on."), + NULL, + }, + &cmdstatus_instrument_timer, + false, + NULL, NULL, NULL + }, + + { + {"cmdstatus_instrument_rows", PGC_USERSET, STATS, + gettext_noop("Automatically instrument all queries for tracking row counts, requires cmdstatus_analyze=on."), + NULL, + }, + &cmdstatus_instrument_rows, + false, + NULL, NULL, NULL + }, + + { + {"cmdstatus_instrument_buffers", PGC_USERSET, STATS, + gettext_noop("Automatically instrument all queries for tracking buffers usage, requires cmdstatus_analyze=on."), + NULL, + }, + &cmdstatus_instrument_buffers, + false, + NULL, NULL, NULL + }, + /* End-of-list marker */ { {NULL, 0, 0, NULL, NULL}, NULL, false, NULL, NULL, NULL diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index c33e585..a275f51 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -471,6 +471,13 @@ #log_statement_stats = off +# - Automatic Query Instrumentation - + +#cmdstatus_analyze = off +#cmdstatus_instrument_timer = off +#cmdstatus_instrument_rows = off +#cmdstatus_instrument_buffers = off + #------------------------------------------------------------------------------ # AUTOVACUUM PARAMETERS #------------------------------------------------------------------------------ diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index 26fcc5b..3334f41 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -35,6 +35,7 @@ typedef struct ExplainState bool timing; /* print detailed node timing */ bool summary; /* print total planning and execution timing */ ExplainFormat format; /* output format */ + bool running; /* explain on a running statement */ /* other states */ PlannedStmt *pstmt; /* top of plan */ List *rtable; /* range table */ diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index c9a2129..a18b089 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -68,6 +68,6 @@ extern PGDLLIMPORT BufferUsage pgBufferUsage; extern Instrumentation *InstrAlloc(int n, int instrument_options); extern void InstrStartNode(Instrumentation *instr); extern void InstrStopNode(Instrumentation *instr, double nTuples); -extern void InstrEndLoop(Instrumentation *instr); +extern void InstrEndLoop(Instrumentation *instr, bool partial_run); #endif /* INSTRUMENT_H */ diff --git a/src/include/utils/cmdstatus.h b/src/include/utils/cmdstatus.h index d6379f0..a9a508a 100644 --- a/src/include/utils/cmdstatus.h +++ b/src/include/utils/cmdstatus.h @@ -16,6 +16,10 @@ #define CMD_STATUS_DEFAULT_INTERRUPT_TIMEOUT 10 /* milliseconds */ extern int cmdstatus_interrupt_timeout; +extern bool cmdstatus_analyze; +extern bool cmdstatus_instrument_timer; +extern bool cmdstatus_instrument_rows; +extern bool cmdstatus_instrument_buffers; extern Size CmdStatusShmemSize(void); extern void CmdStatusShmemInit(void);