Re: Parallel query only when EXPLAIN ANALYZEd

On 1 October 2016 at 05:47, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> FWIW, I tried your original example on Linux yesterday, and it seemed to
> work fine --- it only wanted to use 1 worker, but the speedup was just
> about exactly 2X with or without "explain analyze".  So this is somehow
> Windows specific.  That's darn odd; in a quick look at the relevant code
> I see nothing that looks platform dependent.
>
> Somebody will need to trace through this on Windows and see where it's
> going off the rails.

I had assumed this was something very specific to Jay's machine, and
tracing through the code I didn't really see why EXPLAIN ANALYZE would
behave any differently from just the SELECT.

I tried the test case on 9.6.0 on a Windows 8.1 machine, and it works
fine for me.

Full test case below, if anyone else would like to try.

postgres=# create table big as (
postgres(#   SELECT generate_series(1,30000000) AS id
postgres(# );
SELECT 30000000

postgres=# set max_parallel_workers_per_gather=8;
SET
postgres=# load 'auto_explain';
LOAD
postgres=# set auto_explain.log_min_duration=0;
SET
postgres=# set auto_explain.log_analyze=1;
SET
postgres=# \timing
Timing is on.
postgres=# explain analyze SELECT avg(id) from big where id % 17 = 0;
                                                               QUERY PLAN

----------------------------------------------------------------------------------------------------------------------------------------
 Finalize Aggregate  (cost=223819.96..223819.97 rows=1 width=32)
(actual time=1030.778..1030.778 rows=1 loops=1)
   ->  Gather  (cost=223819.43..223819.94 rows=5 width=32) (actual
time=1029.691..1030.762 rows=6 loops=1)
         Workers Planned: 5
         Workers Launched: 5
         ->  Partial Aggregate  (cost=222819.43..222819.44 rows=1
width=32) (actual time=1004.021..1004.021 rows=1 loops=6)
               ->  Parallel Seq Scan on big  (cost=0.00..222744.43
rows=30000 width=4) (actual time=0.132..974.408 rows=294118 loops=6)
                     Filter: ((id % 17) = 0)
                     Rows Removed by Filter: 4705883
 Planning time: 0.066 ms
 Execution time: 1045.064 ms
(10 rows)

Time: 1045.486 ms (00:01.045)

postgres=# SELECT avg(id) from big where id % 17 = 0;
          avg
-----------------------
 15000001.000000000000
(1 row)


Time: 1061.304 ms (00:01.061)

The logs show:

2016-10-01 09:39:30 NZDT [7084]: [11-1]
user=postgres,db=postgres,app=psql,client=::1 LOG:  duration: 1060.801
ms  plan:
Query Text: SELECT avg(id) from big where id % 17 = 0;
Finalize Aggregate  (cost=223819.96..223819.97 rows=1 width=32)
(actual time=1046.424..1046.424 rows=1 loops=1)
 ->  Gather  (cost=223819.43..223819.94 rows=5 width=32) (actual
time=1045.358..1046.414 rows=6 loops=1)
       Workers Planned: 5
       Workers Launched: 5
       ->  Partial Aggregate  (cost=222819.43..222819.44 rows=1
width=32) (actual time=1023.197..1023.197 rows=1 loops=6)
             ->  Parallel Seq Scan on big  (cost=0.00..222744.43
rows=30000 width=4) (actual time=0.143..992.890 rows=294118 loops=6)
                   Filter: ((id % 17) = 0)
                   Rows Removed by Filter: 4705883



--
 David Rowley                   http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services