Person:+bugs timeouts

Fixed in stable r10739 <http://bazaar.launchpad.net/~launchpad-pqm/launchpad/stable/revision/10739>

Oops, that commit didn't fix this bug.

I've updated the query in the description; its basically insane.

First union is 'bugs this user is the assignee'
Second is 'this user is directly subscribed'
Third is 'this user created the bug and created the bugtask'
Fourth is a poorly phrased 'user commented on the bug' - poorly phrased because the inner query does more work than needed - it only needs to bring back the bug; the outer query can use bugtask.bug to filter on.

I'm not sure whether the four unions are needed or not; I'd break it down and time each separately; if possible optimise, and then look at a combined story. E.g. combining assignee and owner queries is probably basic sense.

Timings:
- first union, 600ms cold, 4ms hot on qastaging.
- second union, 180ms cold, 69ms hot.
- third union, 118ms, 2.8ms
- fourth union, 178778.487 ms, 19734.724 ms

Changing the fourth union to be this:

SELECT BugTask.assignee, BugTask.bug, BugTask.bugwatch, BugTask.date_assigned, BugTask.date_closed, BugTask.date_confirmed, BugTask.date_fix_committed, BugTask.date_fix_released, BugTask.date_incomplete, BugTask.date_inprogress, BugTask.date_left_closed, BugTask.date_left_new, BugTask.date_triaged, BugTask.datecreated, BugTask.distribution, BugTask.distroseries, BugTask.id, BugTask.importance, BugTask.milestone, BugTask.OWNER, BugTask.product, BugTask.productseries, BugTask.sourcepackagename, BugTask.status, BugTask.statusexplanation, BugTask.targetnamecache, BugTask.fti
         FROM BugTask, Bug
         WHERE Bug.id = BugTask.bug
           AND BugTask.status in (10, 15, 20, 21, 22, 25)
           AND Bug.duplicateof IS NULL
           AND BugTask.bug IN
             (SELECT DISTINCT BugMessage.bug
              FROM BugMessage, Message
              WHERE Message.OWNER = 931129
                AND Message.id = BugMessage.message)
           AND Bug.private = FALSE

