Launchpad itself

timeout on code.launchpad.net/~ubuntu-branches

Bug #1031764 reported by John A Meinel on 2012-08-01

This bug affects 3 people

Affects		Status	Importance	Assigned to	Milestone
	Launchpad itself	Fix Released	Critical	William Grant

Bug Description

OOPS-5f256222ff8c758238414f93587ad1eb

This is exceeding the 5s default cap on page timeouts. It is spending >5s in SQL, with these primary culprits:

1978.0 1 SQL-main-slave

SELECT BranchMergeProposal.commit_message,
       BranchMergeProposal.date_created,
       BranchMergeProposal.date_merged,
       BranchMergeProposal.date_queued,
       BranchMergeProposal.date_review_requested,
       BranchMergeProposal.date_reviewed,
       BranchMergeProposal.description,
       BranchMergeProposal.id,
       BranchMergeProposal.merge_reporter,
       BranchMergeProposal.merged_revno,
       BranchMergeProposal.dependent_branch,
       BranchMergeProposal.merge_diff,
       BranchMergeProposal.queue_position,
       BranchMergeProposal.queue_status,
       BranchMergeProposal.queued_revision_id,
       BranchMergeProposal.queuer,
       BranchMergeProposal.registrant,
       BranchMergeProposal.reviewed_revision_id,
       BranchMergeProposal.reviewer,
       BranchMergeProposal.root_message_id,
       BranchMergeProposal.source_branch,
       BranchMergeProposal.superseded_by,
       BranchMergeProposal.target_branch,
       BranchMergeProposal.whiteboard
FROM Branch
JOIN BranchMergeProposal ON Branch.id = BranchMergeProposal.source_branch
AND Branch.OWNER = $INT
JOIN Branch AS target ON target.id = BranchMergeProposal.target_branch
WHERE (Branch.information_type IN ($INT, $INT)
  OR COALESCE((Branch.access_grants)&&
    (SELECT ARRAY_AGG(TeamParticipation.team)
     FROM TeamParticipation
     WHERE TeamParticipation.person = $INT), FALSE)
  OR Branch.access_policy IN
    (SELECT AccessPolicyGrant.policy
     FROM AccessPolicyGrant
     JOIN TeamParticipation ON TeamParticipation.team = AccessPolicyGrant.grantee
     WHERE TeamParticipation.person = $INT))
  AND (target.information_type IN ($INT, $INT)
  OR COALESCE((target.access_grants)&&
    (SELECT ARRAY_AGG(TeamParticipation.team)
     FROM TeamParticipation
     WHERE TeamParticipation.person = $INT), FALSE)
  OR target.access_policy IN
    (SELECT AccessPolicyGrant.policy
     FROM AccessPolicyGrant
     JOIN TeamParticipation ON TeamParticipation.team = AccessPolicyGrant.grantee
     WHERE TeamParticipation.person = $INT))
  AND BranchMergeProposal.source_branch IN ($INT ... $INT)
ORDER BY BranchMergeProposal.date_created DESC, BranchMergeProposal.id

^- This appears to be trying to see if there are any merge proposals for the branches being shown.

There are only 100 branch_ids in the "BranchMergeProposal.source_branch in ..." section. Which doesn't seem terrible. Though the question still remains why the individual query is that slow.

1217.0 2 SQL-main-slave

SELECT Branch.access_policy,
       Branch.branch_format,
       Branch.branch_type,
       Branch.metadir_format,
       Branch.date_created,
       Branch.date_last_modified,
       Branch.summary,
       Branch.distroseries,
       Branch.id,
       Branch.information_type,
       Branch.last_mirror_attempt,
       Branch.last_mirrored,
       Branch.last_mirrored_id,
       Branch.last_scanned,
       Branch.last_scanned_id,
       Branch.lifecycle_status,
       Branch.merge_queue_config,
       Branch.merge_queue,
       Branch.mirror_failures,
       Branch.mirror_status_message,
       Branch.name,
       Branch.next_mirror_time,
       Branch.OWNER, Branch.owner_name,
                     Branch.product,
                     Branch.registrant,
                     Branch.repository_format,
                     Branch.reviewer,
                     Branch.revision_count,
                     Branch.sourcepackagename,
                     Branch.stacked_on,
                     Branch.target_suffix,
                     Branch.unique_name,
                     Branch.url,
                     Branch.whiteboard
