Обсуждение: JIT doing duplicative optimization?

Hello

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?

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:

 Planning Time: 15.060 ms
 JIT:
   Functions: 671
   Options: Inlining false, Optimization true, Expressions true, Deforming true
   Timing: Generation 75.205 ms, Inlining 0.000 ms, Optimization 1387.741 ms, Emission 1110.807 ms, Total 2573.753 ms
 Execution Time: 2587.776 ms

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?

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.

-- 
Álvaro Herrera

On 2021-Nov-11, Alvaro Herrera wrote:

> 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?

Ah, here's a query that illustrates what I'm on about.  I found this
query[1] in a blog post[2].

```
WITH RECURSIVE typeinfo_tree(
    oid, ns, name, kind, basetype, elemtype, elemdelim,
    range_subtype, attrtypoids, attrnames, depth)
AS (
    SELECT
        ti.oid, ti.ns, ti.name, ti.kind, ti.basetype,
        ti.elemtype, ti.elemdelim, ti.range_subtype,
        ti.attrtypoids, ti.attrnames, 0
    FROM
        (
        SELECT
            t.oid                           AS oid,
            ns.nspname                      AS ns,
            t.typname                       AS name,
            t.typtype                       AS kind,
            (CASE WHEN t.typtype = 'd' THEN
                (WITH RECURSIVE typebases(oid, depth) AS (
                    SELECT
                        t2.typbasetype      AS oid,
                        0                   AS depth
                    FROM
                        pg_type t2
                    WHERE
                        t2.oid = t.oid
                    UNION ALL
                    SELECT
                        t2.typbasetype      AS oid,
                        tb.depth + 1        AS depth
                    FROM
                        pg_type t2,
                        typebases tb
                    WHERE
                       tb.oid = t2.oid
                       AND t2.typbasetype != 0
               ) SELECT oid FROM typebases ORDER BY depth DESC LIMIT 1)
               ELSE NULL
            END)                            AS basetype,
            t.typelem                       AS elemtype,
            elem_t.typdelim                 AS elemdelim,
            range_t.rngsubtype              AS range_subtype,
            (CASE WHEN t.typtype = 'c' THEN
                (SELECT
                    array_agg(ia.atttypid ORDER BY ia.attnum)
                FROM
                    pg_attribute ia
                    INNER JOIN pg_class c
                        ON (ia.attrelid = c.oid)
                WHERE
                    ia.attnum > 0 AND NOT ia.attisdropped
                    AND c.reltype = t.oid)
                ELSE NULL
            END)                            AS attrtypoids,
            (CASE WHEN t.typtype = 'c' THEN
                (SELECT
                    array_agg(ia.attname::text ORDER BY ia.attnum)
                FROM
                    pg_attribute ia
                    INNER JOIN pg_class c
                        ON (ia.attrelid = c.oid)
                WHERE
                    ia.attnum > 0 AND NOT ia.attisdropped
                    AND c.reltype = t.oid)
                ELSE NULL
            END)                            AS attrnames
        FROM
            pg_catalog.pg_type AS t
            INNER JOIN pg_catalog.pg_namespace ns ON (
                ns.oid = t.typnamespace)
            LEFT JOIN pg_type elem_t ON (
                t.typlen = -1 AND
                t.typelem != 0 AND
                t.typelem = elem_t.oid
            )
            LEFT JOIN pg_range range_t ON (
                t.oid = range_t.rngtypid
            )
    ) AS ti
    WHERE
        ti.oid = any(ARRAY[16,17]::oid[])

    UNION ALL

    SELECT
        ti.oid, ti.ns, ti.name, ti.kind, ti.basetype,
        ti.elemtype, ti.elemdelim, ti.range_subtype,
        ti.attrtypoids, ti.attrnames, tt.depth + 1
    FROM
        (
        SELECT
            t.oid                           AS oid,
            ns.nspname                      AS ns,
            t.typname                       AS name,
            t.typtype                       AS kind,
            (CASE WHEN t.typtype = 'd' THEN
                (WITH RECURSIVE typebases(oid, depth) AS (
                    SELECT
                        t2.typbasetype      AS oid,
                        0                   AS depth
                    FROM
                        pg_type t2
                    WHERE
                        t2.oid = t.oid
                    UNION ALL
                    SELECT
                        t2.typbasetype      AS oid,
                        tb.depth + 1        AS depth
                    FROM
                        pg_type t2,
                        typebases tb
                    WHERE
                       tb.oid = t2.oid
                       AND t2.typbasetype != 0
               ) SELECT oid FROM typebases ORDER BY depth DESC LIMIT 1)
               ELSE NULL
            END)                            AS basetype,
            t.typelem                       AS elemtype,
            elem_t.typdelim                 AS elemdelim,
            range_t.rngsubtype              AS range_subtype,
            (CASE WHEN t.typtype = 'c' THEN
                (SELECT
                    array_agg(ia.atttypid ORDER BY ia.attnum)
                FROM
                    pg_attribute ia
                    INNER JOIN pg_class c
                        ON (ia.attrelid = c.oid)
                WHERE
                    ia.attnum > 0 AND NOT ia.attisdropped
                    AND c.reltype = t.oid)
                ELSE NULL
            END)                            AS attrtypoids,
            (CASE WHEN t.typtype = 'c' THEN
                (SELECT
                    array_agg(ia.attname::text ORDER BY ia.attnum)
                FROM
                    pg_attribute ia
                    INNER JOIN pg_class c
                        ON (ia.attrelid = c.oid)
                WHERE
                    ia.attnum > 0 AND NOT ia.attisdropped
                    AND c.reltype = t.oid)
                ELSE NULL
            END)                            AS attrnames
        FROM
            pg_catalog.pg_type AS t
            INNER JOIN pg_catalog.pg_namespace ns ON (
                ns.oid = t.typnamespace)
            LEFT JOIN pg_type elem_t ON (
                t.typlen = -1 AND
                t.typelem != 0 AND
                t.typelem = elem_t.oid
            )
            LEFT JOIN pg_range range_t ON (
                t.oid = range_t.rngtypid
            )
    ) ti,
        typeinfo_tree tt
    WHERE
        (tt.elemtype IS NOT NULL AND ti.oid = tt.elemtype)
        OR (tt.attrtypoids IS NOT NULL AND ti.oid = any(tt.attrtypoids))
        OR (tt.range_subtype IS NOT NULL AND ti.oid = tt.range_subtype)
)
SELECT DISTINCT
    *,
    basetype::regtype::text AS basetype_name,
    elemtype::regtype::text AS elemtype_name,
    range_subtype::regtype::text AS range_subtype_name
FROM
    typeinfo_tree
ORDER BY
    depth DESC;
```

