doc/src/sgml/auto-explain.sgml

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