Parallel stats in execution plans
Hi folks -
I'm having trouble understanding what some of the stats mean in the
execution plan output when parallel workers are used. I've tried to read
up about it, but I haven't been able to find anything that explains what
I'm seeing. Apologies in advance if there's documentation I've been too
stupid to find.
I've run the following query. The "towns" table is a massive table that
I created in order to get some big numbers on a parallel query - don't
worry, this isn't a real query I want to make faster, just a silly
example I'd like to understand.
EXPLAIN (ANALYZE, FORMAT JSON, BUFFERS, VERBOSE)
SELECT name, code, article
FROM towns
ORDER BY nameASC,
codeDESC;
The output looks like this:
[
{
"Plan": {
"Node Type": "Gather Merge", "Parallel Aware": false, "Startup Cost":
1013948.54, "Total Cost": 1986244.55, "Plan Rows": 884, "Plan
Width": 77, "Actual Startup Time": 42978.838, "Actual Total Time":
60628.982, "Actual Rows": 1010, "Actual Loops": 1, "Output": ["name", "code", "article"], "Workers Planned": 2, "Workers Launched": 2, "Shared Hit Blocks": 29,
"Shared Read Blocks": 47641, "Shared Dirtied Blocks": 0, "Shared Written
Blocks": 0, "Local Hit Blocks": 0, "Local Read Blocks": 0, "Local
Dirtied Blocks": 0, "Local Written Blocks": 0, "Temp Read Blocks":
91342, "Temp Written Blocks": 91479, "Plans": [
{
"Node Type": "Sort", "Parent Relationship": "Outer", "Parallel Aware":
false, "Startup Cost": 1012948.52, "Total Cost": 1023365.25, "Plan
Rows": 4166692, "Plan Width": 77, "Actual Startup Time": 42765.496,
"Actual Total Time": 48526.168, "Actual Rows": 337, "Actual Loops":
3, "Output": ["name", "code", "article"], "Sort Key": ["towns.name", "towns.code DESC"], "Sort Method": "external merge", "Sort Space Used": 283856, "Sort
Space Type": "Disk", "Shared Hit Blocks": 170, "Shared Read Blocks":
142762, "Shared Dirtied Blocks": 0, "Shared Written Blocks": 0, "Local
Hit Blocks": 0, "Local Read Blocks": 0, "Local Dirtied Blocks": 0,
"Local Written Blocks": 0, "Temp Read Blocks": 273289, "Temp Written
Blocks": 273700, "Workers": [
{
"Worker Number": 0, "Actual Startup Time": 42588.662, "Actual Total
Time": 48456.662, "Actual Rows": 3277980, "Actual Loops": 1, "Shared Hit
Blocks": 72, "Shared Read Blocks": 46794, "Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0, "Local Hit Blocks": 0, "Local Read Blocks":
0, "Local Dirtied Blocks": 0, "Local Written Blocks": 0, "Temp Read
Blocks": 89067, "Temp Written Blocks": 89202 }, {
"Worker Number": 1, "Actual Startup Time": 42946.705, "Actual Total
Time": 48799.414, "Actual Rows": 3385130, "Actual Loops": 1, "Shared Hit
Blocks": 69, "Shared Read Blocks": 48327, "Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0, "Local Hit Blocks": 0, "Local Read Blocks":
0, "Local Dirtied Blocks": 0, "Local Written Blocks": 0, "Temp Read
Blocks": 92880, "Temp Written Blocks": 93019 }
], "Plans": [
{
"Node Type": "Seq Scan", "Parent Relationship": "Outer", "Parallel
Aware": true, "Relation Name": "towns", "Schema": "public", "Alias":
"towns", "Startup Cost": 0.00, "Total Cost": 184524.92, "Plan Rows":
4166692, "Plan Width": 77, "Actual Startup Time": 0.322, "Actual Total
Time": 8305.886, "Actual Rows": 337, "Actual Loops": 3, "Output": ["name", "code", "article"], "Shared Hit Blocks": 96, "Shared Read Blocks": 142762, "Shared Dirtied
Blocks": 0, "Shared Written Blocks": 0, "Local Hit Blocks": 0, "Local
Read Blocks": 0, "Local Dirtied Blocks": 0, "Local Written Blocks": 0,
"Temp Read Blocks": 0, "Temp Written Blocks": 0, "Workers": [
{
"Worker Number": 0, "Actual Startup Time": 0.105, "Actual Total Time":
8394.629, "Actual Rows": 3277980, "Actual Loops": 1, "Shared Hit
Blocks": 35, "Shared Read Blocks": 46794, "Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0, "Local Hit Blocks": 0, "Local Read Blocks":
0, "Local Dirtied Blocks": 0, "Local Written Blocks": 0, "Temp Read
Blocks": 0, "Temp Written Blocks": 0 }, {
"Worker Number": 1, "Actual Startup Time": 0.113, "Actual Total Time":
8139.382, "Actual Rows": 3385130, "Actual Loops": 1, "Shared Hit
Blocks": 32, "Shared Read Blocks": 48327, "Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0, "Local Hit Blocks": 0, "Local Read Blocks":
0, "Local Dirtied Blocks": 0, "Local Written Blocks": 0, "Temp Read
Blocks": 0, "Temp Written Blocks": 0 }
]
}
]
}
]
}, "Planning Time": 22.898, "Triggers": [
], "Execution Time": 61133.161 }
]
Or a more slimmed-down version, with just the confusing fields:
[
{
"Plan": {
"Node Type": "Gather Merge", "Parallel Aware": false,"Actual Total
Time": 60628.982, "Actual Rows": 1010, "Actual Loops": 1,"Workers
Planned": 2, "Workers Launched": 2,"Plans": [
{
"Node Type": "Sort"
Re: Parallel stats in execution plans
It seems like no-one has any ideas on this - does anyone know anywhere
else I can try to look/ask to find out more?
Is it possible that this is a bug?
Thanks
Dave
On 16/01/2019 11:31, David Conlin wrote:
Hi folks -
I'm having trouble understanding what some of the stats mean in the
execution plan output when parallel workers are used. I've tried to
read up about it, but I haven't been able to find anything that
explains what I'm seeing. Apologies in advance if there's
documentation I've been too stupid to find.
I've run the following query. The "towns" table is a massive table
that I created in order to get some big numbers on a parallel query -
don't worry, this isn't a real query I want to make faster, just a
silly example I'd like to understand.
EXPLAIN (ANALYZE, FORMAT JSON, BUFFERS, VERBOSE)
SELECT name, code, article
FROM towns
ORDER BY nameASC,
codeDESC;
The output looks like this:
[
{
"Plan": {
"Node Type": "Gather Merge", "Parallel Aware": false, "Startup Cost":
1013948.54, "Total Cost": 1986244.55, "Plan Rows": 884, "Plan
Width": 77, "Actual Startup Time": 42978.838, "Actual Total Time":
60628.982, "Actual Rows": 1010, "Actual Loops": 1, "Output": ["name", "code", "article"], "Workers Planned": 2, "Workers Launched": 2, "Shared Hit Blocks":
29, "Shared Read Blocks": 47641, "Shared Dirtied Blocks": 0, "Shared
Written Blocks": 0, "Local Hit Blocks": 0, "Local Read Blocks": 0,
"Local Dirtied Blocks": 0, "Local Written Blocks": 0, "Temp Read
Blocks": 91342, "Temp Written Blocks": 91479, "Plans": [
{
"Node Type": "Sort", "Parent Relationship": "Outer", "Parallel Aware":
false, "Startup Cost": 1012948.52, "Total Cost": 1023365.25, "Plan
Rows": 4166692, "Plan Width": 77, "Actual Startup Time": 42765.496,
"Actual Total Time": 48526.168, "Actual Rows": 337, "Actual
Loops": 3, "Output": ["name", "code", "article"], "Sort Key": ["towns.name", "towns.code DESC"], "Sort Method": "external merge", "Sort Space Used": 283856, "Sort
Space Type": "Disk", "Shared Hit Blocks": 170, "Shared Read Blocks":
142762, "Shared Dirtied Blocks": 0, "Shared Written Blocks": 0, "Local
Hit Blocks": 0, "Local Read Blocks": 0, "Local Dirtied Blocks": 0,
"Local Written Blocks": 0, "Temp Read Blocks": 273289, "Temp Written
Blocks": 273700, "Workers": [
{
"Worker Number": 0, "Actual Startup Time": 42588.662, "Actual Total
Time": 48456.662, "Actual Rows": 3277980, "Actual Loops": 1, "Shared
Hit Blocks": 72, "Shared Read Blocks": 46794, "Shared Dirtied Blocks":
0, "Shared Written Blocks": 0, "Local Hit Blocks": 0, "Local Read
Blocks": 0, "Local Dirtied Blocks": 0, "Local Written Blocks": 0,
"Temp Read Blocks": 89067, "Temp Written Blocks": 89202 }, {
"Worker Number": 1, "Actual Startup Time": 42946.705, "Actual Total
Time": 48799.414, "Actual Rows": 3385130, "Actual Loops": 1, "Shared
Hit Blocks": 69, "Shared Read Blocks": 48327, "Shared Dirtied Blocks":
0, "Shared Written Blocks": 0, "Local Hit Blocks": 0, "Local Read
Blocks": 0, "Local Dirtied Blocks": 0, "Local Written Blocks": 0,
"Temp Read Blocks": 92880, "Temp Written Blocks": 93019 }
], "Plans": [
{
"Node Type": "Seq Scan", "Parent Relationship": "Outer", "Parallel
Aware": true, "Relation Name": "towns", "Schema": "public", "Alias":
"towns", "Startup Cost": 0.00, "Total Cost": 184524.92, "Plan Rows":
4166692, "Plan Width": 77, "Actual Startup Time": 0.322, "Actual Total
Time": 8305.886, "Actual Rows": 337, "Actual Loops": 3, "Output": ["name", "code", "article"], "Shared Hit Blocks": 96, "Shared Read Blocks": 142762, "Shared
Dirtied Blocks&
Change in CTE treatment in query plans?
Hi folks - Does anyone know if there's been a change in the way values for CTEs are displayed in query plans? I think that it used to be the case that, for keys that include the values of child nodes values (eg "Shared Hit Blocks", or "Actual Total Time"), CTE scans included the CTE itself, even if it wasn't included as one of its children in the plan. If you didn't subtract the CTE scan, you would see surprising things, like sort operations reading table data, or the total time of the nodes in a single-threaded query plan adding up to significantly more than 100% of the total query time. Now (I think since v11, but I'm not sure), it looks like these values only include the children listed in the plan. For example, I've seen CTE scans that have smaller times and buffers values than the CTE itself, which couldn't be true if the CTE was included in the scan. I'm much less sure, but I *think* the same is also true of other InitPlan nodes - for example, if a node includes the filter "value > $1", its time and buffers used to (but no longer does) include the total for the InitPlan node which returned the value "$1". Am I way off base with this, or did this change happen, and if so, am I right in thinking that it was changed in v11? Thanks in advance Dave
Re: Change in CTE treatment in query plans?
Hi Tom - Thanks so much for getting back to me. I didn't realise that the costs of init/sub plans would be spread across the call sites - I had (stupidly) assumed that each call site would include the full cost. Having taken a couple of days to go back over the problems I was seeing, you were absolutely right - it was all to do with multiple call sites - the postgres version was just a red herring. Thanks for your help & all the best, Dave On 17/10/2019 10:04, Tom Lane wrote: David Conlin writes: Does anyone know if there's been a change in the way values for CTEs are displayed in query plans? Offhand I don't recall any such changes, nor does a cursory look through explain.c find anything promising. If you're concerned with a multiply-referenced CTE, one possibility for funny results is that the blame for its execution cost could be spread across the multiple call sites. The same can happen with initplans/subplans. But I'm just guessing; you didn't show any concrete examples so it's hard to be definite. regards, tom lane
