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
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
|
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd"><html xmlns="http://www.w3.org/1999/xhtml"><head><meta http-equiv="Content-Type" content="text/html; charset=UTF-8" /><title>F.4. auto_explain — log execution plans of slow queries</title><link rel="stylesheet" type="text/css" href="stylesheet.css" /><link rev="made" href="pgsql-docs@lists.postgresql.org" /><meta name="generator" content="DocBook XSL Stylesheets Vsnapshot" /><link rel="prev" href="auth-delay.html" title="F.3. auth_delay — pause on authentication failure" /><link rel="next" href="basebackup-to-shell.html" title="F.5. basebackup_to_shell — example "shell" pg_basebackup module" /></head><body id="docContent" class="container-fluid col-10"><div class="navheader"><table width="100%" summary="Navigation header"><tr><th colspan="5" align="center">F.4. auto_explain — log execution plans of slow queries</th></tr><tr><td width="10%" align="left"><a accesskey="p" href="auth-delay.html" title="F.3. auth_delay — pause on authentication failure">Prev</a> </td><td width="10%" align="left"><a accesskey="u" href="contrib.html" title="Appendix F. Additional Supplied Modules and Extensions">Up</a></td><th width="60%" align="center">Appendix F. Additional Supplied Modules and Extensions</th><td width="10%" align="right"><a accesskey="h" href="index.html" title="PostgreSQL 16.2 Documentation">Home</a></td><td width="10%" align="right"> <a accesskey="n" href="basebackup-to-shell.html" title="F.5. basebackup_to_shell — example "shell" pg_basebackup module">Next</a></td></tr></table><hr /></div><div class="sect1" id="AUTO-EXPLAIN"><div class="titlepage"><div><div><h2 class="title" style="clear: both">F.4. auto_explain — log execution plans of slow queries <a href="#AUTO-EXPLAIN" class="id_link">#</a></h2></div></div></div><div class="toc"><dl class="toc"><dt><span class="sect2"><a href="auto-explain.html#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS">F.4.1. Configuration Parameters</a></span></dt><dt><span class="sect2"><a href="auto-explain.html#AUTO-EXPLAIN-EXAMPLE">F.4.2. Example</a></span></dt><dt><span class="sect2"><a href="auto-explain.html#AUTO-EXPLAIN-AUTHOR">F.4.3. Author</a></span></dt></dl></div><a id="id-1.11.7.14.2" class="indexterm"></a><p>
The <code class="filename">auto_explain</code> module provides a means for
logging execution plans of slow statements automatically, without
having to run <a class="xref" href="sql-explain.html" title="EXPLAIN"><span class="refentrytitle">EXPLAIN</span></a>
by hand. This is especially helpful for tracking down un-optimized queries
in large applications.
</p><p>
The module provides no SQL-accessible functions. To use it, simply
load it into the server. You can load it into an individual session:
</p><pre class="programlisting">
LOAD 'auto_explain';
</pre><p>
(You must be superuser to do that.) More typical usage is to preload
it into some or all sessions by including <code class="literal">auto_explain</code> in
<a class="xref" href="runtime-config-client.html#GUC-SESSION-PRELOAD-LIBRARIES">session_preload_libraries</a> or
<a class="xref" href="runtime-config-client.html#GUC-SHARED-PRELOAD-LIBRARIES">shared_preload_libraries</a> in
<code class="filename">postgresql.conf</code>. Then you can track unexpectedly slow queries
no matter when they happen. Of course there is a price in overhead for
that.
</p><div class="sect2" id="AUTO-EXPLAIN-CONFIGURATION-PARAMETERS"><div class="titlepage"><div><div><h3 class="title">F.4.1. Configuration Parameters <a href="#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS" class="id_link">#</a></h3></div></div></div><p>
There are several configuration parameters that control the behavior of
<code class="filename">auto_explain</code>. Note that the default behavior is
to do nothing, so you must set at least
<code class="varname">auto_explain.log_min_duration</code> if you want any results.
</p><div class="variablelist"><dl class="variablelist"><dt id="AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-MIN-DURATION"><span class="term">
<code class="varname">auto_explain.log_min_duration</code> (<code class="type">integer</code>)
<a id="id-1.11.7.14.5.3.1.1.3" class="indexterm"></a>
</span> <a href="#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-MIN-DURATION" class="id_link">#</a></dt><dd><p>
<code class="varname">auto_explain.log_min_duration</code> is the minimum statement
execution time, in milliseconds, that will cause the statement's plan to
be logged. Setting this to <code class="literal">0</code> logs all plans.
<code class="literal">-1</code> (the default) disables logging of plans. For
example, if you set it to <code class="literal">250ms</code> then all statements
that run 250ms or longer will be logged. Only superusers can change this
setting.
</p></dd><dt id="AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-PARAMETER-MAX-LENGTH"><span class="term">
<code class="varname">auto_explain.log_parameter_max_length</code> (<code class="type">integer</code>)
<a id="id-1.11.7.14.5.3.2.1.3" class="indexterm"></a>
</span> <a href="#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-PARAMETER-MAX-LENGTH" class="id_link">#</a></dt><dd><p>
<code class="varname">auto_explain.log_parameter_max_length</code> controls the
logging of query parameter values. A value of <code class="literal">-1</code> (the
default) logs the parameter values in full. <code class="literal">0</code> disables
logging of parameter values. A value greater than zero truncates each
parameter value to that many bytes. Only superusers can change this
setting.
</p></dd><dt id="AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-ANALYZE"><span class="term">
<code class="varname">auto_explain.log_analyze</code> (<code class="type">boolean</code>)
<a id="id-1.11.7.14.5.3.3.1.3" class="indexterm"></a>
</span> <a href="#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-ANALYZE" class="id_link">#</a></dt><dd><p>
<code class="varname">auto_explain.log_analyze</code> causes <code class="command">EXPLAIN ANALYZE</code>
output, rather than just <code class="command">EXPLAIN</code> output, to be printed
when an execution plan is logged. This parameter is off by default.
Only superusers can change this setting.
</p><div class="note"><h3 class="title">Note</h3><p>
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 an extremely negative impact on performance.
Turning off <code class="varname">auto_explain.log_timing</code> ameliorates the
performance cost, at the price of obtaining less information.
</p></div></dd><dt id="AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-BUFFERS"><span class="term">
<code class="varname">auto_explain.log_buffers</code> (<code class="type">boolean</code>)
<a id="id-1.11.7.14.5.3.4.1.3" class="indexterm"></a>
</span> <a href="#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-BUFFERS" class="id_link">#</a></dt><dd><p>
<code class="varname">auto_explain.log_buffers</code> controls whether buffer
usage statistics are printed when an execution plan is logged; it's
equivalent to the <code class="literal">BUFFERS</code> option of <code class="command">EXPLAIN</code>.
This parameter has no effect
unless <code class="varname">auto_explain.log_analyze</code> is enabled.
This parameter is off by default.
Only superusers can change this setting.
</p></dd><dt id="AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-WAL"><span class="term">
<code class="varname">auto_explain.log_wal</code> (<code class="type">boolean</code>)
<a id="id-1.11.7.14.5.3.5.1.3" class="indexterm"></a>
</span> <a href="#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-WAL" class="id_link">#</a></dt><dd><p>
<code class="varname">auto_explain.log_wal</code> controls whether WAL
usage statistics are printed when an execution plan is logged; it's
equivalent to the <code class="literal">WAL</code> option of <code class="command">EXPLAIN</code>.
This parameter has no effect
unless <code class="varname">auto_explain.log_analyze</code> is enabled.
This parameter is off by default.
Only superusers can change this setting.
</p></dd><dt id="AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-TIMING"><span class="term">
<code class="varname">auto_explain.log_timing</code> (<code class="type">boolean</code>)
<a id="id-1.11.7.14.5.3.6.1.3" class="indexterm"></a>
</span> <a href="#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-TIMING" class="id_link">#</a></dt><dd><p>
<code class="varname">auto_explain.log_timing</code> controls whether per-node
timing information is printed when an execution plan is logged; it's
equivalent to the <code class="literal">TIMING</code> option of <code class="command">EXPLAIN</code>.
The overhead of repeatedly reading the system clock can slow down
queries significantly on some systems, so it may be useful to set this
parameter to off when only actual row counts, and not exact times, are
needed.
This parameter has no effect
unless <code class="varname">auto_explain.log_analyze</code> is enabled.
This parameter is on by default.
Only superusers can change this setting.
</p></dd><dt id="AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-TRIGGERS"><span class="term">
<code class="varname">auto_explain.log_triggers</code> (<code class="type">boolean</code>)
<a id="id-1.11.7.14.5.3.7.1.3" class="indexterm"></a>
</span> <a href="#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-TRIGGERS" class="id_link">#</a></dt><dd><p>
<code class="varname">auto_explain.log_triggers</code> causes trigger
execution statistics to be included when an execution plan is logged.
This parameter has no effect
unless <code class="varname">auto_explain.log_analyze</code> is enabled.
This parameter is off by default.
Only superusers can change this setting.
</p></dd><dt id="AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-VERBOSE"><span class="term">
<code class="varname">auto_explain.log_verbose</code> (<code class="type">boolean</code>)
<a id="id-1.11.7.14.5.3.8.1.3" class="indexterm"></a>
</span> <a href="#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-VERBOSE" class="id_link">#</a></dt><dd><p>
<code class="varname">auto_explain.log_verbose</code> controls whether verbose
details are printed when an execution plan is logged; it's
equivalent to the <code class="literal">VERBOSE</code> option of <code class="command">EXPLAIN</code>.
This parameter is off by default.
Only superusers can change this setting.
</p></dd><dt id="AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-SETTINGS"><span class="term">
<code class="varname">auto_explain.log_settings</code> (<code class="type">boolean</code>)
<a id="id-1.11.7.14.5.3.9.1.3" class="indexterm"></a>
</span> <a href="#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-SETTINGS" class="id_link">#</a></dt><dd><p>
<code class="varname">auto_explain.log_settings</code> controls whether information
about modified configuration options is printed when an execution plan is logged.
Only options affecting query planning with value different from the built-in
default value are included in the output. This parameter is off by default.
Only superusers can change this setting.
</p></dd><dt id="AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-FORMAT"><span class="term">
<code class="varname">auto_explain.log_format</code> (<code class="type">enum</code>)
<a id="id-1.11.7.14.5.3.10.1.3" class="indexterm"></a>
</span> <a href="#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-FORMAT" class="id_link">#</a></dt><dd><p>
<code class="varname">auto_explain.log_format</code> selects the
<code class="command">EXPLAIN</code> output format to be used.
The allowed values are <code class="literal">text</code>, <code class="literal">xml</code>,
<code class="literal">json</code>, and <code class="literal">yaml</code>. The default is text.
Only superusers can change this setting.
</p></dd><dt id="AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-LEVEL"><span class="term">
<code class="varname">auto_explain.log_level</code> (<code class="type">enum</code>)
<a id="id-1.11.7.14.5.3.11.1.3" class="indexterm"></a>
</span> <a href="#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-LEVEL" class="id_link">#</a></dt><dd><p>
<code class="varname">auto_explain.log_level</code> selects the log level at which
auto_explain will log the query plan.
Valid values are <code class="literal">DEBUG5</code>, <code class="literal">DEBUG4</code>,
<code class="literal">DEBUG3</code>, <code class="literal">DEBUG2</code>,
<code class="literal">DEBUG1</code>, <code class="literal">INFO</code>,
<code class="literal">NOTICE</code>, <code class="literal">WARNING</code>,
and <code class="literal">LOG</code>. The default is <code class="literal">LOG</code>.
Only superusers can change this setting.
</p></dd><dt id="AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-NESTED-STATEMENTS"><span class="term">
<code class="varname">auto_explain.log_nested_statements</code> (<code class="type">boolean</code>)
<a id="id-1.11.7.14.5.3.12.1.3" class="indexterm"></a>
</span> <a href="#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-LOG-NESTED-STATEMENTS" class="id_link">#</a></dt><dd><p>
<code class="varname">auto_explain.log_nested_statements</code> 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.
</p></dd><dt id="AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-SAMPLE-RATE"><span class="term">
<code class="varname">auto_explain.sample_rate</code> (<code class="type">real</code>)
<a id="id-1.11.7.14.5.3.13.1.3" class="indexterm"></a>
</span> <a href="#AUTO-EXPLAIN-CONFIGURATION-PARAMETERS-SAMPLE-RATE" class="id_link">#</a></dt><dd><p>
<code class="varname">auto_explain.sample_rate</code> causes auto_explain to only
explain a fraction of the statements in each session. The default is 1,
meaning explain all the queries. In case of nested statements, either all
will be explained or none. Only superusers can change this setting.
</p></dd></dl></div><p>
In ordinary usage, these parameters are set
in <code class="filename">postgresql.conf</code>, although superusers can alter them
on-the-fly within their own sessions.
Typical usage might be:
</p><pre class="programlisting">
# postgresql.conf
session_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = '3s'
</pre></div><div class="sect2" id="AUTO-EXPLAIN-EXAMPLE"><div class="titlepage"><div><div><h3 class="title">F.4.2. Example <a href="#AUTO-EXPLAIN-EXAMPLE" class="id_link">#</a></h3></div></div></div><pre class="programlisting">
postgres=# LOAD 'auto_explain';
postgres=# SET auto_explain.log_min_duration = 0;
postgres=# SET auto_explain.log_analyze = true;
postgres=# SELECT count(*)
FROM pg_class, pg_index
WHERE oid = indrelid AND indisunique;
</pre><p>
This might produce log output such as:
</p><pre class="screen">
LOG: duration: 3.651 ms plan:
Query Text: SELECT count(*)
FROM pg_class, pg_index
WHERE oid = indrelid AND indisunique;
Aggregate (cost=16.79..16.80 rows=1 width=0) (actual time=3.626..3.627 rows=1 loops=1)
-> Hash Join (cost=4.17..16.55 rows=92 width=0) (actual time=3.349..3.594 rows=92 loops=1)
Hash Cond: (pg_class.oid = pg_index.indrelid)
-> Seq Scan on pg_class (cost=0.00..9.55 rows=255 width=4) (actual time=0.016..0.140 rows=255 loops=1)
-> Hash (cost=3.02..3.02 rows=92 width=4) (actual time=3.238..3.238 rows=92 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 4kB
-> Seq Scan on pg_index (cost=0.00..3.02 rows=92 width=4) (actual time=0.008..3.187 rows=92 loops=1)
Filter: indisunique
</pre></div><div class="sect2" id="AUTO-EXPLAIN-AUTHOR"><div class="titlepage"><div><div><h3 class="title">F.4.3. Author <a href="#AUTO-EXPLAIN-AUTHOR" class="id_link">#</a></h3></div></div></div><p>
Takahiro Itagaki <code class="email"><<a class="email" href="mailto:itagaki.takahiro@oss.ntt.co.jp">itagaki.takahiro@oss.ntt.co.jp</a>></code>
</p></div></div><div class="navfooter"><hr /><table width="100%" summary="Navigation footer"><tr><td width="40%" align="left"><a accesskey="p" href="auth-delay.html" title="F.3. auth_delay — pause on authentication failure">Prev</a> </td><td width="20%" align="center"><a accesskey="u" href="contrib.html" title="Appendix F. Additional Supplied Modules and Extensions">Up</a></td><td width="40%" align="right"> <a accesskey="n" href="basebackup-to-shell.html" title="F.5. basebackup_to_shell — example "shell" pg_basebackup module">Next</a></td></tr><tr><td width="40%" align="left" valign="top">F.3. auth_delay — pause on authentication failure </td><td width="20%" align="center"><a accesskey="h" href="index.html" title="PostgreSQL 16.2 Documentation">Home</a></td><td width="40%" align="right" valign="top"> F.5. basebackup_to_shell — example "shell" pg_basebackup module</td></tr></table></div></body></html>
|
