begriffs open source - ai-pg/blob - full-docs/txt/auto-explain.txt

   1
   2 F.3. auto_explain — log execution plans of slow queries #
   3
   4    F.3.1. Configuration Parameters
   5    F.3.2. Example
   6    F.3.3. Author
   7
   8    The auto_explain module provides a means for logging execution plans of
   9    slow statements automatically, without having to run EXPLAIN by hand.
  10    This is especially helpful for tracking down un-optimized queries in
  11    large applications.
  12
  13    The module provides no SQL-accessible functions. To use it, simply load
  14    it into the server. You can load it into an individual session:
  15 LOAD 'auto_explain';
  16
  17    (You must be superuser to do that.) More typical usage is to preload it
  18    into some or all sessions by including auto_explain in
  19    session_preload_libraries or shared_preload_libraries in
  20    postgresql.conf. Then you can track unexpectedly slow queries no matter
  21    when they happen. Of course there is a price in overhead for that.
  22
  23 F.3.1. Configuration Parameters #
  24
  25    There are several configuration parameters that control the behavior of
  26    auto_explain. Note that the default behavior is to do nothing, so you
  27    must set at least auto_explain.log_min_duration if you want any
  28    results.
  29
  30    auto_explain.log_min_duration (integer) #
  31           auto_explain.log_min_duration is the minimum statement execution
  32           time, in milliseconds, that will cause the statement's plan to
  33           be logged. Setting this to 0 logs all plans. -1 (the default)
  34           disables logging of plans. For example, if you set it to 250ms
  35           then all statements that run 250ms or longer will be logged.
  36           Only superusers can change this setting.
  37
  38    auto_explain.log_parameter_max_length (integer) #
  39           auto_explain.log_parameter_max_length controls the logging of
  40           query parameter values. A value of -1 (the default) logs the
  41           parameter values in full. 0 disables logging of parameter
  42           values. A value greater than zero truncates each parameter value
  43           to that many bytes. Only superusers can change this setting.
  44
  45    auto_explain.log_analyze (boolean) #
  46           auto_explain.log_analyze causes EXPLAIN ANALYZE output, rather
  47           than just EXPLAIN output, to be printed when an execution plan
  48           is logged. This parameter is off by default. Only superusers can
  49           change this setting.
  50
  51 Note
  52
  53           When this parameter is on, per-plan-node timing occurs for all
  54           statements executed, whether or not they run long enough to
  55           actually get logged. This can have an extremely negative impact
  56           on performance. Turning off auto_explain.log_timing ameliorates
  57           the performance cost, at the price of obtaining less
  58           information.
  59
  60    auto_explain.log_buffers (boolean) #
  61           auto_explain.log_buffers controls whether buffer usage
  62           statistics are printed when an execution plan is logged; it's
  63           equivalent to the BUFFERS option of EXPLAIN. This parameter has
  64           no effect unless auto_explain.log_analyze is enabled. This
  65           parameter is off by default. Only superusers can change this
  66           setting.
  67
  68    auto_explain.log_wal (boolean) #
  69           auto_explain.log_wal controls whether WAL usage statistics are
  70           printed when an execution plan is logged; it's equivalent to the
  71           WAL option of EXPLAIN. This parameter has no effect unless
  72           auto_explain.log_analyze is enabled. This parameter is off by
  73           default. Only superusers can change this setting.
  74
  75    auto_explain.log_timing (boolean) #
  76           auto_explain.log_timing controls whether per-node timing
  77           information is printed when an execution plan is logged; it's
  78           equivalent to the TIMING option of EXPLAIN. The overhead of
  79           repeatedly reading the system clock can slow down queries
  80           significantly on some systems, so it may be useful to set this
  81           parameter to off when only actual row counts, and not exact
  82           times, are needed. This parameter has no effect unless
  83           auto_explain.log_analyze is enabled. This parameter is on by
  84           default. Only superusers can change this setting.
  85
  86    auto_explain.log_triggers (boolean) #
  87           auto_explain.log_triggers causes trigger execution statistics to
  88           be included when an execution plan is logged. This parameter has
  89           no effect unless auto_explain.log_analyze is enabled. This
  90           parameter is off by default. Only superusers can change this
  91           setting.
  92
  93    auto_explain.log_verbose (boolean) #
  94           auto_explain.log_verbose controls whether verbose details are
  95           printed when an execution plan is logged; it's equivalent to the
  96           VERBOSE option of EXPLAIN. This parameter is off by default.
  97           Only superusers can change this setting.
  98
  99    auto_explain.log_settings (boolean) #
 100           auto_explain.log_settings controls whether information about
 101           modified configuration options is printed when an execution plan
 102           is logged. Only options affecting query planning with value
 103           different from the built-in default value are included in the
 104           output. This parameter is off by default. Only superusers can
 105           change this setting.
 106
 107    auto_explain.log_format (enum) #
 108           auto_explain.log_format selects the EXPLAIN output format to be
 109           used. The allowed values are text, xml, json, and yaml. The
 110           default is text. Only superusers can change this setting.
 111
 112    auto_explain.log_level (enum) #
 113           auto_explain.log_level selects the log level at which
 114           auto_explain will log the query plan. Valid values are DEBUG5,
 115           DEBUG4, DEBUG3, DEBUG2, DEBUG1, INFO, NOTICE, WARNING, and LOG.
 116           The default is LOG. Only superusers can change this setting.
 117
 118    auto_explain.log_nested_statements (boolean) #
 119           auto_explain.log_nested_statements causes nested statements
 120           (statements executed inside a function) to be considered for
 121           logging. When it is off, only top-level query plans are logged.
 122           This parameter is off by default. Only superusers can change
 123           this setting.
 124
 125    auto_explain.sample_rate (real) #
 126           auto_explain.sample_rate causes auto_explain to only explain a
 127           fraction of the statements in each session. The default is 1,
 128           meaning explain all the queries. In case of nested statements,
 129           either all will be explained or none. Only superusers can change
 130           this setting.
 131
 132    In ordinary usage, these parameters are set in postgresql.conf,
 133    although superusers can alter them on-the-fly within their own
 134    sessions. Typical usage might be:
 135 # postgresql.conf
 136 session_preload_libraries = 'auto_explain'
 137
 138 auto_explain.log_min_duration = '3s'
 139
 140 F.3.2. Example #
 141
 142 postgres=# LOAD 'auto_explain';
 143 postgres=# SET auto_explain.log_min_duration = 0;
 144 postgres=# SET auto_explain.log_analyze = true;
 145 postgres=# SELECT count(*)
 146            FROM pg_class, pg_index
 147            WHERE oid = indrelid AND indisunique;
 148
 149    This might produce log output such as:
 150 LOG:  duration: 3.651 ms  plan:
 151   Query Text: SELECT count(*)
 152               FROM pg_class, pg_index
 153               WHERE oid = indrelid AND indisunique;
 154   Aggregate  (cost=16.79..16.80 rows=1 width=0) (actual time=3.626..3.627 rows=1
 155 .00 loops=1)
 156     ->  Hash Join  (cost=4.17..16.55 rows=92 width=0) (actual time=3.349..3.594
 157 rows=92.00 loops=1)
 158           Hash Cond: (pg_class.oid = pg_index.indrelid)
 159           ->  Seq Scan on pg_class  (cost=0.00..9.55 rows=255 width=4) (actual t
 160 ime=0.016..0.140 rows=255.00 loops=1)
 161           ->  Hash  (cost=3.02..3.02 rows=92 width=4) (actual time=3.238..3.238
 162 rows=92.00 loops=1)
 163                 Buckets: 1024  Batches: 1  Memory Usage: 4kB
 164                 ->  Seq Scan on pg_index  (cost=0.00..3.02 rows=92 width=4) (act
 165 ual time=0.008..3.187 rows=92.00 loops=1)
 166                       Filter: indisunique
 167
 168 F.3.3. Author #
 169
 170    Takahiro Itagaki <itagaki.takahiro@oss.ntt.co.jp>