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
1=== modified file '.bzrignore'
2--- .bzrignore 2010-08-12 13:17:05 +0000
3+++ .bzrignore 2010-08-27 14:23:44 +0000
4@@ -77,3 +77,4 @@
5 lib/canonical/launchpad-buildd_*_source.changes
6 lib/canonical/buildd/debian/*
7 lib/canonical/buildd/launchpad-files/*
8+*.pt.py
9
10=== modified file 'configs/development/apidoc-configure-normal.zcml'
11--- configs/development/apidoc-configure-normal.zcml 2010-08-04 15:59:53 +0000
12+++ configs/development/apidoc-configure-normal.zcml 2010-08-27 14:23:44 +0000
13@@ -120,5 +120,11 @@
14 doc_path="../../doc/buildout.txt"
15 parent="lp"
16 />
17+ <apidoc:bookchapter
18+ id="profiling"
19+ title="Profiling"
20+ doc_path="../../lib/canonical/launchpad/doc/profiling.txt"
21+ parent="lp"
22+ />
23
24 </configure>
25
26=== modified file 'configs/development/launchpad-lazr.conf'
27--- configs/development/launchpad-lazr.conf 2010-08-06 17:39:52 +0000
28+++ configs/development/launchpad-lazr.conf 2010-08-27 14:23:44 +0000
29@@ -246,6 +246,9 @@
30 [process_apport_blobs]
31 error_dir: /var/tmp/lperr
32
33+[profiling]
34+profiling_allowed: True
35+
36 [supermirror_puller]
37 error_dir: /var/tmp/codehosting.test
38 oops_prefix: SMP
39
40=== modified file 'lib/canonical/config/schema-lazr.conf'
41--- lib/canonical/config/schema-lazr.conf 2010-08-19 09:45:38 +0000
42+++ lib/canonical/config/schema-lazr.conf 2010-08-27 14:23:44 +0000
43@@ -1642,10 +1642,16 @@
44
45
46 [profiling]
47+# When set to True, the user is allowed to request profiles be run for
48+# either individual pages or for every request sent.
49+# datatype: boolean
50+profiling_allowed: False
51+
52 # When set to True, each requests will be profiled and the resulting data
53-# saved in profile_dir.
54+# saved in profile_dir. `profiling_allowed` must also be True for this to
55+# work.
56 # datatype: boolean
57-profile_requests: False
58+profile_all_requests: False
59
60 # Directory to save profile info. The filename is in the format
61 # <timestamp>-<threadName>.prof
62
63=== modified file 'lib/canonical/launchpad/doc/profiling.txt'
64--- lib/canonical/launchpad/doc/profiling.txt 2010-07-17 13:40:35 +0000
65+++ lib/canonical/launchpad/doc/profiling.txt 2010-08-27 14:23:44 +0000
66@@ -1,8 +1,15 @@
67-= Profiling support =
68+=================
69+Profiling support
70+=================
71+
72+.. ReST Comment: this is intended to be a true DOC test, with an emphasis on
73+ documentation. Of the three sections, the last two have been adjusted for
74+ this goal.
75
76 Launchpad supports three modes of profiling.
77
78-== Profiling requests in pagetests ==
79+Profiling requests in pagetests
80+===============================
81
82 Our testing framework has support for profiling requests made in
83 pagetests. When the PROFILE_PAGETESTS_REQUESTS environment variable is
84@@ -76,142 +83,118 @@
85 False
86
87
88-== Profiling request in the app server ==
89+Profiling request in the app server
90+===================================
91
92-It is also possible to get a profile of each request served by the app
93+It is also possible to get a profile of requests served by the app
94 server.
95
96-This is controlled by the [profiling] config section. Profiling is
97-controlled by the profile_requests configuration variable. When this is
98-True, each request will create a pstats file for the request in the
99-directory specified in the profile_dir variable.
100-
101-By default profiling is turned off.
102-
103- >>> from canonical.config import config
104- >>> config.profiling.profile_requests
105+*Important*: This is not blessed for production, primarily because of
106+the typical cost of employing a profiling hook. Also, profiled requests
107+are forced to run in serial. This is also a concern for production
108+usage, since some of our requests can take much longer than others.
109+
110+It might be fine to occasionally turn on in staging; that is more
111+negotiable, at least. LOSAs will need to vet the feature to see if they are
112+concerned about it giving too much information about our staging system.
113+
114+The feature has two modes.
115+
116+- It can be configured to optionally profile requests. To turn this on, in
117+ ``launchpad-lazr.conf`` (e.g.,
118+ ``configs/development/launchpad-lazr.conf``) , in the ``[profiling]``
119+ section, set ``profiling_allowed: True``. As of this writing, this
120+ is the default value for development.
121+
122+ Once it is turned on, you can insert /++profile++/ in the URL to get
123+ basic instructions on how to use the feature. You use the
124+ ``launchpad-lazr.conf`` ``profile_dir`` setting to determine what
125+ directory will receive written profiles.
126+
127+.. This ReST comment tests the assertion above that profiling_allowed is
128+ True by default for tests and development.
129+
130+ >>> from canonical.config import config
131+ >>> config.profiling.profiling_allowed
132+ True
133+
134+ Similarly, this tests that, in a fully set-up environment, the
135+ profiling machinery that is coded and unit-tested in
136+ lp/services/profile is hooked up properly. This is intended to be a
137+ smoke test. The unit tests verify further functionality.
138+
139+ >>> response = http('GET /++profile++ HTTP/1.0')
140+ >>> '<h1>Profiling Information</h1>' in response.getBody()
141+ True
142+
143+- It can be configured to profile all requests, indiscriminately. To turn
144+ this on, use the ``profiling_allowed`` setting described in option 1
145+ above and also set ``profile_all_requests: True`` in the
146+ ``[profiling]`` section of ``launchpad-lazr.conf``. This is turned
147+ off by default. As with the first option, you use the
148+ ``profile_dir`` setting to determine what directory will receive the
149+ profiles.
150+
151+ Once it is turned on, every request will create a profiling log usable
152+ with KCacheGrind. The browser will include information on the file
153+ created for that request.
154+
155+.. This ReST comment tests the assertion above that profile_all_requests is
156+ False by default for tests and development.
157+
158+ >>> from canonical.config import config
159+ >>> config.profiling.profile_all_requests
160 False
161
162-(Set the profile directory.)
163-
164- >>> from textwrap import dedent
165- >>> profile_dir = tempfile.mkdtemp(prefix='profile')
166- >>> config.push('profile_dir', dedent("""
167- ... [profiling]
168- ... profile_dir: %s""" % profile_dir))
169-
170-So when making a request, no profile information is created.
171-
172- >>> response = http('GET / HTTP/1.0')
173-
174- >>> list(os.listdir(profile_dir))
175- []
176-
177-But if profiling is turned on, profiling data will be created in the
178-directory for the request.
179-
180- >>> config.push('profile_on', dedent("""\
181- ... [profiling]
182- ... profile_requests: True"""))
183-
184- >>> response = http('GET / HTTP/1.0')
185-
186-The profile is named on the time of the request start, the pageid, and
187-the thread that processed it.
188-
189- >>> old_stat_float_times = os.stat_float_times()
190- >>> os.stat_float_times(True)
191- >>> def get_profiles():
192- ... """Return the profile file names sorted by name.
193- ...
194- ... The time information is stripped out to avoid spurious test
195- ... failures. The time resolution isn't great enough to reliably
196- ... sort on it.
197- ... """
198- ... profiles = ['-'.join(name.split('-')[-4:])
199- ... for name in os.listdir(profile_dir)]
200- ... return sorted(profiles)
201-
202- >>> profiles = get_profiles()
203- >>> print "\n".join(profiles)
204- RootObject:index.html-OOPS-...-MainThread.prof
205-
206-Together with the profiling information, an OOPS report is also created.
207-It's not really an OOPS, but the same format is re-used to make
208-analyzing it easier.
209-
210- >>> from sys import stdout
211- >>> from zope.error.interfaces import IErrorReportingUtility
212- >>> logged_oops = getUtility(IErrorReportingUtility).getLastOopsReport()
213- >>> logged_oops.write(stdout)
214- Oops-Id: OOPS-...
215- Exception-Type: ProfilingOops
216- Exception-Value: None
217- Date: ...
218- Page-Id: RootObject:index.html
219- Branch: ...
220- Revision: ...
221- User: ...
222- URL: http://localhost/index.html
223- ...
224-
225-The OOPS id is referenced in the profiling log's filename.
226-
227- >>> profiling_filename = profiles[0]
228- >>> profiling_oops_id = '-'.join(profiling_filename.split('-')[1:3])
229- >>> profiling_oops_id == logged_oops.id
230- True
231-
232-Making another request will create another profile.
233-
234- >>> response = http('GET / HTTP/1.0')
235-
236- >>> print "\n".join(get_profiles())
237- RootObject:index.html-OOPS-...-MainThread.prof
238- RootObject:index.html-OOPS-...-MainThread.prof
239-
240-If the request resulted in an OOPS, the logged OOPS will have the real
241-exception information, instead of the fake ProfilingOops one. Two files
242-are logged. One for the first request in the slave store, and one for
243-the retried request in the master store:
244-
245- >>> http('GET /no-such-file HTTP/1.0', handle_errors=False)
246- Traceback (most recent call last):
247- ...
248- NotFound:...
249- >>> print "\n".join(get_profiles())
250- RootObject:index.html-OOPS-...-MainThread.prof
251- RootObject:index.html-OOPS-...-MainThread.prof
252- Unknown-OOPS-...-MainThread.prof
253- Unknown-OOPS-...-MainThread.prof
254-
255- >>> oops = getUtility(IErrorReportingUtility).getLastOopsReport()
256- >>> oops.write(stdout)
257- Oops-Id: OOPS-...
258- Exception-Type: NotFound
259- ...
260- URL: http://localhost/no-such-file
261- ...
262-
263-
264-== Memory profiling ==
265+Profile files are named based on the time of the request start, the
266+pageid, and the thread that processed it.
267+
268+Together with the profiling information, an informational OOPS report is
269+usually also created.
270+
271+If the request actually resulted in an OOPS, the logged OOPS will have
272+the real exception information, instead of being an informational
273+ProfilingOops.
274+
275+In either case, the OOPS id is referenced in the profiling log's
276+filename.
277+
278+Memory profiling
279+================
280
281 It is possible to keep a log of the memory profile of the application. That's
282 useful to try to figure out what requests are causing the memory usage of the
283 server to increase.
284
285-To create that log, you set the configuration variable memory_profile_log.
286-
287+This is not blessed for production use at this time: the implementation
288+relies on lib/canonical/mem.py, which as of this writing warns in its
289+docstring that "[n]one of this should be in day-to-day use." We should
290+document the source of these concerns and evaluate them before using it in
291+production. Staging may be more acceptable.
292+
293+Note that the data collected will be polluted by parallel requests: if
294+memory increases in one request while another is also running in a different
295+thread, both requests will show the increase.
296+
297+It also will probably be polluted by simultaneous use of the profiling
298+options described above (`Profiling request in the app server`_).
299+
300+To turn this on, use the ``profiling_allowed`` setting described in the
301+previous profiling section, and also set the ``memory_profile_log`` in
302+the ``[profiling]`` section of ``launchpad-lazr.conf`` to a path to a
303+log file.
304+
305+.. This ReST comment tests the assertion above that memory_profile_log is
306+ the way to turn on memory profiling. It is intended to be a smoke test.
307+ The real tests are in the lp/services/profile package.
308+
309+ >>> profile_dir = tempfile.mkdtemp(prefix='profile')
310 >>> memory_profile_log = os.path.join(profile_dir, 'memory.log')
311+ >>> from textwrap import dedent
312 >>> config.push('memory_profile', dedent("""
313 ... [profiling]
314 ... profile_request: False
315 ... memory_profile_log: %s""" % memory_profile_log))
316-
317-After each request is done, that log will have the timestamp of the request,
318-the page id, the oops id, the duration, the starting VSS and RSS, and the
319-ending VSS and RSS.
320-
321 >>> response = http('GET / HTTP/1.0')
322 >>> memory_profile_fh = file(memory_profile_log)
323 >>> (timestamp, page_id, oops_id, duration,
324@@ -220,63 +203,14 @@
325 >>> print timestamp
326 20...
327 >>> print oops_id
328- OOPS-...
329+ -
330 >>> print page_id
331 RootObject:index.html
332
333-When an OOPS is triggered by the request, its identifier is logged:
334-
335- >>> http('GET /no-such-file HTTP/1.0', handle_errors=False)
336- Traceback (most recent call last):
337- ...
338- NotFound:...
339-
340-Two lines are logged. The first one is for the request in the slave
341-store. When that fails, the request is retried in the master store,
342-causing another line to be logged.
343-
344- >>> (timestamp, page_id, first_oops_id, duration,
345- ... start_vss, start_rss, end_vss, end_rss) = (
346- ... memory_profile_fh.readline().split())
347- >>> print first_oops_id
348- OOPS-...
349- >>> print page_id
350- Unknown
351-
352- >>> (timestamp, page_id, second_oops_id, duration,
353- ... start_vss, start_rss, end_vss, end_rss) = (
354- ... memory_profile_fh.readline().split())
355- >>> print second_oops_id
356- OOPS-...
357- >>> print page_id
358- Unknown
359-
360-The logged OOPSes aren't the same.
361-
362- >>> first_oops_id == second_oops_id
363- False
364-
365-The second OOPS has the real exception in its log, instead of the usual
366-ProfilingOops one.
367-
368- >>> oops = getUtility(IErrorReportingUtility).getLastOopsReport()
369- >>> oops.write(stdout)
370- Oops-Id: OOPS-...
371- Exception-Type: NotFound
372- ...
373- URL: http://localhost/no-such-file
374- ...
375-
376-
377-== Clean up ==
378+.. ReST comment: this is clean up for the work done above.
379
380 >>> import shutil
381-
382 >>> os.environ['PROFILE_PAGETESTS_REQUESTS'] = old_profile_environ
383-
384 >>> shutil.rmtree(pagetests_profile_dir)
385 >>> shutil.rmtree(profile_dir)
386-
387- >>> old_config = config.pop('profile_dir')
388-
389- >>> os.stat_float_times(old_stat_float_times)
390+ >>> old_config = config.pop('memory_profile')
391
392=== modified file 'lib/canonical/launchpad/icing/style-3-0.css.in'
393--- lib/canonical/launchpad/icing/style-3-0.css.in 2010-08-27 03:56:44 +0000
394+++ lib/canonical/launchpad/icing/style-3-0.css.in 2010-08-27 14:23:44 +0000
395@@ -221,7 +221,34 @@
396 hr {
397 display: none;
398 }
399-
400+div.profiling_info {
401+ position: absolute;
402+ top: 0;
403+ left: 0;
404+ border: 3px solid red;
405+ background-color: white;
406+ text-align: left;
407+ padding: 1em;
408+ }
409+div.profiling_info h1 {
410+ color: red;
411+ }
412+div.profiling_info h2 {
413+ border-bottom: 3px solid gray;
414+ color: black;
415+ }
416+div.profiling_info h3 {
417+ border-bottom: 1px solid gray;
418+ color: black;
419+ }
420+div.profiling_info p {
421+ color: black;
422+ }
423+div.hide_reveal_profiling {
424+ text-decoration: underline;
425+ color: #093;
426+ font-size: 85%;
427+ }
428
429 /* =========================
430 Universal presentation
431
432=== modified file 'lib/canonical/launchpad/webapp/errorlog.py'
433--- lib/canonical/launchpad/webapp/errorlog.py 2010-08-20 20:31:18 +0000
434+++ lib/canonical/launchpad/webapp/errorlog.py 2010-08-27 14:23:44 +0000
435@@ -9,13 +9,10 @@
436
437 import contextlib
438 import datetime
439-import errno
440 from itertools import repeat
441 import logging
442-import os
443 import re
444 import rfc822
445-import threading
446 import types
447 import urllib
448
449@@ -64,12 +61,14 @@
450 # minute.
451 _rate_restrict_burst = 5
452
453+
454 def _normalise_whitespace(s):
455 """Normalise the whitespace in a string to spaces"""
456 if s is None:
457 return None
458 return ' '.join(s.split())
459
460+
461 def _safestr(obj):
462 if isinstance(obj, unicode):
463 return obj.replace('\\', '\\\\').encode('ASCII',
464@@ -85,14 +84,14 @@
465 'Error in ErrorReportingService while getting a str '
466 'representation of an object')
467 value = '<unprintable %s object>' % (
468- str(type(obj).__name__)
469- )
470+ str(type(obj).__name__))
471 # encode non-ASCII characters
472 value = value.replace('\\', '\\\\')
473 value = re.sub(r'[\x80-\xff]',
474 lambda match: '\\x%02x' % ord(match.group(0)), value)
475 return value
476
477+
478 def _is_sensitive(request, name):
479 """Return True if the given request variable name is sensitive.
480
481@@ -157,7 +156,7 @@
482 self.req_vars = req_vars
483 self.db_statements = db_statements
484 self.branch_nick = versioninfo.branch_nick
485- self.revno = versioninfo.revno
486+ self.revno = versioninfo.revno
487 self.informational = informational
488
489 def __repr__(self):
490@@ -166,8 +165,10 @@
491 def get_chunks(self):
492 chunks = []
493 chunks.append('Oops-Id: %s\n' % _normalise_whitespace(self.id))
494- chunks.append('Exception-Type: %s\n' % _normalise_whitespace(self.type))
495- chunks.append('Exception-Value: %s\n' % _normalise_whitespace(self.value))
496+ chunks.append(
497+ 'Exception-Type: %s\n' % _normalise_whitespace(self.type))
498+ chunks.append(
499+ 'Exception-Value: %s\n' % _normalise_whitespace(self.value))
500 chunks.append('Date: %s\n' % self.time.isoformat())
501 chunks.append('Page-Id: %s\n' % _normalise_whitespace(self.pageid))
502 chunks.append('Branch: %s\n' % self.branch_nick)
503@@ -205,7 +206,7 @@
504 duration = int(float(msg.getheader('duration', '-1')))
505 informational = msg.getheader('informational')
506
507- # Explicitely use an iterator so we can process the file
508+ # Explicitly use an iterator so we can process the file
509 # sequentially. In most instances the iterator will actually
510 # be the file object passed in because file objects should
511 # support iteration.
512@@ -295,7 +296,7 @@
513 # the current log_namer naming rules and the exact timestamp.
514 oops_filename = self.log_namer.getFilename(serial_from_time, time)
515 # Note that if there were no logs written, or if there were two
516- # oops that matched the time window of directory on disk, this
517+ # oops that matched the time window of directory on disk, this
518 # call can raise an IOError.
519 oops_report = open(oops_filename, 'r')
520 try:
521@@ -338,7 +339,8 @@
522 determined if not supplied. Useful for testing. Not part of
523 IErrorReportingUtility).
524 """
525- self._raising(info, request=request, now=now, informational=False)
526+ return self._raising(
527+ info, request=request, now=now, informational=False)
528
529 def _raising(self, info, request=None, now=None, informational=False):
530 """Private method used by raising() and handling()."""
531@@ -355,6 +357,7 @@
532 self._do_copy_to_zlog(
533 entry.time, entry.type, entry.url, info, entry.id)
534 notify(ErrorReportEvent(entry))
535+ return entry
536
537 def _makeErrorReport(self, info, request=None, now=None,
538 informational=False):
539@@ -472,7 +475,8 @@
540 :param now: The datetime to use as the current time. Will be
541 determined if not supplied. Useful for testing.
542 """
543- self._raising(info, request=request, now=now, informational=True)
544+ return self._raising(
545+ info, request=request, now=now, informational=True)
546
547 def _do_copy_to_zlog(self, now, strtype, url, info, oopsid):
548 distant_past = datetime.datetime(1970, 1, 1, 0, 0, 0, tzinfo=UTC)
549
550=== modified file 'lib/lp/services/profile/configure.zcml'
551--- lib/lp/services/profile/configure.zcml 2010-07-14 15:33:36 +0000
552+++ lib/lp/services/profile/configure.zcml 2010-08-27 14:23:44 +0000
553@@ -7,13 +7,18 @@
554 xmlns:browser="http://namespaces.zope.org/browser">
555
556 <subscriber
557- for="canonical.launchpad.webapp.interfaces.IStartRequestEvent"
558 handler="lp.services.profile.profile.start_request"
559 />
560
561 <subscriber
562- for="zope.app.publication.interfaces.IEndRequestEvent"
563 handler="lp.services.profile.profile.end_request"
564 />
565
566+ <!-- Create a namespace to request a profile. -->
567+ <view
568+ name="profile" type="*"
569+ provides="zope.traversing.interfaces.ITraversable" for="*"
570+ factory=".profile.ProfileNamespace"
571+ />
572+
573 </configure>
574
575=== added file 'lib/lp/services/profile/profile.pt'
576--- lib/lp/services/profile/profile.pt 1970-01-01 00:00:00 +0000
577+++ lib/lp/services/profile/profile.pt 2010-08-27 14:23:44 +0000
578@@ -0,0 +1,77 @@
579+<div class="profiling_info">
580+ <div class="hide_reveal_profiling" id="reveal_profiling">
581+ Click to REVEAL profiling information
582+ </div>
583+</div>
584+<div class="profiling_info" id="profiling_info">
585+ <div class="hide_reveal_profiling" id="hide_profiling">
586+ Click to HIDE profiling information
587+ </div>
588+ <h1>Profiling Information</h1>
589+ <tal:block condition="'help' in actions">
590+ <h2>Help</h2>
591+ <p>Hi. I see you are using a <code>++profile++</code> request.
592+ <tal:block condition="always_log">You have configured every request
593+ to have a log, via the <code>profile_all_requests: True</code> in
594+ the <code>[profiling]</code> section of your launchpad-lazr.conf, so
595+ you'll always see some logging information below. In order to also
596+ get immediate profiling results in the browser, use
597+ <code>++profile++show</code>.</tal:block> <tal:block condition="not
598+ always_log">In order to get profiling results, you need to ask for
599+ an HTML view (<code>++profile++show</code>), a KCacheGrind-friendly
600+ log on the filesystem (<code>++profile++log</code>), or both
601+ (<code>++profile++show,log</code>).</tal:block> This can usually go
602+ anywhere in the URL (e.g.,
603+ <code>http://launchpad.dev/++profile++show</code> or
604+ <code>http://launchpad.dev/++profile++show/Firefox</code> or
605+ <code>http://launchpad.dev/Firefox/++profile++show</code>) but some
606+ pages do seem to redirect in surprising ways, so experimentation may
607+ be necessary.</p>
608+ </tal:block>
609+ <h2>Log information</h2>
610+ <tal:block condition="'log' not in actions">
611+ <p>Profile was not logged to file.</p>
612+ <p>Use <code>++profile++log</code> in your URL in order to log the
613+ information to file for later KCacheGrind analysis (or
614+ <code>++profile++log,show</code> to see both the log information and
615+ immediate results).</p>
616+ </tal:block>
617+ <tal:block condition="'log' in actions">
618+ <p tal:condition="always_log"><strong>You have configured every
619+ request to have a full profile log</strong>, via the
620+ <code>profile_all_requests: True</code> in the
621+ <code>[profiling]</code> section of your launchpad-lazr.conf.</p>
622+ <p>Profile was logged to <tal:block replace="dump_path" />.</p>
623+ <p>You should be able to use this simply by entering
624+ <code>kcachegrind <tal:block replace="dump_path" /></code> in the
625+ console for a great visualization of the profile. The <a
626+ href="https://dev.launchpad.net/Debugging#Profiling%%20page%%20requests"
627+ >dev wiki</a> may have more information on how to use this.</p>
628+ </tal:block>
629+ <h2>Profile quick view</h2>
630+ <tal:block condition="'show' not in actions">
631+ <p>Use <code>++profile++show</code> in your URL in order to see
632+ immediate profile results (or <code>++profile++log,show</code> to
633+ see both the log information and immediate results).</p>
634+ </tal:block>
635+ <tal:block condition="'show' in actions">
636+ <h3>Top Inline Time</h3>
637+ <pre tal:content="inlinetime" />
638+ <h3>Top Total Time</h3>
639+ <pre tal:content="totaltime" />
640+ <h3>Top Call Count</h3>
641+ <pre tal:content="callcount" />
642+ <h2>Raw OOPS Information</h2>
643+ <pre tal:content="oops" />
644+ </tal:block>
645+</div>
646+<script>
647+LPS.use('node', 'lp', function (Y) {
648+ Y.get('div#reveal_profiling').on('click', function (e) {
649+ Y.get('div#profiling_info').setStyle('display', 'block');
650+ });
651+ Y.get('div#hide_profiling').on('click', function (e) {
652+ Y.get('div#profiling_info').setStyle('display', 'none');
653+ });
654+});
655+</script>
656
657=== modified file 'lib/lp/services/profile/profile.py'
658--- lib/lp/services/profile/profile.py 2010-08-20 20:31:18 +0000
659+++ lib/lp/services/profile/profile.py 2010-08-27 14:23:44 +0000
660@@ -10,13 +10,22 @@
661 from datetime import datetime
662 import os
663 import threading
664+import StringIO
665
666 from bzrlib.lsprof import BzrProfiler
667-from zope.component import getUtility
668+from chameleon.zpt.template import PageTemplateFile
669+from zope.app.publication.interfaces import IEndRequestEvent
670+from zope.component import (
671+ adapter,
672+ getUtility,
673+ )
674+from zope.contenttype.parse import parse
675 from zope.error.interfaces import IErrorReportingUtility
676+from zope.traversing.namespace import view
677
678 from canonical.config import config
679 import canonical.launchpad.webapp.adapter as da
680+from canonical.launchpad.webapp.interfaces import IStartRequestEvent
681 from canonical.mem import (
682 memory,
683 resident,
684@@ -30,22 +39,47 @@
685 _profilers = threading.local()
686
687
688+@adapter(IStartRequestEvent)
689 def start_request(event):
690 """Handle profiling.
691
692 If profiling is enabled, start a profiler for this thread. If memory
693 profiling is requested, save the VSS and RSS.
694 """
695- if config.profiling.profile_requests:
696- _profilers.profiler = BzrProfiler()
697- _profilers.profiler.start()
698-
699+ if not config.profiling.profiling_allowed:
700+ return
701+ actions = get_desired_profile_actions(event.request)
702+ if config.profiling.profile_all_requests:
703+ actions.add('log')
704+ _profilers.actions = actions
705+ _profilers.profiler = None
706+ if actions:
707+ if actions.difference(('help', )):
708+ # If this assertion has reason to fail, we'll need to add code
709+ # to try and stop the profiler before we delete it, in case it is
710+ # still running.
711+ assert getattr(_profilers, 'profiler', None) is None
712+ _profilers.profiler = BzrProfiler()
713+ _profilers.profiler.start()
714 if config.profiling.memory_profile_log:
715 _profilers.memory_profile_start = (memory(), resident())
716
717-
718+template = PageTemplateFile(
719+ os.path.join(os.path.dirname(__file__), 'profile.pt'))
720+
721+
722+@adapter(IEndRequestEvent)
723 def end_request(event):
724 """If profiling is turned on, save profile data for the request."""
725+ if not config.profiling.profiling_allowed:
726+ return
727+ try:
728+ actions = _profilers.actions
729+ except AttributeError:
730+ # Some tests don't go through all the proper motions, like firing off
731+ # a start request event. Just be quiet about it.
732+ return
733+ del _profilers.actions
734 request = event.request
735 # Create a timestamp including milliseconds.
736 now = datetime.fromtimestamp(da.get_request_start_time())
737@@ -53,33 +87,63 @@
738 now.strftime('%Y-%m-%d_%H:%M:%S'), int(now.microsecond/1000.0))
739 pageid = request._orig_env.get('launchpad.pageid', 'Unknown')
740 oopsid = getattr(request, 'oopsid', None)
741- if config.profiling.profile_requests:
742- profiler = _profilers.profiler
743- _profilers.profiler = None
744- prof_stats = profiler.stop()
745-
746+ content_type = request.response.getHeader('content-type')
747+ if content_type is None:
748+ content_type_params = {}
749+ is_html = False
750+ else:
751+ _major, _minor, content_type_params = parse(content_type)
752+ is_html = _major == 'text' and _minor == 'html'
753+ template_context = {
754+ 'actions': actions,
755+ 'always_log': config.profiling.profile_all_requests}
756+ if _profilers.profiler is not None:
757+ prof_stats = _profilers.profiler.stop()
758+ # Free some memory.
759+ del _profilers.profiler
760 if oopsid is None:
761 # Log an OOPS to get a log of the SQL queries, and other
762 # useful information, together with the profiling
763 # information.
764 info = (ProfilingOops, None, None)
765 error_utility = getUtility(IErrorReportingUtility)
766- error_utility.raising(info, request)
767- oopsid = request.oopsid
768- filename = '%s-%s-%s-%s.prof' % (
769- timestamp, pageid, oopsid,
770- threading.currentThread().getName())
771-
772- dump_path = os.path.join(config.profiling.profile_dir, filename)
773- prof_stats.save(dump_path, format="callgrind")
774-
775- # Free some memory.
776- _profilers.profiler = None
777-
778+ oops = error_utility.handling(info, request)
779+ oopsid = oops.id
780+ else:
781+ oops = request.oops
782+ if 'log' in actions:
783+ filename = '%s-%s-%s-%s.prof' % (
784+ timestamp, pageid, oopsid,
785+ threading.currentThread().getName())
786+ dump_path = os.path.join(config.profiling.profile_dir, filename)
787+ prof_stats.save(dump_path, format="callgrind")
788+ template_context['dump_path'] = os.path.abspath(dump_path)
789+ if is_html and 'show' in actions:
790+ # Generate raw OOPS results.
791+ f = StringIO.StringIO()
792+ oops.write(f)
793+ template_context['oops'] = f.getvalue()
794+ # Generate profile summaries.
795+ for name in ('inlinetime', 'totaltime', 'callcount'):
796+ prof_stats.sort(name)
797+ f = StringIO.StringIO()
798+ prof_stats.pprint(top=25, file=f)
799+ template_context[name] = f.getvalue()
800+ if actions and is_html:
801+ # Hack the new HTML in at the end of the page.
802+ encoding = content_type_params.get('charset', 'utf-8')
803+ added_html = template.render(**template_context).encode(encoding)
804+ existing_html = request.response.consumeBody()
805+ e_start, e_close_body, e_end = existing_html.rpartition(
806+ '</body>')
807+ new_html = ''.join(
808+ (e_start, added_html, e_close_body, e_end))
809+ request.response.setResult(new_html)
810 # Dump memory profiling info.
811 if config.profiling.memory_profile_log:
812 log = file(config.profiling.memory_profile_log, 'a')
813 vss_start, rss_start = _profilers.memory_profile_start
814+ del _profilers.memory_profile_start
815 vss_end, rss_end = memory(), resident()
816 if oopsid is None:
817 oopsid = '-'
818@@ -87,3 +151,47 @@
819 timestamp, pageid, oopsid, da.get_request_duration(),
820 vss_start, rss_start, vss_end, rss_end))
821 log.close()
822+
823+
824+def get_desired_profile_actions(request):
825+ """What does the URL show that the user wants to do about profiling?
826+
827+ Returns a set of actions (comma-separated) if ++profile++ is in the
828+ URL. Note that ++profile++ alone without actions is interpreted as
829+ the "help" action.
830+ """
831+ result = set()
832+ path_info = request.get('PATH_INFO')
833+ if path_info:
834+ # if not, this is almost certainly a test not bothering to set up
835+ # certain bits. We'll handle it silently.
836+ start, match, end = path_info.partition('/++profile++')
837+ # We don't need no steenkin' regex.
838+ if match:
839+ # Now we figure out what actions are desired. Normally,
840+ # parsing the url segment after the namespace ('++profile++'
841+ # in this case) is done in the traverse method of the
842+ # namespace view (see ProfileNamespace in this file). We
843+ # are doing it separately because we want to know what to do
844+ # before the traversal machinery gets started, so we can
845+ # include traversal in the profile.
846+ actions, slash, tail = end.partition('/')
847+ result.update(
848+ action for action in (
849+ item.strip().lower() for item in actions.split(','))
850+ if action)
851+ result.intersection_update(('log', 'show'))
852+ if not result:
853+ result.add('help')
854+ return result
855+
856+
857+class ProfileNamespace(view):
858+ """A see-through namespace that handles traversals with ++profile++."""
859+
860+ def traverse(self, name, remaining):
861+ """Continue on with traversal.
862+ """
863+ # Note that handling the name is done in get_desired_profile_actions,
864+ # above. See the comment in that function.
865+ return self.context
866
867=== added file 'lib/lp/services/profile/tests.py'
868--- lib/lp/services/profile/tests.py 1970-01-01 00:00:00 +0000
869+++ lib/lp/services/profile/tests.py 2010-08-27 14:23:44 +0000
870@@ -0,0 +1,454 @@
871+# Copyright 2010 Canonical Ltd. This software is licensed under the
872+# GNU Affero General Public License version 3 (see the file LICENSE).
873+
874+"""Tests for lp.services.profile.
875+
876+See lib/canonical/doc/profiling.txt for an end-user description of
877+the functionality.
878+"""
879+
880+__metaclass__ = type
881+
882+import glob
883+import os
884+import time
885+import unittest
886+
887+from lp.testing import TestCase
888+from bzrlib.lsprof import BzrProfiler
889+from zope.app.publication.interfaces import EndRequestEvent
890+from zope.component import getSiteManager
891+
892+import canonical.launchpad.webapp.adapter as da
893+from canonical.launchpad.webapp.errorlog import (
894+ ErrorReport,
895+ ErrorReportingUtility,
896+ )
897+from canonical.launchpad.webapp.servers import LaunchpadTestRequest
898+from canonical.launchpad.webapp.interfaces import StartRequestEvent
899+from lp.services.profile import profile
900+
901+EXAMPLE_HTML_START = '''\
902+<html><head><title>Random!</title></head>
903+<body>
904+<h1>Random!</h1>
905+<p>Whatever!</p>
906+'''
907+EXAMPLE_HTML_END = '''\
908+</body>
909+</html>
910+'''
911+EXAMPLE_HTML = EXAMPLE_HTML_START + EXAMPLE_HTML_END
912+
913+
914+class BaseTest(TestCase):
915+
916+ def _get_request(self, path='/'):
917+ """Return a test request for the given path."""
918+ return LaunchpadTestRequest(PATH_INFO=path)
919+
920+ def _get_start_event(self, path='/'):
921+ """Return a start event for the given path."""
922+ return StartRequestEvent(self._get_request(path))
923+
924+ def assertCleanProfilerState(self, message='something did not clean up'):
925+ """Check whether profiler thread local is clean."""
926+ for name in ('profiler', 'actions', 'memory_profile_start'):
927+ self.assertIs(
928+ getattr(profile._profilers, name, None), None,
929+ 'Profiler state (%s) is dirty; %s.' % (name, message))
930+
931+ def pushProfilingConfig(
932+ self, profiling_allowed='False', profile_all_requests='False',
933+ memory_profile_log=''):
934+ """This is a convenience for setting profile configs."""
935+ self.pushConfig(
936+ 'profiling',
937+ profiling_allowed=profiling_allowed,
938+ profile_all_requests=profile_all_requests,
939+ memory_profile_log=memory_profile_log)
940+
941+
942+class TestRequestStartHandler(BaseTest):
943+ """Tests for the start handler of the profiler integration.
944+
945+ See lib/canonical/doc/profiling.txt for an end-user description of
946+ the functionality.
947+ """
948+
949+ def tearDown(self):
950+ "Do the usual tearDown, plus clean up the profiler object."
951+ if getattr(profile._profilers, 'profiler', None) is not None:
952+ profile._profilers.profiler.stop()
953+ del profile._profilers.profiler
954+ for name in ('actions', 'memory_profile_start'):
955+ if getattr(profile._profilers, name, None) is not None:
956+ delattr(profile._profilers, name)
957+ TestCase.tearDown(self)
958+
959+ def test_config_stops_profiling(self):
960+ """The ``profiling_allowed`` configuration should disable all
961+ profiling, even if it is requested"""
962+ self.pushProfilingConfig(
963+ profiling_allowed='False', profile_all_requests='True',
964+ memory_profile_log='.')
965+ profile.start_request(self._get_start_event('/++profile++show,log'))
966+ self.assertCleanProfilerState('config was ignored')
967+
968+ def test_optional_profiling_without_marked_request_has_no_profile(self):
969+ """Even if profiling is allowed, it does not happen with a normal
970+ request."""
971+ self.pushProfilingConfig(profiling_allowed='True')
972+ profile.start_request(self._get_start_event('/'))
973+ self.assertEqual(profile._profilers.actions, set())
974+ self.assertIs(getattr(profile._profilers, 'profiler', None), None)
975+ self.assertIs(
976+ getattr(profile._profilers, 'memory_profile_start', None), None)
977+
978+ def test_optional_profiling_with_show_request_starts_profiling(self):
979+ """If profiling is allowed and a request with the "show" marker
980+ URL segment is made, profiling starts."""
981+ self.pushProfilingConfig(profiling_allowed='True')
982+ profile.start_request(self._get_start_event('/++profile++show/'))
983+ self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
984+ self.assertIs(
985+ getattr(profile._profilers, 'memory_profile_start', None),
986+ None)
987+ self.assertEquals(profile._profilers.actions, set(('show', )))
988+
989+ def test_optional_profiling_with_log_request_starts_profiling(self):
990+ """If profiling is allowed and a request with the "log" marker
991+ URL segment is made, profiling starts."""
992+ self.pushProfilingConfig(profiling_allowed='True')
993+ profile.start_request(self._get_start_event('/++profile++log/'))
994+ self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
995+ self.assertIs(
996+ getattr(profile._profilers, 'memory_profile_start', None),
997+ None)
998+ self.assertEquals(profile._profilers.actions, set(('log', )))
999+
1000+ def test_optional_profiling_with_combined_request_starts_profiling(self):
1001+ """If profiling is allowed and a request with the "log" and
1002+ "show" marker URL segment is made, profiling starts."""
1003+ self.pushProfilingConfig(profiling_allowed='True')
1004+ profile.start_request(self._get_start_event('/++profile++log,show/'))
1005+ self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
1006+ self.assertIs(
1007+ getattr(profile._profilers, 'memory_profile_start', None),
1008+ None)
1009+ self.assertEquals(profile._profilers.actions, set(('log', 'show')))
1010+
1011+ def test_optional_profiling_with_reversed_request_starts_profiling(self):
1012+ """If profiling is allowed and a request with the "show" and
1013+ "log" marker URL segment is made, profiling starts."""
1014+ self.pushProfilingConfig(profiling_allowed='True')
1015+ # The fact that this is reversed from the previous request is the only
1016+ # difference from the previous test. Also, it doesn't have a
1017+ # trailing slash. :-P
1018+ profile.start_request(self._get_start_event('/++profile++show,log'))
1019+ self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
1020+ self.assertIs(
1021+ getattr(profile._profilers, 'memory_profile_start', None),
1022+ None)
1023+ self.assertEquals(profile._profilers.actions, set(('log', 'show')))
1024+
1025+ def test_forced_profiling_registers_action(self):
1026+ """profile_all_requests should register as a log action"""
1027+ self.pushProfilingConfig(
1028+ profiling_allowed='True', profile_all_requests='True')
1029+ profile.start_request(self._get_start_event('/'))
1030+ self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
1031+ self.assertIs(
1032+ getattr(profile._profilers, 'memory_profile_start', None),
1033+ None)
1034+ self.assertEquals(profile._profilers.actions, set(('log', )))
1035+
1036+ def test_optional_profiling_with_wrong_request_helps(self):
1037+ """If profiling is allowed and a request with the marker URL segment
1038+ is made incorrectly, profiling does not start and help is an action.
1039+ """
1040+ self.pushProfilingConfig(profiling_allowed='True')
1041+ profile.start_request(self._get_start_event('/++profile++/'))
1042+ self.assertIs(getattr(profile._profilers, 'profiler', None), None)
1043+ self.assertIs(
1044+ getattr(profile._profilers, 'memory_profile_start', None),
1045+ None)
1046+ self.assertEquals(profile._profilers.actions, set(('help', )))
1047+
1048+ def test_forced_profiling_with_wrong_request_helps(self):
1049+ """If profiling is forced and a request with the marker URL segment
1050+ is made incorrectly, profiling starts and help is an action.
1051+ """
1052+ self.pushProfilingConfig(
1053+ profiling_allowed='True', profile_all_requests='True')
1054+ profile.start_request(self._get_start_event('/++profile++/'))
1055+ self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
1056+ self.assertIs(
1057+ getattr(profile._profilers, 'memory_profile_start', None),
1058+ None)
1059+ self.assertEquals(profile._profilers.actions, set(('help', 'log')))
1060+
1061+ def test_memory_profile_start(self):
1062+ self.pushProfilingConfig(
1063+ profiling_allowed='True', memory_profile_log='.')
1064+ profile.start_request(self._get_start_event('/'))
1065+ self.assertIs(getattr(profile._profilers, 'profiler', None), None)
1066+ self.assertIsInstance(profile._profilers.memory_profile_start, tuple)
1067+ self.assertEqual(len(profile._profilers.memory_profile_start), 2)
1068+ self.assertEqual(profile._profilers.actions, set())
1069+
1070+ def test_combo_memory_and_profile_start(self):
1071+ self.pushProfilingConfig(
1072+ profiling_allowed='True', memory_profile_log='.')
1073+ profile.start_request(self._get_start_event('/++profile++show/'))
1074+ self.assertIsInstance(profile._profilers.profiler, BzrProfiler)
1075+ self.assertIsInstance(profile._profilers.memory_profile_start, tuple)
1076+ self.assertEqual(len(profile._profilers.memory_profile_start), 2)
1077+ self.assertEquals(profile._profilers.actions, set(('show', )))
1078+
1079+
1080+class TestRequestEndHandler(BaseTest):
1081+ """Tests for the end-request handler.
1082+
1083+ If the start-request handler is broken, these tests will fail too, so fix
1084+ the tests in the above test case first.
1085+
1086+ See lib/canonical/doc/profiling.txt for an end-user description
1087+ of the functionality.
1088+ """
1089+
1090+ def setUp(self):
1091+ TestCase.setUp(self)
1092+ self.patch(da, 'get_request_start_time', time.time)
1093+ self.patch(da, 'get_request_duration', lambda: 0.5)
1094+ self.profile_dir = self.makeTemporaryDirectory()
1095+ self.memory_profile_log = os.path.join(self.profile_dir, 'memory_log')
1096+ self.pushConfig('profiling', profile_dir=self.profile_dir)
1097+ self.eru = ErrorReportingUtility()
1098+ sm = getSiteManager()
1099+ sm.registerUtility(self.eru)
1100+ self.addCleanup(sm.unregisterUtility, self.eru)
1101+
1102+ def _get_end_event(self, path='/', result=EXAMPLE_HTML, pageid=None):
1103+ """Return a stop event for the given path and output HTML."""
1104+ start_event = self._get_start_event(path)
1105+ profile.start_request(start_event)
1106+ request = start_event.request
1107+ if pageid is not None:
1108+ request.setInWSGIEnvironment('launchpad.pageid', pageid)
1109+ request.response.setResult(result)
1110+ context = object()
1111+ return EndRequestEvent(context, request)
1112+
1113+ def endRequest(self, path='/', exception=None, pageid=None):
1114+ event = self._get_end_event(path, pageid=pageid)
1115+ if exception is not None:
1116+ self.eru.raising(
1117+ (type(exception), exception, None), event.request)
1118+ profile.end_request(event)
1119+ return event.request
1120+
1121+ def getAddedResponse(self, request,
1122+ start=EXAMPLE_HTML_START, end=EXAMPLE_HTML_END):
1123+ output = request.response.consumeBody()
1124+ return output[len(start):-len(end)]
1125+
1126+ def getMemoryLog(self):
1127+ if not os.path.exists(self.memory_profile_log):
1128+ return []
1129+ f = open(self.memory_profile_log)
1130+ result = f.readlines()
1131+ f.close()
1132+ return result
1133+
1134+ def getProfilePaths(self):
1135+ return glob.glob(os.path.join(self.profile_dir, '*.prof'))
1136+
1137+ #########################################################################
1138+ # Tests
1139+ def test_config_stops_profiling(self):
1140+ """The ``profiling_allowed`` configuration should disable all
1141+ profiling, even if it is requested"""
1142+ self.pushProfilingConfig(
1143+ profiling_allowed='False', profile_all_requests='True',
1144+ memory_profile_log=self.memory_profile_log)
1145+ request = self.endRequest('/++profile++show,log')
1146+ self.assertIs(getattr(request, 'oops', None), None)
1147+ self.assertEqual(self.getAddedResponse(request), '')
1148+ self.assertEqual(self.getMemoryLog(), [])
1149+ self.assertEqual(self.getProfilePaths(), [])
1150+ self.assertCleanProfilerState()
1151+
1152+ def test_optional_profiling_without_marked_request_has_no_profile(self):
1153+ """Even if profiling is allowed, it does not happen with a normal
1154+ request."""
1155+ self.pushProfilingConfig(profiling_allowed='True')
1156+ request = self.endRequest('/')
1157+ self.assertIs(getattr(request, 'oops', None), None)
1158+ self.assertEqual(self.getAddedResponse(request), '')
1159+ self.assertEqual(self.getMemoryLog(), [])
1160+ self.assertEqual(self.getProfilePaths(), [])
1161+ self.assertCleanProfilerState()
1162+
1163+ def test_optional_profiling_with_show_request_profiles(self):
1164+ """If profiling is allowed and a request with the "show" marker
1165+ URL segment is made, profiling starts."""
1166+ self.pushProfilingConfig(profiling_allowed='True')
1167+ request = self.endRequest('/++profile++show/')
1168+ self.assertIsInstance(request.oops, ErrorReport)
1169+ self.assertIn('Top Inline Time', self.getAddedResponse(request))
1170+ self.assertEqual(self.getMemoryLog(), [])
1171+ self.assertEqual(self.getProfilePaths(), [])
1172+ self.assertCleanProfilerState()
1173+
1174+ def test_optional_profiling_with_log_request_profiles(self):
1175+ """If profiling is allowed and a request with the "log" marker
1176+ URL segment is made, profiling starts."""
1177+ self.pushProfilingConfig(profiling_allowed='True')
1178+ request = self.endRequest('/++profile++log/')
1179+ self.assertIsInstance(request.oops, ErrorReport)
1180+ response = self.getAddedResponse(request)
1181+ self.assertIn('Profile was logged to', response)
1182+ self.assertNotIn('Top Inline Time', response)
1183+ self.assertEqual(self.getMemoryLog(), [])
1184+ paths = self.getProfilePaths()
1185+ self.assertEqual(len(paths), 1)
1186+ self.assertIn(paths[0], response)
1187+ self.assertCleanProfilerState()
1188+
1189+ def test_optional_profiling_with_combined_request_profiles(self):
1190+ """If profiling is allowed and a request with the "log" and
1191+ "show" marker URL segment is made, profiling starts."""
1192+ self.pushProfilingConfig(profiling_allowed='True')
1193+ request = self.endRequest('/++profile++log,show')
1194+ self.assertIsInstance(request.oops, ErrorReport)
1195+ response = self.getAddedResponse(request)
1196+ self.assertIn('Profile was logged to', response)
1197+ self.assertIn('Top Inline Time', response)
1198+ self.assertEqual(self.getMemoryLog(), [])
1199+ paths = self.getProfilePaths()
1200+ self.assertEqual(len(paths), 1)
1201+ self.assertIn(paths[0], response)
1202+ self.assertCleanProfilerState()
1203+
1204+ def test_forced_profiling_logs(self):
1205+ """profile_all_requests should register as a log action"""
1206+ self.pushProfilingConfig(
1207+ profiling_allowed='True', profile_all_requests='True')
1208+ request = self.endRequest('/')
1209+ self.assertIsInstance(request.oops, ErrorReport)
1210+ response = self.getAddedResponse(request)
1211+ self.assertIn('Profile was logged to', response)
1212+ self.assertIn('profile_all_requests: True', response)
1213+ self.assertNotIn('Top Inline Time', response)
1214+ self.assertEqual(self.getMemoryLog(), [])
1215+ paths = self.getProfilePaths()
1216+ self.assertEqual(len(paths), 1)
1217+ self.assertIn(paths[0], response)
1218+ self.assertCleanProfilerState()
1219+
1220+ def test_optional_profiling_with_wrong_request_helps(self):
1221+ """If profiling is allowed and a request with the marker URL segment
1222+ is made incorrectly, profiling does not start and help is an action.
1223+ """
1224+ self.pushProfilingConfig(profiling_allowed='True')
1225+ request = self.endRequest('/++profile++')
1226+ self.assertIs(getattr(request, 'oops', None), None)
1227+ response = self.getAddedResponse(request)
1228+ self.assertIn('<h2>Help</h2>', response)
1229+ self.assertNotIn('Top Inline Time', response)
1230+ self.assertEqual(self.getMemoryLog(), [])
1231+ self.assertEqual(self.getProfilePaths(), [])
1232+ self.assertCleanProfilerState()
1233+
1234+ def test_forced_profiling_with_wrong_request_helps(self):
1235+ """If profiling is forced and a request with the marker URL segment
1236+ is made incorrectly, profiling starts and help is an action.
1237+ """
1238+ self.pushProfilingConfig(
1239+ profiling_allowed='True', profile_all_requests='True')
1240+ request = self.endRequest('/++profile++')
1241+ self.assertIsInstance(request.oops, ErrorReport)
1242+ response = self.getAddedResponse(request)
1243+ self.assertIn('<h2>Help</h2>', response)
1244+ self.assertIn('Profile was logged to', response)
1245+ self.assertIn('profile_all_requests: True', response)
1246+ self.assertNotIn('Top Inline Time', response)
1247+ self.assertEqual(self.getMemoryLog(), [])
1248+ paths = self.getProfilePaths()
1249+ self.assertEqual(len(paths), 1)
1250+ self.assertIn(paths[0], response)
1251+ self.assertCleanProfilerState()
1252+
1253+ def test_memory_profile(self):
1254+ "Does the memory profile work?"
1255+ self.pushProfilingConfig(
1256+ profiling_allowed='True',
1257+ memory_profile_log=self.memory_profile_log)
1258+ request = self.endRequest('/')
1259+ self.assertIs(getattr(request, 'oops', None), None)
1260+ self.assertEqual(self.getAddedResponse(request), '')
1261+ log = self.getMemoryLog()
1262+ self.assertEqual(len(log), 1)
1263+ (timestamp, page_id, oops_id, duration, start_vss, start_rss,
1264+ end_vss, end_rss) = log[0].split()
1265+ self.assertEqual(page_id, 'Unknown')
1266+ self.assertEqual(oops_id, '-')
1267+ self.assertEqual(float(duration), 0.5)
1268+ self.assertEqual(self.getProfilePaths(), [])
1269+ self.assertCleanProfilerState()
1270+
1271+ def test_memory_profile_with_non_defaults(self):
1272+ "Does the memory profile work with an oops and pageid?"
1273+ self.pushProfilingConfig(
1274+ profiling_allowed='True',
1275+ memory_profile_log=self.memory_profile_log)
1276+ request = self.endRequest('/++profile++show/no-such-file',
1277+ KeyError(), pageid='Foo')
1278+ log = self.getMemoryLog()
1279+ (timestamp, page_id, oops_id, duration, start_vss, start_rss,
1280+ end_vss, end_rss) = log[0].split()
1281+ self.assertEqual(page_id, 'Foo')
1282+ self.assertEqual(oops_id, request.oopsid)
1283+ self.assertCleanProfilerState()
1284+
1285+ def test_combo_memory_and_profile(self):
1286+ self.pushProfilingConfig(
1287+ profiling_allowed='True',
1288+ memory_profile_log=self.memory_profile_log)
1289+ request = self.endRequest('/++profile++show/')
1290+ self.assertIsInstance(request.oops, ErrorReport)
1291+ self.assertIn('Top Inline Time', self.getAddedResponse(request))
1292+ self.assertEqual(len(self.getMemoryLog()), 1)
1293+ self.assertEqual(self.getProfilePaths(), [])
1294+ self.assertCleanProfilerState()
1295+
1296+ def test_profiling_oops_is_informational(self):
1297+ self.pushProfilingConfig(profiling_allowed='True')
1298+ request = self.endRequest('/++profile++show/')
1299+ response = self.getAddedResponse(request)
1300+ self.assertIsInstance(request.oops, ErrorReport)
1301+ self.assertTrue(request.oops.informational)
1302+ self.assertEquals(request.oops.type, 'ProfilingOops')
1303+ self.assertCleanProfilerState()
1304+
1305+ def test_real_oops_trumps_profiling_oops(self):
1306+ self.pushProfilingConfig(profiling_allowed='True')
1307+ request = self.endRequest('/++profile++show/no-such-file',
1308+ KeyError('foo'))
1309+ self.assertIsInstance(request.oops, ErrorReport)
1310+ self.assertFalse(request.oops.informational)
1311+ self.assertEquals(request.oops.type, 'KeyError')
1312+ response = self.getAddedResponse(request)
1313+ self.assertIn('Exception-Type: KeyError', response)
1314+ self.assertCleanProfilerState()
1315+
1316+ def test_oopsid_is_in_profile_filename(self):
1317+ self.pushProfilingConfig(profiling_allowed='True')
1318+ request = self.endRequest('/++profile++log/')
1319+ self.assertIn("-" + request.oopsid + "-", self.getProfilePaths()[0])
1320+ self.assertCleanProfilerState()
1321+
1322+
1323+def test_suite():
1324+ return unittest.TestLoader().loadTestsFromName(__name__)