Forum OpenACS Development: Slow bugtracker when accepting a patch

Collapse
1: Slow bugtracker when accepting a patch
Posted by Dave Bauer on 09/18/05 05:36 PM
Here is the query, I am filing this here so I can look into it later and report the results.

 dbqd.bug-tracker.www.patch.actions: select nsdb0
select bt_patch_actions.action_id,
       bt_patch_actions.action,
       bt_patch_actions.actor as actor_user_id,
       actor.first_names as actor_first_names,
       actor.last_name as actor_last_name,
       actor.email as actor_email,
       bt_patch_actions.action_date,
       to_char(bt_patch_actions.action_date, 'fmMM/DDfm/YYYY') as action_date_pretty,
       bt_patch_actions.comment_text,
       bt_patch_actions.comment_format
from   bt_patch_actions,
       cc_users actor
where  bt_patch_actions.patch_id = '320984'
and    actor.user_id = bt_patch_actions.actor
order  by action_date

17901 ms

all queries for this page

18289 ms

URL

https://openacs.org/bugtracker/openacs/patch?patch%5fnumber=731

This is the request to fill out the form accepting it. Submitting the form is almost as slow:

14766 ms submitting the patch accept form.
Same query because its just displaying the patch page again.

 dbqd.bug-tracker.www.patch.actions: select nsdb0
select bt_patch_actions.action_id,
       bt_patch_actions.action,
       bt_patch_actions.actor as actor_user_id,
       actor.first_names as actor_first_names,
       actor.last_name as actor_last_name,
       actor.email as actor_email,
       bt_patch_actions.action_date,
       to_char(bt_patch_actions.action_date, 'fmMM/DDfm/YYYY') as action_date_pretty,
       bt_patch_actions.comment_text,
       bt_patch_actions.comment_format
from   bt_patch_actions,
       cc_users actor
where  bt_patch_actions.patch_id = '320984'
and    actor.user_id = bt_patch_actions.actor
order  by action_date
Collapse
2: Re: Slow bugtracker when accepting a patch (response to 1)
Posted by Dave Bauer on 09/18/05 09:14 PM
Ok here is what I have found

Original query

openacs.org=# explain analyze select bt_patch_actions.action_id,
       bt_patch_actions.action,
       bt_patch_actions.actor as actor_user_id,
       actor.first_names as actor_first_names,
       actor.last_name as actor_last_name,
       actor.email as actor_email,
       bt_patch_actions.action_date,
       to_char(bt_patch_actions.action_date, 'fmMM/DDfm/YYYY') as action_date_pretty,
       bt_patch_actions.comment_text,
       bt_patch_actions.comment_format
from   bt_patch_actions,
       cc_users actor
where  bt_patch_actions.patch_id = '320984'
and    actor.user_id = bt_patch_actions.actor

                                                                                               QUERY PLAN                                     \
----------------------------------------------------------------------------------------------------------------------------------------------\-----------------------------------------------------------
 Sort  (cost=404.01..404.02 rows=1 width=328) (actual time=20062.009..20062.016 rows=2 loops=1)
   Sort Key: bt_patch_actions.action_date
   ->  Nested Loop  (cost=0.00..404.00 rows=1 width=328) (actual time=171.294..20061.424 rows=2 loops=1)
         ->  Nested Loop  (cost=0.00..398.00 rows=1 width=332) (actual time=171.081..20061.074 rows=2 loops=1)
               ->  Nested Loop  (cost=0.00..392.00 rows=1 width=280) (actual time=170.972..20060.851 rows=2 loops=1)
                     Join Filter: ("outer".group_id = "inner".object_id)
                     ->  Nested Loop  (cost=0.00..390.93 rows=1 width=288) (actual time=170.858..20060.572 rows=3 loops=1)
                           Join Filter: ("inner".actor = "outer".person_id)
                           ->  Nested Loop  (cost=0.00..336.26 rows=1 width=164) (actual time=0.510..2933.461 rows=9170 loops=1)
                                 ->  Nested Loop  (cost=0.00..330.24 rows=1 width=160) (actual time=0.445..2132.939 rows=9170 loops=1)
                                       ->  Nested Loop  (cost=0.00..324.22 rows=1 width=156) (actual time=0.341..1176.314 rows=9170 loops=1)
                                             ->  Index Scan using group_elem_idx_rel_type_idx on group_element_index  (cost=0.00..318.22 rows=\1 width=16) (actual time=0.260..366.296 rows=9170 loops=1)
                                                   Index Cond: ((rel_type)::text = 'membership_rel'::text)
                                                   Filter: (((ancestor_rel_type)::text = 'membership_rel'::text) AND (container_id = group_id)\)
                                             ->  Index Scan using persons_pk on persons pe  (cost=0.00..5.99 rows=1 width=140) (actual time=0.\047..0.063 rows=1 loops=9170)
                                                   Index Cond: ("outer".element_id = pe.person_id)
                                       ->  Index Scan using acs_objects_pk on acs_objects o  (cost=0.00..6.01 rows=1 width=4) (actual time=0.0\63..0.081 rows=1 loops=9170)
                                             Index Cond: ("outer".person_id = o.object_id)
                                 ->  Index Scan using users_pk on users u  (cost=0.00..6.01 rows=1 width=4) (actual time=0.045..0.064 rows=1 l\oops=9170)
                                       Index Cond: (u.user_id = "outer".object_id)
                           ->  Seq Scan on bt_patch_actions  (cost=0.00..54.56 rows=8 width=124) (actual time=1.822..1.843 rows=2 loops=9170)
                                 Filter: (patch_id = 320984)
                     ->  Seq Scan on acs_magic_objects amo  (cost=0.00..1.06 rows=1 width=4) (actual time=0.052..0.061 rows=1 loops=3)
                           Filter: ((name)::text = 'registered_users'::text)
               ->  Index Scan using parties_pk on parties pa  (cost=0.00..5.99 rows=1 width=72) (actual time=0.068..0.078 rows=1 loops=2)
                     Index Cond: ("outer".element_id = pa.party_id)
         ->  Index Scan using membership_rel_rel_id_pk on membership_rels mr  (cost=0.00..5.98 rows=1 width=4) (actual time=0.075..0.082 rows=\1 loops=2)
               Index Cond: ("outer".rel_id = mr.rel_id)
 Total runtime: 20063.022 ms
