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

Commitb287df7

Browse files
committed
Allow EXPLAIN (ANALYZE, VERBOSE) to display per-worker statistics.
The original parallel sequential scan commit included only very limitedchanges to the EXPLAIN output. Aggregated totals from all workers weredisplayed, but there was no way to see what each individual worker didor to distinguish the effort made by the workers from the effort made bythe leader.Per a gripe by Thom Brown (and maybe others). Patch by me, reviewedby Amit Kapila.
1 parent25c5392 commitb287df7

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
staticvoidshow_foreignscan_info(ForeignScanState*fsstate,ExplainState*es);
105105
staticconstchar*explain_get_index_name(OidindexId);
106+
staticvoidshow_buffer_usage(ExplainState*es,constBufferUsage*usage);
106107
staticvoidExplainIndexScanDetails(Oidindexid,ScanDirectionindexorderdir,
107108
ExplainState*es);
108109
staticvoidExplainScanTarget(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-
constBufferUsage*usage=&planstate->instrument->bufusage;
1446+
WorkerInstrumentation*w=planstate->worker_instrument;
1447+
boolopened_group= false;
1448+
intn;
14421449

1443-
if (es->format==EXPLAIN_FORMAT_TEXT)
1450+
for (n=0;n<w->num_workers;++n)
14441451
{
1445-
boolhas_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-
boolhas_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-
boolhas_temp= (usage->temp_blks_read>0||
1454-
usage->temp_blks_written>0);
1455-
boolhas_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+
doublenloops=instrument->nloops;
1454+
doublestartup_sec;
1455+
doubletotal_sec;
1456+
doublerows;
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
returnresult;
22772243
}
22782244

2245+
/*
2246+
* Show buffer usage details.
2247+
*/
2248+
staticvoid
2249+
show_buffer_usage(ExplainState*es,constBufferUsage*usage)
2250+
{
2251+
if (es->format==EXPLAIN_FORMAT_TEXT)
2252+
{
2253+
boolhas_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+
boolhas_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+
boolhas_temp= (usage->temp_blks_read>0||
2262+
usage->temp_blks_written>0);
2263+
boolhas_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)
[8]ページ先頭
©2009-2025 Movatter.jp