Should bring the query down to ~5 seconds, a clear improvement. This /changes/ the definition of the fourth union from 'commented on' to 'commented on or created' (because the initial comment creates the bug). However, we're unioning with 'created the bug' anyway, so thats fine (but may need some refactoring to accomodate things that want to query just 'commented on' (but they will need improving similarly to this to work at all - separate problem though :)). Once this is working, we can look into making that 5 seconds subsecond. For posterity - this is the query plan of the forth part of the union - its doing a scan of 290K bug rows to get down to 30K candidates, from there filters through bugmessage and message.

                                                                                 QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop (cost=309637.56..346307.47 rows=200 width=397) (actual time=5407.976..5759.241 rows=3449 loops=1)
   -> Hash Semi Join (cost=309637.56..345044.11 rows=200 width=401) (actual time=5407.772..5722.149 rows=4570 loops=1)
         Hash Cond: (bugtask.bug = bugmessage.bug)
         -> Bitmap Heap Scan on bugtask (cost=3846.05..38339.17 rows=257607 width=397) (actual time=119.834..301.939 rows=289425 loops=1)
               Recheck Cond: (status = ANY ('{10,15,20,21,22,25}'::integer[]))
               -> Bitmap Index Scan on bugtask__status__idx (cost=0.00..3781.64 rows=257607 width=0) (actual time=102.681..102.681 rows=296332 loops=1)
                     Index Cond: (status = ANY ('{10,15,20,21,22,25}'::integer[]))
         -> Hash (cost=304054.32..304054.32 rows=138976 width=4) (actual time=5287.536..5287.536 rows=31907 loops=1)
               -> HashAggregate (cost=301274.80..302664.56 rows=138976 width=4) (actual time=5263.038..5276.298 rows=31907 loops=1)
                     -> Hash Join (cost=202215.04..300927.36 rows=138976 width=4) (actual time=1118.848..52...

Using apport (id 1088183) - the highest frequency commentator.

correlated cold 7000ms hot 6300ms
uncorrelated cold 8000ms hot 6500ms

Using id 165 - an id that has commented on one bug
correlated cold 1100ms
uncorrelated 72ms

So I'd go with the uncorrelated (the IN rather than the EXISTS) query.

To analyse this I:
 - gathered timing data
 - split it down to components
 - assessed those:
   - are they fast
   - how do they fit into the overall story
   - how much work do they do to answer their question

I've spent some time trying to refactor this to consolidate the bits of the sql query that get unioned into one query--each sub section that's unioned is basically identical but for one factor (e.g. all of this stuff + assignee = person, all of this stuff + owner = person). I'm pretty sure it would be more efficient to do "all of this stuff + (assignee = person OR owner = person)" but getting to the point where we can generate that query is a big refactor. I've spent a week off and on looking at it and just keep finding new rabbit holes, so I'm throwing it back in the pot for someone else to take a look at.

I chatted with jc on IRC, but for posterity - the unions aren't a problem based on the evidence in this oops. (They /might/ be in other contexts, but lets not borrow trouble).

Oh, an interesting point here - we can trivially fix the commented query with 'BugMessage.index != 0' now that that column is (effectively) indexed.

I have a branch that changes this landing now, but its not a full fix. Stay tuned to this bat channel, more to come.

Stub suggests

21:22 < stub> SELECT DISTINCT ON (BugTask.id) BugTask.*
21:22 < stub> FROM BugTask, Bug, BugMessage, Message
21:22 < stub> WHERE
21:22 < stub> Bug.id = BugTask.bug
21:22 < stub> AND Bug.id = BugMessage.bug
21:22 < stub> AND BugMessage.message = Message.id
21:22 < stub> AND BugTask.status in (10, 15, 20, 21, 22, 25)
21:22 < stub> AND Bug.duplicateof IS NULL
21:22 < stub> AND Bug.private = FALSE
21:22 < stub> AND BugMessage.index > 0
21:22 < stub> AND Message.owner = 931129
21:22 < stub> ORDER BY BugTask.id;

SELECT DISTINCT ON (BugTask.id) BugTask.*
FROM BugTask, Bug, BugMessage, Message
WHERE
 Bug.id = BugTask.bug
 AND Bug.id = BugMessage.bug
AND BugMessage.message = Message.id
AND BugTask.status in (10, 15, 20, 21, 22, 25)
 AND Bug.duplicateof IS NULL
AND Bug.private = FALSE
AND BugMessage.index > 0
 AND Message.owner = 931129
ORDER BY BugTask.id;

this seems to perform tolerably to also filter on product active SELECT DISTINCT ON (BugTask.id) BugTask.*
FROM BugTask left join product on (bugtask.product = product.id and product.active), Bug, BugMessage, Message
WHERE
 Bug.id = BugTask.bug
 AND Bug.id = BugMessage.bug
AND BugMessage.message = Message.id
AND BugTask.status in (10, 15, 20, 21, 22, 25)
 AND Bug.duplicateof IS NULL
AND Bug.private = FALSE
AND BugMessage.index > 0
 AND Message.owner = 931129
and (bugtask.product is null or product.active)
ORDER BY BugTask.id;

Still the fourth component giving grief:
SELECT BugTask.assignee, BugTask.bug, BugTask.bugwatch, BugTask.date_assigned, BugTask.date_closed, BugTask.date_confirmed, BugTask.date_fix_committed, BugTask.date_fix_released, BugTask.date_incomplete, BugTask.date_inprogress, BugTask.date_left_closed, BugTask.date_left_new, BugTask.date_triaged, BugTask.datecreated, BugTask.distribution, BugTask.distroseries, BugTask.id, BugTask.importance, BugTask.milestone, BugTask.OWNER, BugTask.product, BugTask.productseries, BugTask.sourcepackagename, BugTask.status, BugTask.statusexplanation, BugTask.targetnamecache
         FROM BugTask
         LEFT JOIN Product ON BugTask.product = Product.id
         AND Product.active, Bug
         WHERE Bug.id = BugTask.bug
           AND ((BugTask.status = 10)
                OR (BugTask.status = 15)
                OR (BugTask.status = 20)
                OR (BugTask.status = 21)
                OR (BugTask.status = 22)
                OR (BugTask.status = 25))
           AND Bug.duplicateof IS NULL
           AND (Bugtask.product IS NULL
                OR Product.active = TRUE)
           AND BugTask.id IN
             (SELECT DISTINCT BugTask.id
              FROM BugTask, BugMessage, Message
              WHERE Message.OWNER = 100
                AND Message.id = BugMessage.message
                AND BugTask.bug = BugMessage.bug
                AND BugMessage.INDEX > 0)
           AND Bug.private = FALSE;

                                                                                      QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop (cost=305503.56..378400.41 rows=182 width=276) (actual time=5005.584..5307.435 rows=2032 loops=1)
   -> Nested Loop Left Join (cost=305503.56..378026.51 rows=182 width=276) (actual time=5005.239..5286.484 rows=2722 loops=1)
         Filter: ((public.bugtask.product IS NULL) OR product.active)
         -> Hash Semi Join (cost=305503.56..377964.46 rows=200 width=276) (actual time=5005.231..5279.653 rows=2728 loops=1)
               Hash Cond: (public.bugtask.id = public.bugtask.id)
               -> Bitmap Heap Scan on bugtask (cost=8513.27..80064.62 rows=276215 width=276) (actual time=117.865..262.118 rows=308733 loops=1)
                     Recheck Cond: ((status = 10) OR (status = 15) OR (status = 20) OR (status = 21) OR (status = 22) OR (status = 25))
                     -> BitmapOr (cost=8513.27..8513.27 rows=308734 width=0) (actual time=96.118..96.118 rows=0 loops=1)
                           -> Bitmap Index Scan on bugtask__status__idx (cost=0.00..4829.87 rows=184328 width=0) (actual time=58.207..58.207 rows=184491 loops=1)
                                 Index Cond: (status = 10)
                           -> Bitmap Index Scan on bugtask__status__idx (cost=0.00..466.01 rows=17680 width=0) (actual time=6.039..6.039 rows=17642 loops=1)
                                 Index Cond: (status = 15)
                       ...

SELECT DISTINCT ON (BugTask.id) BugTask.*
FROM BugTask left join product on (bugtask.product = product.id and product.active), Bug, BugMessage, Message
WHERE
 Bug.id = BugTask.bug
 AND Bug.id = BugMessage.bug
AND BugMessage.message = Message.id
AND BugTask.status in (10, 15, 20, 21, 22, 25)
 AND Bug.duplicateof IS NULL
AND Bug.private = FALSE
AND BugMessage.index > 0
 AND Message.owner = 100
and (bugtask.product is null or product.active)
ORDER BY BugTask.id;

is actually a higher estimated cost than the current query, by 10%; still, at 4.8seconds its way too long.

                                                                                   QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Unique (cost=327803.87..327954.53 rows=30132 width=415) (actual time=4840.832..4843.424 rows=2032 loops=1)
   -> Sort (cost=327803.87..327879.20 rows=30132 width=415) (actual time=4840.830..4841.649 rows=5285 loops=1)
         Sort Key: bugtask.id
         Sort Method: quicksort Memory: 2316kB
         -> Nested Loop (cost=146017.99..320705.20 rows=30132 width=415) (actual time=169.558..4820.895 rows=5285 loops=1)
               -> Hash Left Join (cost=146017.99..297520.86 rows=30132 width=419) (actual time=168.398..4767.768 rows=6724 loops=1)
                     Hash Cond: (bugtask.product = product.id)
                     Filter: ((bugtask.product IS NULL) OR product.active)
                     -> Nested Loop (cost=142973.14..294071.41 rows=33056 width=419) (actual time=133.727..4722.996 rows=6733 loops=1)
                           -> Hash Join (cost=142973.14..256158.69 rows=75294 width=4) (actual time=122.161..4409.276 rows=32134 loops=1)
                                 Hash Cond: (bugmessage.message = message.id)
                                 -> Seq Scan on bugmessage (cost=0.00..70798.85 rows=3027910 width=8) (actual time=0.021..1354.923 rows=3026226 loops=1)
                                       Filter: (index > 0)
                                 -> Hash (cost=142031.96..142031.96 rows=75294 width=4) (actual time=122.059..122.059 rows=75175 loops=1)
                                       -> Bitmap Heap Scan on message (cost=1205.51..142031.96 rows=75294 width=4) (actual time=22.913..92.674 rows=75175 loops=1)
                                             Recheck Cond: (owner = 100)
                                             -> Bitmap Index Scan on message_owner_idx (cost=0.00..1186.69 rows=75294 width=0) (actual time=17.076..17.076 rows=75175 loops=1)
                                                   Index Cond: (owner = 100)
                           -> Index Scan using bugtask__bug__idx on bugtask (cost=0.00..0.49 rows=1 width=415) (actual time=0.008..0.009 rows=0 loops=32134)
                                 Index Cond: (bugtask.bug = bugmessage.bug)
                                 Filter: (bugtask.status = ANY ('{10,15,20,21,22,25}'::integer[]))
                     -> Hash (cost=...

The key slowdown is in bugmessage<->message establishment. The following should let us evaluate dropping a table in determining that on a staging server:

begin;
alter table bugmessage add column owner int;
update bugmessage set owner=message.owner from message where message.id=bugmessage.message;
create index bugmessage__owner__idx on bugmessage using btree(owner);
create index bugmessage__owner__index__idx on bugmessage using btree(owner, index);
create index bugmessage__commentor__idx on bugmessage using btree(owner) where index > 0;
commit;

Testing that change:

SELECT count(*) from (SELECT DISTINCT ON (BugTask.id) BugTask.*
FROM BugTask, Bug, BugMessage
WHERE
 Bug.id = BugTask.bug
 AND Bug.id = BugMessage.bug
AND BugTask.status in (10, 15, 20, 21, 22, 25)
 AND Bug.duplicateof IS NULL
AND Bug.private = FALSE
AND BugMessage.index > 0
AND BugMessage.owner = 100) as foo;

cold

                                                                                   QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate (cost=198303.34..198303.35 rows=1 width=0) (actual time=16683.662..16683.663 rows=1 loops=1)
   -> Unique (cost=198098.06..198156.71 rows=11730 width=415) (actual time=16680.762..16683.359 rows=2038 loops=1)
         -> Sort (cost=198098.06..198127.39 rows=11730 width=415) (actual time=16680.760..16681.563 rows=5294 loops=1)
               Sort Key: bugtask.id
               Sort Method: quicksort Memory: 2317kB
               -> Nested Loop (cost=501.86..197305.24 rows=11730 width=415) (actual time=56.892..16653.912 rows=5294 loops=1)
                     -> Nested Loop (cost=501.86..128582.62 rows=11730 width=419) (actual time=56.820..16522.481 rows=6733 loops=1)
                           -> Bitmap Heap Scan on bugmessage (cost=501.86..36012.55 rows=26663 width=4) (actual time=26.446..356.463 rows=32134 loops=1)
                                 Recheck Cond: ((owner = 100) AND (index > 0))
                                 -> Bitmap Index Scan on bugmessage__owner__index__idx (cost=0.00..495.20 rows=26663 width=0) (actual time=18.258..18.258 rows=32134 loops=1)
                                       Index Cond: ((owner = 100) AND (index > 0))
                           -> Index Scan using bugtask__bug__idx on bugtask (cost=0.00..3.46 rows=1 width=415) (actual time=0.470..0.502 rows=0 loops=32134)
                                 Index Cond: (bugtask.bug = bugmessage.bug)
                                 Filter: (bugtask.status = ANY ('{10,15,20,21,22,25}'::integer[]))
                     -> Index Scan using bug_pkey on bug (cost=0.00..5.85 rows=1 width=4) (actual time=0.017..0.018 rows=1 loops=6733)
                           Index Cond: (bug.id = bugtask.bug)
                           Filter: ((bug.duplicateof IS NULL) AND (NOT bug.private))
 Total runtime: 16684.306 ms

hot

                                                                                  QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate (cost=198303.34..198303.35 rows=1 width=0) (actual time=522.657..522.658 rows=1 loops=1)
   -> Unique (cost=198098.06..198156.71 rows=11730 width=415) (actual time=517.456..522.067 rows=2038 loops=1)
         -> Sort (cost=198098.06..198127.39 rows=11730 width=415) (actual time=517.453..518.947 r...

And with the product constraint its still reasonable:
explain analyze SELECT count(*) from (SELECT DISTINCT ON (BugTask.id) BugTask.*
FROM BugTask left join product on bugtask.product = product.id, Bug, BugMessage
WHERE
 Bug.id = BugTask.bug
 AND Bug.id = BugMessage.bug
AND BugTask.status in (10, 15, 20, 21, 22, 25)
 AND Bug.duplicateof IS NULL
AND Bug.private = FALSE
AND BugMessage.index > 0
AND BugMessage.owner = 100
and (bugtask.product is null or product.active)) as foo;

                                                                                      QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate (cost=195766.06..195766.07 rows=1 width=0) (actual time=503.638..503.638 rows=1 loops=1)
   -> Unique (cost=195578.95..195632.41 rows=10692 width=415) (actual time=500.720..503.337 rows=2032 loops=1)
         -> Sort (cost=195578.95..195605.68 rows=10692 width=415) (actual time=500.718..501.538 rows=5285 loops=1)
               Sort Key: bugtask.id
               Sort Method: quicksort Memory: 2316kB
               -> Nested Loop (cost=501.86..194863.43 rows=10692 width=415) (actual time=23.042..485.416 rows=5285 loops=1)
                     -> Nested Loop Left Join (cost=501.86..132222.15 rows=10692 width=419) (actual time=23.017..431.153 rows=6724 loops=1)
                           Filter: ((bugtask.product IS NULL) OR product.active)
                           -> Nested Loop (cost=501.86..128582.62 rows=11730 width=419) (actual time=22.994..413.474 rows=6733 loops=1)
                                 -> Bitmap Heap Scan on bugmessage (cost=501.86..36012.55 rows=26663 width=4) (actual time=22.862..76.690 rows=32134 loops=1)
                                       Recheck Cond: ((owner = 100) AND (index > 0))
                                       -> Bitmap Index Scan on bugmessage__owner__index__idx (cost=0.00..495.20 rows=26663 width=0) (actual time=15.267..15.267 rows=32134 loops=1)
                                             Index Cond: ((owner = 100) AND (index > 0))
                                 -> Index Scan using bugtask__bug__idx on bugtask (cost=0.00..3.46 rows=1 width=415) (actual time=0.009..0.010 rows=0 loops=32134)
                                       Index Cond: (bugtask.bug = bugmessage.bug)
                                       Filter: (bugtask.status = ANY ('{10,15,20,21,22,25}'::integer[]))
                           -> Index Scan using product_pkey on product (cost=0.00..0.30 rows=1 width=5) (actual time=0.001..0.001 rows=0 loops=6733)
                                 Index Cond: (bugtask.product = product.id)
                     -> Index Scan using bug_pkey on bug (cost=0.00..5.85 rows=1 width=4) (actual time=0.007..0.007 rows=1 loops=6724)
                           Index Cond: (bug.id = bugtask.bug)
                           Filter: ((bug.duplicateof IS NULL) AND (NOT bug.private))
 Total runtime: 504.301 ms
(22 rows)

exists variant:

explain analyze SELECT count(*) from (SELECT DISTINCT ON (BugTask.id) BugTask.*
FROM BugTask left join product on bugtask.product = product.id, Bug
WHERE
 Bug.id = BugTask.bug
 AND exists (select true from BugMessage where Bug.id = BugMessage.bug and BugMessage.index > 0
AND BugMessage.owner = 100 )
AND BugTask.status in (10, 15, 20, 21, 22, 25)
 AND Bug.duplicateof IS NULL
AND Bug.private = FALSE
AND (bugtask.product is null or product.active)) as foo;

cold:

                                                                                        QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate (cost=190310.08..190310.09 rows=1 width=0) (actual time=5409.006..5409.007 rows=1 loops=1)
   -> Unique (cost=186991.52..187939.68 rows=189632 width=415) (actual time=5405.887..5408.446 rows=2032 loops=1)
         -> Sort (cost=186991.52..187465.60 rows=189632 width=415) (actual time=5405.884..5406.534 rows=2032 loops=1)
               Sort Key: bugtask.id
               Sort Method: quicksort Memory: 855kB
               -> Hash Join (cost=66001.50..139809.58 rows=189632 width=415) (actual time=810.173..5395.111 rows=2032 loops=1)
                     Hash Cond: (bugtask.bug = bug.id)
                     -> Hash Left Join (cost=9710.95..82448.99 rows=251780 width=415) (actual time=224.393..4527.200 rows=306265 loops=1)
                           Hash Cond: (bugtask.product = product.id)
                           Filter: ((bugtask.product IS NULL) OR product.active)
                           -> Bitmap Heap Scan on bugtask (cost=6573.33..75240.10 rows=276215 width=415) (actual time=173.626..3743.762 rows=308734 loops=1)
                                 Recheck Cond: (status = ANY ('{10,15,20,21,22,25}'::integer[]))
                                 -> Bitmap Index Scan on bugtask__status__idx (cost=0.00..6504.28 rows=276215 width=0) (actual time=159.547..159.547 rows=309007 loops=1)
                                       Index Cond: (status = ANY ('{10,15,20,21,22,25}'::integer[]))
                           -> Hash (cost=2771.72..2771.72 rows=29272 width=5) (actual time=50.680..50.680 rows=29105 loops=1)
                                 -> Seq Scan on product (cost=0.00..2771.72 rows=29272 width=5) (actual time=0.019..39.297 rows=29105 loops=1)
                     -> Hash (cost=55957.26..55957.26 rows=26663 width=8) (actual time=574.459..574.459 rows=13676 loops=1)
                           -> Nested Loop (cost=36079.20..55957.26 rows=26663 width=8) (actual time=67.750..559.692 rows=13676 loops=1)
                                 -> HashAggregate (cost=36079.20..36116.95 rows=3775 width=4) (actual time=67.675..81.816 rows=14922 loops=1)
                                       -> Bitmap Heap Scan on bugmessage (cost=501.86..36012.55 rows=26663 width=4) (actual time=11.171..51.408 rows=32134 loops=1)
                                             Recheck Cond: ((ow...

So, it looks like this is the db patch we need:
alter table bugmessage add column owner int;
create index bugmessage__owner__index__idx on bugmessage using btree(owner, index);

We then need a background migration of
this shape:
update bugmessage set owner=message.owner from message where message.id=bugmessage.message;

and finally we can update the 'commented on' query generation to create it like so:
SELECT BugTask.*
FROM BugTask left join product on bugtask.product = product.id, Bug, BugMessage
WHERE
 Bug.id = BugTask.bug
 AND Bug.id = BugMessage.bug
AND BugTask.status in (10, 15, 20, 21, 22, 25)
 AND Bug.duplicateof IS NULL
AND Bug.private = FALSE
AND BugMessage.index > 0
AND BugMessage.owner = 100
and (bugtask.product is null or product.active);

--rollback of the experimental schema:
drop index bugmessage__commentor__idx ;
drop index bugmessage__owner__idx ;
drop index bugmessage__owner__index__idx ;
alter table bugmessage drop column owner;

Fixed in db-stable r10403 <http://bazaar.launchpad.net/~launchpad-pqm/launchpad/db-stable/revision/10403>.

Fixed in db-stable r10416 <http://bazaar.launchpad.net/~launchpad-pqm/launchpad/db-stable/revision/10416>.

2011-04-12 00:57:02 DEBUG Updated 1000 bugmessages.
2011-04-12 00:57:12 DEBUG Updated 1000 bugmessages.
2011-04-12 00:57:19 DEBUG Updated 1000 bugmessages.
2011-04-12 00:57:24 DEBUG Updated 1000 bugmessages.
2011-04-12 00:57:30 DEBUG Updated 1000 bugmessages.
2011-04-12 00:57:36 DEBUG Updated 1000 bugmessages.
2011-04-12 00:57:41 DEBUG Updated 1000 bugmessages.

garbo is happily chewing along

Fixed in db-stable r10423 <http://bazaar.launchpad.net/~launchpad-pqm/launchpad/db-stable/revision/10423>.

New query works for +commentedbugs fine - 43 queries/external actions issued in 2.52 seconds, but on person:+bugs itself we're still timing out. So, qa-ok (some improvement, no worse).

explain analyze SELECT BugTask.assignee, BugTask.bug, BugTask.bugwatch, BugTask.date_assigned, BugTask.date_closed, BugTask.date_confirmed, BugTask.date_fix_committed, BugTask.date_fix_released, BugTask.date_incomplete, BugTask.date_inprogress, BugTask.date_left_closed, BugTask.date_left_new, BugTask.date_triaged, BugTask.datecreated, BugTask.distribution, BugTask.distroseries, BugTask.heat, BugTask.id, BugTask.importance, BugTask.milestone, BugTask.owner, BugTask.product, BugTask.productseries, BugTask.sourcepackagename, BugTask.status, BugTask.statusexplanation, BugTask.targetnamecache, Bug.date_last_message, Bug.date_last_updated, Bug.date_made_private, Bug.datecreated, Bug.description, Bug.duplicateof, Bug.heat, Bug.heat_last_updated, Bug.id, Bug.latest_patch_uploaded, Bug.message_count, Bug.name, Bug.number_of_duplicates, Bug.owner, Bug.private, Bug.security_related, Bug.title, Bug.users_affected_count, Bug.users_unaffected_count, Bug.who_made_private FROM ((SELECT BugTask.assignee, BugTask.bug, BugTask.bugwatch, BugTask.date_assigned, BugTask.date_closed, BugTask.date_confirmed, BugTask.date_fix_committed, BugTask.date_fix_released, BugTask.date_incomplete, BugTask.date_inprogress, BugTask.date_left_closed, BugTask.date_left_new, BugTask.date_triaged, BugTask.datecreated, BugTask.distribution, BugTask.distroseries, BugTask.heat, BugTask.id, BugTask.importance, BugTask.milestone, BugTask.owner, BugTask.product, BugTask.productseries, BugTask.sourcepackagename, BugTask.status, BugTask.statusexplanation, BugTask.targetnamecache FROM BugTask LEFT JOIN Product ON BugTask.product = Product.id AND Product.active, Bug WHERE Bug.id = BugTask.bug AND BugTask.assignee = 100 AND ((BugTask.status = 10) OR (BugTask.status = 15) OR (BugTask.status = 20) OR (BugTask.status = 21) OR (BugTask.status = 22) OR (BugTask.status = 25)) AND Bug.duplicateof is NULL AND (Bugtask.product IS NULL OR Product.active = TRUE) AND (Bug.private = FALSE OR EXISTS ( SELECT BugSubscription.bug FROM BugSubscription, TeamParticipation WHERE TeamParticipation.person = 2 AND TeamParticipation.team = BugSubscription.person AND BugSubscription.bug = Bug.id UNION SELECT BugTask.bug FROM BugTask, TeamParticipation WHERE TeamParticipation.person = 2 AND TeamParticipation.team = BugTask.assignee AND BugTask.bug = Bug.id )) ) UNION (SELECT BugTask.assignee, BugTask.bug, BugTask.bugwatch, BugTask.date_assigned, BugTask.date_closed, BugTask.date_confirmed, BugTask.date_fix_committed, BugTask.date_fix_released, BugTask.date_incomplete, BugTask.date_inprogress, BugTask.date_left_closed, BugTask.date_left_new, BugTask.date_triaged, BugTask.datecreated, BugTask.distribution, BugTask.distroseries, BugTask.heat, BugTask.id, BugTask.importance, BugTask.milestone, BugTask.owner, BugTask.product, BugTask.productseries, BugTask.sourcepackagename, BugTask.status, BugTask.statusexplanation, BugTask.targetnamecache FROM BugTask LEFT JOIN Product ON BugTask.product = Product.id AND Product.active, Bug, BugSubscription WHERE Bug.id = BugTask.bug AND ((BugTask.status = 10) OR (BugTask.status = 15) OR (BugTask.status = 20) OR (BugTask.status = 21) OR (BugTask.status = 22) OR (BugTask.status = 25)) AND...

The join outside the union with bug is triggering a (bogus) seqscan on on Bug. If we query separately for one pages results the query drops to 1.8 seconds (plus the time to retrieve a page of results). This will need some care in the query compiler as we shouldn't destablise all our other queries.

Alternatively, perhaps we could set enable_seqscan = 0 around the query: that has the same effect :)

So, we get this plan with the flag enabled:
explain SELECT COUNT(*) FROM ((SELECT BugTask.assignee, BugTask.bug, BugTask.bugwatch, BugTask.date_assigned, BugTask.date_closed, BugTask.date_confirmed, BugTask.date_fix_committed, BugTask.date_fix_released, BugTask
.date_incomplete, BugTask.date_inprogress, BugTask.date_left_closed, BugTask.date_left_new, BugTask.date_triaged, BugTask.datecreated, BugTask.distribution, BugTask.distroseries, BugTask.heat, BugTask.id, BugTask.importance, BugTask.milestone, BugTask.owner, BugTask.product, BugTask.productseries, BugTask.sourcepackagename, BugTask.status, BugTask.statusexplanation, BugTask.targetnamecache FROM BugTask LEFT JOIN Product ON BugTask.product = Product.id AND Product.active, Bug WHERE Bug.id = BugTask.bug AND BugTask.assignee = 100 AND ((BugTask.status = 10) OR (BugTask.status = 15) OR (BugTask.status = 20) OR (BugTask.status = 21) OR (BugTask.status = 22) OR (BugTask.status = 25)) AND Bug.duplicateof is NULL AND (Bugtask.product IS NULL OR Product.active = TRUE) AND (Bug.private = FALSE OR EXISTS ( SELECT BugSubscription.bug FROM BugSubscription, TeamParticipation WHERE TeamParticipation.person = 2 AND TeamParticipation.team = BugSubscription.person AND BugSubscription.bug = Bug.id UNION SELECT BugTask.bug FROM BugTask, TeamParticipation WHERE TeamParticipation.person = 2 AND TeamParticipation.team = BugTask.assignee AND BugTask.bug = Bug.id )) ) UNION (SELECT BugTask.assignee, BugTask.bug, BugTask.bugwatch, BugTask.date_assigned, BugTask.date_closed, BugTask.date_confirmed, BugTask.date_fix_committed, BugTask.date_fix_released, BugTask.date_incomplete, BugTask.date_inprogress, BugTask.date_left_closed, BugTask.date_left_new, BugTask.date_triaged, BugTask.datecreated, BugTask.distribution, BugTask.distroseries, BugTask.heat, BugTask.id, BugTask.importance, BugTask.milestone, BugTask.owner, BugTask.product, BugTask.productseries, BugTask.sourcepackagename, BugTask.status, BugTask.statusexplanation, BugTask.targetnamecache FROM BugTask LEFT JOIN Product ON BugTask.product = Product.id AND Product.active, Bug, BugSubscription WHERE Bug.id = BugTask.bug AND ((BugTask.status = 10) OR (BugTask.status = 15) OR (BugTask.status = 20) OR (BugTask.status = 21) OR (BugTask.status = 22) OR (BugTask.status = 25)) AND Bug.duplicateof is NULL AND Bug.id = BugSubscription.bug AND BugSubscription.person = 100 AND (Bugtask.product IS NULL OR Product.active = TRUE) AND (Bug.private = FALSE OR EXISTS ( SELECT BugSubscription.bug FROM BugSubscription, TeamParticipation WHERE TeamParticipation.person = 2 AND TeamParticipation.team = BugSubscription.person AND BugSubscription.bug = Bug.id UNION SELECT BugTask.bug FROM BugTask, TeamParticipation WHERE TeamParticipation.person = 2 AND TeamParticipation.team = BugTask.assignee AND BugTask.bug = Bug.id )) ) UNION (SELECT BugTask.assignee, BugTask.bug, BugTask.bugwatch, BugTask.date_assigned, BugTask.date_closed, BugTask.date_confirmed, BugTask.date_fix_committed, BugTask.date_fix_released, BugTask.date_incomplete, BugTask.date_inprogress, BugTask.date_left_closed, BugTask.date_left_new, BugTask.date_triaged, BugTask.datecreated, BugTask.distribution, BugTask.distr...

Breaking it down, the problems here:
 - we repeatedly check privacy in all the subplans, ditto product.active

Nested Loop (cost=3193.87..73534.16 rows=1303 width=280) - ok, not brilliant, but ok
Nested Loop (cost=0.00..98481.42 rows=1499 width=280) - ditto
Nested Loop Left Join (cost=0.00..49419.31 rows=711 width=280) - same
And the problem child:

                                 -> Hash Join (cost=216449.03..292441.56 rows=190053 width=280)
                                       Hash Cond: (public.bugtask.bug = public.bug.id)
                                       -> Hash Left Join (cost=13260.49..88189.71 rows=251706 width=280)
                                             Hash Cond: (public.bugtask.product = public.product.id)
                                             Filter: ((public.bugtask.product IS NULL) OR public.product.active)
                                             -> Bitmap Heap Scan on bugtask (cost=10210.72..81759.72 rows=276144 width=280)
                                                   Recheck Cond: ((status = 10) OR (status = 15) OR (status = 20) OR (status = 21) OR (status = 22) OR (status = 25))
                                                   -> BitmapOr (cost=10210.72..10210.72 rows=308640 width=0)
                                                         -> Bitmap Index Scan on bugtask__status__idx (cost=0.00..5843.19 rows=184232 width=0)
                                                               Index Cond: (status = 10)
                                                         -> Bitmap Index Scan on bugtask__status__idx (cost=0.00..565.49 rows=17739 width=0)
                                                               Index Cond: (status = 15)
                                                         -> Bitmap Index Scan on bugtask__status__idx (cost=0.00..1792.13 rows=56490 width=0)
                                                               Index Cond: (status = 20)
                                                         -> Bitmap Index Scan on bugtask__status__idx (cost=0.00..959.11 rows=30221 width=0)
                                                               Index Cond: (status = 21)
                                                         -> Bitmap Index Scan on bugtask__status__idx (cost=0.00..169.28 rows=5311 width=0)
                                                               Index Cond: (status = 22)
                                                         -> Bitmap Index Scan on bugtask__status__idx (cost=0.00..467.30 rows=14647 width=0)
                                                               Index Cond: (status = 25)
                                             -> Hash (cost=2776.19..2776.19 rows=21886 width=5)
                                                   -> Seq Scan on product (cost=0.00..2776.19 rows=21886 width=5)
                                                         Filter: active
                                       -> Hash (cost=202859.04..202859.04 rows=26360 width=8)
                                             -> Nested Loop (cost=35978.83..202859.04 rows=26360 width=8)
                                                   ...

The commented on subquery is 2 seconds hot; thats in principle ok but we're clearly having trouble. Will see about a reformulation.

SELECT COUNT(*) FROM BugTask LEFT JOIN Product ON BugTask.product = Product.id AND Product.active JOIN Bug ON BugTask.bug = Bug.id WHERE Bug.id = BugTask.bug AND bugtask.status in (10,15,20,21,22,25) AND Bug.duplicateof is NULL AND (Bugtask.product IS NULL OR Product.active = TRUE) AND Bug.id in (SELECT distinct bug from Bugmessage WHERE BugMessage.index > 0 AND BugMessage.owner = 100) AND (Bug.private = FALSE OR EXISTS ( SELECT BugSubscription.bug FROM BugSubscription, TeamParticipation WHERE TeamParticipation.person = 2 AND TeamParticipation.team = BugSubscription.person AND BugSubscription.bug = Bug.id UNION SELECT BugTask.bug FROM BugTask, TeamParticipation WHERE TeamParticipation.person = 2 AND TeamParticipation.team = BugTask.assignee AND BugTask.bug = Bug.id ))

gives

launchpad_qastaging=> explain analyze SELECT COUNT(*) FROM BugTask LEFT JOIN Product ON BugTask.product = Product.id AND Product.active JOIN Bug ON BugTask.bug = Bug.id WHERE Bug.id = BugTask.bug AND bugtask.status in (10,15,20,21,22,25) AND Bug.duplicateof is NULL AND (Bugtask.product IS NULL OR Product.active = TRUE) AND Bug.id in (SELECT distinct bug from Bugmessage WHERE BugMessage.index > 0 AND BugMessage.owner = 100) AND (Bug.private = FALSE OR EXISTS ( SELECT BugSubscription.bug FROM BugSubscription, TeamParticipation WHERE TeamParticipation.person = 2 AND TeamParticipation.team = BugSubscription.person AND BugSubscription.bug = Bug.id UNION SELECT BugTask.bug FROM BugTask, TeamParticipation WHERE TeamParticipation.person = 2 AND TeamParticipation.team = BugTask.assignee AND BugTask.bug = Bug.id ));
                                                                                         QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate (cost=65169.96..65169.97 rows=1 width=0) (actual time=282.109..282.110 rows=1 loops=1)
   -> Nested Loop (cost=35978.83..65169.50 rows=182 width=0) (actual time=120.248..281.635 rows=2037 loops=1)
         -> Nested Loop Left Join (cost=35978.83..56788.78 rows=182 width=8) (actual time=120.228..259.906 rows=2722 loops=1)
               Filter: ((public.bugtask.product IS NULL) OR product.active)
               -> Nested Loop (cost=35978.83..56726.71 rows=200 width=12) (actual time=120.222..254.139 rows=2728 loops=1)
                     -> HashAggregate (cost=35978.83..36016.24 rows=3741 width=4) (actual time=120.103..128.789 rows=14922 loops=1)
                           -> Bitmap Heap Scan on bugmessage (cost=597.90..35912.93 rows=26360 width=4) (actual time=22.410..92.976 rows=32134 loops=1)
                                 Recheck Cond: ((owner = 100) AND (index > 0))
                                 -> Bitmap Index Scan on bugmessage__owner__index__idx (cost=0.00..591.31 rows=26360 width=0) (actual time=13.509..13.509 rows=32134 loops=1)
                                       Index Cond: ((owner = 100) AND (index > 0))
                     -> Index Scan using bugtask__...

With that substituted into the larger query, we're down to (warm) 2 seconds, and (hot) 1.1 seconds.

Fixed in stable r12962 <http://bazaar.launchpad.net/~launchpad-pqm/launchpad/stable/revision/12962>.

The page works hot now on qastaging.