Launchpad itself

Merge lp:~gary/launchpad/lsprof-on-demand into lp:launchpad

  1. lsprof-on-demand
  2. Merge into devel
Proposed by Gary Poster
Status: Merged
Approved by: Robert Collins
Approved revision: no longer in the source branch.
Merged at revision: 11465
Proposed branch: lp:~gary/launchpad/lsprof-on-demand
Merge into: lp:launchpad
Diff against target: 1324 lines (+840/-215)
11 files modified
.bzrignore (+1/-0)
configs/development/apidoc-configure-normal.zcml (+6/-0)
configs/development/launchpad-lazr.conf (+3/-0)
lib/canonical/config/schema-lazr.conf (+8/-2)
lib/canonical/launchpad/doc/profiling.txt (+109/-175)
lib/canonical/launchpad/icing/style-3-0.css.in (+28/-1)
lib/canonical/launchpad/webapp/errorlog.py (+16/-12)
lib/lp/services/profile/configure.zcml (+7/-2)
lib/lp/services/profile/profile.pt (+77/-0)
lib/lp/services/profile/profile.py (+131/-23)
lib/lp/services/profile/tests.py (+454/-0)
To merge this branch: bzr merge lp:~gary/launchpad/lsprof-on-demand
Reviewer Review Type Date Requested Status
Robert Collins (community) Approve
Review via email: mp+33849@code.launchpad.net

Commit message

add profiling-in-demand via a ++profile++ URL hook

Description of the change

= 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.

To post a comment you must log in.
Revision history for this message
Robert Collins (lifeless) wrote :

This is awesome, thanks for doing it. We discussed some stuff on IRC, but its all future-stuff. +1

review: Approve
Revision history for this message
Robert Collins (lifeless) wrote :

11:43 < lifeless> gary_poster: there was one other thing
11:43 < lifeless> the 'tests are not setting stuff up so ignore it' squicks me; I realise why, and the pragmatic need, but I'd like to be able to put a ratchet on those tests and eliminate the badness.
11:44 < gary_poster> lifeless: not clear what you mean yet?
11:44 < gary_poster> oh!
11:44 < gary_poster> yeah that was annoying
11:44 < gary_poster> what do you have in mind for ratcheting?
11:44 < lifeless> well
11:44 < lifeless> depends on how widespread it is I guess
11:45 < lifeless> if its only a few root causes, like some test helpers, we could just do warning.warn() in a branch, and iterate on the branch till its done.
11:45 < lifeless> if its more substantial, perhaps starting the test suite could empty a file
11:45 < lifeless> and each occurence be logged (one line per)
11:46 < lifeless> and the total number of lines reported at the end
11:46 < gary_poster> between a few and several. I have to run though. Please copy that in to the MP and I'll act on it tomorrow.
11:46 < lifeless> lint could report if that file is longer than N

