Merge lp:~gary/launchpad/bug821531 into lp:launchpad

[Gary Poster]

[r=benji][bug=821531] Make it possible to request a pstats ++profile++ with "++profile++pstats" (in addition to a callgrind one, still available as "++pstats++callgrind").

This change adds the ability to get a stdlib-friendly profile output to ++profile++. This lets you dig in farther than KCacheGrind does, which has a maximum of the top 499 calls displayed for a given sorting.

Lint is happy except for being confused with the start of profile.pt.

Thanks

[Benji York (benji)]

This branch looks good. I can't wait to try it out. Here are some
relatively minor comments.

The name "pstats" might be a little better than "stdlib" because it's a
pstats-formatted file that's generated. For that matter, now that there
are more than one output formats, "log" might be better replaced with a
word that describes the generated format ("callgrind") while perhaps
leaving "log" as a backward-compatible alias.

Line 111 of the diff: the docstring summary for StdLibStats wraps.

Line 130 of the diff: JavaScript has warped your brain, you're missing a
comma on the last element of "mapping".

Line 183 of the diff, teeny-tiny suggestion: you could use '-'.join(...)
instead of '%s-%s-%s-%s' % (...).

Lines 235 and 256 of the diff: more docstring wrapping. Maybe those
should just be comments instead.

review: Approve (code)

[Gary Poster (gary)]

I made all changes that you suggested/requested except the '-'.join(...) approach: I prefer the template approach for the filename.

I changed all test docstrings to comments: many of them were wrapping, and as you hinted, comments are reasonable and maybe even preferred for these descriptions anyway.

I'm asking you for a re-review given the size of the changes.

Lint is still as happy as it was ("happy except for being confused with the start of profile.pt"). Thanks!

[Benji York (benji)]

This looks good. Thanks for considering my input.

One thing I didn't notice the first time around (assuming I'm reading
the code correctly): starting on line 279 of the diff, if the user
provides just "log" they will get callgrind output, if they provide
"callgrind" and "pstats" they get both, but if they provide "log" and
"pstats" they will get just "pstats". Given the internal nature of the
code, this corner case is not pressing.

review: Approve (code)

[Gary Poster (gary)]

Thanks again. I added a test for the "log,pstats" behavior: it is intentional ("log" is ambiguous and "pstats" is explicit). Note that if you request "callgrind,pstats" you actually get only callgrind and a warning that we can't do both at the same time.

=== modified file '.bzrignore'
--- .bzrignore	2011-08-05 16:24:32 +0000
+++ .bzrignore	2011-08-08 19:27:37 +0000
@@ -83,3 +83,4 @@
 lib/canonical/launchpad/icing/icon-sprites.positioning
 lib/canonical/launchpad/icing/yui
 .emacs.desktop
+callgrind.out.*

=== modified file 'lib/lp/services/profile/profile.pt'
--- lib/lp/services/profile/profile.pt	2011-08-05 16:24:32 +0000
+++ lib/lp/services/profile/profile.pt	2011-08-08 19:27:37 +0000
@@ -6,7 +6,10 @@
 <div class="profiling_info" id="profiling_info"
      tal:define="actions options/actions;
                  help actions/help|nothing;
-                 log actions/log|nothing;
+                 callgrind actions/callgrind|nothing;
+                 pstats actions/pstats|nothing;
+                 log python: callgrind or pstats;
+                 log_conflict python: callgrind and pstats;
                  show actions/show|nothing;
                  always_log options/always_log;
                  dump_path options/dump_path;
@@ -28,25 +31,35 @@
     you'll always see some logging information below.  In order to also
     get immediate profiling results in the browser, use
     <code>++profile++show</code>.</tal:block> <tal:block condition="not:
