Skip to content

Commit a0c217f

Browse files
author
Maksim Milyutin
committed
Apply patch to postgres core
1 parent f37f286 commit a0c217f

File tree

7 files changed

+300
-28
lines changed

7 files changed

+300
-28
lines changed

‎src/backend/commands/explain.c

Lines changed: 129 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -667,15 +667,35 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es)
667667
Instrumentation *instr = rInfo->ri_TrigInstrument + nt;
668668
char *relname;
669669
char *conname = NULL;
670+
instr_time starttimespan;
671+
double total;
672+
double ntuples;
673+
double ncalls;
670674

671-
/* Must clean up instrumentation state */
672-
InstrEndLoop(instr);
675+
if (!es->runtime)
676+
{
677+
/* Must clean up instrumentation state */
678+
InstrEndLoop(instr);
679+
}
680+
681+
/* Collect statistic variables */
682+
if (!INSTR_TIME_IS_ZERO(instr->starttime))
683+
{
684+
INSTR_TIME_SET_CURRENT(starttimespan);
685+
INSTR_TIME_SUBTRACT(starttimespan, instr->starttime);
686+
}
687+
else
688+
INSTR_TIME_SET_ZERO(starttimespan);
689+
total = instr->total + INSTR_TIME_GET_DOUBLE(instr->counter)
690+
+ INSTR_TIME_GET_DOUBLE(starttimespan);
691+
ntuples = instr->ntuples + instr->tuplecount;
692+
ncalls = ntuples + !INSTR_TIME_IS_ZERO(starttimespan);
673693

674694
/*
675695
* We ignore triggers that were never invoked; they likely aren't
676696
* relevant to the current query type.
677697
*/
678-
if (instr->ntuples == 0)
698+
if (ncalls == 0)
679699
continue;
680700

681701
ExplainOpenGroup("Trigger", NULL, true, es);
@@ -701,9 +721,9 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es)
701721
appendStringInfo(es->str, " on %s", relname);
702722
if (es->timing)
703723
appendStringInfo(es->str, ": time=%.3f calls=%.0f\n",
704-
1000.0 * instr->total, instr->ntuples);
724+
1000.0 * total, ncalls);
705725
else
706-
appendStringInfo(es->str, ": calls=%.0f\n", instr->ntuples);
726+
appendStringInfo(es->str, ": calls=%.0f\n", ncalls);
707727
}
708728
else
709729
{
@@ -712,8 +732,8 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es)
712732
ExplainPropertyText("Constraint Name", conname, es);
713733
ExplainPropertyText("Relation", relname, es);
714734
if (es->timing)
715-
ExplainPropertyFloat("Time", 1000.0 * instr->total, 3, es);
716-
ExplainPropertyFloat("Calls", instr->ntuples, 0, es);
735+
ExplainPropertyFloat("Time", 1000.0 * total, 3, es);
736+
ExplainPropertyFloat("Calls", ncalls, 0, es);
717737
}
718738

719739
if (conname)
@@ -1225,8 +1245,11 @@ ExplainNode(PlanState *planstate, List *ancestors,
12251245
* instrumentation results the user didn't ask for. But we do the
12261246
* InstrEndLoop call anyway, if possible, to reduce the number of cases
12271247
* auto_explain has to contend with.
1248+
*
1249+
* if flag es->stateinfo is set i.e. when printing the current execution state
1250+
* this step of cleaning up is miss
12281251
*/
1229-
if (planstate->instrument)
1252+
if (planstate->instrument && !es->runtime)
12301253
InstrEndLoop(planstate->instrument);
12311254

12321255
if (es->analyze &&
@@ -1259,7 +1282,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
12591282
ExplainPropertyFloat("Actual Loops", nloops, 0, es);
12601283
}
12611284
}
1262-
else if (es->analyze)
1285+
else if (es->analyze && !es->runtime)
12631286
{
12641287
if (es->format == EXPLAIN_FORMAT_TEXT)
12651288
appendStringInfoString(es->str, " (never executed)");
@@ -1275,6 +1298,75 @@ ExplainNode(PlanState *planstate, List *ancestors,
12751298
}
12761299
}
12771300