FROM Branch
WHERE Branch.OWNER = $INT
  AND Branch.lifecycle_status IN ($INT ... $INT)
  AND (Branch.information_type IN ($INT, $INT)
  OR COALESCE((Branch.access_grants)&&
    (SELECT ARRAY_AGG(TeamParticipation.team)
     FROM TeamParticipation
     WHERE TeamParticipation.person = $INT), FALSE)
  OR Branch.access_policy IN
    (SELECT AccessPolicyGrant.policy
     FROM AccessPolicyGrant
     JOIN TeamParticipation ON TeamParticipation.team = AccessPolicyGrant.grantee
     WHERE TeamParticipation.person = $INT))
ORDER BY Branch.date_last_modified DESC, Branch.target_suffix ASC, Branch.lifecycle_status DESC, Branch.owner_name ASC, Branch.name ASC LIMIT $INT
OFFSET $INT

^- One key issue of this request, is that it is being requested 2 times. (The average is 1217s, but both times are close to that.)

Looking at the actual queries, the content is, indeed, identical, so we should be caching the results of the first query, and not issuing a second one.

Note that it does appear to be a data-dependent issue, as https://code.launchpad.net/~jameinel takes 2.81s (with 100/142 possible branches shown, and /850 if you select 'any status').

I wonder if there is an index that could be put for the ORDER BY so that it can return the LIMIT + OFFSET without having to read all 100k+ branches for ~ubuntu-branches.
It could be that this is a regression because of the changes for privacy.

See original description

Tags:

Related branches

lp:~wgrant/launchpad/bug-1007140

Merged into lp:launchpad at revision 15935

Curtis Hovey (community): Approve (code) on 2012-09-11

John A Meinel (jameinel) on 2012-08-01

description:	updated
description:	updated

Revision history for this message

John A Meinel (jameinel) wrote on 2012-08-01:

Download full text (7.0 KiB)

