Skip to content

Commit b287df7

Browse files
robertmhaasrobertmhaas
committed
Allow EXPLAIN (ANALYZE, VERBOSE) to display per-worker statistics.
The original parallel sequential scan commit included only very limited changes to the EXPLAIN output. Aggregated totals from all workers were displayed, but there was no way to see what each individual worker did or to distinguish the effort made by the workers from the effort made by the leader. Per a gripe by Thom Brown (and maybe others). Patch by me, reviewed by Amit Kapila.
1 parent 25c5392 commit b287df7

File tree

4 files changed

+226
-130
lines changed

4 files changed

+226
-130
lines changed

‎src/backend/commands/explain.c‎

Lines changed: 162 additions & 89 deletions
Original file line numberDiff line numberDiff line change
@@ -103,6 +103,7 @@ static void show_instrumentation_count(const char *qlabel, int which,
103103
PlanState *planstate, ExplainState *es);
104104
static void show_foreignscan_info(ForeignScanState *fsstate, ExplainState *es);
105105
static const char *explain_get_index_name(Oid indexId);
106+
static void show_buffer_usage(ExplainState *es, const BufferUsage *usage);
106107
static void ExplainIndexScanDetails(Oid indexid, ScanDirection indexorderdir,
107108
ExplainState *es);
108109
static void ExplainScanTarget(Scan *plan, ExplainState *es);
@@ -1437,108 +1438,73 @@ ExplainNode(PlanState *planstate, List *ancestors,
14371438

14381439
/* Show buffer usage */
14391440
if (es->buffers && planstate->instrument)
1441+
show_buffer_usage(es, &planstate->instrument->bufusage);
1442+
1443+
/* Show worker detail */
1444+
if (es->analyze && es->verbose && planstate->worker_instrument)
14401445
{
1441-
const BufferUsage *usage = &planstate->instrument->bufusage;
1446+
WorkerInstrumentation *w = planstate->worker_instrument;
1447+
bool opened_group = false;
1448+
int n;
14421449

1443-
if (es->format == EXPLAIN_FORMAT_TEXT)
1450+
for (n = 0; n < w->num_workers; ++n)
14441451
{
1445-
bool has_shared = (usage->shared_blks_hit > 0 ||
1446-
usage->shared_blks_read > 0 ||
1447-
usage->shared_blks_dirtied > 0 ||
1448-
usage->shared_blks_written > 0);
1449-
bool has_local = (usage->local_blks_hit > 0 ||
1450-
usage->local_blks_read > 0 ||
1451-
usage->local_blks_dirtied > 0 ||
1452-
usage->local_blks_written > 0);
1453-
bool has_temp = (usage->temp_blks_read > 0 ||
1454-
usage->temp_blks_written > 0);
1455-
bool has_timing = (!INSTR_TIME_IS_ZERO(usage->blk_read_time) ||
1456-
!INSTR_TIME_IS_ZERO(usage->blk_write_time));
1452+
Instrumentation *instrument = &w->instrument[n];
1453+
double nloops = instrument->nloops;
1454+
double startup_sec;
1455+
double total_sec;
1456+
double rows;
1457+
1458+
if (nloops <= 0)
1459+
continue;
1460+
startup_sec = 1000.0 * instrument->startup / nloops;
1461+
total_sec = 1000.0 * instrument->total / nloops;
1462+
rows = instrument->ntuples / nloops;
14571463

1458-
/* Show only positive counter values. */
1459-
if (has_shared || has_local || has_temp)
1464+
if (es->format == EXPLAIN_FORMAT_TEXT)
14601465
{
14611466
appendStringInfoSpaces(es->str, es->indent * 2);
1462-
appendStringInfoString(es->str, "Buffers:");
1463-
1464-
if (has_shared)
1465-
{
1466-
appendStringInfoString(es->str, " shared");
1467-
if (usage->shared_blks_hit > 0)
1468-
appendStringInfo(es->str, " hit=%ld",
1469-
usage->shared_blks_hit);
1470-
if (usage->shared_blks_read > 0)
1471-
appendStringInfo(es->str, " read=%ld",
1472-
usage->shared_blks_read);
1473-
if (usage->shared_blks_dirtied > 0)
1474-
appendStringInfo(es->str, " dirtied=%ld",
1475-
usage->shared_blks_dirtied);
1476-
if (usage->shared_blks_written > 0)
1477-
appendStringInfo(es->str, " written=%ld",
1478-
usage->shared_blks_written);
1479-
if (has_local || has_temp)
1480-
appendStringInfoChar(es->str, ',');
1481-
}
1482-
if (has_local)
1467+
appendStringInfo(es->str, "Worker %d: ", n);
1468+
if (es->timing)
1469+
appendStringInfo(es->str,
1470+
"actual time=%.3f..%.3f rows=%.0f loops=%.0f\n",
1471+
startup_sec, total_sec, rows, nloops);
1472+
else
1473+
appendStringInfo(es->str,
1474+
"actual rows=%.0f loops=%.0f\n",
1475+
rows, nloops);
1476+
es->indent++;
1477+
if (es->buffers)
1478+
show_buffer_usage(es, &instrument->bufusage);
1479+
es->indent--;
1480+
}
1481+
else
1482+
{
1483+
if (!opened_group)
14831484
{
1484-
appendStringInfoString(es->str, " local");
1485-
if (usage->local_blks_hit > 0)
1486-
appendStringInfo(es->str, " hit=%ld",
1487-
usage->local_blks_hit);
1488-
if (usage->local_blks_read > 0)
1489-
appendStringInfo(es->str, " read=%ld",
1490-
usage->local_blks_read);
1491-
if (usage->local_blks_dirtied > 0)
1492-
appendStringInfo(es->str, " dirtied=%ld",
1493-
usage->local_blks_dirtied);
1494-
if (usage->local_blks_written > 0)
1495-
appendStringInfo(es->str, " written=%ld",
1496-
usage->local_blks_written);
1497-
if (has_temp)
1498-
appendStringInfoChar(es->str, ',');
1485+
ExplainOpenGroup("Workers", "Workers", false, es);
1486+
opened_group = true;
14991487
}
1500-
if (has_temp)
1488+
ExplainOpenGroup("Worker", NULL, true, es);
1489+
ExplainPropertyInteger("Worker Number", n, es);
1490+
1491+
if (es->timing)
15011492
{
1502-
appendStringInfoString(es->str, " temp");
1503-
if (usage->temp_blks_read > 0)
1504-
appendStringInfo(es->str, " read=%ld",
1505-
usage->temp_blks_read);
1506-
if (usage->temp_blks_written > 0)
1507-
appendStringInfo(es->str, " written=%ld",
1508-
usage->temp_blks_written);
1493+
ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
1494+
ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
15091495
}
1510-
appendStringInfoChar(es->str, '\n');
1511-
}
1496+
ExplainPropertyFloat("Actual Rows", rows, 0, es);
1497+
ExplainPropertyFloat("Actual Loops", nloops, 0, es);
15121498

1513-
/* As above, show only positive counter values. */
1514-
if (has_timing)
1515-
{
1516-
appendStringInfoSpaces(es->str, es->indent * 2);
1517-
appendStringInfoString(es->str, "I/O Timings:");
1518-
if (!INSTR_TIME_IS_ZERO(usage->blk_read_time))
1519-
appendStringInfo(es->str, " read=%0.3f",
1520-
INSTR_TIME_GET_MILLISEC(usage->blk_read_time));
1521-
if (!INSTR_TIME_IS_ZERO(usage->blk_write_time))
1522-
appendStringInfo(es->str, " write=%0.3f",
1523-
INSTR_TIME_GET_MILLISEC(usage->blk_write_time));
1524-
appendStringInfoChar(es->str, '\n');
1499+
if (es->buffers)
1500+
show_buffer_usage(es, &instrument->bufusage);
1501+
1502+
ExplainCloseGroup("Worker", NULL, true, es);
15251503
}
15261504
}
1527-
else
1528-
{
1529-
ExplainPropertyLong("Shared Hit Blocks", usage->shared_blks_hit, es);
1530-
ExplainPropertyLong("Shared Read Blocks", usage->shared_blks_read, es);
1531-
ExplainPropertyLong("Shared Dirtied Blocks", usage->shared_blks_dirtied, es);
1532-
ExplainPropertyLong("Shared Written Blocks", usage->shared_blks_written, es);
1533-
ExplainPropertyLong("Local Hit Blocks", usage->local_blks_hit, es);
1534-
ExplainPropertyLong("Local Read Blocks", usage->local_blks_read, es);
1535-
ExplainPropertyLong("Local Dirtied Blocks", usage->local_blks_dirtied, es);
1536-
ExplainPropertyLong("Local Written Blocks", usage->local_blks_written, es);
1537-
ExplainPropertyLong("Temp Read Blocks", usage->temp_blks_read, es);
1538-
ExplainPropertyLong("Temp Written Blocks", usage->temp_blks_written, es);
1539-
ExplainPropertyFloat("I/O Read Time", INSTR_TIME_GET_MILLISEC(usage->blk_read_time), 3, es);
1540-
ExplainPropertyFloat("I/O Write Time", INSTR_TIME_GET_MILLISEC(usage->blk_write_time), 3, es);
1541-
}
1505+
1506+
if (opened_group)
1507+
ExplainCloseGroup("Workers", "Workers", false, es);
15421508
}
15431509

15441510
/* Get ready to display the child plans */
@@ -2276,6 +2242,113 @@ explain_get_index_name(Oid indexId)
22762242
return result;
22772243
}
22782244

