Differents execution times with gin index, prepared statement and literals.

Hello,

One of our customer is facing an issue regarding a prepared statement and a gin index.
An important gap between execution times can be shown when using execute or plain literals.

Here is the test that shown this issue :

Init table :

create table tmp_tk_test_index
(
    sync_id           bigint,
    line_id           varchar(50),
    chk_upgrade_index smallint default 0
);

create index idx_tmp_tk_test_index_1
    on tmp_tk_test_index using gin (sync_id, line_id);

insert into tmp_tk_test_index SELECT tb_seq as sync_id, case when tb_seq = 950000 then 'the-test-value-fa529a621a15' else gen_random_uuid()::text end as line_id FROM generate_series(1,1000000) as tb_seq;

Prepare query :

prepare  stmt(bigint, text, int) as delete from  tmp_tk_test_index where sync_id <= $1 and line_id = $2 and chk_upgrade_index = $3;

And then execute it :

postgres=# begin;
BEGIN
postgres=*# explain (analyse) execute stmt(950000, 'the-test-value-fa529a621a15', 0);
                                                                 QUERY PLAN                                            

              

-----------------------------------------------------------------------------------------------------------------------

 Delete on tmp_tk_test_index  (cost=212.52..2662.59 rows=0 width=0) (actual time=60.766..60.767 rows=0 loops=1)

   ->  Bitmap Heap Scan on tmp_tk_test_index  (cost=212.52..2662.59 rows=4 width=6) (actual time=60.756..60.758 rows=1 

loops=1)

         Recheck Cond: ((sync_id <= '950000'::bigint) AND ((line_id)::text = 'the-test-value-fa529a621a15'::text))

         Filter: (chk_upgrade_index = 0)

         Heap Blocks: exact=1

         ->  Bitmap Index Scan on idx_tmp_tk_test_index_1  (cost=0.00..212.52 rows=810 width=0) (actual time=60.745..60

.745 rows=1 loops=1)

               Index Cond: ((sync_id <= '950000'::bigint) AND ((line_id)::text = 'the-test-value-fa529a621a15'::text))

 Planning Time: 6.765 ms

 Execution Time: 61.160 ms

(9 rows)
postgres=*# rollback ;
ROLLBACK

It takes 61.160ms to be executed. However, the "same" query without a prepared statement is far faster :

postgres=# begin;
BEGIN
postgres=*# explain analyze delete from  tmp_tk_test_index where sync_id <= 950000 and line_id = 'the-test-value-fa529a621a15' and chk_upgrade_index = 0;

                                                              QUERY PLAN                                               

-----------------------------------------------------------------------------------------------------------------------

----------------

 Delete on tmp_tk_test_index  (cost=21.36..25.38 rows=0 width=0) (actual time=0.084..0.085 rows=0 loops=1)

   ->  Bitmap Heap Scan on tmp_tk_test_index  (cost=21.36..25.38 rows=1 width=6) (actual time=0.042..0.043 rows=1 loops

=1)

         Recheck Cond: ((line_id)::text = 'the-test-value-fa529a621a15'::text)

         Filter: ((sync_id <= 950000) AND (chk_upgrade_index = 0))

         Heap Blocks: exact=1

         ->  Bitmap Index Scan on idx_tmp_tk_test_index_1  (cost=0.00..21.36 rows=1 width=0) (actual time=0.027..0.028 

rows=1 loops=1)

               Index Cond: ((line_id)::text = 'the-test-value-fa529a621a15'::text)

 Planning Time: 0.325 ms

 Execution Time: 0.148 ms

(9 rows)

postgres=*# rollback ;

ROLLBACK

Only 0.148ms to be executed...

What can cause this quite important gap ? (0.148ms vs 61.160ms).
In the explain plan, I can see that the Index Cond is different : in the slowest case (sync_id <= '950000'::bigint) is present.
Why isn't it present in the second case ?

Two more tests :

The prepared statement is tweaked with sync_id+0. The query is fast :

prepare stmt3(bigint, text, int) as delete from tmp_tk_test_index where sync_id+0 <= $1 and line_id = $2 and chk_upgrade_index = $3;
explain (analyse) execute stmt3(950000, 'the-test-value-fa529a621a15', 0);

Delete on tmp_tk_test_index  (cost=21.36..25.38 rows=0 width=0) (actual time=0.057..0.058 rows=0 loops=1)

   ->  Bitmap Heap Scan on tmp_tk_test_index  (cost=21.36..25.38 rows=1 width=6) (actual time=0.040..0.042 rows=1 loops

=1)

         Recheck Cond: ((line_id)::text = 'the-test-value-fa529a621a15'::text)

         Filter: ((chk_upgrade_index = 0) AND ((sync_id + 0) <= '950000'::bigint))

         Heap Blocks: exact=1

         ->  Bitmap Index Scan on idx_tmp_tk_test_index_1  (cost=0.00..21.36 rows=1 width=0) (actual time=0.020..0.020 

rows=1 loops=1)

               Index Cond: ((line_id)::text = 'the-test-value-fa529a621a15'::text)

 Planning Time: 0.355 ms

 Execution Time: 0.101 ms

(9 rows)

And one with an index but without sync_id inside it. Prepared statement isn't changed.

create index idx_tmp_tk_test_index_2 on tmp_tk_test_index using gin (line_id);

 Delete on tmp_tk_test_index  (cost=21.36..25.38 rows=0 width=0) (actual time=0.052..0.053 rows=0 loops=1)
   ->  Bitmap Heap Scan on tmp_tk_test_index  (cost=21.36..25.38 rows=1 width=6) (actual time=0.036..0.038 rows=1 loops
=1)
         Recheck Cond: ((line_id)::text = 'the-test-value-fa529a621a15'::text)
         Filter: ((sync_id <= '950000'::bigint) AND (chk_upgrade_index = 0))
         Heap Blocks: exact=1
         ->  Bitmap Index Scan on idx_tmp_tk_test_index_2  (cost=0.00..21.36 rows=1 width=0) (actual time=0.020..0.021 
rows=1 loops=1)
               Index Cond: ((line_id)::text = 'the-test-value-fa529a621a15'::text)
 Planning Time: 0.439 ms
 Execution Time: 0.098 ms
(9 rows

Quite fast as well...

Have you got an idea on the initial issue ? Why when using a prepared statement and a gin index the execution time "explode" ?
Something to do with the planner ? optimizer ?

(We executed the same test with a btree index and execution times are the same in both cases).

Regards