I did an EXPLAIN ANALYZE and at the bottom you see this:

 Planning Time: 2.606 ms
 JIT:
   Functions: 148
   Options: Inlining true, Optimization true, Expressions true, Deforming true
   Timing: Generation 19.670 ms, Inlining 19.224 ms, Optimization 435.153 ms, Emission 282.216 ms, Total 756.263 ms
 Execution Time: 757.643 ms

Average time to optimize, per function 435.153/148 = 2.940ms;
average time to emit per function 282.216/148 = 1.906ms

Now let's change the query by making the first innermost recursive CTE into
non-recursive; just delete the RECURSIVE keyword and everything after the UNION
ALL.  You now get this query.

```
explain analyze
WITH RECURSIVE typeinfo_tree(
    oid, ns, name, kind, basetype, elemtype, elemdelim,
    range_subtype, attrtypoids, attrnames, depth)
AS (
    SELECT
        ti.oid, ti.ns, ti.name, ti.kind, ti.basetype,
        ti.elemtype, ti.elemdelim, ti.range_subtype,
        ti.attrtypoids, ti.attrnames, 0
    FROM
        (
        SELECT
            t.oid                           AS oid,
            ns.nspname                      AS ns,
            t.typname                       AS name,
            t.typtype                       AS kind,
            (CASE WHEN t.typtype = 'd' THEN
                (WITH typebases(oid, depth) AS (
                    SELECT
                        t2.typbasetype      AS oid,
                        0                   AS depth
                    FROM
                        pg_type t2
                    WHERE
                        t2.oid = t.oid
               ) SELECT oid FROM typebases ORDER BY depth DESC LIMIT 1)
               ELSE NULL
            END)                            AS basetype,
            t.typelem                       AS elemtype,
            elem_t.typdelim                 AS elemdelim,
            range_t.rngsubtype              AS range_subtype,
            (CASE WHEN t.typtype = 'c' THEN
                (SELECT
                    array_agg(ia.atttypid ORDER BY ia.attnum)
                FROM
                    pg_attribute ia
                    INNER JOIN pg_class c
                        ON (ia.attrelid = c.oid)
                WHERE
                    ia.attnum > 0 AND NOT ia.attisdropped
                    AND c.reltype = t.oid)
                ELSE NULL
            END)                            AS attrtypoids,
            (CASE WHEN t.typtype = 'c' THEN
                (SELECT
                    array_agg(ia.attname::text ORDER BY ia.attnum)
                FROM
                    pg_attribute ia
                    INNER JOIN pg_class c
                        ON (ia.attrelid = c.oid)
                WHERE
                    ia.attnum > 0 AND NOT ia.attisdropped
                    AND c.reltype = t.oid)
                ELSE NULL
            END)                            AS attrnames
        FROM
            pg_catalog.pg_type AS t
            INNER JOIN pg_catalog.pg_namespace ns ON (
                ns.oid = t.typnamespace)
            LEFT JOIN pg_type elem_t ON (
                t.typlen = -1 AND
                t.typelem != 0 AND
                t.typelem = elem_t.oid
            )
            LEFT JOIN pg_range range_t ON (
                t.oid = range_t.rngtypid
            )
    ) AS ti
    WHERE
        ti.oid = any(ARRAY[16,17]::oid[])

    UNION ALL

    SELECT
        ti.oid, ti.ns, ti.name, ti.kind, ti.basetype,
        ti.elemtype, ti.elemdelim, ti.range_subtype,
        ti.attrtypoids, ti.attrnames, tt.depth + 1
    FROM
        (
        SELECT
            t.oid                           AS oid,
            ns.nspname                      AS ns,
            t.typname                       AS name,
            t.typtype                       AS kind,
            (CASE WHEN t.typtype = 'd' THEN
                (WITH RECURSIVE typebases(oid, depth) AS (
                    SELECT
                        t2.typbasetype      AS oid,
                        0                   AS depth
                    FROM
                        pg_type t2
                    WHERE
                        t2.oid = t.oid
                    UNION ALL
                    SELECT
                        t2.typbasetype      AS oid,
                        tb.depth + 1        AS depth
                    FROM
                        pg_type t2,
                        typebases tb
                    WHERE
                       tb.oid = t2.oid
                       AND t2.typbasetype != 0
               ) SELECT oid FROM typebases ORDER BY depth DESC LIMIT 1)
               ELSE NULL
            END)                            AS basetype,
            t.typelem                       AS elemtype,
            elem_t.typdelim                 AS elemdelim,
            range_t.rngsubtype              AS range_subtype,
            (CASE WHEN t.typtype = 'c' THEN
                (SELECT
                    array_agg(ia.atttypid ORDER BY ia.attnum)
                FROM
                    pg_attribute ia
                    INNER JOIN pg_class c
                        ON (ia.attrelid = c.oid)
                WHERE
                    ia.attnum > 0 AND NOT ia.attisdropped
                    AND c.reltype = t.oid)
                ELSE NULL
            END)                            AS attrtypoids,
            (CASE WHEN t.typtype = 'c' THEN
                (SELECT
                    array_agg(ia.attname::text ORDER BY ia.attnum)
                FROM
                    pg_attribute ia
                    INNER JOIN pg_class c
                        ON (ia.attrelid = c.oid)
                WHERE
                    ia.attnum > 0 AND NOT ia.attisdropped
                    AND c.reltype = t.oid)
                ELSE NULL
            END)                            AS attrnames
        FROM
            pg_catalog.pg_type AS t
            INNER JOIN pg_catalog.pg_namespace ns ON (
                ns.oid = t.typnamespace)
            LEFT JOIN pg_type elem_t ON (
                t.typlen = -1 AND
                t.typelem != 0 AND
                t.typelem = elem_t.oid
            )
            LEFT JOIN pg_range range_t ON (
                t.oid = range_t.rngtypid
            )
    ) ti,
        typeinfo_tree tt
    WHERE
        (tt.elemtype IS NOT NULL AND ti.oid = tt.elemtype)
        OR (tt.attrtypoids IS NOT NULL AND ti.oid = any(tt.attrtypoids))
        OR (tt.range_subtype IS NOT NULL AND ti.oid = tt.range_subtype)
)

SELECT DISTINCT
    *,
    basetype::regtype::text AS basetype_name,
    elemtype::regtype::text AS elemtype_name,
    range_subtype::regtype::text AS range_subtype_name
FROM
    typeinfo_tree
ORDER BY
    depth DESC
```    

