Message-ID: <4EE0F966.5020602@peak6.com>
Date: Thu, 8 Dec 2011 11:52:38 -0600
From: Shaun Thomas <sthomas@peak6.com>
Reply-To: <sthomas@peak6.com>
Organization: Peak6
User-Agent: Mozilla/5.0 (X11; Linux i686;
	rv:8.0) Gecko/20111105 Thunderbird/8.0
MIME-Version: 1.0
To: <kaloyan@digsys.bg>
CC: <pgsql-performance@postgresql.org>
Subject: Re: Slow query after upgrade from 8.2 to 8.4
References: <4EE0F3F4.8040909@digsys.bg>
In-Reply-To: <4EE0F3F4.8040909@digsys.bg>
Content-Type: text/plain; charset="windows-1251"; format=flowed
content-transfer-encoding: 7bit

On 12/08/2011 11:29 AM, Kaloyan Iliev Iliev wrote:

> I think the planner didn't choose the best plan. I will try to I rewrite
> the query and set join_collapse_limit to 1 and see what will happen.
> Meanwhile any suggestions are welcome.

Try rewriting the query, definitely. But make sure your statistical 
targets are high enough for an analyze to make a difference. I see way 
too many nested loops with wrong row estimates.

Like these:

Nested Loop (cost=0.00..8675.62 rows=2263 width=4) (actual 
time=0.456..5991.749 rows=68752 loops=167)
Join Filter: (dd.debtid = ad.debtid)

Nested Loop (cost=0.00..7864.54 rows=1160 width=4) (actual 
time=0.374..2781.762 rows=34384 loops=167)

Index Scan using config_office_idx on config cf (cost=0.00..7762.56 
rows=50 width=8) (actual time=0.199..1623.366 rows=2460 loops=167)
Index Cond: (office = 6)
Filter: (id = (SubPlan 6))

There are several spots where the row estimates are off by one or two 
orders of magnitude. Instead of doing a sequence scan for such large 
tables, it's nest looping over an index scan, sometimes millions of times.

And then you have these:

Index Scan using config_confid_idx on config (cost=0.00..0.66 rows=6 
width=12) (actual time=0.023..0.094 rows=10 loops=1655853)
Index Cond: (confid = $3)

Index Scan using debts_desc_refid_idx on debts_desc dd (cost=0.00..1.66 
rows=30 width=8) (actual time=0.061..0.381 rows=14 loops=410867)
Index Cond: (dd.refid = cf.confid)

Index Scan using acc_debts_debtid_idx on acc_debts ad (cost=0.00..0.39 
rows=2 width=8) (actual time=0.034..0.053 rows=2 loops=5742191)
Index Cond: (ad.debtid = dd.debtid)

Index Scan using acc_debtscl_debtid_idx on acc_debts_cleared ad 
(cost=0.00..0.27 rows=1 width=8) (actual time=0.005..0.005 rows=0 
loops=5742183)
Index Cond: (ad.debtid = dd.debtid)

Having index scans that big embedded in nested loops is going to murder 
your CPU even if every table involved is cached in memory. I'm not 
surprised this takes an hour or more to run. Increase the statistics on 
these tables, and pay special attention to the debtid and refid columns, 
and then analyze them again.

What's your default_statistics_target?

-- 
Shaun Thomas
OptionsHouse | 141 W. Jackson Blvd. | Suite 800 | Chicago IL, 60604
312-676-8870
sthomas@peak6.com

______________________________________________

See http://www.peak6.com/email_disclaimer/ for terms and conditions related to this email