Rename EXPLAIN ANALYZE's "total runtime" output to "execution time".

Now that EXPLAIN also outputs a "planning time" measurement, the use of
"total" here seems rather confusing: it sounds like it might include the
planning time which of course it doesn't.  Majority opinion was that
"execution time" is a better label, so we'll call it that.

This should be noted as a backwards incompatibility for tools that examine
EXPLAIN ANALYZE output.

In passing, I failed to resist the temptation to do a little editing on the
materialized-view example affected by this change.

diff --git a/doc/src/sgml/perform.sgml b/doc/src/sgml/perform.sgml
index f0ab440cd385d8573214512e56811476783b5df0..657575c07ad6fbc535c35434fc48b81680d6684e 100644 (file)
--- a/doc/src/sgml/perform.sgml
+++ b/doc/src/sgml/perform.sgml
@@ -584,7 +584,7 @@ WHERE t1.unique1 < 10 AND t1.unique2 = t2.unique2;
    ->  Index Scan using tenk2_unique2 on tenk2 t2  (cost=0.29..7.91 rows=1 width=244) (actual time=0.021..0.022 rows=1 loops=10)
          Index Cond: (unique2 = t1.unique2)
  Planning time: 0.181 ms
- Total runtime: 0.501 ms
+ Execution time: 0.501 ms
 </screen>
 
     Note that the <quote>actual time</quote> values are in milliseconds of
@@ -633,7 +633,7 @@ WHERE t1.unique1 &lt; 100 AND t1.unique2 = t2.unique2 ORDER BY t1.fivethous;
                      -&gt;  Bitmap Index Scan on tenk1_unique1  (cost=0.00..5.04 rows=101 width=0) (actual time=0.049..0.049 rows=100 loops=1)
                            Index Cond: (unique1 &lt; 100)
  Planning time: 0.194 ms
