Обсуждение: Problem analyzing explain analyze output
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)
On Mon, Oct 24, 2005 at 01:53:59AM +0200, Guillaume Smet wrote:
> 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.
You don't have a nested loop with that time; however, you have
> -> Nested Loop (cost=887.45..4031.09 rows=587 width=20) (actual time=254.424..280.794 rows=514 loops=1)
> -> Bitmap Heap Scan on contcrilieu ccl (cost=887.45..1668.96 rows=587 width=8) (actual
time=254.292..257.328rows=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.45 rows=587 width=0) (actual
time=254.143..254.143rows=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=1 width=12) (actual time=0.034..0.036 rows=1
loops=514)
> Index Cond: ("outer".numlieu = l.numlieu)
which seems to make sense; you have one run of about 257ms, plus 514 runs
taking about 0.035ms each (ie. about 18ms), which should add up to become
about 275ms (which is close enough to the reality of 281ms).
/* Steinar */
--
Homepage: http://www.sesse.net/
Steinar, > which seems to make sense; you have one run of about 257ms, plus 514 runs > taking about 0.035ms each (ie. about 18ms), which should add up to become > about 275ms (which is close enough to the reality of 281ms). Yep. The line that disturbed me was the bitmap index scan with a cost of "actual time=254.143..254.143". I was more looking for something like "actual time=0..254.143" which is what I usually have for an index scan. So I suppose that the bitmap index scan returns rows only when it's totally computed. Thanks for your help. Regards. -- Guillaume