Launchpad itself

Timeout on Distribution:+bugs searching by bug supervisor

Bug #892820 reported by Dave Walker
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Launchpad itself
Fix Released
Critical
Raphaël Badin

Bug Description

As part of the Ubuntu server teams bug triaging process, we have a series of pre-canned URL's. Since Friday (18/11/11), this has started OOPs'ing.

An example is, OOPS-c0981f059156b3ed4108c4c92958879c

https://bugs.launchpad.net/ubuntu/+bugs?field.searchtext=&orderby=datecreated&field.status%3Alist=NEW&field.importance%3Alist=UNDECIDED&assignee_option=any&field.assignee=&field.bug_reporter=&field.bug_supervisor=ubuntu-server&field.bug_commenter=&field.subscriber=&field.component-empty-marker=1&field.status_upstream-empty-marker=1&field.omit_dupes.used=&field.omit_dupes=on&field.has_patch.used=&field.has_cve.used=&field.affects_me.used=&field.tag=-notserv&field.tags_combinator=ANY&field.has_no_package.used=&search=Search

This is really very critical for our incoming bug workflow, and blocking.

Analysis
========

Slow query (8.8 seconds) caused by a combination of bad estimation (pg things 26K rows will be returned) and the query describing duplicate work - the bug supervisor check is filtering on task id, which is precisely what the other main filter does; lifting that work up to provide clauses on product, distribution and distribution+sourcepackagename triggers a better plan. (See comment 11).

Alternative fix from #postgresql is to change the sort to 'datecreated + interval '0'' which runs this query otherwise unmodified in 300ms on qastaging.

SELECT BugTask.status, 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.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 BugTask JOIN Bug ON BugTask.bug = Bug.id WHERE Bug.id = BugTask.bug AND BugTask.importance IN (5) AND BugTask.distribution = 1 AND (BugTask.status IN (10)) AND Bug.duplicateof is NULL AND NOT EXISTS (SELECT TRUE FROM BugTag WHERE BugTag.bug = Bug.id AND BugTag.tag = 'notserv') AND BugTask.id IN ( SELECT BugTask.id FROM BugTask, Product WHERE BugTask.product = Product.id AND Product.bug_supervisor = 343381 UNION ALL SELECT BugTask.id FROM BugTask, StructuralSubscription WHERE BugTask.distribution = StructuralSubscription.distribution AND BugTask.sourcepackagename = StructuralSubscription.sourcepackagename AND StructuralSubscription.subscriber = 343381 UNION ALL SELECT BugTask.id FROM BugTask, Distribution WHERE BugTask.distribution = Distribution.id AND Distribution.bug_supervisor = 343381 ) AND (Bug.private = FALSE OR EXISTS ( WITH teams AS ( SELECT team from TeamParticipation WHERE person = 1042386 ) SELECT BugSubscription.bug FROM BugSubscription WHERE BugSubscription.person IN (SELECT team FROM teams) AND BugSubscription.bug = Bug.id UNION SELECT BugTask.bug FROM BugTask WHERE BugTask.assignee IN (SELECT team FROM teams) AND BugTask.bug = Bug.id )) ORDER BY BugTask.datecreated LIMIT 76 OFFSET 0;

