Content-Length: 808880 | pFad | http://github.com/tonybelloni/postgres/commit/e125e28e781116ceb2860be29e6508906c81d2da

85 Add auto-explain contrib module for automatic logging of the plans of · tonybelloni/postgres@e125e28 · GitHub
Skip to content

Commit e125e28

Browse files
tglsfdctglsfdc
committed
Add auto-explain contrib module for automatic logging of the plans of
slow-running queries. Takahiro Itagaki
1 parent 31ec957 commit e125e28

File tree

7 files changed

+429
-3
lines changed

7 files changed

+429
-3
lines changed

‎contrib/Makefile

+2-1
Original file line numberDiff line numberDiff line change
@@ -1,11 +1,12 @@
1-
# $PostgreSQL: pgsql/contrib/Makefile,v 1.84 2008/07/29 18:31:20 tgl Exp $
1+
# $PostgreSQL: pgsql/contrib/Makefile,v 1.85 2008/11/19 02:59:28 tgl Exp $
22

33
subdir = contrib
44
top_builddir = ..
55
include $(top_builddir)/src/Makefile.global
66

77
WANTED_DIRS = \
88
adminpack \
9+
auto_explain \
910
btree_gist \
1011
chkpass \
1112
citext \

‎contrib/README

+4
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,10 @@ adminpack -
2828
File and log manipulation routines, used by pgAdmin
2929
by Dave Page <dpage@vale-housing.co.uk>
3030

31+
auto_explain -
32+
Log EXPLAIN output for long-running queries
33+
by Takahiro Itagaki <itagaki.takahiro@oss.ntt.co.jp>
34+
3135
btree_gist -
3236
Support for emulating BTREE indexing in GiST
3337
by Oleg Bartunov <oleg@sai.msu.su> and Teodor Sigaev <teodor@sigaev.ru>

‎contrib/auto_explain/Makefile

+15
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,15 @@
1+
# $PostgreSQL: pgsql/contrib/auto_explain/Makefile,v 1.1 2008/11/19 02:59:28 tgl Exp $
2+
3+
MODULE_big = auto_explain
4+
OBJS = auto_explain.o
5+
6+
ifdef USE_PGXS
7+
PG_CONFIG = pg_config
8+
PGXS := $(shell $(PG_CONFIG) --pgxs)
9+
include $(PGXS)
10+
else
11+
subdir = contrib/auto_explain
12+
top_builddir = ../..
13+
include $(top_builddir)/src/Makefile.global
14+
include $(top_srcdir)/contrib/contrib-global.mk
15+
endif

‎contrib/auto_explain/auto_explain.c

