Merge lp:~lifeless/launchpad/lsprof into lp:launchpad

[Robert Collins]

Move our existing profiling code to be hook based, which makes it more orthogonal, easier to reason about.

[Curtis Hovey (sinzui)]

Thanks for extracting the profiling behaviour. I have a few remarks.

> === modified file 'lib/canonical/launchpad/webapp/configure.zcml'
> --- lib/canonical/launchpad/webapp/configure.zcml 2010-06-08 15:57:09 +0000
> +++ lib/canonical/launchpad/webapp/configure.zcml 2010-06-27 09:23:29 +0000
> @@ -13,6 +13,8 @@
> <include file="errorlog.zcml" />
> -->
> <include file="bug-5133.zcml" />
> + <!-- Would be nice to turn this off in production -->
> + <include file="profile.zcml" />

Each env gets its own config. ./configs/testrunner-appserver has ZCML
that registers YUI unittest hooks for example. I think this rule could
be in ./configs/development, and in ~launchpad-pqm/production-configs in
staging and dogfood.

> === added file 'lib/canonical/launchpad/webapp/profile.py'
> --- lib/canonical/launchpad/webapp/profile.py 1970-01-01 00:00:00 +0000
> +++ lib/canonical/launchpad/webapp/profile.py 2010-06-27 09:23:29 +0000

We do not want to add to this deprecated location. I think this would
be better located at lib/lp/services/profile

> === added file 'lib/canonical/launchpad/webapp/profile.zcml'
> --- lib/canonical/launchpad/webapp/profile.zcml 1970-01-01 00:00:00 +0000
> +++ lib/canonical/launchpad/webapp/profile.zcml 2010-06-27 09:23:29 +0000

As above.

review: Needs Information

[Robert Collins (lifeless)]

I'll move it to your preferred location.

What rules does testing load - the development set?

-Rob

[Curtis Hovey (sinzui)]

I am not sure I know what you mean by testing. Each environment has its own ZCML configuration (Which is also bad since there is a lot of duplication).

Everyone can see development and testrunner configs in the launchpad tree.

The production configs for staging, dogfood, edge, etc ..., are in
    https://edge.launchpad.net/lp-production-configs

To enable profiling just on staging and dogfood requires an update to their respective directories in that branch.

[Robert Collins (lifeless)]

Yes, I can see that. I meant in the testrunner, because if its not
enabled in the test runner... it can't be tested :)

Anyhow, I think we may still want this on on production, so for now
I'm just going to leave it always configured - I do appreciate the
info though, particularly as I had a comment there.

I'll delete the comment to avoid confusion.

Rob

[Robert Collins (lifeless)]

Ok, I've moved the code as requested.

However, I don't know if it still meets the requirement of lp.services that
'packages in this namespace can only use general LAZR or library functionality.'

profile.py imports the canonical config, webapp adapter (for request
timing) and canonical.mem.

Do they need to be moved across first, before this is safe to port across?

-Rob

[Curtis Hovey (sinzui)]

Canonical.config and webapp adapter should move in our lifetime. They do not need to move now. There are many modules in lp.services using these.

I thought the import rules was removed because it was blocking refactoring. It certainly is being ignored. I think it is unrealistic. The attempt to make all webapp into lazr proved too daunting and I do not think there is any interest in it now. Just getting canonical.launchpad to die will raise a rally of cheers and beers.

review: Approve (code)

[Robert Collins (lifeless)]

Ok, cool, I'll get both of these landed.

=== modified file 'lib/canonical/configure.zcml'
--- lib/canonical/configure.zcml	2010-07-12 08:34:29 +0000
+++ lib/canonical/configure.zcml	2010-07-14 08:59:50 +0000
@@ -20,6 +20,7 @@
     <include package="lp.services.openid" />
     <include package="lp.services.job" />
     <include package="lp.services.memcache" />
+    <include package="lp.services.profile" />
     <include package="lp.services.scripts" />
     <include package="lp.services.worlddata" />
     <include package="lp.services.salesforce" />

=== modified file 'lib/canonical/launchpad/doc/profiling.txt'
--- lib/canonical/launchpad/doc/profiling.txt	2010-04-14 23:53:16 +0000
+++ lib/canonical/launchpad/doc/profiling.txt	2010-07-14 08:59:50 +0000
@@ -69,7 +69,7 @@
     >>> print PageTestLayer.profiler
     None
 
-And no stats file is written when the layer is tore down.
+And no stats file is written when the layer is torn down.
 
     >>> PageTestLayer.tearDown()
     >>> os.path.exists(pagetests_profile)

=== modified file 'lib/canonical/launchpad/webapp/publication.py'
--- lib/canonical/launchpad/webapp/publication.py	2010-06-17 11:35:12 +0000
+++ lib/canonical/launchpad/webapp/publication.py	2010-07-14 08:59:50 +0000
@@ -7,7 +7,6 @@
     'LaunchpadBrowserPublication',
     ]
 
-import os
 import re
 import sys
 import thread
