Merge ~twom/launchpad:stats-request-timings into launchpad:master

[Tom Wardill]

Add traversal and publication duration timings

Use the existing duration timing mechanisms, but output to statsd as well.

[Colin Watson (cjwatson)]

This would probably be a lot more useful if we added a tag with the pageid too - could you add that?

bfe59f2... by Tom Wardill on 2020-09-08

Add publication timings with pageid

[Tom Wardill (twom)]

> This would probably be a lot more useful if we added a tag with the pageid too
> - could you add that?

We don't have pageid in the traversal timings as it's too early, but we do in the publication timings which I've just added.

[Colin Watson (cjwatson)]

I'd really like to see some kind of test for this.

I don't think there's a strong reason we couldn't move the calculation of launchpad.pageid to afterTraversal; logically we should have everything we need for that as soon as traversal is complete. Maybe worth a try?

review: Approve

96347f1... by Tom Wardill on 2020-09-22

Move pageid calculation to afterTraversal

1210f6c... by Tom Wardill on 2020-09-22

Add test

[Colin Watson (cjwatson)]

Could we have a test for each of the failed-traversal and failed-publication cases too? Otherwise this LGTM.

review: Approve

[Colin Watson (cjwatson)]

Also the commit message on this MP is a bit incomplete now; maybe "Add traversal and publication duration timings"?

37e5303... by Tom Wardill on 2020-09-23

Add tests for failed traversal and failed publication