+228
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,228 @@
1+
/*-------------------------------------------------------------------------
2+
*
3+
* auto_explain.c
4+
*
5+
*
6+
* Copyright (c) 2008, PostgreSQL Global Development Group
7+
*
8+
* IDENTIFICATION
9+
* $PostgreSQL: pgsql/contrib/auto_explain/auto_explain.c,v 1.1 2008/11/19 02:59:28 tgl Exp $
10+
*
11+
*-------------------------------------------------------------------------
12+
*/
13+
#include "postgres.h"
14+
15+
#include "commands/explain.h"
16+
#include "executor/instrument.h"
17+
#include "utils/guc.h"
18+
19+
PG_MODULE_MAGIC;
20+
21+
#define GUCNAME(name) ("explain." name)
22+
23+
/* GUC variables */
24+
static int explain_log_min_duration = -1; /* msec or -1 */
25+
static bool explain_log_analyze = false;
26+
static bool explain_log_verbose = false;
27+
static bool explain_log_nested = false;
28+
29+
/* Current nesting depth of ExecutorRun calls */
30+
static int nesting_level = 0;
31+
32+
/* Saved hook values in case of unload */
33+
static ExecutorStart_hook_type prev_ExecutorStart = NULL;
34+
static ExecutorRun_hook_type prev_ExecutorRun = NULL;
35+
static ExecutorEnd_hook_type prev_ExecutorEnd = NULL;
36+
37+
#define auto_explain_enabled() \
38+
(explain_log_min_duration >= 0 && \
39+
(nesting_level == 0 || explain_log_nested))
40+
41+
void _PG_init(void);
42+
void _PG_fini(void);
43+
44+
static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags);
45+
static void explain_ExecutorRun(QueryDesc *queryDesc,
46+
ScanDirection direction,
47+
long count);
48+
static void explain_ExecutorEnd(QueryDesc *queryDesc);
49+
50+
51+
/*
52+
* Module load callback
53+
*/
54+
void
55+
_PG_init(void)
56+
{
57+
/* Define custom GUC variables. */
58+
DefineCustomIntVariable(GUCNAME("log_min_duration"),
59+
"Sets the minimum execution time above which plans will be logged.",
60+
"Zero prints all plans. -1 turns this feature off.",
61+
&explain_log_min_duration,
62+
-1,
63+
-1, INT_MAX / 1000,
64+
PGC_SUSET,
65+
GUC_UNIT_MS,
66+
NULL,
67+
NULL);
68+
69+
DefineCustomBoolVariable(GUCNAME("log_analyze"),
70+
"Use EXPLAIN ANALYZE for plan logging.",
71+
NULL,
72+
&explain_log_analyze,
73+
false,
74+
PGC_SUSET,
75+
0,
76+
NULL,
77+
NULL);
78+
79+
DefineCustomBoolVariable(GUCNAME("log_verbose"),
80+
"Use EXPLAIN VERBOSE for plan logging.",
81+
NULL,
82+
&explain_log_verbose,
83+
false,
84+
PGC_SUSET,
85+
0,
86+
NULL,
87+
NULL);
88+
89+
DefineCustomBoolVariable(GUCNAME("log_nested_statements"),
90+
"Log nested statements.",
91+
NULL,
92+
&explain_log_nested,
93+
false,
94+
PGC_SUSET,
95+
0,
96+
NULL,
97+
NULL);
98+
99+
/* Install hooks. */
100+
prev_ExecutorStart = ExecutorStart_hook;
101+
ExecutorStart_hook = explain_ExecutorStart;
102+
prev_ExecutorRun = ExecutorRun_hook;
103+
ExecutorRun_hook = explain_ExecutorRun;
104+
prev_ExecutorEnd = ExecutorEnd_hook;
105+
ExecutorEnd_hook = explain_ExecutorEnd;
106+
}
107+
108+
/*
109+
* Module unload callback
110+
*/
111+
void
112+
_PG_fini(void)
113+
{
114+
/* Uninstall hooks. */
115+
ExecutorStart_hook = prev_ExecutorStart;
116+
ExecutorRun_hook = prev_ExecutorRun;
117+
ExecutorEnd_hook = prev_ExecutorEnd;
118+
}
119+
120+
/*
121+
* ExecutorStart hook: start up logging if needed
122+
*/
123+
void
124+
explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
125+
{
126+
if (auto_explain_enabled())
127+
{
128+
/* Enable per-node instrumentation iff log_analyze is required. */
129+
if (explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
130+
queryDesc->doInstrument = true;
131+
}
132+
133+
if (prev_ExecutorStart)
134+
prev_ExecutorStart(queryDesc, eflags);
135+
else
136+
standard_ExecutorStart(queryDesc, eflags);
137+
138+
if (auto_explain_enabled())
139+
{
140+
/*
141+
* Set up to track total elapsed time in ExecutorRun. Make sure
142+
* the space is allocated in the per-query context so it will go
143+
* away at ExecutorEnd.
144+
*/
145+
if (queryDesc->totaltime == NULL)
146+
{
147+
MemoryContext oldcxt;
148+
149+
oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
150+
queryDesc->totaltime = InstrAlloc(1);
151+
MemoryContextSwitchTo(oldcxt);
152+
}
153+
}
154+
}
155+
156+
/*
157+
* ExecutorRun hook: all we need do is track nesting depth
158+
*/
159+
void
160+
explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, long count)
161+
{
162+
nesting_level++;
163+
PG_TRY();
164+
{
165+
if (prev_ExecutorRun)
166+
prev_ExecutorRun(queryDesc, direction, count);
167+
else
168+
standard_ExecutorRun(queryDesc, direction, count);
169+
nesting_level--;
170+
}
171+
PG_CATCH();
172+
{
173+
nesting_level--;
174+
PG_RE_THROW();
175+
}
176+
PG_END_TRY();
177+
}
178+
179+
/*
180+
* ExecutorEnd hook: log results if needed
181+
*/
182+
void
183+
explain_ExecutorEnd(QueryDesc *queryDesc)
184+
{
185+
if (queryDesc->totaltime && auto_explain_enabled())
186+
{
187+
double msec;
188+
189+
/*
190+
* Make sure stats accumulation is done. (Note: it's okay if
191+
* several levels of hook all do this.)
192+
*/
193+
InstrEndLoop(queryDesc->totaltime);
194+
195+
/* Log plan if duration is exceeded. */
196+
msec = queryDesc->totaltime->total * 1000.0;
197+
if (msec >= explain_log_min_duration)
198+
{
199+
StringInfoData buf;
200+
201+
initStringInfo(&buf);
202+
ExplainPrintPlan(&buf, queryDesc,
203+
queryDesc->doInstrument && explain_log_analyze,
204+
explain_log_verbose);
205+
206+
/* Remove last line break */
207+
if (buf.len > 0 && buf.data[buf.len - 1] == '\n')
208+
buf.data[--buf.len] = '\0';
209+
210+
/*
211+
* Note: we rely on the existing logging of context or
212+
* debug_query_string to identify just which statement is being
213+
* reported. This isn't ideal but trying to do it here would
214+
* often result in duplication.
215+
*/
216+
ereport(LOG,
217+
(errmsg("duration: %.3f ms plan:\n%s",
218+
msec, buf.data)));
219+
220+
pfree(buf.data);
221+
}
222+
}
223+
224+
if (prev_ExecutorEnd)
225+
prev_ExecutorEnd(queryDesc);
226+
else
227+
standard_ExecutorEnd(queryDesc);
228+
}

0 commit comments

Comments
 (0)








ApplySandwichStrip

pFad - (p)hone/(F)rame/(a)nonymizer/(d)eclutterfier!      Saves Data!


--- a PPN by Garber Painting Akron. With Image Size Reduction included!

Fetched URL: http://github.com/tonybelloni/postgres/commit/e125e28e781116ceb2860be29e6508906c81d2da

Alternative Proxies:

Alternative Proxy

pFad Proxy

pFad v3 Proxy

pFad v4 Proxy