Plan:
 Limit (cost=16707.17..140839.63 rows=76 width=921) (actual time=177865.846..179420.653 rows=5 loops=1)
   -> Nested Loop Anti Join (cost=16707.17..45547185.77 rows=27876 width=921) (actual time=177865.845..179420.646 rows=5 loops=1)
         -> Nested Loop Semi Join (cost=16707.17..45536237.50 rows=27876 width=921) (actual time=177865.785..179420.434 rows=5 loops=1)
               Join Filter: (public.bugtask.id = public.bugtask.id)
               -> Nested Loop (cost=0.00..15171891.61 rows=55751 width=921) (actual time=458.705..6943.130 rows=44267 loops=1)
                     -> Index Scan using bugtask__datecreated__idx on bugtask (cost=0.00..99933.00 rows=73926 width=161) (actual time=264.252..4141.236 rows=152189 loops=1)
                           Filter: ((importance = 5) AND (distribution = 1) AND (status = 10))
                     -> Index Scan using bug_pkey on bug (cost=0.00..203.87 rows=1 width=760) (actual time=0.017..0.017 rows=0 loops=152189)
                           Index Cond: (bug.id = public.bugtask.bug)
                           Filter: ((bug.duplicateof IS NULL) AND ((NOT bug.private) OR (SubPlan 2)))
                           SubPlan 2
                             -> Unique (cost=201.93..201.94 rows=2 width=4) (actual time=0.202..0.202 rows=1 loops=3131)
                                   CTE teams
                                     -> Index Scan using teamparticipation_person_idx on teamparticipation (cost=0.00..184.67 rows=137 width=4) (actual time=0.069..0.591 rows=157 loops=1)
                                           Index Cond: (person = 1042386)
                                   -> Sort (cost=17.27..17.27 rows=2 width=4) (actual time=0.197..0.197 rows=1 loops=3131)
                                         Sort Key: bugsubscription.bug
                                         Sort Method: quicksort Memory: 25kB
                                         -> Append (cost=4.45..17.26 rows=2 width=4) (actual time=0.108..0.183 rows=1 loops=3131)
                                               -> Hash Semi Join (cost=4.45..8.85 rows=1 width=4) (actual time=0.084..0.092 rows=1 loops=3131)
                                                     Hash Cond: (bugsubscription.person = teams.team)
                                                     -> Index Scan using bugsubscription_bug_idx on bugsubscription (cost=0.00..4.39 rows=3 width=8) (actual time=0.065..0.084 rows=4 loops=3131)
                                                           Index Cond: (bug = $1)
                                                     -> Hash (cost=2.74..2.74 rows=137 width=4) (actual time=0.726..0.726 rows=157 loops=1)
                                                           -> CTE Scan on teams (cost=0.00..2.74 rows=137 width=4) (actual time=0.072..0.661 rows=157 loops=1)
                                               -> Nested Loop Semi Join (cost=0.00..8.39 rows=1 width=4) (actual time=0.087..0.087 rows=0 loops=3131)
                                                     Join Filter: (public.bugtask.assignee = teams.team)
                                                     -> Index Scan using bugtask__bug__idx on bugtask (cost=0.00..3.94 rows=1 width=8) (actual time=0.021..0.022 rows=1 loops=3131)
                                                           Index Cond: (bug = $1)
                                                     -> CTE Scan on teams (cost=0.00..2.74 rows=137 width=4) (actual time=0.001..0.031 rows=157 loops=3260)
               -> Materialize (cost=16707.17..16949.10 rows=24193 width=4) (actual time=0.000..1.646 rows=12164 loops=44267)
                     -> Append (cost=2.48..16682.98 rows=24193 width=4) (actual time=0.190..46.945 rows=12165 loops=1)
                           -> Nested Loop (cost=2.48..99.60 rows=11 width=4) (actual time=0.037..0.037 rows=0 loops=1)
                                 -> Index Scan using product__bug_supervisor__idx on product (cost=0.00..3.87 rows=1 width=4) (actual time=0.037..0.037 rows=0 loops=1)
                                       Index Cond: (bug_supervisor = 343381)
                                 -> Bitmap Heap Scan on bugtask (cost=2.48..95.09 rows=52 width=8) (never executed)
                                       Recheck Cond: (public.bugtask.product = product.id)
                                       -> Bitmap Index Scan on bugtask__product__bug__key (cost=0.00..2.47 rows=52 width=0) (never executed)
                                             Index Cond: (public.bugtask.product = product.id)
                           -> Nested Loop (cost=3.50..922.99 rows=6651 width=4) (actual time=0.151..44.760 rows=12165 loops=1)
                                 -> Bitmap Heap Scan on structuralsubscription (cost=3.50..185.88 rows=187 width=8) (actual time=0.094..0.539 rows=187 loops=1)
                                       Recheck Cond: (subscriber = 343381)
                                       -> Bitmap Index Scan on structuralsubscription__subscriber__idx (cost=0.00..3.45 rows=187 width=0) (actual time=0.071..0.071 rows=188 loops=1)
                                             Index Cond: (subscriber = 343381)
                                 -> Index Scan using bugtask__distribution_sourcepackage__heat__idx on bugtask (cost=0.00..3.93 rows=1 width=12) (actual time=0.015..0.222 rows=65 loops=187)
                                       Index Cond: ((public.bugtask.distribution = structuralsubscription.distribution) AND (public.bugtask.sourcepackagename = structuralsubscription.sourcepackagename))
                           -> Nested Loop (cost=0.00..15418.46 rows=17531 width=4) (actual time=0.032..0.032 rows=0 loops=1)
                                 -> Index Scan using distribution__bug_supervisor__idx on distribution (cost=0.00..3.87 rows=1 width=4) (actual time=0.031..0.031 rows=0 loops=1)
                                       Index Cond: (bug_supervisor = 343381)
                                 -> Index Scan using bugtask__distribution_sourcepackage__heat__idx on bugtask (cost=0.00..15168.06 rows=19723 width=8) (never executed)
                                       Index Cond: (public.bugtask.distribution = distribution.id)
         -> Index Scan using bugtag__bug__idx on bugtag (cost=0.00..0.39 rows=1 width=4) (actual time=0.036..0.036 rows=0 loops=5)
               Index Cond: (bugtag.bug = bug.id)
               Filter: (bugtag.tag = 'notserv'::text)
 Total runtime: 179421.810 ms

