Re: BUG #17540: Prepared statement: PG switches to a generic query plan which is consistently much slower

Hi,

On 2022-07-06 15:07:46 -0700, David G. Johnston wrote:
> On Wed, Jul 6, 2022 at 2:41 PM PG Bug reporting form <noreply(at)postgresql(dot)org>
> wrote:
> > It is particularly insidious as actually I wasn't even aware I was using
> > prepared statements. Like most applications I use a database driver (pgx,
> > in
> > Go) which I learnt uses `PQexecPrepared` under the hood, which creates a
> > sort of "unnamed prepared statement" behaving the same as this minimal
> > reproduction without me ever being aware that prepared statements are
> > involved anywhere between my code and the database.
>
>
> Yep, and the core project pretty much says that if you don't like this you
> need to complain to the driver writer and ask them to provide you an
> interface to the unnamed parse-bind-execute API which lets you perform
> parameterization without memory, just safety.
>
> PostgreSQL has built the needed tools to make this less problematic, and
> has made solid attempts to improve matters in the current state of things.
> There doesn't seem to be a bug here. There is potentially room for
> improvement but no one presently is working on things in this area.

I think the cost for the slow plan being so much cheaper can almost be
qualified as bug.

The slow plan seems pretty nonsensical to me. ISTM that something in the
costing there is at least almost broken.

Result (cost=1.06..1.07 rows=1 width=16) (actual time=148.732..148.734 rows=1 loops=1)
Buffers: shared hit=4935
InitPlan 1 (returns $0)
-> Limit (cost=0.42..0.53 rows=1 width=8) (actual time=73.859..73.860 rows=0 loops=1)
Buffers: shared hit=2113
-> Index Scan using pk_rttx on relation_tuple_transaction (cost=0.42..9445.44 rows=86400 width=8) (actual time=73.857..73.858 rows=0 loops=1)
Index Cond: (id IS NOT NULL)
Filter: ("timestamp" >= $1)
Rows Removed by Filter: 259201
Buffers: shared hit=2113
InitPlan 2 (returns $1)
-> Limit (cost=0.42..0.53 rows=1 width=8) (actual time=74.869..74.870 rows=0 loops=1)
Buffers: shared hit=2822
-> Index Scan Backward using pk_rttx on relation_tuple_transaction relation_tuple_transaction_1 (cost=0.42..9445.44 rows=86400 width=8) (actual time=74.868..74.868 rows=0 loops=1)
Index Cond: (id IS NOT NULL)
Filter: ("timestamp" >= $1)
Rows Removed by Filter: 259201
Buffers: shared hit=2822
Planning Time: 0.224 ms
Execution Time: 148.781 ms

The planner assumes the table has 259201 rows. Somehow we end up
assuming that a estimate-less filter reduces the number of rows to 86400
both on a backward and a forward scan.

And for some reason we don't take the filter clause into account *at
all* for the cost of returning the first row.

SET enable_seqscan = false;
EXPLAIN SELECT * FROM relation_tuple_transaction WHERE id IS NOT NULL LIMIT 1;
┌─────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│ QUERY PLAN │
├─────────────────────────────────────────────────────────────────────────────────────────────────────────┤
│ Limit (cost=0.42..0.45 rows=1 width=16) │
│ -> Index Scan using pk_rttx on relation_tuple_transaction (cost=0.42..8797.44 rows=259201 width=16) │
│ Index Cond: (id IS NOT NULL) │
└─────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(3 rows)

It's also pointless that we use "Index Cond: (id IS NOT NULL)" for a
primary key index, but that's a minor thing.

Greetings,

Andres Freund