Bug #1921727 “Error 503 when trying to iterate over lp.people[te...” : Bugs : Launchpad itself

Marcus Tomlinson (marcustomlinson) on 2021-03-29

description:

updated

Revision history for this message

Paweł Stołowski (stolowski) wrote on 2021-03-30:

#1

I'm seeing this a lot as well (on snapd project).

Revision history for this message

Colin Watson (cjwatson) wrote on 2021-03-30:

#2

Quoting the OOPS ID inline here so that oops-tools knows not to garbage-collect it: OOPS-1f3bc04ee184e988ae1d2f8ba056352a

Revision history for this message

Colin Watson (cjwatson) wrote on 2021-03-30:

#3

Download full text (17.3 KiB)

I think this query tipped over the edge of a performance cliff. Query plan on staging:

                                                                                                         QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=744282.38..744599.49 rows=76 width=3123) (actual time=125.687..125.848 rows=76 loops=1)
   Buffers: shared hit=37477
   -> Result (cost=743343.57..746552.22 rows=769 width=3123) (actual time=125.231..125.818 rows=301 loops=1)
         Buffers: shared hit=37477
         -> Sort (cost=743343.57..743345.49 rows=769 width=3122) (actual time=102.384..102.426 rows=301 loops=1)
               Sort Key: (person_sort_key(person.displayname, person.name))
               Sort Method: top-N heapsort Memory: 534kB
               Buffers: shared hit=36818
               -> Nested Loop Left Join (cost=693.97..743308.07 rows=769 width=3122) (actual time=0.324..97.048 rows=1025 loops=1)
                     Buffers: shared hit=36818
                     -> Nested Loop Left Join (cost=693.40..740651.59 rows=769 width=2983) (actual time=0.231..65.660 rows=1025 loops=1)
                           Buffers: shared hit=35537
                           -> Nested Loop Left Join (cost=692.83..738187.36 rows=769 width=2876) (actual time=0.218..62.725 rows=1025 loops=1)
                                 Buffers: shared hit=34650
                                 -> Nested Loop Left Join (cost=692.39..735921.14 rows=769 width=2771) (actual time=0.204..55.545 rows=1025 loops=1)
                                       Buffers: shared hit=30558
                                       -> Nested Loop Left Join (cost=691.96..733660.46 rows=769 width=2730) (actual time=0.190..48.301 rows=1025 loops=1)
                                             Buffers: shared hit=26459
                                             -> Nested Loop Left Join (cost=1.57..8142.33 rows=769 width=1073) (actual time=0.065..21.633 rows=1025 loops=1)
                                                   Buffers: shared hit=10896
                                                   -> Nested Loop Left Join (cost=1.15..5891.74 rows=769 width=1012) (actual time=0.054..16.892 rows=1025 loops=1)
                                                         Buffers: shared hit=7413
                                                         -> Nested Loop (cost=0.86..3765.18 rows=769 width=1000) (actual time=0.045..13.046 rows=1025 loops=1)
                                                               Buffers: shared hit=5132
                                                               -> Index Only Scan using teamparticipation_team_key on teamparticipation (cost=0.43..681.33 rows=769 width=4) (actual time=0.034..3.791 rows=1025 loops=1)
                                                                     Index Cond: (team = 2962068)
                                                                     Filter: (person <> 2962068)
                                        ...

I think this query tipped over the edge of a performance cliff.  Query plan on staging:

QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=744282.38..744599.49 rows=76 width=3123) (actual time=125.687..125.848 rows=76 loops=1)
   Buffers: shared hit=37477
   ->  Result  (cost=743343.57..746552.22 rows=769 width=3123) (actual time=125.231..125.818 rows=301 loops=1)
         Buffers: shared hit=37477
         ->  Sort  (cost=743343.57..743345.49 rows=769 width=3122) (actual time=102.384..102.426 rows=301 loops=1)
               Sort Key: (person_sort_key(person.displayname, person.name))
               Sort Method: top-N heapsort  Memory: 534kB
               Buffers: shared hit=36818
               ->  Nested Loop Left Join  (cost=693.97..743308.07 rows=769 width=3122) (actual time=0.324..97.048 rows=1025 loops=1)
                     Buffers: shared hit=36818
                     ->  Nested Loop Left Join  (cost=693.40..740651.59 rows=769 width=2983) (actual time=0.231..65.660 rows=1025 loops=1)
                           Buffers: shared hit=35537
                           ->  Nested Loop Left Join  (cost=692.83..738187.36 rows=769 width=2876) (actual time=0.218..62.725 rows=1025 loops=1)
                                 Buffers: shared hit=34650
                                 ->  Nested Loop Left Join  (cost=692.39..735921.14 rows=769 width=2771) (actual time=0.204..55.545 rows=1025 loops=1)
                                       Buffers: shared hit=30558
                                       ->  Nested Loop Left Join  (cost=691.96..733660.46 rows=769 width=2730) (actual time=0.190..48.301 rows=1025 loops=1)
                                             Buffers: shared hit=26459
                                             ->  Nested Loop Left Join  (cost=1.57..8142.33 rows=769 width=1073) (actual time=0.065..21.633 rows=1025 loops=1)
                                                   Buffers: shared hit=10896
                                                   ->  Nested Loop Left Join  (cost=1.15..5891.74 rows=769 width=1012) (actual time=0.054..16.892 rows=1025 loops=1)
                                                         Buffers: shared hit=7413
                                                         ->  Nested Loop  (cost=0.86..3765.18 rows=769 width=1000) (actual time=0.045..13.046 rows=1025 loops=1)
                                                               Buffers: shared hit=5132
                                                               ->  Index Only Scan using teamparticipation_team_key on teamparticipation  (cost=0.43..681.33 rows=769 width=4) (actual time=0.034..3.791 rows=1025 loops=1)
                                                                     Index Cond: (team = 2962068)
                                                                     Filter: (person <> 2962068)
                                                                     Rows Removed by Filter: 1
                                                                     Heap Fetches: 1026
                                                                     Buffers: shared hit=1026
                                                               ->  Index Scan using person_pkey on person  (cost=0.43..4.01 rows=1 width=1000) (actual time=0.007..0.007 rows=1 loops=1025)
                                                                     Index Cond: (id = teamparticipation.person)
                                                                     Buffers: shared hit=4106
                                                         ->  Index Scan using karmatotalcache_person_key on karmatotalcache  (cost=0.29..2.77 rows=1 width=12) (actual time=0.003..0.003 rows=0 loops=1025)
                                                               Index Cond: (person = person.id)
                                                               Buffers: shared hit=2281
                                                   ->  Index Scan using personlocation_person_key on personlocation  (cost=0.42..2.93 rows=1 width=61) (actual time=0.003..0.003 rows=0 loops=1025)
                                                         Index Cond: (person = person.id)
                                                         Buffers: shared hit=3483
                                             ->  Bitmap Heap Scan on archive  (cost=690.39..943.45 rows=1 width=1657) (actual time=0.022..0.022 rows=0 loops=1025)
                                                   Recheck Cond: ((id IS NULL) OR (id = (SubPlan 3)))
                                                   Filter: ((id IS NULL) OR ((owner = person.id) AND (id = (SubPlan 3))))
                                                   Heap Blocks: exact=355
                                                   Buffers: shared hit=15563
                                                   ->  BitmapOr  (cost=690.39..690.39 rows=1 width=0) (actual time=0.016..0.016 rows=0 loops=1025)
                                                         Buffers: shared hit=10682
                                                         ->  Bitmap Index Scan on archive_pkey  (cost=0.00..2.24 rows=1 width=0) (actual time=0.003..0.003 rows=0 loops=1025)
                                                               Index Cond: (id IS NULL)
                                                               Buffers: shared hit=3075
                                                         ->  Bitmap Index Scan on archive_pkey  (cost=0.00..252.92 rows=1 width=0) (actual time=0.001..0.001 rows=0 loops=1025)
                                                               Index Cond: (id = (SubPlan 3))
                                                               Buffers: shared hit=1070
                                                               SubPlan 3
                                                                 ->  Aggregate  (cost=251.23..251.24 rows=1 width=4) (actual time=0.010..0.010 rows=1 loops=1380)
                                                                       Buffers: shared hit=11063
                                                                       ->  Index Scan using archive__owner__idx on archive archive_1  (cost=0.43..250.68 rows=220 width=4) (actual time=0.004..0.008 rows=5 loops=1380)
                                                                             Index Cond: (owner = person.id)
                                                                             Filter: (purpose = 2)
                                                                             Rows Removed by Filter: 0
                                                                             Buffers: shared hit=11063
                                       ->  Index Scan using emailaddress__person__key on emailaddress  (cost=0.43..2.94 rows=1 width=41) (actual time=0.005..0.005 rows=1 loops=1025)
                                             Index Cond: (person = person.id)
                                             Buffers: shared hit=4099
                                 ->  Index Scan using account_pkey on account  (cost=0.43..2.95 rows=1 width=105) (actual time=0.005..0.005 rows=1 loops=1025)
                                       Index Cond: (person.account = id)
                                       Filter: (status = 20)
                                       Rows Removed by Filter: 0
                                       Buffers: shared hit=4092
                           ->  Index Scan using libraryfilealias_pkey on libraryfilealias logoalias  (cost=0.57..3.20 rows=1 width=107) (actual time=0.001..0.001 rows=0 loops=1025)
                                 Index Cond: (person.logo = id)
                                 Buffers: shared hit=887
                     ->  Index Scan using libraryfilealias_pkey on libraryfilealias mugshotalias  (cost=0.57..3.20 rows=1 width=107) (actual time=0.001..0.001 rows=0 loops=1025)
                           Index Cond: (person.mugshot = id)
                           Buffers: shared hit=1281
         SubPlan 1
           ->  Index Scan using signedcodeofconduct_owner_idx on signedcodeofconduct  (cost=0.29..3.91 rows=1 width=0) (never executed)
                 Index Cond: (owner = person.id)
                 Filter: (active AND (datecreated >= '2005-04-12 00:00:00'::timestamp without time zone))
         SubPlan 2
           ->  Seq Scan on signedcodeofconduct signedcodeofconduct_1  (cost=0.00..1267.29 rows=43586 width=4) (actual time=0.010..10.793 rows=43590 loops=1)
                 Filter: (active AND (datecreated >= '2005-04-12 00:00:00'::timestamp without time zone))
                 Rows Removed by Filter: 5073
                 Buffers: shared hit=659
 Planning time: 11.854 ms
 Execution time: 126.380 ms