Workarounds
===========

 * Run the query as an anonymous user: the plan for just-public bugs is good and it runs fast.
 * Leave the new bug listing beta : the overhead of the performance bugs in the bug listings work is enough to break this.

See original description

Related branches

lp:~rvb/launchpad/bugs-timeout-bug-892820
Benji York (community): Approve (code)
Diff: 47 lines (+14/-17)
1 file modified
lib/lp/bugs/model/bugtask.py (+14/-17)
Robert Collins (lifeless)
description: updated
Changed in launchpad:
status: New → Triaged
importance: Undecided → Critical
summary: - pre-canned bug search url has started OOPs'ing
+ Timeout on Distribution:+bugs
Robert Collins (lifeless)
description: updated
Robert Collins (lifeless)
tags: added: regression timeout
Revision history for this message
Robert Collins (lifeless) wrote : Re: Timeout on Distribution:+bugs

The query takes 3 minutes to run outside of an appserver

Revision history for this message
Robert Collins (lifeless) wrote :
Download full text (13.9 KiB)

Dropping tag doesn't fix performance. OOPS without tag; OOPS-260c8d819920d52445bc1e437bd80ea8

SELECT BugTask.status, 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.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 BugTask JOIN Bug ON BugTask.bug = Bug.id WHERE Bug.id = BugTask.bug AND BugTask.importance IN (5) AND BugTask.distribution = 1 AND (BugTask.status IN (10)) AND Bug.duplicateof is NULL AND BugTask.id IN ( SELECT BugTask.id FROM BugTask, Product WHERE BugTask.product = Product.id AND Product.bug_supervisor = 343381 UNION ALL SELECT BugTask.id FROM BugTask, StructuralSubscription WHERE BugTask.distribution = StructuralSubscription.distribution AND BugTask.sourcepackagename = StructuralSubscription.sourcepackagename AND StructuralSubscription.subscriber = 343381 UNION ALL SELECT BugTask.id FROM BugTask, Distribution WHERE BugTask.distribution = Distribution.id AND Distribution.bug_supervisor = 343381 ) AND (Bug.private = FALSE OR EXISTS ( WITH teams AS ( SELECT team from TeamParticipation WHERE person = 2 ) SELECT BugSubscription.bug FROM BugSubscription WHERE BugSubscription.person IN (SELECT team FROM teams) AND BugSubscription.bug = Bug.id UNION SELECT BugTask.bug FROM BugTask WHERE BugTask.assignee IN (SELECT team FROM teams) AND BugTask.bug = Bug.id UNION SELECT BugTask.bug FROM BugTask, Product WHERE Product.owner IN (SELECT team FROM teams) AND BugTask.product = Product.id AND BugTask.bug = Bug.id AND Bug.security_related IS False UNION SELECT BugTask.bug FROM BugTask, ProductSeries WHERE ProductSeries.owner IN (SELECT team FROM teams) AND BugTask.productseries = ProductSeries.id AND BugTask.bug = Bug.id AND Bug.security_related IS False UNION SELECT BugTask.bug FROM BugTask, Distribution WHERE Distribution.owner IN (SELECT team FROM teams) AND BugTask.distribution = Distribution.id AND BugTask.bug = Bug.id AND Bug.security_related IS False UNION SELECT BugTask.bug FROM BugTask, DistroSeries, Distribution WHERE Distribution.owner IN (SELECT team FROM teams) AND DistroSeries.distribution = Distribution.id AND BugTask.distroseries = DistroSeries.id AND BugTask.bug = Bug.id AND Bug.security_related IS False )) ORDER BY BugTask.datecreated LIMIT 76 OFFSET 0