At the bottom of the explain you get this.

 Planning Time: 2.508 ms
 JIT:
   Functions: 137
   Options: Inlining true, Optimization true, Expressions true, Deforming true
   Timing: Generation 10.346 ms, Inlining 10.210 ms, Optimization 374.103 ms, Emission 254.557 ms, Total 649.216 ms
 Execution Time: 650.168 ms

Average time to optimize, per function: 374.103/137 = 2.730ms
Average time to emit, per function 254.557 / 137 = 1.858ms


Now do it one more time, with the second innermost recursive CTE.  You get this
query.

```
explain analyze
WITH RECURSIVE typeinfo_tree(
    oid, ns, name, kind, basetype, elemtype, elemdelim,
    range_subtype, attrtypoids, attrnames, depth)
AS (
    SELECT
        ti.oid, ti.ns, ti.name, ti.kind, ti.basetype,
        ti.elemtype, ti.elemdelim, ti.range_subtype,
        ti.attrtypoids, ti.attrnames, 0
    FROM
        (
        SELECT
            t.oid                           AS oid,
            ns.nspname                      AS ns,
            t.typname                       AS name,
            t.typtype                       AS kind,
            (CASE WHEN t.typtype = 'd' THEN
                (WITH typebases(oid, depth) AS (
                    SELECT
                        t2.typbasetype      AS oid,
                        0                   AS depth
                    FROM
                        pg_type t2
                    WHERE
                        t2.oid = t.oid
               ) SELECT oid FROM typebases ORDER BY depth DESC LIMIT 1)
               ELSE NULL
            END)                            AS basetype,
            t.typelem                       AS elemtype,
            elem_t.typdelim                 AS elemdelim,
            range_t.rngsubtype              AS range_subtype,
            (CASE WHEN t.typtype = 'c' THEN
                (SELECT
                    array_agg(ia.atttypid ORDER BY ia.attnum)
                FROM
                    pg_attribute ia
                    INNER JOIN pg_class c
                        ON (ia.attrelid = c.oid)
                WHERE
                    ia.attnum > 0 AND NOT ia.attisdropped
                    AND c.reltype = t.oid)
                ELSE NULL
            END)                            AS attrtypoids,
            (CASE WHEN t.typtype = 'c' THEN
                (SELECT
                    array_agg(ia.attname::text ORDER BY ia.attnum)
                FROM
                    pg_attribute ia
                    INNER JOIN pg_class c
                        ON (ia.attrelid = c.oid)
                WHERE
                    ia.attnum > 0 AND NOT ia.attisdropped
                    AND c.reltype = t.oid)
                ELSE NULL
            END)                            AS attrnames
        FROM
            pg_catalog.pg_type AS t
            INNER JOIN pg_catalog.pg_namespace ns ON (
                ns.oid = t.typnamespace)
            LEFT JOIN pg_type elem_t ON (
                t.typlen = -1 AND
                t.typelem != 0 AND
                t.typelem = elem_t.oid
            )
            LEFT JOIN pg_range range_t ON (
                t.oid = range_t.rngtypid
            )
    ) AS ti
    WHERE
        ti.oid = any(ARRAY[16,17]::oid[])

    UNION ALL

    SELECT
        ti.oid, ti.ns, ti.name, ti.kind, ti.basetype,
        ti.elemtype, ti.elemdelim, ti.range_subtype,
        ti.attrtypoids, ti.attrnames, tt.depth + 1
    FROM
        (
        SELECT
            t.oid                           AS oid,
            ns.nspname                      AS ns,
            t.typname                       AS name,
            t.typtype                       AS kind,
            (CASE WHEN t.typtype = 'd' THEN
                (WITH typebases(oid, depth) AS (
                    SELECT
                        t2.typbasetype      AS oid,
                        0                   AS depth
                    FROM
                        pg_type t2
                    WHERE
                        t2.oid = t.oid
               ) SELECT oid FROM typebases ORDER BY depth DESC LIMIT 1)
               ELSE NULL
            END)                            AS basetype,
            t.typelem                       AS elemtype,
            elem_t.typdelim                 AS elemdelim,
            range_t.rngsubtype              AS range_subtype,
            (CASE WHEN t.typtype = 'c' THEN
                (SELECT
                    array_agg(ia.atttypid ORDER BY ia.attnum)
                FROM
                    pg_attribute ia
                    INNER JOIN pg_class c
                        ON (ia.attrelid = c.oid)
                WHERE
                    ia.attnum > 0 AND NOT ia.attisdropped
                    AND c.reltype = t.oid)
                ELSE NULL
            END)                            AS attrtypoids,
            (CASE WHEN t.typtype = 'c' THEN
                (SELECT
                    array_agg(ia.attname::text ORDER BY ia.attnum)
                FROM
                    pg_attribute ia
                    INNER JOIN pg_class c
                        ON (ia.attrelid = c.oid)
                WHERE
                    ia.attnum > 0 AND NOT ia.attisdropped
                    AND c.reltype = t.oid)
                ELSE NULL
            END)                            AS attrnames
        FROM
            pg_catalog.pg_type AS t
            INNER JOIN pg_catalog.pg_namespace ns ON (
                ns.oid = t.typnamespace)
            LEFT JOIN pg_type elem_t ON (
                t.typlen = -1 AND
                t.typelem != 0 AND
                t.typelem = elem_t.oid
            )
            LEFT JOIN pg_range range_t ON (
                t.oid = range_t.rngtypid
            )
    ) ti,
        typeinfo_tree tt
    WHERE
        (tt.elemtype IS NOT NULL AND ti.oid = tt.elemtype)
        OR (tt.attrtypoids IS NOT NULL AND ti.oid = any(tt.attrtypoids))
        OR (tt.range_subtype IS NOT NULL AND ti.oid = tt.range_subtype)
)

SELECT DISTINCT
    *,
    basetype::regtype::text AS basetype_name,
    elemtype::regtype::text AS elemtype_name,
    range_subtype::regtype::text AS range_subtype_name
FROM
    typeinfo_tree
ORDER BY
    depth DESC;
```