-    always_log">In order to get profiling results, you need to ask for
-    an HTML view (<code>++profile++show</code>), a KCacheGrind-friendly
-    log on the filesystem (<code>++profile++log</code>), or both
-    (<code>++profile++show,log</code>).</tal:block>  This can usually go
-    anywhere in the URL (e.g.,
-    <code>http://launchpad.dev/++profile++show</code> or
+    always_log">In order to get profiling results, you need to ask for an HTML
+    view (<code>++profile++show</code>), a KCacheGrind-friendly log on the
+    filesystem (<code>++profile++callgrind</code>), or a PStats-friendly log
+    (Python standard library) on the filesystem
+    (<code>++profile++pstats</code>). You can also ask for local HTML
+    profiling plus one of the two log files
+    (<code>++profile++show,callgrind</code> or
+    <code>++profile++show,pstats</code>).</tal:block></p>
+    <p>The "++profile++" path segment can usually go anywhere in the URL
+    (e.g., <code>http://launchpad.dev/++profile++show</code> or
     <code>http://launchpad.dev/++profile++show/Firefox</code> or
-    <code>http://launchpad.dev/Firefox/++profile++show</code>) but some
-    pages do seem to redirect in surprising ways, so experimentation may
-    be necessary.</p>
+    <code>http://launchpad.dev/Firefox/++profile++show</code>) but some pages
+    do seem to redirect in surprising ways, so experimentation may be
+    necessary.</p>
   </tal:block>
   <h2>Log information</h2>
   <tal:block condition="not:log">
     <p>Profile was not logged to file.</p>
-    <p>Use <code>++profile++log</code> in your URL in order to log the
-    information to file for later KCacheGrind analysis (or
-    <code>++profile++log,show</code> to see both the log information and
-    immediate results).  Profiles are logged to
-    <tal:block replace="dump_path" />.</p>
+    <p>Use <code>++profile++callgrind</code> in your URL in order to log the
+    information to file for later KCacheGrind analysis.  KCacheGrind is great
+    for visualizing a profile, but it only allows analyzing a limited depth of
+    calls.  If you want a greater profile depth, or if for any other reason
+    you want to use the standard Python library's pstats analysis instead, you
+    can. To do this, use "pstats" instead as part of your ++profile++ request,
+    as in <code>++profile++pstats</code>.  Profiles are logged to <tal:block
+    replace="dump_path" />.</p>
+    <p> You can see both the log information and immediate results with
+    <code>++profile++callgrind,show</code> or
+    <code>++profile++pstats,show</code>.</p>
   </tal:block>
   <tal:block condition="log">
     <p tal:condition="always_log"><strong>You have configured every
@@ -54,17 +67,28 @@
     <code>profile_all_requests: True</code> in the
     <code>[profiling]</code> section of your launchpad-lazr.conf.</p>
     <p>Profile was logged to <tal:block replace="dump_path" />.</p>
-    <p>You should be able to use this simply by entering
-    <code>kcachegrind <tal:block replace="dump_path" /></code> in the
-    console for a great visualization of the profile.  The <a
+    <p tal:condition="callgrind">You should be able to use this
+    simply by entering <code>kcachegrind <tal:block replace="dump_path"
+    /></code> in the console for a great visualization of the profile.  The <a
     href="https://dev.launchpad.net/Debugging#Profiling%%20page%%20requests"
     >dev wiki</a> may have more information on how to use this.</p>
+    <p tal:condition="not:callgrind">You should be able to use this
+    simply by entering <code>python -m pstats <tal:block replace="dump_path"
+    /></code> in the console to use the normal Python profile statistics
+    interface.  Type &quot;help&quot; at the prompt, or see the <a
+    href="http://docs.python.org/library/profile.html#instant-user-s-manual"
+    >Python documentation</a>.</p>
+    <p tal:condition="log_conflict"><strong>You asked for both callgrind and
+    pstats logging.  We can only choose one at a time, and the default is
+    callgrind. If you want a pstats profile as well, request it
+    separately.</strong></p>
   </tal:block>
   <h2>Profile quick view</h2>
   <tal:block condition="not:show">
-    <p>Use <code>++profile++show</code> in your URL in order to see
-    immediate profile results (or <code>++profile++log,show</code> to
-    see both the log information and immediate results).</p>
+    <p>Use <code>++profile++show</code> in your URL in order to see immediate
+    profile results (or <code>++profile++callgrind,show</code> or
+    <code>++profile++pstats,show</code> to see both the log information and
+    immediate results).</p>
   </tal:block>
   <tal:block condition="show">
     <h3>Top Inline Time</h3>

=== modified file 'lib/lp/services/profile/profile.py'
--- lib/lp/services/profile/profile.py	2011-08-05 16:24:32 +0000
+++ lib/lp/services/profile/profile.py	2011-08-08 19:27:37 +0000
@@ -7,11 +7,14 @@
 
 __metaclass__ = type
 
+from cProfile import Profile
 from datetime import datetime
 import os
+import pstats
 import threading
 import StringIO
 
+from bzrlib import errors
 from bzrlib.lsprof import BzrProfiler
 from zope.pagetemplate.pagetemplatefile import PageTemplateFile
 from zope.app.publication.interfaces import IEndRequestEvent
@@ -40,6 +43,84 @@
     """Fake exception used to log OOPS information when profiling pages."""
 
 
+class PStatsProfiler(BzrProfiler):
+    """This provides a wrapper around the standard library's profiler.
+
+    It makes the BzrProfiler and the PStatsProfiler follow a similar API.
+    It also makes them both honor the BzrProfiler's thread lock.
+    """
+
+    def start(self):
+        """Start profiling.
+
+        This will record all calls made until stop() is called.
+
+        Unlike the BzrProfiler, we do not try to get profiles of sub-threads.
+        """
+        self.p = Profile()
+        permitted = self.__class__.profiler_lock.acquire(
+            self.__class__.profiler_block)
+        if not permitted:
+            raise errors.InternalBzrError(msg="Already profiling something")
+        try:
+            self.p.enable(subcalls=True)
+        except:
+            self.__class__.profiler_lock.release()
+            raise
+
+    def stop(self):
+        """Stop profiling.
+
+        This unhooks from threading and cleans up the profiler, returning
+        the gathered Stats object.
+
+        :return: A bzrlib.lsprof.Stats object.
+        """
+        try:
+            self.p.disable()
+            p = self.p
+            self.p = None
+            return PStats(p)
+        finally:
+            self.__class__.profiler_lock.release()
+
+
+class PStats:
+    """Emulate enough of the Bzr stats class for our needs."""
+
+    _stats = None
+
+    def __init__(self, profiler):
+        self.p = profiler
+
+    @property
+    def stats(self):
+        if self._stats is None:
+            self._stats = pstats.Stats(self.p).strip_dirs()
+        return self._stats
+
+    def save(self, filename):
+        self.p.dump_stats(filename)
+
+    def sort(self, name):
+        mapping = {
+            'inlinetime': 'time',
+            'totaltime': 'cumulative',
+            'callcount': 'calls',
+            }
+        self.stats.sort_stats(mapping[name])
+
+    def pprint(self, file):
+        stats = self.stats
+        stream = stats.stream
+        stats.stream = file
+        try:
+            stats.print_stats()
+        finally:
+            stats.stream = stream
+
+
+# Profilers may only run one at a time, but block and serialize.
 _profilers = threading.local()
 
 
@@ -85,17 +166,20 @@
         pass
     actions = get_desired_profile_actions(event.request)
     if config.profiling.profile_all_requests:
-        actions.add('log')
+        actions.add('callgrind')
     _profilers.actions = actions
     _profilers.profiler = None
     _profilers.profiling = True
     if actions:
-        if actions.difference(('help', )):
+        if actions.difference(('help',)):
             # If this assertion has reason to fail, we'll need to add code
             # to try and stop the profiler before we delete it, in case it is
             # still running.
             assert getattr(_profilers, 'profiler', None) is None
-            _profilers.profiler = BzrProfiler()
+            if 'pstats' in actions and 'callgrind' not in actions:
+                _profilers.profiler = PStatsProfiler()
+            else:  # 'callgrind' is the default, and wins in a conflict.
+                _profilers.profiler = BzrProfiler()
             _profilers.profiler.start()
     if config.profiling.memory_profile_log:
         _profilers.memory_profile_start = (memory(), resident())
@@ -138,7 +222,7 @@
     dump_path = config.profiling.profile_dir
     if _profilers.profiler is not None:
         prof_stats = _profilers.profiler.stop()
-        # Free some memory.
+        # Free some memory (at least for the BzrProfiler).
         del _profilers.profiler
         if oopsid is None:
             # Log an OOPS to get a log of the SQL queries, and other
@@ -150,12 +234,21 @@
             oopsid = oops.id
         else:
             oops = request.oops
-        if 'log' in actions:
-            filename = '%s-%s-%s-%s.prof' % (
+        if actions.intersection(('callgrind', 'pstats')):
+            filename = '%s-%s-%s-%s' % (
                 timestamp, pageid, oopsid,
                 threading.currentThread().getName())
+            if 'callgrind' in actions:
+                # callgrind wins in a conflict between it and pstats, as
+                # documented in the help.
+                # The Bzr stats class looks at the filename to know to use
+                # callgrind syntax.
+                filename = 'callgrind.out.' + filename
+            else:
+                filename += '.prof'
             dump_path = os.path.join(dump_path, filename)
-            prof_stats.save(dump_path, format="callgrind")
+            prof_stats.save(dump_path)
+            template_context['dump_path'] = os.path.abspath(dump_path)
         if is_html and 'show' in actions:
             # Generate raw OOPS results.
             f = StringIO.StringIO()
@@ -167,6 +260,8 @@
                 f = StringIO.StringIO()
                 prof_stats.pprint(file=f)
                 template_context[name] = f.getvalue()
+        # Try to free some more memory.
+        del prof_stats
     template_context['dump_path'] = os.path.abspath(dump_path)
     if actions and is_html:
         # Hack the new HTML in at the end of the page.
@@ -219,7 +314,12 @@
                 action for action in (
                     item.strip().lower() for item in actions.split(','))
                 if action)
-            result.intersection_update(('log', 'show'))
+            # 'log' is backwards compatible for 'callgrind'
+            result.intersection_update(('log', 'callgrind', 'show', 'pstats'))
+            if 'log' in result:
+                result.remove('log')
+                if 'pstats' not in result:
+                    result.add('callgrind')
             if not result:
                 result.add('help')
     return result

=== modified file 'lib/lp/services/profile/tests.py'
--- lib/lp/services/profile/tests.py	2011-02-24 06:33:25 +0000
+++ lib/lp/services/profile/tests.py	2011-08-08 19:27:37 +0000
@@ -12,7 +12,6 @@
 import glob
 import os
 import time
-import unittest
 
 from lp.testing import TestCase
 from bzrlib.lsprof import BzrProfiler
@@ -101,12 +100,13 @@
         self.pushProfilingConfig(
             profiling_allowed='False', profile_all_requests='True',
             memory_profile_log='.')
-        profile.start_request(self._get_start_event('/++profile++show,log'))
+        profile.start_request(self._get_start_event(
+            '/++profile++show,callgrind'))
         self.assertCleanProfilerState('config was ignored')
 
     def test_optional_profiling_without_marked_request_has_no_profile(self):
-        """Even if profiling is allowed, it does not happen with a normal
-        request."""
+        # Even if profiling is allowed, it does not happen with a normal
+        # request.
         self.pushProfilingConfig(profiling_allowed='True')
         profile.start_request(self._get_start_event('/'))
         self.assertEqual(profile._profilers.actions, set())
@@ -115,8 +115,8 @@
             getattr(profile._profilers, 'memory_profile_start', None), None)
 
     def test_optional_profiling_with_show_request_starts_profiling(self):
-        """If profiling is allowed and a request with the "show" marker
-        URL segment is made, profiling starts."""
+        # If profiling is allowed and a request with the "show" marker
+        # URL segment is made, profiling starts.
         self.pushProfilingConfig(profiling_allowed='True')
         profile.start_request(self._get_start_event('/++profile++show/'))
         self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
@@ -125,44 +125,100 @@
             None)
         self.assertEquals(profile._profilers.actions, set(('show', )))
 
