Обсуждение: Slow plan choice with prepared query

Hi,


I've experienced a situation where the planner seems to make a very poor 
choice with a prepared query after the first five executions.  Looking 
at the documentation, I think this happens because it switches from a 
custom plan to a generic one, and doesn't make a good choice for the 
generic one.

Postgres version: running in docker, reports to be 'Debian 14.1-1.pgdg110+1'

If I force it to use a custom plan via 'set local plan_cache_mode = 
force_custom_plan', then I don't notice any slowdown.  Without it, the 
6th and onwards calls can take 1 second to 15 seconds each, as opposed 
to about 10ms.

Since I have a workaround, I don't necessarily need assistance, but 
posting this here in case it's of value as a test case. Here's a test 
case that reliably duplicates this issue for me:

----

create table test (
   test_id serial primary key,
   data text
);

insert into test (data) (select data from (select 
generate_series(1,10000) AS id, md5(random()::text) AS data) x);

prepare foo_test(text, text, int, text, bool) as SELECT * FROM (SELECT
   *,
   count(*) OVER () > $3 AS has_more,
   row_number() OVER ()
   FROM (
     WITH counted AS (
       SELECT count(*) AS total
       FROM   (select test_id::text, data
from test
where
   (cast($1 as text) is null or lower(data) like '%' || lower($1) || '%')
and
   (cast($2 as text) is null or lower(test_id::text) like '%' || 
lower($2) || '%')) base
     ), cursor_row AS (
       SELECT base.test_id
       FROM   (select test_id::text, data
from test
where
   (cast($1 as text) is null or lower(data) like '%' || lower($1) || '%')
and
   (cast($2 as text) is null or lower(test_id::text) like '%' || 
lower($2) || '%')) base
       WHERE  base.test_id = $4
     )
     SELECT counted.*, base.*
       FROM   (select test_id::text, data
from test
where
   (cast($1 as text) is null or lower(data) like '%' || lower($1) || '%')
and
   (cast($2 as text) is null or lower(test_id::text) like '%' || 
lower($2) || '%')) base
       LEFT JOIN   cursor_row ON true
       LEFT JOIN   counted ON true
       WHERE ((
             $4 IS NULL OR cast($5 as bool) IS NULL
           ) OR (
             (base.test_id)
               > (cursor_row.test_id)
           ))
       ORDER BY base.test_id ASC
       LIMIT $3 + 1
) xy LIMIT $3 ) z ORDER BY row_number ASC;

\timing

execute foo_test(null, null, 5, 500, true);
execute foo_test(null, null, 5, 500, true);
execute foo_test(null, null, 5, 500, true);
execute foo_test(null, null, 5, 500, true);
execute foo_test(null, null, 5, 500, true);

-- This one should be slower:
execute foo_test(null, null, 5, 500, true);

Dag, if you ain't right!  I can duplicate this on the ones I tested 
with: PG v11 and v14.  Gonna start diving into this myself...

Regards,
Michael Vitale


Mark Saward wrote on 2/23/2022 10:37 PM:
> Hi,
>
>
> I've experienced a situation where the planner seems to make a very 
> poor choice with a prepared query after the first five executions.  
> Looking at the documentation, I think this happens because it switches 
> from a custom plan to a generic one, and doesn't make a good choice 
> for the generic one.
>
> Postgres version: running in docker, reports to be 'Debian 
> 14.1-1.pgdg110+1'
>
> If I force it to use a custom plan via 'set local plan_cache_mode = 
> force_custom_plan', then I don't notice any slowdown.  Without it, the 
> 6th and onwards calls can take 1 second to 15 seconds each, as opposed 
> to about 10ms.
>
> Since I have a workaround, I don't necessarily need assistance, but 
> posting this here in case it's of value as a test case. Here's a test 
> case that reliably duplicates this issue for me:
>
> ----
>
> create table test (
>   test_id serial primary key,
>   data text
> );
>
> insert into test (data) (select data from (select 
> generate_series(1,10000) AS id, md5(random()::text) AS data) x);
>
> prepare foo_test(text, text, int, text, bool) as SELECT * FROM (SELECT
>   *,
>   count(*) OVER () > $3 AS has_more,
>   row_number() OVER ()
>   FROM (
>     WITH counted AS (
>       SELECT count(*) AS total
>       FROM   (select test_id::text, data
> from test
> where
>   (cast($1 as text) is null or lower(data) like '%' || lower($1) || '%')
> and
>   (cast($2 as text) is null or lower(test_id::text) like '%' || 
> lower($2) || '%')) base
>     ), cursor_row AS (
>       SELECT base.test_id
>       FROM   (select test_id::text, data
> from test
> where
>   (cast($1 as text) is null or lower(data) like '%' || lower($1) || '%')
> and
>   (cast($2 as text) is null or lower(test_id::text) like '%' || 
> lower($2) || '%')) base
>       WHERE  base.test_id = $4
>     )
>     SELECT counted.*, base.*
>       FROM   (select test_id::text, data
> from test
> where
>   (cast($1 as text) is null or lower(data) like '%' || lower($1) || '%')
> and
>   (cast($2 as text) is null or lower(test_id::text) like '%' || 
> lower($2) || '%')) base
>       LEFT JOIN   cursor_row ON true
>       LEFT JOIN   counted ON true
>       WHERE ((
>             $4 IS NULL OR cast($5 as bool) IS NULL
>           ) OR (
>             (base.test_id)
>               > (cursor_row.test_id)
>           ))
>       ORDER BY base.test_id ASC
>       LIMIT $3 + 1
> ) xy LIMIT $3 ) z ORDER BY row_number ASC;
>
> \timing
>
> execute foo_test(null, null, 5, 500, true);
> execute foo_test(null, null, 5, 500, true);
> execute foo_test(null, null, 5, 500, true);
> execute foo_test(null, null, 5, 500, true);
> execute foo_test(null, null, 5, 500, true);
>
> -- This one should be slower:
> execute foo_test(null, null, 5, 500, true);
>
>
>

