Skip to content

Commit 16bc2d1

Browse files
author
Maksim Milyutin
committed
Apply patches for pg_query_state extension
1 parent 18061a5 commit 16bc2d1

File tree

9 files changed

+282
-27
lines changed

9 files changed

+282
-27
lines changed

‎src/backend/commands/explain.c

Lines changed: 126 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -653,15 +653,35 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es)
653653
Instrumentation *instr = rInfo->ri_TrigInstrument + nt;
654654
char *relname;
655655
char *conname = NULL;
656+
instr_time starttimespan;
657+
double total;
658+
double ntuples;
659+
double ncalls;
656660

657-
/* Must clean up instrumentation state */
658-
InstrEndLoop(instr);
661+
if (!es->runtime)
662+
{
663+
/* Must clean up instrumentation state */
664+
InstrEndLoop(instr);
665+
}
666+
667+
/* Collect statistic variables */
668+
if (!INSTR_TIME_IS_ZERO(instr->starttime))
669+
{
670+
INSTR_TIME_SET_CURRENT(starttimespan);
671+
INSTR_TIME_SUBTRACT(starttimespan, instr->starttime);
672+
}
673+
else
674+
INSTR_TIME_SET_ZERO(starttimespan);
675+
total = instr->total + INSTR_TIME_GET_DOUBLE(instr->counter)
676+
+ INSTR_TIME_GET_DOUBLE(starttimespan);
677+
ntuples = instr->ntuples + instr->tuplecount;
678+
ncalls = ntuples + !INSTR_TIME_IS_ZERO(starttimespan);
659679

660680
/*
661681
* We ignore triggers that were never invoked; they likely aren't
662682
* relevant to the current query type.
663683
*/
664-
if (instr->ntuples == 0)
684+
if (ncalls == 0)
665685
continue;
666686

667687
ExplainOpenGroup("Trigger", NULL, true, es);
@@ -687,9 +707,9 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es)
687707
appendStringInfo(es->str, " on %s", relname);
688708
if (es->timing)
689709
appendStringInfo(es->str, ": time=%.3f calls=%.0f\n",
690-
1000.0 * instr->total, instr->ntuples);
710+
1000.0 * total, ncalls);
691711
else
692-
appendStringInfo(es->str, ": calls=%.0f\n", instr->ntuples);
712+
appendStringInfo(es->str, ": calls=%.0f\n", ncalls);
693713
}
694714
else
695715
{
@@ -698,8 +718,8 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es)
698718
ExplainPropertyText("Constraint Name", conname, es);
699719
ExplainPropertyText("Relation", relname, es);
700720
if (es->timing)
701-
ExplainPropertyFloat("Time", 1000.0 * instr->total, 3, es);
702-
ExplainPropertyFloat("Calls", instr->ntuples, 0, es);
721+
ExplainPropertyFloat("Time", 1000.0 * total, 3, es);
722+
ExplainPropertyFloat("Calls", ncalls, 0, es);
703723
}
704724

705725
if (conname)
@@ -1247,8 +1267,11 @@ ExplainNode(PlanState *planstate, List *ancestors,
12471267
* instrumentation results the user didn't ask for. But we do the
12481268
* InstrEndLoop call anyway, if possible, to reduce the number of cases
12491269
* auto_explain has to contend with.
1270+
*
1271+
* if flag es->stateinfo is set i.e. when printing the current execution state
1272+
* this step of cleaning up is miss
12501273
*/
1251-
if (planstate->instrument)
1274+
if (planstate->instrument && !es->runtime)
12521275
InstrEndLoop(planstate->instrument);
12531276

12541277
if (es->analyze &&
@@ -1281,7 +1304,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
12811304
ExplainPropertyFloat("Actual Loops", nloops, 0, es);
12821305
}
12831306
}
1284-
else if (es->analyze)
1307+
else if (es->analyze && !es->runtime)
12851308
{
12861309
if (es->format == EXPLAIN_FORMAT_TEXT)
12871310
appendStringInfoString(es->str, " (never executed)");
@@ -1297,6 +1320,75 @@ ExplainNode(PlanState *planstate, List *ancestors,
12971320
}
12981321
}
12991322

