Re: JIT doing duplicative optimization?

Hi,

On 2021-11-11 17:02:09 -0300, Alvaro Herrera wrote:
> Recently I noticed extremely suspicious behavior from queries under JIT.
> A query (details for which sadly I cannot disclose) had an EXPLAIN
> looking like this:
>
> JIT:
> Functions: 743
> Options: Inlining true, Optimization true, Expressions true, Deforming true
> Timing: Generation 47.013 ms, Inlining 20.277 ms, Optimization 3269.381 ms, Emission 2392.115 ms, Total 5728.786 ms
> Execution Time: 5735.552 ms
>
> Disabling JIT, the query takes a few tens of milliseconds, so of course
> the typical recommendation is to disable JIT. But I noted that the
> average time to optimize, per function, is 4.7ms. I didn't know what to
> make of this -- is it a reasonable to to take to optimize a single
> function?

No, that's pretty insane. Any chance you share the generated bitcode for this
- it'll have some details about the query / table structure though. Perhaps
just the contained function names?

> I put that thought aside. But then I spotted a couple of minor things
> in the query that could be made better; so I did some of that, and
> noticed that the number of functions was reduced from 743 to 671, and
> the JIT details in the explain looked like this:

> But what really surprised me is that the the average time to optimize
> per function is now 2.06ms ... less than half of the previous
> measurement. It emits 10% less functions than before, but the time to
> both optimize and emit is reduced by 50%. How does that make sense?

Without knowing the concrete query I don't know if it it's that. But

> I don't know how to approach an investigation into this, but I thought
> that maybe we're doing quadratic effort in the optimization / emission
> phase or something like that.

Yea. One way to investigate it is to enable jit_dump_bitcode and then use
llvm's 'opt' tool to see details about optimization times.

opt -time-passes -O3 -o /dev/null < /srv/dev/pgdev-dev/3990041.77.bc |less

Greetings,

Andres Freund