potential bug with query optimizer and functions - Mailing list pgsql-hackers

While creating a function, I kept getting a large variance in runtime between the raw query vs. using the
function/preparedstatement. After talking with folks on #postgresql, specifically David Fetter, he thought I should
mentionit here.
 

VERSION: PostgreSQL 8.3.7 on i486-pc-linux-gnu, compiled by GCC gcc-4.3.real(Debian 4.3.2-1.1)4.3.2

==============================
DOING A PREPARE, EXPLAIN ANALYZE EXECUTE
==============================
Group  (cost=26857.96..37572.40 rows=40000 width=32) (actual time=6234.328..7015.498 rows=2185 loops=1) ->  Sort
(cost=26857.96..27036.57rows=71444 width=32) (actual time=6230.165..6232.030 rows=5164 loops=1)       Sort Key:
gen_ts_by_scope_extra.thets,gen_ts_by_scope_extra.theinterval, dcdo.contact_output_id       Sort Method:  quicksort
Memory:492kB       ->  Nested Loop Left Join  (cost=1443.96..19386.46 rows=71444 width=32) (actual
time=14.061..6226.787rows=5164 loops=1)             Join Filter: ((dcdo.created >= gen_ts_by_scope_extra.thets) AND
(dcdo.created< (gen_ts_by_scope_extra.thets + gen_ts_by_scope_extra.theinterval)))             ->  Function Scan on
gen_ts_by_scope_extra (cost=0.00..260.00 rows=1000 width=24) (actual time=2.646..3.377 rows=2185 loops=1)
-> Materialize  (cost=1443.96..1450.39 rows=643 width=16) (actual time=0.000..1.046 rows=3603 loops=2185)
   ->  Append  (cost=0.00..1443.32 rows=643 width=16) (actual time=0.086..5.810 rows=3603 loops=1)
  ->  Seq Scan on data_contact_output dcdo  (cost=0.00..1.20 rows=3 width=16) (actual time=0.011..0.011 rows=0 loops=1)
                             Filter: (contact_output_id = $1)                         ->  Bitmap Heap Scan on
data_contact_output_200904dcdo  (cost=4.96..197.97 rows=91 width=16) (actual time=0.013..0.013 rows=0 loops=1)
                    Recheck Cond: (contact_output_id = $1)                               ->  Bitmap Index Scan on
data_contact_output_200904_contact_output_idx (cost=0.00..4.94 rows=91 width=0) (actual time=0.011..0.011 rows=0
loops=1)                                    Index Cond: (contact_output_id = $1)                         ->  Bitmap
HeapScan on data_contact_output_200905 dcdo  (cost=9.57..364.27 rows=169 width=16) (actual time=0.060..0.242 rows=202
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_200905_contact_output_idx  (cost=0.00..9.53 rows=169 width=0) (actual
time=0.049..0.049rows=202 loops=1)                                     Index Cond: (contact_output_id = $1)
           ->  Bitmap Heap Scan on data_contact_output_200906 dcdo  (cost=9.81..381.47 rows=199 width=16) (actual
time=0.528..2.600rows=2548 loops=1)                               Recheck Cond: (contact_output_id = $1)
              ->  Bitmap Index Scan on data_contact_output_200906_contact_output_idx  (cost=0.00..9.76 rows=199
width=0)(actual time=0.463..0.463 rows=2548 loops=1)                                     Index Cond: (contact_output_id
=$1)                         ->  Bitmap Heap Scan on data_contact_output_200907 dcdo  (cost=5.27..304.93 rows=130
width=16)(actual time=0.225..1.076 rows=853 loops=1)                               Recheck Cond: (contact_output_id =
$1)                              ->  Bitmap Index Scan on data_contact_output_200907_contact_output_idx
(cost=0.00..5.24rows=130 width=0) (actual time=0.177..0.177 rows=853 loops=1)                                     Index
Cond:(contact_output_id = $1)                         ->  Bitmap Heap Scan on data_contact_output_200908 dcdo
(cost=4.27..11.38rows=3 width=16) (actual time=0.005..0.005 rows=0 loops=1)                               Recheck Cond:
(contact_output_id= $1)                               ->  Bitmap Index Scan on
data_contact_output_200908_contact_output_idx (cost=0.00..4.27 rows=3 width=0) (actual time=0.003..0.003 rows=0
loops=1)                                    Index Cond: (contact_output_id = $1)                         ->  Bitmap
HeapScan on data_contact_output_200909 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.003..0.003 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_200909_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.003..0.003
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_200910 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.003..0.003 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_200910_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_200911 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.003..0.003 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_200911_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_200912 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.002..0.002 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_200912_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_201001 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.002..0.002 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_201001_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_201002 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.002..0.002 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_201002_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_201003 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.003..0.003 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_201003_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_201004 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.003..0.003 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_201004_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_201005 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.002..0.002 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_201005_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_201006 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.003..0.003 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_201006_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.003..0.003
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_201007 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.003..0.003 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_201007_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_201008 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.004..0.004 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_201008_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_201009 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.003..0.003 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_201009_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_201010 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.003..0.003 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_201010_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.003..0.003
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_201011 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.003..0.003 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_201011_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)                         ->
BitmapHeap Scan on data_contact_output_201012 dcdo  (cost=4.27..11.38 rows=3 width=16) (actual time=0.003..0.003 rows=0
loops=1)                              Recheck Cond: (contact_output_id = $1)                               ->  Bitmap
IndexScan on data_contact_output_201012_contact_output_idx  (cost=0.00..4.27 rows=3 width=0) (actual time=0.003..0.003
rows=0loops=1)                                     Index Cond: (contact_output_id = $1)
 
