DistroSeries:+queue timeouts when filtering by package name

Bug #802335 reported by Scott Kitterman
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Launchpad itself
Fix Released
Critical
Jeroen T. Vermeulen

Bug Description

(Error ID: OOPS-2004CG9) on the +queue page just trying to search for packages by name.
https://lp-oops.canonical.com/oops.py/?oopsid=2004CG9

https://launchpad.net/ubuntu/oneiric/+queue?queue_state=0&queue_text=qt

25. 183 8876ms SQL-launchpad-main-slave
SELECT DISTINCT PackageUpload.archive,
                PackageUpload.changesfile,
                PackageUpload.date_created,
                PackageUpload.distroseries,
                PackageUpload.id,
                PackageUpload.package_copy_job,
                PackageUpload.pocket,
                PackageUpload.signing_key,
                PackageUpload.status
FROM PackageUpload
LEFT JOIN PackageCopyJob ON PackageCopyJob.id = PackageUpload.package_copy_job
LEFT JOIN SourcePackageName ON SourcePackageName.name LIKE '%qt%' ESCAPE '!'
LEFT JOIN PackageUploadSource ON PackageUploadSource.packageupload = PackageUpload.id
LEFT JOIN SourcePackageRelease ON SourcePackageRelease.id = PackageUploadSource.sourcepackagerelease
LEFT JOIN BinaryPackageName ON BinaryPackageName.name LIKE '%qt%' ESCAPE '!'
LEFT JOIN PackageUploadBuild ON PackageUploadBuild.packageupload = PackageUpload.id
LEFT JOIN BinaryPackageRelease ON BinaryPackageRelease.build = PackageUploadBuild.build
LEFT JOIN PackageUploadCustom ON PackageUploadCustom.packageupload = PackageUpload.id
LEFT JOIN LibraryFileAlias ON LibraryFileAlias.id = PackageUploadCustom.libraryfilealias
WHERE PackageUpload.distroseries = 107
  AND PackageUpload.status IN (0)
  AND PackageUpload.archive IN (1, 534)
  AND (PackageCopyJob.package_name LIKE '%qt%' ESCAPE '!'
       OR SourcePackageRelease.sourcepackagename = SourcePackageName.id
       OR BinaryPackageRelease.binarypackagename = BinaryPackageName.id
       OR LibraryFileAlias.filename LIKE '%qt%' ESCAPE '!')
ORDER BY PackageUpload.id DESC LIMIT 31
OFFSET 0