1323+
/*
1324+
* print the progress of node execution at current loop
1325+
*/
1326+
if (planstate->instrument && es->analyze && es->runtime)
1327+
{
1328+
instr_time starttimespan;
1329+
double startup_sec;
1330+
double total_sec;
1331+
double rows;
1332+
double loop_num;
1333+
bool finished;
1334+
1335+
if (!INSTR_TIME_IS_ZERO(planstate->instrument->starttime))
1336+
{
1337+
INSTR_TIME_SET_CURRENT(starttimespan);
1338+
INSTR_TIME_SUBTRACT(starttimespan, planstate->instrument->starttime);
1339+
}
1340+
else
1341+
INSTR_TIME_SET_ZERO(starttimespan);
1342+
startup_sec = 1000.0 * planstate->instrument->firsttuple;
1343+
total_sec = 1000.0 * (INSTR_TIME_GET_DOUBLE(planstate->instrument->counter)
1344+
+ INSTR_TIME_GET_DOUBLE(starttimespan));
1345+
rows = planstate->instrument->tuplecount;
1346+
loop_num = planstate->instrument->nloops + 1;
1347+
1348+
finished = planstate->instrument->nloops > 0
1349+
&& !planstate->instrument->running
1350+
&& INSTR_TIME_IS_ZERO(starttimespan);
1351+
1352+
if (!finished)
1353+
{
1354+
ExplainOpenGroup("Current loop", "Current loop", true, es);
1355+
if (es->format == EXPLAIN_FORMAT_TEXT)
1356+
{
1357+
if (es->timing)
1358+
{
1359+
if (planstate->instrument->running)
1360+
appendStringInfo(es->str,
1361+
" (Current loop: actual time=%.3f..%.3f rows=%.0f, loop number=%.0f)",
1362+
startup_sec, total_sec, rows, loop_num);
1363+
else
1364+
appendStringInfo(es->str,
1365+
" (Current loop: running time=%.3f actual rows=0, loop number=%.0f)",
1366+
total_sec, loop_num);
1367+
}
1368+
else
1369+
appendStringInfo(es->str,
1370+
" (Current loop: actual rows=%.0f, loop number=%.0f)",
1371+
rows, loop_num);
1372+
}
1373+
else
1374+
{
1375+
ExplainPropertyFloat("Actual Loop Number", loop_num, 0, es);
1376+
if (es->timing)
1377+
{
1378+
if (planstate->instrument->running)
1379+
{
1380+
ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
1381+
ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
1382+
}
1383+
else
1384+
ExplainPropertyFloat("Running Time", total_sec, 3, es);
1385+
}
1386+
ExplainPropertyFloat("Actual Rows", rows, 0, es);
1387+
}
1388+
ExplainCloseGroup("Current loop", "Current loop", true, es);
1389+
}
1390+
}
1391+
13001392
/* in text format, first line ends here */
13011393
if (es->format == EXPLAIN_FORMAT_TEXT)
13021394
appendStringInfoChar(es->str, '\n');
@@ -2293,20 +2385,17 @@ show_instrumentation_count(const char *qlabel, int which,
22932385
if (!es->analyze || !planstate->instrument)
22942386
return;
22952387

2388+
nloops = planstate->instrument->nloops;
22962389
if (which == 2)
2297-
nfiltered = planstate->instrument->nfiltered2;
2390+
nfiltered = ((nloops > 0) ? planstate->instrument->accum_nfiltered2 / nloops : 0)
2391+
+ planstate->instrument->nfiltered2;
22982392
else
2299-
nfiltered = planstate->instrument->nfiltered1;
2300-
nloops = planstate->instrument->nloops;
2393+
nfiltered = ((nloops > 0) ? planstate->instrument->accum_nfiltered1 / nloops : 0)
2394+
+ planstate->instrument->nfiltered1;
23012395

23022396
/* In text mode, suppress zero counts; they're not interesting enough */
23032397
if (nfiltered > 0 || es->format != EXPLAIN_FORMAT_TEXT)
2304-
{
2305-
if (nloops > 0)
2306-
ExplainPropertyFloat(qlabel, nfiltered / nloops, 0, es);
2307-
else
2308-
ExplainPropertyFloat(qlabel, 0.0, 0, es);
2309-
}
2398+
ExplainPropertyFloat(qlabel, nfiltered, 0, es);
23102399
}
23112400

