launchpad-reviewers team mailing list archive
-
launchpad-reviewers team
-
Mailing list archive
-
Message #04572
[Merge] lp:~gary/launchpad/profiler into lp:launchpad
Gary Poster has proposed merging lp:~gary/launchpad/profiler into lp:launchpad.
Requested reviews:
Launchpad code reviewers (launchpad-reviewers)
For more details, see:
https://code.launchpad.net/~gary/launchpad/profiler/+merge/71192
In the course of trying to figure out how best to fix bug 724025 (a timeout bug involving Python rather than SQL) I made more tweaks to the ++profile++ tool. These changes do three things.
1) Make it possible to insert profile requests within the code, using the "profiling" context manager or the "start"/"stop" calls. Multiple calls within a request are aggregated.
2) Make it possible to ask for both callgrind and pstats simultaneously. This was not that important to me, but fell out of the refactoring I was doing.
3) Make the in-browser "show" functionality use the pstats rendering, because I liked it better (it gave aggregate time, for one thing).
Along the way, I simplified some tests by abstracting out assertion helpers, and I removed some hacks to use the BzrProfiler itself and simplified the code by using only the Bzr Stats class when we need to write callgrind files.
lint is happy except for its usual confusion with profile.pt.
./lib/lp/services/profile/profile.pt
6: junk after document element
I'm sorry for the extra size of the branch.
Thank you!
Gary
--
https://code.launchpad.net/~gary/launchpad/profiler/+merge/71192
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~gary/launchpad/profiler into lp:launchpad.
=== modified file 'lib/lp/services/profile/__init__.py'
--- lib/lp/services/profile/__init__.py 2011-02-17 16:58:57 +0000
+++ lib/lp/services/profile/__init__.py 2011-08-11 12:46:26 +0000
@@ -2,6 +2,19 @@
# GNU Affero General Public License version 3 (see the file LICENSE).
"""Profiling for Python and Zope applications.
-
-Tests for this package are currently services stories.
"""
+
+__all__ = ['profiling',
+ 'start',
+ 'stop',
+ ]
+
+# Re-export for convenience.
+from lp.services.profile.profile import (
+ profiling,
+ start,
+ stop,
+ )
+
+# Quiet the linter.
+(profiling, start, stop)
=== modified file 'lib/lp/services/profile/profile.pt'
--- lib/lp/services/profile/profile.pt 2011-08-08 15:24:22 +0000
+++ lib/lp/services/profile/profile.pt 2011-08-11 12:46:26 +0000
@@ -9,14 +9,19 @@
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;
- inlinetime options/inlinetime|nothing;
- totaltime options/totaltime|nothing;
- callcount options/callcount|nothing;
+ callgrind_path options/callgrind_path|nothing;
+ pstats_path options/pstats_path|nothing;
+ time options/time|nothing;
+ cumulative options/cumulative|nothing;
+ calls options/calls|nothing;
oops options/oops|nothing;
+ profile_count options/profile_count|nothing;
+ multiple_profiles options/multiple_profiles|nothing;
+ inline_ignored actions/inline_ignored|nothing;
+ inline actions/inline|nothing;
">
<div class="hide_reveal_profiling" id="hide_profiling">
Click to HIDE profiling information
@@ -45,6 +50,33 @@
<code>http://launchpad.dev/Firefox/++profile++show</code>) but some pages
do seem to redirect in surprising ways, so experimentation may be
necessary.</p>
+ <p>If you are working on a developer instance of Launchpad, you can also
+ insert calls directly in your code to profile certain code paths. Try
+ something like this:</p>
+<pre>
+from lp.services.profile import profiling
+with profiling():
+ # Do the work that you want profiled here!
+</pre>
+ <p>Multiple calls like this within a single request will be aggregated
+ together.</p>
+ </tal:block>
+ <tal:block condition="inline_ignored">
+ <h2>Inline request ignored</h2>
+ <p>You tried to use a profiling call in your code while also using a
+ conflicting <code>++profile++</code> request (like <code>show</code> or
+ <code>pstats</code> or <code>callgrind</code>). You can't use both at the
+ same time, so you got the full profile of this request. If you want the
+ results of the inline calls instead, try removing the
+ <code>++profile++</code>...<code>/</code> segment from your browser's URL.
+ </p>
+ </tal:block>
+ <tal:block condition="inline">
+ <h2>Inline request</h2>
+ <p>These results are from profiling statements in your code. <tal:block
+ condition="multiple_profiles">This request made <tal:block
+ replace="profile_count" /> individual profiles. The data here represent
+ an aggregate of all the profiles.</tal:block></p>
</tal:block>
<h2>Log information</h2>
<tal:block condition="not:log">
@@ -68,20 +100,16 @@
<code>[profiling]</code> section of your launchpad-lazr.conf.</p>
<p>Profile was logged to <tal:block replace="dump_path" />.</p>
<p tal:condition="callgrind">You should be able to use this
- simply by entering <code>kcachegrind <tal:block replace="dump_path"
+ simply by entering <code>kcachegrind <tal:block replace="callgrind_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"
+ <p tal:condition="pstats">You should be able to use this
+ simply by entering <code>python -m pstats <tal:block replace="pstats_path"
/></code> in the console to use the normal Python profile statistics
interface. Type "help" 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">
@@ -91,12 +119,15 @@
immediate results).</p>
</tal:block>
<tal:block condition="show">
+ <p tal:condition="multiple_profiles">This request made <tal:block
+ replace="profile_count" /> profiles. The statistics below represent an
+ aggregate of them all.</p>
<h3>Top Inline Time</h3>
- <pre tal:content="inlinetime" />
+ <pre tal:content="time" />
<h3>Top Total Time</h3>
- <pre tal:content="totaltime" />
+ <pre tal:content="cumulative" />
<h3>Top Call Count</h3>
- <pre tal:content="callcount" />
+ <pre tal:content="calls" />
<h2>Raw OOPS Information</h2>
<pre tal:content="oops" />
</tal:block>
=== modified file 'lib/lp/services/profile/profile.py'
--- lib/lp/services/profile/profile.py 2011-08-08 15:24:22 +0000
+++ lib/lp/services/profile/profile.py 2011-08-11 12:46:26 +0000
@@ -3,10 +3,14 @@
"""Profile requests when enabled."""
-__all__ = []
+__all__ = ['profiling',
+ 'start',
+ 'stop',
+ ]
__metaclass__ = type
+import contextlib
from cProfile import Profile
from datetime import datetime
import os
@@ -14,8 +18,7 @@
import threading
import StringIO
-from bzrlib import errors
-from bzrlib.lsprof import BzrProfiler
+from bzrlib import lsprof
from zope.pagetemplate.pagetemplatefile import PageTemplateFile
from zope.app.publication.interfaces import IEndRequestEvent
from zope.component import (
@@ -43,29 +46,46 @@
"""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.
- """
+class Profiler:
+
+ profiler_lock = threading.Lock()
+ """Global lock used to serialise profiles."""
+
+ started = enabled = False
+
+ def disable(self):
+ if self.enabled:
+ self.p.disable()
+ self.enabled = False
+ stats = pstats.Stats(self.p)
+ if self.pstats is None:
+ self.pstats = stats
+ else:
+ self.pstats.add(stats)
+ self.count += 1
+
+ def enable(self):
+ if not self.started:
+ self.start()
+ elif not self.enabled:
+ self.p = Profile()
+ self.p.enable(subcalls=True)
+ self.enabled = True
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")
+ if self.started:
+ return
+ self.count = 0
+ self.pstats = None
+ self.started = True
+ self.__class__.profiler_lock.acquire(True) # Blocks.
try:
- self.p.enable(subcalls=True)
+ self.enable()
except:
self.__class__.profiler_lock.release()
+ self.started = False
raise
def stop(self):
@@ -77,38 +97,41 @@
:return: A bzrlib.lsprof.Stats object.
"""
try:
- self.p.disable()
+ self.disable()
p = self.p
- self.p = None
- return PStats(p)
+ del self.p
+ return Stats(self.pstats, p.getstats(), self.count)
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
+ self.started = False
+
+
+class Stats:
+
+ _callgrind_stats = None
+
+ def __init__(self, stats, rawstats, count):
+ self.stats = stats
+ self.rawstats = rawstats
+ self.count = count
@property
- def stats(self):
- if self._stats is None:
- self._stats = pstats.Stats(self.p).strip_dirs()
- return self._stats
+ def callgrind_stats(self):
+ if self._callgrind_stats is None:
+ self._callgrind_stats = lsprof.Stats(self.rawstats, {})
+ return self._callgrind_stats
def save(self, filename):
- self.p.dump_stats(filename)
+ if filename.startswith('callgrind.out'):
+ self.callgrind_stats.save(filename)
+ else:
+ self.stats.dump_stats(filename)
+
+ def strip_dirs(self):
+ self.stats.strip_dirs()
def sort(self, name):
- mapping = {
- 'inlinetime': 'time',
- 'totaltime': 'cumulative',
- 'callcount': 'calls',
- }
- self.stats.sort_stats(mapping[name])
+ self.stats.sort_stats(name)
def pprint(self, file):
stats = self.stats
@@ -176,10 +199,7 @@
# to try and stop the profiler before we delete it, in case it is
# still running.
assert getattr(_profilers, 'profiler', None) is None
- 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 = Profiler()
_profilers.profiler.start()
if config.profiling.memory_profile_log:
_profilers.memory_profile_start = (memory(), resident())
@@ -188,6 +208,47 @@
os.path.join(os.path.dirname(__file__), 'profile.pt'))
+available_profilers = frozenset(('pstats', 'callgrind'))
+
+
+def start():
+ """Turn on profiling from code.
+ """
+ actions = getattr(_profilers, 'actions', None)
+ profiler = getattr(_profilers, 'profiler', None)
+ if actions is None:
+ actions = _profilers.actions = set()
+ _profilers.profiling = True
+ elif actions.difference(('help',)) and 'inline' not in actions:
+ actions.add('inline_ignored')
+ return
+ actions.update(('pstats', 'show', 'inline'))
+ if profiler is None:
+ profiler = _profilers.profiler = Profiler()
+ profiler.start()
+ else:
+ # For simplicity, we just silently ignore start requests when we
+ # have already started.
+ profiler.enable()
+
+
+def stop():
+ """Stop profiling."""
+ # For simplicity, we just silently ignore stop requests when we
+ # have not started.
+ actions = getattr(_profilers, 'actions', None)
+ profiler = getattr(_profilers, 'profiler', None)
+ if actions is not None and 'inline' in actions and profiler is not None:
+ profiler.disable()
+
+
+@contextlib.contextmanager
+def profiling():
+ start()
+ yield
+ stop()
+
+
@adapter(IEndRequestEvent)
def end_request(event):
"""If profiling is turned on, save profile data for the request."""
@@ -234,32 +295,37 @@
oopsid = oops.id
else:
oops = request.oops
- 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)
- template_context['dump_path'] = os.path.abspath(dump_path)
+ filename = '%s-%s-%s-%s' % (
+ timestamp, pageid, oopsid,
+ threading.currentThread().getName())
+ if 'callgrind' in actions:
+ # The stats class looks at the filename to know to use
+ # callgrind syntax.
+ callgrind_path = os.path.join(
+ dump_path, 'callgrind.out.' + filename)
+ prof_stats.save(callgrind_path)
+ template_context['callgrind_path'] = os.path.abspath(
+ callgrind_path)
+ if 'pstats' in actions:
+ pstats_path = os.path.join(
+ dump_path, filename + '.prof')
+ prof_stats.save(pstats_path)
+ template_context['pstats_path'] = os.path.abspath(
+ pstats_path)
if is_html and 'show' in actions:
# Generate raw OOPS results.
f = StringIO.StringIO()
oops.write(f)
template_context['oops'] = f.getvalue()
# Generate profile summaries.
- for name in ('inlinetime', 'totaltime', 'callcount'):
+ prof_stats.strip_dirs()
+ for name in ('time', 'cumulative', 'calls'):
prof_stats.sort(name)
f = StringIO.StringIO()
prof_stats.pprint(file=f)
template_context[name] = f.getvalue()
+ template_context['profile_count'] = prof_stats.count
+ template_context['multiple_profiles'] = prof_stats.count > 1
# Try to free some more memory.
del prof_stats
template_context['dump_path'] = os.path.abspath(dump_path)
@@ -314,12 +380,16 @@
action for action in (
item.strip().lower() for item in actions.split(','))
if action)
- # 'log' is backwards compatible for 'callgrind'
- result.intersection_update(('log', 'callgrind', 'show', 'pstats'))
+ # 'log' is backwards compatible for 'callgrind'.
if 'log' in result:
result.remove('log')
- if 'pstats' not in result:
- result.add('callgrind')
+ result.add('callgrind')
+ # Only honor the available options.
+ available_options = set(('show',))
+ available_options.update(available_profilers)
+ result.intersection_update(available_options)
+ # If we didn't end up with any known actions, we need to help the
+ # user.
if not result:
result.add('help')
return result
=== modified file 'lib/lp/services/profile/tests.py'
--- lib/lp/services/profile/tests.py 2011-08-08 15:48:34 +0000
+++ lib/lp/services/profile/tests.py 2011-08-11 12:46:26 +0000
@@ -11,10 +11,10 @@
import glob
import os
+import random
import time
from lp.testing import TestCase
-from bzrlib.lsprof import BzrProfiler
from zope.app.publication.interfaces import (
BeforeTraverseEvent,
EndRequestEvent,
@@ -119,7 +119,7 @@
# 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)
+ self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
self.assertIs(
getattr(profile._profilers, 'memory_profile_start', None),
None)
@@ -130,7 +130,7 @@
# 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.assertIsInstance(profile._profilers.profiler, profile.Profiler)
self.assertIs(
getattr(profile._profilers, 'memory_profile_start', None),
None)
@@ -141,7 +141,7 @@
# 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.assertIsInstance(profile._profilers.profiler, profile.Profiler)
self.assertIs(
getattr(profile._profilers, 'memory_profile_start', None),
None)
@@ -153,7 +153,7 @@
self.pushProfilingConfig(profiling_allowed='True')
profile.start_request(
self._get_start_event('/++profile++callgrind,show/'))
- self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
+ self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
self.assertIs(
getattr(profile._profilers, 'memory_profile_start', None),
None)
@@ -169,7 +169,7 @@
# trailing slash. :-P
profile.start_request(
self._get_start_event('/++profile++show,callgrind'))
- self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
+ self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
self.assertIs(
getattr(profile._profilers, 'memory_profile_start', None),
None)
@@ -183,26 +183,27 @@
profile.start_request(
self._get_start_event('/++profile++pstats/'))
self.assertIsInstance(profile._profilers.profiler,
- profile.PStatsProfiler)
+ profile.Profiler)
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):
+ def test_optional_profiling_with_log_pstats(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.
+ # and pstats request.
self.pushProfilingConfig(profiling_allowed='True')
profile.start_request(
self._get_start_event('/++profile++log,pstats/'))
- self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
+ self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
self.assertIs(
getattr(profile._profilers, 'memory_profile_start', None),
None)
- self.assertEquals(profile._profilers.actions, set(('pstats',)))
+ self.assertEquals(
+ profile._profilers.actions, set(('callgrind', 'pstats',)))
- def test_optional_profiling_with_conflicting_request(self):
+ def test_optional_profiling_with_callgrind_pstats(self):
# If profiling is allowed and a request with both the "pstats" and
# "callgrind" markers, profiling starts with the bzr/callgrind
# profiler.
@@ -210,7 +211,7 @@
profile.start_request(
self._get_start_event('/++profile++pstats,callgrind/'))
self.assertIsInstance(profile._profilers.profiler,
- profile.BzrProfiler)
+ profile.Profiler)
self.assertIs(
getattr(profile._profilers, 'memory_profile_start', None),
None)
@@ -222,7 +223,7 @@
self.pushProfilingConfig(
profiling_allowed='True', profile_all_requests='True')
profile.start_request(self._get_start_event('/'))
- self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
+ self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
self.assertIs(
getattr(profile._profilers, 'memory_profile_start', None),
None)
@@ -245,7 +246,7 @@
self.pushProfilingConfig(
profiling_allowed='True', profile_all_requests='True')
profile.start_request(self._get_start_event('/++profile++/'))
- self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
+ self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
self.assertIs(
getattr(profile._profilers, 'memory_profile_start', None),
None)
@@ -265,15 +266,13 @@
self.pushProfilingConfig(
profiling_allowed='True', memory_profile_log='.')
profile.start_request(self._get_start_event('/++profile++show/'))
- self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
+ self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
self.assertIsInstance(profile._profilers.memory_profile_start, tuple)
self.assertEqual(len(profile._profilers.memory_profile_start), 2)
self.assertEquals(profile._profilers.actions, set(('show', )))
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)
@@ -287,19 +286,17 @@
sm.registerUtility(self.eru)
self.addCleanup(sm.unregisterUtility, self.eru)
- def _get_end_event(self, path='/', result=EXAMPLE_HTML, pageid=None):
- """Return a stop event for the given path and output HTML."""
+ def endRequest(self, path='/', exception=None, pageid=None, work=None):
start_event = self._get_start_event(path)
profile.start_request(start_event)
request = start_event.request
if pageid is not None:
request.setInWSGIEnvironment('launchpad.pageid', pageid)
- request.response.setResult(result)
+ if work is not None:
+ work()
+ request.response.setResult(EXAMPLE_HTML)
context = object()
- return EndRequestEvent(context, request)
-
- def endRequest(self, path='/', exception=None, pageid=None):
- event = self._get_end_event(path, pageid=pageid)
+ event = EndRequestEvent(context, request)
if exception is not None:
self.eru.raising(
(type(exception), exception, None), event.request)
@@ -319,9 +316,48 @@
f.close()
return result
- def getProfilePaths(self):
+ def getPStatsProfilePaths(self):
+ return glob.glob(os.path.join(self.profile_dir, '*.prof'))
+
+ def getCallgrindProfilePaths(self):
return glob.glob(os.path.join(self.profile_dir, 'callgrind.out.*'))
+ def getAllProfilePaths(self):
+ return self.getPStatsProfilePaths() + self.getCallgrindProfilePaths()
+
+ def assertBasicProfileExists(self, request, show=False):
+ self.assertIsInstance(request.oops, ErrorReport)
+ response = self.getAddedResponse(request)
+ self.assertIn('Profile was logged to', response)
+ if show:
+ self.assertIn('Top Inline Time', response)
+ else:
+ self.assertNotIn('Top Inline Time', response)
+ self.assertEqual(self.getMemoryLog(), [])
+ self.assertCleanProfilerState()
+ return response
+
+ def assertPStatsProfile(self, response):
+ paths = self.getPStatsProfilePaths()
+ self.assertEqual(len(paths), 1)
+ self.assertIn(paths[0], response)
+ self.assertEqual(0, len(self.getCallgrindProfilePaths()))
+
+ def assertCallgrindProfile(self, response):
+ paths = self.getCallgrindProfilePaths()
+ self.assertEqual(len(paths), 1)
+ self.assertIn(paths[0], response)
+ self.assertEqual(0, len(self.getPStatsProfilePaths()))
+
+ def assertBothProfiles(self, response):
+ paths = self.getAllProfilePaths()
+ self.assertEqual(2, len(paths))
+ for path in paths:
+ self.assertIn(path, response)
+
+ def assertNoProfiles(self):
+ self.assertEqual([], self.getAllProfilePaths())
+
class TestBasicRequestEndHandler(BaseRequestEndHandlerTest):
"""Tests for the end-request handler.
@@ -343,7 +379,7 @@
self.assertIs(getattr(request, 'oops', None), None)
self.assertEqual(self.getAddedResponse(request), '')
self.assertEqual(self.getMemoryLog(), [])
- self.assertEqual(self.getProfilePaths(), [])
+ self.assertNoProfiles()
self.assertCleanProfilerState()
def test_optional_profiling_without_marked_request_has_no_profile(self):
@@ -354,24 +390,17 @@
self.assertIs(getattr(request, 'oops', None), None)
self.assertEqual(self.getAddedResponse(request), '')
self.assertEqual(self.getMemoryLog(), [])
- self.assertEqual(self.getProfilePaths(), [])
+ self.assertNoProfiles()
self.assertCleanProfilerState()
def test_forced_profiling_logs(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')
request = self.endRequest('/')
- self.assertIsInstance(request.oops, ErrorReport)
- response = self.getAddedResponse(request)
- self.assertIn('Profile was logged to', response)
+ response = self.assertBasicProfileExists(request)
+ self.assertCallgrindProfile(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
@@ -383,7 +412,7 @@
self.assertIn('<h2>Help</h2>', response)
self.assertNotIn('Top Inline Time', response)
self.assertEqual(self.getMemoryLog(), [])
- self.assertEqual(self.getProfilePaths(), [])
+ self.assertNoProfiles()
self.assertCleanProfilerState()
def test_forced_profiling_with_wrong_request_helps(self):
@@ -392,21 +421,25 @@
self.pushProfilingConfig(
profiling_allowed='True', profile_all_requests='True')
request = self.endRequest('/++profile++')
- self.assertIsInstance(request.oops, ErrorReport)
- response = self.getAddedResponse(request)
+ response = self.assertBasicProfileExists(request)
+ self.assertCallgrindProfile(response)
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)
+
+ 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.
+ self.pushProfilingConfig(profiling_allowed='True')
+ request = self.endRequest('/++profile++show/')
+ self.assertIsInstance(request.oops, ErrorReport)
+ self.assertIn('Top Inline Time', self.getAddedResponse(request))
self.assertEqual(self.getMemoryLog(), [])
- paths = self.getProfilePaths()
- self.assertEqual(len(paths), 1)
- self.assertIn(paths[0], response)
+ self.assertEqual(self.getCallgrindProfilePaths(), [])
self.assertCleanProfilerState()
-class TestBzrProfilerRequestEndHandler(BaseRequestEndHandlerTest):
- """Tests for the end-request handler of the BzrProfiler.
+class TestCallgrindProfilerRequestEndHandler(BaseRequestEndHandlerTest):
+ """Tests for the callgrind results.
If the start-request handler is broken, these tests will fail too, so fix
the tests in the above test case first.
@@ -415,53 +448,30 @@
of the functionality.
"""
+ assertProfilePaths = BaseRequestEndHandlerTest.assertCallgrindProfile
+
# 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.
- self.pushProfilingConfig(profiling_allowed='True')
- request = self.endRequest('/++profile++show/')
- self.assertIsInstance(request.oops, ErrorReport)
- self.assertIn('Top Inline Time', self.getAddedResponse(request))
- self.assertEqual(self.getMemoryLog(), [])
- self.assertEqual(self.getProfilePaths(), [])
- self.assertCleanProfilerState()
-
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++callgrind/')
- self.assertIsInstance(request.oops, ErrorReport)
- response = self.getAddedResponse(request)
- self.assertIn('Profile was logged to', 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()
+ self.assertProfilePaths(self.assertBasicProfileExists(request))
def test_optional_profiling_with_combined_request_profiles(self):
# 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++callgrind,show')
- self.assertIsInstance(request.oops, ErrorReport)
- response = self.getAddedResponse(request)
- self.assertIn('Profile was logged to', response)
- self.assertIn('Top Inline Time', response)
- self.assertEqual(self.getMemoryLog(), [])
- paths = self.getProfilePaths()
- self.assertEqual(len(paths), 1)
- self.assertIn(paths[0], response)
- self.assertCleanProfilerState()
-
-
-class TestStdLibProfilerRequestEndHandler(TestBzrProfilerRequestEndHandler):
- """Tests for the end-request handler of the stdlib profiler.
+ self.assertProfilePaths(
+ self.assertBasicProfileExists(request, show=True))
+
+
+class TestPStatsProfilerRequestEndHandler(
+ TestCallgrindProfilerRequestEndHandler):
+ """Tests for the pstats results.
If the start-request handler is broken, these tests will fail too, so fix
the tests in the above test case first.
@@ -469,34 +479,23 @@
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,
+ return TestCallgrindProfilerRequestEndHandler.endRequest(self,
path.replace('callgrind', 'pstats'))
-
-class TestConflictingProfilerRequestEndHandler(BaseRequestEndHandlerTest):
-
- def test_optional_profiling_with_conflicting_request_profiles(self):
+ assertProfilePaths = BaseRequestEndHandlerTest.assertPStatsProfile
+
+
+class TestBothProfilersRequestEndHandler(BaseRequestEndHandlerTest):
+
+ def test_optional_profiling_with_both_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++callgrind,pstats/')
- self.assertIsInstance(request.oops, ErrorReport)
- response = self.getAddedResponse(request)
- self.assertIn('Profile was logged to', 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()
+ self.assertBothProfiles(self.assertBasicProfileExists(request))
class TestMemoryProfilerRequestEndHandler(BaseRequestEndHandlerTest):
@@ -524,7 +523,7 @@
self.assertEqual(page_id, 'Unknown')
self.assertEqual(oops_id, '-')
self.assertEqual(float(duration), 0.5)
- self.assertEqual(self.getProfilePaths(), [])
+ self.assertNoProfiles()
self.assertCleanProfilerState()
def test_memory_profile_with_non_defaults(self):
@@ -549,7 +548,7 @@
self.assertIsInstance(request.oops, ErrorReport)
self.assertIn('Top Inline Time', self.getAddedResponse(request))
self.assertEqual(len(self.getMemoryLog()), 1)
- self.assertEqual(self.getProfilePaths(), [])
+ self.assertNoProfiles()
self.assertCleanProfilerState()
@@ -585,7 +584,8 @@
def test_oopsid_is_in_profile_filename(self):
self.pushProfilingConfig(profiling_allowed='True')
request = self.endRequest('/++profile++callgrind/')
- self.assertIn("-" + request.oopsid + "-", self.getProfilePaths()[0])
+ self.assertIn(
+ "-" + request.oopsid + "-", self.getAllProfilePaths()[0])
self.assertCleanProfilerState()
@@ -605,6 +605,49 @@
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', 'callgrind')))
+ self.assertIsInstance(
+ profile._profilers.profiler, profile.Profiler)
+ self.assertEquals(
+ set(('show', 'callgrind')), profile._profilers.actions)
+
+
+class TestInlineProfiling(BaseRequestEndHandlerTest):
+
+ def make_work(self, count=1):
+ def work():
+ for i in range(count):
+ profile.start()
+ random.random()
+ profile.stop()
+ return work
+
+ def test_basic_inline_profiling(self):
+ self.pushProfilingConfig(profiling_allowed='True')
+ request = self.endRequest('/', work=self.make_work())
+ self.assertPStatsProfile(
+ self.assertBasicProfileExists(request, show=True))
+
+ def test_multiple_inline_profiling(self):
+ self.pushProfilingConfig(profiling_allowed='True')
+ request = self.endRequest('/', work=self.make_work(count=2))
+ response = self.assertBasicProfileExists(request, show=True)
+ self.assertPStatsProfile(response)
+ self.assertIn('2 individual profiles', response)
+
+ def test_mixed_profiling(self):
+ # ++profile++ wins over inline.
+ self.pushProfilingConfig(profiling_allowed='True')
+ request = self.endRequest(
+ '/++profile++show,callgrind', work=self.make_work())
+ response = self.assertBasicProfileExists(request, show=True)
+ self.assertCallgrindProfile(response)
+ self.assertIn('Inline request ignored', response)
+
+ def test_context_manager(self):
+ def work():
+ with profile.profiling():
+ random.random()
+ self.pushProfilingConfig(profiling_allowed='True')
+ request = self.endRequest('/', work=work)
+ self.assertPStatsProfile(
+ self.assertBasicProfileExists(request, show=True))
