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