Merge lp:~rvb/launchpad/activereviews-bug-867941 into lp:launchpad

[Raphaël Badin]

[incr] [r=allenap][bug=867941] Eager load stuff to improve the performance of a person's activereviews page.

This branch addresses one of the problems of code.lp.net/~user/+activereviews: the huge number of queries issued by this page (1000+ for pages like https://code.launchpad.net/~ubuntu-branches/+activereviews). It does this by eager loading the relevant data (the related branches & users mainly).

= Tests =

./bin/test -vvc test_branchmergeproposallisting test_activereviews_query_count

= Q/A =

This page issues a lot of queries:
qastaging: [678+, 807+, 1068+, 939+, 1056+, 1140+]
prod: [1405, 849+, 777+, 1034+, 639+, 1382+]
(a '+' next to the number means that the whole page timed out and thus the number of queries is not accurate)

[Raphaël Badin (rvb)]

Something weird is going on here; if I change:

recorder1 = self.createBMPsAndMeasureActiveReviewsPageRendering(3)
recorder2 = self.createBMPsAndMeasureActiveReviewsPageRendering(7)

to:

recorder1 = self.createBMPsAndMeasureActiveReviewsPageRendering(3)
recorder2 = self.createBMPsAndMeasureActiveReviewsPageRendering(70)

Then the number of queries does not match. The extra queries are the one needed to get branch.{_associatedProductSeries, _associatedSuiteSourcePackages} which is exactly what _preloadDataForBranches populates.

This needs investigation…

[Gavin Panella (allenap)]

Nice. However, I think [2] must be resolved, so Needs Fixing. [3] is
just a suggestion which you're welcome to ignore.

[1]

+ transaction.commit()

I don't think this is needed.

[2]

+ with StormStatementRecorder() as recorder:
+ view = create_initialized_view(
+ user, name='+activereviews', rootsite='code',
+ principal=user)
+ view.render()

I discovered (as discussed on IRC) that calling view.initialize()
twice causes the test to pass with number_of_bmps values of >= 14. I
did it by changing view.render() to view(). I have not a clue why this
makes a difference, but it seems like a promising avenue for discovery.
I think this issue must be resolved before landing this branch.

[3]

+ def test_activereviews_query_count(self):
+ recorder1 = self.createBMPsAndMeasureActiveReviewsPageRendering(3)
+ recorder2 = self.createBMPsAndMeasureActiveReviewsPageRendering(7)
+ self.assertThat(recorder2, HasQueryCount(Equals(recorder1.count)))

While trying to debug [2] I noticed that recorder1's statements are
not reported when it fails.

I added the following line to solve that:

    self.addDetail("r1tb", Content(UTF8_TEXT, lambda: [str(recorder1)]))

This also has the advantage that tracebacks recorded are also shown. I
think _MismatchedQueryCount do something similar. Its get_details()
method could be changed to:

    def get_details(self):
        return {
            'queries': Content(
                UTF8_TEXT, lambda: [
                    unicode(self.query_collector).encode("utf8")]),
            }

[4]

+ # Load the registrants' data.
+ load_related(Person, rows, ['registrantID'])
+ # Cache registrants' info (Person and ValidPersonCache).
+ list(self.store.find(
+ (Person, ValidPersonCache),
+ ValidPersonCache.id == Person.id,
+ Person.id.is_in([proposal.registrantID for proposal in rows]),
+ ))
[...]
+ load_related(Person, source_branches, ['ownerID'])

Consider using IPersonSet.getPrecachedPersonsFromIDs() instead here:

    person_ids = set().union(
        (proposal.registrantID for proposal in rows),
        (branch.ownerID for branch in source_branches))
    getUtility(IPersonSet).getPrecachedPersonsFromIDs(
        person_ids, need_validity=True, ...)

review: Needs Fixing

[Raphaël Badin (rvb)]

> [1]

Right.

> [2]
>
> + with StormStatementRecorder() as recorder:
> + view = create_initialized_view(
> + user, name='+activereviews', rootsite='code',
> + principal=user)
> + view.render()
>
> I discovered (as discussed on IRC) that calling view.initialize()
> twice causes the test to pass with number_of_bmps values of >= 14. I
> did it by changing view.render() to view(). I have not a clue why this
> makes a difference, but it seems like a promising avenue for discovery.
> I think this issue must be resolved before landing this branch.

Damn!

> [3]
>
> + def test_activereviews_query_count(self):
> + recorder1 = self.createBMPsAndMeasureActiveReviewsPageRendering(3)
> + recorder2 = self.createBMPsAndMeasureActiveReviewsPageRendering(7)
> + self.assertThat(recorder2, HasQueryCount(Equals(recorder1.count)))
>
> While trying to debug [2] I noticed that recorder1's statements are
> not reported when it fails.
>
> I added the following line to solve that:
>
> self.addDetail("r1tb", Content(UTF8_TEXT, lambda: [str(recorder1)]))

I've added that.

> [4]

One less query \o/.

[Raphaël Badin (rvb)]

= A description of the problem =

The cache for branch._associatedSuiteSourcePackages is populated by _preloadDataForBranches but the cache disappears somehow.

My only idea was to think that maybe there is a cache maximum set somewhere but I can't find one and Gavin says he does not know about such a maximum.

= Queries issued when separating source/target branches =

I tried separating the queries issued to populate the source and the target branches:
self._preloadDataForBranches(target_branches + source_branches) => self._preloadDataForBranches(source_branches) self._preloadDataForBranches(target_branches)

These are the queries for SeriesSourcePackageBranch issued in this case:
http://paste.ubuntu.com/740270/

We can see that all the data is pre fetched and then some of the data is fetched again one branch at a time as if the cache for _associatedSuiteSourcePackages has been cleared; debugging confirms this.

= Calling initialize twice =

Gavin found out that calling initialize twice "fixes" the problem.

These are the queries for SeriesSourcePackageBranch issued in this case:
http://paste.ubuntu.com/740275/

[Raphaël Badin (rvb)]

Ah ah, thanks to jtv's expertise I've found that the problem was indeed a cache size problem. This fixes the problem:

=== modified file 'configs/development/launchpad-lazr.conf'
--- configs/development/launchpad-lazr.conf 2011-10-18 09:25:12 +0000
+++ configs/development/launchpad-lazr.conf 2011-11-17 09:02:41 +0000
@@ -157,7 +157,7 @@
 geoip_database: /usr/share/GeoIP/GeoLiteCity.dat
 geonames_identity: lpdev
 storm_cache: generational
-storm_cache_size: 100
+storm_cache_size: 10000

So I'll keep the numbers of bmp created small to have the test pass even with the default storm_cache_size.

[Gavin Panella (allenap)]

Lovely :)