And the JIT numbers at the bottom look like this:

 Planning Time: 2.041 ms
 JIT:
   Functions: 126
   Options: Inlining false, Optimization true, Expressions true, Deforming true
   Timing: Generation 10.002 ms, Inlining 0.000 ms, Optimization 229.128 ms, Emission 167.338 ms, Total 406.469 ms
 Execution Time: 407.315 ms

Average time to optimize per function 229.128 / 126 = 1.181ms
Average time to emit per function 167.338 / 126 = 1.328ms


In summary,

Query 1, 148 functions JIT-compiled.
Average time to optimize, per function 435.153/148 = 2.940ms;
average time to emit per function 282.216/148 = 1.906ms

Query 2, 137 functions JIT-compiled.
Average time to optimize, per function: 374.103/137 = 2.730ms
Average time to emit, per function 254.557 / 137 = 1.858ms

Query 3, 126 functions JIT-compiled.
Average time to optimize per function 229.128 / 126 = 1.181ms
Average time to emit per function 167.338 / 126 = 1.328ms

????  Something looks very wrong here.

[1] https://gist.github.com/saicitus/251ba20b211e9e73285af35e61b19580
[2]
https://dev.to/xenatisch/cascade-of-doom-jit-and-how-a-postgres-update-led-to-70-failure-on-a-critical-national-service-3f2a

