BUG #19076: Generic query plan is extremely slow - Mailing list pgsql-bugs

From PG Bug reporting form
Subject BUG #19076: Generic query plan is extremely slow
Date
Msg-id 19076-4d897c04a44a9627@postgresql.org
Whole thread Raw
Responses Re: BUG #19076: Generic query plan is extremely slow
List pgsql-bugs
The following bug has been logged on the website:

Bug reference:      19076
Logged by:          Premal Patel
Email address:      premal.patel@veeva.com
PostgreSQL version: 17.6
Operating system:   macOS 15.6.1 (observed on other Linux based OS)
Description:

I have an application which uses a database driver that creates prepared
statements. I am noticing that for some queries, the first 5 executions
after the database connection is created are performant. After this, the
prepared statement uses the generic query plan and is incredibly slow. This
is even if I do not change the parameters and simple re-run the same query
several times with the same arguments. I have tried re-running ANALYZE on
the tables and setting STATISTICS to 1000 on the rows in question with no
luck. Here is what my query looks like:

SELECT accounts_contacts.account_id, count(contacts.id) AS count
    FROM accounts_contacts JOIN contacts ON contacts.id =
accounts_contacts.contact_id
    WHERE accounts_contacts.account_id IN (...) AND contacts.tenant_id =
$1::UUID AND contacts.status = $2::VARCHAR
GROUP BY accounts_contacts.account_id

Here is the EXPLAIN output from the first 5 executions using the custom
query plan:

Finalize HashAggregate  (cost=47034.52..47131.24 rows=9672 width=24) (actual
time=103.173..103.822 rows=1000 loops=1)
      Group Key: accounts_contacts.account_id
      Batches: 1  Memory Usage: 465kB
      ->  Gather  (cost=44906.68..46937.80 rows=19344 width=24) (actual
time=102.801..103.506 rows=2326 loops=1)
            Workers Planned: 2
            Workers Launched: 2
            ->  Partial HashAggregate  (cost=43906.68..44003.40 rows=9672
width=24) (actual time=93.682..93.757 rows=775 loops=3)
                  Group Key: accounts_contacts.account_id
                  Batches: 1  Memory Usage: 465kB
                  Worker 0:  Batches: 1  Memory Usage: 465kB
                  Worker 1:  Batches: 1  Memory Usage: 465kB
                  ->  Hash Join  (cost=6066.79..43819.26 rows=17484
width=32) (actual time=12.902..92.674 rows=11509 loops=3)
                        Hash Cond: (contacts.id =
accounts_contacts.contact_id)
                        ->  Parallel Seq Scan on contacts
(cost=0.00..36177.50 rows=373366 width=16) (actual time=0.435..55.023
rows=288122 loops=3)
                              Filter: ((tenant_id =
'0199729c-3f1e-712f-8b71-f6545a96b225'::uuid) AND ((status)::text =
'ACTIVE'::text))
                              Rows Removed by Filter: 162518
                        ->  Hash  (cost=5275.46..5275.46 rows=63307
width=32) (actual time=12.053..12.054 rows=37282 loops=3)
                              Buckets: 65536  Batches: 1  Memory Usage:
2843kB
                              ->  Index Only Scan using
uq_accounts_contacts_account_id_contact_id on accounts_contacts
(cost=0.42..5275.46 rows=63307 width=32) (actual time=0.335..5.220
rows=37282 loops=3)
                                    Index Cond: (account_id = ANY (...

Here is the EXPLAIN output from executions 6+ using the generic query plan:
GroupAggregate  (cost=5821.21..5821.56 rows=20 width=24) (actual
time=7178.328..7179.934 rows=1000 loops=1)
      Group Key: accounts_contacts.account_id
      ->  Sort  (cost=5821.21..5821.26 rows=20 width=32) (actual
time=7178.314..7178.943 rows=34526 loops=1)
            Sort Key: accounts_contacts.account_id
            Sort Method: quicksort  Memory: 2984kB
            ->  Nested Loop  (cost=10.26..5820.77 rows=20 width=32) (actual
time=34.187..7174.937 rows=34526 loops=1)
                  ->  Bitmap Heap Scan on contacts  (cost=9.83..2490.09
rows=354 width=16) (actual time=34.071..193.216 rows=864365 loops=1)
                        Recheck Cond: (tenant_id = $1)
                        Filter: ((status)::text = ($2)::text)
                        Rows Removed by Filter: 102519
                        Heap Blocks: exact=26858
                        ->  Bitmap Index Scan on ix_contacts_tenant_id
(cost=0.00..9.74 rows=709 width=0) (actual time=32.114..32.114 rows=966884
loops=1)
                              Index Cond: (tenant_id = $1)
                  ->  Index Scan using ix_accounts_contacts_contact_id on
accounts_contacts  (cost=0.42..9.40 rows=1 width=32) (actual
time=0.008..0.008 rows=0 loops=864365)
                        Index Cond: (contact_id = contacts.id)
                        Filter: (account_id = ANY (ARRAY[...]))
                        Rows Removed by Filter: 1

(please note I omitted the account_ids list, but it is of length 1000 in
both cases)

I have seen others report the same issue, as seen in this forum:
https://dba.stackexchange.com/questions/289130/postgresql-changes-same-query-plan-at-runtime


pgsql-bugs by date:

Previous
From: Marco Boeringa
Date:
Subject: Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Next
From: Marco Boeringa
Date:
Subject: Re: Potential "AIO / io workers" inter-worker locking issue in PG18?