launchpad-reviewers team mailing list archive

[Māris Fogels <mfogels@xxxxxxxxx>]

Māris Fogels has proposed merging lp:~mars/launchpad/lsprof into lp:launchpad/devel.

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)


Hello,

This branch uses the bzr lsprof profiling suite to allow us to use KCacheGrind to profile requests to Launchpad.net.  We had to add a new event that fires once at the beginning of requests to start the profiling.  The old profiling code was moved into the new EndRequestEvent hook.  The profiling code was updated to use bzrlib's lsprof wrapper instead of hotshot.  A small tweak was made to ignore the new profile files when they show up in the tree.

Maris
-- 
https://code.launchpad.net/~mars/launchpad/lsprof/+merge/29964
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~mars/launchpad/lsprof into lp:launchpad/devel.

=== modified file '.bzrignore'
--- .bzrignore	2010-06-30 14:59:02 +0000
+++ .bzrignore	2010-07-15 09:41:17 +0000
@@ -69,6 +69,7 @@
 apidocs
 twistd.pid
 lib/canonical/launchpad/apidoc
+<<<<<<< TREE
 lib/canonical/launchpad-buildd_*.dsc
 lib/canonical/launchpad-buildd_*.tar.gz
 lib/canonical/launchpad-buildd_*_all.deb
@@ -76,3 +77,6 @@
 lib/canonical/launchpad-buildd_*_source.build
 lib/canonical/launchpad-buildd_*_source.changes
 lib/canonical/buildd/debian/*
+=======
+*.prof
+>>>>>>> MERGE-SOURCE

=== modified file 'lib/canonical/configure.zcml'
--- lib/canonical/configure.zcml	2010-07-12 08:34:29 +0000
+++ lib/canonical/configure.zcml	2010-07-15 09:41:17 +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-15 09:41:17 +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/interfaces.py'
--- lib/canonical/launchpad/webapp/interfaces.py	2010-05-02 23:43:35 +0000
+++ lib/canonical/launchpad/webapp/interfaces.py	2010-07-15 09:41:17 +0000
@@ -876,3 +876,29 @@
     It's used in the webservice domain for calculating webapp URLs, for
     instance, `ProxiedLibraryFileAlias`.
     """
+
+# XXX mars 2010-07-14 bug=598816
+#
+# We need a conditional import of the request events until the real events
+# land in the Zope mainline.
+#
+# See bug 598816 for the details.
+
+try:
+    from zope.publisher.interfaces import StartRequestEvent
+except:
+    class IStartRequestEvent(Interface):
+        """An event that gets sent before the start of a request."""
+
+        request = Attribute("The request the event is about")
+
+
+    class StartRequestEvent:
+        """An event fired once at the start of requests.
+
+        :ivar request: The request the event is for.
+        """
+        implements(IStartRequestEvent)
+
+        def __init__(self, request):
+            self.request = request

=== 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-15 09:41:17 +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
 
@@ -45,8 +41,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 +49,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, StartRequestEvent)
+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 +61,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 +134,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 +644,6 @@
         superclass = zope.app.publication.browser.BrowserPublication
         superclass.endRequest(self, request, object)
 
-        self.endProfilingHook(request)
-
         da.clear_request_started()
 
         # Maintain operational statistics.
@@ -710,62 +698,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."""
@@ -817,4 +749,3 @@
     tracelog = ITraceLog(request, None)
     if tracelog is not None:
         tracelog.log('%s %s' % (prefix, msg.encode('US-ASCII')))
-

=== 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-15 09:41:17 +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-15 09:41:17 +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="canonical.launchpad.webapp.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-15 09:41:17 +0000
@@ -0,0 +1,86 @@
+# 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 BzrProfiler
+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 = BzrProfiler()
+        _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()