Horton

Re: explain analyze output with parallel workers - question about meaning of information for explain.depesz.com

hubert depesz lubaczewski <depesz@depesz.com>

View thread View on postgr.es
From: hubert depesz lubaczewski <depesz@depesz.com>
To: Amit Kapila <amit.kapila16@gmail.com>
Cc: pgsql-hackers mailing list <pgsql-hackers@postgresql.org>
Date: 2017-11-27T17:56:31Z
Lists: pgsql-hackers 
On Mon, Nov 27, 2017 at 05:24:49PM +0530, Amit Kapila wrote:
> I think it is "actual_time * 1" for anything below Gather.

Well, I think I found another problem.

Please take a look at:
https://explain.depesz.com/s/Bs8c

Node 15 is Gather with loops = 2974 (because it was ran by nested loop).

There were 4 workers, so 5 threads working, but the loops on parallel
seq scan is 17.698 million ?!

The problem is that for explain.depesz.com I'm calculating how much time
pg actually spent doing given thing.

So, if an operation has actual time of 1ms, but 100 loops, it took
100ms.

In case of parallel operations it looks like I can't realistically find
the information anywhere?

In the explain above, we see that Nested loop took, in total, around
2 million miliseconds (step 9).
Out of which, ~ 7000 ms was hash join and it's subnodes.
This leaves most of the time for Gather step, which was called 2974
times with actual time reported as 618ms.
2974 * 618 is 1837932 miliseconds, which seems reasonable.

But then - how much of this time was spent in Parallel Seq Scan in step
#16 ?

2974 * 609ms? Why is loops there 17 million?

Best regards,

depesz

Commits

  1. Back-port fix for accumulation of parallel worker instrumentation.

  2. Test instrumentation of Hash nodes with parallel query.

  3. Try again to fix accumulation of parallel worker instrumentation.

  4. Revert "Fix accumulation of parallel worker instrumentation."

  5. Fix accumulation of parallel worker instrumentation.