From fc656131a2920a8c8a583d749cb7c18c3c57fbfa Mon Sep 17 00:00:00 2001 From: Rafael Castro Date: Wed, 6 Dec 2023 19:18:32 -0300 Subject: [PATCH v34 2/2] Log plan along with instrumentation details Instrumentation is enabled when using EXPLAIN ANALYZE or with auto_explain and the proper settings. A plan output with instrumentation also contains details for nodes that weren't executed yet, depicted with (never executed). This incremental patch also includes a new visualization, depicted with (in progress) that denotes nodes currently being executed, ie, function InstrStartNode was called but InstrStopNode not yet. --- src/backend/commands/explain.c | 131 +++++++++++++++++++++++------- src/backend/executor/instrument.c | 20 ++++- src/include/executor/instrument.h | 1 + 3 files changed, 120 insertions(+), 32 deletions(-) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index a3c0a6a3d9..7369a75cf7 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -1066,8 +1066,17 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es) char *relname; char *conname = NULL; - /* Must clean up instrumentation state */ - InstrEndLoop(instr); + /* Signaled explain, clone instrumentation */ + if (es->signaled) { + instr = palloc(sizeof(*instr)); + *instr = *(rInfo->ri_TrigInstrument + nt); + /* Force end loop even if node is in progress */ + InstrEndLoopForce(instr); + } + else { + instr = rInfo->ri_TrigInstrument + nt; + InstrEndLoop(instr); + } /* * We ignore triggers that were never invoked; they likely aren't @@ -1230,6 +1239,7 @@ ExplainNode(PlanState *planstate, List *ancestors, const char *operation = NULL; const char *custom_name = NULL; ExplainWorkersState *save_workers_state = es->workers_state; + Instrumentation *local_instr = NULL; int save_indent = es->indent; bool haschildren; @@ -1682,37 +1692,63 @@ 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 ... - * This cleanup should not be done when the query has already been - * executed and explain has been called by signal, as the target query - * may use instrumentation and clean itself up. * * 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. + * + * For regular explains instrumentation clean up is called directly in + * the main instrumentation objects. Signaled plan logging needs to clone + * instrumentation object and forcibly end the loop in nodes that may + * be running. */ - if (planstate->instrument && !es->signaled) - InstrEndLoop(planstate->instrument); + if (planstate->instrument) { + /* In flight explain. Clone instrumentation */ + if (es->signaled) { + local_instr = palloc(sizeof(*local_instr)); + *local_instr = *planstate->instrument; + /* Force end loop even if node is in progress */ + InstrEndLoopForce(local_instr); + } + /* Use main instrumentation */ + else { + local_instr = planstate->instrument; + InstrEndLoop(local_instr); + } + } if (es->analyze && - planstate->instrument && planstate->instrument->nloops > 0) + local_instr && local_instr->nloops > 0) { - double nloops = planstate->instrument->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; + double nloops = local_instr->nloops; + double startup_ms = 1000.0 * local_instr->startup / nloops; + double total_ms = 1000.0 * local_instr->total / nloops; + double rows = local_instr->ntuples / nloops; if (es->format == EXPLAIN_FORMAT_TEXT) { if (es->timing) - appendStringInfo(es->str, + /* Node in progress */ + if (!INSTR_TIME_IS_ZERO(planstate->instrument->starttime)) + appendStringInfo(es->str, + " (actual time=%.3f..%.3f rows=%.0f loops=%.0f) (in progress)", + startup_ms, total_ms, rows, nloops); + else + appendStringInfo(es->str, " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)", startup_ms, total_ms, rows, nloops); else - appendStringInfo(es->str, - " (actual rows=%.0f loops=%.0f)", - rows, nloops); + /* Node in progress */ + if (!INSTR_TIME_IS_ZERO(planstate->instrument->starttime)) + appendStringInfo(es->str, + " (actual rows=%.0f loops=%.0f) (in progress)", + rows, nloops); + else + appendStringInfo(es->str, + " (actual rows=%.0f loops=%.0f)", + rows, nloops); } else { @@ -1848,7 +1884,7 @@ ExplainNode(PlanState *planstate, List *ancestors, planstate, es); if (es->analyze) ExplainPropertyFloat("Heap Fetches", NULL, - planstate->instrument->ntuples2, 0, es); + local_instr->ntuples2, 0, es); break; case T_BitmapIndexScan: show_scan_qual(((BitmapIndexScan *) plan)->indexqualorig, @@ -2143,10 +2179,10 @@ ExplainNode(PlanState *planstate, List *ancestors, } /* Show buffer/WAL usage */ - if (es->buffers && planstate->instrument) - show_buffer_usage(es, &planstate->instrument->bufusage, false); - if (es->wal && planstate->instrument) - show_wal_usage(es, &planstate->instrument->walusage); + if (es->buffers && local_instr) + show_buffer_usage(es, &local_instr->bufusage, false); + if (es->wal && local_instr) + show_wal_usage(es, &local_instr->walusage); /* Prepare per-worker buffer/WAL usage */ if (es->workers_state && (es->buffers || es->wal) && es->verbose) @@ -4127,11 +4163,22 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors, double total; double insert_path; double other_path; - - InstrEndLoop(outerPlanState(mtstate)->instrument); + Instrumentation *local_instr; + + /* Signaled explain, clone instrumentation */ + if (es->signaled) { + local_instr = palloc(sizeof(*local_instr)); + *local_instr = *outerPlanState(mtstate)->instrument; + /* Force end loop even if node is in progress */ + InstrEndLoopForce(local_instr); + } + else { + local_instr = outerPlanState(mtstate)->instrument; + InstrEndLoop(local_instr); + } /* count the number of source rows */ - total = outerPlanState(mtstate)->instrument->ntuples; + total = local_instr->ntuples; other_path = mtstate->ps.instrument->ntuples2; insert_path = total - other_path; @@ -4143,7 +4190,7 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors, } else if (node->operation == CMD_MERGE) { - /* EXPLAIN ANALYZE display of tuples processed */ + /* Signaled explain, clone instrumentation */ if (es->analyze && mtstate->ps.instrument) { double total; @@ -4151,11 +4198,22 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors, double update_path; double delete_path; double skipped_path; - - InstrEndLoop(outerPlanState(mtstate)->instrument); + Instrumentation *local_instr; + + /* In flight explain. Clone instrumentation */ + if (es->signaled) { + local_instr = palloc(sizeof(*local_instr)); + *local_instr = *outerPlanState(mtstate)->instrument; + /* Force end loop even if node is in progress */ + InstrEndLoopForce(local_instr); + } + else { + local_instr = outerPlanState(mtstate)->instrument; + InstrEndLoop(local_instr); + } /* count the number of source rows */ - total = outerPlanState(mtstate)->instrument->ntuples; + total = local_instr->ntuples; insert_path = mtstate->mt_merge_inserted; update_path = mtstate->mt_merge_updated; delete_path = mtstate->mt_merge_deleted; @@ -5228,6 +5286,18 @@ ProcessLogQueryPlanInterrupt(void) es->verbose = true; es->signaled = true; + /* + * Adjust instrumentation related settings based + * on QueryDesc object. + */ + es->analyze = ActiveQueryDesc->instrument_options; + es->buffers = (ActiveQueryDesc->instrument_options & + INSTRUMENT_BUFFERS) != 0; + es->wal = (ActiveQueryDesc->instrument_options & + INSTRUMENT_WAL) != 0; + es->timing = (ActiveQueryDesc->instrument_options & + INSTRUMENT_TIMER) != 0; + ExplainAssembleLogOutput(es, ActiveQueryDesc, EXPLAIN_FORMAT_TEXT, 0, -1); ereport(LOG_SERVER_ONLY, @@ -5272,10 +5342,11 @@ pg_log_query_plan(PG_FUNCTION_ARGS) } be_status = pgstat_get_beentry_by_backend_id(proc->backendId); - if (be_status->st_backendType != B_BACKEND) + if (be_status->st_backendType != B_BACKEND && + be_status->st_backendType != B_BG_WORKER) { ereport(WARNING, - (errmsg("PID %d is not a PostgreSQL client backend process", pid))); + (errmsg("PID %d is not a PostgreSQL client backend or background worker process", pid))); PG_RETURN_BOOL(false); } diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index c383f34c06..7000e4d8bc 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -25,6 +25,8 @@ static WalUsage save_pgWalUsage; static void BufferUsageAdd(BufferUsage *dst, const BufferUsage *add); static void WalUsageAdd(WalUsage *dst, WalUsage *add); +static void InstrEndLoopInternal(Instrumentation *instr, bool force); + /* Allocate new instrumentation structure(s) */ Instrumentation * @@ -137,7 +139,7 @@ InstrUpdateTupleCount(Instrumentation *instr, double nTuples) /* Finish a run cycle for a plan node */ void -InstrEndLoop(Instrumentation *instr) +InstrEndLoopInternal(Instrumentation *instr, bool force) { double totaltime; @@ -145,7 +147,7 @@ InstrEndLoop(Instrumentation *instr) if (!instr->running) return; - if (!INSTR_TIME_IS_ZERO(instr->starttime)) + if (!INSTR_TIME_IS_ZERO(instr->starttime) && !force) elog(ERROR, "InstrEndLoop called on running node"); /* Accumulate per-cycle statistics into totals */ @@ -164,6 +166,20 @@ InstrEndLoop(Instrumentation *instr) instr->tuplecount = 0; } +/* Safely finish a run cycle for a plan node */ +void +InstrEndLoop(Instrumentation *instr) +{ + InstrEndLoopInternal(instr, false); +} + +/* Forcibly finish a run cycle for a plan node */ +void +InstrEndLoopForce(Instrumentation *instr) +{ + InstrEndLoopInternal(instr, true); +} + /* aggregate instrumentation information */ void InstrAggNode(Instrumentation *dst, Instrumentation *add) diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index d5d69941c5..b7c98dfd78 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -108,6 +108,7 @@ extern void InstrStartNode(Instrumentation *instr); extern void InstrStopNode(Instrumentation *instr, double nTuples); extern void InstrUpdateTupleCount(Instrumentation *instr, double nTuples); extern void InstrEndLoop(Instrumentation *instr); +extern void InstrEndLoopForce(Instrumentation *instr); extern void InstrAggNode(Instrumentation *dst, Instrumentation *add); extern void InstrStartParallelQuery(void); extern void InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage); -- 2.32.0 (Apple Git-132)