Forum OpenACS Q&A: Tuning a query with CR joins

Collapse
1: Tuning a query with CR joins
Posted by Peter Marklund on 02/17/03 05:19 PM
I have some problems optimizing the index query in Bug Tracker. Here is the query (with most of the where clause cut out for brevity):

select b.bug_id
    from  bt_bugs b,
          bt_components c,
          acs_objects o,
          bt_priority_codes pc,
          bt_severity_codes sc,
          cc_users submitter,
          workflow_cases cas left outer join
          (select rpm.case_id,
                  p.party_id,
                  p.email,
                  acs_object__name(p.party_id) as name
              from workflow_case_role_party_map rpm,
                  parties p
            where rpm.role_id = '10'
              and p.party_id = rpm.party_id) assignee on (cas.case_id = assignee.case_id),
          workflow_case_fsm cfsm,
          workflow_fsm_states st,
          workflow_case_log wclog,
          cr_items wclogi,
          cr_revisions wclogr
    where  c.component_id = b.component_id
    and    o.object_id = b.bug_id
    and    pc.priority_id = b.priority
    and    sc.severity_id = b.severity
    and    submitter.user_id = o.creation_user
    and    cas.workflow_id = '3174'
    and    cas.object_id = b.bug_id
    and    cfsm.case_id = cas.case_id
    and    st.state_id = cfsm.current_state
    and    wclog.case_id = cas.case_id
    and    wclog.action_id = '22'
    and    wclogi.item_id = wclog.entry_id
    and    wclogr.revision_id = wclogi.live_revision
    and    b.project_id = '2978'
    order  by b.bug_number desc;

Here is what explain analyze says:

