launchpad-reviewers team mailing list archive
-
launchpad-reviewers team
-
Mailing list archive
-
Message #00779
[Merge] lp:~gary/launchpad/lsprof-on-demand into lp:launchpad/devel
Gary Poster has proposed merging lp:~gary/launchpad/lsprof-on-demand into lp:launchpad/devel.
Requested reviews:
Launchpad code reviewers (launchpad-reviewers)
Related bugs:
#598289 support a profile decorator for use in staging and development environments
https://bugs.launchpad.net/bugs/598289
= Intro =
This branch adds profiling-in-demand via a ++profile++ URL hook, like ++debug++ and ++oops++.
To test, run ``./bin/test -vvm lp.services.profile.tests`` and ``./bin/test -vvt profiling.txt``.
To QA (please do), go to a URL like https://launchpad.dev/++profile++ or https://launchpad.dev/++profile++show/~mark/+archive/ppa and see what you get. Hopefully the help docs that these URLs display will let you help you figure out what is going on, and see what else to experiment with. Also see the profiling.txt document for help, which is also available in apidoc.launchpad.dev in the Launchpad part of the Books section.
This is a significantly over-large diff. I'm sorry. Suggestions on how I could have divided it up are welcome. Requests to actually do so will be acted upon. :-)
I did get Curtis to review and approve some individual parts of this work. I will identify these below.
= Lint =
./configs/development/launchpad-lazr.conf
96: Line exceeds 78 characters.
115: Line exceeds 78 characters.
126: Line exceeds 78 characters.
./lib/canonical/config/schema-lazr.conf
493: Line exceeds 78 characters.
975: Line exceeds 78 characters.
I brought these up with Curtis. He said not to change them. He is adjusting the linter to ignore over-long lines in these files.
./lib/canonical/launchpad/icing/style-3-0.css.in
LOTSA LINES: Line exceeds 78 characters.
I started looking at these many lines. Some of them were example URLs. Others were comments following some sort of regular pattern. I decided I really didn't want to touch that. None of the lines are mine, in any case.
./lib/lp/services/profile/profile.pt
6: junk after document element
This is a file of an HTML snippet. I assume that's why the linter is unhappy. Is it what it is.
= File-by-File Comments =
.bzrignore
The new addition is the output of chameleon, a page template
implementation to which we plan to switch, and which I used because it
was convenient for a template.
configs/development/apidoc-configure-normal.zcml
This adds the revised file to the apidoc Books section.
configs/development/launchpad-lazr.conf
As is explained in other files, this means that profiling is allowed
with the ++profile++ url segment in development.
lib/canonical/config/schema-lazr.conf
(No comment)
lib/canonical/launchpad/doc/profiling.txt
I converted this to ReST and tried to make the parts of the document that
described the pieces I was changing more like an end-user help document.
The actual tests here are now part of the new unit tests.
lib/canonical/launchpad/icing/style-3-0.css.in
Curtis has reviewed and approved of the placement and abstract content of
this CSS (though he did not see the actual visual result).
lib/canonical/launchpad/webapp/errorlog.py
Most of the changes in this file are to make lint happy.
The ony real changes are that calling "raising" and "handling" returns the
generated OOPS. That has handy and seemed reasonable.
lib/lp/services/profile/configure.zcml
I don't need the "for" lines because I do the declaration in-line in the
Python now.
lib/lp/services/profile/profile.pt
This is a raw Chameleon page template. These templates have Python expressions as their default, which was convenient.
lib/lp/services/profile/profile.py
The comments in get_desired_profile_actions explain what I consider to be
the more unusual choices I made.
lib/lp/services/profile/tests.py
I appear to have gotten tired of writing docstrings for the tests towards
the end. I'm not sure if we require them. Lemme know if you want them.
I tried to make the method names descriptive enough.
--
https://code.launchpad.net/~gary/launchpad/lsprof-on-demand/+merge/33849
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~gary/launchpad/lsprof-on-demand into lp:launchpad/devel.
=== modified file '.bzrignore'
--- .bzrignore 2010-08-12 13:17:05 +0000
+++ .bzrignore 2010-08-26 22:55:56 +0000
@@ -77,3 +77,4 @@
lib/canonical/launchpad-buildd_*_source.changes
lib/canonical/buildd/debian/*
lib/canonical/buildd/launchpad-files/*
+*.pt.py
=== modified file 'configs/development/apidoc-configure-normal.zcml'
--- configs/development/apidoc-configure-normal.zcml 2010-08-04 15:59:53 +0000
+++ configs/development/apidoc-configure-normal.zcml 2010-08-26 22:55:56 +0000
@@ -120,5 +120,11 @@
doc_path="../../doc/buildout.txt"
parent="lp"
/>
+ <apidoc:bookchapter
+ id="profiling"
+ title="Profiling"
+ doc_path="../../lib/canonical/launchpad/doc/profiling.txt"
+ parent="lp"
+ />
</configure>
=== modified file 'configs/development/launchpad-lazr.conf'
--- configs/development/launchpad-lazr.conf 2010-08-06 17:39:52 +0000
+++ configs/development/launchpad-lazr.conf 2010-08-26 22:55:56 +0000
@@ -246,6 +246,9 @@
[process_apport_blobs]
error_dir: /var/tmp/lperr
+[profiling]
+profiling_allowed: True
+
[supermirror_puller]
error_dir: /var/tmp/codehosting.test
oops_prefix: SMP
=== modified file 'lib/canonical/config/schema-lazr.conf'
--- lib/canonical/config/schema-lazr.conf 2010-08-19 09:45:38 +0000
+++ lib/canonical/config/schema-lazr.conf 2010-08-26 22:55:56 +0000
@@ -1642,10 +1642,16 @@
[profiling]
+# When set to True, the user is allowed to request profiles be run for
+# either individual pages or for every request sent.
+# datatype: boolean
+profiling_allowed: False
+
# When set to True, each requests will be profiled and the resulting data
-# saved in profile_dir.
+# saved in profile_dir. `profiling_allowed` must also be True for this to
+# work.
# datatype: boolean
-profile_requests: False
+profile_all_requests: False
# Directory to save profile info. The filename is in the format
# <timestamp>-<threadName>.prof
=== modified file 'lib/canonical/launchpad/doc/profiling.txt'
--- lib/canonical/launchpad/doc/profiling.txt 2010-07-17 13:40:35 +0000
+++ lib/canonical/launchpad/doc/profiling.txt 2010-08-26 22:55:56 +0000
@@ -1,8 +1,15 @@
-= Profiling support =
+=================
+Profiling support
+=================
+
+.. ReST Comment: this is intended to be a true DOC test, with an emphasis on
+ documentation. Of the three sections, the last two have been adjusted for
+ this goal.
Launchpad supports three modes of profiling.
-== Profiling requests in pagetests ==
+Profiling requests in pagetests
+===============================
Our testing framework has support for profiling requests made in
pagetests. When the PROFILE_PAGETESTS_REQUESTS environment variable is
@@ -76,142 +83,118 @@
False
-== Profiling request in the app server ==
+Profiling request in the app server
+===================================
-It is also possible to get a profile of each request served by the app
+It is also possible to get a profile of requests served by the app
server.
-This is controlled by the [profiling] config section. Profiling is
-controlled by the profile_requests configuration variable. When this is
-True, each request will create a pstats file for the request in the
-directory specified in the profile_dir variable.
-
-By default profiling is turned off.
-
- >>> from canonical.config import config
- >>> config.profiling.profile_requests
+*Important*: This is not blessed for production, primarily because of
+the typical cost of employing a profiling hook. Also, profiled requests
+are forced to run in serial. This is also a concern for production
+usage, since some of our requests can take much longer than others.
+
+It might be fine to occasionally turn on in staging; that is more
+negotiable, at least. LOSAs will need to vet the feature to see if they are
+concerned about it giving too much information about our staging system.
+
+The feature has two modes.
+
+- It can be configured to optionally profile requests. To turn this on, in
+ ``launchpad-lazr.conf`` (e.g.,
+ ``configs/development/launchpad-lazr.conf``) , in the ``[profiling]``
+ section, set ``profiling_allowed: True``. As of this writing, this
+ is the default value for development.
+
+ Once it is turned on, you can insert /++profile++/ in the URL to get
+ basic instructions on how to use the feature. You use the
+ ``launchpad-lazr.conf`` ``profile_dir`` setting to determine what
+ directory will receive written profiles.
+
+.. This ReST comment tests the assertion above that profiling_allowed is
+ True by default for tests and development.
+
+ >>> from canonical.config import config
+ >>> config.profiling.profiling_allowed
+ True
+
+ Similarly, this tests that, in a fully set-up environment, the
+ profiling machinery that is coded and unit-tested in
+ lp/services/profile is hooked up properly. This is intended to be a
+ smoke test. The unit tests verify further functionality.
+
+ >>> response = http('GET /++profile++ HTTP/1.0')
+ >>> '<h1>Profiling Information</h1>' in response.getBody()
+ True
+
+- It can be configured to profile all requests, indiscriminately. To turn
+ this on, use the ``profiling_allowed`` setting described in option 1
+ above and also set ``profile_all_requests: True`` in the
+ ``[profiling]`` section of ``launchpad-lazr.conf``. This is turned
+ off by default. As with the first option, you use the
+ ``profile_dir`` setting to determine what directory will receive the
+ profiles.
+
+ Once it is turned on, every request will create a profiling log usable
+ with KCacheGrind. The browser will include information on the file
+ created for that request.
+
+.. This ReST comment tests the assertion above that profile_all_requests is
+ False by default for tests and development.
+
+ >>> from canonical.config import config
+ >>> config.profiling.profile_all_requests
False
-(Set the profile directory.)
-
- >>> from textwrap import dedent
- >>> profile_dir = tempfile.mkdtemp(prefix='profile')
- >>> config.push('profile_dir', dedent("""
- ... [profiling]
- ... profile_dir: %s""" % profile_dir))
-
-So when making a request, no profile information is created.
-
- >>> response = http('GET / HTTP/1.0')
-
- >>> list(os.listdir(profile_dir))
- []
-
-But if profiling is turned on, profiling data will be created in the
-directory for the request.
-
- >>> config.push('profile_on', dedent("""\
- ... [profiling]
- ... profile_requests: True"""))
-
- >>> response = http('GET / HTTP/1.0')
-
-The profile is named on the time of the request start, the pageid, and
-the thread that processed it.
-
- >>> old_stat_float_times = os.stat_float_times()
- >>> os.stat_float_times(True)
- >>> def get_profiles():
- ... """Return the profile file names sorted by name.
- ...
- ... The time information is stripped out to avoid spurious test
- ... failures. The time resolution isn't great enough to reliably
- ... sort on it.
- ... """
- ... profiles = ['-'.join(name.split('-')[-4:])
- ... for name in os.listdir(profile_dir)]
- ... return sorted(profiles)
-
- >>> profiles = get_profiles()
- >>> print "\n".join(profiles)
- RootObject:index.html-OOPS-...-MainThread.prof
-
-Together with the profiling information, an OOPS report is also created.
-It's not really an OOPS, but the same format is re-used to make
-analyzing it easier.
-
- >>> from sys import stdout
- >>> from zope.error.interfaces import IErrorReportingUtility
- >>> logged_oops = getUtility(IErrorReportingUtility).getLastOopsReport()
- >>> logged_oops.write(stdout)
- Oops-Id: OOPS-...
- Exception-Type: ProfilingOops
- Exception-Value: None
- Date: ...
- Page-Id: RootObject:index.html
- Branch: ...
- Revision: ...
- User: ...
- URL: http://localhost/index.html
- ...
-
-The OOPS id is referenced in the profiling log's filename.
-
- >>> profiling_filename = profiles[0]
- >>> profiling_oops_id = '-'.join(profiling_filename.split('-')[1:3])
- >>> profiling_oops_id == logged_oops.id
- True
-
-Making another request will create another profile.
-
- >>> response = http('GET / HTTP/1.0')
-
- >>> print "\n".join(get_profiles())
- RootObject:index.html-OOPS-...-MainThread.prof
- RootObject:index.html-OOPS-...-MainThread.prof
-
-If the request resulted in an OOPS, the logged OOPS will have the real
-exception information, instead of the fake ProfilingOops one. Two files
-are logged. One for the first request in the slave store, and one for
-the retried request in the master store:
-
- >>> http('GET /no-such-file HTTP/1.0', handle_errors=False)
- Traceback (most recent call last):
- ...
- NotFound:...
- >>> print "\n".join(get_profiles())
- RootObject:index.html-OOPS-...-MainThread.prof
- RootObject:index.html-OOPS-...-MainThread.prof
- Unknown-OOPS-...-MainThread.prof
- Unknown-OOPS-...-MainThread.prof
-
- >>> oops = getUtility(IErrorReportingUtility).getLastOopsReport()
- >>> oops.write(stdout)
- Oops-Id: OOPS-...
- Exception-Type: NotFound
- ...
- URL: http://localhost/no-such-file
- ...
-
-
-== Memory profiling ==
+Profile files are named based on the time of the request start, the
+pageid, and the thread that processed it.
+
+Together with the profiling information, an informational OOPS report is
+usually also created.
+
+If the request actually resulted in an OOPS, the logged OOPS will have
+the real exception information, instead of being an informational
+ProfilingOops.
+
+In either case, the OOPS id is referenced in the profiling log's
+filename.
+
+Memory profiling
+================
It is possible to keep a log of the memory profile of the application. That's
useful to try to figure out what requests are causing the memory usage of the
server to increase.
-To create that log, you set the configuration variable memory_profile_log.
-
+This is not blessed for production use at this time: the implementation
+relies on lib/canonical/mem.py, which as of this writing warns in its
+docstring that "[n]one of this should be in day-to-day use." We should
+document the source of these concerns and evaluate them before using it in
+production. Staging may be more acceptable.
+
+Note that the data collected will be polluted by parallel requests: if
+memory increases in one request while another is also running in a different
+thread, both requests will show the increase.
+
+It also will probably be polluted by simultaneous use of the profiling
+options described above (`Profiling request in the app server`_).
+
+To turn this on, use the ``profiling_allowed`` setting described in the
+previous profiling section, and also set the ``memory_profile_log`` in
+the ``[profiling]`` section of ``launchpad-lazr.conf`` to a path to a
+log file.
+
+.. This ReST comment tests the assertion above that memory_profile_log is
+ the way to turn on memory profiling. It is intended to be a smoke test.
+ The real tests are in the lp/services/profile package.
+
+ >>> profile_dir = tempfile.mkdtemp(prefix='profile')
>>> memory_profile_log = os.path.join(profile_dir, 'memory.log')
+ >>> from textwrap import dedent
>>> config.push('memory_profile', dedent("""
... [profiling]
... profile_request: False
... memory_profile_log: %s""" % memory_profile_log))
-
-After each request is done, that log will have the timestamp of the request,
-the page id, the oops id, the duration, the starting VSS and RSS, and the
-ending VSS and RSS.
-
>>> response = http('GET / HTTP/1.0')
>>> memory_profile_fh = file(memory_profile_log)
>>> (timestamp, page_id, oops_id, duration,
@@ -220,63 +203,14 @@
>>> print timestamp
20...
>>> print oops_id
- OOPS-...
+ -
>>> print page_id
RootObject:index.html
-When an OOPS is triggered by the request, its identifier is logged:
-
- >>> http('GET /no-such-file HTTP/1.0', handle_errors=False)
- Traceback (most recent call last):
- ...
- NotFound:...
-
-Two lines are logged. The first one is for the request in the slave
-store. When that fails, the request is retried in the master store,
-causing another line to be logged.
-
- >>> (timestamp, page_id, first_oops_id, duration,
- ... start_vss, start_rss, end_vss, end_rss) = (
- ... memory_profile_fh.readline().split())
- >>> print first_oops_id
- OOPS-...
- >>> print page_id
- Unknown
-
- >>> (timestamp, page_id, second_oops_id, duration,
- ... start_vss, start_rss, end_vss, end_rss) = (
- ... memory_profile_fh.readline().split())
- >>> print second_oops_id
- OOPS-...
- >>> print page_id
- Unknown
-
-The logged OOPSes aren't the same.
-
- >>> first_oops_id == second_oops_id
- False
-
-The second OOPS has the real exception in its log, instead of the usual
-ProfilingOops one.
-
- >>> oops = getUtility(IErrorReportingUtility).getLastOopsReport()
- >>> oops.write(stdout)
- Oops-Id: OOPS-...
- Exception-Type: NotFound
- ...
- URL: http://localhost/no-such-file
- ...
-
-
-== Clean up ==
+.. ReST comment: this is clean up for the work done above.
>>> import shutil
-
>>> os.environ['PROFILE_PAGETESTS_REQUESTS'] = old_profile_environ
-
>>> shutil.rmtree(pagetests_profile_dir)
>>> shutil.rmtree(profile_dir)
-
- >>> old_config = config.pop('profile_dir')
-
- >>> os.stat_float_times(old_stat_float_times)
+ >>> old_config = config.pop('memory_profile')
=== modified file 'lib/canonical/launchpad/icing/style-3-0.css.in'
--- lib/canonical/launchpad/icing/style-3-0.css.in 2010-08-21 13:28:33 +0000
+++ lib/canonical/launchpad/icing/style-3-0.css.in 2010-08-26 22:55:56 +0000
@@ -220,7 +220,34 @@
hr {
display: none;
}
-
+div.profiling_info {
+ position: absolute;
+ top: 0;
+ left: 0;
+ border: 3px solid red;
+ background-color: white;
+ text-align: left;
+ padding: 1em;
+ }
+div.profiling_info h1 {
+ color: red;
+ }
+div.profiling_info h2 {
+ border-bottom: 3px solid gray;
+ color: black;
+ }
+div.profiling_info h3 {
+ border-bottom: 1px solid gray;
+ color: black;
+ }
+div.profiling_info p {
+ color: black;
+ }
+div.hide_reveal_profiling {
+ text-decoration: underline;
+ color: #093;
+ font-size: 85%;
+ }
/* =========================
Universal presentation
=== modified file 'lib/canonical/launchpad/webapp/errorlog.py'
--- lib/canonical/launchpad/webapp/errorlog.py 2010-08-20 20:31:18 +0000
+++ lib/canonical/launchpad/webapp/errorlog.py 2010-08-26 22:55:56 +0000
@@ -9,13 +9,10 @@
import contextlib
import datetime
-import errno
from itertools import repeat
import logging
-import os
import re
import rfc822
-import threading
import types
import urllib
@@ -64,12 +61,14 @@
# minute.
_rate_restrict_burst = 5
+
def _normalise_whitespace(s):
"""Normalise the whitespace in a string to spaces"""
if s is None:
return None
return ' '.join(s.split())
+
def _safestr(obj):
if isinstance(obj, unicode):
return obj.replace('\\', '\\\\').encode('ASCII',
@@ -85,14 +84,14 @@
'Error in ErrorReportingService while getting a str '
'representation of an object')
value = '<unprintable %s object>' % (
- str(type(obj).__name__)
- )
+ str(type(obj).__name__))
# encode non-ASCII characters
value = value.replace('\\', '\\\\')
value = re.sub(r'[\x80-\xff]',
lambda match: '\\x%02x' % ord(match.group(0)), value)
return value
+
def _is_sensitive(request, name):
"""Return True if the given request variable name is sensitive.
@@ -157,7 +156,7 @@
self.req_vars = req_vars
self.db_statements = db_statements
self.branch_nick = versioninfo.branch_nick
- self.revno = versioninfo.revno
+ self.revno = versioninfo.revno
self.informational = informational
def __repr__(self):
@@ -166,8 +165,10 @@
def get_chunks(self):
chunks = []
chunks.append('Oops-Id: %s\n' % _normalise_whitespace(self.id))
- chunks.append('Exception-Type: %s\n' % _normalise_whitespace(self.type))
- chunks.append('Exception-Value: %s\n' % _normalise_whitespace(self.value))
+ chunks.append(
+ 'Exception-Type: %s\n' % _normalise_whitespace(self.type))
+ chunks.append(
+ 'Exception-Value: %s\n' % _normalise_whitespace(self.value))
chunks.append('Date: %s\n' % self.time.isoformat())
chunks.append('Page-Id: %s\n' % _normalise_whitespace(self.pageid))
chunks.append('Branch: %s\n' % self.branch_nick)
@@ -205,7 +206,7 @@
duration = int(float(msg.getheader('duration', '-1')))
informational = msg.getheader('informational')
- # Explicitely use an iterator so we can process the file
+ # Explicitly use an iterator so we can process the file
# sequentially. In most instances the iterator will actually
# be the file object passed in because file objects should
# support iteration.
@@ -295,7 +296,7 @@
# the current log_namer naming rules and the exact timestamp.
oops_filename = self.log_namer.getFilename(serial_from_time, time)
# Note that if there were no logs written, or if there were two
- # oops that matched the time window of directory on disk, this
+ # oops that matched the time window of directory on disk, this
# call can raise an IOError.
oops_report = open(oops_filename, 'r')
try:
@@ -338,7 +339,8 @@
determined if not supplied. Useful for testing. Not part of
IErrorReportingUtility).
"""
- self._raising(info, request=request, now=now, informational=False)
+ return self._raising(
+ info, request=request, now=now, informational=False)
def _raising(self, info, request=None, now=None, informational=False):
"""Private method used by raising() and handling()."""
@@ -355,6 +357,7 @@
self._do_copy_to_zlog(
entry.time, entry.type, entry.url, info, entry.id)
notify(ErrorReportEvent(entry))
+ return entry
def _makeErrorReport(self, info, request=None, now=None,
informational=False):
@@ -472,7 +475,8 @@
:param now: The datetime to use as the current time. Will be
determined if not supplied. Useful for testing.
"""
- self._raising(info, request=request, now=now, informational=True)
+ return self._raising(
+ info, request=request, now=now, informational=True)
def _do_copy_to_zlog(self, now, strtype, url, info, oopsid):
distant_past = datetime.datetime(1970, 1, 1, 0, 0, 0, tzinfo=UTC)
=== modified file 'lib/lp/services/profile/configure.zcml'
--- lib/lp/services/profile/configure.zcml 2010-07-14 15:33:36 +0000
+++ lib/lp/services/profile/configure.zcml 2010-08-26 22:55:56 +0000
@@ -7,13 +7,18 @@
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"
/>
+ <!-- Create a namespace to request a profile. -->
+ <view
+ name="profile" type="*"
+ provides="zope.traversing.interfaces.ITraversable" for="*"
+ factory=".profile.ProfileNamespace"
+ />
+
</configure>
=== added file 'lib/lp/services/profile/profile.pt'
--- lib/lp/services/profile/profile.pt 1970-01-01 00:00:00 +0000
+++ lib/lp/services/profile/profile.pt 2010-08-26 22:55:56 +0000
@@ -0,0 +1,77 @@
+<div class="profiling_info">
+ <div class="hide_reveal_profiling" id="reveal_profiling">
+ Click to REVEAL profiling information
+ </div>
+</div>
+<div class="profiling_info" id="profiling_info">
+ <div class="hide_reveal_profiling" id="hide_profiling">
+ Click to HIDE profiling information
+ </div>
+ <h1>Profiling Information</h1>
+ <tal:block condition="'help' in actions">
+ <h2>Help</h2>
+ <p>Hi. I see you are using a <code>++profile++</code> request.
+ <tal:block condition="always_log">You have configured every request
+ to have a log, via the <code>profile_all_requests: True</code> in
+ the <code>[profiling]</code> section of your launchpad-lazr.conf, so
+ 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
+ <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>
+ </tal:block>
+ <h2>Log information</h2>
+ <tal:block condition="'log' not in actions">
+ <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).</p>
+ </tal:block>
+ <tal:block condition="'log' in actions">
+ <p tal:condition="always_log"><strong>You have configured every
+ request to have a full profile log</strong>, via the
+ <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
+ href="https://dev.launchpad.net/Debugging#Profiling%%20page%%20requests";
+ >dev wiki</a> may have more information on how to use this.</p>
+ </tal:block>
+ <h2>Profile quick view</h2>
+ <tal:block condition="'show' not in actions">
+ <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>
+ </tal:block>
+ <tal:block condition="'show' in actions">
+ <h3>Top Inline Time</h3>
+ <pre tal:content="inlinetime" />
+ <h3>Top Total Time</h3>
+ <pre tal:content="totaltime" />
+ <h3>Top Call Count</h3>
+ <pre tal:content="callcount" />
+ <h2>Raw OOPS Information</h2>
+ <pre tal:content="oops" />
+ </tal:block>
+</div>
+<script>
+LPS.use('node', 'lp', function (Y) {
+ Y.get('div#reveal_profiling').on('click', function (e) {
+ Y.get('div#profiling_info').setStyle('display', 'block');
+ });
+ Y.get('div#hide_profiling').on('click', function (e) {
+ Y.get('div#profiling_info').setStyle('display', 'none');
+ });
+});
+</script>
=== modified file 'lib/lp/services/profile/profile.py'
--- lib/lp/services/profile/profile.py 2010-08-20 20:31:18 +0000
+++ lib/lp/services/profile/profile.py 2010-08-26 22:55:56 +0000
@@ -10,13 +10,22 @@
from datetime import datetime
import os
import threading
+import StringIO
from bzrlib.lsprof import BzrProfiler
-from zope.component import getUtility
+from chameleon.zpt.template import PageTemplateFile
+from zope.app.publication.interfaces import IEndRequestEvent
+from zope.component import (
+ adapter,
+ getUtility,
+ )
+from zope.contenttype.parse import parse
from zope.error.interfaces import IErrorReportingUtility
+from zope.traversing.namespace import view
from canonical.config import config
import canonical.launchpad.webapp.adapter as da
+from canonical.launchpad.webapp.interfaces import IStartRequestEvent
from canonical.mem import (
memory,
resident,
@@ -30,22 +39,53 @@
_profilers = threading.local()
+@adapter(IStartRequestEvent)
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 not config.profiling.profiling_allowed:
+ return
+
+ actions = get_desired_profile_actions(event.request)
+ if config.profiling.profile_all_requests:
+ actions.add('log')
+ _profilers.actions = actions
+ _profilers.profiler = None
+
+ if actions:
+ 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()
+ _profilers.profiler.start()
if config.profiling.memory_profile_log:
_profilers.memory_profile_start = (memory(), resident())
-
+template = PageTemplateFile(
+ os.path.join(os.path.dirname(__file__), 'profile.pt'))
+
+
+@adapter(IEndRequestEvent)
def end_request(event):
"""If profiling is turned on, save profile data for the request."""
+ if not config.profiling.profiling_allowed:
+ return
+
+ try:
+ actions = _profilers.actions
+ except AttributeError:
+ # Some tests don't go through all the proper motions, like firing off
+ # a start request event. Just be quiet about it.
+ return
+
+ del _profilers.actions
+
request = event.request
# Create a timestamp including milliseconds.
now = datetime.fromtimestamp(da.get_request_start_time())
@@ -53,10 +93,23 @@
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()
+
+ content_type = request.response.getHeader('content-type')
+ if content_type is None:
+ content_type_params = {}
+ is_html = False
+ else:
+ _major, _minor, content_type_params = parse(content_type)
+ is_html = _major == 'text' and _minor == 'html'
+
+ template_context = {
+ 'actions': actions,
+ 'always_log': config.profiling.profile_all_requests}
+
+ if _profilers.profiler is not None:
+ prof_stats = _profilers.profiler.stop()
+ # Free some memory.
+ del _profilers.profiler
if oopsid is None:
# Log an OOPS to get a log of the SQL queries, and other
@@ -64,22 +117,48 @@
# 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
+ oops = error_utility.handling(info, request)
+ oopsid = oops.id
+ else:
+ oops = request.oops
+
+ if 'log' in actions:
+ 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")
+ template_context['dump_path'] = os.path.abspath(dump_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.sort(name)
+ f = StringIO.StringIO()
+ prof_stats.pprint(top=25, file=f)
+ template_context[name] = f.getvalue()
+
+ if actions and is_html:
+ # Hack the new HTML in at the end of the page.
+ encoding = content_type_params.get('charset', 'utf-8')
+ added_html = template.render(**template_context).encode(encoding)
+ existing_html = request.response.consumeBody()
+ e_start, e_close_body, e_end = existing_html.rpartition(
+ '</body>')
+ new_html = ''.join(
+ (e_start, added_html, e_close_body, e_end))
+ request.response.setResult(new_html)
# 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
+ del _profilers.memory_profile_start
vss_end, rss_end = memory(), resident()
if oopsid is None:
oopsid = '-'
@@ -87,3 +166,47 @@
timestamp, pageid, oopsid, da.get_request_duration(),
vss_start, rss_start, vss_end, rss_end))
log.close()
+
+
+def get_desired_profile_actions(request):
+ """What does the URL show that the user wants to do about profiling?
+
+ Returns a set of actions (comma-separated) if ++profile++ is in the
+ URL. Note that ++profile++ alone without actions is interpreted as
+ the "help" action.
+ """
+ result = set()
+ path_info = request.get('PATH_INFO')
+ if path_info:
+ # if not, this is almost certainly a test not bothering to set up
+ # certain bits. We'll handle it silently.
+ start, match, end = path_info.partition('/++profile++')
+ # We don't need no steenkin' regex.
+ if match:
+ # Now we figure out what actions are desired. Normally,
+ # parsing the url segment after the namespace ('++profile++'
+ # in this case) is done in the traverse method of the
+ # namespace view (see ProfileNamespace in this file). We
+ # are doing it separately because we want to know what to do
+ # before the traversal machinery gets started, so we can
+ # include traversal in the profile.
+ actions, slash, tail = end.partition('/')
+ result.update(
+ action for action in (
+ item.strip().lower() for item in actions.split(','))
+ if action)
+ result.intersection_update(('log', 'show'))
+ if not result:
+ result.add('help')
+ return result
+
+
+class ProfileNamespace(view):
+ """A see-through namespace that handles traversals with ++profile++."""
+
+ def traverse(self, name, remaining):
+ """Continue on with traversal.
+ """
+ # Note that handling the name is done in get_desired_profile_actions,
+ # above. See the comment in that function.
+ return self.context
=== added file 'lib/lp/services/profile/tests.py'
--- lib/lp/services/profile/tests.py 1970-01-01 00:00:00 +0000
+++ lib/lp/services/profile/tests.py 2010-08-26 22:55:56 +0000
@@ -0,0 +1,454 @@
+# Copyright 2010 Canonical Ltd. This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Tests for lp.services.profile.
+
+See lib/canonical/doc/profiling.txt for an end-user description of
+the functionality.
+"""
+
+__metaclass__ = type
+
+import glob
+import os
+import time
+import unittest
+
+from lp.testing import TestCase
+from bzrlib.lsprof import BzrProfiler
+from zope.app.publication.interfaces import EndRequestEvent
+from zope.component import getSiteManager
+
+import canonical.launchpad.webapp.adapter as da
+from canonical.launchpad.webapp.errorlog import (
+ ErrorReport,
+ ErrorReportingUtility,
+ )
+from canonical.launchpad.webapp.servers import LaunchpadTestRequest
+from canonical.launchpad.webapp.interfaces import StartRequestEvent
+from lp.services.profile import profile
+
+EXAMPLE_HTML_START = '''\
+<html><head><title>Random!</title></head>
+<body>
+<h1>Random!</h1>
+<p>Whatever!</p>
+'''
+EXAMPLE_HTML_END = '''\
+</body>
+</html>
+'''
+EXAMPLE_HTML = EXAMPLE_HTML_START + EXAMPLE_HTML_END
+
+
+class BaseTest(TestCase):
+
+ def _get_request(self, path='/'):
+ """Return a test request for the given path."""
+ return LaunchpadTestRequest(PATH_INFO=path)
+
+ def _get_start_event(self, path='/'):
+ """Return a start event for the given path."""
+ return StartRequestEvent(self._get_request(path))
+
+ def assertCleanProfilerState(self, message='something did not clean up'):
+ """Check whether profiler thread local is clean."""
+ for name in ('profiler', 'actions', 'memory_profile_start'):
+ self.assertIs(
+ getattr(profile._profilers, name, None), None,
+ 'Profiler state (%s) is dirty; %s.' % (name, message))
+
+ def pushProfilingConfig(
+ self, profiling_allowed='False', profile_all_requests='False',
+ memory_profile_log=''):
+ """This is a convenience for setting profile configs."""
+ self.pushConfig(
+ 'profiling',
+ profiling_allowed=profiling_allowed,
+ profile_all_requests=profile_all_requests,
+ memory_profile_log=memory_profile_log)
+
+
+class TestRequestStartHandler(BaseTest):
+ """Tests for the start handler of the profiler integration.
+
+ See lib/canonical/doc/profiling.txt for an end-user description of
+ the functionality.
+ """
+
+ def tearDown(self):
+ "Do the usual tearDown, plus clean up the profiler object."
+ if getattr(profile._profilers, 'profiler', None) is not None:
+ profile._profilers.profiler.stop()
+ del profile._profilers.profiler
+ for name in ('actions', 'memory_profile_start'):
+ if getattr(profile._profilers, name, None) is not None:
+ delattr(profile._profilers, name)
+ TestCase.tearDown(self)
+
+ def test_config_stops_profiling(self):
+ """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='.')
+ profile.start_request(self._get_start_event('/++profile++show,log'))
+ 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."""
+ self.pushProfilingConfig(profiling_allowed='True')
+ profile.start_request(self._get_start_event('/'))
+ self.assertEqual(profile._profilers.actions, set())
+ self.assertIs(getattr(profile._profilers, 'profiler', None), None)
+ self.assertIs(
+ 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."""
+ self.pushProfilingConfig(profiling_allowed='True')
+ profile.start_request(self._get_start_event('/++profile++show/'))
+ self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
+ self.assertIs(
+ getattr(profile._profilers, 'memory_profile_start', None),
+ None)
+ self.assertEquals(profile._profilers.actions, set(('show', )))
+
+ 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."""
+ 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', )))
+
+ 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."""
+ self.pushProfilingConfig(profiling_allowed='True')
+ profile.start_request(self._get_start_event('/++profile++log,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')))
+
+ 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."""
+ 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')))
+
+ def test_forced_profiling_registers_action(self):
+ """profile_all_requests should register as a log action"""
+ self.pushProfilingConfig(
+ profiling_allowed='True', profile_all_requests='True')
+ profile.start_request(self._get_start_event('/'))
+ self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
+ self.assertIs(
+ getattr(profile._profilers, 'memory_profile_start', None),
+ None)
+ self.assertEquals(profile._profilers.actions, set(('log', )))
+
+ 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')
+ profile.start_request(self._get_start_event('/++profile++/'))
+ 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', )))
+
+ 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')
+ profile.start_request(self._get_start_event('/++profile++/'))
+ self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
+ self.assertIs(
+ getattr(profile._profilers, 'memory_profile_start', None),
+ None)
+ self.assertEquals(profile._profilers.actions, set(('help', 'log')))
+
+ def test_memory_profile_start(self):
+ self.pushProfilingConfig(
+ profiling_allowed='True', memory_profile_log='.')
+ profile.start_request(self._get_start_event('/'))
+ self.assertIs(getattr(profile._profilers, 'profiler', None), None)
+ self.assertIsInstance(profile._profilers.memory_profile_start, tuple)
+ self.assertEqual(len(profile._profilers.memory_profile_start), 2)
+ self.assertEqual(profile._profilers.actions, set())
+
+ def test_combo_memory_and_profile_start(self):
+ 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.memory_profile_start, tuple)
+ self.assertEqual(len(profile._profilers.memory_profile_start), 2)
+ 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.
+ """
+
+ def setUp(self):
+ TestCase.setUp(self)
+ self.patch(da, 'get_request_start_time', time.time)
+ self.patch(da, 'get_request_duration', lambda: 0.5)
+ self.profile_dir = self.makeTemporaryDirectory()
+ self.memory_profile_log = os.path.join(self.profile_dir, 'memory_log')
+ self.pushConfig('profiling', profile_dir=self.profile_dir)
+ self.eru = ErrorReportingUtility()
+ sm = getSiteManager()
+ 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."""
+ 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)
+ context = object()
+ return EndRequestEvent(context, request)
+
+ def endRequest(self, path='/', exception=None, pageid=None):
+ event = self._get_end_event(path, pageid=pageid)
+ if exception is not None:
+ self.eru.raising(
+ (type(exception), exception, None), event.request)
+ profile.end_request(event)
+ return event.request
+
+ def getAddedResponse(self, request,
+ start=EXAMPLE_HTML_START, end=EXAMPLE_HTML_END):
+ output = request.response.consumeBody()
+ return output[len(start):-len(end)]
+
+ def getMemoryLog(self):
+ if not os.path.exists(self.memory_profile_log):
+ return []
+ f = open(self.memory_profile_log)
+ result = f.readlines()
+ f.close()
+ return result
+
+ def getProfilePaths(self):
+ return glob.glob(os.path.join(self.profile_dir, '*.prof'))
+
+ #########################################################################
+ # Tests
+ def test_config_stops_profiling(self):
+ """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')
+ self.assertIs(getattr(request, 'oops', None), None)
+ self.assertEqual(self.getAddedResponse(request), '')
+ self.assertEqual(self.getMemoryLog(), [])
+ self.assertEqual(self.getProfilePaths(), [])
+ 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."""
+ self.pushProfilingConfig(profiling_allowed='True')
+ request = self.endRequest('/')
+ self.assertIs(getattr(request, 'oops', None), None)
+ self.assertEqual(self.getAddedResponse(request), '')
+ self.assertEqual(self.getMemoryLog(), [])
+ self.assertEqual(self.getProfilePaths(), [])
+ self.assertCleanProfilerState()
+
+ 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_log_request_profiles(self):
+ """If profiling is allowed and a request with the "log" marker
+ URL segment is made, profiling starts."""
+ self.pushProfilingConfig(profiling_allowed='True')
+ request = self.endRequest('/++profile++log/')
+ 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()
+
+ 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."""
+ self.pushProfilingConfig(profiling_allowed='True')
+ request = self.endRequest('/++profile++log,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()
+
+ 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()
+
+ def test_memory_profile(self):
+ "Does the memory profile work?"
+ self.pushProfilingConfig(
+ profiling_allowed='True',
+ memory_profile_log=self.memory_profile_log)
+ request = self.endRequest('/')
+ self.assertIs(getattr(request, 'oops', None), None)
+ self.assertEqual(self.getAddedResponse(request), '')
+ log = self.getMemoryLog()
+ self.assertEqual(len(log), 1)
+ (timestamp, page_id, oops_id, duration, start_vss, start_rss,
+ end_vss, end_rss) = log[0].split()
+ self.assertEqual(page_id, 'Unknown')
+ self.assertEqual(oops_id, '-')
+ self.assertEqual(float(duration), 0.5)
+ self.assertEqual(self.getProfilePaths(), [])
+ self.assertCleanProfilerState()
+
+ def test_memory_profile_with_non_defaults(self):
+ "Does the memory profile work with an oops and pageid?"
+ self.pushProfilingConfig(
+ profiling_allowed='True',
+ memory_profile_log=self.memory_profile_log)
+ request = self.endRequest('/++profile++show/no-such-file',
+ KeyError(), pageid='Foo')
+ log = self.getMemoryLog()
+ (timestamp, page_id, oops_id, duration, start_vss, start_rss,
+ end_vss, end_rss) = log[0].split()
+ self.assertEqual(page_id, 'Foo')
+ self.assertEqual(oops_id, request.oopsid)
+ self.assertCleanProfilerState()
+
+ def test_combo_memory_and_profile(self):
+ self.pushProfilingConfig(
+ profiling_allowed='True',
+ memory_profile_log=self.memory_profile_log)
+ request = self.endRequest('/++profile++show/')
+ self.assertIsInstance(request.oops, ErrorReport)
+ self.assertIn('Top Inline Time', self.getAddedResponse(request))
+ self.assertEqual(len(self.getMemoryLog()), 1)
+ self.assertEqual(self.getProfilePaths(), [])
+ self.assertCleanProfilerState()
+
+ 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')
+ self.assertCleanProfilerState()
+
+ def test_real_oops_trumps_profiling_oops(self):
+ self.pushProfilingConfig(profiling_allowed='True')
+ request = self.endRequest('/++profile++show/no-such-file',
+ KeyError('foo'))
+ self.assertIsInstance(request.oops, ErrorReport)
+ self.assertFalse(request.oops.informational)
+ self.assertEquals(request.oops.type, 'KeyError')
+ response = self.getAddedResponse(request)
+ self.assertIn('Exception-Type: KeyError', response)
+ self.assertCleanProfilerState()
+
+ def test_oopsid_is_in_profile_filename(self):
+ self.pushProfilingConfig(profiling_allowed='True')
+ request = self.endRequest('/++profile++log/')
+ self.assertIn("-" + request.oopsid + "-", self.getProfilePaths()[0])
+ self.assertCleanProfilerState()
+
+
+def test_suite():
+ return unittest.TestLoader().loadTestsFromName(__name__)