explains (from prod master):
cold:

 Limit (cost=8766663.29..8766663.37 rows=31 width=40) (actual time=101074.967..101074.970 rows=6 loops=1)
   -> Sort (cost=8766663.29..8766664.07 rows=311 width=40) (actual time=101074.967..101074.968 rows=6 loops=1)
         Sort Key: packageupload.id
         Sort Method: quicksort Memory: 25kB
         -> HashAggregate (cost=8766650.92..8766654.03 rows=311 width=40) (actual time=101074.918..101074.926 rows=6 loops=1)
               -> Nested Loop Left Join (cost=4329.30..7591609.41 rows=52224067 width=40) (actual time=5523.307..54459.843 rows=71048692 loops=1)
                     Filter: ((packagecopyjob.package_name ~~ '%qt%'::text) OR (sourcepackagerelease.sourcepackagename = sourcepackagename.id) OR (binarypackagerelease.binarypackagename = binarypackagename.id) OR (libraryfilealias.filename ~~ '%qt%'::text))
                     -> Nested Loop Left Join (cost=824.37..14437.08 rows=225810 width=125) (actual time=0.473..90.740 rows=90315 loops=1)
                           -> Nested Loop Left Join (cost=0.00..9096.51 rows=1158 width=121) (actual time=0.339..38.187 rows=405 loops=1)
                                 -> Nested Loop Left Join (cost=0.00..6958.54 rows=328 width=121) (actual time=0.266..4.979 rows=62 loops=1)
                                       -> Nested Loop Left Join (cost=0.00..5581.32 rows=328 width=84) (actual time=0.264..4.472 rows=62 loops=1)
                                             -> Nested Loop Left Join (cost=0.00..4462.72 rows=315 width=80) (actual time=0.218..3.514 rows=62 loops=1)
                                                   -> Nested Loop Left Join (cost=0.00..3245.52 rows=311 width=76) (actual time=0.155..2.432 rows=62 loops=1)
                                                         -> Nested Loop Left Join (cost=0.00..3138.63 rows=311 width=44) (actual time=0.154..2.325 rows=62 loops=1)
                                                               -> Nested Loop Left Join (cost=0.00..1921.03 rows=311 width=44) (actual time=0.152..2.129 rows=62 loops=1)
                                                                     -> Index Scan using packageupload__distroseries__status__idx on packageupload (cost=0.00..749.77 rows=311 width=40) (actual time=0.103..1.050 rows=62 loops=1)
                                                                           Index Cond: ((distroseries = 107) AND (status = 0))
                                                                           Filter: (archive = ANY ('{1,534}'::integer[]))
                                                                     -> Index Scan using packageuploadsource__packageupload__key on packageuploadsource (cost=0.00..3.75 rows=1 width=8) (actual time=0.016..0.016 rows=0 loops=62)
                                                                           Index Cond: (packageuploadsource.packageupload = packageupload.id)
                                                               -> Index Scan using sourcepackagerelease_pkey on sourcepackagerelease (cost=0.00..3.90 rows=1 width=8) (actual time=0.002..0.002 rows=0 loops=62)
                                                                     Index Cond: (sourcepackagerelease.id = packageuploadsource.sourcepackagerelease)
                                                         -> Index Scan using packagecopyjob_pkey on packagecopyjob (cost=0.00..0.33 rows=1 width=36) (actual time=0.000..0.000 rows=0 loops=62)
                                                               Index Cond: (packagecopyjob.id = packageupload.package_copy_job)
                                                   -> Index Scan using distroreleasequeuebuild__distroreleasequeue__build__unique on packageuploadbuild (cost=0.00..3.90 rows=1 width=8) (actual time=0.015..0.016 rows=1 loops=62)
                                                         Index Cond: (packageuploadbuild.packageupload = packageupload.id)
                                             -> Index Scan using packageuploadcustom__packageupload__idx on packageuploadcustom (cost=0.00..3.54 rows=1 width=8) (actual time=0.014..0.014 rows=0 loops=62)
                                                   Index Cond: (packageuploadcustom.packageupload = packageupload.id)
                                       -> Index Scan using libraryfilealias_pkey on libraryfilealias (cost=0.00..4.19 rows=1 width=45) (actual time=0.007..0.007 rows=0 loops=62)
                                             Index Cond: (libraryfilealias.id = packageuploadcustom.libraryfilealias)
                                 -> Index Scan using binarypackagerelease_build_idx on binarypackagerelease (cost=0.00..6.42 rows=8 width=8) (actual time=0.469..0.531 rows=7 loops=62)
                                       Index Cond: (binarypackagerelease.build = packageuploadbuild.build)
                           -> Materialize (cost=824.37..826.32 rows=195 width=4) (actual time=0.000..0.057 rows=223 loops=405)
                                 -> Seq Scan on sourcepackagename (cost=0.00..824.18 rows=195 width=4) (actual time=0.130..11.103 rows=223 loops=1)
                                       Filter: (name ~~ '%qt%'::text)
                     -> Materialize (cost=3504.93..3516.11 rows=1118 width=4) (actual time=0.000..0.112 rows=1114 loops=90315)
                           -> Seq Scan on binarypackagename (cost=0.00..3503.81 rows=1118 width=4) (actual time=0.254..43.726 rows=1114 loops=1)
                                 Filter: (name ~~ '%qt%'::text)
 Total runtime: 101075.483 ms

