Thread: help interpreting "explain analyze" output

help interpreting "explain analyze" output

From
David Rysdam
Date:
I'm not really looking for information on how to speed this query
up. I'm just trying to interpret the output enough to tell me which step
is slow:

   Seq Scan on mags  (cost=0.00..187700750.56  rows=47476  width=4) (actual time=3004851.889..3004851.889  rows=0
loops=1)
      Filter:  ((signum IS NOT NULL) AND (NOT (SubPlan 1)))
      SubPlan 1
        -> Materialize  (cost=0.00..3713.93  rows=95862  width=4) (actual time=0.011..16.145  rows=48139  loops=94951)
               -> Seq Scan on sigs (cost=0.00..2906.62 rows=95862 width=4) (actual time=0.010..674.201  rows=95862
loops=1)
   Total runtime: 3004852.005 ms

It looks like the inner seq scan takes 674ms, then the materialize takes
an additional 16ms? Or is that 16ms * 94951? Or 674 * 94951?

And the outer seq scan takes 3004851-3004851 = 0ms?



Re: help interpreting "explain analyze" output

From
Vik Fearing
Date:
On 11/26/2013 06:24 PM, David Rysdam wrote:
> I'm not really looking for information on how to speed this query
> up. I'm just trying to interpret the output enough to tell me which step
> is slow:
>
>    Seq Scan on mags  (cost=0.00..187700750.56  rows=47476  width=4) (actual time=3004851.889..3004851.889  rows=0
loops=1)
>       Filter:  ((signum IS NOT NULL) AND (NOT (SubPlan 1)))
>       SubPlan 1
>         -> Materialize  (cost=0.00..3713.93  rows=95862  width=4) (actual time=0.011..16.145  rows=48139
loops=94951)
>                -> Seq Scan on sigs (cost=0.00..2906.62 rows=95862 width=4) (actual time=0.010..674.201  rows=95862
loops=1)
>    Total runtime: 3004852.005 ms
>
> It looks like the inner seq scan takes 674ms, then the materialize takes
> an additional 16ms? Or is that 16ms * 94951? Or 674 * 94951?
>
> And the outer seq scan takes 3004851-3004851 = 0ms?

The actual time shown is not a range.  The first number is how long it
took to produce the first row, and the second is how long it took
overall.  The Seq Scan on mags took 3004851.889ms to produce the first
(non-existent) row and then it was finished so that's also the overall time.

SubPlan 1 took a total of 674.201ms + 94951 * 16.145ms = 1533658.096ms
which means the Filter line actually took 1471193.793ms to determine
there were no matching rows.

That is, if I understood it correctly myself.

--
Vik



Re: help interpreting "explain analyze" output

From
hubert depesz lubaczewski
Date:
On Tue, Nov 26, 2013 at 12:24:08PM -0500, David Rysdam wrote:
> I'm not really looking for information on how to speed this query
> up. I'm just trying to interpret the output enough to tell me which step
> is slow:

You might want to read this:
http://www.depesz.com/tag/unexplainable/

Best regards,

depesz


Attachment