Re: JIT compiling with LLVM v11

On 2018-03-09 13:08:36 -0800, Andres Freund wrote:
> On 2018-03-09 15:42:24 -0500, Peter Eisentraut wrote:
> > What I'd quite like is if EXPLAIN or EXPLAIN ANALYZE showed something
> > about what kind of JIT processing was done, if any, to help with this
> > kind of testing.
>
> Yea, I like that. I think we can only show that when timing is on,
> because otherwise the tests will not be stable depending on --with-jit
> being specified or not.
>
> So I'm thinking of displaying it similar to the "Planning time" piece,
> i.e. depending on es->summary being enabled. It'd be good to display the
> inline/optimize/emit times too. I think we can just store it in the
> JitContext. But the inline/optimize/emission times will only be
> meaningful when the query is actually executed, I don't see a way around
> that...

Not yet really happy with how it exactly looks, but here's my current
state:

tpch_10[20923][1]=# ;explain (format text, analyze, timing off) SELECT relkind, relname FROM pg_class pgc WHERE relkind = 'r';
┌────────────────────────────────────────────────────────────────────────────────────────┐
│ QUERY PLAN │
├────────────────────────────────────────────────────────────────────────────────────────┤
│ Seq Scan on pg_class pgc (cost=0.00..15.70 rows=77 width=65) (actual rows=77 loops=1) │
│ Filter: (relkind = 'r'::"char") │
│ Rows Removed by Filter: 299 │
│ Planning time: 0.187 ms │
│ JIT: │
│ Functions: 4 │
│ Inlining: false │
│ Optimization: false │
│ Execution time: 72.229 ms │
└────────────────────────────────────────────────────────────────────────────────────────┘
(9 rows)

tpch_10[20923][1]=# ;explain (format text, analyze, timing on) SELECT relkind, relname FROM pg_class pgc WHERE relkind = 'r';

┌────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│ QUERY PLAN │
├────────────────────────────────────────────────────────────────────────────────────────────────────────────┤
│ Seq Scan on pg_class pgc (cost=0.00..15.70 rows=77 width=65) (actual time=40.570..40.651 rows=77 loops=1) │
│ Filter: (relkind = 'r'::"char") │
│ Rows Removed by Filter: 299 │
│ Planning time: 0.138 ms │
│ JIT: │
│ Functions: 4 │
│ Inlining: false │
│ Inlining Time: 0.000 │
│ Optimization: false │
│ Optimization Time: 5.023 │
│ Emission Time: 34.987 │
│ Execution time: 46.277 ms │
└────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(12 rows)

json (excerpt):
│ "Triggers": [ ↵│
│ ], ↵│
│ "JIT": { ↵│
│ "Functions": 4, ↵│
│ "Inlining": false, ↵│
│ "Inlining Time": 0.000, ↵│
│ "Optimization": false, ↵│
│ "Optimization Time": 9.701, ↵│
│ "Emission Time": 52.951 ↵│
│ }, ↵│
│ "Execution Time": 70.292 ↵│

I'm not at all wedded to the current format, but I feel like that's the
basic functionality needed?

Right now the JIT bit will only be displayed if at least one JITed
function has been emitted. Otherwise we'll just create noise for
everyone.

Currently a handful of explain outputs in the regression tests change
output when compiled with JITing. Therefore I'm thinking of adding
JITINFO or such option, which can be set to false for those tests?
Maintaining duplicate output for them seems painful. Better ideas?

Greetings,

Andres Freund