Add the option to report WAL usage in EXPLAIN and auto_explain.

This commit adds a new option WAL similar to existing option BUFFERS in the
EXPLAIN command.  This option allows to include information on WAL record
generation added by commit df3b181499 in EXPLAIN output.

This also allows the WAL usage information to be displayed via
the auto_explain module.  A new parameter auto_explain.log_wal controls
whether WAL usage statistics are printed when an execution plan is logged.
This parameter has no effect unless auto_explain.log_analyze is enabled.

Author: Julien Rouhaud
Reviewed-by: Dilip Kumar and Amit Kapila
Discussion: https://postgr.es/m/CAB-hujrP8ZfUkvL5OYETipQwA=e3n7oqHFU=4ZLxWS_Cza3kQQ@mail.gmail.com

diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index f69dde876c374c06b31306d4f1fe253435843d78..56c549d84c1d3e1e6ce748e18b170389c75f7f42 100644 (file)
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -27,6 +27,7 @@ static int    auto_explain_log_min_duration = -1; /* msec or -1 */
 static bool auto_explain_log_analyze = false;
 static bool auto_explain_log_verbose = false;
 static bool auto_explain_log_buffers = false;
+static bool auto_explain_log_wal = false;
 static bool auto_explain_log_triggers = false;
 static bool auto_explain_log_timing = true;
 static bool auto_explain_log_settings = false;
@@ -148,6 +149,17 @@ _PG_init(void)
                             NULL,
                             NULL);
 
+   DefineCustomBoolVariable("auto_explain.log_wal",
+                            "Log WAL usage.",
+                            NULL,
+                            &auto_explain_log_wal,
+                            false,
+                            PGC_SUSET,
+                            0,
+                            NULL,
+                            NULL,
+                            NULL);
+
    DefineCustomBoolVariable("auto_explain.log_triggers",
                             "Include trigger statistics in plans.",
                             "This has no effect unless log_analyze is also set.",
@@ -280,6 +292,8 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
                queryDesc->instrument_options |= INSTRUMENT_ROWS;
            if (auto_explain_log_buffers)
                queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
+           if (auto_explain_log_wal)
+               queryDesc->instrument_options |= INSTRUMENT_WAL;
        }
    }
 
@@ -374,6 +388,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
            es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
            es->verbose = auto_explain_log_verbose;
            es->buffers = (es->analyze && auto_explain_log_buffers);
+           es->wal = (es->analyze && auto_explain_log_wal);
            es->timing = (es->analyze && auto_explain_log_timing);
            es->summary = es->analyze;
            es->format = auto_explain_log_format;

diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml
index 3d619d4a3ddc52b33955036702e6ed73c5d81789..d4d29c4a64991da6c637ac1f7fb2327e6185c335 100644 (file)
--- a/doc/src/sgml/auto-explain.sgml
+++ b/doc/src/sgml/auto-explain.sgml
@@ -109,6 +109,26 @@ LOAD 'auto_explain';
     </listitem>
    </varlistentry>
 
+   <varlistentry>
+    <term>
+     <varname>auto_explain.log_wal</varname> (<type>boolean</type>)
+     <indexterm>
+      <primary><varname>auto_explain.log_wal</varname> configuration parameter</primary>
+     </indexterm>
+    </term>
+    <listitem>
+     <para>
+      <varname>auto_explain.log_wal</varname> controls whether WAL
+      usage statistics are printed when an execution plan is logged; it's
+      equivalent to the <literal>WAL</literal> option of <command>EXPLAIN</command>.
+      This parameter has no effect
+      unless <varname>auto_explain.log_analyze</varname> is enabled.
+      This parameter is off by default.
+      Only superusers can change this setting.
+     </para>
+    </listitem>
+   </varlistentry>
+
    <varlistentry>
     <term>
      <varname>auto_explain.log_timing</varname> (<type>boolean</type>)

diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml
index 385d10411fa04319c7287b468f4f48344abf66a8..024ede4a8d2ce8f08f4069eed236d32b80b52193 100644 (file)
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -41,6 +41,7 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] <replaceable class="parameter">statement</replac
     COSTS [ <replaceable class="parameter">boolean</replaceable> ]
     SETTINGS [ <replaceable class="parameter">boolean</replaceable> ]
     BUFFERS [ <replaceable class="parameter">boolean</replaceable> ]
