1<!-- doc/src/sgml/auto-explain.sgml -->
2
3<sect1 id="auto-explain" xreflabel="auto_explain">
4 <title>auto_explain</title>
5
6 <indexterm zone="auto-explain">
7  <primary>auto_explain</primary>
8 </indexterm>
9
10 <para>
11  The <filename>auto_explain</filename> module provides a means for
12  logging execution plans of slow statements automatically, without
13  having to run <xref linkend="sql-explain"/>
14  by hand.  This is especially helpful for tracking down un-optimized queries
15  in large applications.
16 </para>
17
18 <para>
19  The module provides no SQL-accessible functions.  To use it, simply
20  load it into the server.  You can load it into an individual session:
21
22<programlisting>
23LOAD 'auto_explain';
24</programlisting>
25
26  (You must be superuser to do that.)  More typical usage is to preload
27  it into some or all sessions by including <literal>auto_explain</literal> in
28  <xref linkend="guc-session-preload-libraries"/> or
29  <xref linkend="guc-shared-preload-libraries"/> in
30  <filename>postgresql.conf</filename>.  Then you can track unexpectedly slow queries
31  no matter when they happen.  Of course there is a price in overhead for
32  that.
33 </para>
34
35 <sect2>
36  <title>Configuration Parameters</title>
37
38 <para>
39  There are several configuration parameters that control the behavior of
40  <filename>auto_explain</filename>.  Note that the default behavior is
41  to do nothing, so you must set at least
42  <varname>auto_explain.log_min_duration</varname> if you want any results.
43 </para>
44
45  <variablelist>
46   <varlistentry>
47    <term>
48     <varname>auto_explain.log_min_duration</varname> (<type>integer</type>)
49     <indexterm>
50      <primary><varname>auto_explain.log_min_duration</varname> configuration parameter</primary>
51     </indexterm>
52    </term>
53    <listitem>
54     <para>
55      <varname>auto_explain.log_min_duration</varname> is the minimum statement
56      execution time, in milliseconds, that will cause the statement's plan to
57      be logged. Setting this to <literal>0</literal> logs all plans.
58      <literal>-1</literal> (the default) disables logging of plans. For
59      example, if you set it to <literal>250ms</literal> then all statements
60      that run 250ms or longer will be logged. Only superusers can change this
61      setting.
62     </para>
63    </listitem>
64   </varlistentry>
65
66   <varlistentry>
67    <term>
68     <varname>auto_explain.log_analyze</varname> (<type>boolean</type>)
69     <indexterm>
70      <primary><varname>auto_explain.log_analyze</varname> configuration parameter</primary>
71     </indexterm>
72    </term>
73    <listitem>
74     <para>
75      <varname>auto_explain.log_analyze</varname> causes <command>EXPLAIN ANALYZE</command>
76      output, rather than just <command>EXPLAIN</command> output, to be printed
77      when an execution plan is logged. This parameter is off by default.
78      Only superusers can change this setting.
79     </para>
80     <note>
81      <para>
82       When this parameter is on, per-plan-node timing occurs for all
83       statements executed, whether or not they run long enough to actually
84       get logged.  This can have an extremely negative impact on performance.
85       Turning off <varname>auto_explain.log_timing</varname> ameliorates the
86       performance cost, at the price of obtaining less information.
87      </para>
88     </note>
89    </listitem>
90   </varlistentry>
91
92   <varlistentry>
93    <term>
94     <varname>auto_explain.log_buffers</varname> (<type>boolean</type>)
95     <indexterm>
96      <primary><varname>auto_explain.log_buffers</varname> configuration parameter</primary>
97     </indexterm>
98    </term>
99    <listitem>
100     <para>
101      <varname>auto_explain.log_buffers</varname> controls whether buffer
102      usage statistics are printed when an execution plan is logged; it's
103      equivalent to the <literal>BUFFERS</literal> option of <command>EXPLAIN</command>.
104      This parameter has no effect
105      unless <varname>auto_explain.log_analyze</varname> is enabled.
106      This parameter is off by default.
107      Only superusers can change this setting.
108     </para>
109    </listitem>
110   </varlistentry>
111
112   <varlistentry>
113    <term>
114     <varname>auto_explain.log_wal</varname> (<type>boolean</type>)
115     <indexterm>
116      <primary><varname>auto_explain.log_wal</varname> configuration parameter</primary>
117     </indexterm>
118    </term>
119    <listitem>
120     <para>
121      <varname>auto_explain.log_wal</varname> controls whether WAL
122      usage statistics are printed when an execution plan is logged; it's
123      equivalent to the <literal>WAL</literal> option of <command>EXPLAIN</command>.
124      This parameter has no effect
125      unless <varname>auto_explain.log_analyze</varname> is enabled.
126      This parameter is off by default.
127      Only superusers can change this setting.
128     </para>
129    </listitem>
130   </varlistentry>
131
132   <varlistentry>
133    <term>
134     <varname>auto_explain.log_timing</varname> (<type>boolean</type>)
135     <indexterm>
136      <primary><varname>auto_explain.log_timing</varname> configuration parameter</primary>
137     </indexterm>
138    </term>
139    <listitem>
140     <para>
141      <varname>auto_explain.log_timing</varname> controls whether per-node
142      timing information is printed when an execution plan is logged; it's
143      equivalent to the <literal>TIMING</literal> option of <command>EXPLAIN</command>.
144      The overhead of repeatedly reading the system clock can slow down
145      queries significantly on some systems, so it may be useful to set this
146      parameter to off when only actual row counts, and not exact times, are
147      needed.
148      This parameter has no effect
149      unless <varname>auto_explain.log_analyze</varname> is enabled.
150      This parameter is on by default.
151      Only superusers can change this setting.
152     </para>
153    </listitem>
154   </varlistentry>
155
156   <varlistentry>
157    <term>
158     <varname>auto_explain.log_triggers</varname> (<type>boolean</type>)
159     <indexterm>
160      <primary><varname>auto_explain.log_triggers</varname> configuration parameter</primary>
161     </indexterm>
162    </term>
163    <listitem>
164     <para>
165      <varname>auto_explain.log_triggers</varname> causes trigger
166      execution statistics to be included when an execution plan is logged.
167      This parameter has no effect
168      unless <varname>auto_explain.log_analyze</varname> is enabled.
169      This parameter is off by default.
170      Only superusers can change this setting.
171     </para>
172    </listitem>
173   </varlistentry>
174
175   <varlistentry>
176    <term>
177     <varname>auto_explain.log_verbose</varname> (<type>boolean</type>)
178     <indexterm>
179      <primary><varname>auto_explain.log_verbose</varname> configuration parameter</primary>
180     </indexterm>
181    </term>
182    <listitem>
183     <para>
184      <varname>auto_explain.log_verbose</varname> controls whether verbose
185      details are printed when an execution plan is logged; it's
186      equivalent to the <literal>VERBOSE</literal> option of <command>EXPLAIN</command>.
187      This parameter is off by default.
188      Only superusers can change this setting.
189     </para>
190    </listitem>
191   </varlistentry>
192
193   <varlistentry>
194    <term>
195     <varname>auto_explain.log_settings</varname> (<type>boolean</type>)
196     <indexterm>
197      <primary><varname>auto_explain.log_settings</varname> configuration parameter</primary>
198     </indexterm>
199    </term>
200    <listitem>
201     <para>
202      <varname>auto_explain.log_settings</varname> controls whether information
203      about modified configuration options is printed when an execution plan is logged.
204      Only options affecting query planning with value different from the built-in
205      default value are included in the output.  This parameter is off by default.
206      Only superusers can change this setting.
207     </para>
208    </listitem>
209   </varlistentry>
210
211   <varlistentry>
212    <term>
213     <varname>auto_explain.log_format</varname> (<type>enum</type>)
214     <indexterm>
215      <primary><varname>auto_explain.log_format</varname> configuration parameter</primary>
216     </indexterm>
217    </term>
218    <listitem>
219     <para>
220      <varname>auto_explain.log_format</varname> selects the
221      <command>EXPLAIN</command> output format to be used.
222      The allowed values are <literal>text</literal>, <literal>xml</literal>,
223      <literal>json</literal>, and <literal>yaml</literal>.  The default is text.
224      Only superusers can change this setting.
225     </para>
226    </listitem>
227   </varlistentry>
228
229   <varlistentry>
230    <term>
231     <varname>auto_explain.log_level</varname> (<type>enum</type>)
232     <indexterm>
233      <primary><varname>auto_explain.log_level</varname> configuration parameter</primary>
234     </indexterm>
235    </term>
236    <listitem>
237     <para>
238      <varname>auto_explain.log_level</varname> selects the log level at which
239      auto_explain will log the query plan.
240      Valid values are <literal>DEBUG5</literal>, <literal>DEBUG4</literal>,
241      <literal>DEBUG3</literal>, <literal>DEBUG2</literal>,
242      <literal>DEBUG1</literal>, <literal>INFO</literal>,
243      <literal>NOTICE</literal>, <literal>WARNING</literal>,
244      and <literal>LOG</literal>. The default is <literal>LOG</literal>.
245      Only superusers can change this setting.
246     </para>
247    </listitem>
248   </varlistentry>
249
250   <varlistentry>
251    <term>
252     <varname>auto_explain.log_nested_statements</varname> (<type>boolean</type>)
253     <indexterm>
254      <primary><varname>auto_explain.log_nested_statements</varname> configuration parameter</primary>
255     </indexterm>
256    </term>
257    <listitem>
258     <para>
259      <varname>auto_explain.log_nested_statements</varname> causes nested
260      statements (statements executed inside a function) to be considered
261      for logging.  When it is off, only top-level query plans are logged. This
262      parameter is off by default. Only superusers can change this setting.
263     </para>
264    </listitem>
265   </varlistentry>
266
267   <varlistentry>
268    <term>
269     <varname>auto_explain.sample_rate</varname> (<type>real</type>)
270     <indexterm>
271      <primary><varname>auto_explain.sample_rate</varname> configuration parameter</primary>
272     </indexterm>
273    </term>
274    <listitem>
275     <para>
276      <varname>auto_explain.sample_rate</varname> causes auto_explain to only
277      explain a fraction of the statements in each session.  The default is 1,
278      meaning explain all the queries.  In case of nested statements, either all
279      will be explained or none. Only superusers can change this setting.
280     </para>
281    </listitem>
282   </varlistentry>
283  </variablelist>
284
285  <para>
286   In ordinary usage, these parameters are set
287   in <filename>postgresql.conf</filename>, although superusers can alter them
288   on-the-fly within their own sessions.
289   Typical usage might be:
290  </para>
291
292<programlisting>
293# postgresql.conf
294session_preload_libraries = 'auto_explain'
295
296auto_explain.log_min_duration = '3s'
297</programlisting>
298 </sect2>
299
300 <sect2>
301  <title>Example</title>
302
303<programlisting>
304postgres=# LOAD 'auto_explain';
305postgres=# SET auto_explain.log_min_duration = 0;
306postgres=# SET auto_explain.log_analyze = true;
307postgres=# SELECT count(*)
308           FROM pg_class, pg_index
309           WHERE oid = indrelid AND indisunique;
310</programlisting>
311
312  <para>
313   This might produce log output such as:
314  </para>
315
316<screen><![CDATA[
317LOG:  duration: 3.651 ms  plan:
318  Query Text: SELECT count(*)
319              FROM pg_class, pg_index
320              WHERE oid = indrelid AND indisunique;
321  Aggregate  (cost=16.79..16.80 rows=1 width=0) (actual time=3.626..3.627 rows=1 loops=1)
322    ->  Hash Join  (cost=4.17..16.55 rows=92 width=0) (actual time=3.349..3.594 rows=92 loops=1)
323          Hash Cond: (pg_class.oid = pg_index.indrelid)
324          ->  Seq Scan on pg_class  (cost=0.00..9.55 rows=255 width=4) (actual time=0.016..0.140 rows=255 loops=1)
325          ->  Hash  (cost=3.02..3.02 rows=92 width=4) (actual time=3.238..3.238 rows=92 loops=1)
326                Buckets: 1024  Batches: 1  Memory Usage: 4kB
327                ->  Seq Scan on pg_index  (cost=0.00..3.02 rows=92 width=4) (actual time=0.008..3.187 rows=92 loops=1)
328                      Filter: indisunique
329]]></screen>
330 </sect2>
331
332 <sect2>
333  <title>Author</title>
334
335  <para>
336   Takahiro Itagaki <email>itagaki.takahiro@oss.ntt.co.jp</email>
337  </para>
338 </sect2>
339
340</sect1>
341