review: Approve

=== modified file 'lib/lp/code/browser/tests/test_branchmergeproposallisting.py'
--- lib/lp/code/browser/tests/test_branchmergeproposallisting.py	2011-08-26 06:33:22 +0000
+++ lib/lp/code/browser/tests/test_branchmergeproposallisting.py	2011-11-17 12:35:25 +0000
@@ -8,9 +8,13 @@
 from datetime import datetime
 
 import pytz
+from testtools.content import Content
+from testtools.content_type import UTF8_TEXT
+from testtools.matchers import Equals
 import transaction
 from zope.security.proxy import removeSecurityProxy
 
+from canonical.database.sqlbase import flush_database_caches
 from canonical.launchpad.webapp.servers import LaunchpadTestRequest
 from canonical.testing.layers import DatabaseFunctionalLayer
 from lp.code.browser.branchmergeproposallisting import (
@@ -29,8 +33,10 @@
     login,
     login_person,
     person_logged_in,
+    StormStatementRecorder,
     TestCaseWithFactory,
     )
+from lp.testing.matchers import HasQueryCount
 from lp.testing.views import create_initialized_view
 
 
@@ -377,3 +383,57 @@
             view = create_initialized_view(
                 branch, name='+activereviews', rootsite='code')
             self.assertEqual([mp], list(view.getProposals()))
