From f9b1a0dd403ec0931213c66d5f979a3d3e8e7e30 Mon Sep 17 00:00:00 2001 From: Stephen Frost Date: Wed, 8 Mar 2017 15:14:03 -0500 Subject: [PATCH] Expose explain's SUMMARY option This exposes the existing explain summary option to users to allow them to choose if they wish to have the planning time and totalled run time included in the EXPLAIN result. The existing default behavior is retained if SUMMARY is not specified- running explain without analyze will not print the summary lines (just the planning time, currently) while running explain with analyze will include the summary lines (both the planning time and the totalled execution time). Users who wish to see the summary information for plain explain can now use: EXPLAIN (SUMMARY ON) query; Users who do not want to have the summary printed for an analyze run can use: EXPLAIN (ANALYZE ON, SUMMARY OFF) query; With this, we can now also have EXPLAIN ANALYZE queries included in our regression tests by using: EXPLAIN (ANALYZE ON, TIMING OFF, SUMMARY off) query; I went ahead and added an example of this, which will hopefully not make the buildfarm complain. Author: Ashutosh Bapat Discussion: https://postgr.es/m/CAFjFpReE5z2h98U2Vuia8hcEkpRRwrauRjHmyE44hNv8-xk+XA@mail.gmail.com --- doc/src/sgml/ref/explain.sgml | 16 ++++++++++++++++ src/backend/commands/explain.c | 18 +++++++++++++++--- src/backend/commands/prepare.c | 9 ++++++++- src/test/regress/expected/select.out | 10 ++++++++++ src/test/regress/sql/select.sql | 3 +++ 5 files changed, 52 insertions(+), 4 deletions(-) diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index f14a58dfc6..6d909f1a97 100644 --- a/doc/src/sgml/ref/explain.sgml +++ b/doc/src/sgml/ref/explain.sgml @@ -41,6 +41,7 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] statementboolean ] BUFFERS [ boolean ] TIMING [ boolean ] + SUMMARY [ boolean ] FORMAT { TEXT | XML | JSON | YAML } @@ -196,6 +197,21 @@ ROLLBACK; + + SUMMARY + + + Include summary information (eg: totalled timing information) after the + query plan. Summary information is included by default when + ANALYZE is used but otherwise is not included by + default, but can be enabled using this option. Planning time in + EXPLAIN EXECUTE includes the time required to fetch + the plan from the cache and the time required for re-planning, if + necessary. + + + + FORMAT diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 7a8d36c8db..6fd82e9d52 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -149,6 +149,7 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt, const char *queryString, List *rewritten; ListCell *lc; bool timing_set = false; + bool summary_set = false; /* Parse options list. */ foreach(lc, stmt->options) @@ -168,6 +169,11 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt, const char *queryString, timing_set = true; es->timing = defGetBoolean(opt); } + else if (strcmp(opt->defname, "summary") == 0) + { + summary_set = true; + es->summary = defGetBoolean(opt); + } else if (strcmp(opt->defname, "format") == 0) { char *p = defGetString(opt); @@ -209,8 +215,8 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt, const char *queryString, (errcode(ERRCODE_INVALID_PARAMETER_VALUE), errmsg("EXPLAIN option TIMING requires ANALYZE"))); - /* currently, summary option is not exposed to users; just set it */ - es->summary = es->analyze; + /* if the summary was not set explicitly, set default value */ + es->summary = (summary_set) ? es->summary : es->analyze; /* * Parse analysis was done already, but we still have to run the rule @@ -571,7 +577,13 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, totaltime += elapsed_time(&starttime); - if (es->summary) + /* + * We only report execution time if we actually ran the query (that is, + * the user specified ANALYZE), and if summary reporting is enabled (the + * user can set SUMMARY OFF to not have the timing information included in + * the output). By default, ANALYZE sets SUMMARY to true. + */ + if (es->summary && es->analyze) { if (es->format == EXPLAIN_FORMAT_TEXT) appendStringInfo(es->str, "Execution time: %.3f ms\n", diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c index 116ed67547..1cf0d2b971 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -638,6 +638,10 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, ListCell *p; ParamListInfo paramLI = NULL; EState *estate = NULL; + instr_time planstart; + instr_time planduration; + + INSTR_TIME_SET_CURRENT(planstart); /* Look it up in the hash table */ entry = FetchPreparedStatement(execstmt->name, true); @@ -666,6 +670,9 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, /* Replan if needed, and acquire a transient refcount */ cplan = GetCachedPlan(entry->plansource, paramLI, true); + INSTR_TIME_SET_CURRENT(planduration); + INSTR_TIME_SUBTRACT(planduration, planstart); + plan_list = cplan->stmt_list; /* Explain each query */ @@ -674,7 +681,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, PlannedStmt *pstmt = castNode(PlannedStmt, lfirst(p)); if (pstmt->commandType != CMD_UTILITY) - ExplainOnePlan(pstmt, into, es, query_string, paramLI, NULL); + ExplainOnePlan(pstmt, into, es, query_string, paramLI, &planduration); else ExplainOneUtility(pstmt->utilityStmt, into, es, query_string, paramLI); diff --git a/src/test/regress/expected/select.out b/src/test/regress/expected/select.out index f84f8ac767..1fab5136d2 100644 --- a/src/test/regress/expected/select.out +++ b/src/test/regress/expected/select.out @@ -752,6 +752,16 @@ select * from onek2 where unique2 = 11 and stringu1 = 'ATAAAA'; 494 | 11 | 0 | 2 | 4 | 14 | 4 | 94 | 94 | 494 | 494 | 8 | 9 | ATAAAA | LAAAAA | VVVVxx (1 row) +-- actually run the query with an analyze to use the partial index +explain (costs off, analyze on, timing off, summary off) +select * from onek2 where unique2 = 11 and stringu1 = 'ATAAAA'; + QUERY PLAN +----------------------------------------------------------------- + Index Scan using onek2_u2_prtl on onek2 (actual rows=1 loops=1) + Index Cond: (unique2 = 11) + Filter: (stringu1 = 'ATAAAA'::name) +(3 rows) + explain (costs off) select unique2 from onek2 where unique2 = 11 and stringu1 = 'ATAAAA'; QUERY PLAN diff --git a/src/test/regress/sql/select.sql b/src/test/regress/sql/select.sql index abdd785a77..c80429e7d0 100644 --- a/src/test/regress/sql/select.sql +++ b/src/test/regress/sql/select.sql @@ -195,6 +195,9 @@ SELECT * FROM foo ORDER BY f1 DESC NULLS LAST; explain (costs off) select * from onek2 where unique2 = 11 and stringu1 = 'ATAAAA'; select * from onek2 where unique2 = 11 and stringu1 = 'ATAAAA'; +-- actually run the query with an analyze to use the partial index +explain (costs off, analyze on, timing off, summary off) +select * from onek2 where unique2 = 11 and stringu1 = 'ATAAAA'; explain (costs off) select unique2 from onek2 where unique2 = 11 and stringu1 = 'ATAAAA'; select unique2 from onek2 where unique2 = 11 and stringu1 = 'ATAAAA';