DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma;
	h=message-id:date:from:to:subject:mime-version:content-type
	:content-transfer-encoding:content-disposition;
	b=bChGOuzKfZFk5y/JSj0z9kxGPfffZCuv8MaJbKxA17DLAHuEMMSvgQ+mPRrdaESwk+
	PLReWqSYZm/ZD79lzgDwxWY7PIc1aaHrk0X7rjZ+tsTEJp+f+8eXTWPb/eskxo0d8919
	ZupKTOylZ7zZpcuElsr5y4FosUB/3zSRHVDXI=
Message-ID: <33b743250812301059u31ce82faw3d72a38280b37402@mail.gmail.com>
Date: Tue, 30 Dec 2008 10:59:23 -0800
From: bricklen <bricklen@gmail.com>
To: pgsql-performance@postgresql.org
Subject: Poor plan choice in prepared statement
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 7bit
Content-Disposition: inline

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!