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