(85 rows)

But on production:

QUERY PLAN                                                                                                   
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=1096148.82..1465991.78 rows=76 width=3213) (actual time=3652.795..5153.540 rows=76 loops=1)
   Buffers: shared hit=7105311 read=3
   ->  Nested Loop Left Join  (cost=1218.99..5042762.55 rows=1036 width=3213) (actual time=56.251..5153.436 rows=301 loops=1)
         Buffers: shared hit=7105311 read=3
         ->  Nested Loop Left Join  (cost=1218.42..5038043.49 rows=1036 width=3073) (actual time=38.982..5123.359 rows=301 loops=1)
               Buffers: shared hit=7103840 read=3
               ->  Nested Loop Left Join  (cost=1217.85..5036390.99 rows=1036 width=2966) (actual time=38.968..5122.285 rows=301 loops=1)
                     Buffers: shared hit=7103590 read=3
                     ->  Nested Loop Left Join  (cost=1217.42..5035903.52 rows=1036 width=2860) (actual time=38.942..5119.745 rows=301 loops=1)
                           Buffers: shared hit=7102387 read=2
                           ->  Nested Loop Left Join  (cost=1216.99..5035431.46 rows=1036 width=2819) (actual time=38.917..5117.139 rows=301 loops=1)
                                 Buffers: shared hit=7101183
                                 ->  Nested Loop Left Join  (cost=1.83..3298215.27 rows=1036 width=1181) (actual time=38.845..5108.736 rows=301 loops=1)
                                       Buffers: shared hit=7096663
                                       ->  Nested Loop Left Join  (cost=1.41..3297761.49 rows=1036 width=1120) (actual time=38.813..5106.704 rows=301 loops=1)
                                             Buffers: shared hit=7095646
                                             ->  Nested Loop  (cost=0.99..3297309.65 rows=1036 width=1108) (actual time=38.779..5104.634 rows=301 loops=1)
                                                   Buffers: shared hit=7094642
                                                   ->  Index Scan using person_sorting_idx on person  (cost=0.56..337572.74 rows=6448068 width=1108) (actual time=0.019..2011.398 rows=1768842 loops=1)
                                                         Buffers: shared hit=1782167
                                                   ->  Index Only Scan using teamparticipation_team_key on teamparticipation  (cost=0.43..0.46 rows=1 width=4) (actual time=0.002..0.002 rows=0 loops=1768842)
                                                         Index Cond: ((team = 2962068) AND (person = person.id))
                                                         Filter: (person <> 2962068)
                                                         Rows Removed by Filter: 0
                                                         Heap Fetches: 21
                                                         Buffers: shared hit=5312475
                                             ->  Index Scan using karmatotalcache_person_key on karmatotalcache  (cost=0.42..0.44 rows=1 width=12) (actual time=0.005..0.005 rows=0 loops=301)
                                                   Index Cond: (person = person.id)
                                                   Buffers: shared hit=1004
                                       ->  Index Scan using personlocation_person_key on personlocation  (cost=0.42..0.44 rows=1 width=61) (actual time=0.005..0.005 rows=0 loops=301)
                                             Index Cond: (person = person.id)
                                             Buffers: shared hit=1017
                                 ->  Bitmap Heap Scan on archive  (cost=1215.16..1676.84 rows=1 width=1638) (actual time=0.023..0.024 rows=0 loops=301)
                                       Recheck Cond: ((id IS NULL) OR (id = (SubPlan 3)))
                                       Filter: ((id IS NULL) OR ((owner = person.id) AND (id = (SubPlan 3))))
                                       Heap Blocks: exact=109
                                       Buffers: shared hit=4520
                                       ->  BitmapOr  (cost=1215.16..1215.16 rows=1 width=0) (actual time=0.018..0.018 rows=0 loops=301)
                                             Buffers: shared hit=3109
                                             ->  Bitmap Index Scan on archive_pkey  (cost=0.00..1.64 rows=1 width=0) (actual time=0.003..0.003 rows=0 loops=301)
                                                   Index Cond: (id IS NULL)
                                                   Buffers: shared hit=903
                                             ->  Bitmap Index Scan on archive_pkey  (cost=0.00..460.90 rows=1 width=0) (actual time=0.002..0.002 rows=0 loops=301)
                                                   Index Cond: (id = (SubPlan 3))
                                                   Buffers: shared hit=328
                                                   SubPlan 3
                                                     ->  Aggregate  (cost=460.45..460.46 rows=1 width=4) (actual time=0.010..0.010 rows=1 loops=410)
                                                           Buffers: shared hit=3180
                                                           ->  Index Scan using archive__owner__idx on archive archive_1  (cost=0.43..458.93 rows=610 width=4) (actual time=0.005..0.008 rows=5 loops=410)
                                                                 Index Cond: (owner = person.id)
                                                                 Filter: (purpose = 2)
                                                                 Rows Removed by Filter: 0
                                                                 Buffers: shared hit=3180
                           ->  Index Scan using emailaddress__person__key on emailaddress  (cost=0.43..0.46 rows=1 width=41) (actual time=0.007..0.007 rows=1 loops=301)
                                 Index Cond: (person = person.id)
                                 Buffers: shared hit=1204 read=2
                     ->  Index Scan using account_pkey on account  (cost=0.43..0.47 rows=1 width=106) (actual time=0.006..0.006 rows=1 loops=301)
                           Index Cond: (person.account = id)
                           Filter: (status = 20)
                           Buffers: shared hit=1203 read=1
               ->  Index Scan using libraryfilealias_pkey on libraryfilealias logoalias  (cost=0.57..1.60 rows=1 width=107) (actual time=0.002..0.002 rows=0 loops=301)
                     Index Cond: (person.logo = id)
                     Buffers: shared hit=250
         ->  Index Scan using libraryfilealias_pkey on libraryfilealias mugshotalias  (cost=0.57..1.60 rows=1 width=107) (actual time=0.002..0.002 rows=0 loops=301)
               Index Cond: (person.mugshot = id)
               Buffers: shared hit=400
         SubPlan 1
           ->  Index Scan using signedcodeofconduct_owner_idx on signedcodeofconduct  (cost=0.29..2.71 rows=1 width=0) (never executed)
                 Index Cond: (owner = person.id)
                 Filter: (active AND (datecreated >= '2005-04-12 00:00:00'::timestamp without time zone))
         SubPlan 2
           ->  Seq Scan on signedcodeofconduct signedcodeofconduct_1  (cost=0.00..1727.11 rows=47012 width=4) (actual time=0.018..9.002 rows=43597 loops=1)
                 Filter: (active AND (datecreated >= '2005-04-12 00:00:00'::timestamp without time zone))
                 Rows Removed by Filter: 5076
                 Buffers: shared hit=1071
 Planning time: 19.045 ms
 Execution time: 5154.020 ms
