doc/src/sgml/auto-explain.sgml

   1 <!-- doc/src/sgml/auto-explain.sgml -->
   2
   3 <sect1 id="auto-explain" xreflabel="auto_explain">
   4  <title>auto_explain &mdash; log execution plans of slow queries</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>
  23 LOAD '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 id="auto-explain-configuration-parameters">
  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 id="auto-explain-configuration-parameters-log-min-duration">
  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 id="auto-explain-configuration-parameters-log-parameter-max-length">
  67     <term>
  68      <varname>auto_explain.log_parameter_max_length</varname> (<type>integer</type>)
  69      <indexterm>
  70       <primary><varname>auto_explain.log_parameter_max_length</varname> configuration parameter</primary>
  71      </indexterm>
  72     </term>
  73     <listitem>
  74      <para>
  75       <varname>auto_explain.log_parameter_max_length</varname> controls the
  76       logging of query parameter values. A value of <literal>-1</literal> (the
  77       default) logs the parameter values in full. <literal>0</literal> disables
  78       logging of parameter values. A value greater than zero truncates each
  79       parameter value to that many bytes. Only superusers can change this
  80       setting.
  81      </para>
  82     </listitem>
  83    </varlistentry>
  84
  85    <varlistentry id="auto-explain-configuration-parameters-log-analyze">
  86     <term>
  87      <varname>auto_explain.log_analyze</varname> (<type>boolean</type>)
  88      <indexterm>
  89       <primary><varname>auto_explain.log_analyze</varname> configuration parameter</primary>
  90      </indexterm>
  91     </term>
  92     <listitem>
  93      <para>
  94       <varname>auto_explain.log_analyze</varname> causes <command>EXPLAIN ANALYZE</command>
  95       output, rather than just <command>EXPLAIN</command> output, to be printed
  96       when an execution plan is logged. This parameter is off by default.
  97       Only superusers can change this setting.
  98      </para>
  99      <note>
 100       <para>
 101        When this parameter is on, per-plan-node timing occurs for all
 102        statements executed, whether or not they run long enough to actually
 103        get logged.  This can have an extremely negative impact on performance.
 104        Turning off <varname>auto_explain.log_timing</varname> ameliorates the
 105        performance cost, at the price of obtaining less information.
 106       </para>
 107      </note>
 108     </listitem>
 109    </varlistentry>
 110
 111    <varlistentry id="auto-explain-configuration-parameters-log-buffers">
 112     <term>
 113      <varname>auto_explain.log_buffers</varname> (<type>boolean</type>)
 114      <indexterm>
 115       <primary><varname>auto_explain.log_buffers</varname> configuration parameter</primary>
 116      </indexterm>
 117     </term>
 118     <listitem>
 119      <para>
 120       <varname>auto_explain.log_buffers</varname> controls whether buffer
 121       usage statistics are printed when an execution plan is logged; it's
 122       equivalent to the <literal>BUFFERS</literal> option of <command>EXPLAIN</command>.
 123       This parameter has no effect
 124       unless <varname>auto_explain.log_analyze</varname> is enabled.
 125       This parameter is off by default.
 126       Only superusers can change this setting.
 127      </para>
 128     </listitem>
 129    </varlistentry>
 130
 131    <varlistentry id="auto-explain-configuration-parameters-log-wal">
 132     <term>
 133      <varname>auto_explain.log_wal</varname> (<type>boolean</type>)
 134      <indexterm>
 135       <primary><varname>auto_explain.log_wal</varname> configuration parameter</primary>
 136      </indexterm>
 137     </term>
 138     <listitem>
 139      <para>
 140       <varname>auto_explain.log_wal</varname> controls whether WAL
 141       usage statistics are printed when an execution plan is logged; it's
 142       equivalent to the <literal>WAL</literal> option of <command>EXPLAIN</command>.
 143       This parameter has no effect
 144       unless <varname>auto_explain.log_analyze</varname> is enabled.
 145       This parameter is off by default.
 146       Only superusers can change this setting.
 147      </para>
 148     </listitem>
 149    </varlistentry>
 150
 151    <varlistentry id="auto-explain-configuration-parameters-log-timing">
 152     <term>
 153      <varname>auto_explain.log_timing</varname> (<type>boolean</type>)
 154      <indexterm>
 155       <primary><varname>auto_explain.log_timing</varname> configuration parameter</primary>
 156      </indexterm>
 157     </term>
 158     <listitem>
 159      <para>
 160       <varname>auto_explain.log_timing</varname> controls whether per-node
 161       timing information is printed when an execution plan is logged; it's
 162       equivalent to the <literal>TIMING</literal> option of <command>EXPLAIN</command>.
 163       The overhead of repeatedly reading the system clock can slow down
 164       queries significantly on some systems, so it may be useful to set this
 165       parameter to off when only actual row counts, and not exact times, are
 166       needed.
 167       This parameter has no effect
 168       unless <varname>auto_explain.log_analyze</varname> is enabled.
 169       This parameter is on by default.
 170       Only superusers can change this setting.
 171      </para>
 172     </listitem>
 173    </varlistentry>
 174
 175    <varlistentry id="auto-explain-configuration-parameters-log-triggers">
 176     <term>
 177      <varname>auto_explain.log_triggers</varname> (<type>boolean</type>)
 178      <indexterm>
 179       <primary><varname>auto_explain.log_triggers</varname> configuration parameter</primary>
 180      </indexterm>
 181     </term>
 182     <listitem>
 183      <para>
 184       <varname>auto_explain.log_triggers</varname> causes trigger
 185       execution statistics to be included when an execution plan is logged.
 186       This parameter has no effect
 187       unless <varname>auto_explain.log_analyze</varname> is enabled.
 188       This parameter is off by default.
 189       Only superusers can change this setting.
 190      </para>
 191     </listitem>
 192    </varlistentry>
 193
 194    <varlistentry id="auto-explain-configuration-parameters-log-verbose">
 195     <term>
 196      <varname>auto_explain.log_verbose</varname> (<type>boolean</type>)
 197      <indexterm>
 198       <primary><varname>auto_explain.log_verbose</varname> configuration parameter</primary>
 199      </indexterm>
 200     </term>
 201     <listitem>
 202      <para>
 203       <varname>auto_explain.log_verbose</varname> controls whether verbose
 204       details are printed when an execution plan is logged; it's
 205       equivalent to the <literal>VERBOSE</literal> option of <command>EXPLAIN</command>.
 206       This parameter is off by default.
 207       Only superusers can change this setting.
 208      </para>
 209     </listitem>
 210    </varlistentry>
 211
 212    <varlistentry id="auto-explain-configuration-parameters-log-settings">
 213     <term>
 214      <varname>auto_explain.log_settings</varname> (<type>boolean</type>)
 215      <indexterm>
 216       <primary><varname>auto_explain.log_settings</varname> configuration parameter</primary>
 217      </indexterm>
 218     </term>
 219     <listitem>
 220      <para>
 221       <varname>auto_explain.log_settings</varname> controls whether information
 222       about modified configuration options is printed when an execution plan is logged.
 223       Only options affecting query planning with value different from the built-in
 224       default value are included in the output.  This parameter is off by default.
 225       Only superusers can change this setting.
 226      </para>
 227     </listitem>
 228    </varlistentry>
 229
 230    <varlistentry id="auto-explain-configuration-parameters-log-format">
 231     <term>
 232      <varname>auto_explain.log_format</varname> (<type>enum</type>)
 233      <indexterm>
 234       <primary><varname>auto_explain.log_format</varname> configuration parameter</primary>
 235      </indexterm>
 236     </term>
 237     <listitem>
 238      <para>
 239       <varname>auto_explain.log_format</varname> selects the
 240       <command>EXPLAIN</command> output format to be used.
 241       The allowed values are <literal>text</literal>, <literal>xml</literal>,
 242       <literal>json</literal>, and <literal>yaml</literal>.  The default is text.
 243       Only superusers can change this setting.
 244      </para>
 245     </listitem>
 246    </varlistentry>
 247
 248    <varlistentry id="auto-explain-configuration-parameters-log-level">
 249     <term>
 250      <varname>auto_explain.log_level</varname> (<type>enum</type>)
 251      <indexterm>
 252       <primary><varname>auto_explain.log_level</varname> configuration parameter</primary>
 253      </indexterm>
 254     </term>
 255     <listitem>
 256      <para>
 257       <varname>auto_explain.log_level</varname> selects the log level at which
 258       auto_explain will log the query plan.
 259       Valid values are <literal>DEBUG5</literal>, <literal>DEBUG4</literal>,
 260       <literal>DEBUG3</literal>, <literal>DEBUG2</literal>,
 261       <literal>DEBUG1</literal>, <literal>INFO</literal>,
 262       <literal>NOTICE</literal>, <literal>WARNING</literal>,
 263       and <literal>LOG</literal>. The default is <literal>LOG</literal>.
 264       Only superusers can change this setting.
 265      </para>
 266     </listitem>
 267    </varlistentry>
 268
 269    <varlistentry id="auto-explain-configuration-parameters-log-nested-statements">
 270     <term>
 271      <varname>auto_explain.log_nested_statements</varname> (<type>boolean</type>)
 272      <indexterm>
 273       <primary><varname>auto_explain.log_nested_statements</varname> configuration parameter</primary>
 274      </indexterm>
 275     </term>
 276     <listitem>
 277      <para>
 278       <varname>auto_explain.log_nested_statements</varname> causes nested
 279       statements (statements executed inside a function) to be considered
 280       for logging.  When it is off, only top-level query plans are logged. This
 281       parameter is off by default. Only superusers can change this setting.
 282      </para>
 283     </listitem>
 284    </varlistentry>
 285
 286    <varlistentry id="auto-explain-configuration-parameters-sample-rate">
 287     <term>
 288      <varname>auto_explain.sample_rate</varname> (<type>real</type>)
 289      <indexterm>
 290       <primary><varname>auto_explain.sample_rate</varname> configuration parameter</primary>
 291      </indexterm>
 292     </term>
 293     <listitem>
 294      <para>
 295       <varname>auto_explain.sample_rate</varname> causes auto_explain to only
 296       explain a fraction of the statements in each session.  The default is 1,
 297       meaning explain all the queries.  In case of nested statements, either all
 298       will be explained or none. Only superusers can change this setting.
 299      </para>
 300     </listitem>
 301    </varlistentry>
 302   </variablelist>
 303
 304   <para>
 305    In ordinary usage, these parameters are set
 306    in <filename>postgresql.conf</filename>, although superusers can alter them
 307    on-the-fly within their own sessions.
 308    Typical usage might be:
 309   </para>
 310
 311 <programlisting>
 312 # postgresql.conf
 313 session_preload_libraries = 'auto_explain'
 314
 315 auto_explain.log_min_duration = '3s'
 316 </programlisting>
 317  </sect2>
 318
 319  <sect2 id="auto-explain-example">
 320   <title>Example</title>
 321
 322 <programlisting>
 323 postgres=# LOAD 'auto_explain';
 324 postgres=# SET auto_explain.log_min_duration = 0;
 325 postgres=# SET auto_explain.log_analyze = true;
 326 postgres=# SELECT count(*)
 327            FROM pg_class, pg_index
 328            WHERE oid = indrelid AND indisunique;
 329 </programlisting>
 330
 331   <para>
 332    This might produce log output such as:
 333   </para>
 334
 335 <screen><![CDATA[
 336 LOG:  duration: 3.651 ms  plan:
 337   Query Text: SELECT count(*)
 338               FROM pg_class, pg_index
 339               WHERE oid = indrelid AND indisunique;
 340   Aggregate  (cost=16.79..16.80 rows=1 width=0) (actual time=3.626..3.627 rows=1 loops=1)
 341     ->  Hash Join  (cost=4.17..16.55 rows=92 width=0) (actual time=3.349..3.594 rows=92 loops=1)
 342           Hash Cond: (pg_class.oid = pg_index.indrelid)
 343           ->  Seq Scan on pg_class  (cost=0.00..9.55 rows=255 width=4) (actual time=0.016..0.140 rows=255 loops=1)
 344           ->  Hash  (cost=3.02..3.02 rows=92 width=4) (actual time=3.238..3.238 rows=92 loops=1)
 345                 Buckets: 1024  Batches: 1  Memory Usage: 4kB
 346                 ->  Seq Scan on pg_index  (cost=0.00..3.02 rows=92 width=4) (actual time=0.008..3.187 rows=92 loops=1)
 347                       Filter: indisunique
 348 ]]></screen>
 349  </sect2>
 350
 351  <sect2 id="auto-explain-author">
 352   <title>Author</title>
 353
 354   <para>
 355    Takahiro Itagaki <email>itagaki.takahiro@oss.ntt.co.jp</email>
 356   </para>
 357  </sect2>
 358
 359 </sect1>