23122401
/*
@@ -2658,14 +2747,28 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors,
26582747
double insert_path;
26592748
double other_path;
26602749

2661-
InstrEndLoop(mtstate->mt_plans[0]->instrument);
2750+
if (!es->runtime)
2751+
InstrEndLoop(mtstate->mt_plans[0]->instrument);
26622752

26632753
/* count the number of source rows */
2664-
total = mtstate->mt_plans[0]->instrument->ntuples;
2665-
other_path = mtstate->ps.instrument->nfiltered2;
2666-
insert_path = total - other_path;
2754+
other_path = mtstate->ps.instrument->accum_nfiltered2
2755+
+ mtstate->ps.instrument->nfiltered2;
2756+
2757+
/*
2758+
* Insert occurs after extracting row from subplan and in runtime mode
2759+
* we can appear between these two operations - situation when
2760+
* total > insert_path + other_path. Therefore we don't know exactly
2761+
* whether last row from subplan is inserted.
2762+
* We don't print inserted tuples in runtime mode in order to not print
2763+
* inconsistent data
2764+
*/
2765+
if (!es->runtime)
2766+
{
2767+
total = mtstate->mt_plans[0]->instrument->ntuples;
2768+
insert_path = total - other_path;
2769+
ExplainPropertyFloat("Tuples Inserted", insert_path, 0, es);
2770+
}
26672771

2668-
ExplainPropertyFloat("Tuples Inserted", insert_path, 0, es);
26692772
ExplainPropertyFloat("Conflicting Tuples", other_path, 0, es);
26702773
}
26712774
}

‎src/backend/executor/execProcnode.c

Lines changed: 13 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -115,7 +115,6 @@
115115
#include "executor/nodeWorktablescan.h"
116116
#include "miscadmin.h"
117117

118-
119118
/* ------------------------------------------------------------------------
120119
* ExecInitNode
121120
*
@@ -356,6 +355,9 @@ ExecInitNode(Plan *node, EState *estate, int eflags)
356355
return result;
357356
}
358357

358+
/* Hooks for plugins to pre/post process ExecProcNode */
359+
PreExecProcNode_hook_type preExecProcNode_hook = NULL;
360+
PostExecProcNode_hook_type postExecProcNode_hook = NULL;
359361

360362
/* ----------------------------------------------------------------
361363
* ExecProcNode
@@ -374,7 +376,12 @@ ExecProcNode(PlanState *node)
374376
ExecReScan(node); /* let ReScan handle this */
375377

376378
if (node->instrument)
379+
{
380+
if (preExecProcNode_hook)
381+
preExecProcNode_hook(node);
382+
377383
InstrStartNode(node->instrument);
384+
}
378385

379386
switch (nodeTag(node))
380387
{
@@ -527,8 +534,13 @@ ExecProcNode(PlanState *node)
527534
}
528535

529536
if (node->instrument)
537+
{
530538
InstrStopNode(node->instrument, TupIsNull(result) ? 0.0 : 1.0);
531539

540+
if (postExecProcNode_hook)
541+
postExecProcNode_hook(node, result);
542+
}
543+
532544
return result;
533545
}
534546

‎src/backend/executor/instrument.c

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -118,13 +118,17 @@ InstrEndLoop(Instrumentation *instr)
118118
instr->total += totaltime;
119119
instr->ntuples += instr->tuplecount;
120120
instr->nloops += 1;
121+
instr->accum_nfiltered1 += instr->nfiltered1;
122+
instr->accum_nfiltered2 += instr->nfiltered2;
121123

122124
/* Reset for next cycle (if any) */
123125
instr->running = false;
124126
INSTR_TIME_SET_ZERO(instr->starttime);
125127
INSTR_TIME_SET_ZERO(instr->counter);
126128
instr->firsttuple = 0;
127129
instr->tuplecount = 0;
130+
instr->nfiltered1 = 0;
131+
instr->nfiltered2 = 0;
128132
}
129133

130134
/* dst += add - sub */

0 commit comments

Comments
 (0)