Movatterモバイル変換

[0]ホーム
URL:

Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

 Sign up
Appearance settings

Commitaf7914c

Browse files
committed
Add TIMING option to EXPLAIN, to allow eliminating of timing overhead.
Sometimes it may be useful to get actual row counts out of EXPLAIN(ANALYZE) without paying the cost of timing every node entry/exit.With this patch, you can say EXPLAIN (ANALYZE, TIMING OFF) to get that.Tomas Vondra, reviewed by Eric Theise, with minor doc changes by me.
1 parent1631598 commitaf7914c

File tree

6 files changed

+97
-22
lines changed

6 files changed

+97
-22
lines changed

‎contrib/auto_explain/auto_explain.c

Lines changed: 18 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@ static intauto_explain_log_min_duration = -1; /* msec or -1 */
2323
staticboolauto_explain_log_analyze= false;
2424
staticboolauto_explain_log_verbose= false;
2525
staticboolauto_explain_log_buffers= false;
26+
staticboolauto_explain_log_timing= false;
2627
staticintauto_explain_log_format=EXPLAIN_FORMAT_TEXT;
2728
staticboolauto_explain_log_nested_statements= false;
2829

@@ -133,6 +134,17 @@ _PG_init(void)
133134
NULL,
134135
NULL);
135136

137+
DefineCustomBoolVariable("auto_explain.log_timing",
138+
"Collect timing data, not just row counts.",
139+
NULL,
140+
&auto_explain_log_timing,
141+
true,
142+
PGC_SUSET,
143+
0,
144+
NULL,
145+
NULL,
146+
NULL);
147+
136148
EmitWarningsOnPlaceholders("auto_explain");
137149

138150
/* Install hooks. */
@@ -170,7 +182,12 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
170182
/* Enable per-node instrumentation iff log_analyze is required. */
171183
if (auto_explain_log_analyze&& (eflags&EXEC_FLAG_EXPLAIN_ONLY)==0)
172184
{
173-
queryDesc->instrument_options |=INSTRUMENT_TIMER;
185+
if (auto_explain_log_timing)
186+
queryDesc->instrument_options |=INSTRUMENT_TIMER;
187+
else
188+
queryDesc->instrument_options |=INSTRUMENT_ROWS;
189+
190+
174191
if (auto_explain_log_buffers)
175192
queryDesc->instrument_options |=INSTRUMENT_BUFFERS;
176193
}

‎doc/src/sgml/ref/explain.sgml

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -40,6 +40,7 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] <replaceable class="parameter">statement</replac
4040
VERBOSE [ <replaceable class="parameter">boolean</replaceable> ]
4141
COSTS [ <replaceable class="parameter">boolean</replaceable> ]
4242
BUFFERS [ <replaceable class="parameter">boolean</replaceable> ]
43+
TIMING [ <replaceable class="parameter">boolean</replaceable> ]
4344
FORMAT { TEXT | XML | JSON | YAML }
4445
</synopsis>
4546
</refsynopsisdiv>
@@ -171,6 +172,21 @@ ROLLBACK;
171172
</listitem>
172173
</varlistentry>
173174

175+
<varlistentry>
176+
<term><literal>TIMING</literal></term>
177+
<listitem>
178+
<para>
179+
Include the actual startup time and time spent in the node in the output.
180+
The overhead of repeatedly reading the system clock can slow down the
181+
query significantly on some systems, so it may be useful to set this
182+
parameter to <literal>FALSE</literal> when only actual row counts, and not
183+
exact times, are needed.
184+
This parameter may only be used when <literal>ANALYZE</literal> is also
185+
enabled. It defaults to <literal>TRUE</literal>.
186+
</para>
187+
</listitem>
188+
</varlistentry>
189+
174190
<varlistentry>
175191
<term><literal>FORMAT</literal></term>
176192
<listitem>

‎src/backend/commands/explain.c

Lines changed: 38 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -116,6 +116,7 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
116116
TupOutputState*tstate;
117117
List*rewritten;
118118
ListCell*lc;
119+
booltiming_set= false;
119120

