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.048 rows=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