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
[email protected]
--
Sent via pgsql-hackers mailing list ([email protected])
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
