Problem analyzing explain analyze output - Mailing list pgsql-performance

Hi all,

I'm currently testing PostgreSQL 8.1 beta3 and I have a problem with a
EXPLAIN ANALYZE output. You can find it attached.

I don't understand why I have the Nested Loop at line 19 with an actual
time of 254.292..257.328 because I can't find anywhere the line taking
this 254 ms. Is it a problem with 8.1b3 or can anyone explain me where I
can find the part of the query taking this time? I'm not sure to
understand the new bitmap scan stuff.

Thanks for your help

Regards,

--
Guillaume
                                                                                              QUERY PLAN
                                                                              

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=4351.26..4351.28 rows=10 width=20) (actual time=314.658..314.686 rows=10 loops=1)
   ->  Sort  (cost=4351.26..4351.32 rows=26 width=20) (actual time=314.651..314.660 rows=10 loops=1)
         Sort Key: count(*)
         ->  HashAggregate  (cost=4350.32..4350.65 rows=26 width=20) (actual time=314.003..314.174 rows=54 loops=1)
               ->  Nested Loop  (cost=4234.34..4350.06 rows=26 width=20) (actual time=304.894..312.847 rows=110
loops=1)
                     ->  Hash Join  (cost=4234.34..4253.25 rows=26 width=4) (actual time=304.788..308.011 rows=110
loops=1)
                           Hash Cond: (("outer".codetylieu)::text = ("inner".codetylieu)::text)
                           ->  Hash Join  (cost=4232.18..4250.09 rows=43 width=11) (actual time=304.269..306.780
rows=115loops=1) 
                                 Hash Cond: (("outer".codegelieu)::text = ("inner".codegelieu)::text)
                                 ->  Seq Scan on genrelieu gl  (cost=0.00..8.84 rows=384 width=14) (actual
time=0.013..1.024rows=384 loops=1) 
                                 ->  Hash  (cost=4232.07..4232.07 rows=43 width=11) (actual time=304.162..304.162
rows=115loops=1) 
                                       ->  Nested Loop  (cost=4096.51..4232.07 rows=43 width=11) (actual
time=293.711..303.521rows=115 loops=1) 
                                             ->  Merge Join  (cost=4096.51..4100.10 rows=33 width=12) (actual
time=293.588..295.843rows=114 loops=1) 
                                                   Merge Cond: ("outer"."?column5?" = "inner"."?column2?")
                                                   ->  Sort  (cost=4058.09..4059.55 rows=587 width=20) (actual
time=291.107..291.605rows=514 loops=1) 
                                                         Sort Key: (l.codequar)::text
                                                         ->  Nested Loop  (cost=887.45..4031.09 rows=587 width=20)
(actualtime=254.424..280.794 rows=514 loops=1) 
                                                               ->  Bitmap Heap Scan on contcrilieu ccl
(cost=887.45..1668.96rows=587 width=8) (actual time=254.292..257.328 rows=514 loops=1) 
                                                                     Recheck Cond: ((dcrilieu >= (now() - '60
days'::interval))AND ((flagcriaccepteelieu)::text = 'O'::text)) 
                                                                     ->  Bitmap Index Scan on idx_contcrilieu_4
(cost=0.00..887.45rows=587 width=0) (actual time=254.143..254.143 rows=514 loops=1) 
                                                                           Index Cond: ((dcrilieu >= (now() - '60
days'::interval))AND ((flagcriaccepteelieu)::text = 'O'::text)) 
                                                               ->  Index Scan using pk_lieu on lieu l  (cost=0.00..4.01
rows=1width=12) (actual time=0.034..0.036 rows=1 loops=514) 
                                                                     Index Cond: ("outer".numlieu = l.numlieu)
                                                   ->  Sort  (cost=38.43..38.61 rows=73 width=8) (actual
time=1.539..1.731rows=163 loops=1) 
                                                         Sort Key: (vq.codequar)::text
                                                         ->  Bitmap Heap Scan on vilquartier vq  (cost=2.26..36.17
rows=73width=8) (actual time=0.408..0.788 rows=73 loops=1) 
                                                               Recheck Cond: ((codevil)::text = 'PAR'::text)
                                                               ->  Bitmap Index Scan on idx_vilquartier_codevil
(cost=0.00..2.26rows=73 width=0) (actual time=0.376..0.376 rows=73 loops=1) 
                                                                     Index Cond: ((codevil)::text = 'PAR'::text)
                                             ->  Index Scan using idx_lieugelieu_numlieu_principal on lieugelieu lgl
(cost=0.00..3.99rows=1 width=11) (actual time=0.055..0.060 rows=1 loops=114) 
                                                   Index Cond: (("outer".numlieu = lgl.numlieu) AND (lgl.principal =
1::numeric))
                           ->  Hash  (cost=2.11..2.11 rows=17 width=7) (actual time=0.450..0.450 rows=17 loops=1)
                                 ->  Seq Scan on rubtylieu rtl  (cost=0.00..2.11 rows=17 width=7) (actual
time=0.127..0.352rows=17 loops=1) 
                                       Filter: ((codeth)::text = 'BAD'::text)
                     ->  Index Scan using pk_contact on contact c  (cost=0.00..3.71 rows=1 width=20) (actual
time=0.034..0.037rows=1 loops=110) 
                           Index Cond: (c.numcont = "outer".numcont)
 Total runtime: 317.250 ms
(37 rows)