Re: Parallel query only when EXPLAIN ANALYZEd

On 1 October 2016 at 05:47, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)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