+    WAL [ <replaceable class="parameter">boolean</replaceable> ]
     TIMING [ <replaceable class="parameter">boolean</replaceable> ]
     SUMMARY [ <replaceable class="parameter">boolean</replaceable> ]
     FORMAT { TEXT | XML | JSON | YAML }
@@ -192,6 +193,19 @@ ROLLBACK;
     </listitem>
    </varlistentry>
 
+   <varlistentry>
+    <term><literal>WAL</literal></term>
+    <listitem>
+     <para>
+      Include information on WAL record generation. Specifically, include the
+      number of records, number of full page image records and amount of WAL
+      bytes generated.  In text format, only non-zero values are printed.  This
+      parameter may only be used when <literal>ANALYZE</literal> is also
+      enabled.  It defaults to <literal>FALSE</literal>.
+     </para>
+    </listitem>
+   </varlistentry>
+
    <varlistentry>
     <term><literal>TIMING</literal></term>
     <listitem>

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 81a18abbeb3cd6f74b70e9981cb5036fecb01371..bb58f92851812386b2e01d5946142e4d38e9f3a9 100644 (file)
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -113,6 +113,7 @@ static void show_foreignscan_info(ForeignScanState *fsstate, ExplainState *es);
 static void show_eval_params(Bitmapset *bms_params, ExplainState *es);
 static const char *explain_get_index_name(Oid indexId);
 static void show_buffer_usage(ExplainState *es, const BufferUsage *usage);
+static void show_wal_usage(ExplainState *es, const WalUsage *usage);
 static void ExplainIndexScanDetails(Oid indexid, ScanDirection indexorderdir,
                                    ExplainState *es);
 static void ExplainScanTarget(Scan *plan, ExplainState *es);
@@ -175,6 +176,8 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
            es->costs = defGetBoolean(opt);
        else if (strcmp(opt->defname, "buffers") == 0)
            es->buffers = defGetBoolean(opt);
+       else if (strcmp(opt->defname, "wal") == 0)
+           es->wal = defGetBoolean(opt);
        else if (strcmp(opt->defname, "settings") == 0)
            es->settings = defGetBoolean(opt);
        else if (strcmp(opt->defname, "timing") == 0)
@@ -219,6 +222,11 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
                (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
                 errmsg("EXPLAIN option BUFFERS requires ANALYZE")));
 
+   if (es->wal && !es->analyze)
+       ereport(ERROR,
+               (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+                errmsg("EXPLAIN option WAL requires ANALYZE")));
+
    /* if the timing was not set explicitly, set default value */
    es->timing = (timing_set) ? es->timing : es->analyze;
 
@@ -506,6 +514,8 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 
    if (es->buffers)
        instrument_option |= INSTRUMENT_BUFFERS;
+   if (es->wal)
+       instrument_option |= INSTRUMENT_WAL;
 
    /*
     * We always collect timing for the entire statement, even when node-level
@@ -1970,12 +1980,14 @@ ExplainNode(PlanState *planstate, List *ancestors,
        }
    }
 
-   /* Show buffer usage */
+   /* Show buffer/WAL usage */
    if (es->buffers && planstate->instrument)
        show_buffer_usage(es, &planstate->instrument->bufusage);
+   if (es->wal && planstate->instrument)
+       show_wal_usage(es, &planstate->instrument->walusage);
 
-   /* Prepare per-worker buffer usage */
-   if (es->workers_state && es->buffers && es->verbose)
+   /* Prepare per-worker buffer/WAL usage */
+   if (es->workers_state && (es->buffers || es->wal) && es->verbose)
    {
        WorkerInstrumentation *w = planstate->worker_instrument;
 
@@ -1988,7 +2000,10 @@ ExplainNode(PlanState *planstate, List *ancestors,
                continue;
 
            ExplainOpenWorker(n, es);
-           show_buffer_usage(es, &instrument->bufusage);
+           if (es->buffers)
+               show_buffer_usage(es, &instrument->bufusage);
+           if (es->wal)
+               show_wal_usage(es, &instrument->walusage);
            ExplainCloseWorker(n, es);
        }
    }
@@ -3087,6 +3102,44 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage)
    }
 }
 