+    def test_optional_profiling_with_callgrind_request_starts_profiling(self):
+        # If profiling is allowed and a request with the "callgrind" marker
+        # URL segment is made, profiling starts.
+        self.pushProfilingConfig(profiling_allowed='True')
+        profile.start_request(self._get_start_event('/++profile++callgrind/'))
+        self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
+        self.assertIs(
+            getattr(profile._profilers, 'memory_profile_start', None),
+            None)
+        self.assertEquals(profile._profilers.actions, set(('callgrind', )))
+
     def test_optional_profiling_with_log_request_starts_profiling(self):
-        """If profiling is allowed and a request with the "log" marker
-        URL segment is made, profiling starts."""
+        # If profiling is allowed and a request with the "log" marker URL
+        # segment is made, profiling starts as a callgrind profile request.
         self.pushProfilingConfig(profiling_allowed='True')
         profile.start_request(self._get_start_event('/++profile++log/'))
         self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
-        self.assertEquals(profile._profilers.actions, set(('log', )))
+        self.assertEquals(profile._profilers.actions, set(('callgrind', )))
 
     def test_optional_profiling_with_combined_request_starts_profiling(self):
-        """If profiling is allowed and a request with the "log" and
-        "show" marker URL segment is made, profiling starts."""
+        # If profiling is allowed and a request with the "callgrind" and
+        # "show" marker URL segment is made, profiling starts.
         self.pushProfilingConfig(profiling_allowed='True')
