Forum OpenACS Development: Slow bugtracker when accepting a patch
dbqd.bug-tracker.www.patch.actions: select nsdb0select 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 nsdb0select 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
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
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.