As per PG official documentation on PREPARE, it is working as expected.  
Use custom plan, but after 5th iteration compare cost of custom plan vs 
generic plan and use the one with the less cost which is the generic 
plan even though it is not as performant. Look at explain output to see 
the diffs between 5th iteration and 6th one:  explain (analyze, summary, 
buffers true) execute foo_test(null, null, 5, 500, true);

It appears the SORT is the problem and a mismatch between text and 
integer for base.text_id? --> WHERE  base.test_id = $4

Regards,
Michael Vitale



MichaelDBA wrote on 2/24/2022 1:45 PM:
> Dag, if you ain't right!  I can duplicate this on the ones I tested 
> with: PG v11 and v14.  Gonna start diving into this myself...
>
> Regards,
> Michael Vitale
>
>
> Mark Saward wrote on 2/23/2022 10:37 PM:
>> Hi,
>>
>>
>> I've experienced a situation where the planner seems to make a very 
>> poor choice with a prepared query after the first five executions. 
>> Looking at the documentation, I think this happens because it 
>> switches from a custom plan to a generic one, and doesn't make a good 
>> choice for the generic one.
>>
>> Postgres version: running in docker, reports to be 'Debian 
>> 14.1-1.pgdg110+1'
>>
>> If I force it to use a custom plan via 'set local plan_cache_mode = 
>> force_custom_plan', then I don't notice any slowdown.  Without it, 
>> the 6th and onwards calls can take 1 second to 15 seconds each, as 
>> opposed to about 10ms.
>>
>> Since I have a workaround, I don't necessarily need assistance, but 
>> posting this here in case it's of value as a test case. Here's a test 
>> case that reliably duplicates this issue for me:
>>
>> ----
>>
>> create table test (
>>   test_id serial primary key,
>>   data text
>> );
>>
>> insert into test (data) (select data from (select 
>> generate_series(1,10000) AS id, md5(random()::text) AS data) x);
>>
>> prepare foo_test(text, text, int, text, bool) as SELECT * FROM (SELECT
>>   *,
>>   count(*) OVER () > $3 AS has_more,
>>   row_number() OVER ()
>>   FROM (
>>     WITH counted AS (
>>       SELECT count(*) AS total
>>       FROM   (select test_id::text, data
>> from test
>> where
>>   (cast($1 as text) is null or lower(data) like '%' || lower($1) || '%')
>> and
>>   (cast($2 as text) is null or lower(test_id::text) like '%' || 
>> lower($2) || '%')) base
>>     ), cursor_row AS (
>>       SELECT base.test_id
>>       FROM   (select test_id::text, data
>> from test
>> where
>>   (cast($1 as text) is null or lower(data) like '%' || lower($1) || '%')
>> and
>>   (cast($2 as text) is null or lower(test_id::text) like '%' || 
>> lower($2) || '%')) base
>>       WHERE  base.test_id = $4
>>     )
>>     SELECT counted.*, base.*
>>       FROM   (select test_id::text, data
>> from test
>> where
>>   (cast($1 as text) is null or lower(data) like '%' || lower($1) || '%')
>> and
>>   (cast($2 as text) is null or lower(test_id::text) like '%' || 
>> lower($2) || '%')) base
>>       LEFT JOIN   cursor_row ON true
>>       LEFT JOIN   counted ON true
>>       WHERE ((
>>             $4 IS NULL OR cast($5 as bool) IS NULL
>>           ) OR (
>>             (base.test_id)
>>               > (cursor_row.test_id)
>>           ))
>>       ORDER BY base.test_id ASC
>>       LIMIT $3 + 1
>> ) xy LIMIT $3 ) z ORDER BY row_number ASC;
>>
>> \timing
>>
>> execute foo_test(null, null, 5, 500, true);
>> execute foo_test(null, null, 5, 500, true);
>> execute foo_test(null, null, 5, 500, true);
>> execute foo_test(null, null, 5, 500, true);
>> execute foo_test(null, null, 5, 500, true);
>>
>> -- This one should be slower:
>> execute foo_test(null, null, 5, 500, true);
>>
>>
>>
>
>
>