-        profile.start_request(self._get_start_event('/++profile++log,show/'))
+        profile.start_request(
+            self._get_start_event('/++profile++callgrind,show/'))
         self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
-        self.assertEquals(profile._profilers.actions, set(('log', 'show')))
+        self.assertEquals(
+            profile._profilers.actions, set(('callgrind', 'show')))
 
     def test_optional_profiling_with_reversed_request_starts_profiling(self):
-        """If profiling is allowed and a request with the "show" and
-        "log" marker URL segment is made, profiling starts."""
+        # If profiling is allowed and a request with the "show" and the
+        # "callgrind" marker URL segment is made, profiling starts.
         self.pushProfilingConfig(profiling_allowed='True')
         # The fact that this is reversed from the previous request is the only
         # difference from the previous test.  Also, it doesn't have a
         # trailing slash. :-P
-        profile.start_request(self._get_start_event('/++profile++show,log'))
-        self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
-        self.assertIs(
-            getattr(profile._profilers, 'memory_profile_start', None),
-            None)
-        self.assertEquals(profile._profilers.actions, set(('log', 'show')))
+        profile.start_request(
+            self._get_start_event('/++profile++show,callgrind'))
+        self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
+        self.assertIs(
+            getattr(profile._profilers, 'memory_profile_start', None),
+            None)
+        self.assertEquals(
+            profile._profilers.actions, set(('callgrind', 'show')))
+
+    def test_optional_profiling_with_pstats_request_starts_profiling(self):
+        # If profiling is allowed and a request with the "pstats" marker,
+        # profiling starts with the pstats profiler.
+        self.pushProfilingConfig(profiling_allowed='True')
+        profile.start_request(
+            self._get_start_event('/++profile++pstats/'))
+        self.assertIsInstance(profile._profilers.profiler,
+                              profile.PStatsProfiler)
+        self.assertIs(
+            getattr(profile._profilers, 'memory_profile_start', None),
+            None)
+        self.assertEquals(profile._profilers.actions, set(('pstats',)))
+
+    def test_optional_profiling_with_log_request_starts_profiling(self):
+        # If profiling is allowed and a request with the "log" and "pstats"
+        # marker URL segments is made, profiling starts as a callgrind profile
+        # request.
+        self.pushProfilingConfig(profiling_allowed='True')
+        profile.start_request(
+            self._get_start_event('/++profile++log,pstats/'))
+        self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
+        self.assertIs(
+            getattr(profile._profilers, 'memory_profile_start', None),
+            None)
+        self.assertEquals(profile._profilers.actions, set(('pstats',)))
+
+    def test_optional_profiling_with_conflicting_request(self):
+        # If profiling is allowed and a request with both the "pstats" and
+        # "callgrind" markers, profiling starts with the bzr/callgrind
+        # profiler.
+        self.pushProfilingConfig(profiling_allowed='True')
+        profile.start_request(
+            self._get_start_event('/++profile++pstats,callgrind/'))
+        self.assertIsInstance(profile._profilers.profiler,
+                              profile.BzrProfiler)
+        self.assertIs(
+            getattr(profile._profilers, 'memory_profile_start', None),
+            None)
+        self.assertEquals(
+            profile._profilers.actions, set(('pstats', 'callgrind')))
 
     def test_forced_profiling_registers_action(self):