1301+
/*
1302+
* print the progress of node execution at current loop
1303+
*/
1304+
if (planstate->instrument && es->analyze && es->runtime)
1305+
{
1306+
instr_time starttimespan;
1307+
double startup_sec;
1308+
double total_sec;
1309+
double rows;
1310+
double loop_num;
1311+
bool finished;
1312+
1313+
if (!INSTR_TIME_IS_ZERO(planstate->instrument->starttime))
1314+
{
1315+
INSTR_TIME_SET_CURRENT(starttimespan);
1316+
INSTR_TIME_SUBTRACT(starttimespan, planstate->instrument->starttime);
1317+
}
1318+
else
1319+
INSTR_TIME_SET_ZERO(starttimespan);
1320+
startup_sec = 1000.0 * planstate->instrument->firsttuple;
1321+
total_sec = 1000.0 * (INSTR_TIME_GET_DOUBLE(planstate->instrument->counter)
1322+
+ INSTR_TIME_GET_DOUBLE(starttimespan));
1323+
rows = planstate->instrument->tuplecount;
1324+
loop_num = planstate->instrument->nloops + 1;
1325+
1326+
finished = planstate->instrument->nloops > 0
1327+
&& !planstate->instrument->running
1328+
&& INSTR_TIME_IS_ZERO(starttimespan);
1329+
1330+
if (!finished)
1331+
{
1332+
ExplainOpenGroup("Current loop", "Current loop", true, es);
1333+
if (es->format == EXPLAIN_FORMAT_TEXT)
1334+
{
1335+
if (es->timing)
1336+
{
1337+
if (planstate->instrument->running)
1338+
appendStringInfo(es->str,
1339+
" (Current loop: actual time=%.3f..%.3f rows=%.0f, loop number=%.0f)",
1340+
startup_sec, total_sec, rows, loop_num);
1341+
else
1342+
appendStringInfo(es->str,
1343+
" (Current loop: running time=%.3f actual rows=0, loop number=%.0f)",
1344+
total_sec, loop_num);
1345+
}
1346+
else
1347+
appendStringInfo(es->str,
1348+
" (Current loop: actual rows=%.0f, loop number=%.0f)",
1349+
rows, loop_num);
1350+
}
1351+
else
1352+
{
1353+
ExplainPropertyFloat("Actual Loop Number", loop_num, 0, es);
1354+
if (es->timing)
1355+
{
1356+
if (planstate->instrument->running)
1357+
{
1358+
ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
1359+
ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
1360+
}
1361+
else
1362+
ExplainPropertyFloat("Running Time", total_sec, 3, es);
1363+
}
1364+
ExplainPropertyFloat("Actual Rows", rows, 0, es);
1365+
}
1366+
ExplainCloseGroup("Current loop", "Current loop", true, es);
1367+
}
1368+
}
1369+
12781370
/* in text format, first line ends here */
12791371
if (es->format == EXPLAIN_FORMAT_TEXT)
12801372
appendStringInfoChar(es->str, '\n');
@@ -1508,8 +1600,9 @@ ExplainNode(PlanState *planstate, List *ancestors,
15081600
if (es->buffers && planstate->instrument)
15091601
show_buffer_usage(es, &planstate->instrument->bufusage);
15101602

1511-
/* Show worker detail */
1512-
if (es->analyze && es->verbose && planstate->worker_instrument)
1603+
/* Show worker detail after query execution */
1604+
if (es->analyze && es->verbose && planstate->worker_instrument
1605+
&& !es->runtime)
15131606
{
15141607
WorkerInstrumentation *w = planstate->worker_instrument;
15151608
bool opened_group = false;
@@ -2269,20 +2362,17 @@ show_instrumentation_count(const char *qlabel, int which,
22692362
if (!es->analyze || !planstate->instrument)
22702363
return;
22712364

2365+
nloops = planstate->instrument->nloops;
22722366
if (which == 2)
2273-
nfiltered = planstate->instrument->nfiltered2;
2367+
nfiltered = ((nloops > 0) ? planstate->instrument->accum_nfiltered2 / nloops : 0)
2368+
+ planstate->instrument->nfiltered2;
22742369
else
2275-
nfiltered = planstate->instrument->nfiltered1;
2276-
nloops = planstate->instrument->nloops;
2370+
nfiltered = ((nloops > 0) ? planstate->instrument->accum_nfiltered1 / nloops : 0)
2371+
+ planstate->instrument->nfiltered1;
22772372

22782373
/* In text mode, suppress zero counts; they're not interesting enough */
22792374
if (nfiltered > 0 || es->format != EXPLAIN_FORMAT_TEXT)
2280-
{
2281-
if (nloops > 0)
2282-
ExplainPropertyFloat(qlabel, nfiltered / nloops, 0, es);
2283-
else
2284-
ExplainPropertyFloat(qlabel, 0.0, 0, es);
2285-
}
2375+
ExplainPropertyFloat(qlabel, nfiltered, 0, es);
22862376
}
22872377

22882378
/*
@@ -2754,14 +2844,28 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors,
27542844
double insert_path;
27552845
double other_path;
27562846

2757-
InstrEndLoop(mtstate->mt_plans[0]->instrument);
2847+
if (!es->runtime)
2848+
InstrEndLoop(mtstate->mt_plans[0]->instrument);
27582849

27592850
/* count the number of source rows */
2760-
total = mtstate->mt_plans[0]->instrument->ntuples;
2761-
other_path = mtstate->ps.instrument->nfiltered2;
2762-
insert_path = total - other_path;
2851+
other_path = mtstate->ps.instrument->accum_nfiltered2
2852+
+ mtstate->ps.instrument->nfiltered2;
2853+
2854+
/*
2855+
* Insert occurs after extracting row from subplan and in runtime mode
2856+
* we can appear between these two operations - situation when
2857+
* total > insert_path + other_path. Therefore we don't know exactly
2858+
* whether last row from subplan is inserted.
2859+
* We don't print inserted tuples in runtime mode in order to not print
2860+
* inconsistent data
2861+
*/
2862+
if (!es->runtime)
2863+
{
2864+
total = mtstate->mt_plans[0]->instrument->ntuples;
2865+
insert_path = total - other_path;
2866+
ExplainPropertyFloat("Tuples Inserted", insert_path, 0, es);
2867+
}
27632868

2764-
ExplainPropertyFloat("Tuples Inserted", insert_path, 0, es);
27652869
ExplainPropertyFloat("Conflicting Tuples", other_path, 0, es);
27662870
}
27672871
}

‎src/backend/executor/instrument.c

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -129,13 +129,17 @@ InstrEndLoop(Instrumentation *instr)
129129
instr->total += totaltime;
130130
instr->ntuples += instr->tuplecount;
131131
instr->nloops += 1;
132+
instr->accum_nfiltered1 += instr->nfiltered1;
133+
instr->accum_nfiltered2 += instr->nfiltered2;
132134

133135
/* Reset for next cycle (if any) */
134136
instr->running = false;
135137
INSTR_TIME_SET_ZERO(instr->starttime);
136138
INSTR_TIME_SET_ZERO(instr->counter);
137139
instr->firsttuple = 0;
138140
instr->tuplecount = 0;
141+
instr->nfiltered1 = 0;
142+
instr->nfiltered2 = 0;
139143
}
140144

141145
/* aggregate instrumentation information */

0 commit comments

Comments
 (0)