+/*
+ * Show WAL usage details.
+ */
+static void
+show_wal_usage(ExplainState *es, const WalUsage *usage)
+{
+   if (es->format == EXPLAIN_FORMAT_TEXT)
+   {
+       /* Show only positive counter values. */
+       if ((usage->wal_records > 0) || (usage->wal_num_fpw > 0) ||
+           (usage->wal_bytes > 0))
+       {
+           ExplainIndentText(es);
+           appendStringInfoString(es->str, "WAL:");
+
+           if (usage->wal_records > 0)
+               appendStringInfo(es->str, "  records=%ld",
+                                usage->wal_records);
+           if (usage->wal_num_fpw > 0)
+               appendStringInfo(es->str, "  full page writes=%ld",
+                                usage->wal_num_fpw);
+           if (usage->wal_bytes > 0)
+               appendStringInfo(es->str, "  bytes=" UINT64_FORMAT,
+                                usage->wal_bytes);
+           appendStringInfoChar(es->str, '\n');
+       }
+   }
+   else
+   {
+       ExplainPropertyInteger("WAL records", NULL,
+                              usage->wal_records, es);
+       ExplainPropertyInteger("WAL full page writes", NULL,
+                              usage->wal_num_fpw, es);
+       ExplainPropertyUInteger("WAL bytes", NULL,
+                               usage->wal_bytes, es);
+   }
+}
+
 /*
  * Add some additional details about an IndexScan or IndexOnlyScan
  */
@@ -3871,6 +3924,19 @@ ExplainPropertyInteger(const char *qlabel, const char *unit, int64 value,
    ExplainProperty(qlabel, unit, buf, true, es);
 }
 
+/*
+ * Explain an unsigned integer-valued property.
+ */
+void
+ExplainPropertyUInteger(const char *qlabel, const char *unit, uint64 value,
+                       ExplainState *es)
+{
+   char        buf[32];
+
+   snprintf(buf, sizeof(buf), UINT64_FORMAT, value);
+   ExplainProperty(qlabel, unit, buf, true, es);
+}
+
 /*
  * Explain a float-valued property, using the specified number of
  * fractional digits.

diff --git a/src/bin/psql/tab-complete.c b/src/bin/psql/tab-complete.c
index 5fec59723cff6b7a717afb2fcf655112012d924a..0e7a373caf2ff7c50b6963aaf6d8118b967a60a9 100644 (file)
--- a/src/bin/psql/tab-complete.c
+++ b/src/bin/psql/tab-complete.c
@@ -3045,8 +3045,8 @@ psql_completion(const char *text, int start, int end)
         */
        if (ends_with(prev_wd, '(') || ends_with(prev_wd, ','))
            COMPLETE_WITH("ANALYZE", "VERBOSE", "COSTS", "SETTINGS",
-                         "BUFFERS", "TIMING", "SUMMARY", "FORMAT");
-       else if (TailMatches("ANALYZE|VERBOSE|COSTS|SETTINGS|BUFFERS|TIMING|SUMMARY"))
+                         "BUFFERS", "WAL", "TIMING", "SUMMARY", "FORMAT");
+       else if (TailMatches("ANALYZE|VERBOSE|COSTS|SETTINGS|BUFFERS|WAL|TIMING|SUMMARY"))
            COMPLETE_WITH("ON", "OFF");
        else if (TailMatches("FORMAT"))
            COMPLETE_WITH("TEXT", "XML", "JSON", "YAML");

diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 739c1d0b423cb84be5f833cb62ffce717a2b3d2f..ba661d32a63094dbdda7df9893de45373d2eed58 100644 (file)
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -42,6 +42,7 @@ typedef struct ExplainState
    bool        analyze;        /* print actual times */
    bool        costs;          /* print estimated costs */
    bool        buffers;        /* print buffer usage */
+   bool        wal;            /* print WAL usage */
    bool        timing;         /* print detailed node timing */
    bool        summary;        /* print total planning and execution timing */
    bool        settings;       /* print modified settings */
@@ -111,6 +112,8 @@ extern void ExplainPropertyText(const char *qlabel, const char *value,
                                ExplainState *es);
 extern void ExplainPropertyInteger(const char *qlabel, const char *unit,
                                   int64 value, ExplainState *es);
+extern void ExplainPropertyUInteger(const char *qlabel, const char *unit,
+                                   uint64 value, ExplainState *es);
 extern void ExplainPropertyFloat(const char *qlabel, const char *unit,
                                 double value, int ndigits, ExplainState *es);
 extern void ExplainPropertyBool(const char *qlabel, bool value,