|
| 1 | +diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c |
| 2 | +index 18a5af6b919..73d3d6171eb 100644 |
| 3 | +--- a/src/backend/commands/explain.c |
| 4 | ++++ b/src/backend/commands/explain.c |
| 5 | +@@ -18,6 +18,7 @@ |
| 6 | + #include "commands/createas.h" |
| 7 | + #include "commands/defrem.h" |
| 8 | + #include "commands/prepare.h" |
| 9 | ++#include "executor/nodeHash.h" |
| 10 | + #include "foreign/fdwapi.h" |
| 11 | + #include "jit/jit.h" |
| 12 | + #include "libpq/pqformat.h" |
| 13 | +@@ -1233,14 +1234,36 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es) |
| 14 | + char *relname; |
| 15 | + char *conname = NULL; |
| 16 | + |
| 17 | ++ instr_time starttimespan; |
| 18 | ++ double total; |
| 19 | ++ double ntuples; |
| 20 | ++ double ncalls; |
| 21 | ++ |
| 22 | ++ if (!es->runtime) |
| 23 | ++ { |
| 24 | + /* Must clean up instrumentation state */ |
| 25 | + InstrEndLoop(instr); |
| 26 | ++ } |
| 27 | ++ |
| 28 | ++ /* Collect statistic variables */ |
| 29 | ++ if (!INSTR_TIME_IS_ZERO(instr->starttime)) |
| 30 | ++ { |
| 31 | ++ INSTR_TIME_SET_CURRENT(starttimespan); |
| 32 | ++ INSTR_TIME_SUBTRACT(starttimespan, instr->starttime); |
| 33 | ++ } |
| 34 | ++ else |
| 35 | ++ INSTR_TIME_SET_ZERO(starttimespan); |
| 36 | ++ |
| 37 | ++ total = instr->total + INSTR_TIME_GET_DOUBLE(instr->counter) |
| 38 | ++ + INSTR_TIME_GET_DOUBLE(starttimespan); |
| 39 | ++ ntuples = instr->ntuples + instr->tuplecount; |
| 40 | ++ ncalls = ntuples + !INSTR_TIME_IS_ZERO(starttimespan); |
| 41 | + |
| 42 | + /* |
| 43 | + * We ignore triggers that were never invoked; they likely aren't |
| 44 | + * relevant to the current query type. |
| 45 | + */ |
| 46 | +- if (instr->ntuples == 0) |
| 47 | ++ if (ncalls == 0) |
| 48 | + continue; |
| 49 | + |
| 50 | + ExplainOpenGroup("Trigger", NULL, true, es); |
| 51 | +@@ -1266,9 +1289,9 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es) |
| 52 | + appendStringInfo(es->str, " on %s", relname); |
| 53 | + if (es->timing) |
| 54 | + appendStringInfo(es->str, ": time=%.3f calls=%.0f\n", |
| 55 | +- 1000.0 * instr->total, instr->ntuples); |
| 56 | ++ 1000.0 * total, ncalls); |
| 57 | + else |
| 58 | +- appendStringInfo(es->str, ": calls=%.0f\n", instr->ntuples); |
| 59 | ++ appendStringInfo(es->str, ": calls=%.0f\n", ncalls); |
| 60 | + } |
| 61 | + else |
| 62 | + { |
| 63 | +@@ -1277,9 +1300,8 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es) |
| 64 | + ExplainPropertyText("Constraint Name", conname, es); |
| 65 | + ExplainPropertyText("Relation", relname, es); |
| 66 | + if (es->timing) |
| 67 | +- ExplainPropertyFloat("Time", "ms", 1000.0 * instr->total, 3, |
| 68 | +- es); |
| 69 | +- ExplainPropertyFloat("Calls", NULL, instr->ntuples, 0, es); |
| 70 | ++ ExplainPropertyFloat("Time", "ms", 1000.0 * total, 3, es); |
| 71 | ++ ExplainPropertyFloat("Calls", NULL, ncalls, 0, es); |
| 72 | + } |
| 73 | + |
| 74 | + if (conname) |
| 75 | +@@ -1949,8 +1971,11 @@ ExplainNode(PlanState *planstate, List *ancestors, |
| 76 | + * instrumentation results the user didn't ask for. But we do the |
| 77 | + * InstrEndLoop call anyway, if possible, to reduce the number of cases |
| 78 | + * auto_explain has to contend with. |
| 79 | ++ * |
| 80 | ++ * If flag es->stateinfo is set, i.e. when printing the current execution |
| 81 | ++ * state, this step of cleaning up is missed. |
| 82 | + */ |
| 83 | +- if (planstate->instrument) |
| 84 | ++ if (planstate->instrument && !es->runtime) |
| 85 | + InstrEndLoop(planstate->instrument); |
| 86 | + |
| 87 | + if (es->analyze && |
| 88 | +@@ -1985,7 +2010,7 @@ ExplainNode(PlanState *planstate, List *ancestors, |
| 89 | + ExplainPropertyFloat("Actual Loops", NULL, nloops, 0, es); |
| 90 | + } |
| 91 | + } |
| 92 | +- else if (es->analyze) |
| 93 | ++ else if (es->analyze && !es->runtime) |
| 94 | + { |
| 95 | + if (es->format == EXPLAIN_FORMAT_TEXT) |
| 96 | + appendStringInfoString(es->str, " (never executed)"); |
| 97 | +@@ -2001,6 +2026,75 @@ ExplainNode(PlanState *planstate, List *ancestors, |
| 98 | + } |
| 99 | + } |
| 100 | + |
| 101 | ++ /* |
| 102 | ++ * Print the progress of node execution at current loop. |
| 103 | ++ */ |
| 104 | ++ if (planstate->instrument && es->analyze && es->runtime) |
| 105 | ++ { |
| 106 | ++ instr_time starttimespan; |
| 107 | ++ double startup_sec; |
| 108 | ++ double total_sec; |
| 109 | ++ double rows; |
| 110 | ++ double loop_num; |
| 111 | ++ bool finished; |
| 112 | ++ |
| 113 | ++ if (!INSTR_TIME_IS_ZERO(planstate->instrument->starttime)) |
| 114 | ++ { |
| 115 | ++ INSTR_TIME_SET_CURRENT(starttimespan); |
| 116 | ++ INSTR_TIME_SUBTRACT(starttimespan, planstate->instrument->starttime); |
| 117 | ++ } |
| 118 | ++ else |
| 119 | ++ INSTR_TIME_SET_ZERO(starttimespan); |
| 120 | ++ startup_sec = 1000.0 * planstate->instrument->firsttuple; |
| 121 | ++ total_sec = 1000.0 * (INSTR_TIME_GET_DOUBLE(planstate->instrument->counter) |
| 122 | ++ + INSTR_TIME_GET_DOUBLE(starttimespan)); |
| 123 | ++ rows = planstate->instrument->tuplecount; |
| 124 | ++ loop_num = planstate->instrument->nloops + 1; |
| 125 | ++ |
| 126 | ++ finished = planstate->instrument->nloops > 0 |
| 127 | ++ && !planstate->instrument->running |
| 128 | ++ && INSTR_TIME_IS_ZERO(starttimespan); |
| 129 | ++ |
| 130 | ++ if (!finished) |
| 131 | ++ { |
| 132 | ++ ExplainOpenGroup("Current loop", "Current loop", true, es); |
| 133 | ++ if (es->format == EXPLAIN_FORMAT_TEXT) |
| 134 | ++ { |
| 135 | ++ if (es->timing) |
| 136 | ++ { |
| 137 | ++ if (planstate->instrument->running) |
| 138 | ++ appendStringInfo(es->str, |
| 139 | ++ " (Current loop: actual time=%.3f..%.3f rows=%.0f, loop number=%.0f)", |
| 140 | ++ startup_sec, total_sec, rows, loop_num); |
| 141 | ++ else |
| 142 | ++ appendStringInfo(es->str, |
| 143 | ++ " (Current loop: running time=%.3f actual rows=0, loop number=%.0f)", |
| 144 | ++ total_sec, loop_num); |
| 145 | ++ } |
| 146 | ++ else |
| 147 | ++ appendStringInfo(es->str, |
| 148 | ++ " (Current loop: actual rows=%.0f, loop number=%.0f)", |
| 149 | ++ rows, loop_num); |
| 150 | ++ } |
| 151 | ++ else |
| 152 | ++ { |
| 153 | ++ ExplainPropertyFloat("Actual Loop Number", NULL, loop_num, 0, es); |
| 154 | ++ if (es->timing) |
| 155 | ++ { |
| 156 | ++ if (planstate->instrument->running) |
| 157 | ++ { |
| 158 | ++ ExplainPropertyFloat("Actual Startup Time", NULL, startup_sec, 3, es); |
| 159 | ++ ExplainPropertyFloat("Actual Total Time", NULL, total_sec, 3, es); |
| 160 | ++ } |
| 161 | ++ else |
| 162 | ++ ExplainPropertyFloat("Running Time", NULL, total_sec, 3, es); |
| 163 | ++ } |
| 164 | ++ ExplainPropertyFloat("Actual Rows", NULL, rows, 0, es); |
| 165 | ++ } |
| 166 | ++ ExplainCloseGroup("Current loop", "Current loop", true, es); |
| 167 | ++ } |
| 168 | ++ } |
| 169 | ++ |
| 170 | + /* in text format, first line ends here */ |
| 171 | + if (es->format == EXPLAIN_FORMAT_TEXT) |
| 172 | + appendStringInfoChar(es->str, '\n'); |
| 173 | +@@ -2416,6 +2510,9 @@ ExplainNode(PlanState *planstate, List *ancestors, |
| 174 | + |
| 175 | + /* Prepare per-worker buffer/WAL usage */ |
| 176 | + if (es->workers_state && (es->buffers || es->wal) && es->verbose) |
| 177 | ++ /* Show worker detail after query execution */ |
| 178 | ++ if (es->analyze && es->verbose && planstate->worker_instrument |
| 179 | ++ && !es->runtime) |
| 180 | + { |
| 181 | + WorkerInstrumentation *w = planstate->worker_instrument; |
| 182 | + |
| 183 | +@@ -3403,6 +3500,11 @@ show_hash_info(HashState *hashstate, ExplainState *es) |
| 184 | + memcpy(&hinstrument, hashstate->hinstrument, |
| 185 | + sizeof(HashInstrumentation)); |
| 186 | + |
| 187 | ++ if (hashstate->hashtable) |
| 188 | ++ { |
| 189 | ++ ExecHashAccumInstrumentation(&hinstrument, hashstate->hashtable); |
| 190 | ++ } |
| 191 | ++ |
| 192 | + /* |
| 193 | + * Merge results from workers. In the parallel-oblivious case, the |
| 194 | + * results from all participants should be identical, except where |
| 195 | +@@ -3937,20 +4039,16 @@ show_instrumentation_count(const char *qlabel, int which, |
| 196 | + if (!es->analyze || !planstate->instrument) |
| 197 | + return; |
| 198 | + |
| 199 | ++ nloops = planstate->instrument->nloops; |
| 200 | + if (which == 2) |
| 201 | +- nfiltered = planstate->instrument->nfiltered2; |
| 202 | ++ nfiltered = ((nloops > 0) ? planstate->instrument->nfiltered2 / nloops : 0); |
| 203 | + else |
| 204 | +- nfiltered = planstate->instrument->nfiltered1; |
| 205 | ++ nfiltered = ((nloops > 0) ? planstate->instrument->nfiltered1 / nloops : 0); |
| 206 | + nloops = planstate->instrument->nloops; |
| 207 | + |
| 208 | + /* In text mode, suppress zero counts; they're not interesting enough */ |
| 209 | + if (nfiltered > 0 || es->format != EXPLAIN_FORMAT_TEXT) |
| 210 | +- { |
| 211 | +- if (nloops > 0) |
| 212 | +- ExplainPropertyFloat(qlabel, NULL, nfiltered / nloops, 0, es); |
| 213 | +- else |
| 214 | +- ExplainPropertyFloat(qlabel, NULL, 0.0, 0, es); |
| 215 | +- } |
| 216 | ++ ExplainPropertyFloat(qlabel, NULL, nfiltered, 0, es); |
| 217 | + } |
| 218 | + |
| 219 | + /* |
| 220 | +@@ -4617,15 +4715,27 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors, |
| 221 | + double insert_path; |
| 222 | + double other_path; |
| 223 | + |
| 224 | +- InstrEndLoop(outerPlanState(mtstate)->instrument); |
| 225 | ++ if (!es->runtime) |
| 226 | ++ InstrEndLoop(outerPlanState(mtstate)->instrument); |
| 227 | + |
| 228 | + /* count the number of source rows */ |
| 229 | +- total = outerPlanState(mtstate)->instrument->ntuples; |
| 230 | + other_path = mtstate->ps.instrument->ntuples2; |
| 231 | +- insert_path = total - other_path; |
| 232 | + |
| 233 | +- ExplainPropertyFloat("Tuples Inserted", NULL, |
| 234 | +- insert_path, 0, es); |
| 235 | ++ /* |
| 236 | ++ * Insert occurs after extracting row from subplan and in runtime mode |
| 237 | ++ * we can appear between these two operations - situation when |
| 238 | ++ * total > insert_path + other_path. Therefore we don't know exactly |
| 239 | ++ * whether last row from subplan is inserted. |
| 240 | ++ * We don't print inserted tuples in runtime mode in order to not print |
| 241 | ++ * inconsistent data |
| 242 | ++ */ |
| 243 | ++ if (!es->runtime) |
| 244 | ++ { |
| 245 | ++ total = outerPlanState(mtstate)->instrument->ntuples; |
| 246 | ++ insert_path = total - other_path; |
| 247 | ++ ExplainPropertyFloat("Tuples Inserted", NULL, insert_path, 0, es); |
| 248 | ++ } |
| 249 | ++ |
| 250 | + ExplainPropertyFloat("Conflicting Tuples", NULL, |
| 251 | + other_path, 0, es); |
| 252 | + } |
| 253 | +diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h |
| 254 | +index 3ab0aae78f7..3644c0db116 100644 |
| 255 | +--- a/src/include/commands/explain.h |
| 256 | ++++ b/src/include/commands/explain.h |
| 257 | +@@ -57,6 +57,8 @@ typedef struct ExplainState |
| 258 | + bool generic; /* generate a generic plan */ |
| 259 | + ExplainSerializeOption serialize; /* serialize the query's output? */ |
| 260 | + ExplainFormat format; /* output format */ |
| 261 | ++ bool runtime; /* print intermediate state of query execution, |
| 262 | ++ not after completion */ |
| 263 | + /* state for output formatting --- not reset for each new plan tree */ |
| 264 | + int indent; /* current indentation level */ |
| 265 | + List *grouping_stack; /* format-specific grouping state */ |
0 commit comments