Thread: Same SQL, 104296ms of difference between 7.4.12 and 8.0.7
Hello
I have a sql statement that takes 108489.780 ms with 8.0.7 in a
RHEL4/amd64linux server with 2xAMD Opteron(tm) Processor 275 2.00GHz /
8GB RAM and only 4193.588 ms with 7.4.12 in a RHEL3/386linux server with
2xIntel(R) Xeon(TM) CPU 2.40GHz / 4GB RAM.
Some information:
- There is no IO when I am running the sql, but it uses 99% of the cpu.
- I run VACUUM VERBOSE ANALYZE in both databases before the test.
- The databases are identical.
- No other jobs running when testing.
- Some different parameters between 7.4.12 and 8.0.7 :
7.4.12:
-------
shared_buffers = 114966 #(15% of ram)
sort_mem = 16384
vacuum_mem = 524288
wal_buffers = 64
checkpoint_segments = 16
effective_cache_size = 383220 #(50% ram)
random_page_cost = 3
default_statistics_target = 100
8.0.7:
------
shared_buffers = 250160 #(25% ram)
work_mem = 8192
maintenance_work_mem = 131072
wal_buffers = 128
checkpoint_segments = 64
effective_cache_size = 500321 #(50% ram)
random_page_cost = 3
default_statistics_target = 100
Any ideas of what I can test/configurate to find out why this happens?
Thanks in advance.
*******************
With 7.4.12
*******************
rtprod=# explain analyze SELECT DISTINCT main.* FROM Users main ,
Principals Principals_1, ACL ACL_2, Groups Groups_3, CachedGroupMembers
CachedGroupMembers_4 WHERE ((ACL_2.RightName = 'OwnTicket')) AND
((CachedGroupMembers_4.MemberId = Principals_1.id)) AND ((Groups_3.id =
CachedGroupMembers_4.GroupId)) AND ((Principals_1.Disabled =
'0')OR(Principals_1.Disabled = '0')) AND ((Principals_1.id != '1')) AND
((main.id = Principals_1.id)) AND ( ( ACL_2.PrincipalId =
Groups_3.id AND ACL_2.PrincipalType = 'Group' AND ( Groups_3.Domain =
'SystemInternal' OR Groups_3.Domain = 'UserDefined' OR Groups_3.Domain =
'ACLEquivalence')) OR ( ( (Groups_3.Domain = 'RT::Queue-Role' ) ) AND
Groups_3.Type = ACL_2.PrincipalType) ) AND (ACL_2.ObjectType =
'RT::System' OR (ACL_2.ObjectType = 'RT::Queue') ) ORDER BY main.Name
ASC;
QUERYPLAN
Unique (cost=40250.00..40250.09 rows=1 width=695) (actual
time=3974.528..4182.343 rows=264 loops=1)
-> Sort (cost=40250.00..40250.00 rows=1 width=695) (actual
time=3974.522..3992.487 rows=24697 loops=1)
Sort Key: main.name, main.id, main."password", main.comments,
main.signature, main.emailaddress, main.freeformcontactinfo,
main.organization, main.realname, main.nickname, main.lang,
main.emailencoding, main.webencoding, main.externalcontactinfoid,
main.contactinfosystem, main.externalauthid, main.authsystem,
main.gecos, main.homephone, main.workphone, main.mobilephone,
main.pagerphone, main.address1, main.address2, main.city, main.state,
main.zip, main.country, main.timezone, main.pgpkey, main.creator,
main.created, main.lastupdatedby, main.lastupdated
-> Nested Loop (cost=33.67..40249.99 rows=1 width=695)
(actual time=37.793..3240.146 rows=24697 loops=1)
-> Nested Loop (cost=33.67..40246.95 rows=1 width=699)
(actual time=37.754..2635.812 rows=24697 loops=1)
-> Nested Loop (cost=33.67..40242.47 rows=1
width=4) (actual time=37.689..2091.634 rows=24755 loops=1)
-> Nested Loop (cost=33.67..40225.72 rows=1
width=4) (actual time=37.663..1967.388 rows=54 loops=1)
Join Filter:
(((("outer"."domain")::text = 'RT::Queue-Role'::text) OR
("inner".principalid = "outer".id)) AND ((("outer"."type")::text =
("inner".principaltype)::text) OR ("inner".principalid = "outer".id))
AND ((("outer"."domain")::text = 'RT::Queue-Role'::text) OR
(("inner".principaltype)::text = 'Group'::text)) AND
((("outer"."type")::text = ("inner".principaltype)::text) OR
(("inner".principaltype)::text = 'Group'::text)) AND
((("outer"."type")::text = ("inner".principaltype)::text) OR
(("outer"."domain")::text = 'SystemInternal'::text) OR
(("outer"."domain")::text = 'UserDefined'::text) OR
(("outer"."domain")::text = 'ACLEquivalence'::text)))
-> Index Scan using groups4, groups4,
groups4, groups4 on groups groups_3 (cost=0.00..2164.05 rows=15845
width=32) (actual time=0.041..43.636 rows=16160 loops=1)
Index Cond: ((("domain")::text =
'RT::Queue-Role'::text) OR (("domain")::text = 'SystemInternal'::text)
OR (("domain")::text = 'UserDefined'::text) OR (("domain")::text =
'ACLEquivalence'::text))
-> Materialize (cost=33.67..34.15
rows=48 width=13) (actual time=0.001..0.040 rows=54 loops=16160)
-> Seq Scan on acl acl_2
(cost=0.00..33.67 rows=48 width=13) (actual time=0.016..0.989 rows=54
loops=1)
Filter: (((rightname)::text
= 'OwnTicket'::text) AND (((objecttype)::text = 'RT::System'::text) OR
((objecttype)::text = 'RT::Queue'::text)))
-> Index Scan using cachedgroupmembers3 on
cachedgroupmembers cachedgroupmembers_4 (cost=0.00..16.45 rows=23
width=8) (actual time=0.015..1.296 rows=458 loops=54)
Index Cond: ("outer".id =
cachedgroupmembers_4.groupid)
-> Index Scan using users_pkey on users main
(cost=0.00..4.47 rows=1 width=695) (actual time=0.007..0.009 rows=1
loops=24755)
Index Cond: (main.id = "outer".memberid)
-> Index Scan using principals_pkey on principals
principals_1 (cost=0.00..3.02 rows=1 width=4) (actual time=0.010..0.012
rows=1 loops=24697)
Index Cond: ("outer".id = principals_1.id)
Filter: ((disabled = 0::smallint) AND (id <> 1))
Total runtime: 4193.588 ms
(21 rows)
*****************************
With 8.0.7
*****************************
rtprod=# explain analyze SELECT DISTINCT main.* FROM Users main ,
Principals Principals_1, ACL ACL_2, Groups Groups_3, CachedGroupMembers
CachedGroupMembers_4 WHERE ((ACL_2.RightName = 'OwnTicket')) AND
((CachedGroupMembers_4.MemberId = Principals_1.id)) AND ((Groups_3.id =
CachedGroupMembers_4.GroupId)) AND ((Principals_1.Disabled =
'0')OR(Principals_1.Disabled = '0')) AND ((Principals_1.id != '1')) AND
((main.id = Principals_1.id)) AND ( ( ACL_2.PrincipalId =
Groups_3.id AND ACL_2.PrincipalType = 'Group' AND ( Groups_3.Domain =
'SystemInternal' OR Groups_3.Domain = 'UserDefined' OR Groups_3.Domain =
'ACLEquivalence')) OR ( ( (Groups_3.Domain = 'RT::Queue-Role' ) ) AND
Groups_3.Type = ACL_2.PrincipalType) ) AND (ACL_2.ObjectType =
'RT::System' OR (ACL_2.ObjectType = 'RT::Queue') ) ORDER BY main.Name
ASC;
QUERYPLAN
Unique (cost=164248.03..164250.91 rows=33 width=695) (actual
time=108249.642..108479.808 rows=264 loops=1)
-> Sort (cost=164248.03..164248.11 rows=33 width=695) (actual
time=108249.637..108293.474 rows=24697 loops=1)
Sort Key: main.name, main.id, main."password", main.comments,
main.signature, main.emailaddress, main.freeformcontactinfo,
main.organization, main.realname, main.nickname, main.lang,
main.emailencoding, main.webencoding, main.externalcontactinfoid,
main.contactinfosystem, main.externalauthid, main.authsystem,
main.gecos, main.homephone, main.workphone, main.mobilephone,
main.pagerphone, main.address1, main.address2, main.city, main.state,
main.zip, main.country, main.timezone, main.pgpkey, main.creator,
main.created, main.lastupdatedby, main.lastupdated
-> Nested Loop (cost=4702.57..164247.19 rows=33 width=695)
(actual time=2949.010..107407.145 rows=24697 loops=1)
Join Filter: ((("inner".principalid = "outer".id) AND
(("inner".principaltype)::text = 'Group'::text) AND
((("outer"."domain")::text = 'SystemInternal'::text) OR
(("outer"."domain")::text = 'UserDefined'::text) OR
(("outer"."domain")::text = 'ACLEquivalence'::text))) OR
((("outer"."domain")::text = 'RT::Queue-Role'::text) AND
(("outer"."type")::text = ("inner".principaltype)::text)))
-> Hash Join (cost=4667.85..51078.88 rows=62852
width=727) (actual time=649.028..13602.451 rows=513264 loops=1)
Hash Cond: ("outer".groupid = "inner".id)
-> Merge Join (cost=0.00..32353.73 rows=62852
width=699) (actual time=0.809..6644.928 rows=513264 loops=1)
Merge Cond: ("outer".id = "inner".memberid)
-> Merge Join (cost=0.00..6379.54
rows=15877 width=699) (actual time=0.118..911.395 rows=15866 loops=1)
Merge Cond: ("outer".id = "inner".id)
-> Index Scan using users_pkey on
users main (cost=0.00..1361.01 rows=15880 width=695) (actual
time=0.016..49.141 rows=15880 loops=1)
-> Index Scan using principals_pkey on
principals principals_1 (cost=0.00..4399.08 rows=168394 width=4)
(actual time=0.026..412.688 rows=168409 loops=1)
Filter: ((disabled = 0::smallint)
AND (id <> 1))
-> Index Scan using cachedgroupmembers2 on
cachedgroupmembers cachedgroupmembers_4 (cost=0.00..18647.25
rows=666758 width=8) (actual time=0.008..1513.877 rows=666754 loops=1)
-> Hash (cost=3094.48..3094.48 rows=152548
width=32) (actual time=637.618..637.618 rows=0 loops=1)
-> Seq Scan on groups groups_3
(cost=0.00..3094.48 rows=152548 width=32) (actual time=0.017..333.669
rows=152548 loops=1)
-> Materialize (cost=34.72..35.20 rows=48 width=13)
(actual time=0.001..0.077 rows=54 loops=513264)
-> Seq Scan on acl acl_2 (cost=0.00..34.67
rows=48 width=13) (actual time=0.013..0.850 rows=54 loops=1)
Filter: (((rightname)::text =
'OwnTicket'::text) AND (((objecttype)::text = 'RT::System'::text) OR
((objecttype)::text = 'RT::Queue'::text)))
Total runtime: 108486.306 ms
(21 rows)
--
Rafael Martinez, <r.m.guerrero@usit.uio.no>
Center for Information Technology Services
University of Oslo, Norway
PGP Public Key: http://folk.uio.no/rafael/
Rafael Martinez Guerrero wrote:
> Hello
>
> I have a sql statement that takes 108489.780 ms with 8.0.7 in a
> RHEL4/amd64linux server with 2xAMD Opteron(tm) Processor 275 2.00GHz /
> 8GB RAM and only 4193.588 ms with 7.4.12 in a RHEL3/386linux server with
> 2xIntel(R) Xeon(TM) CPU 2.40GHz / 4GB RAM.
>
> Some information:
>
> - There is no IO when I am running the sql, but it uses 99% of the cpu.
> - I run VACUUM VERBOSE ANALYZE in both databases before the test.
> - The databases are identical.
> - No other jobs running when testing.
> - Some different parameters between 7.4.12 and 8.0.7 :
>
> 7.4.12:
> -------
> shared_buffers = 114966 #(15% of ram)
> sort_mem = 16384
> vacuum_mem = 524288
> wal_buffers = 64
> checkpoint_segments = 16
> effective_cache_size = 383220 #(50% ram)
> random_page_cost = 3
> default_statistics_target = 100
>
> 8.0.7:
> ------
> shared_buffers = 250160 #(25% ram)
> work_mem = 8192
> maintenance_work_mem = 131072
> wal_buffers = 128
> checkpoint_segments = 64
> effective_cache_size = 500321 #(50% ram)
> random_page_cost = 3
> default_statistics_target = 100
>
> 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.
--
Richard Huxton
Archonet Ltd
On Fri, 2006-04-07 at 15:31, Richard Huxton wrote: > Rafael Martinez Guerrero wrote: > > Hello > > > > I have a sql statement that takes 108489.780 ms with 8.0.7 in a > > RHEL4/amd64linux server with 2xAMD Opteron(tm) Processor 275 2.00GHz / > > 8GB RAM and only 4193.588 ms with 7.4.12 in a RHEL3/386linux server with > > 2xIntel(R) Xeon(TM) CPU 2.40GHz / 4GB RAM. > > > > Some information: > > > > - There is no IO when I am running the sql, but it uses 99% of the cpu. > > - I run VACUUM VERBOSE ANALYZE in both databases before the test. > > - The databases are identical. > > - No other jobs running when testing. > > - Some different parameters between 7.4.12 and 8.0.7 : > > > > 7.4.12: > > ------- > > shared_buffers = 114966 #(15% of ram) > > sort_mem = 16384 > > vacuum_mem = 524288 > > wal_buffers = 64 > > checkpoint_segments = 16 > > effective_cache_size = 383220 #(50% ram) > > random_page_cost = 3 > > default_statistics_target = 100 > > > > 8.0.7: > > ------ > > shared_buffers = 250160 #(25% ram) > > work_mem = 8192 > > maintenance_work_mem = 131072 > > wal_buffers = 128 > > checkpoint_segments = 64 > > effective_cache_size = 500321 #(50% ram) > > random_page_cost = 3 > > default_statistics_target = 100 > > > > 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 -- Rafael Martinez, <r.m.guerrero@usit.uio.no> Center for Information Technology Services University of Oslo, Norway PGP Public Key: http://folk.uio.no/rafael/
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
On Fri, 2006-04-07 at 16:41 +0200, Gábriel Ákos wrote: > > > > Any ideas of what I can test/configurate to find out why this happens? > > Thanks in advance. > > Increase work_mem to 50% of memory, and don't care about > maintenance_work_mem and effective_cache_size, they don't matter in this > case. > The problem is not the amount of memory. It works much faster with only 16M and 7.4.12 than 8.0.7. -- Rafael Martinez, <r.m.guerrero@usit.uio.no> Center for Information Technology Services University of Oslo, Norway PGP Public Key: http://folk.uio.no/rafael/
Rafael Martinez Guerrero <r.m.guerrero@usit.uio.no> writes:
> I have a sql statement that takes 108489.780 ms with 8.0.7 in a
> RHEL4/amd64linux server with 2xAMD Opteron(tm) Processor 275 2.00GHz /
> 8GB RAM and only 4193.588 ms with 7.4.12 in a RHEL3/386linux server with
> 2xIntel(R) Xeon(TM) CPU 2.40GHz / 4GB RAM.
I think you've discovered a planner regression.
Simplified test case using the regression database:
explain select * from tenk1 a, tenk1 b
where (a.ten = b.ten and (a.unique1 = 100 or a.unique1 = 101))
or (a.hundred = b.hundred and a.unique1 = 42);
7.4:
Nested Loop (cost=0.00..2219.74 rows=4 width=488)
Join Filter: ((("outer".hundred = "inner".hundred) OR ("outer".ten = "inner".ten)) AND (("outer".unique1 = 42) OR
("outer".ten= "inner".ten)) AND (("outer".hundred = "inner".hundred) OR ("outer".unique1 = 100) OR ("outer".unique1 =
101)))
-> Index Scan using tenk1_unique1, tenk1_unique1, tenk1_unique1 on tenk1 a (cost=0.00..18.04 rows=3 width=244)
Index Cond: ((unique1 = 42) OR (unique1 = 100) OR (unique1 = 101))
-> Seq Scan on tenk1 b (cost=0.00..458.24 rows=10024 width=244)
(5 rows)
8.0:
Nested Loop (cost=810.00..6671268.00 rows=2103 width=488)
Join Filter: ((("outer".ten = "inner".ten) AND (("outer".unique1 = 100) OR ("outer".unique1 = 101))) OR
(("outer".hundred= "inner".hundred) AND ("outer".unique1 = 42)))
-> Seq Scan on tenk1 a (cost=0.00..458.00 rows=10000 width=244)
-> Materialize (cost=810.00..1252.00 rows=10000 width=244)
-> Seq Scan on tenk1 b (cost=0.00..458.00 rows=10000 width=244)
(5 rows)
Note the failure to pull out the unique1 conditions from the join clause
and use them with the index. I didn't bother to do EXPLAIN ANALYZE;
this plan obviously sucks compared to the other.
8.1:
TRAP: FailedAssertion("!(!restriction_is_or_clause((RestrictInfo *) orarg))", File: "indxpath.c", Line: 479)
LOG: server process (PID 12201) was terminated by signal 6
server closed the connection unexpectedly
Oh dear.
regards, tom lane
I wrote:
> Rafael Martinez Guerrero <r.m.guerrero@usit.uio.no> writes:
>> I have a sql statement that takes 108489.780 ms with 8.0.7 in a
>> RHEL4/amd64linux server with 2xAMD Opteron(tm) Processor 275 2.00GHz /
>> 8GB RAM and only 4193.588 ms with 7.4.12 in a RHEL3/386linux server with
>> 2xIntel(R) Xeon(TM) CPU 2.40GHz / 4GB RAM.
> I think you've discovered a planner regression.
> Simplified test case using the regression database:
> explain select * from tenk1 a, tenk1 b
> where (a.ten = b.ten and (a.unique1 = 100 or a.unique1 = 101))
> or (a.hundred = b.hundred and a.unique1 = 42);
I've repaired the assertion crash in 8.1/HEAD, but I don't think it's
practical to teach 8.0 to optimize queries like this nicely. The reason
7.4 can do it is that 7.4 forces the WHERE condition into CNF, ie
(a.hundred = b.hundred OR a.ten = b.ten) AND
(a.unique1 = 42 OR a.ten = b.ten) AND
(a.hundred = b.hundred OR a.unique1 = 100 OR a.unique1 = 101) AND
(a.unique1 = 42 OR a.unique1 = 100 OR a.unique1 = 101)
from which it's easy to extract the index condition for A. We decided
that forcing to CNF wasn't such a hot idea, so 8.0 and later don't do
it, but 8.0's logic for extracting index conditions from joinquals isn't
up to the problem of handling sub-ORs. Fixing that looks like a larger
change than I care to back-patch into an old release.
My recommendation is to update to 8.1.4 when it comes out.
regards, tom lane
On Fri, 2006-04-07 at 13:36 -0400, Tom Lane wrote: > I wrote: > > Rafael Martinez Guerrero <r.m.guerrero@usit.uio.no> writes: > >> I have a sql statement that takes 108489.780 ms with 8.0.7 in a > >> RHEL4/amd64linux server with 2xAMD Opteron(tm) Processor 275 2.00GHz / > >> 8GB RAM and only 4193.588 ms with 7.4.12 in a RHEL3/386linux server with > >> 2xIntel(R) Xeon(TM) CPU 2.40GHz / 4GB RAM. > > > I think you've discovered a planner regression. > > Simplified test case using the regression database: > > > explain select * from tenk1 a, tenk1 b > > where (a.ten = b.ten and (a.unique1 = 100 or a.unique1 = 101)) > > or (a.hundred = b.hundred and a.unique1 = 42); > > I've repaired the assertion crash in 8.1/HEAD, but I don't think it's > practical to teach 8.0 to optimize queries like this nicely. The reason > 7.4 can do it is that 7.4 forces the WHERE condition into CNF, ie > [..................] Tom, thank you very much for your help. As I suspected this was a more complicated problem than the configuration of some parameters :( . Good that we have found out this now and not after the upgrade. All our upgrade plans and testing for all our databases have been done for/with 8.0.x (yes, I know 8.1.x is much better, but I am working in a conservative place from the sysadm point of view). We will have to change our plans and go for 8.1 if we want this to work. > My recommendation is to update to 8.1.4 when it comes out. Any idea about when 8.1.4 will be released? Thanks again. -- Rafael Martinez, <r.m.guerrero@usit.uio.no> Center for Information Technology Services University of Oslo, Norway PGP Public Key: http://folk.uio.no/rafael/