diff --git a/doc/src/sgml/perform.sgml b/doc/src/sgml/perform.sgml index f0ab440cd385d8573214512e56811476783b5df0..657575c07ad6fbc535c35434fc48b81680d6684e 100644 --- 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 < 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 diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index 04a78ee82ea2b6ca7225d05779141aa61f0960a5..c4aa95f93023317e37616a7b083fd35680f4f3cd 100644 --- 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 --- 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) + -> 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 diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 08f3167f10d638a8b616504ee4030b32e1ab66d2..1104cc363123a1c833bd4c1f1a01c60992041658 100644 --- 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); }