/*
* ExecutorStart hook: start up logging if needed
*/
static void
explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
{
/*
* For rate sampling, randomly choose top-level statement. Either all
* nested statements will be explained or none will.
*/
if (auto_explain_log_min_duration >= 0 && nesting_level == 0)
current_query_sampled = (random() < auto_explain_sample_rate *
MAX_RANDOM_VALUE);
if (auto_explain_enabled() && current_query_sampled)
{
/* Enable per-node instrumentation iff log_analyze is required. */
if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
{
if (auto_explain_log_timing)
queryDesc->instrument_options |= INSTRUMENT_TIMER;
else
queryDesc->instrument_options |= INSTRUMENT_ROWS;
if (auto_explain_log_buffers)
queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
}
}
if (prev_ExecutorStart)
prev_ExecutorStart(queryDesc, eflags);
else
standard_ExecutorStart(queryDesc, eflags);
if (auto_explain_enabled() && current_query_sampled)
{
/*
* Set up to track total elapsed time in ExecutorRun. Make sure the
* space is allocated in the per-query context so it will go away at
* ExecutorEnd.
*/
if (queryDesc->totaltime == NULL)
{
MemoryContext oldcxt;
oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL);
MemoryContextSwitchTo(oldcxt);
}
}
}
/*
* 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);
}
/*
* ExecutorStart hook: start up logging if needed
*/
static void
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 (auto_explain_log_timing)
queryDesc->instrument_options |= INSTRUMENT_TIMER;
else
queryDesc->instrument_options |= INSTRUMENT_ROWS;
if (auto_explain_log_buffers)
queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
}
}
if (prev_ExecutorStart)
prev_ExecutorStart(queryDesc, eflags);
else
standard_ExecutorStart(queryDesc, eflags);
if (auto_explain_enabled())
{
/*
* Set up to track total elapsed time in ExecutorRun. Make sure the
* space is allocated in the per-query context so it will go away at
* ExecutorEnd.
*/
if (queryDesc->totaltime == NULL)
{
MemoryContext oldcxt;
oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL);
MemoryContextSwitchTo(oldcxt);
}
}
}
/*
* executor_start hook: start up logging if needed
*/
static void
explain_executor_start(struct qry_desc *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)
{
queryDesc->instrument_options |= INSTRUMENT_TIMER;
if (auto_explain_log_buffers)
queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
}
}
if (prev_executor_start)
prev_executor_start(queryDesc, eflags);
else
standard_executor_start(queryDesc, eflags);
if (auto_explain_enabled())
{
/*
* Set up to track total elapsed time in executor_run. Make sure the
* space is allocated in the per-query context so it will go away at
* executor_end.
*/
if (queryDesc->totaltime == NULL)
{
struct mctx * oldcxt;
oldcxt = mctx_switch(queryDesc->estate->es_query_cxt);
queryDesc->totaltime = instr_alloc(1, INSTRUMENT_ALL);
mctx_switch(oldcxt);
}
}
}
/*
* 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);
}
