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