-- 
Álvaro Herrera         PostgreSQL Developer  —  https://www.EnterpriseDB.com/
"Java is clearly an example of money oriented programming"  (A. Stepanov)

Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
> On 2021-Nov-11, Alvaro Herrera wrote:
>> 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?

> Ah, here's a query that illustrates what I'm on about.  I found this
> query[1] in a blog post[2].
> ...

> Query 1, 148 functions JIT-compiled.
> Average time to optimize, per function 435.153/148 = 2.940ms;
> average time to emit per function 282.216/148 = 1.906ms

> Query 2, 137 functions JIT-compiled.
> Average time to optimize, per function: 374.103/137 = 2.730ms
> Average time to emit, per function 254.557 / 137 = 1.858ms

> Query 3, 126 functions JIT-compiled.
> Average time to optimize per function 229.128 / 126 = 1.181ms
> Average time to emit per function 167.338 / 126 = 1.328ms

Yeah, in combination with your other measurement, it sure does look like
there's something worse-than-linear going on here.  The alternative is to
assume that the individual functions are more complex in one query than
the other, and that seems like a bit of a stretch.

You could probably generate some queries with lots and lots of expressions
to characterize this better.  If it is O(N^2), it should not be hard to
drive the cost up to the point where the guilty bit of code would stand
out in a perf trace.

            regards, tom lane