On staging, for the first query, it returns 0 rows, but still takes 1200ms to execute. It would seem we should be filtering in a different order. EXPLAIN ANALYZE gives:
 Sort  (cost=95124.34..95124.52 rows=71 width=785) (actual time=1555.036..1555.036 rows=0 loops=1)
   Sort Key: branchmergeproposal.date_created, branchmergeproposal.id
   Sort Method: quicksort  Memory: 25kB
   InitPlan 1 (returns $0)
     ->  Aggregate  (cost=59.47..59.48 rows=1 width=4) (never executed)
           ->  Index Scan using teamparticipation_person_idx on teamparticipation  (cost=0.00..59.34 rows=51 width=4) (never executed)
                 Index Cond: (person = 10583)
   InitPlan 3 (returns $2)
     ->  Aggregate  (cost=59.47..59.48 rows=1 width=4) (actual time=0.360..0.361 rows=1 loops=1)
           ->  Index Scan using teamparticipation_person_idx on teamparticipation  (cost=0.00..59.34 rows=51 width=4) (actual time=0.029..0.283 rows=120 loops=1)
                 Index Cond: (person = 10583)
   ->  Hash Join  (cost=91145.54..95003.19 rows=71 width=785) (actual time=1555.024..1555.024 rows=0 loops=1)
         Hash Cond: (branchmergeproposal.target_branch = target.id)
         ->  Hash Join  (cost=44836.77..46503.17 rows=72 width=785) (actual time=0.296..0.296 rows=0 loops=1)
               Hash Cond: (branchmergeproposal.source_branch = branch.id)
               ->  Bitmap Heap Scan on branchmergeproposal  (cost=178.91..377.49 rows=110 width=785) (actual time=0.293..0.293 rows=0 loops=1)
                     Recheck Cond: (source_branch = ANY ('{642702,594960,642701,642699,642698,642697,626259,627638,612893,608781,642661,605468,591171,642609,642611,642610,642607,642606,642605,642601,642600,642599,567823,642598,642597,642596,642595,642594,642593,642591,642590,642589,642588,642587,642586,642585,642584,615804,642583,618044,618397,642580,642579, 614466,294897,631531,597979,145586,626091,641863,631530,184187,379944,350369,205826,642550,642547,612682,110462,305784,612846,412005,598022,642525,614325,642287,597972,611905,120004,642506,542770,456310,363093,613279,637525,614713,455168,637532,602879,607321,597781,610894,631529,615237,605684,615280,598021,105569,130730,605092,614295,615277,615274,621997,291172,642394,642392,642391,599195,352385}'::integer[]))
                     ->  Bitmap Index Scan on branchmergeproposal__source_branch__idx  (cost=0.00..178.88 rows=110 width=0) (actual time=0.289..0.289 rows=0 loops=1)
                           Index Cond: (source_branch = ANY ('{642702,594960,642701,642699,642698,642697,626259,627638,612893,608781,642661,605468,591171,642609,642611,642610,642607,642606,642605,642601,642600,642599,567823,642598,642597,642596,642595,642594,642593,642591,642590,642589,642588,642587,642586,642585,642584,615804,642583,618044,618397,642580,642579,614466,294897,631531,597979,145586,626091,641863,631530,184187,379944,350369,205826,642550,642547,612682,110462,305784,612846,412005,598022,642525,614325,642287,597972,611905,120004,642506,542770,456310,363093,613279,637525,614713,455168,637532,602879,607321,597781,610894,631529,615237,605684,615280,598021,105569,130730,605092,614295,615277,615274,621997,291172,642394,642392,642391,599195,352385}'::integer[]))
               ->  Hash  (cost=38593.59..38593.59 rows=369622 width=4) (never executed)
                     ->  Seq Scan on branch  (cost=3245.05..38593.59 rows=369622 width=4) (never executed)
                           Filter: ((owner = 2866082) AND ((information_type = ANY ('{1,2}'::integer[])) OR COALESCE((access_grants && $0), false) OR (hashed SubPlan 2)))
                           SubPlan 2
                             ->  Hash Join  (cost=2167.74..3245.04 rows=6 width=4) (never executed)
                                   Hash Cond: (public.teamparticipation.team = public.accesspolicygrant.grantee)
                                   ->  Index Scan using teamparticipation_person_idx on teamparticipation  (cost=0.00..59.34 rows=51 width=4) (never executed)
                                         Index Cond: (person = 10583)
                                   ->  Hash  (cost=1229.55..1229.55 rows=75055 width=8) (never executed)
                                         ->  Seq Scan on accesspolicygrant  (cost=0.00..1229.55 rows=75055 width=8) (never executed)
         ->  Hash  (cost=37180.78..37180.78 rows=556319 width=4) (actual time=1549.799..1549.799 rows=543710 loops=1)
               Buckets: 32768  Batches: 4  Memory Usage: 4820kB
               ->  Seq Scan on branch target  (cost=3245.05..37180.78 rows=556319 width=4) (actual time=0.023..1259.048 rows=543710 loops=1)
                     Filter: ((information_type = ANY ('{1,2}'::integer[])) OR COALESCE((access_grants && $2), false) OR (hashed SubPlan 4))
                     SubPlan 4
                       ->  Hash Join  (cost=2167.74..3245.04 rows=6 width=4) (actual time=81.948..86.522 rows=6145 loops=1)
                             Hash Cond: (public.teamparticipation.team = public.accesspolicygrant.grantee)
                             ->  Index Scan using teamparticipation_person_idx on teamparticipation  (cost=0.00..59.34 rows=51 width=4) (actual time=0.012..0.307 rows=120 loops=1)
                                   Index Cond: (person = 10583)
                             ->  Hash  (cost=1229.55..1229.55 rows=75055 width=8) (actual time=81.856..81.856 rows=75059 loops=1)
                                   Buckets: 8192  Batches: 1  Memory Usage: 2932kB
                                   ->  Seq Scan on accesspolicygrant  (cost=0.00..1229.55 rows=75055 width=8) (actual time=0.012..36.818 rows=75059 loops=1)
 Total runtime: 1555.384 ms
(42 rows)

If I'm reading it correctly, all of the time is spent here:
         Hash Cond: (branchmergeproposal.target_branch = target.id)