hot:

 Limit (cost=8766663.29..8766663.37 rows=31 width=40) (actual time=100988.048..100988.051 rows=6 loops=1)
   -> Sort (cost=8766663.29..8766664.07 rows=311 width=40) (actual time=100988.048..100988.049 rows=6 loops=1)
         Sort Key: packageupload.id
         Sort Method: quicksort Memory: 25kB
         -> HashAggregate (cost=8766650.92..8766654.03 rows=311 width=40) (actual time=100988.029..100988.031 rows=6 loops=1)
               -> Nested Loop Left Join (cost=4329.30..7591609.41 rows=52224067 width=40) (actual time=5507.490..53809.347 rows=71048692 loops=1)
                     Filter: ((packagecopyjob.package_name ~~ '%qt%'::text) OR (sourcepackagerelease.sourcepackagename = sourcepackagename.id) OR (binarypackagerelease.binarypackagename = binarypackagename.id) OR (libraryfilealias.filename ~~ '%qt%'::text))
                     -> Nested Loop Left Join (cost=824.37..14437.08 rows=225810 width=125) (actual time=0.323..57.966 rows=90315 loops=1)
                           -> Nested Loop Left Join (cost=0.00..9096.51 rows=1158 width=121) (actual time=0.214..9.477 rows=405 loops=1)
                                 -> Nested Loop Left Join (cost=0.00..6958.54 rows=328 width=121) (actual time=0.099..4.951 rows=62 loops=1)
                                       -> Nested Loop Left Join (cost=0.00..5581.32 rows=328 width=84) (actual time=0.098..3.986 rows=62 loops=1)
                                             -> Nested Loop Left Join (cost=0.00..4462.72 rows=315 width=80) (actual time=0.086..2.516 rows=62 loops=1)
                                                   -> Nested Loop Left Join (cost=0.00..3245.52 rows=311 width=76) (actual time=0.072..1.810 rows=62 loops=1)
                                                         -> Nested Loop Left Join (cost=0.00..3138.63 rows=311 width=44) (actual time=0.071..1.710 rows=62 loops=1)
                                                               -> Nested Loop Left Join (cost=0.00..1921.03 rows=311 width=44) (actual time=0.068..1.541 rows=62 loops=1)
                                                                     -> Index Scan using packageupload__distroseries__status__idx on packageupload (cost=0.00..749.77 rows=311 width=40) (actual time=0.053..0.973 rows=62 loops=1)
                                                                           Index Cond: ((distroseries = 107) AND (status = 0))
                                                                           Filter: (archive = ANY ('{1,534}'::integer[]))
                                                                     -> Index Scan using packageuploadsource__packageupload__key on packageuploadsource (cost=0.00..3.75 rows=1 width=8) (actual time=0.007..0.007 rows=0 loops=62)
                                                                           Index Cond: (packageuploadsource.packageupload = packageupload.id)
                                                               -> Index Scan using sourcepackagerelease_pkey on sourcepackagerelease (cost=0.00..3.90 rows=1 width=8) (actual time=0.001..0.001 rows=0 loops=62)
                                                                     Index Cond: (sourcepackagerelease.id = packageuploadsource.sourcepackagerelease)
                                                         -> Index Scan using packagecopyjob_pkey on packagecopyjob (cost=0.00..0.33 rows=1 width=36) (actual time=0.000..0.000 rows=0 loops=62)
                                                               Index Cond: (packagecopyjob.id = packageupload.package_copy_job)
                                                   -> Index Scan using distroreleasequeuebuild__distroreleasequeue__build__unique on packageuploadbuild (cost=0.00..3.90 rows=1 width=8) (actual time=0.009..0.010 rows=1 loops=62)
                                                         Index Cond: (packageuploadbuild.packageupload = packageupload.id)
                                             -> Index Scan using packageuploadcustom__packageupload__idx on packageuploadcustom (cost=0.00..3.54 rows=1 width=8) (actual time=0.022..0.023 rows=0 loops=62)
                                                   Index Cond: (packageuploadcustom.packageupload = packageupload.id)
                                       -> Index Scan using libraryfilealias_pkey on libraryfilealias (cost=0.00..4.19 rows=1 width=45) (actual time=0.014..0.014 rows=0 loops=62)
                                             Index Cond: (libraryfilealias.id = packageuploadcustom.libraryfilealias)
                                 -> Index Scan using binarypackagerelease_build_idx on binarypackagerelease (cost=0.00..6.42 rows=8 width=8) (actual time=0.033..0.069 rows=7 loops=62)
                                       Index Cond: (binarypackagerelease.build = packageuploadbuild.build)
                           -> Materialize (cost=824.37..826.32 rows=195 width=4) (actual time=0.000..0.050 rows=223 loops=405)
                                 -> Seq Scan on sourcepackagename (cost=0.00..824.18 rows=195 width=4) (actual time=0.097..8.999 rows=223 loops=1)
                                       Filter: (name ~~ '%qt%'::text)
                     -> Materialize (cost=3504.93..3516.11 rows=1118 width=4) (actual time=0.000..0.111 rows=1114 loops=90315)
                           -> Seq Scan on binarypackagename (cost=0.00..3503.81 rows=1118 width=4) (actual time=0.199..42.633 rows=1114 loops=1)
                                 Filter: (name ~~ '%qt%'::text)
 Total runtime: 100989.058 ms

Related branches

Changed in launchpad:
status: New → Triaged
importance: Undecided → Critical
tags: added: timeout
Revision history for this message
Robert Collins (lifeless) wrote :

I'm marking this as a regression because the poor plan is (AFAICT) due to the new packagecopyjob).

tags: added: regression
summary: - Timeout on +queue page when searching for packages by name
+ DistroSeries:+queue timeouts when filtering by package name
description: updated
tags: added: derivation
Revision history for this message
Jeroen T. Vermeulen (jtv) wrote :

I'm exchanging the left-join conditions (on name pattern) for the name match with their "where" conditions (on id/FK match). That gives me 3 orders of magnitude of improvement on the example query.

Changed in launchpad:
status: Triaged → In Progress
assignee: nobody → Jeroen T. Vermeulen (jtv)
Revision history for this message
Jeroen T. Vermeulen (jtv) wrote :

My apologies; I miscalculated. I'm getting 4 orders of magnitude, not 3. My branch is ready for review.

Revision history for this message
Launchpad QA Bot (lpqabot) wrote :
tags: added: qa-needstesting
Changed in launchpad:
status: In Progress → Fix Committed
tags: added: qa-ok
removed: qa-needstesting
Steve Kowalik (stevenk)
Changed in launchpad:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

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