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

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 Andreas,

yes, it is a reduced test case from a very long query.

Thank you,

*Jakub Janeček*
IT Specialist
jakub.janecek@comgate.cz
+420 603 488 306 <//+420603488306>

[image: ComGate logo] <http://www.comgate.cz/cz?utm_source=email_podpis&gt;

ComGate, Gočárova třída 1754/48b, Pražské předměstí, 500 02 Hradec Králové
www.comgate.cz <http://www.comgate.cz/cz?utm_source=email_podpis&gt;

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