- Total runtime: 8.008 ms
+ Execution time: 8.008 ms
 </screen>
 
     The Sort node shows the sort method used (in particular, whether the sort
@@ -657,7 +657,7 @@ EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE ten &lt; 7;
    Filter: (ten &lt; 7)
    Rows Removed by Filter: 3000
  Planning time: 0.083 ms
- Total runtime: 5.905 ms
+ Execution time: 5.905 ms
 </screen>
 
     These counts can be particularly valuable for filter conditions applied at
@@ -680,7 +680,7 @@ EXPLAIN ANALYZE SELECT * FROM polygon_tbl WHERE f1 @&gt; polygon '(0.5,2.0)';
    Filter: (f1 @&gt; '((0.5,2))'::polygon)
    Rows Removed by Filter: 4
  Planning time: 0.040 ms
- Total runtime: 0.083 ms
+ Execution time: 0.083 ms
 </screen>
 
     The planner thinks (quite correctly) that this sample table is too small
@@ -699,7 +699,7 @@ EXPLAIN ANALYZE SELECT * FROM polygon_tbl WHERE f1 @&gt; polygon '(0.5,2.0)';
    Index Cond: (f1 @&gt; '((0.5,2))'::polygon)
    Rows Removed by Index Recheck: 1
  Planning time: 0.034 ms
- Total runtime: 0.144 ms
+ Execution time: 0.144 ms
 </screen>
 
     Here we can see that the index returned one candidate row, which was
@@ -730,7 +730,7 @@ EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND unique
                Index Cond: (unique2 &gt; 9000)
                Buffers: shared hit=5
  Planning time: 0.088 ms
- Total runtime: 0.423 ms
+ Execution time: 0.423 ms
 </screen>
 
     The numbers provided by <literal>BUFFERS</> help to identify which parts
@@ -758,7 +758,7 @@ EXPLAIN ANALYZE UPDATE tenk1 SET hundred = hundred + 1 WHERE unique1 &lt; 100;
          -&gt;  Bitmap Index Scan on tenk1_unique1  (cost=0.00..5.04 rows=101 width=0) (actual time=0.043..0.043 rows=100 loops=1)
                Index Cond: (unique1 &lt; 100)
  Planning time: 0.079 ms
- Total runtime: 14.727 ms
+ Execution time: 14.727 ms
 
 ROLLBACK;
 </screen>
@@ -781,7 +781,7 @@ ROLLBACK;
    </para>
 
    <para>
-    The <literal>Total runtime</literal> shown by <command>EXPLAIN
+    The <literal>Execution time</literal> shown by <command>EXPLAIN
     ANALYZE</command> includes executor start-up and shut-down time, as well
     as the time to run any triggers that are fired, but it does not include
     parsing, rewriting, or planning time.
@@ -792,7 +792,7 @@ ROLLBACK;
     The total time spent in each trigger
     (either <literal>BEFORE</> or <literal>AFTER</>) is also shown separately.
     Note that deferred constraint triggers will not be executed
-    until end of transaction and are thus not shown at all by
+    until end of transaction and are thus not considered at all by
     <command>EXPLAIN ANALYZE</command>.
    </para>
 
@@ -844,7 +844,7 @@ EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND unique2 &gt; 9000
          Filter: (unique1 &lt; 100)
          Rows Removed by Filter: 287
  Planning time: 0.096 ms
- Total runtime: 0.336 ms
+ Execution time: 0.336 ms
 </screen>
 
     the estimated cost and row count for the Index Scan node are shown as

diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml
index 04a78ee82ea2b6ca7225d05779141aa61f0960a5..c4aa95f93023317e37616a7b083fd35680f4f3cd 100644 (file)
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -408,7 +408,7 @@ EXPLAIN ANALYZE EXECUTE query(100, 200);
    ->  Index Scan using test_pkey on test  (cost=0.29..9.29 rows=50 width=8) (actual time=0.039..0.091 rows=99 loops=1)
          Index Cond: ((id > $1) AND (id < $2))
  Planning time: 0.197 ms
- Total runtime: 0.225 ms
+ Execution time: 0.225 ms
 (5 rows)
 </programlisting>
   </para>

diff --git a/doc/src/sgml/rules.sgml b/doc/src/sgml/rules.sgml
index 2686c8f517865b950dcb9e378a0eac362a72b467..a2a3baebd74bf251fe618a15a736cb51d51b5a6c 100644 (file)
--- a/doc/src/sgml/rules.sgml
+++ b/doc/src/sgml/rules.sgml
@@ -993,11 +993,17 @@ REFRESH MATERIALIZED VIEW sales_summary;
 
 <para>
     Another use for a materialized view is to allow faster access to data
-    brought across from a remote system, through a foreign data wrapper.
+    brought across from a remote system through a foreign data wrapper.
     A simple example using <literal>file_fdw</literal> is below, with timings,
     but since this is using cache on the local system the performance
-    difference on a foreign data wrapper to a remote system could be greater.
+    difference compared to access to a remote system would usually be greater
+    than shown here.  Notice we are also exploiting the ability to put an
+    index on the materialized view, whereas <literal>file_fdw</literal> does
+    not support indexes; this advantage might not apply for other sorts of
+    foreign data access.
+</para>
 
+<para>
     Setup:
 
 <programlisting>
@@ -1005,7 +1011,7 @@ CREATE EXTENSION file_fdw;
 CREATE SERVER local_file FOREIGN DATA WRAPPER file_fdw;
 CREATE FOREIGN TABLE words (word text NOT NULL)
   SERVER local_file
-  OPTIONS (filename '/etc/dictionaries-common/words');
+  OPTIONS (filename '/usr/share/dict/words');
 CREATE MATERIALIZED VIEW wrd AS SELECT * FROM words;
 CREATE UNIQUE INDEX wrd_word ON wrd (word);
 CREATE EXTENSION pg_trgm;
@@ -1024,26 +1030,28 @@ SELECT count(*) FROM words WHERE word = 'caterpiler';
 (1 row)
 </programlisting>
 
-    The plan is:
+    With <command>EXPLAIN ANALYZE</>, we see:
 
 <programlisting>
- Aggregate  (cost=4125.19..4125.20 rows=1 width=0) (actual time=26.013..26.014 rows=1 loops=1)
-   ->  Foreign Scan on words  (cost=0.00..4124.70 rows=196 width=0) (actual time=26.011..26.011 rows=0 loops=1)
+ Aggregate  (cost=21763.99..21764.00 rows=1 width=0) (actual time=188.180..188.181 rows=1 loops=1)
+   -&gt;  Foreign Scan on words  (cost=0.00..21761.41 rows=1032 width=0) (actual time=188.177..188.177 rows=0 loops=1)
          Filter: (word = 'caterpiler'::text)
-         Rows Removed by Filter: 99171
-         Foreign File: /etc/dictionaries-common/words
-         Foreign File Size: 938848
- Total runtime: 26.081 ms
+         Rows Removed by Filter: 479829
+         Foreign File: /usr/share/dict/words
+         Foreign File Size: 4953699
+ Planning time: 0.118 ms
+ Execution time: 188.273 ms
 </programlisting>
 
     If the materialized view is used instead, the query is much faster:
 
 <programlisting>
- Aggregate  (cost=4.44..4.45 rows=1 width=0) (actual time=0.074..0.074 rows=1 loops=1)
-   ->  Index Only Scan using wrd_word on wrd  (cost=0.42..4.44 rows=1 width=0) (actual time=0.071..0.071 rows=0 loops=1)
+ Aggregate  (cost=4.44..4.45 rows=1 width=0) (actual time=0.042..0.042 rows=1 loops=1)
+   -&gt;  Index Only Scan using wrd_word on wrd  (cost=0.42..4.44 rows=1 width=0) (actual time=0.039..0.039 rows=0 loops=1)
          Index Cond: (word = 'caterpiler'::text)
          Heap Fetches: 0
- Total runtime: 0.119 ms
+ Planning time: 0.164 ms
+ Execution time: 0.117 ms
 </programlisting>
 
     Either way, the word is spelled wrong, so let's look for what we might
@@ -1068,23 +1076,25 @@ SELECT word FROM words ORDER BY word <-> 'caterpiler' LIMIT 10;
 </programlisting>
 
 <programlisting>
- Limit  (cost=2195.70..2195.72 rows=10 width=32) (actual time=218.904..218.906 rows=10 loops=1)
-   ->  Sort  (cost=2195.70..2237.61 rows=16765 width=32) (actual time=218.902..218.904 rows=10 loops=1)
-         Sort Key: ((word <-> 'caterpiler'::text))
+ Limit  (cost=11583.61..11583.64 rows=10 width=32) (actual time=1431.591..1431.594 rows=10 loops=1)
+   -&gt;  Sort  (cost=11583.61..11804.76 rows=88459 width=32) (actual time=1431.589..1431.591 rows=10 loops=1)
+         Sort Key: ((word &lt;-&gt; 'caterpiler'::text))
          Sort Method: top-N heapsort  Memory: 25kB
-         ->  Foreign Scan on words  (cost=0.00..1833.41 rows=16765 width=32) (actual time=0.046..200.965 rows=99171 loops=1)
-               Foreign File: /etc/dictionaries-common/words
-               Foreign File Size: 938848
- Total runtime: 218.966 ms
+         -&gt;  Foreign Scan on words  (cost=0.00..9672.05 rows=88459 width=32) (actual time=0.057..1286.455 rows=479829 loops=1)
+               Foreign File: /usr/share/dict/words
+               Foreign File Size: 4953699
+ Planning time: 0.128 ms
+ Execution time: 1431.679 ms
 </programlisting>
 
     Using the materialized view:
 
 <programlisting>
- Limit  (cost=0.28..1.02 rows=10 width=9) (actual time=24.916..25.079 rows=10 loops=1)
-   ->  Index Scan using wrd_trgm on wrd  (cost=0.28..7383.70 rows=99171 width=9) (actual time=24.914..25.076 rows=10 loops=1)
-         Order By: (word <-> 'caterpiler'::text)
- Total runtime: 25.884 ms
+ Limit  (cost=0.29..1.06 rows=10 width=10) (actual time=187.222..188.257 rows=10 loops=1)
+   -&gt;  Index Scan using wrd_trgm on wrd  (cost=0.29..37020.87 rows=479829 width=10) (actual time=187.219..188.252 rows=10 loops=1)
+         Order By: (word &lt;-&gt; 'caterpiler'::text)
+ Planning time: 0.196 ms
+ Execution time: 198.640 ms
 </programlisting>
 
     If you can tolerate periodic update of the remote data to the local

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 08f3167f10d638a8b616504ee4030b32e1ab66d2..1104cc363123a1c833bd4c1f1a01c60992041658 100644 (file)
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -508,7 +508,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 
        /*
         * Close down the query and free resources.  Include time for this in the
-        * total runtime (although it should be pretty minimal).
+        * total execution time (although it should be pretty minimal).
         */
        INSTR_TIME_SET_CURRENT(starttime);
 
@@ -527,10 +527,10 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
        if (es->analyze)
        {
                if (es->format == EXPLAIN_FORMAT_TEXT)
-                       appendStringInfo(es->str, "Total runtime: %.3f ms\n",
+                       appendStringInfo(es->str, "Execution time: %.3f ms\n",
                                                         1000.0 * totaltime);
                else
-                       ExplainPropertyFloat("Total Runtime", 1000.0 * totaltime,
+                       ExplainPropertyFloat("Execution Time", 1000.0 * totaltime,
                                                                 3, es);
        }