-        """profile_all_requests should register as a log action"""
+        # profile_all_requests should register as a callgrind action.
         self.pushProfilingConfig(
             profiling_allowed='True', profile_all_requests='True')
         profile.start_request(self._get_start_event('/'))
@@ -170,12 +226,11 @@
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
-        self.assertEquals(profile._profilers.actions, set(('log', )))
+        self.assertEquals(profile._profilers.actions, set(('callgrind', )))
 
     def test_optional_profiling_with_wrong_request_helps(self):
-        """If profiling is allowed and a request with the marker URL segment
-        is made incorrectly, profiling does not start and help is an action.
-        """
+        # If profiling is allowed and a request with the marker URL segment
+        # is made incorrectly, profiling does not start and help is an action.
         self.pushProfilingConfig(profiling_allowed='True')
         profile.start_request(self._get_start_event('/++profile++/'))
         self.assertIs(getattr(profile._profilers, 'profiler', None), None)
@@ -185,9 +240,8 @@
         self.assertEquals(profile._profilers.actions, set(('help', )))
 
     def test_forced_profiling_with_wrong_request_helps(self):
-        """If profiling is forced and a request with the marker URL segment
-        is made incorrectly, profiling starts and help is an action.
-        """
+        # If profiling is forced and a request with the marker URL segment
+        # is made incorrectly, profiling starts and help is an action.
         self.pushProfilingConfig(
             profiling_allowed='True', profile_all_requests='True')
         profile.start_request(self._get_start_event('/++profile++/'))