diff --git a/lib/lp/services/webapp/publication.py b/lib/lp/services/webapp/publication.py
index a289f44..b76eec7 100644
--- a/lib/lp/services/webapp/publication.py
+++ b/lib/lp/services/webapp/publication.py
@@ -427,13 +427,8 @@ class LaunchpadBrowserPublication(
         request.setInWSGIEnvironment(
             'launchpad.userid', request.principal.id)
 
-        # The view may be security proxied
-        view = removeSecurityProxy(ob)
-        # It's possible that the view is a bound method.
-        view = getattr(view, '__self__', view)
-        context = removeSecurityProxy(getattr(view, 'context', None))
-        pageid = self.constructPageID(view, context)
-        request.setInWSGIEnvironment('launchpad.pageid', pageid)
+        # pageid is calculated at `afterTraversal`
+        pageid = request._orig_env['launchpad.pageid']
         # And spit the pageid out to our tracelog.
         tracelog(request, 'p', pageid)
 
@@ -485,6 +480,11 @@ class LaunchpadBrowserPublication(
             publication_thread_duration = None
         request.setInWSGIEnvironment(
             'launchpad.publicationduration', publication_duration)
+        # Update statsd, timing is in milliseconds
+        getUtility(IStatsdClient).timing(
+            'publication_duration,success=True,pageid={}'.format(
+                request._orig_env.get('launchpad.pageid')),
+            publication_duration * 1000)
 
         # Calculate SQL statement statistics.
         sql_statements = da.get_request_statements()
@@ -562,12 +562,24 @@ class LaunchpadBrowserPublication(
         # Log the URL including vhost information to the ZServer tracelog.
         tracelog(request, 'u', request.getURL())
 
+        # The view may be security proxied
+        view = removeSecurityProxy(ob)
+        # It's possible that the view is a bound method.
+        view = getattr(view, '__self__', view)
+        context = removeSecurityProxy(getattr(view, 'context', None))
+        pageid = self.constructPageID(view, context)
+        request.setInWSGIEnvironment('launchpad.pageid', pageid)
+
         assert hasattr(request, '_traversal_start'), (
             'request._traversal_start, which should have been set by '
             'beforeTraversal(), was not found.')
         traversal_duration = time.time() - request._traversal_start
         request.setInWSGIEnvironment(
             'launchpad.traversalduration', traversal_duration)
+        # Update statsd, timing is in milliseconds
+        getUtility(IStatsdClient).timing(
+            'traversal_duration,success=True,pageid={}'.format(pageid),
+            traversal_duration * 1000)
         if request._traversal_thread_start is not None:
             traversal_thread_duration = (
                 _get_thread_time() - request._traversal_thread_start)
@@ -600,6 +612,11 @@ class LaunchpadBrowserPublication(
             publication_duration = now - request._publication_start
             request.setInWSGIEnvironment(
                 'launchpad.publicationduration', publication_duration)
+            # Update statsd, timing is in milliseconds
+            getUtility(IStatsdClient).timing(
+                'publication_duration,success=False,pageid={}'.format(
+                    request._orig_env.get('launchpad.pageid')),
+                publication_duration * 1000)
             if thread_now is not None:
                 publication_thread_duration = (
                     thread_now - request._publication_thread_start)
@@ -612,6 +629,11 @@ class LaunchpadBrowserPublication(
             traversal_duration = now - request._traversal_start
             request.setInWSGIEnvironment(
                 'launchpad.traversalduration', traversal_duration)
+            # Update statsd, timing is in milliseconds
+            getUtility(IStatsdClient).timing(
+                'traversal_duration,success=False,pageid={}'.format(
+                    request._orig_env.get('launchpad.pageid')
+                ), traversal_duration * 1000)
             if thread_now is not None:
                 traversal_thread_duration = (
                     thread_now - request._traversal_thread_start)
diff --git a/lib/lp/services/webapp/tests/test_publication.py b/lib/lp/services/webapp/tests/test_publication.py
index 335f999..fa9e9b4 100644
--- a/lib/lp/services/webapp/tests/test_publication.py
+++ b/lib/lp/services/webapp/tests/test_publication.py
@@ -19,6 +19,11 @@ from storm.database import (
     STATE_RECONNECT,
     )
 from storm.exceptions import DisconnectionError
+from testtools.matchers import (
+    Equals,
+    GreaterThan,
+    MatchesListwise,
+    )
 from zope.component import getUtility
 from zope.interface import directlyProvides
 from zope.publisher.interfaces import (
@@ -32,6 +37,7 @@ from lp.services.oauth.interfaces import (
     IOAuthConsumerSet,
     IOAuthSignedRequest,
     )
+from lp.services.statsd.tests import StatsMixin
 import lp.services.webapp.adapter as dbadapter
 from lp.services.webapp.interfaces import (
     NoReferrerError,
@@ -55,6 +61,7 @@ from lp.testing import (
     TestCase,
     TestCaseWithFactory,
     )
+from lp.testing.fakemethod import FakeMethod
 from lp.testing.layers import DatabaseFunctionalLayer
 
 
@@ -299,3 +306,73 @@ class TestUnicodePath(TestCaseWithFactory):
             browser.open,
             'http://launchpad.test/%ED%B4%B5')
         self.assertEqual(0, len(self.oopses))
+
+
+class TestPublisherStats(StatsMixin, TestCaseWithFactory):
+
+    layer = DatabaseFunctionalLayer
+
+    def setUp(self):
+        super(TestPublisherStats, self).setUp()
+        self.setUpStats()
+
+    def test_traversal_stats(self):
+        self.useFixture(FakeLogger())
+        browser = self.getUserBrowser()
+        browser.open('http://launchpad.test')
+        self.assertEqual(2, self.stats_client.timing.call_count)
+        self.assertThat(
+            [x[0] for x in self.stats_client.timing.call_args_list],
+            MatchesListwise(
+                [MatchesListwise(
+                    (Equals('traversal_duration,success=True,'
+                     'pageid=RootObject:index.html'),
+                     GreaterThan(0))),
+                 MatchesListwise(
+                     (Equals('publication_duration,success=True,'
+                      'pageid=RootObject:index.html'),
+                      GreaterThan(0)))]))
+
+    def test_traversal_failure_stats(self):
+        self.useFixture(FakeLogger())
+        browser = self.getUserBrowser()
+        self.patch(
+            LaunchpadBrowserPublication,
+            'afterTraversal',
+            FakeMethod(failure=Exception))
+        self.assertRaises(
+            Exception,
+            browser.open,
+            'http://launchpad.test/')
+        self.assertEqual(1, self.stats_client.timing.call_count)
+        self.assertThat(
+            [x[0] for x in self.stats_client.timing.call_args_list],
+            MatchesListwise(
+                [MatchesListwise(
+                    (Equals('traversal_duration,success=False,'
+                     'pageid=None'),
+                     GreaterThan(0)))]))
+
+    def test_publication_failure_stats(self):
+        self.useFixture(FakeLogger())
+        browser = self.getUserBrowser()
+        self.patch(
+            dbadapter,
+            'set_permit_timeout_from_features',
+            FakeMethod(failure=Exception))
+        self.assertRaises(
+            Exception,
+            browser.open,
+            'http://launchpad.test/')
+        self.assertEqual(2, self.stats_client.timing.call_count)
+        self.assertThat(
+            [x[0] for x in self.stats_client.timing.call_args_list],
+            MatchesListwise(
+                [MatchesListwise(
+                    (Equals('traversal_duration,success=True,'
+                     'pageid=RootObject:index.html'),
+                     GreaterThan(0))),
+                 MatchesListwise(
+                     (Equals('publication_duration,success=False,'
+                      'pageid=RootObject:index.html'),
+                      GreaterThan(0)))]))