@@ -15,9 +14,6 @@
 import traceback
 import urllib
 
-from cProfile import Profile
-from datetime import datetime
-
 import tickcount
 import transaction
 
@@ -29,7 +25,8 @@
 from zc.zservertracelog.interfaces import ITraceLog
 import zope.app.publication.browser
 from zope.app import zapi  # used to get at the adapters service
-from zope.app.publication.interfaces import BeforeTraverseEvent
+from zope.app.publication.interfaces import (
+    BeforeTraverseEvent, StartRequestEvent)
 from zope.app.security.interfaces import IUnauthenticatedPrincipal
 from zope.component import getUtility, queryMultiAdapter
 from zope.error.interfaces import IErrorReportingUtility
@@ -45,8 +42,7 @@
 import canonical.launchpad.layers as layers
 import canonical.launchpad.webapp.adapter as da
 
-from canonical.config import config, dbconfig
-from canonical.mem import memory, resident
+from canonical.config import config
 from canonical.launchpad.interfaces.launchpad import ILaunchpadCelebrities
 from canonical.launchpad.interfaces.oauth import IOAuthSignedRequest
 from canonical.launchpad.readonly import is_read_only
@@ -54,10 +50,9 @@
     IPerson, IPersonSet, ITeam)
 from canonical.launchpad.webapp.interfaces import (
     IDatabasePolicy, ILaunchpadRoot, INotificationResponse, IOpenLaunchBag,
-    IPlacelessAuthUtility, IPrimaryContext, IStoreSelector, MAIN_STORE,
-    MASTER_FLAVOR, OffsiteFormPostError, NoReferrerError, SLAVE_FLAVOR)
-from canonical.launchpad.webapp.dbpolicy import (
-    DatabaseBlockedPolicy, LaunchpadDatabasePolicy)
+    IPlacelessAuthUtility, IPrimaryContext, IStoreSelector,
+    MASTER_FLAVOR, OffsiteFormPostError, NoReferrerError)
+from canonical.launchpad.webapp.dbpolicy import LaunchpadDatabasePolicy
 from canonical.launchpad.webapp.menu import structured
 from canonical.launchpad.webapp.opstats import OpStats
 from lazr.uri import URI, InvalidURIError
@@ -67,10 +62,6 @@
 METHOD_WRAPPER_TYPE = type({}.__setitem__)
 
 
-class ProfilingOops(Exception):
-    """Fake exception used to log OOPS information when profiling pages."""
-
-
 class LoginRoot:
     """Object that provides IPublishTraverse to return only itself.
 
@@ -144,7 +135,7 @@
     # revisited.
 
     def beforeTraversal(self, request):
-        self.startProfilingHook()
+        notify(StartRequestEvent(request))
         request._traversalticks_start = tickcount.tickcount()
         threadid = thread.get_ident()
         threadrequestfile = open('thread-%s.request' % threadid, 'w')
@@ -654,8 +645,6 @@
         superclass = zope.app.publication.browser.BrowserPublication
         superclass.endRequest(self, request, object)
 
-        self.endProfilingHook(request)
-
         da.clear_request_started()
 
         # Maintain operational statistics.
@@ -710,62 +699,6 @@
             if thread_name != 'MainThread' or name.endswith('-slave'):
                 store.reset()
 
-    def startProfilingHook(self):
-        """Handle profiling.
-
-        If requests profiling start a profiler. If memory profiling is
-        requested, save the VSS and RSS.
-        """
-        if config.profiling.profile_requests:
-            self.thread_locals.profiler = Profile()
-            self.thread_locals.profiler.enable()
-
-        if config.profiling.memory_profile_log:
-            self.thread_locals.memory_profile_start = (memory(), resident())
-
-    def endProfilingHook(self, request):
-        """If profiling is turned on, save profile data for the request."""
-        # Create a timestamp including milliseconds.
-        now = datetime.fromtimestamp(da.get_request_start_time())
-        timestamp = "%s.%d" % (
-            now.strftime('%Y-%m-%d_%H:%M:%S'), int(now.microsecond/1000.0))
-        pageid = request._orig_env.get('launchpad.pageid', 'Unknown')
-        oopsid = getattr(request, 'oopsid', None)
-
-        if config.profiling.profile_requests:
-            profiler = self.thread_locals.profiler
-            profiler.disable()
-
-            if oopsid is None:
-                # Log an OOPS to get a log of the SQL queries, and other
-                # useful information,  together with the profiling
-                # information.
-                info = (ProfilingOops, None, None)
-                error_utility = getUtility(IErrorReportingUtility)
-                error_utility.raising(info, request)
-                oopsid = request.oopsid
-            filename = '%s-%s-%s-%s.prof' % (
-                timestamp, pageid, oopsid,
-                threading.currentThread().getName())
-
-            profiler.dump_stats(
-                os.path.join(config.profiling.profile_dir, filename))
-
-            # Free some memory.
-            self.thread_locals.profiler = None
-
-        # Dump memory profiling info.
-        if config.profiling.memory_profile_log:
-            log = file(config.profiling.memory_profile_log, 'a')
-            vss_start, rss_start = self.thread_locals.memory_profile_start
-            vss_end, rss_end = memory(), resident()
-            if oopsid is None:
-                oopsid = '-'
-            log.write('%s %s %s %f %d %d %d %d\n' % (
-                timestamp, pageid, oopsid, da.get_request_duration(),
-                vss_start, rss_start, vss_end, rss_end))
-            log.close()
-
 
 class InvalidThreadsConfiguration(Exception):
     """Exception thrown when the number of threads isn't set correctly."""

