Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.72) (envelope-from ) id 1UZOLZ-0006Yh-U3 for pgsql-performance@arkaria.postgresql.org; Mon, 06 May 2013 16:33:06 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.72) (envelope-from ) id 1UZOLZ-0002Xv-Ds for pgsql-performance@arkaria.postgresql.org; Mon, 06 May 2013 16:33:05 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtp (Exim 4.72) (envelope-from ) id 1UX8cL-0005r6-OM for pgsql-performance@postgresql.org; Tue, 30 Apr 2013 11:21:05 +0000 Received: from cl-2390.ham-01.de.sixxs.net ([2001:6f8:900:955::2] helo=feynman.df7cb.de) by magus.postgresql.org with esmtp (Exim 4.72) (envelope-from ) id 1UX8cF-0005pn-B3 for pgsql-performance@postgresql.org; Tue, 30 Apr 2013 11:21:05 +0000 Received: from msgid.df7cb.de (benz.df7cb.de [IPv6:2001:6f8:10ee:e:134::2]) (using TLSv1 with cipher DHE-RSA-AES128-SHA (128/128 bits)) (Client did not present a certificate) by feynman.df7cb.de (Postfix) with ESMTPSA id 916F4698BE for ; Tue, 30 Apr 2013 13:20:56 +0200 (CEST) Date: Tue, 30 Apr 2013 13:20:55 +0200 From: Christoph Berg To: PostgreSQL Performance Subject: RT3.4 query needed a lot more tuning with 9.2 than it did with 8.1 Message-ID: <20130430112055.GA27525@msgid.df7cb.de> Mail-Followup-To: Christoph Berg , PostgreSQL Performance MIME-Version: 1.0 Content-Type: multipart/signed; micalg=pgp-sha256; protocol="application/pgp-signature"; boundary="lrZ03NoBR/3+SXJZ" Content-Disposition: inline User-Agent: Mutt/1.5.21 (2010-09-15) X-Pg-Spam-Score: -1.9 (-) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org --lrZ03NoBR/3+SXJZ Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Content-Transfer-Encoding: quoted-printable Hi, this is more of a report than a question, because we thought this would be interesting to share. We recently (finally) migrated an Request Tracker 3.4 database running on 8.1.19 to 9.2.4. The queries used by rt3.4 are sometimes weird, but 8.1 coped without too much tuning. The schema looks like this: http://bestpractical.com/rt/3.4-schema.png One query that took about 80ms on 8.1.19 took 8s on 9.2.4: SELECT DISTINCT main.* FROM Users main , Principals Principals_1, ACL ACL_2= , Groups Groups_3, CachedGroupMembers CachedGroupMembers_4 WHERE ((ACL_2.RightName =3D 'OwnTicket')) AND ((CachedGroupMembers_4.MemberId =3D Principals_1.id)) AND ((Groups_3.id =3D CachedGroupMembers_4.GroupId)) AND ((Principals_1.Disabled =3D '0') OR (Principals_1.Disabled =3D '0')) AND ((Principals_1.id !=3D '1')) AND ((main.id =3D Principals_1.id)) AND ( ( ACL_2.PrincipalId =3D Groups_3.id AND ACL_2.PrincipalType =3D 'Grou= p' AND ( Groups_3.Domain =3D 'SystemInternal' OR Groups_3.Domain = =3D 'UserDefined' OR Groups_3.Domain =3D 'ACLEquivalence')) OR ( ( (Groups_3.Domain =3D 'RT::Queue-Role' AND Groups_3.Instance= =3D 10) OR ( Groups_3.Domain =3D 'RT::Ticket-Role' AND Groups_3.Instance = =3D 999028) ) AND Groups_3.Type =3D ACL_2.PrincipalType) ) AND (ACL_2.ObjectType =3D 'RT::System' OR (ACL_2.ObjectType =3D 'RT::Q= ueue' AND ACL_2.ObjectId =3D 10) ) ORDER BY main.Name ASC; 8.1 plan: (http://explain.depesz.com/s/gZ6) Unique (cost=3D1117.67..1118.46 rows=3D9 width=3D1115) (actual time=3D82.= 646..85.695 rows=3D439 loops=3D1) -> Sort (cost=3D1117.67..1117.70 rows=3D9 width=3D1115) (actual time= =3D82.645..82.786 rows=3D1518 loops=3D1) Sort Key: main.name, main.id, main."password", main.comments, main= =2Esignature, main.emailaddress, main.freeformcontactinfo, main.organizatio= n, main.realname, main.nickname, main.lang, main.emailencoding, main.webenc= oding, main.externalcontactinfoid, main.contactinfosystem, main.externalaut= hid, main.authsystem, main.gecos, main.homephone, main.workphone, main.mobi= lephone, main.pagerphone, main.address1, main.address2, main.city, main.sta= te, main.zip, main.country, main.timezone, main.pgpkey, main.creator, main.= created, main.lastupdatedby, main.lastupdated -> Nested Loop (cost=3D10.51..1117.53 rows=3D9 width=3D1115) (ac= tual time=3D0.205..23.688 rows=3D1518 loops=3D1) -> Nested Loop (cost=3D10.51..1087.81 rows=3D9 width=3D111= 9) (actual time=3D0.193..13.495 rows=3D1600 loops=3D1) -> Nested Loop (cost=3D10.51..1060.15 rows=3D9 width= =3D4) (actual time=3D0.175..3.307 rows=3D1635 loops=3D1) -> Nested Loop (cost=3D10.51..536.13 rows=3D4 = width=3D4) (actual time=3D0.161..1.057 rows=3D23 loops=3D1) Join Filter: ((("outer".principalid =3D "i= nner".id) AND (("outer".principaltype)::text =3D 'Group'::text) AND ((("inn= er"."domain")::text =3D 'SystemInternal'::text) OR (("inner"."domain")::tex= t =3D 'UserDefined'::text) OR (("inner"."domain")::text =3D 'ACLEquivalence= '::text))) OR ((((("inner"."domain")::text =3D 'RT::Queue-Role'::text) AND = ("inner".instance =3D 10)) OR ((("inner"."domain")::text =3D 'RT::Ticket-Ro= le'::text) AND ("inner".instance =3D 999028))) AND (("inner"."type")::text = =3D ("outer".principaltype)::text))) -> Bitmap Heap Scan on acl acl_2 (cost= =3D4.24..61.15 rows=3D33 width=3D13) (actual time=3D0.107..0.141 rows=3D22 = loops=3D1) Recheck Cond: ((((rightname)::text = =3D 'OwnTicket'::text) AND ((objecttype)::text =3D 'RT::System'::text)) OR = (((rightname)::text =3D 'OwnTicket'::text) AND ((objecttype)::text =3D 'RT:= :Queue'::text) AND (objectid =3D 10))) -> BitmapOr (cost=3D4.24..4.24 row= s=3D34 width=3D0) (actual time=3D0.097..0.097 rows=3D0 loops=3D1) -> Bitmap Index Scan on acl1 = (cost=3D0.00..2.13 rows=3D22 width=3D0) (actual time=3D0.054..0.054 rows= =3D8 loops=3D1) Index Cond: (((rightname= )::text =3D 'OwnTicket'::text) AND ((objecttype)::text =3D 'RT::System'::te= xt)) -> Bitmap Index Scan on acl1 = (cost=3D0.00..2.11 rows=3D13 width=3D0) (actual time=3D0.041..0.041 rows= =3D14 loops=3D1) Index Cond: (((rightname= )::text =3D 'OwnTicket'::text) AND ((objecttype)::text =3D 'RT::Queue'::tex= t) AND (objectid =3D 10)) -> Bitmap Heap Scan on groups groups_3 (= cost=3D6.27..14.32 rows=3D2 width=3D36) (actual time=3D0.036..0.036 rows=3D= 1 loops=3D22) Recheck Cond: (("outer".principalid = =3D groups_3.id) OR ((((groups_3."type")::text =3D ("outer".principaltype):= :text) AND (groups_3.instance =3D 10) AND ((groups_3."domain")::text =3D 'R= T::Queue-Role'::text)) OR (((groups_3."type")::text =3D ("outer".principalt= ype)::text) AND (groups_3.instance =3D 999028) AND ((groups_3."domain")::te= xt =3D 'RT::Ticket-Role'::text)))) Filter: ((("domain")::text =3D 'Syst= emInternal'::text) OR (("domain")::text =3D 'UserDefined'::text) OR (("doma= in")::text =3D 'ACLEquivalence'::text) OR ((("domain")::text =3D 'RT::Queue= -Role'::text) AND (instance =3D 10)) OR (instance =3D 999028)) -> BitmapOr (cost=3D6.27..6.27 row= s=3D2 width=3D0) (actual time=3D0.033..0.033 rows=3D0 loops=3D22) -> Bitmap Index Scan on group= s_pkey (cost=3D0.00..2.00 rows=3D1 width=3D0) (actual time=3D0.006..0.006 = rows=3D1 loops=3D22) Index Cond: ("outer".pri= ncipalid =3D groups_3.id) -> BitmapOr (cost=3D4.02..4.= 02 rows=3D1 width=3D0) (actual time=3D0.025..0.025 rows=3D0 loops=3D22) -> Bitmap Index Scan on= groups2 (cost=3D0.00..2.01 rows=3D1 width=3D0) (actual time=3D0.013..0.01= 3 rows=3D0 loops=3D22) Index Cond: (((gro= ups_3."type")::text =3D ("outer".principaltype)::text) AND (groups_3.instan= ce =3D 10) AND ((groups_3."domain")::text =3D 'RT::Queue-Role'::text)) -> Bitmap Index Scan on= groups2 (cost=3D0.00..2.01 rows=3D1 width=3D0) (actual time=3D0.011..0.01= 1 rows=3D0 loops=3D22) Index Cond: (((gro= ups_3."type")::text =3D ("outer".principaltype)::text) AND (groups_3.instan= ce =3D 999028) AND ((groups_3."domain")::text =3D 'RT::Ticket-Role'::text)) -> Index Scan using cachedgroupmembers3 on cach= edgroupmembers cachedgroupmembers_4 (cost=3D0.00..130.13 rows=3D70 width= =3D8) (actual time=3D0.007..0.074 rows=3D71 loops=3D23) Index Cond: ("outer".id =3D cachedgroupmem= bers_4.groupid) -> Index Scan using users_pkey on users main (cost= =3D0.00..3.06 rows=3D1 width=3D1115) (actual time=3D0.004..0.005 rows=3D1 l= oops=3D1635) Index Cond: (main.id =3D "outer".memberid) -> Index Scan using principals_pkey on principals principal= s_1 (cost=3D0.00..3.29 rows=3D1 width=3D4) (actual time=3D0.005..0.005 row= s=3D1 loops=3D1600) Index Cond: ("outer".memberid =3D principals_1.id) Filter: ((disabled =3D 0) AND (id <> 1)) Total runtime: 86.293 ms (34 Zeilen) Untuned 9.2 plan: (http://explain.depesz.com/s/mQw) Unique (cost=3D784205.94..796940.08 rows=3D145533 width=3D1061) (actual t= ime=3D9710.683..9713.175 rows=3D439 loops=3D1) -> Sort (cost=3D784205.94..784569.77 rows=3D145533 width=3D1061) (actu= al time=3D9710.682..9710.792 rows=3D1518 loops=3D1) Sort Key: main.name, main.id, main.password, main.comments, main.s= ignature, main.emailaddress, main.freeformcontactinfo, main.organization, m= ain.realname, main.nickname, main.lang, main.emailencoding, main.webencodin= g, main.externalcontactinfoid, main.contactinfosystem, main.externalauthid,= main.authsystem, main.gecos, main.homephone, main.workphone, main.mobileph= one, main.pagerphone, main.address1, main.address2, main.city, main.state, = main.zip, main.country, main.timezone, main.pgpkey, main.creator, main.crea= ted, main.lastupdatedby, main.lastupdated Sort Method: quicksort Memory: 569kB -> Hash Join (cost=3D379261.01..568771.27 rows=3D145533 width=3D= 1061) (actual time=3D6432.551..9673.393 rows=3D1518 loops=3D1) Hash Cond: (principals_1.id =3D main.id) -> Seq Scan on principals principals_1 (cost=3D0.00..11111= 2.14 rows=3D4970343 width=3D4) (actual time=3D0.024..1903.364 rows=3D497035= 7 loops=3D1) Filter: ((id <> 1) AND (disabled =3D 0)) Rows Removed by Filter: 149 -> Hash (cost=3D357969.80..357969.80 rows=3D145537 width= =3D1065) (actual time=3D5887.121..5887.121 rows=3D1600 loops=3D1) Buckets: 1024 Batches: 256 Memory Usage: 17kB -> Merge Join (cost=3D327489.90..357969.80 rows=3D14= 5537 width=3D1065) (actual time=3D5618.604..5880.608 rows=3D1600 loops=3D1) Merge Cond: (main.id =3D cachedgroupmembers_4.me= mberid) -> Index Scan using users_pkey on users main (= cost=3D0.00..27100.40 rows=3D389108 width=3D1061) (actual time=3D0.032..205= =2E696 rows=3D383693 loops=3D1) -> Materialize (cost=3D327350.03..328077.71 ro= ws=3D145536 width=3D4) (actual time=3D5618.545..5619.315 rows=3D1635 loops= =3D1) -> Sort (cost=3D327350.03..327713.87 row= s=3D145536 width=3D4) (actual time=3D5618.539..5618.940 rows=3D1635 loops= =3D1) Sort Key: cachedgroupmembers_4.membe= rid Sort Method: quicksort Memory: 125kB -> Hash Join (cost=3D1868.02..3128= 78.08 rows=3D145536 width=3D4) (actual time=3D0.890..5617.609 rows=3D1635 l= oops=3D1) Hash Cond: (cachedgroupmembers= _4.groupid =3D groups_3.id) -> Seq Scan on cachedgroupmem= bers cachedgroupmembers_4 (cost=3D0.00..185630.60 rows=3D10696560 width=3D= 8) (actual time=3D0.018..2940.137 rows=3D10696622 loops=3D1) -> Hash (cost=3D844.83..844.= 83 rows=3D62335 width=3D4) (actual time=3D0.760..0.760 rows=3D23 loops=3D1) Buckets: 4096 Batches: = 4 Memory Usage: 12kB -> Nested Loop (cost= =3D24.57..844.83 rows=3D62335 width=3D4) (actual time=3D0.109..0.633 rows= =3D23 loops=3D1) -> Bitmap Heap Sc= an on acl acl_2 (cost=3D8.90..61.36 rows=3D33 width=3D10) (actual time=3D0= =2E070..0.112 rows=3D22 loops=3D1) Recheck Cond= : ((((rightname)::text =3D 'OwnTicket'::text) AND ((objecttype)::text =3D '= RT::System'::text)) OR (((rightname)::text =3D 'OwnTicket'::text) AND ((obj= ecttype)::text =3D 'RT::Queue'::text) AND (objectid =3D 10))) -> BitmapOr= (cost=3D8.90..8.90 rows=3D35 width=3D0) (actual time=3D0.064..0.064 rows= =3D0 loops=3D1) -> Bi= tmap Index Scan on acl1 (cost=3D0.00..4.47 rows=3D22 width=3D0) (actual ti= me=3D0.036..0.036 rows=3D8 loops=3D1) = Index Cond: (((rightname)::text =3D 'OwnTicket'::text) AND ((objecttype)::t= ext =3D 'RT::System'::text)) -> Bi= tmap Index Scan on acl1 (cost=3D0.00..4.41 rows=3D13 width=3D0) (actual ti= me=3D0.026..0.026 rows=3D14 loops=3D1) = Index Cond: (((rightname)::text =3D 'OwnTicket'::text) AND ((objecttype)::t= ext =3D 'RT::Queue'::text) AND (objectid =3D 10)) -> Bitmap Heap Sc= an on groups groups_3 (cost=3D15.67..23.73 rows=3D1 width=3D30) (actual ti= me=3D0.022..0.023 rows=3D1 loops=3D22) Recheck Cond= : ((acl_2.principalid =3D id) OR ((((type)::text =3D (acl_2.principaltype):= :text) AND (instance =3D 10) AND ((domain)::text =3D 'RT::Queue-Role'::text= )) OR (((type)::text =3D (acl_2.principaltype)::text) AND (instance =3D 999= 028) AND ((domain)::text =3D 'RT::Ticket-Role'::text)))) Filter: ((((= domain)::text =3D 'SystemInternal'::text) OR ((domain)::text =3D 'UserDefin= ed'::text) OR ((domain)::text =3D 'ACLEquivalence'::text) OR (((domain)::te= xt =3D 'RT::Queue-Role'::text) AND (instance =3D 10)) OR (((domain)::text = =3D 'RT::Ticket-Role'::text) AND (instance =3D 999028))) AND (((acl_2.princ= ipalid =3D id) AND ((acl_2.principaltype)::text =3D 'Group'::text) AND (((d= omain)::text =3D 'SystemInternal'::text) OR ((domain)::text =3D 'UserDefine= d'::text) OR ((domain)::text =3D 'ACLEquivalence'::text))) OR (((((domain):= :text =3D 'RT::Queue-Role'::text) AND (instance =3D 10)) OR (((domain)::tex= t =3D 'RT::Ticket-Role'::text) AND (instance =3D 999028))) AND ((type)::tex= t =3D (acl_2.principaltype)::text)))) -> BitmapOr= (cost=3D15.67..15.67 rows=3D2 width=3D0) (actual time=3D0.019..0.019 rows= =3D0 loops=3D22) -> Bi= tmap Index Scan on groups_pkey (cost=3D0.00..4.76 rows=3D1 width=3D0) (act= ual time=3D0.005..0.005 rows=3D1 loops=3D22) = Index Cond: (acl_2.principalid =3D id) -> Bi= tmapOr (cost=3D10.66..10.66 rows=3D1 width=3D0) (actual time=3D0.013..0.01= 3 rows=3D0 loops=3D22) = -> Bitmap Index Scan on groups2 (cost=3D0.00..5.33 rows=3D1 width=3D0) (a= ctual time=3D0.007..0.007 rows=3D0 loops=3D22) = Index Cond: (((type)::text =3D (acl_2.principaltype)::text) AND (inst= ance =3D 10) AND ((domain)::text =3D 'RT::Queue-Role'::text)) = -> Bitmap Index Scan on groups2 (cost=3D0.00..5.33 rows=3D1 width=3D0) (a= ctual time=3D0.006..0.006 rows=3D0 loops=3D22) = Index Cond: (((type)::text =3D (acl_2.principaltype)::text) AND (inst= ance =3D 999028) AND ((domain)::text =3D 'RT::Ticket-Role'::text)) Total runtime: 9713.547 ms (43 Zeilen) Things got a lot better with enable_seqscan=3Doff: (http://explain.depesz.c= om/s/WPt) Unique (cost=3D1509543.77..1522277.91 rows=3D145533 width=3D1061) (actual= time=3D306.972..309.551 rows=3D439 loops=3D1) -> Sort (cost=3D1509543.77..1509907.60 rows=3D145533 width=3D1061) (ac= tual time=3D306.971..307.108 rows=3D1518 loops=3D1) Sort Key: main.name, main.id, main.password, main.comments, main.s= ignature, main.emailaddress, main.freeformcontactinfo, main.organization, m= ain.realname, main.nickname, main.lang, main.emailencoding, main.webencodin= g, main.externalcontactinfoid, main.contactinfosystem, main.externalauthid,= main.authsystem, main.gecos, main.homephone, main.workphone, main.mobileph= one, main.pagerphone, main.address1, main.address2, main.city, main.state, = main.zip, main.country, main.timezone, main.pgpkey, main.creator, main.crea= ted, main.lastupdatedby, main.lastupdated Sort Method: quicksort Memory: 569kB -> Nested Loop (cost=3D828855.15..1294109.10 rows=3D145533 width= =3D1061) (actual time=3D2.951..267.996 rows=3D1518 loops=3D1) Join Filter: (main.id =3D principals_1.id) -> Merge Join (cost=3D828855.15..858971.23 rows=3D145537 w= idth=3D1065) (actual time=3D2.940..260.852 rows=3D1600 loops=3D1) Merge Cond: (cachedgroupmembers_4.memberid =3D main.id) -> Sort (cost=3D828715.29..829079.13 rows=3D145537 w= idth=3D4) (actual time=3D2.903..3.321 rows=3D1635 loops=3D1) Sort Key: cachedgroupmembers_4.memberid Sort Method: quicksort Memory: 125kB -> Nested Loop (cost=3D15.67..814243.24 rows= =3D145537 width=3D4) (actual time=3D0.234..2.407 rows=3D1635 loops=3D1) -> Nested Loop (cost=3D15.67..1108.61 ro= ws=3D62334 width=3D4) (actual time=3D0.219..0.903 rows=3D23 loops=3D1) -> Index Only Scan using acl1 on ac= l acl_2 (cost=3D0.00..325.14 rows=3D33 width=3D10) (actual time=3D0.121..0= =2E367 rows=3D22 loops=3D1) Index Cond: (rightname =3D 'Ow= nTicket'::text) Filter: (((objecttype)::text = =3D 'RT::System'::text) OR (((objecttype)::text =3D 'RT::Queue'::text) AND = (objectid =3D 10))) Rows Removed by Filter: 220 Heap Fetches: 242 -> Bitmap Heap Scan on groups group= s_3 (cost=3D15.67..23.73 rows=3D1 width=3D30) (actual time=3D0.023..0.023 = rows=3D1 loops=3D22) Recheck Cond: ((acl_2.principa= lid =3D id) OR ((((type)::text =3D (acl_2.principaltype)::text) AND (instan= ce =3D 10) AND ((domain)::text =3D 'RT::Queue-Role'::text)) OR (((type)::te= xt =3D (acl_2.principaltype)::text) AND (instance =3D 999028) AND ((domain)= ::text =3D 'RT::Ticket-Role'::text)))) Filter: ((((domain)::text =3D = 'SystemInternal'::text) OR ((domain)::text =3D 'UserDefined'::text) OR ((do= main)::text =3D 'ACLEquivalence'::text) OR (((domain)::text =3D 'RT::Queue-= Role'::text) AND (instance =3D 10)) OR (((domain)::text =3D 'RT::Ticket-Rol= e'::text) AND (instance =3D 999028))) AND (((acl_2.principalid =3D id) AND = ((acl_2.principaltype)::text =3D 'Group'::text) AND (((domain)::text =3D 'S= ystemInternal'::text) OR ((domain)::text =3D 'UserDefined'::text) OR ((doma= in)::text =3D 'ACLEquivalence'::text))) OR (((((domain)::text =3D 'RT::Queu= e-Role'::text) AND (instance =3D 10)) OR (((domain)::text =3D 'RT::Ticket-R= ole'::text) AND (instance =3D 999028))) AND ((type)::text =3D (acl_2.princi= paltype)::text)))) -> BitmapOr (cost=3D15.67..1= 5.67 rows=3D2 width=3D0) (actual time=3D0.019..0.019 rows=3D0 loops=3D22) -> Bitmap Index Scan on= groups_pkey (cost=3D0.00..4.76 rows=3D1 width=3D0) (actual time=3D0.005..= 0.005 rows=3D1 loops=3D22) Index Cond: (acl_2= =2Eprincipalid =3D id) -> BitmapOr (cost=3D10= =2E66..10.66 rows=3D1 width=3D0) (actual time=3D0.013..0.013 rows=3D0 loops= =3D22) -> Bitmap Index S= can on groups2 (cost=3D0.00..5.33 rows=3D1 width=3D0) (actual time=3D0.007= =2E.0.007 rows=3D0 loops=3D22) Index Cond: = (((type)::text =3D (acl_2.principaltype)::text) AND (instance =3D 10) AND (= (domain)::text =3D 'RT::Queue-Role'::text)) -> Bitmap Index S= can on groups2 (cost=3D0.00..5.33 rows=3D1 width=3D0) (actual time=3D0.006= =2E.0.006 rows=3D0 loops=3D22) Index Cond: = (((type)::text =3D (acl_2.principaltype)::text) AND (instance =3D 999028) A= ND ((domain)::text =3D 'RT::Ticket-Role'::text)) -> Index Scan using cachedgroupmembers3 o= n cachedgroupmembers cachedgroupmembers_4 (cost=3D0.00..12.89 rows=3D15 wi= dth=3D8) (actual time=3D0.009..0.049 rows=3D71 loops=3D23) Index Cond: (groupid =3D groups_3.id) -> Index Scan using users_pkey on users main (cost= =3D0.00..27100.40 rows=3D389108 width=3D1061) (actual time=3D0.030..201.696= rows=3D384832 loops=3D1) -> Index Scan using principals_pkey on principals principal= s_1 (cost=3D0.00..2.98 rows=3D1 width=3D4) (actual time=3D0.003..0.004 row= s=3D1 loops=3D1600) Index Cond: (id =3D cachedgroupmembers_4.memberid) Filter: ((id <> 1) AND (disabled =3D 0)) Rows Removed by Filter: 0 Total runtime: 309.868 ms (37 Zeilen) A similar result was with seqscans re-enabled, but effective_cache_size=3D3= 2GB (anything >=3D 2GB worked), and the cachedgroupmembers.memberis stats targe= t set to 500: (http://explain.depesz.com/s/GJa) Unique (cost=3D422364.07..434891.88 rows=3D143175 width=3D1085) (actual t= ime=3D313.184..315.682 rows=3D439 loops=3D1) -> Sort (cost=3D422364.07..422722.01 rows=3D143175 width=3D1085) (actu= al time=3D313.181..313.301 rows=3D1518 loops=3D1) Sort Key: main.name, main.id, main.password, main.comments, main.s= ignature, main.emailaddress, main.freeformcontactinfo, main.organization, m= ain.realname, main.nickname, main.lang, main.emailencoding, main.webencodin= g, main.externalcontactinfoid, main.contactinfosystem, main.externalauthid,= main.authsystem, main.gecos, main.homephone, main.workphone, main.mobileph= one, main.pagerphone, main.address1, main.address2, main.city, main.state, = main.zip, main.country, main.timezone, main.pgpkey, main.creator, main.crea= ted, main.lastupdatedby, main.lastupdated Sort Method: quicksort Memory: 569kB -> Nested Loop (cost=3D197638.24..342080.48 rows=3D143175 width= =3D1085) (actual time=3D4.382..274.157 rows=3D1518 loops=3D1) Join Filter: (main.id =3D principals_1.id) -> Merge Join (cost=3D197638.24..220156.59 rows=3D143179 w= idth=3D1089) (actual time=3D4.369..267.021 rows=3D1600 loops=3D1) Merge Cond: (main.id =3D cachedgroupmembers_4.memberid) -> Index Scan using users_pkey on users main (cost= =3D0.00..19537.00 rows=3D389111 width=3D1085) (actual time=3D0.033..206.621= rows=3D383693 loops=3D1) -> Sort (cost=3D197499.17..197857.11 rows=3D143178 w= idth=3D4) (actual time=3D4.326..4.737 rows=3D1635 loops=3D1) Sort Key: cachedgroupmembers_4.memberid Sort Method: quicksort Memory: 125kB -> Nested Loop (cost=3D15.67..185237.80 rows= =3D143178 width=3D4) (actual time=3D0.088..3.749 rows=3D1635 loops=3D1) -> Nested Loop (cost=3D15.67..937.99 row= s=3D61327 width=3D4) (actual time=3D0.073..2.047 rows=3D23 loops=3D1) -> Seq Scan on acl acl_2 (cost=3D0= =2E00..154.68 rows=3D33 width=3D10) (actual time=3D0.022..1.485 rows=3D22 l= oops=3D1) Filter: (((rightname)::text = =3D 'OwnTicket'::text) AND (((objecttype)::text =3D 'RT::System'::text) OR = (((objecttype)::text =3D 'RT::Queue'::text) AND (objectid =3D 10)))) Rows Removed by Filter: 4912 -> Bitmap Heap Scan on groups group= s_3 (cost=3D15.67..23.73 rows=3D1 width=3D30) (actual time=3D0.024..0.024 = rows=3D1 loops=3D22) Recheck Cond: ((acl_2.principa= lid =3D id) OR ((((type)::text =3D (acl_2.principaltype)::text) AND (instan= ce =3D 10) AND ((domain)::text =3D 'RT::Queue-Role'::text)) OR (((type)::te= xt =3D (acl_2.principaltype)::text) AND (instance =3D 999028) AND ((domain)= ::text =3D 'RT::Ticket-Role'::text)))) Filter: ((((domain)::text =3D = 'SystemInternal'::text) OR ((domain)::text =3D 'UserDefined'::text) OR ((do= main)::text =3D 'ACLEquivalence'::text) OR (((domain)::text =3D 'RT::Queue-= Role'::text) AND (instance =3D 10)) OR (instance =3D 999028)) AND (((acl_2.= principalid =3D id) AND ((acl_2.principaltype)::text =3D 'Group'::text) AND= (((domain)::text =3D 'SystemInternal'::text) OR ((domain)::text =3D 'UserD= efined'::text) OR ((domain)::text =3D 'ACLEquivalence'::text))) OR (((((dom= ain)::text =3D 'RT::Queue-Role'::text) AND (instance =3D 10)) OR (((domain)= ::text =3D 'RT::Ticket-Role'::text) AND (instance =3D 999028))) AND ((type)= ::text =3D (acl_2.principaltype)::text)))) -> BitmapOr (cost=3D15.67..1= 5.67 rows=3D2 width=3D0) (actual time=3D0.020..0.020 rows=3D0 loops=3D22) -> Bitmap Index Scan on= groups_pkey (cost=3D0.00..4.76 rows=3D1 width=3D0) (actual time=3D0.005..= 0.005 rows=3D1 loops=3D22) Index Cond: (acl_2= =2Eprincipalid =3D id) -> BitmapOr (cost=3D10= =2E66..10.66 rows=3D1 width=3D0) (actual time=3D0.014..0.014 rows=3D0 loops= =3D22) -> Bitmap Index S= can on groups2 (cost=3D0.00..5.33 rows=3D1 width=3D0) (actual time=3D0.007= =2E.0.007 rows=3D0 loops=3D22) Index Cond: = (((type)::text =3D (acl_2.principaltype)::text) AND (instance =3D 10) AND (= (domain)::text =3D 'RT::Queue-Role'::text)) -> Bitmap Index S= can on groups2 (cost=3D0.00..5.33 rows=3D1 width=3D0) (actual time=3D0.006= =2E.0.006 rows=3D0 loops=3D22) Index Cond: = (((type)::text =3D (acl_2.principaltype)::text) AND (instance =3D 999028) A= ND ((domain)::text =3D 'RT::Ticket-Role'::text)) -> Index Scan using cachedgroupmembers3 o= n cachedgroupmembers cachedgroupmembers_4 (cost=3D0.00..2.86 rows=3D15 wid= th=3D8) (actual time=3D0.009..0.055 rows=3D71 loops=3D23) Index Cond: (groupid =3D groups_3.id) -> Index Scan using principals_pkey on principals principal= s_1 (cost=3D0.00..0.84 rows=3D1 width=3D4) (actual time=3D0.003..0.004 row= s=3D1 loops=3D1600) Index Cond: (id =3D cachedgroupmembers_4.memberid) Filter: ((id <> 1) AND (disabled =3D 0)) Rows Removed by Filter: 0 Total runtime: 316.054 ms (35 Zeilen) This plan is still slower than the origial 80ms, due to the Index Scan on users_pkey. Setting cpu_tuple_cost =3D 0.06 fixed this: (http://explain.depesz.com/s/R0g) Unique (cost=3D430656.51..443500.29 rows=3D146786 width=3D1065) (actual t= ime=3D50.400..52.876 rows=3D441 loops=3D1) -> Sort (cost=3D430656.51..431023.48 rows=3D146786 width=3D1065) (actu= al time=3D50.399..50.504 rows=3D1522 loops=3D1) Sort Key: main.name, main.id, main.password, main.comments, main.s= ignature, main.emailaddress, main.freeformcontactinfo, main.organization, m= ain.realname, main.nickname, main.lang, main.emailencoding, main.webencodin= g, main.externalcontactinfoid, main.contactinfosystem, main.externalauthid,= main.authsystem, main.gecos, main.homephone, main.workphone, main.mobileph= one, main.pagerphone, main.address1, main.address2, main.city, main.state, = main.zip, main.country, main.timezone, main.pgpkey, main.creator, main.crea= ted, main.lastupdatedby, main.lastupdated Sort Method: quicksort Memory: 570kB -> Nested Loop (cost=3D8.36..368962.31 rows=3D146786 width=3D106= 5) (actual time=3D0.326..15.253 rows=3D1522 loops=3D1) -> Nested Loop (cost=3D8.36..309751.83 rows=3D146786 width= =3D8) (actual time=3D0.232..9.224 rows=3D1551 loops=3D1) -> Nested Loop (cost=3D8.36..211474.01 rows=3D146790= width=3D4) (actual time=3D0.225..2.590 rows=3D1639 loops=3D1) -> Nested Loop (cost=3D8.36..550.15 rows=3D630= 34 width=3D4) (actual time=3D0.213..0.919 rows=3D23 loops=3D1) -> Index Only Scan using acl1 on acl acl_= 2 (cost=3D0.00..133.99 rows=3D33 width=3D10) (actual time=3D0.117..0.370 r= ows=3D22 loops=3D1) Index Cond: (rightname =3D 'OwnTicke= t'::text) Filter: (((objecttype)::text =3D 'RT= ::System'::text) OR (((objecttype)::text =3D 'RT::Queue'::text) AND (object= id =3D 10))) Rows Removed by Filter: 220 Heap Fetches: 242 -> Bitmap Heap Scan on groups groups_3 (= cost=3D8.36..12.55 rows=3D1 width=3D30) (actual time=3D0.023..0.023 rows=3D= 1 loops=3D22) Recheck Cond: ((acl_2.principalid = =3D id) OR ((((type)::text =3D (acl_2.principaltype)::text) AND (instance = =3D 10) AND ((domain)::text =3D 'RT::Queue-Role'::text)) OR (((type)::text = =3D (acl_2.principaltype)::text) AND (instance =3D 999028) AND ((domain)::t= ext =3D 'RT::Ticket-Role'::text)))) Filter: ((((domain)::text =3D 'Syste= mInternal'::text) OR ((domain)::text =3D 'UserDefined'::text) OR ((domain):= :text =3D 'ACLEquivalence'::text) OR (((domain)::text =3D 'RT::Queue-Role':= :text) AND (instance =3D 10)) OR (instance =3D 999028)) AND (((acl_2.princi= palid =3D id) AND ((acl_2.principaltype)::text =3D 'Group'::text) AND (((do= main)::text =3D 'SystemInternal'::text) OR ((domain)::text =3D 'UserDefined= '::text) OR ((domain)::text =3D 'ACLEquivalence'::text))) OR (((((domain)::= text =3D 'RT::Queue-Role'::text) AND (instance =3D 10)) OR (((domain)::text= =3D 'RT::Ticket-Role'::text) AND (instance =3D 999028))) AND ((type)::text= =3D (acl_2.principaltype)::text)))) -> BitmapOr (cost=3D8.36..8.36 row= s=3D2 width=3D0) (actual time=3D0.019..0.019 rows=3D0 loops=3D22) -> Bitmap Index Scan on group= s_pkey (cost=3D0.00..2.51 rows=3D1 width=3D0) (actual time=3D0.005..0.005 = rows=3D1 loops=3D22) Index Cond: (acl_2.princ= ipalid =3D id) -> BitmapOr (cost=3D5.60..5.= 60 rows=3D1 width=3D0) (actual time=3D0.014..0.014 rows=3D0 loops=3D22) -> Bitmap Index Scan on= groups2 (cost=3D0.00..2.80 rows=3D1 width=3D0) (actual time=3D0.007..0.00= 7 rows=3D0 loops=3D22) Index Cond: (((typ= e)::text =3D (acl_2.principaltype)::text) AND (instance =3D 10) AND ((domai= n)::text =3D 'RT::Queue-Role'::text)) -> Bitmap Index Scan on= groups2 (cost=3D0.00..2.80 rows=3D1 width=3D0) (actual time=3D0.006..0.00= 6 rows=3D0 loops=3D22) Index Cond: (((typ= e)::text =3D (acl_2.principaltype)::text) AND (instance =3D 999028) AND ((d= omain)::text =3D 'RT::Ticket-Role'::text)) -> Index Scan using cachedgroupmembers3 on cach= edgroupmembers cachedgroupmembers_4 (cost=3D0.00..2.45 rows=3D15 width=3D8= ) (actual time=3D0.008..0.054 rows=3D71 loops=3D23) Index Cond: (groupid =3D groups_3.id) -> Index Scan using principals_pkey on principals pri= ncipals_1 (cost=3D0.00..0.61 rows=3D1 width=3D4) (actual time=3D0.003..0.0= 04 rows=3D1 loops=3D1639) Index Cond: (id =3D cachedgroupmembers_4.memberi= d) Filter: ((id <> 1) AND (disabled =3D 0)) Rows Removed by Filter: 0 -> Index Scan using users_pkey on users main (cost=3D0.00.= =2E0.34 rows=3D1 width=3D1065) (actual time=3D0.003..0.003 rows=3D1 loops= =3D1551) Index Cond: (id =3D cachedgroupmembers_4.memberid) Total runtime: 53.174 ms (33 Zeilen) The tipping point for cpu_tuple_cost was 0.05, 0.04 didn't have any effect. Old 8.1 config: shared_buffers =3D 262144 # min 16 or max_connections*2, 8K= B each temp_buffers =3D 65536 # min 100, 8KB each work_mem =3D 24576 # min 64, size in KB maintenance_work_mem =3D 65536 effective_cache_size =3D 786432 default_statistics_target =3D 100 New 9.2 config: shared_buffers =3D 4GB work_mem =3D 32MB random_page_cost =3D 2.0 (after tuning, but didn't change anything) effective_cache_size =3D 32GB (after tuning) Christoph --=20 cb@df7cb.de | http://www.df7cb.de/ --lrZ03NoBR/3+SXJZ Content-Type: application/pgp-signature; name="signature.asc" Content-Description: Digital signature -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.12 (GNU/Linux) iQIcBAEBCAAGBQJRf6kVAAoJEExaa6sS0qeuioEQAJeatoBQ5InXuKuu1lFmsfzT H+7VEgo4kuw9wejBBukjc1W8cCI8WnH6MPO6lJKtS6LPaN/+8xjjTzbk/rjclAGN znJw89TccC70cqzVsGDlI/x5t75gIpnBboqz+ADJXle6fVOoNOXAduT+Ups3hmie y+U2KwX49o8eVB5rgH3vPS5zlsjNvvhV+NKmL+2KmQzzDLL9TAKyd9MUdlJ3weCy Je+4O1vkaU0p5XJqVGIw2zFdvwW7CFhvbXI9ZlnmtWwLXOqF3N19x4H6/AV8gp8F ZRGZmOV5u63ZW9iOlZoaxhKpDR9+TOAQTW6/FpLdJFCpxoCnpL/H0YGvwBegaLRb cf0oK20gHfqLJlbMSNP/RaReb+8tnd10Lig+b0Z6NdWU9mn7Ko4ktP4agVDYq6cr EclhI9KQseovol7A520pY7tLZde0vNfT4dE1xvVqvNUlR77t36kHQSVf3DLprO/m GbsitRVe1IGtvbyyWP/g5dpTq99pg49Bbxyln8uAzkQG6OjsrqYi3ZZM+NJU9Xie DXe9Q23VSOWaltmNy5LWa6IwdrwTrsHNAUA6d+jKpxem2bhax5jHzhZBPaW2z9Fs rx11XV8NVcOQKYDoP3MnG+TT+jyrd5/mUmWmwQU3MLwpAPBvxNl8gA5W42tFY0yU wCAVVfdvF8AOZ6lDappU =kTSM -----END PGP SIGNATURE----- --lrZ03NoBR/3+SXJZ--