@@ -195,7 +249,8 @@
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
-        self.assertEquals(profile._profilers.actions, set(('help', 'log')))
+        self.assertEquals(
+            profile._profilers.actions, set(('help', 'callgrind')))
 
     def test_memory_profile_start(self):
         self.pushProfilingConfig(
@@ -216,15 +271,9 @@
         self.assertEquals(profile._profilers.actions, set(('show', )))
 
 
-class TestRequestEndHandler(BaseTest):
-    """Tests for the end-request handler.
-
-    If the start-request handler is broken, these tests will fail too, so fix
-    the tests in the above test case first.
-
-    See lib/canonical/doc/profiling.txt for an end-user description
-    of the functionality.
-    """
+class BaseRequestEndHandlerTest(BaseTest):
+    # These are shared by tests of the bzr profiler, the stdlib profiler,
+    # and the memory analysis.
 
     def setUp(self):
         TestCase.setUp(self)
@@ -271,17 +320,26 @@
         return result
 
     def getProfilePaths(self):
-        return glob.glob(os.path.join(self.profile_dir, '*.prof'))
-
-    #########################################################################
-    # Tests
+        return glob.glob(os.path.join(self.profile_dir, 'callgrind.out.*'))
+
+
+class TestBasicRequestEndHandler(BaseRequestEndHandlerTest):
+    """Tests for the end-request handler.
+
+    If the start-request handler is broken, these tests will fail too, so fix
+    the tests in the above test case first.
+
+    See lib/canonical/doc/profiling.txt for an end-user description
+    of the functionality.
+    """
+
     def test_config_stops_profiling(self):
-        """The ``profiling_allowed`` configuration should disable all
-        profiling, even if it is requested"""
+        # The ``profiling_allowed`` configuration should disable all
+        # profiling, even if it is requested.
         self.pushProfilingConfig(
             profiling_allowed='False', profile_all_requests='True',
             memory_profile_log=self.memory_profile_log)
-        request = self.endRequest('/++profile++show,log')
+        request = self.endRequest('/++profile++show,callgrind')
         self.assertIs(getattr(request, 'oops', None), None)
         self.assertEqual(self.getAddedResponse(request), '')
         self.assertEqual(self.getMemoryLog(), [])
@@ -289,8 +347,8 @@
         self.assertCleanProfilerState()
 
     def test_optional_profiling_without_marked_request_has_no_profile(self):
-        """Even if profiling is allowed, it does not happen with a normal
-        request."""
+        # Even if profiling is allowed, it does not happen with a normal
+        # request.
         self.pushProfilingConfig(profiling_allowed='True')
         request = self.endRequest('/')
         self.assertIs(getattr(request, 'oops', None), None)
@@ -299,9 +357,70 @@
         self.assertEqual(self.getProfilePaths(), [])
         self.assertCleanProfilerState()
 
+    def test_forced_profiling_logs(self):
+        # profile_all_requests should register as a log action.
+        self.pushProfilingConfig(
+            profiling_allowed='True', profile_all_requests='True')
+        request = self.endRequest('/')
+        self.assertIsInstance(request.oops, ErrorReport)
+        response = self.getAddedResponse(request)
+        self.assertIn('Profile was logged to', response)
+        self.assertIn('profile_all_requests: True', response)
+        self.assertNotIn('Top Inline Time', response)
+        self.assertEqual(self.getMemoryLog(), [])
+        paths = self.getProfilePaths()
+        self.assertEqual(len(paths), 1)
+        self.assertIn(paths[0], response)
+        self.assertCleanProfilerState()
+
+    def test_optional_profiling_with_wrong_request_helps(self):
+        # If profiling is allowed and a request with the marker URL segment
+        # is made incorrectly, profiling does not start and help is an action.
+        self.pushProfilingConfig(profiling_allowed='True')
+        request = self.endRequest('/++profile++')
+        self.assertIs(getattr(request, 'oops', None), None)
+        response = self.getAddedResponse(request)
+        self.assertIn('<h2>Help</h2>', response)
+        self.assertNotIn('Top Inline Time', response)
+        self.assertEqual(self.getMemoryLog(), [])
+        self.assertEqual(self.getProfilePaths(), [])
+        self.assertCleanProfilerState()
+
+    def test_forced_profiling_with_wrong_request_helps(self):
+        # If profiling is forced and a request with the marker URL segment
+        # is made incorrectly, profiling starts and help is an action.
+        self.pushProfilingConfig(
+            profiling_allowed='True', profile_all_requests='True')
+        request = self.endRequest('/++profile++')
+        self.assertIsInstance(request.oops, ErrorReport)
+        response = self.getAddedResponse(request)
+        self.assertIn('<h2>Help</h2>', response)
+        self.assertIn('Profile was logged to', response)
+        self.assertIn('profile_all_requests: True', response)
+        self.assertNotIn('Top Inline Time', response)
+        self.assertEqual(self.getMemoryLog(), [])
+        paths = self.getProfilePaths()
+        self.assertEqual(len(paths), 1)
+        self.assertIn(paths[0], response)
+        self.assertCleanProfilerState()
+
+
+class TestBzrProfilerRequestEndHandler(BaseRequestEndHandlerTest):
+    """Tests for the end-request handler of the BzrProfiler.
+
+    If the start-request handler is broken, these tests will fail too, so fix
+    the tests in the above test case first.
+
+    See lib/canonical/doc/profiling.txt for an end-user description
+    of the functionality.
+    """
+
+    # Note that these tests are re-used by TestStdLibProfilerRequestEndHandler
+    # below.
+
     def test_optional_profiling_with_show_request_profiles(self):
-        """If profiling is allowed and a request with the "show" marker
-        URL segment is made, profiling starts."""
+        # If profiling is allowed and a request with the "show" marker
+        # URL segment is made, profiling starts.
         self.pushProfilingConfig(profiling_allowed='True')
         request = self.endRequest('/++profile++show/')
         self.assertIsInstance(request.oops, ErrorReport)
@@ -310,11 +429,11 @@
         self.assertEqual(self.getProfilePaths(), [])
         self.assertCleanProfilerState()
 
-    def test_optional_profiling_with_log_request_profiles(self):
-        """If profiling is allowed and a request with the "log" marker
-        URL segment is made, profiling starts."""
+    def test_optional_profiling_with_callgrind_request_profiles(self):
+        # If profiling is allowed and a request with the "callgrind" marker
+        # URL segment is made, profiling starts.
         self.pushProfilingConfig(profiling_allowed='True')
-        request = self.endRequest('/++profile++log/')
+        request = self.endRequest('/++profile++callgrind/')
         self.assertIsInstance(request.oops, ErrorReport)
         response = self.getAddedResponse(request)
         self.assertIn('Profile was logged to', response)
@@ -326,10 +445,10 @@
         self.assertCleanProfilerState()
 
     def test_optional_profiling_with_combined_request_profiles(self):
-        """If profiling is allowed and a request with the "log" and
-        "show" marker URL segment is made, profiling starts."""
+        # If profiling is allowed and a request with the "callgrind" and
+        # "show" marker URL segment is made, profiling starts.
         self.pushProfilingConfig(profiling_allowed='True')
-        request = self.endRequest('/++profile++log,show')
+        request = self.endRequest('/++profile++callgrind,show')
         self.assertIsInstance(request.oops, ErrorReport)
         response = self.getAddedResponse(request)
         self.assertIn('Profile was logged to', response)
@@ -340,57 +459,58 @@
         self.assertIn(paths[0], response)
         self.assertCleanProfilerState()
 
-    def test_forced_profiling_logs(self):
-        """profile_all_requests should register as a log action"""
-        self.pushProfilingConfig(
-            profiling_allowed='True', profile_all_requests='True')
-        request = self.endRequest('/')
-        self.assertIsInstance(request.oops, ErrorReport)
-        response = self.getAddedResponse(request)
-        self.assertIn('Profile was logged to', response)
-        self.assertIn('profile_all_requests: True', response)
-        self.assertNotIn('Top Inline Time', response)
-        self.assertEqual(self.getMemoryLog(), [])
-        paths = self.getProfilePaths()
-        self.assertEqual(len(paths), 1)
-        self.assertIn(paths[0], response)
-        self.assertCleanProfilerState()
-
-    def test_optional_profiling_with_wrong_request_helps(self):
-        """If profiling is allowed and a request with the marker URL segment
-        is made incorrectly, profiling does not start and help is an action.
-        """
+
+class TestStdLibProfilerRequestEndHandler(TestBzrProfilerRequestEndHandler):
+    """Tests for the end-request handler of the stdlib profiler.
+
+    If the start-request handler is broken, these tests will fail too, so fix
+    the tests in the above test case first.
+
+    See lib/canonical/doc/profiling.txt for an end-user description
+    of the functionality.
+    """
+    # Take over the BzrProfiler questions to test the stdlib variant.
+
+    def getProfilePaths(self):
+        return glob.glob(os.path.join(self.profile_dir, '*.prof'))
+
+    def endRequest(self, path):
+        return TestBzrProfilerRequestEndHandler.endRequest(self,
+            path.replace('callgrind', 'pstats'))
+
+
+class TestConflictingProfilerRequestEndHandler(BaseRequestEndHandlerTest):
+
+    def test_optional_profiling_with_conflicting_request_profiles(self):
+        # If profiling is allowed and a request with the "callgrind" and
+        # "pstats" markers is made, profiling starts with the callgrind
+        # approach only.
         self.pushProfilingConfig(profiling_allowed='True')
-        request = self.endRequest('/++profile++')
-        self.assertIs(getattr(request, 'oops', None), None)
-        response = self.getAddedResponse(request)
-        self.assertIn('<h2>Help</h2>', response)
-        self.assertNotIn('Top Inline Time', response)
-        self.assertEqual(self.getMemoryLog(), [])
-        self.assertEqual(self.getProfilePaths(), [])
-        self.assertCleanProfilerState()
-
-    def test_forced_profiling_with_wrong_request_helps(self):
-        """If profiling is forced and a request with the marker URL segment
-        is made incorrectly, profiling starts and help is an action.
-        """
-        self.pushProfilingConfig(
-            profiling_allowed='True', profile_all_requests='True')
-        request = self.endRequest('/++profile++')
+        request = self.endRequest('/++profile++callgrind,pstats/')
         self.assertIsInstance(request.oops, ErrorReport)
         response = self.getAddedResponse(request)
-        self.assertIn('<h2>Help</h2>', response)
         self.assertIn('Profile was logged to', response)
-        self.assertIn('profile_all_requests: True', response)
         self.assertNotIn('Top Inline Time', response)
+        self.assertIn('You asked for both callgrind and', response)
         self.assertEqual(self.getMemoryLog(), [])
         paths = self.getProfilePaths()
         self.assertEqual(len(paths), 1)
         self.assertIn(paths[0], response)
         self.assertCleanProfilerState()
 
+
+class TestMemoryProfilerRequestEndHandler(BaseRequestEndHandlerTest):
+    """Tests for the end-request handler of the memory profile.
+
+    If the start-request handler is broken, these tests will fail too, so fix
+    the tests in the above test case first.
+
+    See lib/canonical/doc/profiling.txt for an end-user description
+    of the functionality.
+    """
+
     def test_memory_profile(self):
-        "Does the memory profile work?"
+        # Does the memory profile work?
         self.pushProfilingConfig(
             profiling_allowed='True',
             memory_profile_log=self.memory_profile_log)
@@ -408,7 +528,7 @@
         self.assertCleanProfilerState()
 
     def test_memory_profile_with_non_defaults(self):
-        "Does the memory profile work with an oops and pageid?"
+        # Does the memory profile work with an oops and pageid?
         self.pushProfilingConfig(
             profiling_allowed='True',
             memory_profile_log=self.memory_profile_log)
@@ -432,10 +552,20 @@
         self.assertEqual(self.getProfilePaths(), [])
         self.assertCleanProfilerState()
 
+
+class TestOOPSRequestEndHandler(BaseRequestEndHandlerTest):
+    """Tests for the end-request handler of the OOPS output.
+
+    If the start-request handler is broken, these tests will fail too, so fix
+    the tests in the above test case first.
+
+    See lib/canonical/doc/profiling.txt for an end-user description
+    of the functionality.
+    """
+
     def test_profiling_oops_is_informational(self):
         self.pushProfilingConfig(profiling_allowed='True')
         request = self.endRequest('/++profile++show/')
-        response = self.getAddedResponse(request)
         self.assertIsInstance(request.oops, ErrorReport)
         self.assertTrue(request.oops.informational)
         self.assertEquals(request.oops.type, 'ProfilingOops')
@@ -454,7 +584,7 @@
 
     def test_oopsid_is_in_profile_filename(self):
         self.pushProfilingConfig(profiling_allowed='True')
-        request = self.endRequest('/++profile++log/')
+        request = self.endRequest('/++profile++callgrind/')
         self.assertIn("-" + request.oopsid + "-", self.getProfilePaths()[0])
         self.assertCleanProfilerState()
 
@@ -471,9 +601,10 @@
             profiling_allowed='False', profile_all_requests='True',
             memory_profile_log='.')
         event = BeforeTraverseEvent(None,
-            self._get_request('/++profile++show,log'))
-        with FeatureFixture({'profiling.enabled':'on'}):
+            self._get_request('/++profile++show,callgrind'))
+        with FeatureFixture({'profiling.enabled': 'on'}):
             profile.before_traverse(event)
             self.assertTrue(profile._profilers.profiling)
             self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
-            self.assertEquals(profile._profilers.actions, set(('show', 'log')))
+            self.assertEquals(profile._profilers.actions, set(
+                ('show', 'callgrind')))