From 0bb615ec6fa326cf816c54edf0ea6cea4ab91d67 Mon Sep 17 00:00:00 2001 From: Daniel Gustafsson Date: Tue, 30 Oct 2018 11:19:51 +0100 Subject: [PATCH] Add costs and duration options to auto_explain This adds additional options to auto_explain for controlling logging of costs and the query duration. While being able to turn costs on or off can be useful, the main driver is to be able to properly test the extension. This commit adds basic test coverage to auto_explain using the options introduced to keep the test output stable. --- contrib/auto_explain/Makefile | 2 + contrib/auto_explain/auto_explain.c | 39 +++++++++++++-- contrib/auto_explain/expected/auto_explain.out | 68 ++++++++++++++++++++++++++ contrib/auto_explain/sql/auto_explain.sql | 26 ++++++++++ doc/src/sgml/auto-explain.sgml | 34 +++++++++++++ 5 files changed, 165 insertions(+), 4 deletions(-) create mode 100644 contrib/auto_explain/expected/auto_explain.out create mode 100644 contrib/auto_explain/sql/auto_explain.sql diff --git a/contrib/auto_explain/Makefile b/contrib/auto_explain/Makefile index fcf36c5ab0..db61901830 100644 --- a/contrib/auto_explain/Makefile +++ b/contrib/auto_explain/Makefile @@ -4,6 +4,8 @@ MODULE_big = auto_explain OBJS = auto_explain.o $(WIN32RES) PGFILEDESC = "auto_explain - logging facility for execution plans" +REGRESS = auto_explain + ifdef USE_PGXS PG_CONFIG = pg_config PGXS := $(shell $(PG_CONFIG) --pgxs) diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index 646cd0d42c..89fd317cb2 100644 --- a/contrib/auto_explain/auto_explain.c +++ b/contrib/auto_explain/auto_explain.c @@ -28,6 +28,8 @@ static bool auto_explain_log_verbose = false; static bool auto_explain_log_buffers = false; static bool auto_explain_log_triggers = false; static bool auto_explain_log_timing = true; +static bool auto_explain_log_costs = true; +static bool auto_explain_log_duration = true; static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT; static int auto_explain_log_level = LOG; static bool auto_explain_log_nested_statements = false; @@ -145,6 +147,29 @@ _PG_init(void) NULL, NULL); + DefineCustomBoolVariable("auto_explain.log_costs", + "Include costs in plans.", + NULL, + &auto_explain_log_costs, + true, + PGC_SUSET, + 0, + NULL, + NULL, + NULL); + + DefineCustomBoolVariable("auto_explain.log_duration", + "Log the duration of the query.", + NULL, + &auto_explain_log_duration, + true, + PGC_SUSET, + 0, + NULL, + NULL, + NULL); + + DefineCustomEnumVariable("auto_explain.log_format", "EXPLAIN format to be used for plan logging.", NULL, @@ -356,6 +381,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc) es->timing = (es->analyze && auto_explain_log_timing); es->summary = es->analyze; es->format = auto_explain_log_format; + es->costs = auto_explain_log_costs; ExplainBeginOutput(es); ExplainQueryText(es, queryDesc); @@ -383,10 +409,15 @@ explain_ExecutorEnd(QueryDesc *queryDesc) * 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))); + if (auto_explain_log_duration) + ereport(auto_explain_log_level, + (errmsg("duration: %.3f ms plan:\n%s", + msec, es->str->data), + errhidestmt(true))); + else + ereport(auto_explain_log_level, + (errmsg("plan:\n%s", es->str->data), + errhidestmt(true))); pfree(es->str->data); } diff --git a/contrib/auto_explain/expected/auto_explain.out b/contrib/auto_explain/expected/auto_explain.out new file mode 100644 index 0000000000..461343b1e1 --- /dev/null +++ b/contrib/auto_explain/expected/auto_explain.out @@ -0,0 +1,68 @@ +LOAD 'auto_explain'; +SET auto_explain.log_min_duration = 0; +SET auto_explain.log_duration = off; +SET auto_explain.log_level = NOTICE; +SET auto_explain.log_timing = off; +SET auto_explain.log_costs = off; +-- Should log +SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class'; +NOTICE: plan: +Query Text: SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class'; +Index Only Scan using pg_class_relname_nsp_index on pg_class + Index Cond: (relname = 'pg_class'::name) + ?column? +---------- + +(1 row) + +SET auto_explain.log_verbose = on; +SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class'; +NOTICE: plan: +Query Text: SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class'; +Index Only Scan using pg_class_relname_nsp_index on pg_catalog.pg_class + Output: NULL::text + Index Cond: (pg_class.relname = 'pg_class'::name) + ?column? +---------- + +(1 row) + +SET auto_explain.log_format = json; +SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class'; +NOTICE: plan: +{ + "Query Text": "SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';", + "Plan": { + "Node Type": "Index Only Scan", + "Parallel Aware": false, + "Scan Direction": "Forward", + "Index Name": "pg_class_relname_nsp_index", + "Relation Name": "pg_class", + "Schema": "pg_catalog", + "Alias": "pg_class", + "Output": ["NULL::text"], + "Index Cond": "(pg_class.relname = 'pg_class'::name)" + } +} + ?column? +---------- + +(1 row) + +-- Shouldn't log due to too high loglevel +SET auto_explain.log_level = DEBUG5; +SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class'; + ?column? +---------- + +(1 row) + +-- Shouldn't log due to query being too fast +SET auto_explain.log_level = NOTICE; +SET auto_explain.log_min_duration = 1000; +SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class'; + ?column? +---------- + +(1 row) + diff --git a/contrib/auto_explain/sql/auto_explain.sql b/contrib/auto_explain/sql/auto_explain.sql new file mode 100644 index 0000000000..cea1be3ec1 --- /dev/null +++ b/contrib/auto_explain/sql/auto_explain.sql @@ -0,0 +1,26 @@ +LOAD 'auto_explain'; + +SET auto_explain.log_min_duration = 0; +SET auto_explain.log_duration = off; +SET auto_explain.log_level = NOTICE; +SET auto_explain.log_timing = off; +SET auto_explain.log_costs = off; + +-- Should log +SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class'; + +SET auto_explain.log_verbose = on; +SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class'; + +SET auto_explain.log_format = json; +SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class'; + +-- Shouldn't log due to too high loglevel +SET auto_explain.log_level = DEBUG5; +SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class'; + +-- Shouldn't log due to query being too fast +SET auto_explain.log_level = NOTICE; +SET auto_explain.log_min_duration = 1000; +SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class'; + diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml index 120b168d45..be06a29139 100644 --- a/doc/src/sgml/auto-explain.sgml +++ b/doc/src/sgml/auto-explain.sgml @@ -108,6 +108,40 @@ LOAD 'auto_explain'; + + + auto_explain.log_costs (boolean) + + auto_explain.log_costs configuration parameter + + + + + auto_explain.log_costs controls whether per node costs + are printed when an execution plan is logged; it's + equivalent to the COSTS option of EXPLAIN. + This parameter is on by default. + Only superusers can change this setting. + + + + + + + auto_explain.log_duration (boolean) + + auto_explain.log_duration configuration parameter + + + + + auto_explain.log_duration controls whether the logged + plan is prefixed with the duration of the query. This parameter is on by + default. Only superusers can change this setting. + + + + auto_explain.log_timing (boolean) -- 2.14.1.145.gb3622a4ee