Sort  (cost=166.14..166.14 rows=1 width=112) (actual time=6.49..6.49 rows=2 loops=1)
  ->  Nested Loop  (cost=107.18..166.13 rows=1 width=112) (actual time=4.70..5.60 rows=2 loops=1)
        ->  Nested Loop  (cost=107.18..161.29 rows=1 width=108) (actual time=4.63..5.49 rows=2 loops=1)
              ->  Nested Loop  (cost=107.18..156.46 rows=1 width=104) (actual time=4.55..5.33 rows=2 loops=1)
                    ->  Nested Loop  (cost=107.18..151.62 rows=1 width=100) (actual time=4.48..5.19 rows=2 loops=1)
                          ->  Hash Join  (cost=107.18..146.79 rows=1 width=92) (actual time=4.39..5.02 rows=2 loops=1)
                                ->  Nested Loop  (cost=106.13..145.72 rows=1 width=84) (actual time=3.02..3.49 rows=2 loops=1)
                                      ->  Nested Loop  (cost=106.13..140.89 rows=1 width=80) (actual time=2.94..3.35 rows=2 loops=1)
                                            ->  Nested Loop  (cost=106.13..136.05 rows=1 width=72) (actual time=2.86..3.20 rows=2 loops=1)
                                                  ->  Hash Join  (cost=106.13..131.22 rows=1 width=68) (actual time=2.78..3.05 rows=2 loops=1)
                                                        ->  Hash Join  (cost=89.05..114.11 rows=5 width=48) (actual time=1.62..1.76 rows=2 loops=1)
                                                              ->  Seq Scan on workflow_case_fsm cfsm  (cost=0.00..20.00 rows=1000 width=8) (actual time=0.03..0.05 rows=2 loops=1)
                                                              ->  Hash  (cost=89.05..89.05 rows=1 width=40) (actual time=0.85..0.85 rows=0 loops=1)
                                                                    ->  Nested Loop  (cost=0.00..89.05 rows=1 width=40) (actual time=0.76..0.84 rows=2 loops=1)
                                                                          ->  Nested Loop  (cost=0.00..47.77 rows=1 width=12) (actual time=0.14..0.20 rows=2 loops=1)
                                                                                ->  Seq Scan on workflow_cases cas  (cost=0.00..1.02 rows=1 width=8) (actual time=0.06..0.08 rows=2 loops=1)
                                                                                ->  Subquery Scan assignee  (cost=0.00..46.68 rows=5 width=80) (actual time=0.03..0.03 rows=0 loops=2)
                                                                                      ->  Nested Loop  (cost=0.00..46.68 rows=5 width=80) (actual time=0.02..0.02 rows=0 loops=2)
                                                                                            ->  Seq Scan on workflow_case_role_party_map rpm  (cost=0.00..22.50 rows=5 width=8) (actual time=0.02..0.02 rows=0 loops=2)
                                                                                            ->  Index Scan using parties_pk on parties p  (cost=0.00..4.82 rows=1 width=72)
                                                                          ->  Materialize  (cost=41.27..41.27 rows=1 width=28) (actual time=0.30..0.30 rows=1 loops=2)
                                                                                ->  Nested Loop  (cost=0.00..41.27 rows=1 width=28) (actual time=0.50..0.59 rows=1 loops=1)
                                                                                      ->  Nested Loop  (cost=0.00..36.43 rows=1 width=24) (actual time=0.44..0.52 rows=1 loops=1)
                                                                                            ->  Nested Loop  (cost=0.00..31.60 rows=1 width=20) (actual time=0.38..0.44 rows=1 loops=1)
                                                                                                  ->  Nested Loop  (cost=0.00..26.76 rows=1 width=16) (actual time=0.30..0.33 rows=1 loops=1)
                                                                                                        ->  Nested Loop  (cost=0.00..21.93 rows=1 width=12) (actual time=0.21..0.23 rows=1 loops=1)
                                                                                                              ->  Index Scan using group_elem_idx_group_idx on group_element_index  (cost=0.00..17.09 rows=1 width=8) (actual time=0.12..0.12 rows=1 loops=1)
                                                                                                              ->  Index Scan using persons_pk on persons pe  (cost=0.00..4.82 rows=1 width=4) (actual time=0.07..0.07 rows=1 loops=1)
                                                                                                        ->  Index Scan using acs_objects_pk on acs_objects o  (cost=0.00..4.82 rows=1 width=4) (actual time=0.07..0.08 rows=1 loops=1)
                                                                                                  ->  Index Scan using users_pk on users u  (cost=0.00..4.82 rows=1 width=4) (actual time=0.04..0.08 rows=1 loops=1)
                                                                                            ->  Index Scan using parties_pk on parties pa  (cost=0.00..4.82 rows=1 width=4) (actual time=0.04..0.04 rows=1 loops=1)
                                                                                      ->  Index Scan using membership_rel_rel_id_pk on membership_rels mr  (cost=0.00..4.82 rows=1 width=4) (actual time=0.04..0.05 rows=1 loops=1)
                                                        ->  Hash  (cost=17.07..17.07 rows=5 width=20) (actual time=0.16..0.16 rows=0 loops=1)
                                                              ->  Index Scan using bt_bugs_bug_number_un on bt_bugs b  (cost=0.00..17.07 rows=5 width=20) (actual time=0.11..0.14 rows=3 loops=1)
                                                  ->  Index Scan using bt_components_pk on bt_components c  (cost=0.00..4.82 rows=1 width=4) (actual time=0.03..0.04 rows=1 loops=2)
                                            ->  Index Scan using acs_objects_pk on acs_objects o  (cost=0.00..4.82 rows=1 width=8) (actual time=0.04..0.04 rows=1 loops=2)
                                      ->  Index Scan using wf_fsm_states_pk on workflow_fsm_states st  (cost=0.00..4.82 rows=1 width=4) (actual time=0.03..0.04 rows=1 loops=2)
                                ->  Hash  (cost=1.05..1.05 rows=1 width=8) (actual time=0.10..0.10 rows=0 loops=1)
                                      ->  Seq Scan on workflow_case_log wclog  (cost=0.00..1.05 rows=1 width=8) (actual time=0.07..0.08 rows=2 loops=1)
                          ->  Index Scan using cr_items_pk on cr_items wclogi  (cost=0.00..4.82 rows=1 width=8) (actual time=0.04..0.05 rows=1 loops=2)
                    ->  Index Scan using bt_severity_codes_pk on bt_severity_codes sc  (cost=0.00..4.82 rows=1 width=4) (actual time=0.03..0.03 rows=1 loops=2)
              ->  Index Scan using cr_revisions_pk on cr_revisions wclogr  (cost=0.00..4.82 rows=1 width=4) (actual time=0.03..0.04 rows=1 loops=2)
        ->  Index Scan using bt_priority_codes_pk on bt_priority_codes pc  (cost=0.00..4.82 rows=1 width=4) (actual time=0.03..0.04 rows=1 loops=2)
