Thread: BUG #15486: PG11 jit on 50x slower than jit off

The following bug has been logged on the website:

Bug reference:      15486
Logged by:          Jakub Janeček
Email address:      jakub.janecek@comgate.cz
PostgreSQL version: 11.0
Operating system:   Debian 9
Description:

Hi team,

we have a problem with PG11 and JIT. Execution time with JIT ON is slower
than JIT OFF. PostgreSQL is running on Debian in LXC Container on Proxmox
VE.

Here is some example:

create table t(a int);
insert into t select generate_series from generate_series(1, 100000);
analyze t;
set jit to off;

explain analyze SELECT  
    ARRAY( SELECT DISTINCT unnest(array[]::integer[] || t.a) AS unnest) AS
c1,
    ARRAY( SELECT DISTINCT unnest(((((array[]::integer[]))) || t.a)) AS
unnest) AS c2
   FROM t
;

set jit to on;

explain analyze SELECT  
    ARRAY( SELECT DISTINCT unnest(array[]::integer[] || t.a) AS unnest) AS
c1,
    ARRAY( SELECT DISTINCT unnest(((((array[]::integer[]))) || t.a)) AS
unnest) AS c2
   FROM t
;

show jit_provider;

Here are results:

JIT OFF
QUERY PLAN
--------------------------------------------------------------------------------------------------------------
 Seq Scan on t  (cost=0.00..455443.00 rows=100000 width=64) (actual
time=0.032..1047.012 rows=100000 loops=1)
   SubPlan 1
     ->  HashAggregate  (cost=0.77..2.27 rows=100 width=4) (actual
time=0.001..0.002 rows=1 loops=100000)
           Group Key: unnest(('{}'::integer[] || t.a))
           ->  ProjectSet  (cost=0.00..0.52 rows=100 width=4) (actual
time=0.001..0.001 rows=1 loops=100000)
                 ->  Result  (cost=0.00..0.01 rows=1 width=0) (actual
time=0.000..0.000 rows=1 loops=100000)
   SubPlan 2
     ->  HashAggregate  (cost=0.77..2.27 rows=100 width=4) (actual
time=0.001..0.002 rows=1 loops=100000)
           Group Key: unnest(('{}'::integer[] || t.a))
           ->  ProjectSet  (cost=0.00..0.52 rows=100 width=4) (actual
time=0.001..0.001 rows=1 loops=100000)
                 ->  Result  (cost=0.00..0.01 rows=1 width=0) (actual
time=0.000..0.000 rows=1 loops=100000)
 Planning Time: 0.162 ms
 Execution Time: 1099.676 ms
(13 rows)
--------------------

JIT ON
 QUERY PLAN
---------------------------------------------------------------------------------------------------------------------
 Seq Scan on t  (cost=0.00..455443.00 rows=100000 width=64) (actual
time=12.979..57391.188 rows=100000 loops=1)
   SubPlan 1
     ->  HashAggregate  (cost=0.77..2.27 rows=100 width=4) (actual
time=0.004..0.004 rows=1 loops=100000)
           Group Key: unnest(('{}'::integer[] || t.a))
           ->  ProjectSet  (cost=0.00..0.52 rows=100 width=4) (actual
time=0.002..0.002 rows=1 loops=100000)
                 ->  Result  (cost=0.00..0.01 rows=1 width=0) (actual
time=0.000..0.000 rows=1 loops=100000)
   SubPlan 2
     ->  HashAggregate  (cost=0.77..2.27 rows=100 width=4) (actual
time=0.004..0.004 rows=1 loops=100000)
           Group Key: unnest(('{}'::integer[] || t.a))
           ->  ProjectSet  (cost=0.00..0.52 rows=100 width=4) (actual
time=0.002..0.002 rows=1 loops=100000)
                 ->  Result  (cost=0.00..0.01 rows=1 width=0) (actual
time=0.000..0.000 rows=1 loops=100000)
 Planning Time: 0.092 ms
 JIT:
   Functions: 600016
   Options: Inlining false, Optimization false, Expressions true, Deforming
true
   Timing: Generation 55262.932 ms, Inlining 0.000 ms, Optimization 0.481