...
         ->  Hash  (cost=37180.78..37180.78 rows=556319 width=4) (actual time=1549.799..1549.799 rows=543710 loops=1)
               Buckets: 32768  Batches: 4  Memory Usage: 4820kB
               ->  Seq Scan on branch target  (cost=3245.05..37180.78 rows=556319 width=4) (actual time=0.023..1259.048 rows=543710 loops=1)
                     Filter: ((information_type = ANY ('{1,2}'::integer[])) OR COALESCE((access_grants && $2), false) OR (hashed SubPlan 4))
                     SubPlan 4

That appears to be just a bad plan, since it seems to think that reading all branch ids into a hash map, and then using that to filter against the branchmergeproposals is a good query. Rather than getting the list of branchmergeproposals that match the source_id, and then filtering against the branch's to get the target info.

This could be the regression, since it seems to be trying to filter out merge proposals that have a target that is not visible, but it doing so by joining against a sequential scan of *all* possible branches.

It is possible we only see this for ~ubuntu-branches because it potentially has far more branches at the source, and the query planner isn't noticing that the IN (100 branches) is going to filter things out much faster.

I'm guessing the query just needs to be explicitly rewritten so that it finds the BMPs first, and then filters by target-not-visible second.

Revision history for this message

John A Meinel (jameinel) wrote on 2012-08-01:

For the second query, it takes ~1200ms on staging as well. The query planner says:
Limit (cost=50118.35..50118.60 rows=101 width=830) (actual time=1304.710..1304.751 rows=101 loops=1)
   InitPlan 1 (returns $0)
     -> Aggregate (cost=59.47..59.48 rows=1 width=4) (never executed)
           -> Index Scan using teamparticipation_person_idx on teamparticipation (cost=0.00..59.34 rows=51 width=4) (never executed)
                 Index Cond: (person = 10583)
   -> Sort (cost=50058.86..50669.06 rows=244079 width=830) (actual time=1304.707..1304.725 rows=101 loops=1)
         Sort Key: branch.date_last_modified, branch.target_suffix, branch.lifecycle_status, branch.owner_name, branch.name
         Sort Method: top-N heapsort Memory: 77kB
         -> Seq Scan on branch (cost=3245.05..40712.82 rows=244079 width=830) (actual time=0.027..782.749 rows=373887 loops=1)
               Filter: ((owner = 2866082) AND (lifecycle_status = ANY ('{10,30,50}'::integer[])) AND ((information_type = ANY ('{1,2}'::integer[])) OR COALESCE((access_grants && $0), false) OR (hashed SubPlan 2)))
               SubPlan 2
                 -> Hash Join (cost=2167.74..3245.04 rows=6 width=4) (never executed)
                       Hash Cond: (public.teamparticipation.team = accesspolicygrant.grantee)
                       -> Index Scan using teamparticipation_person_idx on teamparticipation (cost=0.00..59.34 rows=51width=4) (never executed)
                             Index Cond: (person = 10583)
                       -> Hash (cost=1229.55..1229.55 rows=75055 width=8) (never executed)
                             -> Seq Scan on accesspolicygrant (cost=0.00..1229.55 rows=75055 width=8) (never executed)
Total runtime: 1304.974 ms
(18 rows)

That also shows the expensive part being:
-> Seq Scan on branch (cost=3245.05..40712.82 rows=244079 width=830) (actual time=0.027..782.749 rows=373887 loops=1)

So it is starting with a sequential scan of all 370k branches, it then creates a 100 node bucket, which as it finds nodes 'newer' than what is in the bucket, it puts them in there, caveat the following hash join (which never executes for some reason).

Now, maybe this is actually reasonable for ~ubuntu-branches. By my count, there are 562,000 branches, and according to this query, 373,887 of them are part of ~ubuntu-branches. That is far more than the standard >10% => full-table-scan.

Note that part of the query:
launchpad_staging=> select count(*) from branch where lifecycle_status in (10,30,50) and (information_type in (1,2));
count
--------
455713

Since it does need so much information, but it is filtering from 300k rows down to 100. It feels like having an index on those exact fields would help a lot here.

I can't create an actual index to test it, but something like:
CREATE INDEX CONCURRENTLY branch_recent_branches_idx ON Branch(date_last_modified DESC, target_suffix ASC, lifecycle_status DESC, owner_name ASC, name ASC);