Total runtime: 8.99 msec

Removing the joins with cr_items and cr_revisions makes the query time go from about 1000 ms to 100 ms (on a pretty powerful and idle server). However, according to explain postgres is doing index scan on the primary keys of those tables when joining.

Any ideas about how to optimize this query would be much appreciated.

Thanks!

Peter

Collapse
2: Re: Tuning a query with CR joins (response to 1)
Posted by Jeff Davis on 02/17/03 05:37 PM
Peter, you might try increasing the geqo_threshold
and see if it has something to do with
whether or not the subselects and views are flattened.
See http://xarg.net/writing/misc/GEQO for my experiences
with this most mysterious of tuning parameters :)
Collapse
3: Re: Tuning a query with CR joins (response to 1)
Posted by Jun Yamog on 02/17/03 05:53 PM
Hi Jeff,

Very interesting.  Are there any negative effects in increasing the threshold aside from more resources?  I am thinking of just increasing mine so I would not run into this problem in the future.

Collapse
4: Re: Tuning a query with CR joins (response to 1)
Posted by Peter Marklund on 02/17/03 06:05 PM
Jeff,
well what can I say...you are my god! The query went from 1000+ ms to 160 ms when increasing the GEQO_THRESHOLD from 5 to 15!

Admittedly the query a still a on the slow side, but it's no longer a show stopper.

Cheers

Peter

Collapse
5: Re: Tuning a query with CR joins (response to 3)
Posted by Jeff Davis on 02/17/03 06:10 PM
the reason the geqo_threshold is there is to act as a cutoff for using exhaustive search for query optimization, above the threshold it uses the genetic query optimizer which should be faster for generating a query plan. If you do a lot of very complicated queries that are fast, having geqo set higher could reduce your overall throughput since the extra time planning might cost more than the time saved from using the exhaustive search.

I don't really know how good the genetic query optimizer is though and I think most complicated queries tend to be slow queries so I am inclined to increase it on openacs sites. I have been running with it set to 30 on my local box to see if anything bad happens but to date it has worked fine.

Also, I would prefer deterministic results to geqo "may it works maybe it doesn't" plans, and if query planning time is too long for a fast complicated query then resort to explicit joins to control the planning time.

Collapse
6: Re: Tuning a query with CR joins (response to 1)
Posted by Don Baccus on 02/17/03 08:13 PM
I don't know why they have it set so low by default ... among other things the genetic query optimizer hasn't been worked on in a long time and little is understood about it in the community.

This needs to get written up in our installation documents ... I think setting it high enough so that GEQO is turned off is the best things for us to do.

And now that PL/pgSQL procs can return rowsets in PG 7.3, one can remove the plan optimization overhead by burying something like this in a function (each back end generates a plan for a  PL/pgSQL function once per back end lifetime)

In fact for future planning you might want to mark the query to that effect ... for the day when we dump PG 7.2 support.

There's some way to find out how long the planner takes vs. execution, though like many of the stats information functions available it doesn't seem to be documented in the 7.3 HTML docs I've looked through.

If the planner's taking (say) 60 ms of that 100 ms then burying it in a PL/pgSQL function will represent a real savings but it would be best, of course, to measure first and hack later.

I assume you mean you cut out most of the columns being returned, not the WHERE clause, which appears to be there in all its full glory.  If all you need is the bug_id then we can suggest several simplifications to the query :)

Collapse
7: Re: Tuning a query with CR joins (response to 6)
Posted by Jeff Davis on 02/17/03 11:55 PM
Actually, I have been wondering about supporting prepared queries in the db driver. At the very least it might be nice to do prepares so that we could tell how long the plan generation takes and flag problematic queries.

Of course since Lamar Owen is the maintainer I guess it falls to him :)

Collapse
8: Re: Tuning a query with CR joins (response to 1)
Posted by Don Baccus on 02/18/03 02:31 AM
Or me ...

Yes, I've thought about it, too but we'll have to dump 7.2 support first, right? (I think it's a 7.3 feature)

We could actually have the db_* interface do it as a param'd option, using the fullquery name as the name of the prepared statement.  I haven't tracked the details of the prepared statement stuff - do all PG backends see the prepared statement or just the one that executes it?  If all then it would be easy to stuff a "prepared statement exists" flag in the XML kept for the query and check it, do the prepare if necessary and then execute regardless.

Worth exploring ...