Thread: Performance degradation if query returns no rows and column expression is used after upgrading to 12

Hi!

Query returns no rows but its execution time in Postgres 12 depends on the column expression.

Query with  column expression

coalesce( (select sum(taitmata) from rid join dok using (dokumnr)
where toode=toode.toode and doktyyp='T' and not dok.taidetud and dok.kinnitatud and
taitmata is not null),0)

takes  666 ms :

explain analyze select
coalesce( (select sum(taitmata) from rid join dok using (dokumnr)
where toode=toode.toode and doktyyp='T' and not dok.taidetud and dok.kinnitatud and
taitmata is not null),0)
from toode
    where toode.ribakood='testmiin'::text
       or toode.nimetus ilike '%'||'testmiin'||'%' escape '!'
       or toode.toode ilike '%'||'testmiin'||'%' escape '!'
       or toode.markused ilike '%'||'testmiin'||'%' escape '!'
       or to_tsvector('english',toode.nimetus) @@ plainto_tsquery('testmiin')
         or to_tsvector('english',toode.engnimetus) @@  plainto_tsquery('testmiin')

"Gather  (cost=1000.00..505930.82 rows=153 width=32) (actual time=661.419..661.476 rows=0 loops=1)"
"  Workers Planned: 1"
"  Workers Launched: 1"
"  ->  Parallel Seq Scan on toode  (cost=0.00..10015.31 rows=90 width=21) (actual time=574.922..574.922 rows=0 loops=2)"
"        Filter: (((ribakood)::text = 'testmiin'::text) OR (nimetus ~~* '%testmiin%'::text) OR (toode ~~* '%testmiin%'::text) OR
(markused ~~* '%testmiin%'::text) OR (to_tsvector('english'::regconfig, (nimetus)::text) @@ plainto_tsquery('testmiin'::text)) OR
(to_tsvector('english'::regconfig, (engnimetus)::text) @@ plainto_tsquery('testmiin'::text)))"
"        Rows Removed by Filter: 7202"
"  SubPlan 1"
"    ->  Aggregate  (cost=3234.63..3234.64 rows=1 width=32) (never executed)"
"          ->  Nested Loop  (cost=11.26..3234.52 rows=43 width=3) (never executed)"
"                ->  Bitmap Heap Scan on rid  (cost=10.84..1191.72 rows=270 width=7) (never executed)"
"                      Recheck Cond: (toode = toode.toode)"
"                      Filter: (taitmata IS NOT NULL)"
"                      ->  Bitmap Index Scan on rid_toode_pattern_idx  (cost=0.00..10.77 rows=312 width=0) (never executed)"
"                            Index Cond: (toode = toode.toode)"
"                ->  Index Scan using dok_pkey on dok  (cost=0.42..7.57 rows=1 width=4) (never executed)"
"                      Index Cond: (dokumnr = rid.dokumnr)"
"                      Filter: ((NOT taidetud) AND kinnitatud AND (doktyyp = 'T'::bpchar))"
"Planning Time: 2.102 ms"
"JIT:"
"  Functions: 24"
"  Options: Inlining true, Optimization true, Expressions true, Deforming true"
"  Timing: Generation 5.592 ms, Inlining 95.077 ms, Optimization 463.742 ms, Emission 277.062 ms, Total 841.473 ms"
"Execution Time: 666.007 ms"

Same query with sime column expression

1

run 3.6 times faster:


explain analyze select 1
from toode
    where toode.ribakood='testmiin'::text
       or toode.nimetus ilike '%'||'testmiin'||'%' escape '!'
       or toode.toode ilike '%'||'testmiin'||'%' escape '!'
       or toode.markused ilike '%'||'testmiin'||'%' escape '!'
       or to_tsvector('english',toode.nimetus) @@ plainto_tsquery('testmiin')
         or to_tsvector('english',toode.engnimetus) @@
         plainto_tsquery('testmiin')

"Gather  (cost=1000.00..11030.61 rows=153 width=4) (actual time=182.414..185.648 rows=0 loops=1)"
"  Workers Planned: 1"
"  Workers Launched: 1"
"  ->  Parallel Seq Scan on toode  (cost=0.00..10015.31 rows=90 width=4) (actual time=155.338..155.339 rows=0 loops=2)"
"        Filter: (((ribakood)::text = 'testmiin'::text) OR (nimetus ~~* '%testmiin%'::text) OR (toode ~~* '%testmiin%'::text) OR
(markused ~~* '%testmiin%'::text) OR (to_tsvector('english'::regconfig, (nimetus)::text) @@ plainto_tsquery('testmiin'::text)) OR
(to_tsvector('english'::regconfig, (engnimetus)::text) @@ plainto_tsquery('testmiin'::text)))"
"        Rows Removed by Filter: 7202"
"Planning Time: 1.729 ms"
"Execution Time: 185.674 ms"

If there are more column expressions, perfomance difference is bigger.
rid  table used in column expression contains 1.8 million of rows.
Performance degradation probably occured if upgraded from Postgres 9.1 to Postgres 12

