potential bug with query optimizer and functions

While creating a function, I kept getting a large variance in runtime between the raw query vs. using the function/prepared statement. After talking with folks on #postgresql, specifically David Fetter, he thought I should mention it 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.57 rows=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.787 rows=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_200904 dcdo (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 Heap Scan 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 Index Scan on data_contact_output_200905_contact_output_idx (cost=0.00..9.53 rows=169 width=0) (actual time=0.049..0.049 rows=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.600 rows=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.24 rows=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.38 rows=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 Heap Scan 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 Index Scan on data_contact_output_200909_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 Heap 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 Index Scan on data_contact_output_200910_contact_output_idx (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (contact_output_id = $1)
-> Bitmap Heap 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 Index Scan on data_contact_output_200911_contact_output_idx (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (contact_output_id = $1)
-> Bitmap Heap 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 Index Scan on data_contact_output_200912_contact_output_idx (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (contact_output_id = $1)
-> Bitmap Heap 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 Index Scan on data_contact_output_201001_contact_output_idx (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (contact_output_id = $1)
-> Bitmap Heap 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 Index Scan on data_contact_output_201002_contact_output_idx (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (contact_output_id = $1)
-> Bitmap Heap 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 Index Scan on data_contact_output_201003_contact_output_idx (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (contact_output_id = $1)
-> Bitmap Heap 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 Index Scan on data_contact_output_201004_contact_output_idx (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (contact_output_id = $1)
-> Bitmap Heap 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 Index Scan on data_contact_output_201005_contact_output_idx (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (contact_output_id = $1)
-> Bitmap Heap 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 Index Scan on data_contact_output_201006_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 Heap 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 Index Scan on data_contact_output_201007_contact_output_idx (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (contact_output_id = $1)
-> Bitmap Heap 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 Index Scan on data_contact_output_201008_contact_output_idx (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (contact_output_id = $1)
-> Bitmap Heap 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 Index Scan on data_contact_output_201009_contact_output_idx (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (contact_output_id = $1)
-> Bitmap Heap 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 Index Scan on data_contact_output_201010_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 Heap 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 Index Scan on data_contact_output_201011_contact_output_idx (cost=0.00..4.27 rows=3 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (contact_output_id = $1)
-> Bitmap Heap 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 Index Scan on data_contact_output_201012_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)
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.74 rows=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=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.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 Scan on 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_idx on data_contact_output_200904 dcdo (cost=0.00..2.33 rows=7 width=16) (actual time=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_idx on data_contact_output_200905 dcdo (cost=0.00..4.16 rows=15 width=16) (actual time=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_idx on data_contact_output_200906 dcdo (cost=0.00..9.92 rows=258 width=16) (actual time=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_idx on data_contact_output_200907 dcdo (cost=0.00..6.12 rows=100 width=16) (actual time=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_idx on data_contact_output_200908 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_200909 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_200910 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_200911 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_200912 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_201001 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_201002 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_201003 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_201004 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_201005 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_201006 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_201007 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_201008 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_201009 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_201010 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_201011 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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_idx on data_contact_output_201012 dcdo (cost=0.00..0.32 rows=1 width=16) (actual time=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(dot)conrad(at)digitecinc(dot)com