+
+
+class PersonActiveReviewsPerformance(TestCaseWithFactory):
+    """Test the performance of the person's active reviews page."""
+
+    layer = DatabaseFunctionalLayer
+
+    def createBMP(self, reviewer=None, target_branch_owner=None):
+        target_branch = None
+        if target_branch_owner is not None:
+            target_branch = self.factory.makeProductBranch(
+                owner=target_branch_owner)
+        bmp = self.factory.makeBranchMergeProposal(
+            reviewer=reviewer,
+            target_branch=target_branch)
+        login_person(bmp.source_branch.owner)
+        bmp.requestReview()
+        return bmp
+
+    def createBMPsAndRecordQueries(self, number_of_bmps):
+        # Create {number_of_bmps} branch merge proposals related to a
+        # user, render the person's +activereviews page and return the
+        # view and a recorder of the queries generated by this page
+        # rendering.
+        user = self.factory.makePerson()
+        for i in xrange(number_of_bmps):
+            # Create one of the two types of BMP which will be displayed
+            # on a person's +activereviews page:
+            # - A BMP for which the person is the reviewer.
+            # - A BMP for which the person is the owner of the target
+            # branch.
+            if i % 2 == 0:
+                self.createBMP(target_branch_owner=user)
+            else:
+                self.createBMP(reviewer=user)
+        login_person(user)
+        flush_database_caches()
+        with StormStatementRecorder() as recorder:
+            view = create_initialized_view(
+                user, name='+activereviews', rootsite='code',
+                principal=user)
+            view.render()
+        return recorder, view
+
+    def test_activereviews_query_count(self):
+        # Note that we keep the number of bmps created small (3 and 7)
+        # so that the all the per-cached objects will fit into the cache
+        # used in tests (storm_cache_size: 100).
+        recorder1, view1 = self.createBMPsAndRecordQueries(3)
+        self.assertEqual(3, view1.proposal_count)
+        self.addDetail("r1tb", Content(UTF8_TEXT, lambda: [str(recorder1)]))
+        recorder2, view2 = self.createBMPsAndRecordQueries(7)
+        self.assertEqual(7, view2.proposal_count)
+        self.assertThat(recorder2, HasQueryCount(Equals(recorder1.count)))

=== modified file 'lib/lp/code/model/branchcollection.py'
--- lib/lp/code/model/branchcollection.py	2011-11-01 08:17:57 +0000
+++ lib/lp/code/model/branchcollection.py	2011-11-17 12:35:25 +0000
@@ -69,6 +69,7 @@
     PreviewDiff,
     )
 from lp.code.model.seriessourcepackagebranch import SeriesSourcePackageBranch
+from lp.registry.interfaces.person import IPersonSet
 from lp.registry.model.distribution import Distribution
 from lp.registry.model.distroseries import DistroSeries
 from lp.registry.model.person import (
@@ -400,7 +401,24 @@
         # limited by the defined collection.
         owned = self.ownedBy(person).getMergeProposals(status)
         reviewing = self.getMergeProposalsForReviewer(person, status)
-        return owned.union(reviewing)
+        resultset = owned.union(reviewing)
+
+        def do_eager_load(rows):
+            source_branches = load_related(Branch, rows, ['source_branchID'])
+            # Cache person's data (registrants of the proposal and
+            # owners of the source branches).
+            person_ids = set().union(
+                (proposal.registrantID for proposal in rows),
+                (branch.ownerID for branch in source_branches))
+            list(getUtility(IPersonSet).getPrecachedPersonsFromIDs(
+                person_ids, need_validity=True))
+            # Load the source/target branches and preload the data for
+            # these branches.
+            target_branches = load_related(Branch, rows, ['target_branchID'])
+            self._preloadDataForBranches(target_branches + source_branches)
+            load_related(Product, target_branches, ['productID'])
+
+        return DecoratedResultSet(resultset, pre_iter_hook=do_eager_load)
 
     def getMergeProposalsForReviewer(self, reviewer, status=None):
         """See `IBranchCollection`."""