Message-ID: <443679F3.20907@archonet.com>
Date: Fri, 07 Apr 2006 15:40:51 +0100
From: Richard Huxton <dev@archonet.com>
User-Agent: Thunderbird 1.5 (X11/20051201)
MIME-Version: 1.0
To: Rafael Martinez Guerrero <r.m.guerrero@usit.uio.no>
Cc: pgsql-performance@postgresql.org
Subject: Re: Same SQL, 104296ms of difference between 7.4.12 and
References: <1144413933.24060.253.camel@bbking.uio.no>	
	<443669A5.2000603@archonet.com>
	<1144418444.24060.269.camel@bbking.uio.no>
In-Reply-To: <1144418444.24060.269.camel@bbking.uio.no>
Content-Type: text/plain; charset=ISO-8859-15; format=flowed
Content-Transfer-Encoding: 7bit

Rafael Martinez Guerrero wrote:
>>> Any ideas of what I can test/configurate to find out why this happens?
>>> Thanks in advance.
>> I haven't looked in detail at the plans, but what stands out to me is 
>> that you've got a sort with a lot of columns and you've halved sort_mem 
>> (work_mem). Try increasing it (perhaps to 32000 even).
>> 	set work_mem = 32000;
>>
>> Give that a quick go and see what happens. If it doesn't work, we'll 
>> look at the plans in more detail.
> 
> I know that this SQL could be done in a much better way, but I can not
> change it at the moment. 
> 
> work_mem = 16384:
> -----------------
> After restarting the database and running the explain two times:
> 107911.229 ms
> 
> work_mem = 32768:
> -----------------
> After restarting the database and running the explain two times:
> 103988.337 ms

Damn! I hate it when I have to actually work at a problem :-)


Well, the first thing that strikes me is that the row estimates are 
terrible for 7.4.12 (which runs quickly) and much better for 8.0.7 
(which runs slowly). Which suggests you were lucky before.

The second thing I notice is the bit that goes: Materialize ... Seq Scan 
on acl acl_2. If you compare the two you'll see that the 7.4 version 
loops 16,160 times but 8.0 loops 513,264 times.

This is a bad choice, and I'm guessing it's made because it gets the row 
estimate wrong:
Hash Join  (cost=4667.85..51078.88 rows=62852 width=727) (actual 
time=649.028..13602.451 rows=513264 loops=1)

That's the comparison Groups_3.id = CachedGroupMembers_4.GroupId if I'm 
reading this correctly. Is there anything unusual about those two columns?
-- 
   Richard Huxton
   Archonet Ltd