(77 rows)

Notice that instead of sorting at the end (i.e. near the outside of the plan structure), the inner loop starts by doing a slow index scan of person_sorting_idx, and then looking through that for team membership.  This is much slower than staging's approach of scanning teamparticipation_team_key first and selecting only Person rows that match that.  PostgreSQL's cost analysis here is apparently somewhat wrong.

Since we know that team membership is highly selective when compared with scanning the whole Person table, we should be able to lift that out into a CTE to force PostgreSQL to do that bit first.  I'm waiting for a sysadmin to confirm that for me on production.

Changed in launchpad:
status:	New → In Progress
importance:	Undecided → Critical
assignee:	nobody → Colin Watson (cjwatson)
tags:	added: lp-registry oops timeout

Colin Watson (cjwatson) on 2021-03-31

Changed in launchpad:
status:	In Progress → Fix Committed

Colin Watson (cjwatson) on 2021-04-01

Changed in launchpad:
status:	Fix Committed → Fix Released

Revision history for this message

Marcus Tomlinson (marcustomlinson) wrote on 2021-04-01:

#4

Excellent, thanks for that! I can confirm this is now working.

Launchpad itself

Error 503 when trying to iterate over lp.people[team].participants

Bug Description

Related branches

Other bug subscribers

Remote bug watches