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 _______________________________________________ Mailing list: https://launchpad.net/~launchpad-dev Post to : [email protected] Unsubscribe : https://launchpad.net/~launchpad-dev More help : https://help.launchpad.net/ListHelp