120121
/* Initialize ExplainState. */
121122
ExplainInitState(&es);
@@ -133,6 +134,11 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
133134
es.costs=defGetBoolean(opt);
134135
elseif (strcmp(opt->defname,"buffers")==0)
135136
es.buffers=defGetBoolean(opt);
137+
elseif (strcmp(opt->defname,"timing")==0)
138+
{
139+
timing_set= true;
140+
es.timing=defGetBoolean(opt);
141+
}
136142
elseif (strcmp(opt->defname,"format")==0)
137143
{
138144
char*p=defGetString(opt);
@@ -162,6 +168,15 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
162168
ereport(ERROR,
163169
(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
164170
errmsg("EXPLAIN option BUFFERS requires ANALYZE")));
171+
172+
/* if the timing was not set explicitly, set default value */
173+
es.timing= (timing_set) ?es.timing :es.analyze;
174+
175+
/* check that timing is used with EXPLAIN ANALYZE */
176+
if (es.timing&& !es.analyze)
177+
ereport(ERROR,
178+
(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
179+
errmsg("EXPLAIN option TIMING requires ANALYZE")));
165180

166181
/*
167182
* Parse analysis was done already, but we still have to run the rule
@@ -360,8 +375,11 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ExplainState *es,
360375
inteflags;
361376
intinstrument_option=0;
362377

363-
if (es->analyze)
378+
if (es->analyze&&es->timing)
364379
instrument_option |=INSTRUMENT_TIMER;
380+
elseif (es->analyze)
381+
instrument_option |=INSTRUMENT_ROWS;
382+
365383
if (es->buffers)
366384
instrument_option |=INSTRUMENT_BUFFERS;
367385

@@ -956,29 +974,42 @@ ExplainNode(PlanState *planstate, List *ancestors,
956974

957975
if (es->format==EXPLAIN_FORMAT_TEXT)
958976
{
959-
appendStringInfo(es->str,
960-
" (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
961-
startup_sec,total_sec,rows,nloops);
977+
if (planstate->instrument->need_timer)
978+
appendStringInfo(es->str,
979+
" (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
980+
startup_sec,total_sec,rows,nloops);
981+
else
982+
appendStringInfo(es->str,
983+
" (actual rows=%.0f loops=%.0f)",
984+
rows,nloops);
962985
}
963986
else
964987
{
965-
ExplainPropertyFloat("Actual Startup Time",startup_sec,3,es);
966-
ExplainPropertyFloat("Actual Total Time",total_sec,3,es);
988+
if (planstate->instrument->need_timer)
989+
{
990+
ExplainPropertyFloat("Actual Startup Time",startup_sec,3,es);
991+
ExplainPropertyFloat("Actual Total Time",total_sec,3,es);
992+
}
967993
ExplainPropertyFloat("Actual Rows",rows,0,es);
968994
ExplainPropertyFloat("Actual Loops",nloops,0,es);
969995
}
970996
}
971997
elseif (es->analyze)
972998
{
999+
9731000
if (es->format==EXPLAIN_FORMAT_TEXT)
9741001
appendStringInfo(es->str," (never executed)");
975-
else
1002+
elseif (planstate->instrument->need_timer)
9761003
{
9771004
ExplainPropertyFloat("Actual Startup Time",0.0,3,es);
9781005
ExplainPropertyFloat("Actual Total Time",0.0,3,es);
1006+
}
1007+
else
1008+
{
9791009
ExplainPropertyFloat("Actual Rows",0.0,0,es);
9801010
ExplainPropertyFloat("Actual Loops",0.0,0,es);
9811011
}
1012+
9821013
}
9831014

9841015
/* in text format, first line ends here */

‎src/backend/executor/instrument.c

Lines changed: 21 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -29,17 +29,19 @@ InstrAlloc(int n, int instrument_options)
2929
{
3030
Instrumentation*instr;
3131

32-
/* timer is always required for now */
33-
Assert(instrument_options&INSTRUMENT_TIMER);
34-
3532
/* initialize all fields to zeroes, then modify as needed */
3633
instr=palloc0(n*sizeof(Instrumentation));
37-
if (instrument_options&INSTRUMENT_BUFFERS)
34+
if (instrument_options&(INSTRUMENT_BUFFERS |INSTRUMENT_TIMER))
3835
{
3936
inti;
37+
boolneed_buffers=instrument_options&INSTRUMENT_BUFFERS;
38+
boolneed_timer=instrument_options&INSTRUMENT_TIMER;
4039

4140
for (i=0;i<n;i++)
42-
instr[i].need_bufusage= true;
41+
{
42+
instr[i].need_bufusage=need_buffers;
43+
instr[i].need_timer=need_timer;
44+
}
4345
}
4446

4547
returninstr;
@@ -49,7 +51,7 @@ InstrAlloc(int n, int instrument_options)
4951
void
5052
InstrStartNode(Instrumentation*instr)
5153
{
52-
if (INSTR_TIME_IS_ZERO(instr->starttime))
54+
if (instr->need_timer&&INSTR_TIME_IS_ZERO(instr->starttime))
5355
INSTR_TIME_SET_CURRENT(instr->starttime);
5456
else
5557
elog(DEBUG2,"InstrStartNode called twice in a row");
@@ -68,16 +70,22 @@ InstrStopNode(Instrumentation *instr, double nTuples)
6870
/* count the returned tuples */
6971
instr->tuplecount+=nTuples;
7072

71-
if (INSTR_TIME_IS_ZERO(instr->starttime))
73+
/* let's update the time only if the timer was requested */
74+
if (instr->need_timer)
7275
{
73-
elog(DEBUG2,"InstrStopNode called without start");
74-
return;
75-
}
7676

77-
INSTR_TIME_SET_CURRENT(endtime);
78-
INSTR_TIME_ACCUM_DIFF(instr->counter,endtime,instr->starttime);
77+
if (INSTR_TIME_IS_ZERO(instr->starttime))
78+
{
79+
elog(DEBUG2,"InstrStopNode called without start");
80+
return;
81+
}
7982

80-
INSTR_TIME_SET_ZERO(instr->starttime);
83+
INSTR_TIME_SET_CURRENT(endtime);
84+
INSTR_TIME_ACCUM_DIFF(instr->counter,endtime,instr->starttime);
85+
86+
INSTR_TIME_SET_ZERO(instr->starttime);
87+
88+
}
8189

8290
/* Add delta of buffer usage since entry to node's totals */
8391
if (instr->need_bufusage)

‎src/include/commands/explain.h

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@ typedef struct ExplainState
3131
boolanalyze;/* print actual times */
3232
boolcosts;/* print costs */
3333
boolbuffers;/* print buffer usage */
34+
booltiming;/* print timing */
3435
ExplainFormatformat;/* output format */
3536
/* other states */
3637
PlannedStmt*pstmt;/* top of plan */

‎src/include/executor/instrument.h

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -31,14 +31,16 @@ typedef struct BufferUsage
3131
/* Flag bits included in InstrAlloc's instrument_options bitmask */
3232
typedefenumInstrumentOption
3333
{
34-
INSTRUMENT_TIMER=1 <<0,/* needs timer */
34+
INSTRUMENT_TIMER=1 <<0,/* needs timer(and row counts)*/
3535
INSTRUMENT_BUFFERS=1 <<1,/* needs buffer usage */
36+
INSTRUMENT_ROWS=1 <<2,/* needs row count */
3637
INSTRUMENT_ALL=0x7FFFFFFF
3738
}InstrumentOption;
3839

3940
typedefstructInstrumentation
4041
{
4142
/* Parameters set at node creation: */
43+
boolneed_timer;/* TRUE if we need timer data */
4244
boolneed_bufusage;/* TRUE if we need buffer usage data */
4345
/* Info about current plan cycle: */
4446
boolrunning;/* TRUE if we've completed first tuple */

0 commit comments

Comments
 (0)
[8]ページ先頭
©2009-2025 Movatter.jp