/* * ExecutorEnd hook: log results if needed */ static void explain_ExecutorEnd(QueryDesc *queryDesc) { if (queryDesc->totaltime && auto_explain_enabled()) { double msec; /* * Make sure stats accumulation is done. (Note: it's okay if several * levels of hook all do this.) */ InstrEndLoop(queryDesc->totaltime); /* Log plan if duration is exceeded. */ msec = queryDesc->totaltime->total * 1000.0; if (msec >= auto_explain_log_min_duration) { ExplainState es; ExplainInitState(&es); es.analyze = (queryDesc->instrument_options && auto_explain_log_analyze); es.verbose = auto_explain_log_verbose; es.buffers = (es.analyze && auto_explain_log_buffers); es.format = auto_explain_log_format; ExplainBeginOutput(&es); ExplainQueryText(&es, queryDesc); ExplainPrintPlan(&es, queryDesc); ExplainEndOutput(&es); /* Remove last line break */ if (es.str->len > 0 && es.str->data[es.str->len - 1] == '\n') es.str->data[--es.str->len] = '\0'; /* * Note: we rely on the existing logging of context or * debug_query_string to identify just which statement is being * reported. This isn't ideal but trying to do it here would * often result in duplication. */ ereport(LOG, (errmsg("duration: %.3f ms plan:\n%s", msec, es.str->data), errhidestmt(true))); pfree(es.str->data); } } if (prev_ExecutorEnd) prev_ExecutorEnd(queryDesc); else standard_ExecutorEnd(queryDesc); }
/* * ExecutorEnd hook: log results if needed */ static void explain_ExecutorEnd(QueryDesc *queryDesc) { if (queryDesc->totaltime && auto_explain_enabled() && current_query_sampled) { double msec; /* * Make sure stats accumulation is done. (Note: it's okay if several * levels of hook all do this.) */ InstrEndLoop(queryDesc->totaltime); /* Log plan if duration is exceeded. */ msec = queryDesc->totaltime->total * 1000.0; if (msec >= auto_explain_log_min_duration) { ExplainState *es = NewExplainState(); es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze); es->verbose = auto_explain_log_verbose; es->buffers = (es->analyze && auto_explain_log_buffers); es->timing = (es->analyze && auto_explain_log_timing); es->summary = es->analyze; es->format = auto_explain_log_format; ExplainBeginOutput(es); ExplainQueryText(es, queryDesc); ExplainPrintPlan(es, queryDesc); if (es->analyze && auto_explain_log_triggers) ExplainPrintTriggers(es, queryDesc); if (es->costs) ExplainPrintJITSummary(es, queryDesc); ExplainEndOutput(es); /* Remove last line break */ if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n') es->str->data[--es->str->len] = '\0'; /* Fix JSON to output an object */ if (auto_explain_log_format == EXPLAIN_FORMAT_JSON) { es->str->data[0] = '{'; es->str->data[es->str->len - 1] = '}'; } /* * Note: we rely on the existing logging of context or * debug_query_string to identify just which statement is being * reported. This isn't ideal but trying to do it here would * often result in duplication. */ ereport(auto_explain_log_level, (errmsg("duration: %.3f ms plan:\n%s", msec, es->str->data), errhidestmt(true))); pfree(es->str->data); } } if (prev_ExecutorEnd) prev_ExecutorEnd(queryDesc); else standard_ExecutorEnd(queryDesc); }