Movatterモバイル変換

[0]ホーム
URL:

Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

 Sign up
Appearance settings

Commit5f86cbd

Browse files
committed
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 theplanning 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 examineEXPLAIN ANALYZE output.In passing, I failed to resist the temptation to do a little editing on thematerialized-view example affected by this change.
1 parente183d11 commit5f86cbd

File tree

4 files changed

+48
-38
lines changed

4 files changed

+48
-38
lines changed

‎doc/src/sgml/perform.sgml

Lines changed: 10 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -584,7 +584,7 @@ WHERE t1.unique1 < 10 AND t1.unique2 = t2.unique2;
584584
-> 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)
585585
Index Cond: (unique2 = t1.unique2)
586586
Planning time: 0.181 ms
587-
Total runtime: 0.501 ms
587+
Execution time: 0.501 ms
588588
</screen>
589589

590590
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;
633633
-&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)
634634
Index Cond: (unique1 &lt; 100)
635635
Planning time: 0.194 ms
636-
Total runtime: 8.008 ms
636+
Execution time: 8.008 ms
637637
</screen>
638638

639639
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;
657657
Filter: (ten &lt; 7)
658658
Rows Removed by Filter: 3000
659659
Planning time: 0.083 ms
660-
Total runtime: 5.905 ms
660+
Execution time: 5.905 ms
661661
</screen>
662662

663663
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)';
680680
Filter: (f1 @&gt; '((0.5,2))'::polygon)
681681
Rows Removed by Filter: 4
682682
Planning time: 0.040 ms
683-
Total runtime: 0.083 ms
683+
Execution time: 0.083 ms
684684
</screen>
685685

686686
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)';
699699
Index Cond: (f1 @&gt; '((0.5,2))'::polygon)
700700
Rows Removed by Index Recheck: 1
701701
Planning time: 0.034 ms
702-
Total runtime: 0.144 ms
702+
Execution time: 0.144 ms
703703
</screen>
704704

705705
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
730730
Index Cond: (unique2 &gt; 9000)
731731
Buffers: shared hit=5
732732
Planning time: 0.088 ms
733-
Total runtime: 0.423 ms
733+
Execution time: 0.423 ms
734734
</screen>
735735

736736
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;
758758
-&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)
759759
Index Cond: (unique1 &lt; 100)
760760
Planning time: 0.079 ms
761-
Total runtime: 14.727 ms
761+
Execution time: 14.727 ms
762762

763763
ROLLBACK;
764764
</screen>
@@ -781,7 +781,7 @@ ROLLBACK;
781781
</para>
782782

783783
<para>
784-
The <literal>Total runtime</literal> shown by <command>EXPLAIN
784+
The <literal>Execution time</literal> shown by <command>EXPLAIN
785785
ANALYZE</command> includes executor start-up and shut-down time, as well
786786
as the time to run any triggers that are fired, but it does not include
787787
parsing, rewriting, or planning time.
@@ -792,7 +792,7 @@ ROLLBACK;
792792
The total time spent in each trigger
793793
(either <literal>BEFORE</> or <literal>AFTER</>) is also shown separately.
794794
Note that deferred constraint triggers will not be executed
795-
until end of transaction and are thus notshown at all by
795+
until end of transaction and are thus notconsidered at all by
796796
<command>EXPLAIN ANALYZE</command>.
797797
</para>
798798

@@ -844,7 +844,7 @@ EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND unique2 &gt; 9000
844844
Filter: (unique1 &lt; 100)
845845
Rows Removed by Filter: 287
846846
Planning time: 0.096 ms
847-
Total runtime: 0.336 ms
847+
Execution time: 0.336 ms
848848
</screen>
849849

850850
the estimated cost and row count for the Index Scan node are shown as

‎doc/src/sgml/ref/explain.sgml

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -408,7 +408,7 @@ EXPLAIN ANALYZE EXECUTE query(100, 200);
408408
-&gt; 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)
409409
Index Cond: ((id &gt; $1) AND (id &lt; $2))
410410
Planning time: 0.197 ms
411-
Total runtime: 0.225 ms
411+
Execution time: 0.225 ms
412412
(5 rows)
413413
</programlisting>
414414
</para>

‎doc/src/sgml/rules.sgml

Lines changed: 34 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -993,19 +993,25 @@ REFRESH MATERIALIZED VIEW sales_summary;
993993

994994
<para>
995995
Another use for a materialized view is to allow faster access to data
996-
brought across from a remote system, through a foreign data wrapper.
996+
brought across from a remote system through a foreign data wrapper.
997997
A simple example using <literal>file_fdw</literal> is below, with timings,
998998
but since this is using cache on the local system the performance
999-
difference on a foreign data wrapper to a remote system could be greater.
999+
difference compared to access to a remote system would usually be greater
1000+
than shown here. Notice we are also exploiting the ability to put an
1001+
index on the materialized view, whereas <literal>file_fdw</literal> does
1002+
not support indexes; this advantage might not apply for other sorts of
1003+
foreign data access.
1004+
</para>
10001005

1006+
<para>
10011007
Setup:
10021008

10031009
<programlisting>
10041010
CREATE EXTENSION file_fdw;
10051011
CREATE SERVER local_file FOREIGN DATA WRAPPER file_fdw;
10061012
CREATE FOREIGN TABLE words (word text NOT NULL)
10071013
SERVER local_file
1008-
OPTIONS (filename '/etc/dictionaries-common/words');
1014+
OPTIONS (filename '/usr/share/dict/words');
10091015
CREATE MATERIALIZED VIEW wrd AS SELECT * FROM words;
10101016
CREATE UNIQUE INDEX wrd_word ON wrd (word);
10111017
CREATE EXTENSION pg_trgm;
@@ -1024,26 +1030,28 @@ SELECT count(*) FROM words WHERE word = 'caterpiler';
10241030
(1 row)
10251031
</programlisting>
10261032

