Forum OpenACS Q&A: Re: Re: Performance Problems - what is the bottleneck?

Collapse
17: Re: Re: Performance Problems - what is the bottleneck? (response to 15)
Posted by Rocael Hernández Rizzardini on 02/09/06 12:27 AM
1310 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '1228' and ppm.party_id = '24471989' and ppm.privilege = 'dotlrn_browse' )

Now, with explain analyze:

QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Result  (cost=3655.01..3655.04 rows=1 width=0) (actual time=3377.385..3377.402 rows=1 loops=1)
   One-Time Filter: $0
   InitPlan
     ->  Nested Loop  (cost=6.35..3655.01 rows=38 width=0) (actual time=3377.341..3377.341 rows=1 loops=1)
           ->  Hash Join  (cost=6.35..2462.49 rows=198 width=4) (actual time=0.616..1953.102 rows=82802 loops=1)
                 Hash Cond: (("outer".privilege)::text = ("inner".privilege)::text)
                 ->  Nested Loop  (cost=0.00..2446.33 rows=626 width=16) (actual time=0.071..1060.517 rows=82804 loops=1)
                       ->  Index Scan using acs_object_context_index_pk on acs_object_context_index c  (cost=0.00..39.90 rows=13 width=4) (actual time=0.035..0.040 rows=2 loops=1)
                             Index Cond: (object_id = 1228)
                       ->  Index Scan using acs_permissions_pk on acs_permissions p  (cost=0.00..184.49 rows=50 width=20) (actual time=0.017..214.914 rows=41402 loops=2)
                             Index Cond: ("outer".ancestor_id = p.object_id)
                 ->  Hash  (cost=6.34..6.34 rows=4 width=14) (actual time=0.325..0.325 rows=0 loops=1)
                       ->  Seq Scan on acs_privilege_descendant_map pdm  (cost=0.00..6.34 rows=4 width=14) (actual time=0.252..0.302 rows=2 loops=1)
                             Filter: ((descendant)::text = 'dotlrn_browse'::text)
           ->  Index Scan using party_approved_member_map_pk on party_approved_member_map pamm  (cost=0.00..6.01 rows=1 width=4) (actual time=0.010..0.010 rows=0 loops=82802)
                 Index Cond: ((pamm.party_id = "outer".grantee_id) AND (pamm.member_id = 24471989))
   ->  Subquery Scan dual  (cost=0.00..0.02 rows=1 width=0) (actual time=0.028..0.038 rows=1 loops=1)
         ->  Result  (cost=0.00..0.01 rows=1 width=0) (actual time=0.020..0.023 rows=1 loops=1)
 Total runtime: 3377.578 ms
(19 rows)

In this case, is giving lots of rows. I don't remember right now, I think it was as well that we needed a way to stop the query execution when just one row is returned. I was diging into this like 2 months ago, we might go further into this now.

Collapse
18: Re: Re: Re: Performance Problems - what is the bottleneck? (response to 17)
Posted by Rocael Hernández Rizzardini on 02/09/06 12:33 AM
limit 1 doesn't do the magic.
we're running PostgreSQL 7.4.7 on i386-pc-linux-gnu
Collapse
21: Re: Re: Re: Performance Problems - what is the bottleneck? (response to 17)
Posted by Daniël Mantione on 02/09/06 11:01 AM
The hash join is killing you, it returns 82804 rows while PostgreSQL expected 198 rows. It looks you need a "VACUUM ANALYZE", if it doesn't help you need to configure PostgreSQL to gather more statistics while analyzing (it is a setting somewhere, read PostgreSQL docs).
Collapse
22: Re: Re: Re: Re: Performance Problems - what is the bottleneck? (response to 21)
Posted by Don Baccus on 02/09/06 07:35 PM
Yes, I believe Daniel's right, good eye there.

Roc, what does the query:

select count(*)
from acs_object_party_privilege_map ppm
where ppm.object_id = '1228' and ppm.party_id = '24471989' and ppm.privilege = 'dotlrn_browse';

return?

Also .LRN and several OpenACS packages declare far too many custom privileges. I've mentioned this before and in fact have cleaned up a couple of packages. The hierarchy map is always short enough to be sequentially scanned. Cutting the number of privileges in the system in half would cut the cost of joining against the hierarchy table by half as well, on average.

Something folks should think about while working on new packages especially (please, don't define new versions of "read" or "write" when plain old "read" or "write" will work!)

This isn't the cause of your extremely slow query, rather I'm pointing out (again) that in those cases where permissions queries are reasonably fast, they could be made a couple of times faster by reducing the number of unnecessary custom privileges.