Make auto_explain print the query identifier in verbose mode

When auto_explain.log_verbose is on, auto_explain should print in the
logs plans equivalent to the EXPLAIN (VERBOSE).  However, when
compute_query_id is on, query identifiers were not showing up, being
only handled by EXPLAIN (VERBOSE).  This brings auto_explain on par with
EXPLAIN regarding that.  Note that like EXPLAIN, auto_explain does not
show the query identifier when compute_query_id=regress.

The change is done so as the choice of printing the query identifier is
done in ExplainPrintPlan() rather than in ExplainOnePlan(), to avoid a
duplication of the logic dealing with the query ID.  auto_explain is the
only in-core caller of ExplainPrintPlan().

While looking at the area, I have noticed that more consolidation
between EXPLAIN and auto_explain would be in order for the logging of
the plan duration and the buffer usage.  This refactoring is left as a
future change.

Author: Atsushi Torikoshi
Reviewed-by: Justin Pryzby, Julien Rouhaud
Discussion: https://postgr.es/m/1ea21936981f161bccfce05765c03bee@oss.nttdata.com

diff --git a/contrib/auto_explain/t/001_auto_explain.pl b/contrib/auto_explain/t/001_auto_explain.pl
index 0cf093c88e7aee494f275007a6ecdef566a7ea18..7873feb04475489937a7d6807d72e3c8ac87ab6f 100644 (file)
--- a/contrib/auto_explain/t/001_auto_explain.pl
+++ b/contrib/auto_explain/t/001_auto_explain.pl
@@ -106,6 +106,35 @@ unlike(
    qr/Query Parameters:/,
    "query parameters not logged when disabled, text mode");
 
+# Query Identifier.
+# Logging enabled.
+$log_contents = query_log(
+   $node,
+   "SELECT * FROM pg_class;",
+   {
+       "auto_explain.log_verbose" => "on",
+       "compute_query_id"         => "on"
+   });
+
+like(
+   $log_contents,
+   qr/Query Identifier:/,
+   "query identifier logged with compute_query_id=on, text mode");
+
+# Logging disabled.
+$log_contents = query_log(
+   $node,
+   "SELECT * FROM pg_class;",
+   {
+       "auto_explain.log_verbose" => "on",
+       "compute_query_id"         => "regress"
+   });
+
+unlike(
+   $log_contents,
+   qr/Query Identifier:/,
+   "query identifier not logged with compute_query_id=regress, text mode");
+
 # JSON format.
 $log_contents = query_log(
    $node,

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 5212a64b1e53ea3128c52c0b89c93cd9f5102111..a0311ce9dc679073c5d32d83bae33a69383e6c49 100644 (file)
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -604,22 +604,6 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
    /* Create textual dump of plan tree */
    ExplainPrintPlan(es, queryDesc);
 
-   /*
-    * COMPUTE_QUERY_ID_REGRESS means COMPUTE_QUERY_ID_AUTO, but we don't show
-    * the queryid in any of the EXPLAIN plans to keep stable the results
-    * generated by regression test suites.
-    */
-   if (es->verbose && plannedstmt->queryId != UINT64CONST(0) &&
-       compute_query_id != COMPUTE_QUERY_ID_REGRESS)
-   {
-       /*
-        * Output the queryid as an int64 rather than a uint64 so we match
-        * what would be seen in the BIGINT pg_stat_statements.queryid column.
-        */
-       ExplainPropertyInteger("Query Identifier", NULL, (int64)
-                              plannedstmt->queryId, es);
-   }
-
    /* Show buffer usage in planning */
    if (bufusage)
    {
@@ -791,6 +775,22 @@ ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc)
     * don't match the built-in defaults.
     */
    ExplainPrintSettings(es);
+
+   /*
+    * COMPUTE_QUERY_ID_REGRESS means COMPUTE_QUERY_ID_AUTO, but we don't show
+    * the queryid in any of the EXPLAIN plans to keep stable the results
+    * generated by regression test suites.
+    */
+   if (es->verbose && queryDesc->plannedstmt->queryId != UINT64CONST(0) &&
+       compute_query_id != COMPUTE_QUERY_ID_REGRESS)
+   {
+       /*
+        * Output the queryid as an int64 rather than a uint64 so we match
+        * what would be seen in the BIGINT pg_stat_statements.queryid column.
+        */
+       ExplainPropertyInteger("Query Identifier", NULL, (int64)
+                              queryDesc->plannedstmt->queryId, es);
+   }
 }
 
 /*