Explain analyze: Total time spent executing a task. Documentation error or my error?Explain plan issue with group by clause in postgresql 8.4Explain MySQL explain execution plan maths, difference between two plansPostgreSQL Simple JOIN very slowImprove PostgreSQL query performanceDISTINCT INNER JOIN slowWhy is select faster than a function call?long running query PostgreSQLHow to force a merge join?How to optimize a MAX SQL query with GROUP BY DATEPossible Indexing Question? - How do I increase query speed?
What's the difference between DHCP and NAT? Are they mutually exclusive?
Mathematica 12 has gotten worse at solving simple equations?
What is the logic behind charging tax _in the form of money_ for owning property when the property does not produce money?
If absolute velocity does not exist, how can we say a rocket accelerates in empty space?
What is Gilligan's full Name?
Why do I seem to lose data using this bash pipe construction?
How to Handle Many Times Series Simultaneously?
What is the theme of analysis?
When to use и or а as “and”?
Is it true that "only photographers care about noise"?
Was self-modifying code possible using BASIC?
How to generate list of *all* available commands and functions?
How to befriend someone who doesn't like to talk?
Are the guests in Westworld forbidden to tell the hosts that they are robots?
Is Jesus the last Prophet?
Professor Roman loves to teach unorthodox Chemistry
Why is my power MOSFET heating up when on?
My mom's return ticket is 3 days after I-94 expires
What is this Amiga 2000 mod?
What does "lit." mean in boiling point or melting point specification?
Oil draining out shortly after turbo hose detached/broke
How much web presence should I have?
In Pandemic, why take the extra step of eradicating a disease after you've cured it?
Part of my house is inexplicably gone
Explain analyze: Total time spent executing a task. Documentation error or my error?
Explain plan issue with group by clause in postgresql 8.4Explain MySQL explain execution plan maths, difference between two plansPostgreSQL Simple JOIN very slowImprove PostgreSQL query performanceDISTINCT INNER JOIN slowWhy is select faster than a function call?long running query PostgreSQLHow to force a merge join?How to optimize a MAX SQL query with GROUP BY DATEPossible Indexing Question? - How do I increase query speed?
.everyoneloves__top-leaderboard:empty,.everyoneloves__mid-leaderboard:empty,.everyoneloves__bot-mid-leaderboard:empty height:90px;width:728px;box-sizing:border-box;
I think found a mistake, and a possible correction, in the postgres documentation regarding explain plans.
From: https://www.postgresql.org/docs/current/using-explain.html
Index Scan using tenk2_unique2 on tenk2 t2 (cost=0.29..7.91 rows=1 width=244) (actual time=0.021..0.022 rows=1 loops=10)
"In the above example, we spent a total of 0.220 milliseconds executing the index scans on tenk2."
The docs would seem to indicate Actual Total Time * Actual Loops = total time spent on an operation.
However, from a JSON plan I produced:
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Join Type": "Inner",
"Startup Cost": 66575.34,
"Total Cost": 76861.82,
"Plan Rows": 407,
"Plan Width": 290,
"Actual Startup Time": 49962.789,
"Actual Total Time": 51206.643,
"Actual Rows": 127117,
"Actual Loops": 3,
"Output": [ ... ],
...
"Execution Time": 52677.398
(The complete plan is here.)
Actual Total Time * Actual Loops = 51 sec * 3 = 2 min 33 sec clearly exceeds the Execution Time of 52.7 seconds.
Am I understanding the documentation correctly?
If so, shouldn't it say, "we spent a total of 0.01 milliseconds executing the index scans on tenk2"?
postgresql sql-execution-plan explain
edited Mar 25 at 14:48
Laurenz Albe
56.7k113658
asked Mar 24 at 22:38
wmeitzenwmeitzen
417
|
show 6 more comments
I think found a mistake, and a possible correction, in the postgres documentation regarding explain plans.
From: https://www.postgresql.org/docs/current/using-explain.html
Index Scan using tenk2_unique2 on tenk2 t2 (cost=0.29..7.91 rows=1 width=244) (actual time=0.021..0.022 rows=1 loops=10)
"In the above example, we spent a total of 0.220 milliseconds executing the index scans on tenk2."
The docs would seem to indicate Actual Total Time * Actual Loops = total time spent on an operation.
However, from a JSON plan I produced:
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Join Type": "Inner",
"Startup Cost": 66575.34,
"Total Cost": 76861.82,
"Plan Rows": 407,
"Plan Width": 290,
"Actual Startup Time": 49962.789,
"Actual Total Time": 51206.643,
"Actual Rows": 127117,
"Actual Loops": 3,
"Output": [ ... ],
...
"Execution Time": 52677.398
(The complete plan is here.)
Actual Total Time * Actual Loops = 51 sec * 3 = 2 min 33 sec clearly exceeds the Execution Time of 52.7 seconds.
Am I understanding the documentation correctly?
If so, shouldn't it say, "we spent a total of 0.01 milliseconds executing the index scans on tenk2"?
postgresql sql-execution-plan explain
edited Mar 25 at 14:48
Laurenz Albe
56.7k113658
asked Mar 24 at 22:38
wmeitzenwmeitzen
417
The documentation is correct in this case. YourEXPLAINoutput is incomplete, so it's hard to make a judgement if it contradicts the documentation or not.
– Laurenz Albe
Mar 25 at 7:15
How can the documentation be correct ifActual Total Time*Actual LoopsexceedsExecution Time?
– wmeitzen
Mar 25 at 11:48
I'm not sure. That's why I'd like to see the whole plan. If it is not too much to ask, in text format.
– Laurenz Albe
Mar 25 at 12:03
Here it is: tatiyants.com/pev/#/plans/plan_1553519907593. The operation in my post is the hash join usings._fixation_key = f._fixation_key.
– wmeitzen
Mar 25 at 13:26
That link leads to an empty page for me. Can you add it to the question?
– Laurenz Albe
Mar 25 at 13:30
|
show 6 more comments
I think found a mistake, and a possible correction, in the postgres documentation regarding explain plans.
From: https://www.postgresql.org/docs/current/using-explain.html
Index Scan using tenk2_unique2 on tenk2 t2 (cost=0.29..7.91 rows=1 width=244) (actual time=0.021..0.022 rows=1 loops=10)
"In the above example, we spent a total of 0.220 milliseconds executing the index scans on tenk2."
The docs would seem to indicate Actual Total Time * Actual Loops = total time spent on an operation.
However, from a JSON plan I produced:
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Join Type": "Inner",
"Startup Cost": 66575.34,
"Total Cost": 76861.82,
"Plan Rows": 407,
"Plan Width": 290,
"Actual Startup Time": 49962.789,
"Actual Total Time": 51206.643,
"Actual Rows": 127117,
"Actual Loops": 3,
"Output": [ ... ],
...
"Execution Time": 52677.398
(The complete plan is here.)
Actual Total Time * Actual Loops = 51 sec * 3 = 2 min 33 sec clearly exceeds the Execution Time of 52.7 seconds.
Am I understanding the documentation correctly?
If so, shouldn't it say, "we spent a total of 0.01 milliseconds executing the index scans on tenk2"?
postgresql sql-execution-plan explain
edited Mar 25 at 14:48
Laurenz Albe
56.7k113658
asked Mar 24 at 22:38
wmeitzenwmeitzen
417
I think found a mistake, and a possible correction, in the postgres documentation regarding explain plans.
From: https://www.postgresql.org/docs/current/using-explain.html
Index Scan using tenk2_unique2 on tenk2 t2 (cost=0.29..7.91 rows=1 width=244) (actual time=0.021..0.022 rows=1 loops=10)
"In the above example, we spent a total of 0.220 milliseconds executing the index scans on tenk2."
The docs would seem to indicate Actual Total Time * Actual Loops = total time spent on an operation.
However, from a JSON plan I produced:
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Join Type": "Inner",
"Startup Cost": 66575.34,
"Total Cost": 76861.82,
"Plan Rows": 407,
"Plan Width": 290,
"Actual Startup Time": 49962.789,
"Actual Total Time": 51206.643,
"Actual Rows": 127117,
"Actual Loops": 3,
"Output": [ ... ],
...
"Execution Time": 52677.398
(The complete plan is here.)
Actual Total Time * Actual Loops = 51 sec * 3 = 2 min 33 sec clearly exceeds the Execution Time of 52.7 seconds.
Am I understanding the documentation correctly?
If so, shouldn't it say, "we spent a total of 0.01 milliseconds executing the index scans on tenk2"?
postgresql sql-execution-plan explain
postgresql sql-execution-plan explain
edited Mar 25 at 14:48
Laurenz Albe
56.7k113658
asked Mar 24 at 22:38
wmeitzenwmeitzen
417
edited Mar 25 at 14:48
Laurenz Albe
56.7k113658
asked Mar 24 at 22:38
wmeitzenwmeitzen
417
edited Mar 25 at 14:48
Laurenz Albe
56.7k113658
edited Mar 25 at 14:48
Laurenz Albe
56.7k113658
edited Mar 25 at 14:48
Laurenz Albe
56.7k113658
56.7k113658
asked Mar 24 at 22:38
wmeitzenwmeitzen
417
asked Mar 24 at 22:38
wmeitzenwmeitzen
417
asked Mar 24 at 22:38
wmeitzenwmeitzen
417
417
The documentation is correct in this case. YourEXPLAINoutput is incomplete, so it's hard to make a judgement if it contradicts the documentation or not.
– Laurenz Albe
Mar 25 at 7:15
How can the documentation be correct ifActual Total Time*Actual LoopsexceedsExecution Time?
– wmeitzen
Mar 25 at 11:48
I'm not sure. That's why I'd like to see the whole plan. If it is not too much to ask, in text format.
– Laurenz Albe
Mar 25 at 12:03
Here it is: tatiyants.com/pev/#/plans/plan_1553519907593. The operation in my post is the hash join usings._fixation_key = f._fixation_key.
– wmeitzen
Mar 25 at 13:26
That link leads to an empty page for me. Can you add it to the question?
– Laurenz Albe
Mar 25 at 13:30
|
show 6 more comments
The documentation is correct in this case. YourEXPLAINoutput is incomplete, so it's hard to make a judgement if it contradicts the documentation or not.
– Laurenz Albe
Mar 25 at 7:15
How can the documentation be correct ifActual Total Time*Actual LoopsexceedsExecution Time?
– wmeitzen
Mar 25 at 11:48
I'm not sure. That's why I'd like to see the whole plan. If it is not too much to ask, in text format.
– Laurenz Albe
Mar 25 at 12:03
Here it is: tatiyants.com/pev/#/plans/plan_1553519907593. The operation in my post is the hash join usings._fixation_key = f._fixation_key.
– wmeitzen
Mar 25 at 13:26
That link leads to an empty page for me. Can you add it to the question?
– Laurenz Albe
Mar 25 at 13:30
The documentation is correct in this case. Your
EXPLAIN output is incomplete, so it's hard to make a judgement if it contradicts the documentation or not.– Laurenz Albe
Mar 25 at 7:15
The documentation is correct in this case. Your
EXPLAIN output is incomplete, so it's hard to make a judgement if it contradicts the documentation or not.– Laurenz Albe
Mar 25 at 7:15
How can the documentation be correct if
Actual Total Time * Actual Loops exceeds Execution Time?– wmeitzen
Mar 25 at 11:48
How can the documentation be correct if
Actual Total Time * Actual Loops exceeds Execution Time?– wmeitzen
Mar 25 at 11:48
I'm not sure. That's why I'd like to see the whole plan. If it is not too much to ask, in text format.
– Laurenz Albe
Mar 25 at 12:03
I'm not sure. That's why I'd like to see the whole plan. If it is not too much to ask, in text format.
– Laurenz Albe
Mar 25 at 12:03
Here it is: tatiyants.com/pev/#/plans/plan_1553519907593. The operation in my post is the hash join using
s._fixation_key = f._fixation_key.– wmeitzen
Mar 25 at 13:26
Here it is: tatiyants.com/pev/#/plans/plan_1553519907593. The operation in my post is the hash join using
s._fixation_key = f._fixation_key.– wmeitzen
Mar 25 at 13:26
That link leads to an empty page for me. Can you add it to the question?
– Laurenz Albe
Mar 25 at 13:30
That link leads to an empty page for me. Can you add it to the question?
– Laurenz Albe
Mar 25 at 13:30
|
show 6 more comments
1 Answer
1
active
oldest
votes
Your Hash Join is underneath a Gather node:
Gather (cost=67,575.34..77,959.52 rows=977 width=290) (actual time=51,264.085..52,595.474 rows=381,352 loops=1)
Buffers: shared hit=611279 read=99386
-> Hash Join (cost=66,575.34..76,861.82 rows=407 width=290) (actual time=49,962.789..51,206.643 rows=127,117 loops=3)
Buffers: shared hit=611279 read=99386
That means that The query started two background workers which ran in parallel with the main backend to complete the hash join (see the "Workers Launched": 2 in the execution plan).
Now it is evident that if three processes work on a task, the total execution time will not be the sum of the individual execution times.
In other words, the rule about multiplication of execution time with the number of loops holds for nested loop join, (which is single threaded), but not for parallel execution of a query.
answered Mar 25 at 15:01
Laurenz AlbeLaurenz Albe
56.7k113658
Your answer has led me to read the explain and parallel query docs much more closely.
– wmeitzen
Mar 26 at 16:16
add a comment |
Your Answer
StackExchange.ifUsing("editor", function ()
StackExchange.using("externalEditor", function ()
StackExchange.using("snippets", function ()
StackExchange.snippets.init();
);
);
, "code-snippets");
StackExchange.ready(function()
var channelOptions =
tags: "".split(" "),
id: "1"
;
initTagRenderer("".split(" "), "".split(" "), channelOptions);
StackExchange.using("externalEditor", function()
// Have to fire editor after snippets, if snippets enabled
if (StackExchange.settings.snippets.snippetsEnabled)
StackExchange.using("snippets", function()
createEditor();
);
else
createEditor();
);
function createEditor()
StackExchange.prepareEditor(
heartbeatType: 'answer',
autoActivateHeartbeat: false,
convertImagesToLinks: true,
noModals: true,
showLowRepImageUploadWarning: true,
reputationToPostImages: 10,
bindNavPrevention: true,
postfix: "",
imageUploader:
brandingHtml: "Powered by u003ca class="icon-imgur-white" href="https://imgur.com/"u003eu003c/au003e",
contentPolicyHtml: "User contributions licensed under u003ca href="https://creativecommons.org/licenses/by-sa/3.0/"u003ecc by-sa 3.0 with attribution requiredu003c/au003e u003ca href="https://stackoverflow.com/legal/content-policy"u003e(content policy)u003c/au003e",
allowUrls: true
,
onDemand: true,
discardSelector: ".discard-answer"
,immediatelyShowMarkdownHelp:true
);
);
Sign up or log in
StackExchange.ready(function ()
StackExchange.helpers.onClickDraftSave('#login-link');
);
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
StackExchange.ready(
function ()
StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2fstackoverflow.com%2fquestions%2f55329262%2fexplain-analyze-total-time-spent-executing-a-task-documentation-error-or-my-er%23new-answer', 'question_page');
);
Post as a guest
Required, but never shown
1 Answer
1
active
oldest
votes
1 Answer
1
active
oldest
votes
active
oldest
votes
active
oldest
votes
Your Hash Join is underneath a Gather node:
Gather (cost=67,575.34..77,959.52 rows=977 width=290) (actual time=51,264.085..52,595.474 rows=381,352 loops=1)
Buffers: shared hit=611279 read=99386
-> Hash Join (cost=66,575.34..76,861.82 rows=407 width=290) (actual time=49,962.789..51,206.643 rows=127,117 loops=3)
Buffers: shared hit=611279 read=99386
That means that The query started two background workers which ran in parallel with the main backend to complete the hash join (see the "Workers Launched": 2 in the execution plan).
Now it is evident that if three processes work on a task, the total execution time will not be the sum of the individual execution times.
In other words, the rule about multiplication of execution time with the number of loops holds for nested loop join, (which is single threaded), but not for parallel execution of a query.
answered Mar 25 at 15:01
Laurenz AlbeLaurenz Albe
56.7k113658
Your answer has led me to read the explain and parallel query docs much more closely.
– wmeitzen
Mar 26 at 16:16
add a comment |
Your Hash Join is underneath a Gather node:
Gather (cost=67,575.34..77,959.52 rows=977 width=290) (actual time=51,264.085..52,595.474 rows=381,352 loops=1)
Buffers: shared hit=611279 read=99386
-> Hash Join (cost=66,575.34..76,861.82 rows=407 width=290) (actual time=49,962.789..51,206.643 rows=127,117 loops=3)
Buffers: shared hit=611279 read=99386
That means that The query started two background workers which ran in parallel with the main backend to complete the hash join (see the "Workers Launched": 2 in the execution plan).
Now it is evident that if three processes work on a task, the total execution time will not be the sum of the individual execution times.
In other words, the rule about multiplication of execution time with the number of loops holds for nested loop join, (which is single threaded), but not for parallel execution of a query.
answered Mar 25 at 15:01
Laurenz AlbeLaurenz Albe
56.7k113658
Your answer has led me to read the explain and parallel query docs much more closely.
– wmeitzen
Mar 26 at 16:16
add a comment |
Your Hash Join is underneath a Gather node:
Gather (cost=67,575.34..77,959.52 rows=977 width=290) (actual time=51,264.085..52,595.474 rows=381,352 loops=1)
Buffers: shared hit=611279 read=99386
-> Hash Join (cost=66,575.34..76,861.82 rows=407 width=290) (actual time=49,962.789..51,206.643 rows=127,117 loops=3)
Buffers: shared hit=611279 read=99386
That means that The query started two background workers which ran in parallel with the main backend to complete the hash join (see the "Workers Launched": 2 in the execution plan).
Now it is evident that if three processes work on a task, the total execution time will not be the sum of the individual execution times.
In other words, the rule about multiplication of execution time with the number of loops holds for nested loop join, (which is single threaded), but not for parallel execution of a query.
answered Mar 25 at 15:01
Laurenz AlbeLaurenz Albe
56.7k113658
Your Hash Join is underneath a Gather node:
Gather (cost=67,575.34..77,959.52 rows=977 width=290) (actual time=51,264.085..52,595.474 rows=381,352 loops=1)
Buffers: shared hit=611279 read=99386
-> Hash Join (cost=66,575.34..76,861.82 rows=407 width=290) (actual time=49,962.789..51,206.643 rows=127,117 loops=3)
Buffers: shared hit=611279 read=99386
That means that The query started two background workers which ran in parallel with the main backend to complete the hash join (see the "Workers Launched": 2 in the execution plan).
Now it is evident that if three processes work on a task, the total execution time will not be the sum of the individual execution times.
In other words, the rule about multiplication of execution time with the number of loops holds for nested loop join, (which is single threaded), but not for parallel execution of a query.
answered Mar 25 at 15:01
Laurenz AlbeLaurenz Albe
56.7k113658
answered Mar 25 at 15:01
Laurenz AlbeLaurenz Albe
56.7k113658
answered Mar 25 at 15:01
Laurenz AlbeLaurenz Albe
56.7k113658
answered Mar 25 at 15:01
Laurenz AlbeLaurenz Albe
56.7k113658
56.7k113658
Your answer has led me to read the explain and parallel query docs much more closely.
– wmeitzen
Mar 26 at 16:16
add a comment |
Your answer has led me to read the explain and parallel query docs much more closely.
– wmeitzen
Mar 26 at 16:16
Your answer has led me to read the explain and parallel query docs much more closely.
– wmeitzen
Mar 26 at 16:16
Your answer has led me to read the explain and parallel query docs much more closely.
– wmeitzen
Mar 26 at 16:16
add a comment |
Thanks for contributing an answer to Stack Overflow!
- Please be sure to answer the question. Provide details and share your research!
But avoid …
- Asking for help, clarification, or responding to other answers.
- Making statements based on opinion; back them up with references or personal experience.
To learn more, see our tips on writing great answers.
Sign up or log in
StackExchange.ready(function ()
StackExchange.helpers.onClickDraftSave('#login-link');
);
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
StackExchange.ready(
function ()
StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2fstackoverflow.com%2fquestions%2f55329262%2fexplain-analyze-total-time-spent-executing-a-task-documentation-error-or-my-er%23new-answer', 'question_page');
);
Post as a guest
Required, but never shown
Sign up or log in
StackExchange.ready(function ()
StackExchange.helpers.onClickDraftSave('#login-link');
);
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
Sign up or log in
StackExchange.ready(function ()
StackExchange.helpers.onClickDraftSave('#login-link');
);
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
Sign up or log in
StackExchange.ready(function ()
StackExchange.helpers.onClickDraftSave('#login-link');
);
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
The documentation is correct in this case. Your
EXPLAINoutput is incomplete, so it's hard to make a judgement if it contradicts the documentation or not.– Laurenz Albe
Mar 25 at 7:15
How can the documentation be correct if
Actual Total Time*Actual LoopsexceedsExecution Time?– wmeitzen
Mar 25 at 11:48
I'm not sure. That's why I'd like to see the whole plan. If it is not too much to ask, in text format.
– Laurenz Albe
Mar 25 at 12:03
Here it is: tatiyants.com/pev/#/plans/plan_1553519907593. The operation in my post is the hash join using
s._fixation_key = f._fixation_key.– wmeitzen
Mar 25 at 13:26
That link leads to an empty page for me. Can you add it to the question?
– Laurenz Albe
Mar 25 at 13:30