I have run an explain analyze query on my postgres database using pgAdmin.
It created a visualization with negative exclusive time:
I thought that total time of "Gather Merge" was lower than its child, "Group", but if I read raw postgres output correctly it is not true.
[
{
"Plan": {
"Node Type": "Result",
"Parallel Aware": false,
"Startup Cost": 5259558.14,
"Total Cost": 5259558.24,
"Plan Rows": 1,
"Plan Width": 2,
"Actual Startup Time": 2891.076,
"Actual Total Time": 2925.989,
"Actual Rows": 1,
"Actual Loops": 1,
"Output": [
"(SubPlan 2)",
"(SubPlan 3)"
],
"Shared Hit Blocks": 16,
"Shared Read Blocks": 605065,
"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,
"I/O Read Time": 1329.432,
"I/O Write Time": 0,
"Plans": [
{
"Node Type": "Group",
"Parent Relationship": "InitPlan",
"Subplan Name": "CTE foo",
"Parallel Aware": false,
"Startup Cost": 5255772.15,
"Total Cost": 5259558.14,
"Plan Rows": 4,
"Plan Width": 2,
"Actual Startup Time": 2851.957,
"Actual Total Time": 2925.973,
"Actual Rows": 3,
"Actual Loops": 1,
"Output": [
"\"DailyRatePricingTable\".\"HasFlatPrices\"",
"\"DailyRatePricingTable\".\"HasOccupancyPrices\""
],
"Group Key": [
"\"DailyRatePricingTable\".\"HasFlatPrices\"",
"\"DailyRatePricingTable\".\"HasOccupancyPrices\""
],
"Shared Hit Blocks": 16,
"Shared Read Blocks": 605065,
"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,
"I/O Read Time": 1329.432,
"I/O Write Time": 0,
"Plans": [
{
"Node Type": "Gather Merge",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Startup Cost": 5255772.15,
"Total Cost": 5259558.1,
"Plan Rows": 8,
"Plan Width": 2,
"Actual Startup Time": 2851.955,
"Actual Total Time": 2925.966,
"Actual Rows": 5,
"Actual Loops": 1,
"Output": [
"\"DailyRatePricingTable\".\"HasFlatPrices\"",
"\"DailyRatePricingTable\".\"HasOccupancyPrices\""
],
"Workers Planned": 2,
"Workers Launched": 2,
"Shared Hit Blocks": 16,
"Shared Read Blocks": 605065,
"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,
"I/O Read Time": 1329.432,
"I/O Write Time": 0,
"Plans": [
{
"Node Type": "Group",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Startup Cost": 5254772.12,
"Total Cost": 5258557.15,
"Plan Rows": 4,
"Plan Width": 2,
"Actual Startup Time": 2849.038,
"Actual Total Time": 2898.808,
"Actual Rows": 3,
"Actual Loops": 3,
"Output": [
"\"DailyRatePricingTable\".\"HasFlatPrices\"",
"\"DailyRatePricingTable\".\"HasOccupancyPrices\""
],
"Group Key": [
"\"DailyRatePricingTable\".\"HasFlatPrices\"",
"\"DailyRatePricingTable\".\"HasOccupancyPrices\""
],
"Shared Hit Blocks": 16,
"Shared Read Blocks": 605065,
"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,
"I/O Read Time": 1329.432,
"I/O Write Time": 0,
"Workers": [
{
"Worker Number": 0,
"Actual Startup Time": 2848.861,
"Actual Total Time": 2913.74,
"Actual Rows": 4,
"Actual Loops": 1,
"Shared Hit Blocks": 8,
"Shared Read Blocks": 40501,
"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,
"I/O Read Time": 92.497,
"I/O Write Time": 0
},
{
"Worker Number": 1,
"Actual Startup Time": 2847.78,
"Actual Total Time": 2912.523,
"Actual Rows": 3,
"Actual Loops": 1,
"Shared Hit Blocks": 8,
"Shared Read Blocks": 40588,
"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,
"I/O Read Time": 92.609,
"I/O Write Time": 0
}
],
"Plans": [
{
"Node Type": "Sort",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Startup Cost": 5254772.12,
"Total Cost": 5256033.8,
"Plan Rows": 504670,
"Plan Width": 2,
"Actual Startup Time": 2849.035,
"Actual Total Time": 2868.677,
"Actual Rows": 310993,
"Actual Loops": 3,
"Output": [
"\"DailyRatePricingTable\".\"HasFlatPrices\"",
"\"DailyRatePricingTable\".\"HasOccupancyPrices\""
],
"Sort Key": [
"\"DailyRatePricingTable\".\"HasFlatPrices\"",
"\"DailyRatePricingTable\".\"HasOccupancyPrices\""
],
"Sort Method": "quicksort",
"Sort Space Used": 31099,
"Sort Space Type": "Memory",
"Shared Hit Blocks": 16,
"Shared Read Blocks": 605065,
"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,
"I/O Read Time": 1329.432,
"I/O Write Time": 0,
"Workers": [
{
"Worker Number": 0,
"Actual Startup Time": 2848.858,
"Actual Total Time": 2874.257,
"Actual Rows": 403788,
"Actual Loops": 1,
"Sort Method": "quicksort",
"Sort Space Used": 31232,
"Sort Space Type": "Memory",
"Shared Hit Blocks": 8,
"Shared Read Blocks": 40501,
"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,
"I/O Read Time": 92.497,
"I/O Write Time": 0
},
{
"Worker Number": 1,
"Actual Startup Time": 2847.777,
"Actual Total Time": 2873.428,
"Actual Rows": 406553,
"Actual Loops": 1,
"Sort Method": "quicksort",
"Sort Space Used": 31361,
"Sort Space Type": "Memory",
"Shared Hit Blocks": 8,
"Shared Read Blocks": 40588,
"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,
"I/O Read Time": 92.609,
"I/O Write Time": 0
}
],
"Plans": [
{
"Node Type": "Bitmap Heap Scan",
"Parent Relationship": "Outer",
"Parallel Aware": true,
"Relation Name": "DailyRatePricingTable",
"Schema": "RateManager",
"Alias": "DailyRatePricingTable",
"Startup Cost": 2209995.05,
"Total Cost": 5206967.31,
"Plan Rows": 504670,
"Plan Width": 2,
"Actual Startup Time": 2486.18,
"Actual Total Time": 2779.302,
"Actual Rows": 404097,
"Actual Loops": 3,
"Output": [
"\"DailyRatePricingTable\".\"HasFlatPrices\"",
"\"DailyRatePricingTable\".\"HasOccupancyPrices\""
],
"Recheck Cond": "(\"DailyRatePricingTable\".\"TenantId\" = '3eb2f28c-67aa-405d-9821-c9fc59de1501'::uuid)",
"Rows Removed by Index Recheck": 0,
"Exact Heap Blocks": 40808,
"Lossy Heap Blocks": 0,
"Shared Hit Blocks": 0,
"Shared Read Blocks": 605065,
"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,
"I/O Read Time": 1329.432,
"I/O Write Time": 0,
"Workers": [
{
"Worker Number": 0,
"Actual Startup Time": 2485.217,
"Actual Total Time": 2779.164,
"Actual Rows": 404130,
"Actual Loops": 1,
"Shared Hit Blocks": 0,
"Shared Read Blocks": 40501,
"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,
"I/O Read Time": 92.497,
"I/O Write Time": 0
},
{
"Worker Number": 1,
"Actual Startup Time": 2485.342,
"Actual Total Time": 2779.53,
"Actual Rows": 406879,
"Actual Loops": 1,
"Shared Hit Blocks": 0,
"Shared Read Blocks": 40588,
"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,
"I/O Read Time": 92.609,
"I/O Write Time": 0
}
],
"Plans": [
{
"Node Type": "Bitmap Index Scan",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Index Name": "PK_DailyRatePricingTable",
"Startup Cost": 0,
"Total Cost": 2209692.25,
"Plan Rows": 1211208,
"Plan Width": 0,
"Actual Startup Time": 2459.404,
"Actual Total Time": 2459.404,
"Actual Rows": 1213885,
"Actual Loops": 1,
"Index Cond": "(\"DailyRatePricingTable\".\"TenantId\" = '3eb2f28c-67aa-405d-9821-c9fc59de1501'::uuid)",
"Shared Hit Blocks": 0,
"Shared Read Blocks": 483154,
"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,
"I/O Read Time": 1048.699,
"I/O Write Time": 0,
"Workers": []
}
]
}
]
}
]
}
]
}
]
},
{
"Node Type": "CTE Scan",
"Parent Relationship": "SubPlan",
"Subplan Name": "SubPlan 2",
"Parallel Aware": false,
"CTE Name": "foo",
"Alias": "foo",
"Startup Cost": 0,
"Total Cost": 0.08,
"Plan Rows": 4,
"Plan Width": 1,
"Actual Startup Time": 2851.959,
"Actual Total Time": 2891.068,
"Actual Rows": 3,
"Actual Loops": 1,
"Output": [
"foo.\"HasFlatPrices\""
],
"Shared Hit Blocks": 0,
"Shared Read Blocks": 523976,
"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,
"I/O Read Time": 1144.327,
"I/O Write Time": 0
},
{
"Node Type": "CTE Scan",
"Parent Relationship": "SubPlan",
"Subplan Name": "SubPlan 3",
"Parallel Aware": false,
"CTE Name": "foo",
"Alias": "foo_1",
"Startup Cost": 0,
"Total Cost": 0.08,
"Plan Rows": 4,
"Plan Width": 1,
"Actual Startup Time": 0.001,
"Actual Total Time": 0.001,
"Actual Rows": 2,
"Actual Loops": 1,
"Output": [
"foo_1.\"HasOccupancyPrices\""
],
"Shared Hit Blocks": 0,
"Shared Read Blocks": 0,
"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,
"I/O Read Time": 0,
"I/O Write Time": 0
}
]
},
"Planning": {
"Shared Hit Blocks": 3,
"Shared Read Blocks": 0,
"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,
"I/O Read Time": 0,
"I/O Write Time": 0
},
"Triggers": []
}
]
Is there any reasonable explanation for this? Can pgAdmin visualization be trusted?
There is a similar question In pgadmin EXPLAIN ANALYSE , exclusive vs inclusive but I don't see that negative values are explained there.
PostgreSQL 13.3 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 7.3.1 20180712 (Red Hat 7.3.1-6), 64-bit
PgAdmin 4.16
CodePudding user response：
That's a pgAdmin bug
pgAdmin blindly multiplies the execution time with the loop count, which is fine for nested loops, but wrong for parallel operations. So the numbers below the “Gather” are too high by a factor of three.