ms, Emission 12.218 ms, Total 55275.631 ms
 Execution Time: 70522.785 ms
(17 rows)
------------------

If you need more details, do not hesitate to contact me.

Thank you,
best regards,

Jakub Janecek

Hi,

On 2018-11-05 08:10:17 +0000, PG Bug reporting form wrote:
> Here is some example:
> 
> create table t(a int);
> insert into t select generate_series from generate_series(1, 100000);
> analyze t;
> set jit to on;
> 
> explain analyze SELECT  
>     ARRAY( SELECT DISTINCT unnest(array[]::integer[] || t.a) AS unnest) AS
> c1,
>     ARRAY( SELECT DISTINCT unnest(((((array[]::integer[]))) || t.a)) AS
> unnest) AS c2
>    FROM t
> ;
> 

>  JIT:
>    Functions: 600016

Clearly the problem is that we're generating an absolutely absurd number
of functions. I'll try to look into why soon.

Thanks for the reproducible test case!

I assume this isn't quite a real case, but something real reduced into a
small testcase?

Greetings,

Andres Freund

Hi,

On 2018-11-05 08:10:17 +0000, PG Bug reporting form wrote:
> we have a problem with PG11 and JIT. Execution time with JIT ON is slower
> than JIT OFF. PostgreSQL is running on Debian in LXC Container on Proxmox
> VE.
> 
> Here is some example:
> 
> create table t(a int);
> insert into t select generate_series from generate_series(1, 100000);
> analyze t;
> set jit to off;
> 
> explain analyze SELECT  
>     ARRAY( SELECT DISTINCT unnest(array[]::integer[] || t.a) AS unnest) AS
> c1,
>     ARRAY( SELECT DISTINCT unnest(((((array[]::integer[]))) || t.a)) AS
> unnest) AS c2
>    FROM t
> ;
> 
> set jit to on;
> 
> explain analyze SELECT  
>     ARRAY( SELECT DISTINCT unnest(array[]::integer[] || t.a) AS unnest) AS
> c1,
>     ARRAY( SELECT DISTINCT unnest(((((array[]::integer[]))) || t.a)) AS
> unnest) AS c2
>    FROM t
> ;
> 

> Here are results:

>    Timing: Generation 55262.932 ms, Inlining 0.000 ms, Optimization 0.481
> ms, Emission 12.218 ms, Total 55275.631 ms
>  Execution Time: 70522.785 ms
> (17 rows)
> ------------------

Thanks for the handy reproducer!

The relevant call stack out of which most of the JIT compilation happens
is:
#11 0x0000560b5baa312a in jit_compile_expr (state=0x560b5d5d25c0)
    at /home/andres/src/postgresql/src/backend/jit/jit.c:180
#12 0x0000560b5b6ca191 in ExecReadyExpr (state=0x560b5d5d25c0)
    at /home/andres/src/postgresql/src/backend/executor/execExpr.c:628
#13 0x0000560b5b6cfe43 in ExecBuildGroupingEqual (ldesc=0x560b5d5dffa8, rdesc=0x560b5d5dffa8, 
    lops=0x560b5bd7d9c0 <TTSOpsMinimalTuple>, rops=0x560b5bd7d9c0 <TTSOpsMinimalTuple>, numCols=1, 
    keyColIdx=0x560b5d5dff28, eqfunctions=0x560b5d5e00c0, parent=0x560b5d5b7e90)
    at /home/andres/src/postgresql/src/backend/executor/execExpr.c:3449
#14 0x0000560b5b6d8b10 in BuildTupleHashTable (parent=0x560b5d5b7e90, inputDesc=0x560b5d5dffa8, 
    numCols=1, keyColIdx=0x560b5d5dff28, eqfuncoids=0x560b5d5e00c0, hashfunctions=0x560b5d5e00e0, 
    nbuckets=100, additionalsize=0, tablecxt=0x560b5d5d11f0, tempcxt=0x560b5d5cd1d0, 
    use_variable_hash_iv=false) at /home/andres/src/postgresql/src/backend/executor/execGrouping.c:211
#15 0x0000560b5b6f6155 in build_hash_table (aggstate=0x560b5d5b7e90)
    at /home/andres/src/postgresql/src/backend/executor/nodeAgg.c:1280