This can be done in a separate branch; or just chat with me your monday about this (it affects other things in webapp.* too, I suspect). I was running into remarkable pain with a similar cause, and so was Martin Pool with his flags stuff.

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
=== modified file '.bzrignore'
--- .bzrignore 2010-08-12 13:17:05 +0000
+++ .bzrignore 2010-08-27 14:23:44 +0000
@@ -77,3 +77,4 @@
77lib/canonical/launchpad-buildd_*_source.changes77lib/canonical/launchpad-buildd_*_source.changes
78lib/canonical/buildd/debian/*78lib/canonical/buildd/debian/*
79lib/canonical/buildd/launchpad-files/*79lib/canonical/buildd/launchpad-files/*
80*.pt.py
8081
=== 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-27 14:23:44 +0000
@@ -120,5 +120,11 @@
120 doc_path="../../doc/buildout.txt"120 doc_path="../../doc/buildout.txt"
121 parent="lp"121 parent="lp"
122 />122 />
123 <apidoc:bookchapter
124 id="profiling"
125 title="Profiling"
126 doc_path="../../lib/canonical/launchpad/doc/profiling.txt"
127 parent="lp"
128 />
123129
124</configure>130</configure>
125131
=== 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-27 14:23:44 +0000
@@ -246,6 +246,9 @@
246[process_apport_blobs]246[process_apport_blobs]
247error_dir: /var/tmp/lperr247error_dir: /var/tmp/lperr
248248
249[profiling]
250profiling_allowed: True
251
249[supermirror_puller]252[supermirror_puller]
250error_dir: /var/tmp/codehosting.test253error_dir: /var/tmp/codehosting.test
251oops_prefix: SMP254oops_prefix: SMP
252255
=== 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-27 14:23:44 +0000
@@ -1642,10 +1642,16 @@
16421642
16431643
1644[profiling]1644[profiling]
1645# When set to True, the user is allowed to request profiles be run for
1646# either individual pages or for every request sent.
1647# datatype: boolean
1648profiling_allowed: False
1649
1645# When set to True, each requests will be profiled and the resulting data1650# When set to True, each requests will be profiled and the resulting data
1646# saved in profile_dir.1651# saved in profile_dir. `profiling_allowed` must also be True for this to
1652# work.
1647# datatype: boolean1653# datatype: boolean
1648profile_requests: False1654profile_all_requests: False
16491655
1650# Directory to save profile info. The filename is in the format1656# Directory to save profile info. The filename is in the format
1651# <timestamp>-<threadName>.prof1657# <timestamp>-<threadName>.prof
16521658
=== 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-27 14:23:44 +0000
@@ -1,8 +1,15 @@
1= Profiling support =1=================
2Profiling support
3=================
4
5.. ReST Comment: this is intended to be a true DOC test, with an emphasis on
6 documentation. Of the three sections, the last two have been adjusted for
7 this goal.
28
3Launchpad supports three modes of profiling.9Launchpad supports three modes of profiling.
410
5== Profiling requests in pagetests ==11Profiling requests in pagetests
12===============================
613
7Our testing framework has support for profiling requests made in14Our testing framework has support for profiling requests made in
8pagetests. When the PROFILE_PAGETESTS_REQUESTS environment variable is15pagetests. When the PROFILE_PAGETESTS_REQUESTS environment variable is
@@ -76,142 +83,118 @@
76 False83 False
7784
7885
79== Profiling request in the app server ==86Profiling request in the app server
87===================================
8088
81It is also possible to get a profile of each request served by the app89It is also possible to get a profile of requests served by the app
82server.90server.
8391
84This is controlled by the [profiling] config section. Profiling is92*Important*: This is not blessed for production, primarily because of
85controlled by the profile_requests configuration variable. When this is93the typical cost of employing a profiling hook. Also, profiled requests
86True, each request will create a pstats file for the request in the94are forced to run in serial. This is also a concern for production
87directory specified in the profile_dir variable.95usage, since some of our requests can take much longer than others.
8896
89By default profiling is turned off.97It might be fine to occasionally turn on in staging; that is more
9098negotiable, at least. LOSAs will need to vet the feature to see if they are
91 >>> from canonical.config import config99concerned about it giving too much information about our staging system.
92 >>> config.profiling.profile_requests100
101The feature has two modes.
102
103- It can be configured to optionally profile requests. To turn this on, in
104 ``launchpad-lazr.conf`` (e.g.,
105 ``configs/development/launchpad-lazr.conf``) , in the ``[profiling]``
106 section, set ``profiling_allowed: True``. As of this writing, this
107 is the default value for development.
108
109 Once it is turned on, you can insert /++profile++/ in the URL to get
110 basic instructions on how to use the feature. You use the
111 ``launchpad-lazr.conf`` ``profile_dir`` setting to determine what
112 directory will receive written profiles.
113
114.. This ReST comment tests the assertion above that profiling_allowed is
115 True by default for tests and development.
116
117 >>> from canonical.config import config
118 >>> config.profiling.profiling_allowed
119 True
120
121 Similarly, this tests that, in a fully set-up environment, the
122 profiling machinery that is coded and unit-tested in
123 lp/services/profile is hooked up properly. This is intended to be a
124 smoke test. The unit tests verify further functionality.
125
126 >>> response = http('GET /++profile++ HTTP/1.0')
127 >>> '<h1>Profiling Information</h1>' in response.getBody()
128 True
129
130- It can be configured to profile all requests, indiscriminately. To turn
131 this on, use the ``profiling_allowed`` setting described in option 1
132 above and also set ``profile_all_requests: True`` in the
133 ``[profiling]`` section of ``launchpad-lazr.conf``. This is turned
134 off by default. As with the first option, you use the
135 ``profile_dir`` setting to determine what directory will receive the
136 profiles.
137
138 Once it is turned on, every request will create a profiling log usable
139 with KCacheGrind. The browser will include information on the file
140 created for that request.
141
142.. This ReST comment tests the assertion above that profile_all_requests is
143 False by default for tests and development.
144
145 >>> from canonical.config import config
146 >>> config.profiling.profile_all_requests
93 False147 False
94148
95(Set the profile directory.)149Profile files are named based on the time of the request start, the
96150pageid, and the thread that processed it.
97 >>> from textwrap import dedent151
98 >>> profile_dir = tempfile.mkdtemp(prefix='profile')152Together with the profiling information, an informational OOPS report is
99 >>> config.push('profile_dir', dedent("""153usually also created.
100 ... [profiling]154
101 ... profile_dir: %s""" % profile_dir))155If the request actually resulted in an OOPS, the logged OOPS will have
102156the real exception information, instead of being an informational
103So when making a request, no profile information is created.157ProfilingOops.
104158
105 >>> response = http('GET / HTTP/1.0')159In either case, the OOPS id is referenced in the profiling log's
106160filename.
107 >>> list(os.listdir(profile_dir))161
108 []162Memory profiling
109163================
110But if profiling is turned on, profiling data will be created in the
111directory for the request.
112
113 >>> config.push('profile_on', dedent("""\
114 ... [profiling]
115 ... profile_requests: True"""))
116
117 >>> response = http('GET / HTTP/1.0')
118
119The profile is named on the time of the request start, the pageid, and
120the thread that processed it.
121
122 >>> old_stat_float_times = os.stat_float_times()
123 >>> os.stat_float_times(True)
124 >>> def get_profiles():
125 ... """Return the profile file names sorted by name.
126 ...
127 ... The time information is stripped out to avoid spurious test
128 ... failures. The time resolution isn't great enough to reliably
129 ... sort on it.
130 ... """
131 ... profiles = ['-'.join(name.split('-')[-4:])
132 ... for name in os.listdir(profile_dir)]
133 ... return sorted(profiles)
134
135 >>> profiles = get_profiles()
136 >>> print "\n".join(profiles)
137 RootObject:index.html-OOPS-...-MainThread.prof
138
139Together with the profiling information, an OOPS report is also created.
140It's not really an OOPS, but the same format is re-used to make
141analyzing it easier.
142
143 >>> from sys import stdout
144 >>> from zope.error.interfaces import IErrorReportingUtility
145 >>> logged_oops = getUtility(IErrorReportingUtility).getLastOopsReport()
146 >>> logged_oops.write(stdout)
147 Oops-Id: OOPS-...
148 Exception-Type: ProfilingOops
149 Exception-Value: None
150 Date: ...
151 Page-Id: RootObject:index.html
152 Branch: ...
153 Revision: ...
154 User: ...
155 URL: http://localhost/index.html
156 ...
157
158The OOPS id is referenced in the profiling log's filename.
159
160 >>> profiling_filename = profiles[0]
161 >>> profiling_oops_id = '-'.join(profiling_filename.split('-')[1:3])
162 >>> profiling_oops_id == logged_oops.id
163 True
164
165Making another request will create another profile.
166
167 >>> response = http('GET / HTTP/1.0')
168
169 >>> print "\n".join(get_profiles())
170 RootObject:index.html-OOPS-...-MainThread.prof
171 RootObject:index.html-OOPS-...-MainThread.prof
172
173If the request resulted in an OOPS, the logged OOPS will have the real
174exception information, instead of the fake ProfilingOops one. Two files
175are logged. One for the first request in the slave store, and one for
176the retried request in the master store:
177
178 >>> http('GET /no-such-file HTTP/1.0', handle_errors=False)
179 Traceback (most recent call last):
180 ...
181 NotFound:...
182 >>> print "\n".join(get_profiles())
183 RootObject:index.html-OOPS-...-MainThread.prof
184 RootObject:index.html-OOPS-...-MainThread.prof
185 Unknown-OOPS-...-MainThread.prof
186 Unknown-OOPS-...-MainThread.prof
187
188 >>> oops = getUtility(IErrorReportingUtility).getLastOopsReport()
189 >>> oops.write(stdout)
190 Oops-Id: OOPS-...
191 Exception-Type: NotFound
192 ...
193 URL: http://localhost/no-such-file
194 ...
195
196
197== Memory profiling ==
198164
199It is possible to keep a log of the memory profile of the application. That's165It is possible to keep a log of the memory profile of the application. That's
200useful to try to figure out what requests are causing the memory usage of the166useful to try to figure out what requests are causing the memory usage of the
201server to increase.167server to increase.
202168
203To create that log, you set the configuration variable memory_profile_log.169This is not blessed for production use at this time: the implementation
204170relies on lib/canonical/mem.py, which as of this writing warns in its
171docstring that "[n]one of this should be in day-to-day use." We should
172document the source of these concerns and evaluate them before using it in
173production. Staging may be more acceptable.
174
175Note that the data collected will be polluted by parallel requests: if
176memory increases in one request while another is also running in a different
177thread, both requests will show the increase.
178
179It also will probably be polluted by simultaneous use of the profiling
180options described above (`Profiling request in the app server`_).
181
182To turn this on, use the ``profiling_allowed`` setting described in the
183previous profiling section, and also set the ``memory_profile_log`` in
184the ``[profiling]`` section of ``launchpad-lazr.conf`` to a path to a
185log file.
186
187.. This ReST comment tests the assertion above that memory_profile_log is
188 the way to turn on memory profiling. It is intended to be a smoke test.
189 The real tests are in the lp/services/profile package.
190
191 >>> profile_dir = tempfile.mkdtemp(prefix='profile')
205 >>> memory_profile_log = os.path.join(profile_dir, 'memory.log')192 >>> memory_profile_log = os.path.join(profile_dir, 'memory.log')
193 >>> from textwrap import dedent
206 >>> config.push('memory_profile', dedent("""194 >>> config.push('memory_profile', dedent("""
207 ... [profiling]195 ... [profiling]
208 ... profile_request: False196 ... profile_request: False
209 ... memory_profile_log: %s""" % memory_profile_log))197 ... memory_profile_log: %s""" % memory_profile_log))
210
211After each request is done, that log will have the timestamp of the request,
212the page id, the oops id, the duration, the starting VSS and RSS, and the
213ending VSS and RSS.
214
215 >>> response = http('GET / HTTP/1.0')198 >>> response = http('GET / HTTP/1.0')
216 >>> memory_profile_fh = file(memory_profile_log)199 >>> memory_profile_fh = file(memory_profile_log)
217 >>> (timestamp, page_id, oops_id, duration,200 >>> (timestamp, page_id, oops_id, duration,
@@ -220,63 +203,14 @@
220 >>> print timestamp203 >>> print timestamp
221 20...204 20...
222 >>> print oops_id205 >>> print oops_id
223 OOPS-...206 -
224 >>> print page_id207 >>> print page_id
225 RootObject:index.html208 RootObject:index.html
226209
227When an OOPS is triggered by the request, its identifier is logged:210.. ReST comment: this is clean up for the work done above.
228
229 >>> http('GET /no-such-file HTTP/1.0', handle_errors=False)
230 Traceback (most recent call last):
231 ...
232 NotFound:...
233
234Two lines are logged. The first one is for the request in the slave
235store. When that fails, the request is retried in the master store,
236causing another line to be logged.
237
238 >>> (timestamp, page_id, first_oops_id, duration,
239 ... start_vss, start_rss, end_vss, end_rss) = (
240 ... memory_profile_fh.readline().split())
241 >>> print first_oops_id
242 OOPS-...
243 >>> print page_id
244 Unknown
245
246 >>> (timestamp, page_id, second_oops_id, duration,
247 ... start_vss, start_rss, end_vss, end_rss) = (
248 ... memory_profile_fh.readline().split())
249 >>> print second_oops_id
250 OOPS-...
251 >>> print page_id
252 Unknown
253
254The logged OOPSes aren't the same.
255
256 >>> first_oops_id == second_oops_id
257 False
258
259The second OOPS has the real exception in its log, instead of the usual
260ProfilingOops one.
261
262 >>> oops = getUtility(IErrorReportingUtility).getLastOopsReport()
263 >>> oops.write(stdout)
264 Oops-Id: OOPS-...
265 Exception-Type: NotFound
266 ...
267 URL: http://localhost/no-such-file
268 ...
269
270
271== Clean up ==
272211
273 >>> import shutil212 >>> import shutil
274
275 >>> os.environ['PROFILE_PAGETESTS_REQUESTS'] = old_profile_environ213 >>> os.environ['PROFILE_PAGETESTS_REQUESTS'] = old_profile_environ
276
277 >>> shutil.rmtree(pagetests_profile_dir)214 >>> shutil.rmtree(pagetests_profile_dir)
278 >>> shutil.rmtree(profile_dir)215 >>> shutil.rmtree(profile_dir)
279216 >>> old_config = config.pop('memory_profile')
280 >>> old_config = config.pop('profile_dir')
281
282 >>> os.stat_float_times(old_stat_float_times)
283217
=== modified file 'lib/canonical/launchpad/icing/style-3-0.css.in'
--- lib/canonical/launchpad/icing/style-3-0.css.in 2010-08-27 03:56:44 +0000
+++ lib/canonical/launchpad/icing/style-3-0.css.in 2010-08-27 14:23:44 +0000
@@ -221,7 +221,34 @@
221hr {221hr {
222 display: none;222 display: none;
223 }223 }
224224div.profiling_info {
225 position: absolute;
226 top: 0;
227 left: 0;
228 border: 3px solid red;
229 background-color: white;
230 text-align: left;
231 padding: 1em;
232 }
233div.profiling_info h1 {
234 color: red;
235 }
236div.profiling_info h2 {
237 border-bottom: 3px solid gray;
238 color: black;
239 }
240div.profiling_info h3 {
241 border-bottom: 1px solid gray;
242 color: black;
243 }
244div.profiling_info p {
245 color: black;
246 }
247div.hide_reveal_profiling {
248 text-decoration: underline;
249 color: #093;
250 font-size: 85%;
251 }
225252
226/* =========================253/* =========================
227 Universal presentation254 Universal presentation
228255
=== 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-27 14:23:44 +0000
@@ -9,13 +9,10 @@
99
10import contextlib10import contextlib
11import datetime11import datetime
12import errno
13from itertools import repeat12from itertools import repeat
14import logging13import logging
15import os
16import re14import re
17import rfc82215import rfc822
18import threading
19import types16import types
20import urllib17import urllib
2118
@@ -64,12 +61,14 @@
64# minute.61# minute.
65_rate_restrict_burst = 562_rate_restrict_burst = 5
6663
64
67def _normalise_whitespace(s):65def _normalise_whitespace(s):
68 """Normalise the whitespace in a string to spaces"""66 """Normalise the whitespace in a string to spaces"""
69 if s is None:67 if s is None:
70 return None68 return None
71 return ' '.join(s.split())69 return ' '.join(s.split())
7270
71
73def _safestr(obj):72def _safestr(obj):
74 if isinstance(obj, unicode):73 if isinstance(obj, unicode):
75 return obj.replace('\\', '\\\\').encode('ASCII',74 return obj.replace('\\', '\\\\').encode('ASCII',
@@ -85,14 +84,14 @@
85 'Error in ErrorReportingService while getting a str '84 'Error in ErrorReportingService while getting a str '
86 'representation of an object')85 'representation of an object')
87 value = '<unprintable %s object>' % (86 value = '<unprintable %s object>' % (
88 str(type(obj).__name__)87 str(type(obj).__name__))
89 )
90 # encode non-ASCII characters88 # encode non-ASCII characters
91 value = value.replace('\\', '\\\\')89 value = value.replace('\\', '\\\\')
92 value = re.sub(r'[\x80-\xff]',90 value = re.sub(r'[\x80-\xff]',
93 lambda match: '\\x%02x' % ord(match.group(0)), value)91 lambda match: '\\x%02x' % ord(match.group(0)), value)
94 return value92 return value
9593
94
96def _is_sensitive(request, name):95def _is_sensitive(request, name):
97 """Return True if the given request variable name is sensitive.96 """Return True if the given request variable name is sensitive.
9897
@@ -157,7 +156,7 @@
157 self.req_vars = req_vars156 self.req_vars = req_vars
158 self.db_statements = db_statements157 self.db_statements = db_statements
159 self.branch_nick = versioninfo.branch_nick158 self.branch_nick = versioninfo.branch_nick
160 self.revno = versioninfo.revno159 self.revno = versioninfo.revno
161 self.informational = informational160 self.informational = informational
162161
163 def __repr__(self):162 def __repr__(self):
@@ -166,8 +165,10 @@
166 def get_chunks(self):165 def get_chunks(self):
167 chunks = []166 chunks = []
168 chunks.append('Oops-Id: %s\n' % _normalise_whitespace(self.id))167 chunks.append('Oops-Id: %s\n' % _normalise_whitespace(self.id))
169 chunks.append('Exception-Type: %s\n' % _normalise_whitespace(self.type))168 chunks.append(
170 chunks.append('Exception-Value: %s\n' % _normalise_whitespace(self.value))169 'Exception-Type: %s\n' % _normalise_whitespace(self.type))
170 chunks.append(
171 'Exception-Value: %s\n' % _normalise_whitespace(self.value))
171 chunks.append('Date: %s\n' % self.time.isoformat())172 chunks.append('Date: %s\n' % self.time.isoformat())
172 chunks.append('Page-Id: %s\n' % _normalise_whitespace(self.pageid))173 chunks.append('Page-Id: %s\n' % _normalise_whitespace(self.pageid))
173 chunks.append('Branch: %s\n' % self.branch_nick)174 chunks.append('Branch: %s\n' % self.branch_nick)
@@ -205,7 +206,7 @@
205 duration = int(float(msg.getheader('duration', '-1')))206 duration = int(float(msg.getheader('duration', '-1')))
206 informational = msg.getheader('informational')207 informational = msg.getheader('informational')
207208
208 # Explicitely use an iterator so we can process the file209 # Explicitly use an iterator so we can process the file
209 # sequentially. In most instances the iterator will actually210 # sequentially. In most instances the iterator will actually
210 # be the file object passed in because file objects should211 # be the file object passed in because file objects should
211 # support iteration.212 # support iteration.
@@ -295,7 +296,7 @@
295 # the current log_namer naming rules and the exact timestamp.296 # the current log_namer naming rules and the exact timestamp.
296 oops_filename = self.log_namer.getFilename(serial_from_time, time)297 oops_filename = self.log_namer.getFilename(serial_from_time, time)
297 # Note that if there were no logs written, or if there were two298 # Note that if there were no logs written, or if there were two
298 # oops that matched the time window of directory on disk, this 299 # oops that matched the time window of directory on disk, this
299 # call can raise an IOError.300 # call can raise an IOError.
300 oops_report = open(oops_filename, 'r')301 oops_report = open(oops_filename, 'r')
301 try:302 try:
@@ -338,7 +339,8 @@
338 determined if not supplied. Useful for testing. Not part of339 determined if not supplied. Useful for testing. Not part of
339 IErrorReportingUtility).340 IErrorReportingUtility).
340 """341 """
341 self._raising(info, request=request, now=now, informational=False)342 return self._raising(
343 info, request=request, now=now, informational=False)
342344
343 def _raising(self, info, request=None, now=None, informational=False):345 def _raising(self, info, request=None, now=None, informational=False):
344 """Private method used by raising() and handling()."""346 """Private method used by raising() and handling()."""
@@ -355,6 +357,7 @@
355 self._do_copy_to_zlog(357 self._do_copy_to_zlog(
356 entry.time, entry.type, entry.url, info, entry.id)358 entry.time, entry.type, entry.url, info, entry.id)
357 notify(ErrorReportEvent(entry))359 notify(ErrorReportEvent(entry))
360 return entry
358361
359 def _makeErrorReport(self, info, request=None, now=None,362 def _makeErrorReport(self, info, request=None, now=None,
360 informational=False):363 informational=False):
@@ -472,7 +475,8 @@
472 :param now: The datetime to use as the current time. Will be475 :param now: The datetime to use as the current time. Will be
473 determined if not supplied. Useful for testing.476 determined if not supplied. Useful for testing.
474 """477 """
475 self._raising(info, request=request, now=now, informational=True)478 return self._raising(
479 info, request=request, now=now, informational=True)
476480
477 def _do_copy_to_zlog(self, now, strtype, url, info, oopsid):481 def _do_copy_to_zlog(self, now, strtype, url, info, oopsid):
478 distant_past = datetime.datetime(1970, 1, 1, 0, 0, 0, tzinfo=UTC)482 distant_past = datetime.datetime(1970, 1, 1, 0, 0, 0, tzinfo=UTC)
479483
=== 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-27 14:23:44 +0000
@@ -7,13 +7,18 @@
7 xmlns:browser="http://namespaces.zope.org/browser">7 xmlns:browser="http://namespaces.zope.org/browser">
88
9 <subscriber9 <subscriber
10 for="canonical.launchpad.webapp.interfaces.IStartRequestEvent"
11 handler="lp.services.profile.profile.start_request"10 handler="lp.services.profile.profile.start_request"
12 />11 />
1312
14 <subscriber13 <subscriber
15 for="zope.app.publication.interfaces.IEndRequestEvent"
16 handler="lp.services.profile.profile.end_request"14 handler="lp.services.profile.profile.end_request"
17 />15 />
1816
17 <!-- Create a namespace to request a profile. -->
18 <view
19 name="profile" type="*"
20 provides="zope.traversing.interfaces.ITraversable" for="*"
21 factory=".profile.ProfileNamespace"
22 />
23
19</configure>24</configure>
2025
=== 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-27 14:23:44 +0000
@@ -0,0 +1,77 @@
1<div class="profiling_info">
2 <div class="hide_reveal_profiling" id="reveal_profiling">
3 Click to REVEAL profiling information
4 </div>
5</div>
6<div class="profiling_info" id="profiling_info">
7 <div class="hide_reveal_profiling" id="hide_profiling">
8 Click to HIDE profiling information
9 </div>
10 <h1>Profiling Information</h1>
11 <tal:block condition="'help' in actions">
12 <h2>Help</h2>
13 <p>Hi. I see you are using a <code>++profile++</code> request.
14 <tal:block condition="always_log">You have configured every request
15 to have a log, via the <code>profile_all_requests: True</code> in
16 the <code>[profiling]</code> section of your launchpad-lazr.conf, so
17 you'll always see some logging information below. In order to also
18 get immediate profiling results in the browser, use
19 <code>++profile++show</code>.</tal:block> <tal:block condition="not
20 always_log">In order to get profiling results, you need to ask for
21 an HTML view (<code>++profile++show</code>), a KCacheGrind-friendly
22 log on the filesystem (<code>++profile++log</code>), or both
23 (<code>++profile++show,log</code>).</tal:block> This can usually go
24 anywhere in the URL (e.g.,
25 <code>http://launchpad.dev/++profile++show</code> or
26 <code>http://launchpad.dev/++profile++show/Firefox</code> or
27 <code>http://launchpad.dev/Firefox/++profile++show</code>) but some
28 pages do seem to redirect in surprising ways, so experimentation may
29 be necessary.</p>
30 </tal:block>
31 <h2>Log information</h2>
32 <tal:block condition="'log' not in actions">
33 <p>Profile was not logged to file.</p>
34 <p>Use <code>++profile++log</code> in your URL in order to log the
35 information to file for later KCacheGrind analysis (or
36 <code>++profile++log,show</code> to see both the log information and
37 immediate results).</p>
38 </tal:block>
39 <tal:block condition="'log' in actions">
40 <p tal:condition="always_log"><strong>You have configured every
41 request to have a full profile log</strong>, via the
42 <code>profile_all_requests: True</code> in the
43 <code>[profiling]</code> section of your launchpad-lazr.conf.</p>
44 <p>Profile was logged to <tal:block replace="dump_path" />.</p>
45 <p>You should be able to use this simply by entering
46 <code>kcachegrind <tal:block replace="dump_path" /></code> in the
47 console for a great visualization of the profile. The <a
48 href="https://dev.launchpad.net/Debugging#Profiling%%20page%%20requests"
49 >dev wiki</a> may have more information on how to use this.</p>
50 </tal:block>
51 <h2>Profile quick view</h2>
52 <tal:block condition="'show' not in actions">
53 <p>Use <code>++profile++show</code> in your URL in order to see
54 immediate profile results (or <code>++profile++log,show</code> to
55 see both the log information and immediate results).</p>
56 </tal:block>
57 <tal:block condition="'show' in actions">
58 <h3>Top Inline Time</h3>
59 <pre tal:content="inlinetime" />
60 <h3>Top Total Time</h3>
61 <pre tal:content="totaltime" />
62 <h3>Top Call Count</h3>
63 <pre tal:content="callcount" />
64 <h2>Raw OOPS Information</h2>
65 <pre tal:content="oops" />
66 </tal:block>
67</div>
68<script>
69LPS.use('node', 'lp', function (Y) {
70 Y.get('div#reveal_profiling').on('click', function (e) {
71 Y.get('div#profiling_info').setStyle('display', 'block');
72 });
73 Y.get('div#hide_profiling').on('click', function (e) {
74 Y.get('div#profiling_info').setStyle('display', 'none');
75 });
76});
77</script>
078
=== 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-27 14:23:44 +0000
@@ -10,13 +10,22 @@
10from datetime import datetime10from datetime import datetime
11import os11import os
12import threading12import threading
13import StringIO
1314
14from bzrlib.lsprof import BzrProfiler15from bzrlib.lsprof import BzrProfiler
15from zope.component import getUtility16from chameleon.zpt.template import PageTemplateFile
17from zope.app.publication.interfaces import IEndRequestEvent
18from zope.component import (
19 adapter,
20 getUtility,
21 )
22from zope.contenttype.parse import parse
16from zope.error.interfaces import IErrorReportingUtility23from zope.error.interfaces import IErrorReportingUtility
24from zope.traversing.namespace import view
1725
18from canonical.config import config26from canonical.config import config
19import canonical.launchpad.webapp.adapter as da27import canonical.launchpad.webapp.adapter as da
28from canonical.launchpad.webapp.interfaces import IStartRequestEvent
20from canonical.mem import (29from canonical.mem import (
21 memory,30 memory,
22 resident,31 resident,
@@ -30,22 +39,47 @@
30_profilers = threading.local()39_profilers = threading.local()
3140
3241
42@adapter(IStartRequestEvent)
33def start_request(event):43def start_request(event):
34 """Handle profiling.44 """Handle profiling.
3545
36 If profiling is enabled, start a profiler for this thread. If memory46 If profiling is enabled, start a profiler for this thread. If memory
37 profiling is requested, save the VSS and RSS.47 profiling is requested, save the VSS and RSS.
38 """48 """
39 if config.profiling.profile_requests:49 if not config.profiling.profiling_allowed:
40 _profilers.profiler = BzrProfiler()50 return
41 _profilers.profiler.start()51 actions = get_desired_profile_actions(event.request)
4252 if config.profiling.profile_all_requests:
53 actions.add('log')
54 _profilers.actions = actions
55 _profilers.profiler = None
56 if actions:
57 if actions.difference(('help', )):
58 # If this assertion has reason to fail, we'll need to add code
59 # to try and stop the profiler before we delete it, in case it is
60 # still running.
61 assert getattr(_profilers, 'profiler', None) is None
62 _profilers.profiler = BzrProfiler()
63 _profilers.profiler.start()
43 if config.profiling.memory_profile_log:64 if config.profiling.memory_profile_log:
44 _profilers.memory_profile_start = (memory(), resident())65 _profilers.memory_profile_start = (memory(), resident())
4566
4667template = PageTemplateFile(
68 os.path.join(os.path.dirname(__file__), 'profile.pt'))
69
70
71@adapter(IEndRequestEvent)
47def end_request(event):72def end_request(event):
48 """If profiling is turned on, save profile data for the request."""73 """If profiling is turned on, save profile data for the request."""
74 if not config.profiling.profiling_allowed:
75 return
76 try:
77 actions = _profilers.actions
78 except AttributeError:
79 # Some tests don't go through all the proper motions, like firing off
80 # a start request event. Just be quiet about it.
81 return
82 del _profilers.actions
49 request = event.request83 request = event.request
50 # Create a timestamp including milliseconds.84 # Create a timestamp including milliseconds.
51 now = datetime.fromtimestamp(da.get_request_start_time())85 now = datetime.fromtimestamp(da.get_request_start_time())
@@ -53,33 +87,63 @@
53 now.strftime('%Y-%m-%d_%H:%M:%S'), int(now.microsecond/1000.0))87 now.strftime('%Y-%m-%d_%H:%M:%S'), int(now.microsecond/1000.0))
54 pageid = request._orig_env.get('launchpad.pageid', 'Unknown')88 pageid = request._orig_env.get('launchpad.pageid', 'Unknown')
55 oopsid = getattr(request, 'oopsid', None)89 oopsid = getattr(request, 'oopsid', None)
56 if config.profiling.profile_requests:90 content_type = request.response.getHeader('content-type')
57 profiler = _profilers.profiler91 if content_type is None:
58 _profilers.profiler = None92 content_type_params = {}
59 prof_stats = profiler.stop()93 is_html = False
6094 else:
95 _major, _minor, content_type_params = parse(content_type)
96 is_html = _major == 'text' and _minor == 'html'
97 template_context = {
98 'actions': actions,
99 'always_log': config.profiling.profile_all_requests}
100 if _profilers.profiler is not None:
101 prof_stats = _profilers.profiler.stop()
102 # Free some memory.
103 del _profilers.profiler
61 if oopsid is None:104 if oopsid is None:
62 # Log an OOPS to get a log of the SQL queries, and other105 # Log an OOPS to get a log of the SQL queries, and other
63 # useful information, together with the profiling106 # useful information, together with the profiling
64 # information.107 # information.
65 info = (ProfilingOops, None, None)108 info = (ProfilingOops, None, None)
66 error_utility = getUtility(IErrorReportingUtility)109 error_utility = getUtility(IErrorReportingUtility)
67 error_utility.raising(info, request)110 oops = error_utility.handling(info, request)
68 oopsid = request.oopsid111 oopsid = oops.id
69 filename = '%s-%s-%s-%s.prof' % (112 else:
70 timestamp, pageid, oopsid,113 oops = request.oops
71 threading.currentThread().getName())114 if 'log' in actions:
72115 filename = '%s-%s-%s-%s.prof' % (
73 dump_path = os.path.join(config.profiling.profile_dir, filename)116 timestamp, pageid, oopsid,
74 prof_stats.save(dump_path, format="callgrind")117 threading.currentThread().getName())
75118 dump_path = os.path.join(config.profiling.profile_dir, filename)
76 # Free some memory.119 prof_stats.save(dump_path, format="callgrind")
77 _profilers.profiler = None120 template_context['dump_path'] = os.path.abspath(dump_path)
78121 if is_html and 'show' in actions:
122 # Generate raw OOPS results.
123 f = StringIO.StringIO()
124 oops.write(f)
125 template_context['oops'] = f.getvalue()
126 # Generate profile summaries.
127 for name in ('inlinetime', 'totaltime', 'callcount'):
128 prof_stats.sort(name)
129 f = StringIO.StringIO()
130 prof_stats.pprint(top=25, file=f)
131 template_context[name] = f.getvalue()
132 if actions and is_html:
133 # Hack the new HTML in at the end of the page.
134 encoding = content_type_params.get('charset', 'utf-8')
135 added_html = template.render(**template_context).encode(encoding)
136 existing_html = request.response.consumeBody()
137 e_start, e_close_body, e_end = existing_html.rpartition(
138 '</body>')
139 new_html = ''.join(
140 (e_start, added_html, e_close_body, e_end))
141 request.response.setResult(new_html)
79 # Dump memory profiling info.142 # Dump memory profiling info.
80 if config.profiling.memory_profile_log:143 if config.profiling.memory_profile_log:
81 log = file(config.profiling.memory_profile_log, 'a')144 log = file(config.profiling.memory_profile_log, 'a')
82 vss_start, rss_start = _profilers.memory_profile_start145 vss_start, rss_start = _profilers.memory_profile_start
146 del _profilers.memory_profile_start
83 vss_end, rss_end = memory(), resident()147 vss_end, rss_end = memory(), resident()
84 if oopsid is None:148 if oopsid is None:
85 oopsid = '-'149 oopsid = '-'
@@ -87,3 +151,47 @@
87 timestamp, pageid, oopsid, da.get_request_duration(),151 timestamp, pageid, oopsid, da.get_request_duration(),
88 vss_start, rss_start, vss_end, rss_end))152 vss_start, rss_start, vss_end, rss_end))
89 log.close()153 log.close()
154
155
156def get_desired_profile_actions(request):
157 """What does the URL show that the user wants to do about profiling?
158
159 Returns a set of actions (comma-separated) if ++profile++ is in the
160 URL. Note that ++profile++ alone without actions is interpreted as
161 the "help" action.
162 """
163 result = set()
164 path_info = request.get('PATH_INFO')
165 if path_info:
166 # if not, this is almost certainly a test not bothering to set up
167 # certain bits. We'll handle it silently.
168 start, match, end = path_info.partition('/++profile++')
169 # We don't need no steenkin' regex.
170 if match:
171 # Now we figure out what actions are desired. Normally,
172 # parsing the url segment after the namespace ('++profile++'
173 # in this case) is done in the traverse method of the
174 # namespace view (see ProfileNamespace in this file). We
175 # are doing it separately because we want to know what to do
176 # before the traversal machinery gets started, so we can
177 # include traversal in the profile.
178 actions, slash, tail = end.partition('/')
179 result.update(
180 action for action in (
181 item.strip().lower() for item in actions.split(','))
182 if action)
183 result.intersection_update(('log', 'show'))
184 if not result:
185 result.add('help')
186 return result
187
188
189class ProfileNamespace(view):
190 """A see-through namespace that handles traversals with ++profile++."""
191
192 def traverse(self, name, remaining):
193 """Continue on with traversal.
194 """
195 # Note that handling the name is done in get_desired_profile_actions,
196 # above. See the comment in that function.
197 return self.context
90198
=== 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-27 14:23:44 +0000
@@ -0,0 +1,454 @@
1# Copyright 2010 Canonical Ltd. This software is licensed under the
2# GNU Affero General Public License version 3 (see the file LICENSE).
3
4"""Tests for lp.services.profile.
5
6See lib/canonical/doc/profiling.txt for an end-user description of
7the functionality.
8"""
9
10__metaclass__ = type
11
12import glob
13import os
14import time
15import unittest
16
17from lp.testing import TestCase
18from bzrlib.lsprof import BzrProfiler
19from zope.app.publication.interfaces import EndRequestEvent
20from zope.component import getSiteManager
21
22import canonical.launchpad.webapp.adapter as da
23from canonical.launchpad.webapp.errorlog import (
24 ErrorReport,
25 ErrorReportingUtility,
26 )
27from canonical.launchpad.webapp.servers import LaunchpadTestRequest
28from canonical.launchpad.webapp.interfaces import StartRequestEvent
29from lp.services.profile import profile
30
31EXAMPLE_HTML_START = '''\
32<html><head><title>Random!</title></head>
33<body>
34<h1>Random!</h1>
35<p>Whatever!</p>
36'''
37EXAMPLE_HTML_END = '''\
38</body>
39</html>
40'''
41EXAMPLE_HTML = EXAMPLE_HTML_START + EXAMPLE_HTML_END
42
43
44class BaseTest(TestCase):
45
46 def _get_request(self, path='/'):
47 """Return a test request for the given path."""
48 return LaunchpadTestRequest(PATH_INFO=path)
49
50 def _get_start_event(self, path='/'):
51 """Return a start event for the given path."""
52 return StartRequestEvent(self._get_request(path))
53
54 def assertCleanProfilerState(self, message='something did not clean up'):
55 """Check whether profiler thread local is clean."""
56 for name in ('profiler', 'actions', 'memory_profile_start'):
57 self.assertIs(
58 getattr(profile._profilers, name, None), None,
59 'Profiler state (%s) is dirty; %s.' % (name, message))
60
61 def pushProfilingConfig(
62 self, profiling_allowed='False', profile_all_requests='False',
63 memory_profile_log=''):
64 """This is a convenience for setting profile configs."""
65 self.pushConfig(
66 'profiling',
67 profiling_allowed=profiling_allowed,
68 profile_all_requests=profile_all_requests,
69 memory_profile_log=memory_profile_log)
70
71
72class TestRequestStartHandler(BaseTest):
73 """Tests for the start handler of the profiler integration.
74
75 See lib/canonical/doc/profiling.txt for an end-user description of
76 the functionality.
77 """
78
79 def tearDown(self):
80 "Do the usual tearDown, plus clean up the profiler object."
81 if getattr(profile._profilers, 'profiler', None) is not None:
82 profile._profilers.profiler.stop()
83 del profile._profilers.profiler
84 for name in ('actions', 'memory_profile_start'):
85 if getattr(profile._profilers, name, None) is not None:
86 delattr(profile._profilers, name)
87 TestCase.tearDown(self)
88
89 def test_config_stops_profiling(self):
90 """The ``profiling_allowed`` configuration should disable all
91 profiling, even if it is requested"""
92 self.pushProfilingConfig(
93 profiling_allowed='False', profile_all_requests='True',
94 memory_profile_log='.')
95 profile.start_request(self._get_start_event('/++profile++show,log'))
96 self.assertCleanProfilerState('config was ignored')
97
98 def test_optional_profiling_without_marked_request_has_no_profile(self):
99 """Even if profiling is allowed, it does not happen with a normal
100 request."""
101 self.pushProfilingConfig(profiling_allowed='True')
102 profile.start_request(self._get_start_event('/'))
103 self.assertEqual(profile._profilers.actions, set())
104 self.assertIs(getattr(profile._profilers, 'profiler', None), None)
105 self.assertIs(
106 getattr(profile._profilers, 'memory_profile_start', None), None)
107
108 def test_optional_profiling_with_show_request_starts_profiling(self):
109 """If profiling is allowed and a request with the "show" marker
110 URL segment is made, profiling starts."""
111 self.pushProfilingConfig(profiling_allowed='True')
112 profile.start_request(self._get_start_event('/++profile++show/'))
113 self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
114 self.assertIs(
115 getattr(profile._profilers, 'memory_profile_start', None),
116 None)
117 self.assertEquals(profile._profilers.actions, set(('show', )))
118
119 def test_optional_profiling_with_log_request_starts_profiling(self):
120 """If profiling is allowed and a request with the "log" marker
121 URL segment is made, profiling starts."""
122 self.pushProfilingConfig(profiling_allowed='True')
123 profile.start_request(self._get_start_event('/++profile++log/'))
124 self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
125 self.assertIs(
126 getattr(profile._profilers, 'memory_profile_start', None),
127 None)
128 self.assertEquals(profile._profilers.actions, set(('log', )))
129
130 def test_optional_profiling_with_combined_request_starts_profiling(self):
131 """If profiling is allowed and a request with the "log" and
132 "show" marker URL segment is made, profiling starts."""
133 self.pushProfilingConfig(profiling_allowed='True')
134 profile.start_request(self._get_start_event('/++profile++log,show/'))
135 self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
136 self.assertIs(
137 getattr(profile._profilers, 'memory_profile_start', None),
138 None)
139 self.assertEquals(profile._profilers.actions, set(('log', 'show')))
140
141 def test_optional_profiling_with_reversed_request_starts_profiling(self):
142 """If profiling is allowed and a request with the "show" and
143 "log" marker URL segment is made, profiling starts."""
144 self.pushProfilingConfig(profiling_allowed='True')
145 # The fact that this is reversed from the previous request is the only
146 # difference from the previous test. Also, it doesn't have a
147 # trailing slash. :-P
148 profile.start_request(self._get_start_event('/++profile++show,log'))
149 self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
150 self.assertIs(
151 getattr(profile._profilers, 'memory_profile_start', None),
152 None)
153 self.assertEquals(profile._profilers.actions, set(('log', 'show')))
154
155 def test_forced_profiling_registers_action(self):
156 """profile_all_requests should register as a log action"""
157 self.pushProfilingConfig(
158 profiling_allowed='True', profile_all_requests='True')
159 profile.start_request(self._get_start_event('/'))
160 self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
161 self.assertIs(
162 getattr(profile._profilers, 'memory_profile_start', None),
163 None)
164 self.assertEquals(profile._profilers.actions, set(('log', )))
165
166 def test_optional_profiling_with_wrong_request_helps(self):
167 """If profiling is allowed and a request with the marker URL segment
168 is made incorrectly, profiling does not start and help is an action.
169 """
170 self.pushProfilingConfig(profiling_allowed='True')
171 profile.start_request(self._get_start_event('/++profile++/'))
172 self.assertIs(getattr(profile._profilers, 'profiler', None), None)
173 self.assertIs(
174 getattr(profile._profilers, 'memory_profile_start', None),
175 None)
176 self.assertEquals(profile._profilers.actions, set(('help', )))
177
178 def test_forced_profiling_with_wrong_request_helps(self):
179 """If profiling is forced and a request with the marker URL segment
180 is made incorrectly, profiling starts and help is an action.
181 """
182 self.pushProfilingConfig(
183 profiling_allowed='True', profile_all_requests='True')
184 profile.start_request(self._get_start_event('/++profile++/'))
185 self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
186 self.assertIs(
187 getattr(profile._profilers, 'memory_profile_start', None),
188 None)
189 self.assertEquals(profile._profilers.actions, set(('help', 'log')))
190
191 def test_memory_profile_start(self):
192 self.pushProfilingConfig(
193 profiling_allowed='True', memory_profile_log='.')
194 profile.start_request(self._get_start_event('/'))
195 self.assertIs(getattr(profile._profilers, 'profiler', None), None)
196 self.assertIsInstance(profile._profilers.memory_profile_start, tuple)
197 self.assertEqual(len(profile._profilers.memory_profile_start), 2)
198 self.assertEqual(profile._profilers.actions, set())
199
200 def test_combo_memory_and_profile_start(self):
201 self.pushProfilingConfig(
202 profiling_allowed='True', memory_profile_log='.')
203 profile.start_request(self._get_start_event('/++profile++show/'))
204 self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
205 self.assertIsInstance(profile._profilers.memory_profile_start, tuple)
206 self.assertEqual(len(profile._profilers.memory_profile_start), 2)
207 self.assertEquals(profile._profilers.actions, set(('show', )))
208
209
210class TestRequestEndHandler(BaseTest):
211 """Tests for the end-request handler.
212
213 If the start-request handler is broken, these tests will fail too, so fix
214 the tests in the above test case first.
215
216 See lib/canonical/doc/profiling.txt for an end-user description
217 of the functionality.
218 """
219
220 def setUp(self):
221 TestCase.setUp(self)
222 self.patch(da, 'get_request_start_time', time.time)
223 self.patch(da, 'get_request_duration', lambda: 0.5)
224 self.profile_dir = self.makeTemporaryDirectory()
225 self.memory_profile_log = os.path.join(self.profile_dir, 'memory_log')
226 self.pushConfig('profiling', profile_dir=self.profile_dir)
227 self.eru = ErrorReportingUtility()
228 sm = getSiteManager()
229 sm.registerUtility(self.eru)
230 self.addCleanup(sm.unregisterUtility, self.eru)
231
232 def _get_end_event(self, path='/', result=EXAMPLE_HTML, pageid=None):
233 """Return a stop event for the given path and output HTML."""
234 start_event = self._get_start_event(path)
235 profile.start_request(start_event)
236 request = start_event.request
237 if pageid is not None:
238 request.setInWSGIEnvironment('launchpad.pageid', pageid)
239 request.response.setResult(result)
240 context = object()
241 return EndRequestEvent(context, request)
242
243 def endRequest(self, path='/', exception=None, pageid=None):
244 event = self._get_end_event(path, pageid=pageid)
245 if exception is not None:
246 self.eru.raising(
247 (type(exception), exception, None), event.request)
248 profile.end_request(event)
249 return event.request
250
251 def getAddedResponse(self, request,
252 start=EXAMPLE_HTML_START, end=EXAMPLE_HTML_END):
253 output = request.response.consumeBody()
254 return output[len(start):-len(end)]
255
256 def getMemoryLog(self):
257 if not os.path.exists(self.memory_profile_log):
258 return []
259 f = open(self.memory_profile_log)
260 result = f.readlines()
261 f.close()
262 return result
263
264 def getProfilePaths(self):
265 return glob.glob(os.path.join(self.profile_dir, '*.prof'))
266
267 #########################################################################
268 # Tests
269 def test_config_stops_profiling(self):
270 """The ``profiling_allowed`` configuration should disable all
271 profiling, even if it is requested"""
272 self.pushProfilingConfig(
273 profiling_allowed='False', profile_all_requests='True',
274 memory_profile_log=self.memory_profile_log)
275 request = self.endRequest('/++profile++show,log')
276 self.assertIs(getattr(request, 'oops', None), None)
277 self.assertEqual(self.getAddedResponse(request), '')
278 self.assertEqual(self.getMemoryLog(), [])
279 self.assertEqual(self.getProfilePaths(), [])
280 self.assertCleanProfilerState()
281
282 def test_optional_profiling_without_marked_request_has_no_profile(self):
283 """Even if profiling is allowed, it does not happen with a normal
284 request."""
285 self.pushProfilingConfig(profiling_allowed='True')
286 request = self.endRequest('/')
287 self.assertIs(getattr(request, 'oops', None), None)
288 self.assertEqual(self.getAddedResponse(request), '')
289 self.assertEqual(self.getMemoryLog(), [])
290 self.assertEqual(self.getProfilePaths(), [])
291 self.assertCleanProfilerState()
292
293 def test_optional_profiling_with_show_request_profiles(self):
294 """If profiling is allowed and a request with the "show" marker
295 URL segment is made, profiling starts."""
296 self.pushProfilingConfig(profiling_allowed='True')
297 request = self.endRequest('/++profile++show/')
298 self.assertIsInstance(request.oops, ErrorReport)
299 self.assertIn('Top Inline Time', self.getAddedResponse(request))
300 self.assertEqual(self.getMemoryLog(), [])
301 self.assertEqual(self.getProfilePaths(), [])
302 self.assertCleanProfilerState()
303
304 def test_optional_profiling_with_log_request_profiles(self):
305 """If profiling is allowed and a request with the "log" marker
306 URL segment is made, profiling starts."""
307 self.pushProfilingConfig(profiling_allowed='True')
308 request = self.endRequest('/++profile++log/')
309 self.assertIsInstance(request.oops, ErrorReport)
310 response = self.getAddedResponse(request)
311 self.assertIn('Profile was logged to', response)
312 self.assertNotIn('Top Inline Time', response)
313 self.assertEqual(self.getMemoryLog(), [])
314 paths = self.getProfilePaths()
315 self.assertEqual(len(paths), 1)
316 self.assertIn(paths[0], response)
317 self.assertCleanProfilerState()
318
319 def test_optional_profiling_with_combined_request_profiles(self):
320 """If profiling is allowed and a request with the "log" and
321 "show" marker URL segment is made, profiling starts."""
322 self.pushProfilingConfig(profiling_allowed='True')
323 request = self.endRequest('/++profile++log,show')
324 self.assertIsInstance(request.oops, ErrorReport)
325 response = self.getAddedResponse(request)
326 self.assertIn('Profile was logged to', response)
327 self.assertIn('Top Inline Time', response)
328 self.assertEqual(self.getMemoryLog(), [])
329 paths = self.getProfilePaths()
330 self.assertEqual(len(paths), 1)
331 self.assertIn(paths[0], response)
332 self.assertCleanProfilerState()
333
334 def test_forced_profiling_logs(self):
335 """profile_all_requests should register as a log action"""
336 self.pushProfilingConfig(
337 profiling_allowed='True', profile_all_requests='True')
338 request = self.endRequest('/')
339 self.assertIsInstance(request.oops, ErrorReport)
340 response = self.getAddedResponse(request)
341 self.assertIn('Profile was logged to', response)
342 self.assertIn('profile_all_requests: True', response)
343 self.assertNotIn('Top Inline Time', response)
344 self.assertEqual(self.getMemoryLog(), [])
345 paths = self.getProfilePaths()
346 self.assertEqual(len(paths), 1)
347 self.assertIn(paths[0], response)
348 self.assertCleanProfilerState()
349
350 def test_optional_profiling_with_wrong_request_helps(self):
351 """If profiling is allowed and a request with the marker URL segment
352 is made incorrectly, profiling does not start and help is an action.
353 """
354 self.pushProfilingConfig(profiling_allowed='True')
355 request = self.endRequest('/++profile++')
356 self.assertIs(getattr(request, 'oops', None), None)
357 response = self.getAddedResponse(request)
358 self.assertIn('<h2>Help</h2>', response)
359 self.assertNotIn('Top Inline Time', response)
360 self.assertEqual(self.getMemoryLog(), [])
361 self.assertEqual(self.getProfilePaths(), [])
362 self.assertCleanProfilerState()
363
364 def test_forced_profiling_with_wrong_request_helps(self):
365 """If profiling is forced and a request with the marker URL segment
366 is made incorrectly, profiling starts and help is an action.
367 """
368 self.pushProfilingConfig(
369 profiling_allowed='True', profile_all_requests='True')
370 request = self.endRequest('/++profile++')
371 self.assertIsInstance(request.oops, ErrorReport)
372 response = self.getAddedResponse(request)
373 self.assertIn('<h2>Help</h2>', response)
374 self.assertIn('Profile was logged to', response)
375 self.assertIn('profile_all_requests: True', response)
376 self.assertNotIn('Top Inline Time', response)
377 self.assertEqual(self.getMemoryLog(), [])
378 paths = self.getProfilePaths()
379 self.assertEqual(len(paths), 1)
380 self.assertIn(paths[0], response)
381 self.assertCleanProfilerState()
382
383 def test_memory_profile(self):
384 "Does the memory profile work?"
385 self.pushProfilingConfig(
386 profiling_allowed='True',
387 memory_profile_log=self.memory_profile_log)
388 request = self.endRequest('/')
389 self.assertIs(getattr(request, 'oops', None), None)
390 self.assertEqual(self.getAddedResponse(request), '')
391 log = self.getMemoryLog()
392 self.assertEqual(len(log), 1)
393 (timestamp, page_id, oops_id, duration, start_vss, start_rss,
394 end_vss, end_rss) = log[0].split()
395 self.assertEqual(page_id, 'Unknown')
396 self.assertEqual(oops_id, '-')
397 self.assertEqual(float(duration), 0.5)
398 self.assertEqual(self.getProfilePaths(), [])
399 self.assertCleanProfilerState()
400
401 def test_memory_profile_with_non_defaults(self):
402 "Does the memory profile work with an oops and pageid?"
403 self.pushProfilingConfig(
404 profiling_allowed='True',
405 memory_profile_log=self.memory_profile_log)
406 request = self.endRequest('/++profile++show/no-such-file',
407 KeyError(), pageid='Foo')
408 log = self.getMemoryLog()
409 (timestamp, page_id, oops_id, duration, start_vss, start_rss,
410 end_vss, end_rss) = log[0].split()
411 self.assertEqual(page_id, 'Foo')
412 self.assertEqual(oops_id, request.oopsid)
413 self.assertCleanProfilerState()
414
415 def test_combo_memory_and_profile(self):
416 self.pushProfilingConfig(
417 profiling_allowed='True',
418 memory_profile_log=self.memory_profile_log)
419 request = self.endRequest('/++profile++show/')
420 self.assertIsInstance(request.oops, ErrorReport)
421 self.assertIn('Top Inline Time', self.getAddedResponse(request))
422 self.assertEqual(len(self.getMemoryLog()), 1)
423 self.assertEqual(self.getProfilePaths(), [])
424 self.assertCleanProfilerState()
425
426 def test_profiling_oops_is_informational(self):
427 self.pushProfilingConfig(profiling_allowed='True')
428 request = self.endRequest('/++profile++show/')
429 response = self.getAddedResponse(request)
430 self.assertIsInstance(request.oops, ErrorReport)
431 self.assertTrue(request.oops.informational)
432 self.assertEquals(request.oops.type, 'ProfilingOops')
433 self.assertCleanProfilerState()
434
435 def test_real_oops_trumps_profiling_oops(self):
436 self.pushProfilingConfig(profiling_allowed='True')
437 request = self.endRequest('/++profile++show/no-such-file',
438 KeyError('foo'))
439 self.assertIsInstance(request.oops, ErrorReport)
440 self.assertFalse(request.oops.informational)
441 self.assertEquals(request.oops.type, 'KeyError')
442 response = self.getAddedResponse(request)
443 self.assertIn('Exception-Type: KeyError', response)
444 self.assertCleanProfilerState()
445
446 def test_oopsid_is_in_profile_filename(self):
447 self.pushProfilingConfig(profiling_allowed='True')
448 request = self.endRequest('/++profile++log/')
449 self.assertIn("-" + request.oopsid + "-", self.getProfilePaths()[0])
450 self.assertCleanProfilerState()
451
452
453def test_suite():
454 return unittest.TestLoader().loadTestsFromName(__name__)