Launchpad itself

Bug #1031764
Comment #1

Comment 1 for bug 1031764

Revision history for this message

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

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.

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

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.