2245+
/*
2246+
* Show buffer usage details.
2247+
*/
2248+
static void
2249+
show_buffer_usage(ExplainState *es, const BufferUsage *usage)
2250+
{
2251+
if (es->format == EXPLAIN_FORMAT_TEXT)
2252+
{
2253+
bool has_shared = (usage->shared_blks_hit > 0 ||
2254+
usage->shared_blks_read > 0 ||
2255+
usage->shared_blks_dirtied > 0 ||
2256+
usage->shared_blks_written > 0);
2257+
bool has_local = (usage->local_blks_hit > 0 ||
2258+
usage->local_blks_read > 0 ||
2259+
usage->local_blks_dirtied > 0 ||
2260+
usage->local_blks_written > 0);
2261+
bool has_temp = (usage->temp_blks_read > 0 ||
2262+
usage->temp_blks_written > 0);
2263+
bool has_timing = (!INSTR_TIME_IS_ZERO(usage->blk_read_time) ||
2264+
!INSTR_TIME_IS_ZERO(usage->blk_write_time));
2265+
2266+
/* Show only positive counter values. */
2267+
if (has_shared || has_local || has_temp)
2268+
{
2269+
appendStringInfoSpaces(es->str, es->indent * 2);
2270+
appendStringInfoString(es->str, "Buffers:");
2271+
2272+
if (has_shared)
2273+
{
2274+
appendStringInfoString(es->str, " shared");
2275+
if (usage->shared_blks_hit > 0)
2276+
appendStringInfo(es->str, " hit=%ld",
2277+
usage->shared_blks_hit);
2278+
if (usage->shared_blks_read > 0)
2279+
appendStringInfo(es->str, " read=%ld",
2280+
usage->shared_blks_read);
2281+
if (usage->shared_blks_dirtied > 0)
2282+
appendStringInfo(es->str, " dirtied=%ld",
2283+
usage->shared_blks_dirtied);
2284+
if (usage->shared_blks_written > 0)
2285+
appendStringInfo(es->str, " written=%ld",
2286+
usage->shared_blks_written);
2287+
if (has_local || has_temp)
2288+
appendStringInfoChar(es->str, ',');
2289+
}
2290+
if (has_local)
2291+
{
2292+
appendStringInfoString(es->str, " local");
2293+
if (usage->local_blks_hit > 0)
2294+
appendStringInfo(es->str, " hit=%ld",
2295+
usage->local_blks_hit);
2296+
if (usage->local_blks_read > 0)
2297+
appendStringInfo(es->str, " read=%ld",
2298+
usage->local_blks_read);
2299+
if (usage->local_blks_dirtied > 0)
2300+
appendStringInfo(es->str, " dirtied=%ld",
2301+
usage->local_blks_dirtied);
2302+
if (usage->local_blks_written > 0)
2303+
appendStringInfo(es->str, " written=%ld",
2304+
usage->local_blks_written);
2305+
if (has_temp)
2306+
appendStringInfoChar(es->str, ',');
2307+
}
2308+
if (has_temp)
2309+
{
2310+
appendStringInfoString(es->str, " temp");
2311+
if (usage->temp_blks_read > 0)
2312+
appendStringInfo(es->str, " read=%ld",
2313+
usage->temp_blks_read);
2314+
if (usage->temp_blks_written > 0)
2315+
appendStringInfo(es->str, " written=%ld",
2316+
usage->temp_blks_written);
2317+
}
2318+
appendStringInfoChar(es->str, '\n');
2319+
}
2320+
2321+
/* As above, show only positive counter values. */
2322+
if (has_timing)
2323+
{
2324+
appendStringInfoSpaces(es->str, es->indent * 2);
2325+
appendStringInfoString(es->str, "I/O Timings:");
2326+
if (!INSTR_TIME_IS_ZERO(usage->blk_read_time))
2327+
appendStringInfo(es->str, " read=%0.3f",
2328+
INSTR_TIME_GET_MILLISEC(usage->blk_read_time));
2329+
if (!INSTR_TIME_IS_ZERO(usage->blk_write_time))
2330+
appendStringInfo(es->str, " write=%0.3f",
2331+
INSTR_TIME_GET_MILLISEC(usage->blk_write_time));
2332+
appendStringInfoChar(es->str, '\n');
2333+
}
2334+
}
2335+
else
2336+
{
2337+
ExplainPropertyLong("Shared Hit Blocks", usage->shared_blks_hit, es);
2338+
ExplainPropertyLong("Shared Read Blocks", usage->shared_blks_read, es);
2339+
ExplainPropertyLong("Shared Dirtied Blocks", usage->shared_blks_dirtied, es);
2340+
ExplainPropertyLong("Shared Written Blocks", usage->shared_blks_written, es);
2341+
ExplainPropertyLong("Local Hit Blocks", usage->local_blks_hit, es);
2342+
ExplainPropertyLong("Local Read Blocks", usage->local_blks_read, es);
2343+
ExplainPropertyLong("Local Dirtied Blocks", usage->local_blks_dirtied, es);
2344+
ExplainPropertyLong("Local Written Blocks", usage->local_blks_written, es);
2345+
ExplainPropertyLong("Temp Read Blocks", usage->temp_blks_read, es);
2346+
ExplainPropertyLong("Temp Written Blocks", usage->temp_blks_written, es);
2347+
ExplainPropertyFloat("I/O Read Time", INSTR_TIME_GET_MILLISEC(usage->blk_read_time), 3, es);
2348+
ExplainPropertyFloat("I/O Write Time", INSTR_TIME_GET_MILLISEC(usage->blk_write_time), 3, es);
2349+
}
2350+
}
2351+
22792352
/*
22802353
* Add some additional details about an IndexScan or IndexOnlyScan
22812354
*/

0 commit comments

Comments
 (0)