launchpad-reviewers team mailing list archive
-
launchpad-reviewers team
-
Mailing list archive
-
Message #04509
[Merge] lp:~gary/launchpad/bug821531 into lp:launchpad
Gary Poster has proposed merging lp:~gary/launchpad/bug821531 into lp:launchpad.
Requested reviews:
Launchpad code reviewers (launchpad-reviewers)
Related bugs:
Bug #821531 in Launchpad itself: "++profile++ does not allow saving standard Python profiler format"
https://bugs.launchpad.net/launchpad/+bug/821531
For more details, see:
https://code.launchpad.net/~gary/launchpad/bug821531/+merge/70738
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
--
https://code.launchpad.net/~gary/launchpad/bug821531/+merge/70738
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~gary/launchpad/bug821531 into lp:launchpad.
=== 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 13:10:47 +0000
@@ -7,6 +7,7 @@
tal:define="actions options/actions;
help actions/help|nothing;
log actions/log|nothing;
+ stdlib actions/stdlib|nothing;
show actions/show|nothing;
always_log options/always_log;
dump_path options/dump_path;
@@ -47,6 +48,12 @@
<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>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, include "stdlib" as part of
+ your ++profile++ request, as in <code>++profile++log,stdlib</code> or
+ <code>++profile++log,show,stdlib</code>.</p>
</tal:block>
<tal:block condition="log">
<p tal:condition="always_log"><strong>You have configured every
@@ -54,11 +61,17 @@
<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="not:stdlib">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="stdlib">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 "help" at the prompt, or see the <a
+ href="http://docs.python.org/library/profile.html#instant-user-s-manual";
+ >Python documentation</a>.</p>
</tal:block>
<h2>Profile quick view</h2>
<tal:block condition="not:show">
=== 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 13:10:47 +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,85 @@
"""Fake exception used to log OOPS information when profiling pages."""
+class StdLibProfiler(BzrProfiler):
+ """This provides a wrapper around the standard library's profiler.
+
+ It makes the BzrProfiler and the StdLibProfiler 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 StdLibStats(p)
+ finally:
+ self.__class__.profiler_lock.release()
+
+
+class StdLibStats:
+ """This emulates enough of the Bzr stats class to make it interoperable
+ for our purposes."""
+
+ _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()
@@ -90,12 +172,15 @@
_profilers.profiler = None
_profilers.profiling = True
if actions:
- if actions.difference(('help', )):
+ if actions.difference(('help', 'stdlib')):
# 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 'stdlib' in actions:
+ _profilers.profiler = StdLibProfiler()
+ else:
+ _profilers.profiler = BzrProfiler()
_profilers.profiler.start()
if config.profiling.memory_profile_log:
_profilers.memory_profile_start = (memory(), resident())
@@ -138,7 +223,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
@@ -151,11 +236,18 @@
else:
oops = request.oops
if 'log' in actions:
- filename = '%s-%s-%s-%s.prof' % (
+ filename = '%s-%s-%s-%s' % (
timestamp, pageid, oopsid,
threading.currentThread().getName())
+ if 'stdlib' in actions:
+ filename += '.prof'
+ else:
+ # The Bzr stats class looks at the filename to know to use
+ # callgrind syntax.
+ filename = 'callgrind.out.' + filename
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 +259,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,8 +313,8 @@
action for action in (
item.strip().lower() for item in actions.split(','))
if action)
- result.intersection_update(('log', 'show'))
- if not result:
+ result.intersection_update(('log', 'show', 'stdlib'))
+ if not result.difference(('stdlib',)):
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 13:10:47 +0000
@@ -12,7 +12,6 @@
import glob
import os
import time
-import unittest
from lp.testing import TestCase
from bzrlib.lsprof import BzrProfiler
@@ -161,6 +160,20 @@
None)
self.assertEquals(profile._profilers.actions, set(('log', 'show')))
+ def test_optional_profiling_with_stdliblog_request_starts_profiling(self):
+ """If profiling is allowed and a request with the "log" marker
+ URL segment is made with "stdlib", profiling starts with the stdlib
+ profiler."""
+ self.pushProfilingConfig(profiling_allowed='True')
+ profile.start_request(
+ self._get_start_event('/++profile++log,stdlib/'))
+ self.assertIsInstance(profile._profilers.profiler,
+ profile.StdLibProfiler)
+ self.assertIs(
+ getattr(profile._profilers, 'memory_profile_start', None),
+ None)
+ self.assertEquals(profile._profilers.actions, set(('log', 'stdlib')))
+
def test_forced_profiling_registers_action(self):
"""profile_all_requests should register as a log action"""
self.pushProfilingConfig(
@@ -184,6 +197,18 @@
None)
self.assertEquals(profile._profilers.actions, set(('help', )))
+ def test_optional_profiling_with_stdlib_only_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')
+ profile.start_request(self._get_start_event('/++profile++stdlib/'))
+ self.assertIs(getattr(profile._profilers, 'profiler', None), None)
+ self.assertIs(
+ getattr(profile._profilers, 'memory_profile_start', None),
+ None)
+ self.assertEquals(profile._profilers.actions, set(('help', 'stdlib')))
+
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.
@@ -216,15 +241,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,10 +290,19 @@
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"""
@@ -299,6 +327,69 @@
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."""
@@ -340,54 +431,35 @@
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.
- """
- 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 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('++profile++', '++profile++stdlib,'))
+
+
+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?"
@@ -432,10 +504,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')
@@ -472,8 +554,9 @@
memory_profile_log='.')
event = BeforeTraverseEvent(None,
self._get_request('/++profile++show,log'))
- with FeatureFixture({'profiling.enabled':'on'}):
+ 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', 'log')))