#16 0x0000560b5b6fa1f1 in ExecReScanAgg (node=0x560b5d5b7e90)
    at /home/andres/src/postgresql/src/backend/executor/nodeAgg.c:3444
#17 0x0000560b5b6c8491 in ExecReScan (node=0x560b5d5b7e90)
    at /home/andres/src/postgresql/src/backend/executor/execAmi.c:261
#18 0x0000560b5b71ec64 in ExecScanSubPlan (node=0x560b5d5e1e28, econtext=0x560b5d5e0a58, 
    isNull=0x560b5d5e0ed5) at /home/andres/src/postgresql/src/backend/executor/nodeSubplan.c:298
#19 0x0000560b5b71e72c in ExecSubPlan (node=0x560b5d5e1e28, econtext=0x560b5d5e0a58, 
    isNull=0x560b5d5e0ed5) at /home/andres/src/postgresql/src/backend/executor/nodeSubplan.c:90
#20 0x0000560b5b6d6850 in ExecEvalSubPlan (state=0x560b5d5e0ed0, op=0x560b5d5e1020, 
    econtext=0x560b5d5e0a58) at /home/andres/src/postgresql/src/backend/executor/execExprInterp.c:3770

So what happens is that we currently generate an expression whenever
BuildTupleHashTable() is called - which generally sounds sane. But in
this specific case the BuildTupleHashTable() is called many many times,
because we reset the subplans (the correlated aubqueries) for every
input row.

This actually isn't great outside of JIT compilation as well - we waste
a substantial portion of time rebuilding the expression everytime, and
the hashtable grows every time as well.

I see three possible solutions:

1) Move ExecBuildGroupingEqual to BuildTupleHashTable callers and pass
   it in. That way we don't need to rebuild the expression, but would
   still pay the price of re-allocating the hashtable itself.
2) Create a new ResetTupleHashTable that reuses the TupleHashTable, but
   recreates hashtable->hashtab afresh.
3) Create a new ResetTupleHashTable that iterates over the hashtable and
   resets the fields.

I'm somewhat opposed to 1) as that'll require breaking existing APIs in
11, and exposes more details to the outside than necessary.  I don't
really have an opinion between 2) and 3) - 2) is better if the
inputsizes are very irregular with only a few large hashtables between
resets, 3) is much better when the predicted size is correct or
commonlytoo small.

Comments?

Greetings,

Andres Freund

>>>>> "Andres" == Andres Freund <andres@anarazel.de> writes:

 Andres> This actually isn't great outside of JIT compilation as well -
 Andres> we waste a substantial portion of time rebuilding the
 Andres> expression everytime, and the hashtable grows every time as
 Andres> well.

Why would the hashtable grow? All of BuildTupleHashTable's callers
follow this pattern: the hashtable is allocated in a memory context that
will be reset on every rescan. Everything the hash table initialization
does is assumed to be completely discardable.

Which means that if you want to add a ResetTupleHashTable, it'll mean
significant reorganization of the callers' use of memory contexts, since
the hashtable will have to go into per-query memory (and presumably
create a child context of its own).

(There's an implicit assumption by all of BuildTupleHashTable's callers
that it will not allocate anything outside of the passed-in tablecxt,
which will be reset. Having BuildTupleHashTable allocate anything in its
caller's context is effectively an API break. But I notice this
_already_ got broken in pg11: the ExprContext that now gets allocated in
BuildTupleHashTable will be leaked into per-query memory on each cycle.)

-- 
Andrew (irc:RhodiumToad)

Hi,

On 2018-11-05 08:10:17 +0000, PG Bug reporting form wrote:
> The following bug has been logged on the website:
> 
> Bug reference:      15486
> Logged by:          Jakub Janeček
> Email address:      jakub.janecek@comgate.cz
> PostgreSQL version: 11.0
> Operating system:   Debian 9
> Description:        
> 
> Hi team,
> 
> we have a problem with PG11 and JIT. Execution time with JIT ON is slower
> than JIT OFF. PostgreSQL is running on Debian in LXC Container on Proxmox
> VE.

I've now pushed a fix. It should be included in the next set of minor
releases, which are expected next week.  Thanks for the report!

Greetings,

Andres Freund