I wrote:
> You could probably generate some queries with lots and lots of expressions
> to characterize this better.  If it is O(N^2), it should not be hard to
> drive the cost up to the point where the guilty bit of code would stand
> out in a perf trace.

I experimented with that, using a few different-size queries generated
like this:

print "explain analyze\n";
for (my $i = 1; $i < 100; $i++) {
    print " select sum(f1+$i) from base union all\n";
}
print "select sum(f1+0) from base;\n";

on a table made like

create table base as select generate_series(1,10000000) f1;

What I got, after setting max_parallel_workers_per_gather = 0,
was

10 subqueries:

 Planning Time: 0.260 ms
 JIT:
   Functions: 30
   Options: Inlining true, Optimization true, Expressions true, Deforming true
   Timing: Generation 4.651 ms, Inlining 8.870 ms, Optimization 152.937 ms, Emis
sion 95.046 ms, Total 261.504 ms
 Execution Time: 15258.249 ms

100 subqueries:

 Planning Time: 2.231 ms
 JIT:
   Functions: 300
   Options: Inlining true, Optimization true, Expressions true, Deforming true
   Timing: Generation 44.163 ms, Inlining 9.934 ms, Optimization 1448.971 ms, Em
ission 928.438 ms, Total 2431.506 ms
 Execution Time: 154815.515 ms

1000 subqueries:

 Planning Time: 29.480 ms
 JIT:
   Functions: 3000
   Options: Inlining true, Optimization true, Expressions true, Deforming true
   Timing: Generation 444.479 ms, Inlining 25.688 ms, Optimization 14989.696 ms,
 Emission 9891.993 ms, Total 25351.856 ms
 Execution Time: 1522011.367 ms

So the overhead looks pretty linear, or even a shade sublinear for the
"inlining" bit, *as long as only one process is involved*.  However,
I noted that if I didn't force that, the JIT overhead went up because
the planner wanted to use more workers and each worker has to do its own
compilations.  So perhaps the apparent nonlinearity in your examples comes
from that?

BTW, I realized while working on this that I have little idea what the
"Functions:" count is.  Nor does our documentation explain that (or any
other of these numbers), at least not anywhere I could find.  That seems
like a pretty serious documentation fail.  If these numbers aren't
important enough to explain in the docs, why are we printing them at all?

            regards, tom lane

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

Hi,

On 2021-11-14 18:46:34 -0500, Tom Lane wrote:
> BTW, I realized while working on this that I have little idea what the
> "Functions:" count is.  Nor does our documentation explain that (or any
> other of these numbers), at least not anywhere I could find.  That seems
> like a pretty serious documentation fail.

It's literally the number of functions created in the JIT code. That could be
functions for evaluating one expression, or functions for deforming tuples of
one type of tupledesc. It's the simplest measure of "amount of JITed stuff" I
could find. I'd proposed a more detailed explain option where we'd optionally
print details about what exactly is JITed where a while back, but there were
some explain output format challenges...


> If these numbers aren't important enough to explain in the docs, why are we
> printing them at all?

Afaict we don't have detailed docs for EXPLAIN output in general?

Greetings,

Andres Freund