(29 rows)

First I see a join on cc_users, which is a slow view, and not necessary in this case, since we are joining against an existing list of user_ids in the database. I see a sequential scan on bt_patch_actions. This table has 1496 rows, so we might need an index on there.

First we join on acs_users_all instead of cc_users

openacs.org=# explain analyze select bt_patch_actions.action_id,
       bt_patch_actions.action,
       bt_patch_actions.actor as actor_user_id,
       actor.first_names as actor_first_names,
       actor.last_name as actor_last_name,
       actor.email as actor_email,
       bt_patch_actions.action_date,
       to_char(bt_patch_actions.action_date, 'fmMM/DDfm/YYYY') as action_date_pretty,
       bt_patch_actions.comment_text,
       bt_patch_actions.comment_format
from   bt_patch_actions,
       acs_users_all actor
where  bt_patch_actions.patch_id = '320984'
and    actor.user_id = bt_patch_actions.actor;
                                                                 QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=0.00..90.75 rows=2 width=376) (actual time=1.704..1.972 rows=2 loops=1)
   ->  Nested Loop  (cost=0.00..78.70 rows=2 width=384) (actual time=1.631..1.821 rows=2 loops=1)
         ->  Nested Loop  (cost=0.00..66.71 rows=2 width=244) (actual time=1.571..1.680 rows=2 loops=1)
               ->  Seq Scan on bt_patch_actions  (cost=0.00..54.70 rows=2 width=172) (actual time=1.452..1.471 rows=2 loops=1)
                     Filter: (patch_id = 320984)
               ->  Index Scan using parties_pk on parties pa  (cost=0.00..5.99 rows=1 width=72) (actual time=0.062..0.068 rows=1 loops=2)
                     Index Cond: ("outer".actor = pa.party_id)
         ->  Index Scan using persons_pk on persons pe  (cost=0.00..5.99 rows=1 width=140) (actual time=0.026..0.038 rows=1 loops=2)
               Index Cond: ("outer".actor = pe.person_id)
   ->  Index Scan using users_pk on users u  (cost=0.00..6.01 rows=1 width=4) (actual time=0.017..0.024 rows=1 loops=2)
         Index Cond: (u.user_id = "outer".party_id)
 Total runtime: 2.206 ms
(12 rows)

This is 10x faster.

Adding an index on bt_patch_actions.patch_id

                                                                             QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------\---------------------
 Nested Loop  (cost=0.00..40.18 rows=2 width=376) (actual time=0.299..0.611 rows=2 loops=1)
   ->  Nested Loop  (cost=0.00..28.18 rows=2 width=248) (actual time=0.220..0.431 rows=2 loops=1)
         ->  Nested Loop  (cost=0.00..16.13 rows=2 width=244) (actual time=0.147..0.277 rows=2 loops=1)
               ->  Index Scan using bt_patch_actions_patch_id_fk on bt_patch_actions  (cost=0.00..4.13 rows=2 width=172) (actual time=0.027..0.042 rows=2 loops=1)
                     Index Cond: (patch_id = 320984)
               ->  Index Scan using parties_pk on parties pa  (cost=0.00..5.99 rows=1 width=72) (actual time=0.075..0.087 rows=1 loops=2)
                     Index Cond: ("outer".actor = pa.party_id)
         ->  Index Scan using users_pk on users u  (cost=0.00..6.01 rows=1 width=4) (actual time=0.038..0.048 rows=1 loops=2)
               Index Cond: (u.user_id = "outer".party_id)
   ->  Index Scan using persons_pk on persons pe  (cost=0.00..5.99 rows=1 width=140) (actual time=0.031..0.042 rows=1 loops=2)
         Index Cond: ("outer".actor = pe.person_id)
 Total runtime: 0.827 ms
(12 rows)

Now that's fast!

I vacuumed the bt_patch_actions table after adding the index. I also tested with the index, joining on cc_users. The result was 1551 ms, faster, but still not fast enough.

I have made the query change on openacs.org and CVS. It looks like the new

Collapse
3: Re: Slow bugtracker when accepting a patch (response to 1)
Posted by Dave Bauer on 09/18/05 09:15 PM
Oops. posted too soon.

It looks like the bugtracker on 5.1 and 5.2 branch do not have the index. I am trying to figure out the best way to make sure an upgrade will work from any version.