mirror of https://github.com/postgres/postgres
slow-running queries. Takahiro ItagakiREL8_5_ALPHA1_BRANCH
Tom Lane
17 years ago
parent
31ec957a15
commit
e125e28e78
@ -0,0 +1,15 @@ |
|||||||
|
# $PostgreSQL: pgsql/contrib/auto_explain/Makefile,v 1.1 2008/11/19 02:59:28 tgl Exp $
|
||||||
|
|
||||||
|
MODULE_big = auto_explain
|
||||||
|
OBJS = auto_explain.o
|
||||||
|
|
||||||
|
ifdef USE_PGXS |
||||||
|
PG_CONFIG = pg_config
|
||||||
|
PGXS := $(shell $(PG_CONFIG) --pgxs)
|
||||||
|
include $(PGXS) |
||||||
|
else |
||||||
|
subdir = contrib/auto_explain
|
||||||
|
top_builddir = ../..
|
||||||
|
include $(top_builddir)/src/Makefile.global |
||||||
|
include $(top_srcdir)/contrib/contrib-global.mk |
||||||
|
endif |
||||||
@ -0,0 +1,228 @@ |
|||||||
|
/*-------------------------------------------------------------------------
|
||||||
|
* |
||||||
|
* auto_explain.c |
||||||
|
* |
||||||
|
* |
||||||
|
* Copyright (c) 2008, PostgreSQL Global Development Group |
||||||
|
* |
||||||
|
* IDENTIFICATION |
||||||
|
* $PostgreSQL: pgsql/contrib/auto_explain/auto_explain.c,v 1.1 2008/11/19 02:59:28 tgl Exp $ |
||||||
|
* |
||||||
|
*------------------------------------------------------------------------- |
||||||
|
*/ |
||||||
|
#include "postgres.h" |
||||||
|
|
||||||
|
#include "commands/explain.h" |
||||||
|
#include "executor/instrument.h" |
||||||
|
#include "utils/guc.h" |
||||||
|
|
||||||
|
PG_MODULE_MAGIC; |
||||||
|
|
||||||
|
#define GUCNAME(name) ("explain." name) |
||||||
|
|
||||||
|
/* GUC variables */ |
||||||
|
static int explain_log_min_duration = -1; /* msec or -1 */ |
||||||
|
static bool explain_log_analyze = false; |
||||||
|
static bool explain_log_verbose = false; |
||||||
|
static bool explain_log_nested = false; |
||||||
|
|
||||||
|
/* Current nesting depth of ExecutorRun calls */ |
||||||
|
static int nesting_level = 0; |
||||||
|
|
||||||
|
/* Saved hook values in case of unload */ |
||||||
|
static ExecutorStart_hook_type prev_ExecutorStart = NULL; |
||||||
|
static ExecutorRun_hook_type prev_ExecutorRun = NULL; |
||||||
|
static ExecutorEnd_hook_type prev_ExecutorEnd = NULL; |
||||||
|
|
||||||
|
#define auto_explain_enabled() \ |
||||||
|
(explain_log_min_duration >= 0 && \
|
||||||
|
(nesting_level == 0 || explain_log_nested)) |
||||||
|
|
||||||
|
void _PG_init(void); |
||||||
|
void _PG_fini(void); |
||||||
|
|
||||||
|
static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags); |
||||||
|
static void explain_ExecutorRun(QueryDesc *queryDesc, |
||||||
|
ScanDirection direction, |
||||||
|
long count); |
||||||
|
static void explain_ExecutorEnd(QueryDesc *queryDesc); |
||||||
|
|
||||||
|
|
||||||
|
/*
|
||||||
|
* Module load callback |
||||||
|
*/ |
||||||
|
void |
||||||
|
_PG_init(void) |
||||||
|
{ |
||||||
|
/* Define custom GUC variables. */ |
||||||
|
DefineCustomIntVariable(GUCNAME("log_min_duration"), |
||||||
|
"Sets the minimum execution time above which plans will be logged.", |
||||||
|
"Zero prints all plans. -1 turns this feature off.", |
||||||
|
&explain_log_min_duration, |
||||||
|
-1, |
||||||
|
-1, INT_MAX / 1000, |
||||||
|
PGC_SUSET, |
||||||
|
GUC_UNIT_MS, |
||||||
|
NULL, |
||||||
|
NULL); |
||||||
|
|
||||||
|
DefineCustomBoolVariable(GUCNAME("log_analyze"), |
||||||
|
"Use EXPLAIN ANALYZE for plan logging.", |
||||||
|
NULL, |
||||||
|
&explain_log_analyze, |
||||||
|
false, |
||||||
|
PGC_SUSET, |
||||||
|
0, |
||||||
|
NULL, |
||||||
|
NULL); |
||||||
|
|
||||||
|
DefineCustomBoolVariable(GUCNAME("log_verbose"), |
||||||
|
"Use EXPLAIN VERBOSE for plan logging.", |
||||||
|
NULL, |
||||||
|
&explain_log_verbose, |
||||||
|
false, |
||||||
|
PGC_SUSET, |
||||||
|
0, |
||||||
|
NULL, |
||||||
|
NULL); |
||||||
|
|
||||||
|
DefineCustomBoolVariable(GUCNAME("log_nested_statements"), |
||||||
|
"Log nested statements.", |
||||||
|
NULL, |
||||||
|
&explain_log_nested, |
||||||
|
false, |
||||||
|
PGC_SUSET, |
||||||
|
0, |
||||||
|
NULL, |
||||||
|
NULL); |
||||||
|
|
||||||
|
/* Install hooks. */ |
||||||
|
prev_ExecutorStart = ExecutorStart_hook; |
||||||
|
ExecutorStart_hook = explain_ExecutorStart; |
||||||
|
prev_ExecutorRun = ExecutorRun_hook; |
||||||
|
ExecutorRun_hook = explain_ExecutorRun; |
||||||
|
prev_ExecutorEnd = ExecutorEnd_hook; |
||||||
|
ExecutorEnd_hook = explain_ExecutorEnd; |
||||||
|
} |
||||||
|
|
||||||
|
/*
|
||||||
|
* Module unload callback |
||||||
|
*/ |
||||||
|
void |
||||||
|
_PG_fini(void) |
||||||
|
{ |
||||||
|
/* Uninstall hooks. */ |
||||||
|
ExecutorStart_hook = prev_ExecutorStart; |
||||||
|
ExecutorRun_hook = prev_ExecutorRun; |
||||||
|
ExecutorEnd_hook = prev_ExecutorEnd; |
||||||
|
} |
||||||
|
|
||||||
|
/*
|
||||||
|
* ExecutorStart hook: start up logging if needed |
||||||
|
*/ |
||||||
|
void |
||||||
|
explain_ExecutorStart(QueryDesc *queryDesc, int eflags) |
||||||
|
{ |
||||||
|
if (auto_explain_enabled()) |
||||||
|
{ |
||||||
|
/* Enable per-node instrumentation iff log_analyze is required. */ |
||||||
|
if (explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0) |
||||||
|
queryDesc->doInstrument = true; |
||||||
|
} |
||||||
|
|
||||||
|
if (prev_ExecutorStart) |
||||||
|
prev_ExecutorStart(queryDesc, eflags); |
||||||
|
else |
||||||
|
standard_ExecutorStart(queryDesc, eflags); |
||||||
|
|
||||||
|
if (auto_explain_enabled()) |
||||||
|
{ |
||||||
|
/*
|
||||||
|
* Set up to track total elapsed time in ExecutorRun. Make sure |
||||||
|
* the space is allocated in the per-query context so it will go |
||||||
|
* away at ExecutorEnd. |
||||||
|
*/ |
||||||
|
if (queryDesc->totaltime == NULL) |
||||||
|
{ |
||||||
|
MemoryContext oldcxt; |
||||||
|
|
||||||
|
oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt); |
||||||
|
queryDesc->totaltime = InstrAlloc(1); |
||||||
|
MemoryContextSwitchTo(oldcxt); |
||||||
|
} |
||||||
|
} |
||||||
|
} |
||||||
|
|
||||||
|
/*
|
||||||
|
* ExecutorRun hook: all we need do is track nesting depth |
||||||
|
*/ |
||||||
|
void |
||||||
|
explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, long count) |
||||||
|
{ |
||||||
|
nesting_level++; |
||||||
|
PG_TRY(); |
||||||
|
{ |
||||||
|
if (prev_ExecutorRun) |
||||||
|
prev_ExecutorRun(queryDesc, direction, count); |
||||||
|
else |
||||||
|
standard_ExecutorRun(queryDesc, direction, count); |
||||||
|
nesting_level--; |
||||||
|
} |
||||||
|
PG_CATCH(); |
||||||
|
{ |
||||||
|
nesting_level--; |
||||||
|
PG_RE_THROW(); |
||||||
|
} |
||||||
|
PG_END_TRY(); |
||||||
|
} |
||||||
|
|
||||||
|
/*
|
||||||
|
* ExecutorEnd hook: log results if needed |
||||||
|
*/ |
||||||
|
void |
||||||
|
explain_ExecutorEnd(QueryDesc *queryDesc) |
||||||
|
{ |
||||||
|
if (queryDesc->totaltime && auto_explain_enabled()) |
||||||
|
{ |
||||||
|
double msec; |
||||||
|
|
||||||
|
/*
|
||||||
|
* Make sure stats accumulation is done. (Note: it's okay if |
||||||
|
* several levels of hook all do this.) |
||||||
|
*/ |
||||||
|
InstrEndLoop(queryDesc->totaltime); |
||||||
|
|
||||||
|
/* Log plan if duration is exceeded. */ |
||||||
|
msec = queryDesc->totaltime->total * 1000.0; |
||||||
|
if (msec >= explain_log_min_duration) |
||||||
|
{ |
||||||
|
StringInfoData buf; |
||||||
|
|
||||||
|
initStringInfo(&buf); |
||||||
|
ExplainPrintPlan(&buf, queryDesc, |
||||||
|
queryDesc->doInstrument && explain_log_analyze, |
||||||
|
explain_log_verbose); |
||||||
|
|
||||||
|
/* Remove last line break */ |
||||||
|
if (buf.len > 0 && buf.data[buf.len - 1] == '\n') |
||||||
|
buf.data[--buf.len] = '\0'; |
||||||
|
|
||||||
|
/*
|
||||||
|
* Note: we rely on the existing logging of context or |
||||||
|
* debug_query_string to identify just which statement is being |
||||||
|
* reported. This isn't ideal but trying to do it here would |
||||||
|
* often result in duplication. |
||||||
|
*/ |
||||||
|
ereport(LOG, |
||||||
|
(errmsg("duration: %.3f ms plan:\n%s", |
||||||
|
msec, buf.data))); |
||||||
|
|
||||||
|
pfree(buf.data); |
||||||
|
} |
||||||
|
} |
||||||
|
|
||||||
|
if (prev_ExecutorEnd) |
||||||
|
prev_ExecutorEnd(queryDesc); |
||||||
|
else |
||||||
|
standard_ExecutorEnd(queryDesc); |
||||||
|
} |
||||||
@ -0,0 +1,176 @@ |
|||||||
|
<!-- $PostgreSQL: pgsql/doc/src/sgml/auto-explain.sgml,v 1.1 2008/11/19 02:59:28 tgl Exp $ --> |
||||||
|
|
||||||
|
<sect1 id="auto-explain"> |
||||||
|
<title>auto_explain</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" endterm="sql-explain-title"> |
||||||
|
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 all sessions by including <literal>auto_explain</> in |
||||||
|
<xref linkend="guc-shared-preload-libraries"> in |
||||||
|
<filename>postgresql.conf</>. Then you can track unexpectedly slow queries |
||||||
|
no matter when they happen. Of course there is a price in overhead for |
||||||
|
that. |
||||||
|
</para> |
||||||
|
|
||||||
|
<sect2> |
||||||
|
<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>explain.log_min_duration</varname> if you want any results. |
||||||
|
</para> |
||||||
|
|
||||||
|
<variablelist> |
||||||
|
<varlistentry> |
||||||
|
<term> |
||||||
|
<varname>explain.log_min_duration</varname> (<type>integer</type>) |
||||||
|
</term> |
||||||
|
<indexterm> |
||||||
|
<primary><varname>explain.log_min_duration</> configuration parameter</primary> |
||||||
|
</indexterm> |
||||||
|
<listitem> |
||||||
|
<para> |
||||||
|
<varname>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 zero logs all plans. Minus-one (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> |
||||||
|
<term> |
||||||
|
<varname>explain.log_analyze</varname> (<type>boolean</type>) |
||||||
|
</term> |
||||||
|
<indexterm> |
||||||
|
<primary><varname>explain.log_analyze</> configuration parameter</primary> |
||||||
|
</indexterm> |
||||||
|
<listitem> |
||||||
|
<para> |
||||||
|
<varname>explain.log_analyze</varname> causes <command>EXPLAIN ANALYZE</> |
||||||
|
output, rather than just <command>EXPLAIN</> 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 extremely negative impact on performance. |
||||||
|
</para> |
||||||
|
</note> |
||||||
|
</listitem> |
||||||
|
</varlistentry> |
||||||
|
|
||||||
|
<varlistentry> |
||||||
|
<term> |
||||||
|
<varname>explain.log_verbose</varname> (<type>boolean</type>) |
||||||
|
</term> |
||||||
|
<indexterm> |
||||||
|
<primary><varname>explain.log_verbose</> configuration parameter</primary> |
||||||
|
</indexterm> |
||||||
|
<listitem> |
||||||
|
<para> |
||||||
|
<varname>explain.log_verbose</varname> causes <command>EXPLAIN VERBOSE</> |
||||||
|
output, rather than just <command>EXPLAIN</> output, to be printed |
||||||
|
when an execution plan is logged. This parameter is off by default. |
||||||
|
Only superusers can change this setting. |
||||||
|
</para> |
||||||
|
</listitem> |
||||||
|
</varlistentry> |
||||||
|
|
||||||
|
<varlistentry> |
||||||
|
<term> |
||||||
|
<varname>explain.log_nested_statements</varname> (<type>boolean</type>) |
||||||
|
</term> |
||||||
|
<indexterm> |
||||||
|
<primary><varname>explain.log_nested_statements</> configuration parameter</primary> |
||||||
|
</indexterm> |
||||||
|
<listitem> |
||||||
|
<para> |
||||||
|
<varname>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> |
||||||
|
</variablelist> |
||||||
|
|
||||||
|
<para> |
||||||
|
In order to set these parameters in your <filename>postgresql.conf</> file, |
||||||
|
you will need to add <literal>explain</> in |
||||||
|
<varname>custom_variable_classes</>. Typical usage might be: |
||||||
|
</para> |
||||||
|
|
||||||
|
<programlisting> |
||||||
|
# postgresql.conf |
||||||
|
shared_preload_libraries = 'auto_explain' |
||||||
|
|
||||||
|
custom_variable_classes = 'explain' |
||||||
|
explain.log_min_duration = '3s' |
||||||
|
</programlisting> |
||||||
|
</sect2> |
||||||
|
|
||||||
|
<sect2> |
||||||
|
<title>Example</title> |
||||||
|
|
||||||
|
<programlisting> |
||||||
|
postgres=# LOAD 'auto_explain'; |
||||||
|
postgres=# SET explain.log_min_duration = 0; |
||||||
|
postgres=# SELECT count(*) |
||||||
|
FROM pg_class, pg_index |
||||||
|
WHERE oid = indrelid AND indisunique; |
||||||
|
</programlisting> |
||||||
|
|
||||||
|
<para> |
||||||
|
This might produce log output such as: |
||||||
|
</para> |
||||||
|
|
||||||
|
<programlisting> |
||||||
|
LOG: duration: 0.986 ms plan: |
||||||
|
Aggregate (cost=14.90..14.91 rows=1 width=0) |
||||||
|
-> Hash Join (cost=3.91..14.70 rows=81 width=0) |
||||||
|
Hash Cond: (pg_class.oid = pg_index.indrelid) |
||||||
|
-> Seq Scan on pg_class (cost=0.00..8.27 rows=227 width=4) |
||||||
|
-> Hash (cost=2.90..2.90 rows=81 width=4) |
||||||
|
-> Seq Scan on pg_index (cost=0.00..2.90 rows=81 width=4) |
||||||
|
Filter: indisunique |
||||||
|
STATEMENT: SELECT count(*) |
||||||
|
FROM pg_class, pg_index |
||||||
|
WHERE oid = indrelid AND indisunique; |
||||||
|
</programlisting> |
||||||
|
</sect2> |
||||||
|
|
||||||
|
<sect2> |
||||||
|
<title>Author</title> |
||||||
|
|
||||||
|
<para> |
||||||
|
Takahiro Itagaki <email>itagaki.takahiro@oss.ntt.co.jp</email> |
||||||
|
</para> |
||||||
|
</sect2> |
||||||
|
|
||||||
|
</sect1> |
||||||
Loading…
Reference in new issue