| F.3. auto_explain — log execution plans of slow queries | ||||
|---|---|---|---|---|
| Prev | Up | Appendix F. Additional Supplied Modules and Extensions | Home | Next |
F.3. auto_explain — log execution plans of slow queries#
Theauto_explain module provides a means for logging execution plans of slow statements automatically, without having to runEXPLAIN by hand. This is especially helpful for tracking down un-optimized queries in large applications.
The module provides no SQL-accessible functions. To use it, simply load it into the server. You can load it into an individual session:
LOAD 'auto_explain';
(You must be superuser to do that.) More typical usage is to preload it into some or all sessions by includingauto_explain insession_preload_libraries orshared_preload_libraries inpostgresql.conf. Then you can track unexpectedly slow queries no matter when they happen. Of course there is a price in overhead for that.
F.3.1. Configuration Parameters#
There are several configuration parameters that control the behavior ofauto_explain. Note that the default behavior is to do nothing, so you must set at leastauto_explain.log_min_duration if you want any results.
auto_explain.log_min_duration(integer)#auto_explain.log_min_durationis the minimum statement execution time, in milliseconds, that will cause the statement's plan to be logged. Setting this to0logs all plans.-1(the default) disables logging of plans. For example, if you set it to250msthen all statements that run 250ms or longer will be logged. Only superusers can change this setting.auto_explain.log_parameter_max_length(integer)#auto_explain.log_parameter_max_lengthcontrols the logging of query parameter values. A value of-1(the default) logs the parameter values in full.0disables logging of parameter values. A value greater than zero truncates each parameter value to that many bytes. Only superusers can change this setting.auto_explain.log_analyze(boolean)#auto_explain.log_analyzecausesEXPLAIN ANALYZEoutput, rather than justEXPLAINoutput, to be printed when an execution plan is logged. This parameter is off by default. Only superusers can change this setting.Note
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
auto_explain.log_timingameliorates the performance cost, at the price of obtaining less information.auto_explain.log_buffers(boolean)#auto_explain.log_bufferscontrols whether buffer usage statistics are printed when an execution plan is logged; it's equivalent to theBUFFERSoption ofEXPLAIN. This parameter has no effect unlessauto_explain.log_analyzeis enabled. This parameter is off by default. Only superusers can change this setting.auto_explain.log_wal(boolean)#auto_explain.log_walcontrols whether WAL usage statistics are printed when an execution plan is logged; it's equivalent to theWALoption ofEXPLAIN. This parameter has no effect unlessauto_explain.log_analyzeis enabled. This parameter is off by default. Only superusers can change this setting.auto_explain.log_timing(boolean)#auto_explain.log_timingcontrols whether per-node timing information is printed when an execution plan is logged; it's equivalent to theTIMINGoption ofEXPLAIN. 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 unlessauto_explain.log_analyzeis enabled. This parameter is on by default. Only superusers can change this setting.auto_explain.log_triggers(boolean)#auto_explain.log_triggerscauses trigger execution statistics to be included when an execution plan is logged. This parameter has no effect unlessauto_explain.log_analyzeis enabled. This parameter is off by default. Only superusers can change this setting.auto_explain.log_verbose(boolean)#auto_explain.log_verbosecontrols whether verbose details are printed when an execution plan is logged; it's equivalent to theVERBOSEoption ofEXPLAIN. This parameter is off by default. Only superusers can change this setting.auto_explain.log_settings(boolean)#auto_explain.log_settingscontrols 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.auto_explain.log_format(enum)#auto_explain.log_formatselects theEXPLAINoutput format to be used. The allowed values aretext,xml,json, andyaml. The default is text. Only superusers can change this setting.auto_explain.log_level(enum)#auto_explain.log_levelselects the log level at which auto_explain will log the query plan. Valid values areDEBUG5,DEBUG4,DEBUG3,DEBUG2,DEBUG1,INFO,NOTICE,WARNING, andLOG. The default isLOG. Only superusers can change this setting.auto_explain.log_nested_statements(boolean)#auto_explain.log_nested_statementscauses 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.auto_explain.sample_rate(real)#auto_explain.sample_ratecauses 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.
In ordinary usage, these parameters are set inpostgresql.conf, although superusers can alter them on-the-fly within their own sessions. Typical usage might be:
# postgresql.confsession_preload_libraries = 'auto_explain'auto_explain.log_min_duration = '3s'
F.3.2. Example#
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;
This might produce log output such as:
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
F.3.3. Author#
Takahiro Itagaki<itagaki.takahiro@oss.ntt.co.jp>