mirror of
https://github.com/postgres/postgres.git
synced 2025-05-25 00:04:05 -04:00
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.
This commit is contained in:
Tom Lane
parent
e183d11262
commit
5f86cbd714
@ -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 < 100 AND t1.unique2 = t2.unique2 ORDER BY t1.fivethous;
|
||||
-> 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 < 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 < 7;
|
||||
Filter: (ten < 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 @> polygon '(0.5,2.0)';
|
||||
Filter: (f1 @> '((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 @> polygon '(0.5,2.0)';
|
||||
Index Cond: (f1 @> '((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 < 100 AND unique
|
||||
Index Cond: (unique2 > 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 < 100;
|
||||
-> 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 < 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 < 100 AND unique2 > 9000
|
||||
Filter: (unique1 < 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
|
||||
|
||||
@ -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>
|
||||
|
||||
@ -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)
|
||||
-> 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)
|
||||
-> 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)
|
||||
-> Sort (cost=11583.61..11804.76 rows=88459 width=32) (actual time=1431.589..1431.591 rows=10 loops=1)
|
||||
Sort Key: ((word <-> '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
|
||||
-> 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)
|
||||
-> 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 <-> '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
|
||||
|
||||
@ -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);
|
||||
}
|
||||
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user