1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
|
<!-- $PostgreSQL: pgsql/doc/src/sgml/auto-explain.sgml,v 1.3 2009/01/02 01:16:02 tgl Exp $ -->
<sect1 id="auto-explain">
<title>auto_explain</title>
<indexterm zone="auto-explain">
<primary>auto_explain</primary>
</indexterm>
<para>
The <filename>auto_explain</filename> module provides a means for
logging execution plans of slow statements automatically, without
having to run <xref linkend="sql-explain" endterm="sql-explain-title">
by hand. This is especially helpful for tracking down un-optimized queries
in large applications.
</para>
<para>
The module provides no SQL-accessible functions. To use it, simply
load it into the server. You can load it into an individual session:
<programlisting>
LOAD 'auto_explain';
</programlisting>
(You must be superuser to do that.) More typical usage is to preload
it into all sessions by including <literal>auto_explain</> in
<xref linkend="guc-shared-preload-libraries"> in
<filename>postgresql.conf</>. Then you can track unexpectedly slow queries
no matter when they happen. Of course there is a price in overhead for
that.
</para>
<sect2>
<title>Configuration parameters</title>
<para>
There are several configuration parameters that control the behavior of
<filename>auto_explain</filename>. Note that the default behavior is
to do nothing, so you must set at least
<varname>auto_explain.log_min_duration</varname> if you want any results.
</para>
<variablelist>
<varlistentry>
<term>
<varname>auto_explain.log_min_duration</varname> (<type>integer</type>)
</term>
<indexterm>
<primary><varname>auto_explain.log_min_duration</> configuration parameter</primary>
</indexterm>
<listitem>
<para>
<varname>auto_explain.log_min_duration</varname> is the minimum statement
execution time, in milliseconds, that will cause the statement's plan to
be logged. Setting this to zero logs all plans. Minus-one (the default)
disables logging of plans. For example, if you set it to
<literal>250ms</literal> then all statements that run 250ms or longer
will be logged. Only superusers can change this setting.
</para>
</listitem>
</varlistentry>
<varlistentry>
<term>
<varname>auto_explain.log_analyze</varname> (<type>boolean</type>)
</term>
<indexterm>
<primary><varname>auto_explain.log_analyze</> configuration parameter</primary>
</indexterm>
<listitem>
<para>
<varname>auto_explain.log_analyze</varname> causes <command>EXPLAIN ANALYZE</>
output, rather than just <command>EXPLAIN</> output, to be printed
when an execution plan is logged. This parameter is off by default.
Only superusers can change this setting.
</para>
<note>
<para>
When this parameter is on, per-plan-node timing occurs for all
statements executed, whether or not they run long enough to actually
get logged. This can have extremely negative impact on performance.
</para>
</note>
</listitem>
</varlistentry>
<varlistentry>
<term>
<varname>auto_explain.log_verbose</varname> (<type>boolean</type>)
</term>
<indexterm>
<primary><varname>auto_explain.log_verbose</> configuration parameter</primary>
</indexterm>
<listitem>
<para>
<varname>auto_explain.log_verbose</varname> causes <command>EXPLAIN VERBOSE</>
output, rather than just <command>EXPLAIN</> output, to be printed
when an execution plan is logged. This parameter is off by default.
Only superusers can change this setting.
</para>
</listitem>
</varlistentry>
<varlistentry>
<term>
<varname>auto_explain.log_nested_statements</varname> (<type>boolean</type>)
</term>
<indexterm>
<primary><varname>auto_explain.log_nested_statements</> configuration parameter</primary>
</indexterm>
<listitem>
<para>
<varname>auto_explain.log_nested_statements</varname> causes nested
statements (statements executed inside a function) to be considered
for logging. When it is off, only top-level query plans are logged. This
parameter is off by default. Only superusers can change this setting.
</para>
</listitem>
</varlistentry>
</variablelist>
<para>
In order to set these parameters in your <filename>postgresql.conf</> file,
you will need to add <literal>auto_explain</> to
<xref linkend="guc-custom-variable-classes">. Typical usage might be:
</para>
<programlisting>
# postgresql.conf
shared_preload_libraries = 'auto_explain'
custom_variable_classes = 'auto_explain'
auto_explain.log_min_duration = '3s'
</programlisting>
</sect2>
<sect2>
<title>Example</title>
<programlisting>
postgres=# LOAD 'auto_explain';
postgres=# SET auto_explain.log_min_duration = 0;
postgres=# SELECT count(*)
FROM pg_class, pg_index
WHERE oid = indrelid AND indisunique;
</programlisting>
<para>
This might produce log output such as:
</para>
<programlisting><![CDATA[
LOG: duration: 0.986 ms plan:
Aggregate (cost=14.90..14.91 rows=1 width=0)
-> Hash Join (cost=3.91..14.70 rows=81 width=0)
Hash Cond: (pg_class.oid = pg_index.indrelid)
-> Seq Scan on pg_class (cost=0.00..8.27 rows=227 width=4)
-> Hash (cost=2.90..2.90 rows=81 width=4)
-> Seq Scan on pg_index (cost=0.00..2.90 rows=81 width=4)
Filter: indisunique
STATEMENT: SELECT count(*)
FROM pg_class, pg_index
WHERE oid = indrelid AND indisunique;
]]>
</programlisting>
</sect2>
<sect2>
<title>Author</title>
<para>
Takahiro Itagaki <email>[email protected]</email>
</para>
</sect2>
</sect1>
|