explain:
 Limit (cost=16707.17..149356.52 rows=76 width=921) (actual time=29718.551..178256.887 rows=23 loops=1)
   -> Nested Loop Semi Join (cost=16707.17..48683307.80 rows=...

Revision history for this message
Robert Collins (lifeless) wrote :
Download full text (4.6 KiB)

Ah, I'm seeing different (more complex) rules - due to disclosure.private_bug_visibility_rules.enabled being on for team:launchpad.

Original OOPS has:
SELECT BugTask.status,
       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.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 BugTask
JOIN Bug ON BugTask.bug = Bug.id
WHERE Bug.id = BugTask.bug
  AND BugTask.importance IN (5)
  AND BugTask.distribution = 1
  AND (BugTask.status IN (10))
  AND Bug.duplicateof IS NULL
  AND BugTask.id IN
    (SELECT BugTask.id
     FROM BugTask,
          Product
     WHERE BugTask.product = Product.id
       AND Product.bug_supervisor = 343381
     UNION ALL SELECT BugTask.id
     FROM BugTask,
          StructuralSubscription
     WHERE BugTask.distribution = StructuralSubscription.distribution
       AND BugTask.sourcepackagename = StructuralSubscription.sourcepackagename
       AND StructuralSubscription.subscriber = 343381
     UNION ALL SELECT BugTask.id
     FROM BugTask,
          Distribution
     WHERE BugTask.distribution = Distribution.id
       AND Distribution.bug_supervisor = 343381)
  AND (Bug.private = FALSE
       OR EXISTS (WITH teams AS
                    (SELECT team
                     FROM TeamParticipation
                     WHERE person = 2)
                  SELECT BugSubscription.bug
                  FROM BugSubscription
                  WHERE BugSubscription.person IN
                      (SELECT team
                       FROM teams)
                    AND BugSubscription.bug = Bug.id
                  UNION
                  SELECT BugTask.bug
                  FROM BugTask
                  WHERE BugTask.assignee IN
                      (SELECT team
                       FROM teams)
                    AND BugTask.bug = Bug.id
                  UNION
                  SELECT BugTask.bug
                  FROM BugTask,
                       Product
                  WHERE Product.owner IN
                      (SELECT team
                       FROM teams)
                    AND BugTask.product = Product.id
           ...

Read more...

Revision history for this message
Dave Walker (davewalker) wrote :

Testing a url without tag searching:

https://bugs.launchpad.net/ubuntu/+bugs?field.searchtext=&orderby=datecreated&field.status%3Alist=NEW&field.importance%3Alist=UNDECIDED&assignee_option=any&field.assignee=&field.bug_reporter=&field.bug_supervisor=ubuntu-server&field.bug_commenter=&field.subscriber=&field.component-empty-marker=1&field.status_upstream-empty-marker=1&field.omit_dupes.used=&field.omit_dupes=on&field.has_patch.used=&field.has_cve.used=&field.affects_me.used=&field.has_no_package.used=&search=Search

Generated:
OOPS-4466be4293abcae51b4f267b335d5db3

Revision history for this message
Robert Collins (lifeless) wrote :
Download full text (11.0 KiB)

plan of original query - looks identical at quick glance
 Limit (cost=16707.17..149356.52 rows=76 width=921) (actual time=170689.101..172503.304 rows=10 loops=1)
   -> Nested Loop Semi Join (cost=16707.17..48683307.80 rows=27883 width=921) (actual time=170689.099..172503.290 rows=10 loops=1)
         Join Filter: (public.bugtask.id = public.bugtask.id)
         -> Nested Loop (cost=0.00..18311341.12 rows=55765 width=921) (actual time=727.239..8917.468 rows=44262 loops=1)
               -> Index Scan using bugtask__datecreated__idx on bugtask (cost=0.00..99933.00 rows=73926 width=161) (actual time=397.501..5236.896 rows=152188 loops=1)
                     Filter: ((importance = 5) AND (distribution = 1) AND (status = 10))
               -> Index Scan using bug_pkey on bug (cost=0.00..246.33 rows=1 width=760) (actual time=0.022..0.023 rows=0 loops=152188)
                     Index Cond: (bug.id = public.bugtask.bug)
                     Filter: ((bug.duplicateof IS NULL) AND ((NOT bug.private) OR (SubPlan 2)))
                     SubPlan 2
                       -> HashAggregate (cost=244.40..244.46 rows=6 width=4) (actual time=0.346..0.346 rows=1 loops=3132)
                             CTE teams
                               -> Index Scan using teamparticipation_person_idx on teamparticipation (cost=0.00..178.02 rows=132 width=4) (actual time=0.135..4.342 rows=142 loops=1)
                                     Index Cond: (person = 2)
                             -> Append (cost=4.29..66.36 rows=6 width=4) (actual time=0.150..0.335 rows=1 loops=3132)
                                   -> Hash Semi Join (cost=4.29..8.68 rows=1 width=4) (actual time=0.091..0.099 rows=1 loops=3132)
                                         Hash Cond: (bugsubscription.person = teams.team)
                                         -> Index Scan using bugsubscription_bug_idx on bugsubscription (cost=0.00..4.39 rows=3 width=8) (actual time=0.071..0.089 rows=4 loops=3132)
                                               Index Cond: (bug = $1)
                                         -> Hash (cost=2.64..2.64 rows=132 width=4) (actual time=4.526..4.526 rows=142 loops=1)
                                               -> CTE Scan on teams (cost=0.00..2.64 rows=132 width=4) (actual time=0.142..4.441 rows=142 loops=1)
                                   -> Nested Loop Semi Join (cost=0.00..8.23 rows=1 width=4) (actual time=0.087..0.087 rows=0 loops=3132)
                                         Join Filter: (public.bugtask.assignee = teams.team)
                                         -> Index Scan using bugtask__bug__idx on bugtask (cost=0.00..3.94 rows=1 width=8) (actual time=0.025..0.025 rows=1 loops=3132)
                                               Index Cond: (bug = $1)
                                         -> CTE Scan on teams (cost=0.00..2.64 rows=132 width=4) (actual time=0.001..0.029 rows=142 loops=3261)
                                   -> Result (cost=0.00..12.11 rows=1 width=4) (actual time=0.022..0.022 rows=0 loops=3132)
                                         One-Time Filter: ($2 IS FALSE)
                                ...

Revision history for this message
Robert Collins (lifeless) wrote :

Instant-noisy bug. So - Copy-paste fail; OOPS-c0981f059156b3ed4108c4c92958879c (daviey's) has:
SELECT BugTask.status, 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.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 BugTask JOIN Bug ON BugTask.bug = Bug.id
WHERE Bug.id = BugTask.bug AND BugTask.importance IN (5) AND BugTask.distribution = 1 AND (BugTask.status IN (10)) AND Bug.duplicateof is NULL AND NOT EXISTS (SELECT TRUE FROM BugTag WHERE BugTag.bug = Bug.id AND BugTag.tag = 'notserv')
AND BugTask.id IN (
SELECT BugTask.id FROM BugTask, Product WHERE BugTask.product = Product.id AND Product.bug_supervisor = 343381
UNION ALL SELECT BugTask.id FROM BugTask, StructuralSubscription WHERE BugTask.distribution = StructuralSubscription.distribution AND BugTask.sourcepackagename = StructuralSubscription.sourcepackagename AND StructuralSubscription.subscriber = 343381
UNION ALL SELECT BugTask.id FROM BugTask, Distribution WHERE BugTask.distribution = Distribution.id AND Distribution.bug_supervisor = 343381 ) AND
 (Bug.private = FALSE OR EXISTS ( WITH teams AS ( SELECT team from TeamParticipation WHERE person = 1042386 ) SELECT BugSubscription.bug FROM BugSubscription WHERE BugSubscription.person IN (SELECT team FROM teams) AND BugSubscription.bug = Bug.id UNION SELECT BugTask.bug FROM BugTask WHERE BugTask.assignee IN (SELECT team FROM teams) AND BugTask.bug = Bug.id )) ORDER BY BugTask.datecreated LIMIT 76 OFFSET 0;

Revision history for this message
Robert Collins (lifeless) wrote :

https://lp-oops.canonical.com/oops.py/?oopsid=OOPS-61398f63dc890e7f5cf2b3276ae04ecf#statementlog is the page in question as an anonymous user.

Query there has the same structsub entries etc - and works nice and fast.
SELECT BugTask.*, Bug.*
FROM BugTask
JOIN Bug ON BugTask.bug = Bug.id
WHERE Bug.id = BugTask.bug
  AND BugTask.importance IN (5)
  AND BugTask.distribution = 1
  AND (BugTask.status IN (10))
  AND Bug.duplicateof IS NULL
  AND NOT EXISTS
    (SELECT TRUE
     FROM BugTag
     WHERE BugTag.bug = Bug.id
       AND BugTag.tag = 'notserv')
  AND BugTask.id IN
    ( SELECT BugTask.id
     FROM BugTask,
          Product
     WHERE BugTask.product = Product.id
       AND Product.bug_supervisor = 343381
     UNION ALL SELECT BugTask.id
     FROM BugTask,
          StructuralSubscription
     WHERE BugTask.distribution = StructuralSubscription.distribution
       AND BugTask.sourcepackagename = StructuralSubscription.sourcepackagename
       AND StructuralSubscription.subscriber = 343381
     UNION ALL SELECT BugTask.id
     FROM BugTask,
          Distribution
     WHERE BugTask.distribution = Distribution.id
       AND Distribution.bug_supervisor = 343381 )
  AND Bug.private = FALSE
ORDER BY BugTask.datecreated LIMIT 76
OFFSET 0;

Revision history for this message
Robert Collins (lifeless) wrote :

I had been thinking that this was a unexpected side effect of r14297, but local testing generates the same query, so that theory is out.

This means its one of our ongoing 'data changed slightly, query becomes intransigent' problems.

tags: removed: regression
Robert Collins (lifeless)
description: updated
description: updated
Revision history for this message
Robert Collins (lifeless) wrote :

examining the plan - the nested loop anti-join only kicks in at 177865ms, so not a problem

We get 12000 bugtasks from the bug supervisor clauses:
               -> Materialize (cost=16707.17..16949.10 rows=24193 width=4) (actual time=0.000..1.646 rows=12164 loops=44267)
none from product, 12K from structural subscriptions to distribution sourcepackages , none from distribution bug supervisor

however, it runs this subselect 44K times - though its materialized, its 1.6ms per time to consult it.

http://explain.depesz.com/s/4zx for a pretty view

Revision history for this message
Dave Walker (davewalker) wrote :

Robert discovered that removing orderby=datecreated url parameter made the query work without a timeout. This is now, no longer blocking.

Thanks very much!

Revision history for this message
Robert Collins (lifeless) wrote :
Download full text (6.6 KiB)

rephrasing the supervisor check brings it down to 4 seconds:
SELECT BugTask.status, 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.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 BugTask JOIN Bug ON BugTask.bug = Bug.id WHERE Bug.id = BugTask.bug AND BugTask.importance IN (5) AND BugTask.distribution = 1 AND (BugTask.status IN (10)) AND Bug.duplicateof is NULL AND NOT EXISTS (SELECT TRUE FROM BugTag WHERE BugTag.bug = Bug.id AND BugTag.tag = 'notserv') AND (BugTask.product in (select product.id from product where bug_supervisor = 343381) OR
(BugTask.distribution, Bugtask.sourcepackagename) in (SELECT StructuralSubscription.distribution, StructuralSubscription.sourcepackagename from StructuralSubscription where subscriber=343381) OR
BugTask.distribution in (SELECT id from Distribution where bug_supervisor=343381))
                                                                                                                                                                                                                                                AND (Bug.private = FALSE OR EXISTS ( WITH teams AS ( SELECT team from TeamParticipation WHERE person = 1042386 ) SELECT BugSubscription.bug FROM BugSubscription WHERE BugSubscription.person IN (SELECT team FROM teams) AND BugSubscription.bug = Bug.id UNION SELECT BugTask.bug FROM BugTask WHERE BugTask.assignee IN (SELECT team FROM teams) AND BugTask.bug = Bug.id )) ORDER BY BugTask.datecreated LIMIT 76 OFFSET 0

 Limit (cost=194.09..20947.97 rows=76 width=921) (actual time=3913.046..3920.141 rows=4 loops=1)
   -> Nested Loop Anti Join (cost=194.09..13321456.48 rows=48782 width=921) (actual time=3913.044..3920.137 rows=4 loops=1)
         -> Nested Loop (cost=194.09..13302301.74 rows=48782 width=921) (actual time=3912.964..3919.241 rows=4 loops=1)
               -> Index Scan using bugtask__datecreated__idx on bugtask (cost=194.09..110609.89 rows=64685 width=161) (actual time=355.727..3882.752 rows=1192 loops=1)
                     Filter: ((importance = 5) AND (distribution = 1) AND (status = 10) AND ((hashed SubPlan 1) OR (hashed SubPlan 2) OR (hashed SubPlan 3)))
                     SubPlan 1
                       -> Index Scan using product__bug_supervisor__idx on product (cost=0.00..3.87 rows=1 width=4) (actual time=0.089..0.089 rows=0 loops=1)
                             Index Cond...

Read more...

Robert Collins (lifeless)
description: updated
Robert Collins (lifeless)
description: updated
Revision history for this message
Dave Walker (davewalker) wrote :

Stage 2 of our process is (trimmed noise from URL):
https://bugs.launchpad.net/ubuntu/+bugs?field.searchtext=&orderby=-importance&search=Search&field.status%3Alist=NEW&field.bug_supervisor=ubuntu-server

This is now causing a timeout aswell.

Thanks!

Julian Edwards (julian-edwards)
Changed in launchpad:
assignee: nobody → Launchpad Red Squad (redsquad)
Revision history for this message
Raphaël Badin (rvb) wrote :

Rephrasing the supervisor seems to improve things quite a lot indeed. But I don't get the same numbers you have:
https://pastebin.canonical.com/56422/ => https://pastebin.canonical.com/56424/.

Anyway, I guess the only way to find out what this really brings is to have the appserver issue it for real on qastaging.

Changed in launchpad:
assignee: Launchpad Red Squad (redsquad) → Raphaël Badin (rvb)
status: Triaged → In Progress
Revision history for this message
Francis J. Lacoste (flacoste) wrote :

Escalated by Kate on 2011-11-23

tags: added: escalated
Revision history for this message
Launchpad QA Bot (lpqabot) wrote :

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

tags: added: qa-needstesting
Changed in launchpad:
status: In Progress → Fix Committed
Revision history for this message
Raphaël Badin (rvb) wrote :

Testing on qastaging:
old query: [8898.0, 6006.0, 4913.0]
new query: [595.0, 548.0, 611.0]

tags: added: qa-ok
removed: qa-needstesting
Revision history for this message
Raphaël Badin (rvb) wrote :

I'm still getting timeouts on qastaging when the cache is cold.

Raphaël Badin (rvb)
Changed in launchpad:
status: Fix Committed → Fix Released
Revision history for this message
Robert Collins (lifeless) wrote :

OOPS-f91c829404e2b1d60216acf02a09a05d occurrence today.

Changed in launchpad:
status: Fix Released → In Progress
Revision history for this message
Robert Collins (lifeless) wrote :

381. 3656 5423ms SQL-main-slave

SELECT COUNT(*)..

dooms it - 5.4 second query 3.6 seconds in.

I haven't got an explain analyze for the count yet.

Revision history for this message
William Grant (wgrant) wrote :

This is probably bug #901122 and bug #901124. Try with the beta listings disabled.

Revision history for this message
Robert Collins (lifeless) wrote :

Those bugs certainly contribute but a 5.4 second count @ 3.6 seconds is itself a problem - thats 9 seconds right there. It may be we're doing eager loading, as you say. setting a batch limit of 1 should eliminate that.

summary: - Timeout on Distribution:+bugs
+ Timeout on Distribution:+bugs searching by bug supervisor
Revision history for this message
Robert Collins (lifeless) wrote :

Recent explain of the issue http://explain.depesz.com/s/CQn

Revision history for this message
Robert Collins (lifeless) wrote :

Note the table scan in the middle - this is probably because pg thinks we are going to get 34K rows back.

OOPS with the originally filed URL: OOPS-3c75f2462717713eeb8f9e07f3800664

Shows the count being 3.5 seconds and run twice. So wgrants reference to other bugs is correct. I'm going to close this bug and open a new one for the case spamaps was running into.

Changed in launchpad:
status: In Progress → Fix Released
description: updated
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.