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

On 2018-09-18 10:03:02 +0530, Amit Khandekar wrote:
> Attached v3 patch that does the above change.

Attached is a revised version of that patch. I've changed quite a few
things:
- I've reverted the split of "base" and "provider specific" contexts - I
don't think it really buys us anything here.

- I've reverted the context creation changes - instead of creating a
context in the leader just to store instrumentation in the worker,
there's now a new EState->es_jit_combined_instr.

- That also means worker instrumentation doesn't get folded into the
leader's instrumentation. This seems good for the future and for
extensions - it's not actually "linear" time that's spent doing
JIT in workers (& leader), as all of that work happens in
parallel. Being able to disentangle that seems important.

- Only allocate / transport JIT instrumentation if instrumentation is
enabled.

- Smaller cleanups.

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

Instead of "JIT for worker 0" we could instead do "Worker 0: JIT", but
I'm not sure that's better, given that the JIT group is multi-line
output.

Currently structured formats show this as:
"JIT": {
"Worker Number": 1,
"Functions": 2,
"Options": {
"Inlining": true,
"Optimization": true,
"Expressions": true,
"Deforming": true
},
"Timing": {
"Generation": 0.374,
"Inlining": 70.341,
"Optimization": 8.006,
"Emission": 7.670,
"Total": 86.390
}
},

This needs a bit more polish tomorrow, but I'm starting to like where
this is going. Comments?

Greetings,

Andres Freund