Re: Postgres chooses slow query plan from time to time

2021-09-15 Thread Tom Lane
Kristjan Mustkivi  writes:
> Both are of type varchar(30).

Ah, right, you showed that back at the top of the thread.

> So is this something odd: Filter: (((product_code)::text = ($1)::text)
> AND ((balance_type)::text = ($4)::text)) ?

Yes, that is very darn odd.  When I try this I get:

regression=# create table foo(f1 varchar(30), f2 int, primary key (f2,f1));
CREATE TABLE

regression=# explain select * from foo where f2 = 11 and f1 = 'bar';
QUERY PLAN
--
 Index Only Scan using foo_pkey on foo  (cost=0.15..8.17 rows=1 width=37)
   Index Cond: ((f2 = 11) AND (f1 = 'bar'::text))
(2 rows)

regression=# explain select * from foo where f2 = 11 and f1::text = 'bar';
QUERY PLAN
--
 Index Only Scan using foo_pkey on foo  (cost=0.15..8.17 rows=1 width=37)
   Index Cond: ((f2 = 11) AND (f1 = 'bar'::text))
(2 rows)

regression=# prepare p as select * from foo where f2 = $1 and f1 = $2;
PREPARE

regression=# explain execute p(11,'bar');
QUERY PLAN
--
 Index Only Scan using foo_pkey on foo  (cost=0.15..8.17 rows=1 width=37)
   Index Cond: ((f2 = 11) AND (f1 = 'bar'::text))
(2 rows)

-- repeat a few times till it switches to a generic plan ...

regression=# explain execute p(11,'bar');
QUERY PLAN
--
 Index Only Scan using foo_pkey on foo  (cost=0.15..8.17 rows=1 width=37)
   Index Cond: ((f2 = $1) AND (f1 = $2))
(2 rows)

Note the lack of any visible cast on the varchar column, in each one of
these queries, even where I tried to force one to appear.  There is
something happening in your database that is not happening in mine.

My mind is now running to the possibility that you've got some extension
that creates an "=" operator that is capturing the syntax.

regards, tom lane




Re: Postgres chooses slow query plan from time to time

2021-09-15 Thread Kristjan Mustkivi
On Wed, Sep 15, 2021 at 3:16 PM Tom Lane  wrote:

> Note the lack of any visible cast on the varchar column, in each one of
> these queries, even where I tried to force one to appear.  There is
> something happening in your database that is not happening in mine.
>
> My mind is now running to the possibility that you've got some extension
> that creates an "=" operator that is capturing the syntax.
>
> regards, tom lane

The following extensions have been installed:

─[ RECORD 1 ]──
Name│ btree_gist
Version │ 1.5
Schema  │ public
Description │ support for indexing common datatypes in GiST
─[ RECORD 2 ]──
Name│ pg_stat_statements
Version │ 1.6
Schema  │ public
Description │ track execution statistics of all SQL statements executed
─[ RECORD 3 ]──
Name│ pgcrypto
Version │ 1.3
Schema  │ public
Description │ cryptographic functions
─[ RECORD 4 ]──
Name│ plpgsql
Version │ 1.0
Schema  │ pg_catalog
Description │ PL/pgSQL procedural language

Plus the some libraries preloaded: shared_preload_libraries =
'pg_stat_statements,pg_cron,auto_explain'

Thank you so much for looking into this!

Best regards,
-- 
Kristjan Mustkivi

Email: [email protected]


Re: Postgres chooses slow query plan from time to time

2021-09-15 Thread Tom Lane
Kristjan Mustkivi  writes:
> On Wed, Sep 15, 2021 at 3:16 PM Tom Lane  wrote:
>> Note the lack of any visible cast on the varchar column, in each one of
>> these queries, even where I tried to force one to appear.  There is
>> something happening in your database that is not happening in mine.

> The following extensions have been installed:
> [ nothing very exciting ]

I still get the same results after installing those extensions.

I realized that the reason I don't see a cast is that
fix_indexqual_operand removes the cast from an index qualifier
expression's index-column side.  In any other context, there would
be a cast there, since the operator is =(text,text) not
=(varchar,varchar).  So that seems like a red herring ... or is it?
Now I'm confused by your original report, in which you show

>>> ->  Index Scan using mytable_pk on mytable pbh (cost=0.70..176.82 
>>> rows=186 width=66) (actual time=1.001..8.610 rows=25 loops=1)
>>>   Index Cond: ((cage_code = 123) AND (cage_player_id = 
>>> '12345'::bigint) AND ((product_code)::text = 'PRODUCT'::text) AND 
>>> ((balance_type)::text = 'TOTAL'::text))
>>>   Filter: (modified_time < '2021-09-13 04:00:00+00'::timestamp 
>>> with time zone)

According to the code I just looked at, there should absolutely not
be casts on the product_code and balance_type index columns here.
So I'm not quite sure what's up ... -ENOCAFFEINE perhaps.

Nonetheless, this point is probably just a sideshow.  The above
EXPLAIN output proves that the planner *can* match this index,
which destroys my idea that you had a datatype mismatch preventing
it from doing so.

After looking again at the original problem, I think you are getting
bit by an issue we've seen before.  The planner is coming out with
a decently accurate cost estimate for the query when specific values
are inserted for the parameters.  However, when it considers a generic
version of the query with no known parameter values, the cost estimates
are not so good, and by chance it comes out estimating a very low cost
for the alternative plan that uses the other index.  That cost is not
right, but the planner doesn't know that, so it seizes on that plan.

This is a hard problem to fix, and we don't have a good answer for it.
In v12 and up, you can use the big hammer of disabling generic plans by
setting plan_cache_mode to "force_custom_plan", but v11 doesn't have
that parameter.  You might need to avoid using a prepared statement for
this query.

regards, tom lane