launchpad-dev team mailing list archive

[John Arbash Meinel <john@xxxxxxxxxxxxxxxxx>]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 1/25/2011 9:22 PM, Robert Collins wrote:
> 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 :)

To summarize (so I'm sure I understood what your point is):

  Function cost is not clearly identified in EXPLAIN [ANALYZE] queries,
  so be on the lookout for them.

  If they are the overhead, you can probably look into caching the
  result. (even generating it as an ON INSERT trigger?)

  Going a step further and improving the query selectivity by
  specialized indexes can be difficult, especially when that index
  would need to apply across tables.

> 
> 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,
...
> 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)


^- What is really confusing (for me) here is that the Sort Key is listed
as part of the outer Sort call, which is actually quite cheap (12539.243
- - 12539.223 = 0.02ms), but the Hash Join is where the function is
actually getting called. I also really wonder why the outer Sort claims
it is going to need to look at 56,248 rows, but the actual rows is only
76. That seems like a really bad estimate.

I can sort of see how 'this key is applied to this method', but at least
in my head the costly key stuff would be underneath the method.
(Thinking like lsprof layout.)

If Postgresql just assigned how much time it spent calling the Sort Key,
this probably would have been easier to notice, but I don't know what
that would take for them to implement.

>                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.

I'm a bit confused by your comments here. I think the reason the sort
key isn't visible as a time consumer is because Postgres doesn't assign
time to the actual function. It only sees from the outer position. I
started doing a top-N heapsort at this time, and finished it at this
time. (Which happened to be using this function as the sort key.)

You don't really know if "top-N heapsort" is the expensive part (because
it had so many rows to sort relative to eachother), or if the Sort Key
was the overhead (because it was so expensive to evaluate each row.)

> 
> 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.

I think here you switched topics, and changed to focusing on how could
we get the whole result from a very specific indexed query?

> 
> 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)
> 

^- I think you're formatting lost something here. It looks like you were
trying to indent something?

I don't see how the "but we want to skip all the other archives" applies
to "debversion_sort_key(binarypackagerelease.version)".

I can't say that I fully understand everything going on here, but is it
possible to define a global ordering?

> 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
> 

Anyway, I think this was interesting, but I'm not sure I followed all of
it. I really don't understand the "binarypackagesort_key" that you are
describing here. It may just be misunderstanding how the tables interrelate.

John
=:->
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAk1ATdUACgkQJdeBCYSNAANppACgyRdepq2Yh3TNNVaH9ulxgFFz
PCoAn2DvteHq8O3+V0qQRwFo77c0vRaH
=lvI4
-----END PGP SIGNATURE-----