public inbox for [email protected]
help / color / mirror / Atom feedExplain Analyze - actual time in loops
6+ messages / 3 participants
[nested] [flat]
* Explain Analyze - actual time in loops
@ 2017-09-08 03:17 Neto pr <[email protected]>
0 siblings, 1 reply; 6+ messages in thread
From: Neto pr @ 2017-09-08 03:17 UTC (permalink / raw)
To: pgsql-performance
Dear,
I'm trying to interpret an Explain Analyze, but I did not understand this:
-> According to the Postgresql documentation at: https://www.postgresql.org/
docs/9.6/static/using-explain.html
" the loops value reports the total number of executions of the node, and
the actual time and rows values shown are averages per-execution.
.... Multiply by the loops value to get the total time actually spent in
the node"
But look at this case, in which the total query time was 66 minutes.
(Explain Analyze complete and Query at this link: https://goo.gl/Kp45fu )
What interests me is this section:
################################ ###################################
-> Index Scan using idx_l_partkeylineitem000x on lineitem (cost =
0.57..97.65 rows = 26 width = 36)
(current time = 23.615..419.113 rows = 30 loops = 26469)
Index Cond: (l_partkey = part.p_partkey)
################################################## #################
According to the documentation, one should multiply the Actual Time by the
number of Loops.
That is: 419113 ms -> 419113/1000/60 = 6.9 minutes * 26469 (loops) = 182.6
minutes.
But how does this stretch take 182.6 minutes, if the entire query ran in 66
minutes?
Of course I'm making a miscalculation, but if anyone can give me a hint as
to how I would calculate this time.
What I need to know is the time spent go through the
idx_l_partkeylineitem000x index, remembering that I did an Explain Analyze
which is theoretically the actual time spent and not an estimate
as happens with the simple Explain .
thank you and best regards
[] 's Neto
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: Explain Analyze - actual time in loops
@ 2017-09-08 12:46 Igor Neyman <[email protected]>
parent: Neto pr <[email protected]>
0 siblings, 1 reply; 6+ messages in thread
From: Igor Neyman @ 2017-09-08 12:46 UTC (permalink / raw)
To: Neto pr <[email protected]>; pgsql-performance
From: [email protected] [mailto:[email protected]] On Behalf Of Neto pr
Sent: Thursday, September 07, 2017 11:17 PM
To: [email protected]
Subject: [PERFORM] Explain Analyze - actual time in loops
…
################################ ###################################
-> Index Scan using idx_l_partkeylineitem000x on lineitem (cost = 0.57..97.65 rows = 26 width = 36)
(current time = 23.615..419.113 rows = 30 loops = 26469)
Index Cond: (l_partkey = part.p_partkey)
################################################## #################
According to the documentation, one should multiply the Actual Time by the number of Loops.
That is: 419113 ms -> 419113/1000/60 = 6.9 minutes * 26469 (loops) = 182.6 minutes.
But how does this stretch take 182.6 minutes, if the entire query ran in 66 minutes?
……………….
thank you and best regards
[] 's Neto
Neto,
The time you see there is in ms, so the point (‘.’) you see is the digital point.
So, it is 419.113ms or a little less than half a second (0.419sec).
Igor Neyman
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: Explain Analyze - actual time in loops
@ 2017-09-08 13:08 Neto pr <[email protected]>
parent: Igor Neyman <[email protected]>
0 siblings, 1 reply; 6+ messages in thread
From: Neto pr @ 2017-09-08 13:08 UTC (permalink / raw)
To: Igor Neyman <[email protected]>; +Cc: pgsql-performance
Igor,
You're right, I confused the radix character.
But even so the result is approximate to the previous message, 182 minutes, see
below:
419.113 / 1000 = 0.41 seconds * 26469 (loops) = 11093.50 seconds or 184
minutes
After analyzing, I saw that in some places of the plan, it is being used
Parallelism. Does this explain why the final value spent (in minutes) to go
through the index (184 minutes) is greater than the total query time (66
minutes)?
Regards
Neto
2017-09-08 5:46 GMT-07:00 Igor Neyman <[email protected]>:
> *From:* [email protected] [mailto:pgsql-performance-
> [email protected]] *On Behalf Of *Neto pr
> *Sent:* Thursday, September 07, 2017 11:17 PM
> *To:* [email protected]
> *Subject:* [PERFORM] Explain Analyze - actual time in loops
>
>
>
> …
>
> ################################ ###################################
> -> Index Scan using idx_l_partkeylineitem000x on lineitem (cost =
> 0.57..97.65 rows = 26 width = 36)
> (current time = 23.615..419.113 rows = 30 loops = 26469)
> Index Cond: (l_partkey = part.p_partkey)
> ################################################## #################
> According to the documentation, one should multiply the Actual Time by the
> number of Loops.
> That is: 419113 ms -> 419113/1000/60 = 6.9 minutes * 26469 (loops) = 182.6
> minutes.
>
> But how does this stretch take 182.6 minutes, if the entire query ran in
> 66 minutes?
>
> ……………….
> thank you and best regards
> [] 's Neto
>
> Neto,
>
> The time you see there is in ms, so the point (‘.’) you see is the digital
> point.
>
> So, it is 419.113ms or a little less than half a second (0.419sec).
>
> Igor Neyman
>
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: Explain Analyze - actual time in loops
@ 2017-09-08 13:44 Tom Lane <[email protected]>
parent: Neto pr <[email protected]>
0 siblings, 1 reply; 6+ messages in thread
From: Tom Lane @ 2017-09-08 13:44 UTC (permalink / raw)
To: Neto pr <[email protected]>; +Cc: Igor Neyman <[email protected]>; pgsql-performance
Neto pr <[email protected]> writes:
> After analyzing, I saw that in some places of the plan, it is being used
> Parallelism. Does this explain why the final value spent (in minutes) to go
> through the index (184 minutes) is greater than the total query time (66
> minutes)?
I was just about to ask you about that. If this is under a Gather node,
I believe that the numbers include time expended in all processes.
So if you had three or more workers these results would make sense.
regards, tom lane
--
Sent via pgsql-performance mailing list ([email protected])
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: Explain Analyze - actual time in loops
@ 2017-09-08 14:02 Neto pr <[email protected]>
parent: Tom Lane <[email protected]>
0 siblings, 1 reply; 6+ messages in thread
From: Neto pr @ 2017-09-08 14:02 UTC (permalink / raw)
To: Tom Lane <[email protected]>; +Cc: Igor Neyman <[email protected]>; pgsql-performance
Thanks for reply Tom and Igor.
Just only more information:
I need to know the height of a B-tree index (level of the leaf node
farthest from the root).
I tried to find this data in PG_INDEXES and PG_CLASS views, but I did not
find it.
Does anyone know if Postgresql stores this information, referring to the
height of the index tree?
Regards
2017-09-08 6:44 GMT-07:00 Tom Lane <[email protected]>:
> Neto pr <[email protected]> writes:
> > After analyzing, I saw that in some places of the plan, it is being used
> > Parallelism. Does this explain why the final value spent (in minutes) to
> go
> > through the index (184 minutes) is greater than the total query time (66
> > minutes)?
>
> I was just about to ask you about that. If this is under a Gather node,
> I believe that the numbers include time expended in all processes.
> So if you had three or more workers these results would make sense.
>
> regards, tom lane
>
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: Explain Analyze - actual time in loops
@ 2017-09-08 14:07 Tom Lane <[email protected]>
parent: Neto pr <[email protected]>
0 siblings, 0 replies; 6+ messages in thread
From: Tom Lane @ 2017-09-08 14:07 UTC (permalink / raw)
To: Neto pr <[email protected]>; +Cc: Igor Neyman <[email protected]>; pgsql-performance
Neto pr <[email protected]> writes:
> I need to know the height of a B-tree index (level of the leaf node
> farthest from the root).
pageinspect's bt_metap() will give you that --- it's the "level"
field, I believe.
regards, tom lane
--
Sent via pgsql-performance mailing list ([email protected])
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 6+ messages in thread
end of thread, other threads:[~2017-09-08 14:07 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2017-09-08 03:17 Explain Analyze - actual time in loops Neto pr <[email protected]>
2017-09-08 12:46 ` Igor Neyman <[email protected]>
2017-09-08 13:08 ` Neto pr <[email protected]>
2017-09-08 13:44 ` Tom Lane <[email protected]>
2017-09-08 14:02 ` Neto pr <[email protected]>
2017-09-08 14:07 ` Tom Lane <[email protected]>
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox