diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index 2a184ed..a64b3fe 100644 --- a/contrib/auto_explain/auto_explain.c +++ b/contrib/auto_explain/auto_explain.c @@ -13,6 +13,7 @@ #include "postgres.h" #include +#include #include "commands/explain.h" #include "executor/instrument.h" @@ -46,6 +47,9 @@ static ExecutorStart_hook_type prev_ExecutorStart = NULL; static ExecutorRun_hook_type prev_ExecutorRun = NULL; static ExecutorFinish_hook_type prev_ExecutorFinish = NULL; static ExecutorEnd_hook_type prev_ExecutorEnd = NULL; +static pqsigfunc prev_sigusr1 = NULL; + +static QueryDesc *current_query_desc = NULL; #define auto_explain_enabled() \ (auto_explain_log_min_duration >= 0 && \ @@ -54,6 +58,8 @@ static ExecutorEnd_hook_type prev_ExecutorEnd = NULL; void _PG_init(void); void _PG_fini(void); +static void sigusr1_handler(int signum); + static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags); static void explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, @@ -61,6 +67,7 @@ static void explain_ExecutorRun(QueryDesc *queryDesc, static void explain_ExecutorFinish(QueryDesc *queryDesc); static void explain_ExecutorEnd(QueryDesc *queryDesc); +static void explain_output_plain(QueryDesc *queryDesc, double time_msec, int format); /* * Module load callback @@ -170,6 +177,8 @@ _PG_init(void) ExecutorFinish_hook = explain_ExecutorFinish; prev_ExecutorEnd = ExecutorEnd_hook; ExecutorEnd_hook = explain_ExecutorEnd; + + prev_sigusr1 = pqsignal(SIGUSR1, sigusr1_handler); } /* @@ -185,12 +194,34 @@ _PG_fini(void) ExecutorEnd_hook = prev_ExecutorEnd; } +static void +sigusr1_handler(int signum) +{ + int save_errno = errno; + + if (current_query_desc != NULL) + { + explain_output_plain(current_query_desc, 0.0, EXPLAIN_FORMAT_TEXT); + } + + if (prev_sigusr1 != NULL && + prev_sigusr1 != SIG_IGN && + prev_sigusr1 != SIG_DFL) + { + prev_sigusr1(signum); + } + + errno = save_errno; +} + /* * ExecutorStart hook: start up logging if needed */ static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags) { + current_query_desc = queryDesc; + if (auto_explain_enabled()) { /* Enable per-node instrumentation iff log_analyze is required. */ @@ -294,45 +325,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc) 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); + explain_output_plain(queryDesc, msec, auto_explain_log_format); } } @@ -340,4 +333,50 @@ explain_ExecutorEnd(QueryDesc *queryDesc) prev_ExecutorEnd(queryDesc); else standard_ExecutorEnd(queryDesc); + + current_query_desc = NULL; +} + +static void +explain_output_plain(QueryDesc *queryDesc, double time_msec, int format) +{ + 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 = 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 (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", + time_msec, es->str->data), + errhidestmt(true))); + + pfree(es->str->data); }