/*
* executor_end hook: log results if needed
*/
static void
explain_executor_end(struct qry_desc *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.)
*/
instr_end_loop(queryDesc->totaltime);
/* Log plan if duration is exceeded. */
msec = queryDesc->totaltime->total * 1000.0;
if (msec >= auto_explain_log_min_duration)
{
struct explain_state es;
explain_init_state(&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;
explain_begin_output(&es);
explain_query_text(&es, queryDesc);
explain_print_plan(&es, queryDesc);
explain_end_output(&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_executor_end)
prev_executor_end(queryDesc);
else
standard_executor_end(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);
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(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);
}