Total runtime: 7017.096 ms

==============================
DOING AN EXPLAIN ANALYZE query
==============================
Group  (cost=90863.24..104733.24 rows=40000 width=32) (actual time=188.712..730.063 rows=2185 loops=1) ->  Sort
(cost=90863.24..91830.74rows=387000 width=32) (actual time=185.074..186.704 rows=5164 loops=1)       Sort Key:
gen_ts_by_scope_extra.thets,gen_ts_by_scope_extra.theinterval, dcdo.contact_output_id       Sort Method:  quicksort
Memory:492kB       ->  Nested Loop Left Join  (cost=0.00..36423.82 rows=387000 width=32) (actual time=2.779..181.244
rows=5164loops=1)             Join Filter: ((dcdo.created >= gen_ts_by_scope_extra.thets) AND (dcdo.created <
(gen_ts_by_scope_extra.thets+ gen_ts_by_scope_extra.theinterval)))             ->  Function Scan on
gen_ts_by_scope_extra (cost=0.00..260.00 rows=1000 width=24) (actual time=2.652..3.473 rows=2185 loops=1)
-> Append  (cost=0.00..29.20 rows=398 width=16) (actual time=0.051..0.065 rows=2 loops=2185)                   ->  Seq
Scanon data_contact_output dcdo  (cost=0.00..1.20 rows=1 width=16) (actual time=0.005..0.005 rows=0 loops=2185)
               Filter: (dcdo.contact_output_id = 3103)                   ->  Index Scan using
data_contact_output_200904_contact_output_idxon data_contact_output_200904 dcdo  (cost=0.00..2.33 rows=7 width=16)
(actualtime=0.004..0.004 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_200905_contact_output_idxon data_contact_output_200905 dcdo  (cost=0.00..4.16 rows=15 width=16)
(actualtime=0.005..0.005 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_200906_contact_output_idxon data_contact_output_200906 dcdo  (cost=0.00..9.92 rows=258 width=16)
(actualtime=0.005..0.006 rows=1 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_200907_contact_output_idxon data_contact_output_200907 dcdo  (cost=0.00..6.12 rows=100 width=16)
(actualtime=0.005..0.005 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_200908_contact_output_idxon data_contact_output_200908 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_200909_contact_output_idxon data_contact_output_200909 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_200910_contact_output_idxon data_contact_output_200910 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_200911_contact_output_idxon data_contact_output_200911 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_200912_contact_output_idxon data_contact_output_200912 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_201001_contact_output_idxon data_contact_output_201001 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_201002_contact_output_idxon data_contact_output_201002 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_201003_contact_output_idxon data_contact_output_201003 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_201004_contact_output_idxon data_contact_output_201004 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_201005_contact_output_idxon data_contact_output_201005 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_201006_contact_output_idxon data_contact_output_201006 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_201007_contact_output_idxon data_contact_output_201007 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_201008_contact_output_idxon data_contact_output_201008 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_201009_contact_output_idxon data_contact_output_201009 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_201010_contact_output_idxon data_contact_output_201010 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_201011_contact_output_idxon data_contact_output_201011 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))                  ->  Index Scan using
data_contact_output_201012_contact_output_idxon data_contact_output_201012 dcdo  (cost=0.00..0.32 rows=1 width=16)
(actualtime=0.002..0.002 rows=0 loops=2185)                         Index Cond: ((dcdo.contact_output_id = 3103) AND
(dcdo.created>= gen_ts_by_scope_extra.thets) AND (dcdo.created < (gen_ts_by_scope_extra.thets +
gen_ts_by_scope_extra.theinterval)))
Total runtime: 731.399 ms



-- 
Sincerely,

Zach Conrad
Digitec Incorporated
zach.conrad@digitecinc.com