Re: Query is over 2x slower with jit=on

Hi,

On 2018-09-25 01:47:49 -0700, Andres Freund wrote:
> Forcing parallelism and JIT to be on, I get:
> 
> postgres[20216][1]=# EXPLAIN (ANALYZE, VERBOSE, BUFFERS) SELECT count(*) FROM pg_class;
> 
> Finalize Aggregate  (cost=15.43..15.44 rows=1 width=8) (actual time=183.282..183.282 rows=1 loops=1)
>   Output: count(*)
>   Buffers: shared hit=13
>   ->  Gather  (cost=15.41..15.42 rows=2 width=8) (actual time=152.835..152.904 rows=2 loops=1)
>         Output: (PARTIAL count(*))
>         Workers Planned: 2
>         Workers Launched: 2
>         JIT for worker 0:
>           Functions: 2
>           Options: Inlining true, Optimization true, Expressions true, Deforming true
>           Timing: Generation 0.480 ms, Inlining 78.789 ms, Optimization 5.797 ms, Emission 5.554 ms, Total 90.620 ms
>         JIT for worker 1:
>           Functions: 2
>           Options: Inlining true, Optimization true, Expressions true, Deforming true
>           Timing: Generation 0.475 ms, Inlining 78.632 ms, Optimization 5.954 ms, Emission 5.900 ms, Total 90.962 ms
>         Buffers: shared hit=13
>         ->  Partial Aggregate  (cost=15.41..15.42 rows=1 width=8) (actual time=90.608..90.609 rows=1 loops=2)
>               Output: PARTIAL count(*)
>               Buffers: shared hit=13
>               Worker 0: actual time=90.426..90.426 rows=1 loops=1
>                 Buffers: shared hit=7
>               Worker 1: actual time=90.791..90.792 rows=1 loops=1
>                 Buffers: shared hit=6
>               ->  Parallel Seq Scan on pg_catalog.pg_class  (cost=0.00..14.93 rows=193 width=0) (actual
time=0.006..0.048rows=193 loops=2)
 
>                     Output: relname, relnamespace, reltype, reloftype, relowner, relam, relfilenode, reltablespace,
relpages,reltuples, relallvisible, reltoastrelid, relhasindex, relisshared, relpersistence, relkind, relnatts,
relchecks,relhasoids, relhasrules, relhastriggers, relhassubclass, relrowsecurity, relfo
 
>                     Buffers: shared hit=13
>                     Worker 0: actual time=0.006..0.047 rows=188 loops=1
>                       Buffers: shared hit=7
>                     Worker 1: actual time=0.006..0.048 rows=198 loops=1
>                       Buffers: shared hit=6
> Planning Time: 0.152 ms
> JIT:
>   Functions: 4
>   Options: Inlining true, Optimization true, Expressions true, Deforming true
>   Timing: Generation 0.955 ms, Inlining 157.422 ms, Optimization 11.751 ms, Emission 11.454 ms, Total 181.582 ms
> Execution Time: 184.197 ms

With parallelism on, this is the aggregated cost of doing JIT
compilation. I wonder if, in VERBOSE mode, we should separately display
the cost of JIT for the leader.  Comments?

- Andres