launchpad-dev team mailing list archive

[Robert Collins <robertc@xxxxxxxxxxxxxxxxx>]

I found an interesting cause for a slow query in the weekend and
thought I'd share it as the first in a resurrected Performance Tuesday
mail. I found this interesting because the query plan was a little
opaque to read, and I had a couple of dead ends analyzing it - so it
may help folk doing slow query analysis a little if I write this up.
I'm sure our SQL gods will have no surprises here :)

It all starts with https://bugs.launchpad.net/launchpad/+bug/706200.
This bug reports a (slightly crackful) API script timing out.

The OOPS reveals a 15 second query:

15003.0	1	SQL-launchpad-main-master
SELECT BinaryPackagePublishingHistory.archive,
BinaryPackagePublishingHistory.binarypackagerelease,
BinaryPackagePublishingHistory.component,
BinaryPackagePublishingHistory.datecreated,
BinaryPackagePublishingHistory.datemadepending,
BinaryPackagePublishingHistory.datepublished,
BinaryPackagePublishingHistory.dateremoved,
BinaryPackagePublishingHistory.datesuperseded,
BinaryPackagePublishingHistory.distroarchseries,
BinaryPackagePublishingHistory.id,
BinaryPackagePublishingHistory.pocket,
BinaryPackagePublishingHistory.priority,
BinaryPackagePublishingHistory.removal_comment,
BinaryPackagePublishingHistory.removed_by,
BinaryPackagePublishingHistory.scheduleddeletiondate,
BinaryPackagePublishingHistory.section,
BinaryPackagePublishingHistory.status,
BinaryPackagePublishingHistory.supersededby
FROM BinaryPackageName, BinaryPackagePublishingHistory, BinaryPackageRelease
WHERE BinaryPackagePublishingHistory.archive = 2034
  AND BinaryPackagePublishingHistory.binarypackagerelease =
BinaryPackageRelease.id
  AND BinaryPackageRelease.binarypackagename = BinaryPackageName.id
  AND (1=1)
ORDER BY BinaryPackageName.name,
debversion_sort_key(BinaryPackageRelease.VERSION) DESC,
BinaryPackagePublishingHistory.id DESC LIMIT 76
OFFSET 0

With the following query plan on qastaging (after allowing for cold disk cache):
                 QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit (cost=361303.95..361304.14 rows=76 width=163) (actual
time=12539.225..12539.275 rows=76 loops=1)
   -> Sort (cost=361303.95..361444.57 rows=56248 width=163) (actual
time=12539.223..12539.243 rows=76 loops=1)
         Sort Key: binarypackagename.name,
(debversion_sort_key(binarypackagerelease.version)),
binarypackagepublishinghistory.id
         Sort Method: top-N heapsort Memory: 46kB
         -> Hash Join (cost=5140.97..359265.54 rows=56248 width=163)
(actual time=228.492..12402.625 rows=55469 loops=1)
               Hash Cond: (binarypackagerelease.binarypackagename =
binarypackagename.id)
               -> Nested Loop (cost=902.15..339628.83 rows=56248
width=142) (actual time=19.106..716.124 rows=55469 loops=1)
                     -> Bitmap Heap Scan on
binarypackagepublishinghistory (cost=902.15..96928.16 rows=56248
width=117) (actual time=19.075..94.576 rows=55469 loops=1)
                           Recheck Cond: (archive = 2034)
                           -> Bitmap Index Scan on
securebinarypackagepublishinghistory__archive__status__idx
(cost=0.00..888.09 rows=56248 width=0) (actual time=15.623..15.623
rows=55469 loops=1)
                                 Index Cond: (archive = 2034)
                     -> Index Scan using binarypackage_pkey on
binarypackagerelease (cost=0.00..4.30 rows=1 width=29) (actual
time=0.008..0.009 rows=1 loops=55469)
                           Index Cond: (binarypackagerelease.id =
binarypackagepublishinghistory.binarypackagerelease)
               -> Hash (cost=2470.03..2470.03 rows=141503 width=29)
(actual time=208.698..208.698 rows=141503 loops=1)
                     -> Seq Scan on binarypackagename
(cost=0.00..2470.03 rows=141503 width=29) (actual time=0.014..73.582
rows=141503 loops=1)
 Total runtime: 12539.594 ms

(reminder: when ready an explain analyze, the 'cost' is a arbitrary
metric, the 'time' is in milliseconds, and the x..y mean 'starting at
x and continuing until y'

If you look at the query, you can see a function call in the ORDER BY
clause: we call debversion_sort_key(binarypackagerelease.version).
However this sort key isn't visible as a time consumer in the query
plan.

There are three reasons it might not be visible: it might be that we
can determine the order from an index, which saves evaluation of the
entire result set (queries that can do this are generally extremely
fast and efficient); or it may be that its not a significant time, or
its just unclear.

In this case the latter applies: the function call is actually the
dominating factor for this query. Here's how to break it down.

Firstly, note that the order by is coming from three different tables
- this means we would need to traverse several different indices to
generate the ordering by index. There are 140K package names in the
system, and 55K history rows for archive 2304 (see the row counts in
the plan). So postgresql is choosing to start with the 55K history
rows rather than the package names.

What indices would we need to generate the results incrementally? Well
we'd need :
 - binarypackagename.name (indexed),
 - debversion_sort_key(binarypackagerelease.version)  - but we want to
skip all the other archives so it probably needs to be a composite
index:
 - binarypackagepublishinghistory.archive,
debversion_sort_key(binarypackagerelease.version,
-binarypackagepublishinghistory.id) - which we cannot do because that
is across two different tables.
   (if we index bpph.archive, bpph.binarypackagerelease the sort order
of binarypackagerelease will be a simple int: useless for our needs)

So back to the plan - this is the bit that actually shows the cost:

         -> Hash Join (cost=5140.97..359265.54 rows=56248 width=163)
(actual time=228.492..12402.625 rows=55469 loops=1)

all the subordinate steps finish very early. I suspect that the
functional call to debversion_sort_key() is happening as part of
building the larger intermediate table (55K rows long).

What we can easily do now is to add a cached version of the sort key,
which lets postgresql serve this in 800ms. What we should do when
we're a little further down the path is figure out how to calculate
the order directly out of index, so that we can serve it in 100ms.

For instance, one way we might do that is to build an index on
binarypackagesort_key(binarypackagepublishinghistory.binarypackagerelease)
- where binarypackagesort_key looks up the binarypackagerelease record
and its debversion_sort_key : in principle we can build an index which
can be served from, letting postgresql not calculate the function at
all except when given < or > operators in queries.

-Rob