=== added directory 'lib/lp/services/profile'
=== added file 'lib/lp/services/profile/__init__.py'
--- lib/lp/services/profile/__init__.py	1970-01-01 00:00:00 +0000
+++ lib/lp/services/profile/__init__.py	2010-07-14 08:59:50 +0000
@@ -0,0 +1,7 @@
+# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""lp.services.profile - profiling for zope applications.
+
+Tests for this package are currently services stories.
+"""

=== added file 'lib/lp/services/profile/configure.zcml'
--- lib/lp/services/profile/configure.zcml	1970-01-01 00:00:00 +0000
+++ lib/lp/services/profile/configure.zcml	2010-07-14 08:59:50 +0000
@@ -0,0 +1,19 @@
+<!-- Copyright 2010 Canonical Ltd.  This software is licensed under the
+     GNU Affero General Public License version 3 (see the file LICENSE).
+-->
+
+<configure
+    xmlns="http://namespaces.zope.org/zope"
+    xmlns:browser="http://namespaces.zope.org/browser">
+
+    <subscriber
+        for="zope.app.publication.interfaces.IStartRequestEvent"
+        handler="lp.services.profile.profile.start_request"
+        />
+
+    <subscriber
+        for="zope.app.publication.interfaces.IEndRequestEvent"
+        handler="lp.services.profile.profile.end_request"
+        />
+
+</configure>

=== added file 'lib/lp/services/profile/profile.py'
--- lib/lp/services/profile/profile.py	1970-01-01 00:00:00 +0000
+++ lib/lp/services/profile/profile.py	2010-07-14 08:59:50 +0000
@@ -0,0 +1,87 @@
+# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Profile requests when enabled."""
+
+__all__ = []
+
+__metaclass__ = type
+
+from datetime import datetime
+import os
+import threading
+
+from bzrlib.lsprof import Profiler
+from zope.error.interfaces import IErrorReportingUtility
+from zope.component import getUtility
+
+from canonical.config import config
+import canonical.launchpad.webapp.adapter as da
+from canonical.mem import memory, resident
+
+
+class ProfilingOops(Exception):
+    """Fake exception used to log OOPS information when profiling pages."""
+
+
+_profilers = threading.local()
+
+
+def start_request(event):
+    """Handle profiling.
+
+    If profiling is enabled, start a profiler for this thread. If memory
+    profiling is requested, save the VSS and RSS.
+    """
+    if config.profiling.profile_requests:
+        _profilers.profiler = Profiler()
+        _profilers.profiler.start()
+
+    if config.profiling.memory_profile_log:
+        _profilers.memory_profile_start = (memory(), resident())
+
+
+def end_request(event):
+    """If profiling is turned on, save profile data for the request."""
+    request = event.request
+    # Create a timestamp including milliseconds.
+    now = datetime.fromtimestamp(da.get_request_start_time())
+    timestamp = "%s.%d" % (
+        now.strftime('%Y-%m-%d_%H:%M:%S'), int(now.microsecond/1000.0))
+    pageid = request._orig_env.get('launchpad.pageid', 'Unknown')
+    oopsid = getattr(request, 'oopsid', None)
+    if config.profiling.profile_requests:
+        profiler = _profilers.profiler
+        _profilers.profiler = None
+        prof_stats = profiler.stop()
+
+        if oopsid is None:
+            # Log an OOPS to get a log of the SQL queries, and other
+            # useful information,  together with the profiling
+            # information.
+            info = (ProfilingOops, None, None)
+            error_utility = getUtility(IErrorReportingUtility)
+            error_utility.raising(info, request)
+            oopsid = request.oopsid
+        filename = '%s-%s-%s-%s.prof' % (
+            timestamp, pageid, oopsid,
+            threading.currentThread().getName())
+
+        dump_path = os.path.join(config.profiling.profile_dir, filename)
+        prof_stats.save(dump_path, format="callgrind")
+
+        # Free some memory.
+        _profilers.profiler = None
+
+    # Dump memory profiling info.
+    if config.profiling.memory_profile_log:
+        log = file(config.profiling.memory_profile_log, 'a')
+        vss_start, rss_start = _profilers.memory_profile_start
+        vss_end, rss_end = memory(), resident()
+        if oopsid is None:
+            oopsid = '-'
+        log.write('%s %s %s %f %d %d %d %d\n' % (
+            timestamp, pageid, oopsid, da.get_request_duration(),
+            vss_start, rss_start, vss_end, rss_end))
+        log.close()
+