For the second query, it takes ~1200ms on staging as well. The query planner says:
 Limit  (cost=50118.35..50118.60 rows=101 width=830) (actual time=1304.710..1304.751 rows=101 loops=1)
   InitPlan 1 (returns $0)
     ->  Aggregate  (cost=59.47..59.48 rows=1 width=4) (never executed)
           ->  Index Scan using teamparticipation_person_idx on teamparticipation  (cost=0.00..59.34 rows=51 width=4) (never executed)
                 Index Cond: (person = 10583)
   ->  Sort  (cost=50058.86..50669.06 rows=244079 width=830) (actual time=1304.707..1304.725 rows=101 loops=1)
         Sort Key: branch.date_last_modified, branch.target_suffix, branch.lifecycle_status, branch.owner_name, branch.name
         Sort Method: top-N heapsort  Memory: 77kB
         ->  Seq Scan on branch  (cost=3245.05..40712.82 rows=244079 width=830) (actual time=0.027..782.749 rows=373887 loops=1)
               Filter: ((owner = 2866082) AND (lifecycle_status = ANY ('{10,30,50}'::integer[])) AND ((information_type = ANY ('{1,2}'::integer[])) OR COALESCE((access_grants && $0), false) OR (hashed SubPlan 2)))
               SubPlan 2
                 ->  Hash Join  (cost=2167.74..3245.04 rows=6 width=4) (never executed)
                       Hash Cond: (public.teamparticipation.team = accesspolicygrant.grantee)
                       ->  Index Scan using teamparticipation_person_idx on teamparticipation  (cost=0.00..59.34 rows=51width=4) (never executed)
                             Index Cond: (person = 10583)
                       ->  Hash  (cost=1229.55..1229.55 rows=75055 width=8) (never executed)
                             ->  Seq Scan on accesspolicygrant  (cost=0.00..1229.55 rows=75055 width=8) (never executed)
 Total runtime: 1304.974 ms
(18 rows)

That also shows the expensive part being:
         ->  Seq Scan on branch  (cost=3245.05..40712.82 rows=244079 width=830) (actual time=0.027..782.749 rows=373887 loops=1)

So it is starting with  a sequential scan of all 370k branches, it then creates a 100 node bucket, which as it finds nodes 'newer' than what is in the bucket, it puts them in there, caveat the following hash join (which never executes for some reason).

Note that part of the query:
launchpad_staging=> select count(*) from branch where lifecycle_status in (10,30,50) and (information_type in (1,2));
 count
--------
 455713

Since it does need so much information, but it is filtering from 300k rows down to 100. It feels like having an index on those exact fields would help a lot here.

Revision history for this message

Daniel Holbach (dholbach) wrote on 2012-08-09:

<wgrant> dholbach: Bug #1029642 is probably the one you actually care about

Curtis Hovey (sinzui) on 2012-08-16

tags:

removed: oops

Revision history for this message

Francis J. Lacoste (flacoste) wrote on 2012-08-17:

The hard timeout on this page was increased to 9s to alleviate this issue.

William Grant (wgrant) on 2012-09-10

Changed in launchpad:
assignee:	nobody → William Grant (wgrant)
status:	Triaged → In Progress

Revision history for this message

William Grant (wgrant) wrote on 2012-09-11:

Apart from the core branch queries, the query to find MPs for the current batch of branches is slow for the same reason as bug #1007140, and the same fix works: https://pastebin.canonical.com/74194/ https://pastebin.canonical.com/74196/

Revision history for this message

Launchpad QA Bot (lpqabot) wrote on 2012-09-12:

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

tags:	added: qa-needstesting
Changed in launchpad:
status:	In Progress → Fix Committed

William Grant (wgrant) on 2012-09-12

tags:

added: qa-ok
removed: qa-needstesting

Revision history for this message

William Grant (wgrant) wrote on 2012-09-12:

It's still not good, but it's now reliably ~4s.

Changed in launchpad:
assignee:	William Grant (wgrant) → nobody
status:	Fix Committed → In Progress
assignee:	nobody → William Grant (wgrant)
status:	In Progress → Fix Released