1027-
The plan is:
1033+
With <command>EXPLAIN ANALYZE</>, we see:
10281034

10291035
<programlisting>
1030-
Aggregate (cost=4125.19..4125.20 rows=1 width=0) (actual time=26.013..26.014 rows=1 loops=1)
1031-
-> Foreign Scan on words (cost=0.00..4124.70 rows=196 width=0) (actual time=26.011..26.011 rows=0 loops=1)
1036+
Aggregate (cost=21763.99..21764.00 rows=1 width=0) (actual time=188.180..188.181 rows=1 loops=1)
1037+
-&gt; Foreign Scan on words (cost=0.00..21761.41 rows=1032 width=0) (actual time=188.177..188.177 rows=0 loops=1)
10321038
Filter: (word = 'caterpiler'::text)
1033-
Rows Removed by Filter: 99171
1034-
Foreign File: /etc/dictionaries-common/words
1035-
Foreign File Size: 938848
1036-
Total runtime: 26.081 ms
1039+
Rows Removed by Filter: 479829
1040+
Foreign File: /usr/share/dict/words
1041+
Foreign File Size: 4953699
1042+
Planning time: 0.118 ms
1043+
Execution time: 188.273 ms
10371044
</programlisting>
10381045

10391046
If the materialized view is used instead, the query is much faster:
10401047

10411048
<programlisting>
1042-
Aggregate (cost=4.44..4.45 rows=1 width=0) (actual time=0.074..0.074 rows=1 loops=1)
1043-
-> 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)
1049+
Aggregate (cost=4.44..4.45 rows=1 width=0) (actual time=0.042..0.042 rows=1 loops=1)
1050+
-&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)
10441051
Index Cond: (word = 'caterpiler'::text)
10451052
Heap Fetches: 0
1046-
Total runtime: 0.119 ms
1053+
Planning time: 0.164 ms
1054+
Execution time: 0.117 ms
10471055
</programlisting>
10481056

10491057
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;
10681076
</programlisting>
10691077

10701078
<programlisting>
1071-
Limit (cost=2195.70..2195.72 rows=10 width=32) (actual time=218.904..218.906 rows=10 loops=1)
1072-
-> Sort (cost=2195.70..2237.61 rows=16765 width=32) (actual time=218.902..218.904 rows=10 loops=1)
1073-
Sort Key: ((word<-> 'caterpiler'::text))
1079+
Limit (cost=11583.61..11583.64 rows=10 width=32) (actual time=1431.591..1431.594 rows=10 loops=1)
1080+
-&gt; Sort (cost=11583.61..11804.76 rows=88459 width=32) (actual time=1431.589..1431.591 rows=10 loops=1)
1081+
Sort Key: ((word&lt;-&gt; 'caterpiler'::text))
10741082
Sort Method: top-N heapsort Memory: 25kB
1075-
-> Foreign Scan on words (cost=0.00..1833.41 rows=16765 width=32) (actual time=0.046..200.965 rows=99171 loops=1)
1076-
Foreign File: /etc/dictionaries-common/words
1077-
Foreign File Size: 938848
1078-
Total runtime: 218.966 ms
1083+
-&gt; Foreign Scan on words (cost=0.00..9672.05 rows=88459 width=32) (actual time=0.057..1286.455 rows=479829 loops=1)
1084+
Foreign File: /usr/share/dict/words
1085+
Foreign File Size: 4953699
1086+
Planning time: 0.128 ms
1087+
Execution time: 1431.679 ms
10791088
</programlisting>
10801089

10811090
Using the materialized view:
10821091

10831092
<programlisting>
1084-
Limit (cost=0.28..1.02 rows=10 width=9) (actual time=24.916..25.079 rows=10 loops=1)
1085-
-> 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)
1086-
Order By: (word <-> 'caterpiler'::text)
1087-
Total runtime: 25.884 ms
1093+
Limit (cost=0.29..1.06 rows=10 width=10) (actual time=187.222..188.257 rows=10 loops=1)
1094+
-&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)
1095+
Order By: (word &lt;-&gt; 'caterpiler'::text)
1096+
Planning time: 0.196 ms
1097+
Execution time: 198.640 ms
10881098
</programlisting>
10891099

10901100
If you can tolerate periodic update of the remote data to the local

‎src/backend/commands/explain.c

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -508,7 +508,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
508508

509509
/*
510510
* Close down the query and free resources. Include time for this in the
511-
* totalruntime (although it should be pretty minimal).
511+
* totalexecution time (although it should be pretty minimal).
512512
*/
513513
INSTR_TIME_SET_CURRENT(starttime);
514514

@@ -527,10 +527,10 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
527527
if (es->analyze)
528528
{
529529
if (es->format==EXPLAIN_FORMAT_TEXT)
530-
appendStringInfo(es->str,"Total runtime: %.3f ms\n",
530+
appendStringInfo(es->str,"Execution time: %.3f ms\n",
531531
1000.0*totaltime);
532532
else
533-
ExplainPropertyFloat("Total Runtime",1000.0*totaltime,
533+
ExplainPropertyFloat("Execution Time",1000.0*totaltime,
534534
3,es);
535535
}
536536

0 commit comments

Comments
 (0)
[8]ページ先頭
©2009-2025 Movatter.jp