mirror of
https://github.com/postgres/postgres.git
synced 2025-11-19 13:42:17 +03:00
95dbd827f2
Commitddb17e387aattempted to avoid confusing users by displaying digits after the decimal point only when nloops > 1, since it's impossible to have a fraction row count after a single iteration. However, this made the regression tests unstable since parallal queries will have nloops>1 for all nodes below the Gather or Gather Merge in normal cases, but if the workers don't start in time and the leader finishes all the work, they will suddenly have nloops==1, making it unpredictable whether the digits after the decimal point would be displayed or not. Although44cbba9a7fseemed to fix the immediate failures, it may still be the case that there are lower-probability failures elsewhere in the regression tests. Various fixes are possible here. For example, it has previously been proposed that we should try to display the digits after the decimal point only if rows/nloops is an integer, but currently rows is storead as a float so it's not theoretically an exact quantity -- precision could be lost in extreme cases. It has also been proposed that we should try to display the digits after the decimal point only if we're under some sort of construct that could potentially cause looping regardless of whether it actually does. While such ideas are not without merit, this patch adopts the much simpler solution of always display two decimal digits. If that approach stands up to scrutiny from the buildfarm and human users, it spares us the trouble of doing anything more complex; if not, we can reassess. This commit incidentally reverts44cbba9a7f, which should no longer be needed. Author: Robert Haas <robertmhaas@gmail.com> Author: Ilia Evdokimov <ilya.evdokimov@tantorlabs.com> Discussion: http://postgr.es/m/CA+TgmoazzVHn8sFOMFAEwoqBTDxKT45D7mvkyeHgqtoD2cn58Q@mail.gmail.com
360 lines
14 KiB
Plaintext
360 lines
14 KiB
Plaintext
<!-- doc/src/sgml/auto-explain.sgml -->
|
|
|
|
<sect1 id="auto-explain" xreflabel="auto_explain">
|
|
<title>auto_explain — log execution plans of slow queries</title>
|
|
|
|
<indexterm zone="auto-explain">
|
|
<primary>auto_explain</primary>
|
|
</indexterm>
|
|
|
|
<para>
|
|
The <filename>auto_explain</filename> module provides a means for
|
|
logging execution plans of slow statements automatically, without
|
|
having to run <xref linkend="sql-explain"/>
|
|
by hand. This is especially helpful for tracking down un-optimized queries
|
|
in large applications.
|
|
</para>
|
|
|
|
<para>
|
|
The module provides no SQL-accessible functions. To use it, simply
|
|
load it into the server. You can load it into an individual session:
|
|
|
|
<programlisting>
|
|
LOAD 'auto_explain';
|
|
</programlisting>
|
|
|
|
(You must be superuser to do that.) More typical usage is to preload
|
|
it into some or all sessions by including <literal>auto_explain</literal> in
|
|
<xref linkend="guc-session-preload-libraries"/> or
|
|
<xref linkend="guc-shared-preload-libraries"/> in
|
|
<filename>postgresql.conf</filename>. Then you can track unexpectedly slow queries
|
|
no matter when they happen. Of course there is a price in overhead for
|
|
that.
|
|
</para>
|
|
|
|
<sect2 id="auto-explain-configuration-parameters">
|
|
<title>Configuration Parameters</title>
|
|
|
|
<para>
|
|
There are several configuration parameters that control the behavior of
|
|
<filename>auto_explain</filename>. Note that the default behavior is
|
|
to do nothing, so you must set at least
|
|
<varname>auto_explain.log_min_duration</varname> if you want any results.
|
|
</para>
|
|
|
|
<variablelist>
|
|
<varlistentry id="auto-explain-configuration-parameters-log-min-duration">
|
|
<term>
|
|
<varname>auto_explain.log_min_duration</varname> (<type>integer</type>)
|
|
<indexterm>
|
|
<primary><varname>auto_explain.log_min_duration</varname> configuration parameter</primary>
|
|
</indexterm>
|
|
</term>
|
|
<listitem>
|
|
<para>
|
|
<varname>auto_explain.log_min_duration</varname> is the minimum statement
|
|
execution time, in milliseconds, that will cause the statement's plan to
|
|
be logged. Setting this to <literal>0</literal> logs all plans.
|
|
<literal>-1</literal> (the default) disables logging of plans. For
|
|
example, if you set it to <literal>250ms</literal> then all statements
|
|
that run 250ms or longer will be logged. Only superusers can change this
|
|
setting.
|
|
</para>
|
|
</listitem>
|
|
</varlistentry>
|
|
|
|
<varlistentry id="auto-explain-configuration-parameters-log-parameter-max-length">
|
|
<term>
|
|
<varname>auto_explain.log_parameter_max_length</varname> (<type>integer</type>)
|
|
<indexterm>
|
|
<primary><varname>auto_explain.log_parameter_max_length</varname> configuration parameter</primary>
|
|
</indexterm>
|
|
</term>
|
|
<listitem>
|
|
<para>
|
|
<varname>auto_explain.log_parameter_max_length</varname> controls the
|
|
logging of query parameter values. A value of <literal>-1</literal> (the
|
|
default) logs the parameter values in full. <literal>0</literal> disables
|
|
logging of parameter values. A value greater than zero truncates each
|
|
parameter value to that many bytes. Only superusers can change this
|
|
setting.
|
|
</para>
|
|
</listitem>
|
|
</varlistentry>
|
|
|
|
<varlistentry id="auto-explain-configuration-parameters-log-analyze">
|
|
<term>
|
|
<varname>auto_explain.log_analyze</varname> (<type>boolean</type>)
|
|
<indexterm>
|
|
<primary><varname>auto_explain.log_analyze</varname> configuration parameter</primary>
|
|
</indexterm>
|
|
</term>
|
|
<listitem>
|
|
<para>
|
|
<varname>auto_explain.log_analyze</varname> causes <command>EXPLAIN ANALYZE</command>
|
|
output, rather than just <command>EXPLAIN</command> output, to be printed
|
|
when an execution plan is logged. This parameter is off by default.
|
|
Only superusers can change this setting.
|
|
</para>
|
|
<note>
|
|
<para>
|
|
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 <varname>auto_explain.log_timing</varname> ameliorates the
|
|
performance cost, at the price of obtaining less information.
|
|
</para>
|
|
</note>
|
|
</listitem>
|
|
</varlistentry>
|
|
|
|
<varlistentry id="auto-explain-configuration-parameters-log-buffers">
|
|
<term>
|
|
<varname>auto_explain.log_buffers</varname> (<type>boolean</type>)
|
|
<indexterm>
|
|
<primary><varname>auto_explain.log_buffers</varname> configuration parameter</primary>
|
|
</indexterm>
|
|
</term>
|
|
<listitem>
|
|
<para>
|
|
<varname>auto_explain.log_buffers</varname> controls whether buffer
|
|
usage statistics are printed when an execution plan is logged; it's
|
|
equivalent to the <literal>BUFFERS</literal> option of <command>EXPLAIN</command>.
|
|
This parameter has no effect
|
|
unless <varname>auto_explain.log_analyze</varname> is enabled.
|
|
This parameter is off by default.
|
|
Only superusers can change this setting.
|
|
</para>
|
|
</listitem>
|
|
</varlistentry>
|
|
|
|
<varlistentry id="auto-explain-configuration-parameters-log-wal">
|
|
<term>
|
|
<varname>auto_explain.log_wal</varname> (<type>boolean</type>)
|
|
<indexterm>
|
|
<primary><varname>auto_explain.log_wal</varname> configuration parameter</primary>
|
|
</indexterm>
|
|
</term>
|
|
<listitem>
|
|
<para>
|
|
<varname>auto_explain.log_wal</varname> controls whether WAL
|
|
usage statistics are printed when an execution plan is logged; it's
|
|
equivalent to the <literal>WAL</literal> option of <command>EXPLAIN</command>.
|
|
This parameter has no effect
|
|
unless <varname>auto_explain.log_analyze</varname> is enabled.
|
|
This parameter is off by default.
|
|
Only superusers can change this setting.
|
|
</para>
|
|
</listitem>
|
|
</varlistentry>
|
|
|
|
<varlistentry id="auto-explain-configuration-parameters-log-timing">
|
|
<term>
|
|
<varname>auto_explain.log_timing</varname> (<type>boolean</type>)
|
|
<indexterm>
|
|
<primary><varname>auto_explain.log_timing</varname> configuration parameter</primary>
|
|
</indexterm>
|
|
</term>
|
|
<listitem>
|
|
<para>
|
|
<varname>auto_explain.log_timing</varname> controls whether per-node
|
|
timing information is printed when an execution plan is logged; it's
|
|
equivalent to the <literal>TIMING</literal> option of <command>EXPLAIN</command>.
|
|
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
|
|
unless <varname>auto_explain.log_analyze</varname> is enabled.
|
|
This parameter is on by default.
|
|
Only superusers can change this setting.
|
|
</para>
|
|
</listitem>
|
|
</varlistentry>
|
|
|
|
<varlistentry id="auto-explain-configuration-parameters-log-triggers">
|
|
<term>
|
|
<varname>auto_explain.log_triggers</varname> (<type>boolean</type>)
|
|
<indexterm>
|
|
<primary><varname>auto_explain.log_triggers</varname> configuration parameter</primary>
|
|
</indexterm>
|
|
</term>
|
|
<listitem>
|
|
<para>
|
|
<varname>auto_explain.log_triggers</varname> causes trigger
|
|
execution statistics to be included when an execution plan is logged.
|
|
This parameter has no effect
|
|
unless <varname>auto_explain.log_analyze</varname> is enabled.
|
|
This parameter is off by default.
|
|
Only superusers can change this setting.
|
|
</para>
|
|
</listitem>
|
|
</varlistentry>
|
|
|
|
<varlistentry id="auto-explain-configuration-parameters-log-verbose">
|
|
<term>
|
|
<varname>auto_explain.log_verbose</varname> (<type>boolean</type>)
|
|
<indexterm>
|
|
<primary><varname>auto_explain.log_verbose</varname> configuration parameter</primary>
|
|
</indexterm>
|
|
</term>
|
|
<listitem>
|
|
<para>
|
|
<varname>auto_explain.log_verbose</varname> controls whether verbose
|
|
details are printed when an execution plan is logged; it's
|
|
equivalent to the <literal>VERBOSE</literal> option of <command>EXPLAIN</command>.
|
|
This parameter is off by default.
|
|
Only superusers can change this setting.
|
|
</para>
|
|
</listitem>
|
|
</varlistentry>
|
|
|
|
<varlistentry id="auto-explain-configuration-parameters-log-settings">
|
|
<term>
|
|
<varname>auto_explain.log_settings</varname> (<type>boolean</type>)
|
|
<indexterm>
|
|
<primary><varname>auto_explain.log_settings</varname> configuration parameter</primary>
|
|
</indexterm>
|
|
</term>
|
|
<listitem>
|
|
<para>
|
|
<varname>auto_explain.log_settings</varname> controls 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.
|
|
</para>
|
|
</listitem>
|
|
</varlistentry>
|
|
|
|
<varlistentry id="auto-explain-configuration-parameters-log-format">
|
|
<term>
|
|
<varname>auto_explain.log_format</varname> (<type>enum</type>)
|
|
<indexterm>
|
|
<primary><varname>auto_explain.log_format</varname> configuration parameter</primary>
|
|
</indexterm>
|
|
</term>
|
|
<listitem>
|
|
<para>
|
|
<varname>auto_explain.log_format</varname> selects the
|
|
<command>EXPLAIN</command> output format to be used.
|
|
The allowed values are <literal>text</literal>, <literal>xml</literal>,
|
|
<literal>json</literal>, and <literal>yaml</literal>. The default is text.
|
|
Only superusers can change this setting.
|
|
</para>
|
|
</listitem>
|
|
</varlistentry>
|
|
|
|
<varlistentry id="auto-explain-configuration-parameters-log-level">
|
|
<term>
|
|
<varname>auto_explain.log_level</varname> (<type>enum</type>)
|
|
<indexterm>
|
|
<primary><varname>auto_explain.log_level</varname> configuration parameter</primary>
|
|
</indexterm>
|
|
</term>
|
|
<listitem>
|
|
<para>
|
|
<varname>auto_explain.log_level</varname> selects the log level at which
|
|
auto_explain will log the query plan.
|
|
Valid values are <literal>DEBUG5</literal>, <literal>DEBUG4</literal>,
|
|
<literal>DEBUG3</literal>, <literal>DEBUG2</literal>,
|
|
<literal>DEBUG1</literal>, <literal>INFO</literal>,
|
|
<literal>NOTICE</literal>, <literal>WARNING</literal>,
|
|
and <literal>LOG</literal>. The default is <literal>LOG</literal>.
|
|
Only superusers can change this setting.
|
|
</para>
|
|
</listitem>
|
|
</varlistentry>
|
|
|
|
<varlistentry id="auto-explain-configuration-parameters-log-nested-statements">
|
|
<term>
|
|
<varname>auto_explain.log_nested_statements</varname> (<type>boolean</type>)
|
|
<indexterm>
|
|
<primary><varname>auto_explain.log_nested_statements</varname> configuration parameter</primary>
|
|
</indexterm>
|
|
</term>
|
|
<listitem>
|
|
<para>
|
|
<varname>auto_explain.log_nested_statements</varname> causes 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.
|
|
</para>
|
|
</listitem>
|
|
</varlistentry>
|
|
|
|
<varlistentry id="auto-explain-configuration-parameters-sample-rate">
|
|
<term>
|
|
<varname>auto_explain.sample_rate</varname> (<type>real</type>)
|
|
<indexterm>
|
|
<primary><varname>auto_explain.sample_rate</varname> configuration parameter</primary>
|
|
</indexterm>
|
|
</term>
|
|
<listitem>
|
|
<para>
|
|
<varname>auto_explain.sample_rate</varname> causes 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.
|
|
</para>
|
|
</listitem>
|
|
</varlistentry>
|
|
</variablelist>
|
|
|
|
<para>
|
|
In ordinary usage, these parameters are set
|
|
in <filename>postgresql.conf</filename>, although superusers can alter them
|
|
on-the-fly within their own sessions.
|
|
Typical usage might be:
|
|
</para>
|
|
|
|
<programlisting>
|
|
# postgresql.conf
|
|
session_preload_libraries = 'auto_explain'
|
|
|
|
auto_explain.log_min_duration = '3s'
|
|
</programlisting>
|
|
</sect2>
|
|
|
|
<sect2 id="auto-explain-example">
|
|
<title>Example</title>
|
|
|
|
<programlisting>
|
|
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;
|
|
</programlisting>
|
|
|
|
<para>
|
|
This might produce log output such as:
|
|
</para>
|
|
|
|
<screen><![CDATA[
|
|
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.00 loops=1)
|
|
-> Hash Join (cost=4.17..16.55 rows=92 width=0) (actual time=3.349..3.594 rows=92.00 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.00 loops=1)
|
|
-> Hash (cost=3.02..3.02 rows=92 width=4) (actual time=3.238..3.238 rows=92.00 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.00 loops=1)
|
|
Filter: indisunique
|
|
]]></screen>
|
|
</sect2>
|
|
|
|
<sect2 id="auto-explain-author">
|
|
<title>Author</title>
|
|
|
|
<para>
|
|
Takahiro Itagaki <email>itagaki.takahiro@oss.ntt.co.jp</email>
|
|
</para>
|
|
</sect2>
|
|
|
|
</sect1>
|