Skip site navigation (1) Skip section navigation (2)

potential bug with query optimizer and functions

From: Zach Conrad <zach(dot)conrad(at)digitecinc(dot)com>
To: pgsql-hackers(at)postgresql(dot)org
Subject: potential bug with query optimizer and functions
Date: 2009-07-27 19:15:17
Message-ID: 24806242.42271248722117678.JavaMail.root@zimbra (view raw or flat)
Thread:
Lists: pgsql-hackers
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

Responses

pgsql-hackers by date

Next:From: Robert HaasDate: 2009-07-27 19:50:17
Subject: Re: potential bug with query optimizer and functions
Previous:From: Dean RasheedDate: 2009-07-27 19:03:45
Subject: Re: WIP: Deferrable unique constraints

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group