Обсуждение: Please help with this explain analyse...
Hi all,
I don't understand why this request take so long. Maybe I read the
analyse correctly but It seem that the first line(Nested Loop Left Join
...) take all the time. But I don't understand where the performance
problem is ??? All the time is passed in the first line ...
Thanks for your help!
/David
explain analyse SELECT *
FROM CR INNER JOIN CS ON CR.CRNUM = CS.CSCRNUM AND
CR.CRYPNUM = CS.CSYPNUM
INNER JOIN GL ON CS.CSGLNUM = GL.GLNUM AND
GL.GLSOCTRL = 1
INNER JOIN RR ON CR.CRRRNUM = RR.RRNUM
LEFT OUTER JOIN YR ON YR.YRYOTYPE = 'Client' AND
YR.YRYONUM = 'Comptabilite.Recevable.Regroupement' AND YR.YRREF = RR.RRNUM
WHERE CRYPNUM = 'M'
AND CRDATE + INTERVAL '0 days' <= '2005-01-28'
"Nested Loop Left Join (cost=0.00..42.12 rows=1 width=8143) (actual
time=15.254..200198.524 rows=8335 loops=1)"
" Join Filter: (("inner".yrref)::text = ("outer".rrnum)::text)"
" -> Nested Loop (cost=0.00..36.12 rows=1 width=7217) (actual
time=0.441..2719.821 rows=8335 loops=1)"
" -> Nested Loop (cost=0.00..30.12 rows=1 width=1580) (actual
time=0.242..1837.413 rows=8335 loops=1)"
" -> Nested Loop (cost=0.00..18.07 rows=2 width=752)
(actual time=0.145..548.607 rows=13587 loops=1)"
" -> Seq Scan on gl (cost=0.00..5.21 rows=1
width=608) (actual time=0.036..0.617 rows=1 loops=1)"
" Filter: (glsoctrl = 1)"
" -> Index Scan using cs_pk on cs (cost=0.00..12.83
rows=2 width=144) (actual time=0.087..444.999 rows=13587 loops=1)"
" Index Cond: (('M'::text = (cs.csypnum)::text)
AND ((cs.csglnum)::text = ("outer".glnum)::text))"
" -> Index Scan using cr_pk on cr (cost=0.00..6.02 rows=1
width=828) (actual time=0.073..0.077 rows=1 loops=13587)"
" Index Cond: (((cr.crypnum)::text = 'M'::text) AND
(cr.crnum = "outer".cscrnum))"
" Filter: ((crdate + '00:00:00'::interval) <=
'2005-01-28 00:00:00'::timestamp without time zone)"
" -> Index Scan using rr_pk on rr (cost=0.00..5.99 rows=1
width=5637) (actual time=0.062..0.069 rows=1 loops=8335)"
" Index Cond: (("outer".crrrnum)::text = (rr.rrnum)::text)"
" -> Index Scan using yr_idx1 on yr (cost=0.00..5.99 rows=1
width=926) (actual time=0.127..17.379 rows=1154 loops=8335)"
" Index Cond: (((yryotype)::text = 'Client'::text) AND
((yryonum)::text = 'Comptabilite.Recevable.Regroupement'::text))"
"Total runtime: 200235.732 ms"
David Gagnon wrote:
> " -> Index Scan using cr_pk on cr (cost=0.00..6.02 rows=1
> width=828) (actual time=0.073..0.077 rows=1 loops=13587)"
> " Index Cond: (((cr.crypnum)::text = 'M'::text) AND
> (cr.crnum = "outer".cscrnum))"
> " Filter: ((crdate + '00:00:00'::interval) <=
> '2005-01-28 00:00:00'::timestamp without time zone)"
> " -> Index Scan using rr_pk on rr (cost=0.00..5.99 rows=1
> width=5637) (actual time=0.062..0.069 rows=1 loops=8335)"
> " Index Cond: (("outer".crrrnum)::text = (rr.rrnum)::text)"
> " -> Index Scan using yr_idx1 on yr (cost=0.00..5.99 rows=1
> width=926) (actual time=0.127..17.379 rows=1154 loops=8335)"
Your loops are what is causing the time spent.
eg. "actual time=0.127..17.379 rows=1154 loops=8335)" ==
8335*(17.379-0.127)/1000=>143 secs (if my math is correct).
--
_______________________________
This e-mail may be privileged and/or confidential, and the sender does
not waive any related rights and obligations. Any distribution, use or
copying of this e-mail or the information it contains by other than an
intended recipient is unauthorized. If you received this e-mail in
error, please advise me (by return e-mail or otherwise) immediately.
_______________________________
Bricklen Anderson <BAnderson@PresiNET.com> writes:
> Your loops are what is causing the time spent.
> eg. "actual time=0.127..17.379 rows=1154 loops=8335)" ==
> 8335*(17.379-0.127)/1000=>143 secs (if my math is correct).
As for where the problem is, I think it's the horrid misestimate of the
number of matching rows in cs_pk:
>> " -> Index Scan using cs_pk on cs (cost=0.00..12.83
>> rows=2 width=144) (actual time=0.087..444.999 rows=13587 loops=1)"
>> " Index Cond: (('M'::text = (cs.csypnum)::text)
>> AND ((cs.csglnum)::text = ("outer".glnum)::text))"
Has that table been ANALYZEd recently? How about the gl table?
regards, tom lane
I restored my db but haven't run the analyse... That was the problem.
Thanks
/David
"Merge Left Join (cost=2273.54..2290.19 rows=228 width=816) (actual
time=2098.257..2444.472 rows=8335 loops=1)"
" Merge Cond: (("outer".rrnum)::text = "inner"."?column8?")"
" -> Merge Join (cost=2131.25..2141.31 rows=228 width=744) (actual
time=2037.953..2251.289 rows=8335 loops=1)"
" Merge Cond: ("outer"."?column31?" = "inner"."?column77?")"
" -> Sort (cost=1975.03..1975.60 rows=228 width=235) (actual
time=1798.556..1811.828 rows=8335 loops=1)"
" Sort Key: (cr.crrrnum)::text"
" -> Hash Join (cost=1451.41..1966.10 rows=228 width=235)
(actual time=267.751..515.396 rows=8335 loops=1)"
" Hash Cond: ("outer".crnum = "inner".cscrnum)"
" -> Seq Scan on cr (cost=0.00..489.77 rows=4529
width=101) (actual time=0.077..97.615 rows=8335 loops=1)"
" Filter: (((crypnum)::text = 'M'::text) AND
((crdate + '00:00:00'::interval) <= '2005-01-28 00:00:00'::timestamp
without time zone))"
" -> Hash (cost=1449.70..1449.70 rows=684
width=134) (actual time=267.568..267.568 rows=13587 loops=1)"
" -> Nested Loop (cost=20.59..1449.70
rows=684 width=134) (actual time=33.099..178.524 rows=13587 loops=1)"
" -> Seq Scan on gl (cost=0.00..5.21
rows=2 width=91) (actual time=0.021..0.357 rows=1 loops=1)"
" Filter: (glsoctrl = 1)"
" -> Bitmap Heap Scan on cs
(cost=20.59..684.42 rows=3026 width=43) (actual time=33.047..115.151
rows=13587 loops=1)"
" Recheck Cond: ((cs.csglnum)::text
= ("outer".glnum)::text)"
" Filter: ('M'::text =
(csypnum)::text)"
" -> Bitmap Index Scan on
cs_gl_fk (cost=0.00..20.59 rows=3026 width=0) (actual
time=32.475..32.475 rows=13587 loops=1)"
" Index Cond:
((cs.csglnum)::text = ("outer".glnum)::text)"
" -> Sort (cost=156.22..159.65 rows=1372 width=509) (actual
time=239.315..254.024 rows=8974 loops=1)"
" Sort Key: (rr.rrnum)::text"
" -> Seq Scan on rr (cost=0.00..84.72 rows=1372
width=509) (actual time=0.055..33.564 rows=1372 loops=1)"
" -> Sort (cost=142.29..144.55 rows=903 width=72) (actual
time=60.246..74.813 rows=8932 loops=1)"
" Sort Key: (yr.yrref)::text"
" -> Bitmap Heap Scan on yr (cost=16.42..97.96 rows=903
width=72) (actual time=8.513..13.587 rows=1154 loops=1)"
" Recheck Cond: (((yryotype)::text = 'Client'::text) AND
((yryonum)::text = 'Comptabilite.Recevable.Regroupement'::text))"
" -> Bitmap Index Scan on yr_idx1 (cost=0.00..16.42
rows=903 width=0) (actual time=8.471..8.471 rows=1154 loops=1)"
" Index Cond: (((yryotype)::text = 'Client'::text)
AND ((yryonum)::text = 'Comptabilite.Recevable.Regroupement'::text))"
"Total runtime: 2466.197 ms"
>Bricklen Anderson <BAnderson@PresiNET.com> writes:
>
>
>>Your loops are what is causing the time spent.
>>eg. "actual time=0.127..17.379 rows=1154 loops=8335)" ==
>>8335*(17.379-0.127)/1000=>143 secs (if my math is correct).
>>
>>
>
>As for where the problem is, I think it's the horrid misestimate of the
>number of matching rows in cs_pk:
>
>
>
>>>" -> Index Scan using cs_pk on cs (cost=0.00..12.83
>>>rows=2 width=144) (actual time=0.087..444.999 rows=13587 loops=1)"
>>>" Index Cond: (('M'::text = (cs.csypnum)::text)
>>>AND ((cs.csglnum)::text = ("outer".glnum)::text))"
>>>
>>>
>
>Has that table been ANALYZEd recently? How about the gl table?
>
> regards, tom lane
>
>
>