Poor plan choice in prepared statement

From: bricklen <bricklen(at)gmail(dot)com>
To: pgsql-performance(at)postgresql(dot)org
Subject: Poor plan choice in prepared statement
Date: 2008-12-30 18:59:23
Message-ID: 33b743250812301059u31ce82faw3d72a38280b37402@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

Hi, I am re-posting my question here after trying to find a solution
in the PHP pgsql list with no luck.

I am experiencing some performance issues that I think are stemming
from prepared statements. I have a pretty simple query:

SELECT cl.idOffer,cl.idaffiliate ,cl.subid,cl.datetime
FROM click AS cl LEFT JOIN conversion AS co ON cl.clickgenerated =
co.clickgenerated
WHERE cl."date" >= '2008-12-01'
AND cl."date" <= '2008-12-23'
AND cl.idAffiliate = 49978
LIMIT 10;

Run times:

- sub-second when issued from the command line (not prepared)
- runs sub-second from our PHP application if I prepend the query with
"EXPLAIN ANALYZE", and looking at the resulting plan, it shows the
same plan as when it runs quickly from the command line.
- runs sub-second if I remove the "prepare" function from the PHP
application and execute the query with the variables in-line.

- takes 200+ seconds when run from the command line inside a prepared
statement (see query below)
- takes over 200s when run from our application, within the PHP PDO
prepared function (same as preparing from the command line)

I would like to continue to use bind variables to prevent sql
injection, but I'd like to force a plan re-parse for every single
query (if necessary?)

Does anyone have any ideas?

postgresql 8.2.11, freshly loaded db, vacuumed and analyzed.
All indices in the plans are regular b-trees.

-- good plan, from non-prepared statement
--
dev=# EXPLAIN ANALYZE SELECT cl.idOffer,cl.idaffiliate ,cl.subid,cl.datetime
dev-# FROM click AS cl LEFT JOIN conversion AS co ON cl.clickgenerated
= co.clickgenerated
dev-# WHERE cl."date" >= '2008-12-01'
dev-# AND cl."date" <= '2008-12-23'
dev-# AND cl.idAffiliate = 49978
dev-# LIMIT 10;

Limit (cost=0.00..30.52 rows=10 width=48) (actual time=0.253..0.429
rows=10 loops=1)
-> Nested Loop Left Join (cost=0.00..2613524.29 rows=856328
width=48) (actual time=0.251..0.416 rows=10 loops=1)
-> Append (cost=0.00..77406.15 rows=19179 width=80) (actual
time=0.226..0.256 rows=10 loops=1)
-> Seq Scan on click cl (cost=0.00..15.07 rows=1
width=80) (actual time=0.001..0.001 rows=0 loops=1)
Filter: ((date >= '2008-12-01'::date) AND (date
<= '2008-12-23'::date) AND (idaffiliate = 49978))
-> Bitmap Heap Scan on click_00030 cl
(cost=406.48..77391.08 rows=19178 width=46) (actual time=0.222..0.241
rows=10 loops=1)
Recheck Cond: (idaffiliate = 49978)
Filter: ((date >= '2008-12-01'::date) AND (date
<= '2008-12-23'::date))
-> Bitmap Index Scan on
click_00030_idaffiliate_idx (cost=0.00..401.68 rows=21355 width=0)
(actual time=0.138..0.138 rows=484 loops=1)
Index Cond: (idaffiliate = 49978)
-> Index Scan using conversion_clickgenerated_idx on
"conversion" co (cost=0.00..131.67 rows=45 width=12) (actual
time=0.014..0.014 rows=0 loops=10)
Index Cond: ((cl.clickgenerated)::text =
(co.clickgenerated)::text)
Total runtime: 0.495 ms

-- bad plan, from prepared statement
--
dev=# prepare fooplan (date,date,int,int) as
dev-# SELECT cl.idOffer AS campaign, cl.idAffiliate AS affiliate,
cl.idCreative AS creative, cl.subid, cl.datetime
dev-# FROM click AS cl LEFT JOIN conversion AS co ON cl.clickGenerated
= co.clickGenerated
dev-# WHERE cl."date" >= $1
dev-# AND cl."date" <= $2
dev-# AND cl.idAffiliate = $3
dev-# LIMIT $4;
ERROR: prepared statement "fooplan" already exists
dev=# explain analyze execute fooplan ('2008-12-01','2008-12-23',49978,10);

QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=0.00..15275.74 rows=3277 width=227) (actual
time=201350.494..201350.765 rows=10 loops=1)
-> Nested Loop Left Join (cost=0.00..152771.39 rows=32773
width=227) (actual time=201350.489..201350.748 rows=10 loops=1)
-> Append (cost=0.00..16031.56 rows=734 width=180) (actual
time=201350.438..201350.542 rows=10 loops=1)
-> Seq Scan on click cl (cost=0.00..15.07 rows=1
width=180) (actual time=0.001..0.001 rows=0 loops=1)
Filter: ((date >= $1) AND (date <= $2) AND
(idaffiliate = $3))
-> Bitmap Heap Scan on click_00028 cl
(cost=6701.97..8179.43 rows=372 width=177) (actual time=0.060..0.060
rows=0 loops=1)
Recheck Cond: ((idaffiliate = $3) AND (date >=
$1) AND (date <= $2))
-> BitmapAnd (cost=6701.97..6701.97 rows=372
width=0) (actual time=0.058..0.058 rows=0 loops=1)
-> Bitmap Index Scan on
click_00028_idaffiliate_idx (cost=0.00..1384.22 rows=74456 width=0)
(actual time=0.038..0.038 rows=86 loops=1)
Index Cond: (idaffiliate = $3)
-> Bitmap Index Scan on
click_00028_date_idx (cost=0.00..5317.31 rows=253151 width=0) (actual
time=0.010..0.010 rows=0 loops=1)
Index Cond: ((date >= $1) AND (date <= $2))
-> Bitmap Heap Scan on click_00030 cl
(cost=6383.03..7811.35 rows=360 width=141) (actual
time=201350.373..201350.466 rows=10 loops=1)
Recheck Cond: ((idaffiliate = $3) AND (date >=
$1) AND (date <= $2))
-> BitmapAnd (cost=6383.03..6383.03 rows=360
width=0) (actual time=201350.280..201350.280 rows=0 loops=1)
-> Bitmap Index Scan on
click_00030_idaffiliate_idx (cost=0.00..1337.96 rows=72058 width=0)
(actual time=0.101..0.101 rows=484 loops=1)
Index Cond: (idaffiliate = $3)
-> Bitmap Index Scan on
click_00030_date_idx (cost=0.00..5044.64 rows=240312 width=0) (actual
time=201347.064..201347.064 rows=43352606 loops=1)
Index Cond: ((date >= $1) AND (date <= $2))
-> Index Scan using click_current_massive_idx on
click_current cl (cost=0.00..25.70 rows=1 width=152) (never executed)
Index Cond: ((date >= $1) AND (date <= $2) AND
(idaffiliate = $3))
-> Index Scan using conversion_clickgenerated_idx on
"conversion" co (cost=0.00..185.51 rows=45 width=16) (actual
time=0.015..0.016 rows=0 loops=10)
Index Cond: ((cl.clickgenerated)::text =
(co.clickgenerated)::text)
Total runtime: 201350.887 ms
(24 rows)

Time: 201351.556 ms
dev=# deallocate fooplan;
DEALLOCATE

Thanks!

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Merlin Moncure 2008-12-30 19:42:49 Re: Poor plan choice in prepared statement
Previous Message Tom Lane 2008-12-30 15:39:21 Re: Big index sizes