Since no data is returned query perfomance should be same.
How to fix it ?

Andrus.

Hi!

>on your query there is too slow JIT. Is strange how much. So the best way is disable JIT probably

>set jit to off;

>or same field in postgresql.conf

 

Thank you.

 

set jit to off 

 

makes select fast.

I have encountered this issue only in this query in one database

 

There is  variation of this query running with diferent data in different database in same Debian 10 server. It works fast.

Should I disable jit only for this query or in postgresql.conf permanently?

 

Andrus.

Hi!

 

>It is really strange why it is too slow. Can you prepare test case? Looks like bug (maybe not Postgres's bug)

 

Testcase is below.

With  jit on it takes 3.3 sec  and with jit off 1.5 sec.

 

Andrus.

 

create temp table toode ( toode char(20), ribakood char(20),

                         nimetus char(50), markused char(50), engnimetus char(50) ) on commit drop;

insert into toode (toode) select generate_series(1,14400);

CREATE INDEX ON toode USING gin

    (to_tsvector('english'::regconfig, nimetus::text));

CREATE UNIQUE INDEX    ON toode     (ribakood )

    WHERE ribakood IS NOT NULL AND btrim(ribakood::text) <> ''::text;

CREATE INDEX ON toode (toode);

CREATE UNIQUE INDEX    ON toode     (upper(toode::text) );

create temp table dok ( dokumnr serial  primary key ) on commit drop;

insert into dok  select generate_series(1,14400);

 

create temp table rid ( dokumnr int, taitmata numeric, toode char(20)  ) on commit drop;

insert into rid  select generate_series(1,1440000);

 

CREATE INDEX rid_dokumnr_idx    ON rid     (dokumnr );

-- jit on: 3.3 sec  jit off: 1.5 sec

set jit to off;

select

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

  (select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode )

 

from toode

where toode.ribakood='testmiin'::text

       or toode.nimetus ilike '%'||'testmiin'||'%' escape '!'

       or toode.toode ilike '%'||'testmiin'||'%' escape '!'

       or toode.markused ilike '%'||'testmiin'||'%' escape '!'

 

or to_tsvector('english',toode.nimetus) @@ plainto_tsquery('testmiin')

         or to_tsvector('english',toode.engnimetus) @@

         plainto_tsquery('testmiin') 

Hi

 

>this query is little bit strange - it has pretty big cost, and because returns nothing, then it's pretty fast against cost. 
>there is 18 subqueries, but jit_above_cost is ralated just to one query. This is probably worst case for JIT.

>This query is pretty slow and expensive (and then the cost of JIT is minimal), but when the query returns some rows, then JIT start to helps.
>So maybe if you find some queries that returns some rows, then the speed will be better with active JIT than with disabled JIT.

 

Below is modified testcase which returns one row.

In Debian 10 VPS with jit on it takes 2.5 sec  and with jit off  0.4 s

 

jit is still many times slower in Debian even if data is returned.

 

In Windows 10 workstation there is no difference.

 

>The situation when the query returns no rows, then JIT is significant bottleneck - but it looks like corner case.

 

Both testcases simulate search queries in typical e-shop.

Users can use any search term and expect that query returns fast.

 

Modified testcase which returns one row:

 

create temp table toode ( toode char(20) primary key, ribakood char(20),

                 nimetus char(50), markused char(50), engnimetus char(50) ) on commit drop;

insert into toode (toode) select generate_series(1,14400);

insert into toode (toode,nimetus)

select 'TEST'|| generate_series, 'This is testmiin item'

  from generate_series(1,1);

 

CREATE INDEX ON toode USING gin(to_tsvector('english'::regconfig, nimetus::text));

CREATE UNIQUE INDEX    ON toode (ribakood )

    WHERE ribakood IS NOT NULL AND btrim(ribakood::text) <> ''::text;

create temp table dok ( dokumnr serial  primary key ) on commit drop;

insert into dok  select generate_series(1,10000);

 

create temp table rid (id serial primary key,

                       dokumnr int references dok, taitmata numeric, toode char(20) references toode ) on commit drop;

insert into rid  (dokumnr,toode)

select generate_series % 10000+1, 1

from  generate_series(1,10000);

 

CREATE INDEX ON rid(dokumnr );

CREATE INDEX ON rid(toode);

-- jit on: 2.5 sec  jit off:  0.4 s

set jit to off;

select

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

  (select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode ) ,

(select sum(taitmata) from rid join dok using (dokumnr)  where toode=toode.toode )

 

from toode

where toode.ribakood='testmiin'::text

       or toode.nimetus ilike '%'||'testmiin'||'%' escape '!'

       or toode.toode ilike '%'||'testmiin'||'%' escape '!'

       or toode.markused ilike '%'||'testmiin'||'%' escape '!'

 

or to_tsvector('english',toode.nimetus) @@ plainto_tsquery('testmiin')

         or to_tsvector('english',toode.engnimetus) @@

         plainto_tsquery('testmiin') 

 

Andrus.