Search code examples
postgresqlquery-planner

Different execution plan for local PostgreSQL client for same query


For some reason, the same query executed locally and from my golang backend application uses different execution plans.

Flow of events: I have encountered an inefficient plan running from my backend application to the database. After connecting to the same PostgreSQL database with a PG client on my local machine (with the same user as the backend Application), I reproduced the query which takes >70ms. I then use my local PG client for adding an index and re-executing the query and the execution went down to <1ms.

It seems however that the same query keeps being executed from my backend Application and still takes >70ms which makes me think that the newly added index is not chosen. I excluded the potential reason that the backend Application query runs in a transaction by using BEGIN; and COMMIT; on my local PG client, with no change in results.

Despite my best efforts I was unable to understand the reason for this unusual behavior. Maybe someone here has an idea? How is this possible?

-- The index I added:
CREATE INDEX CONCURRENTLY mytable_temp ON mytable (poolid, id asc) where NOT used;
-- The query:
BEGIN;
explain analyze UPDATE
    mytable
SET
    used = true
WHERE
    id = (
        SELECT
            id
        FROM
            mytable
        WHERE (poolid = 9
            AND used = false
            AND((startdate IS NULL
                OR startdate <= '2021-12-03 18:12:16.952353384')
            AND(enddate IS NULL
                OR enddate >= '2021-12-03 18:12:16.952353384')))
    ORDER BY
        id ASC
    LIMIT 1
FOR UPDATE SKIP LOCKED)
RETURNING
    mytable.id,
    mytable.poolid,
    mytable.code,
    mytable.startdate,
    mytable.enddate,
    mytable.attributes,
    mytable.used,
    mytable.importid,
    mytable.created;
COMMIT;

The plan (when executed locally):

Update on mytable  (cost=0.92..2.93 rows=1 width=132) (actual time=0.091..0.092 rows=1 loops=1)
  InitPlan 1 (returns $1)
    ->  Limit  (cost=0.43..0.49 rows=1 width=10) (actual time=0.069..0.069 rows=1 loops=1)
          ->  LockRows  (cost=0.43..98599.17 rows=1699030 width=10) (actual time=0.068..0.069 rows=1 loops=1)
                ->  Index Scan using mytable_temp on mytable mytable_1  (cost=0.43..81608.87 rows=1699030 width=10) (actual time=0.065..0.065 rows=1 loops=1)
                      Index Cond: (poolid = 9)
"                      Filter: ((NOT used) AND ((startdate IS NULL) OR (startdate <= '2021-12-03 18:12:16.952353+00'::timestamp with time zone)) AND ((enddate IS NULL) OR (enddate >= '2021-12-03 18:12:16.952353+00'::timestamp with time zone)))"
  ->  Index Scan using mytable_pkey on mytable  (cost=0.43..2.45 rows=1 width=132) (actual time=0.081..0.081 rows=1 loops=1)
        Index Cond: (id = $1)
Planning Time: 0.146 ms
Execution Time: 0.120 ms

Solution

  • Investigation shows that the slow statement is a prepared statement, and the first few executions are fast. That is an almost certain proof that a mis-estimated generic plan is at fault. You can do the following:

    • improve PostgreSQL's estimates so that it doesn't choose that generic plan (best, but difficult)

    • set plan_cache_mode to force_custom_plan for this statement (from PostgreSQL v12 on)

    • avoid using a prepared statement for this query