Launchpad itself

Merge lp:~stub/launchpad/page-performance-report into lp:launchpad

  1. page-performance-report
  2. Merge into devel
Proposed by Stuart Bishop
Status: Merged
Approved by: Muharem Hrnjadovic
Approved revision: not available
Merged at revision: not available
Proposed branch: lp:~stub/launchpad/page-performance-report
Merge into: lp:launchpad
Diff against target: 512 lines (+493/-0)
4 files modified
lib/lp/scripts/helpers.py (+57/-0)
lib/lp/scripts/utilities/pageperformancereport.py (+387/-0)
utilities/page-performance-report.ini (+31/-0)
utilities/page-performance-report.py (+18/-0)
To merge this branch: bzr merge lp:~stub/launchpad/page-performance-report
Reviewer Review Type Date Requested Status
Muharem Hrnjadovic (community) Approve
Review via email: mp+18522@code.launchpad.net
To post a comment you must log in.
Revision history for this message
Stuart Bishop (stub) wrote :

We want to make slow pages faster. At the moment we do this by optimizing test pages, but we really have no idea if we have made other pages slower. When we optimize, we need to ensure the system improves overall rather than playing whack a mole, speeding up some pages while causing others to timeout.

This hasn't been a genuine problem so far, but we want to evaluate using memcache. memcache is unusual in that it will slow down the initial page renderings due to overhead in stuffing data into the caches, and speed up repeat renderings. This branch is to provide us with tools to confirm if our experiments succeeded or failed.

The reporting tool is basic, but meets our initial needs in the current state. An example report from edge data can be found at http://people.canonical.com/~stub/lpperf.html .

To get meaningful graphs I had to use a pretty severe logarithmic scale on the y-axis and the numerical stats (mean, median, standard deviation) are pretty useless with real Launchpad data, but it is a start. The issue here is that slow requests are actually vastly outnumbered by fast requests in most of Launchpad, which is surprising to developers who spend their time worrying about the minor percentage of pages that generate timeouts and create the bulk of complaints.

Revision history for this message
Muharem Hrnjadovic (al-maisan) wrote :

The example report quoted in the merge proposal cover letter looks very good!

review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
=== added file 'lib/lp/scripts/helpers.py'
--- lib/lp/scripts/helpers.py 1970-01-01 00:00:00 +0000
+++ lib/lp/scripts/helpers.py 2010-02-03 14:58:22 +0000
@@ -0,0 +1,57 @@
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"""Helpers for command line tools."""
5
6__metaclass__ = type
7__all__ = ["LPOptionParser"]
8
9from copy import copy
10from datetime import datetime
11from optparse import Option, OptionParser, OptionValueError
12
13from canonical.launchpad.scripts.logger import logger_options
14
15
16def _check_datetime(option, opt, value):
17 "Type checker for optparse datetime option type."
18 # We support 5 valid ISO8601 formats.
19 formats = [
20 '%Y-%m-%dT%H:%M:%S',
21 '%Y-%m-%dT%H:%M',
22 '%Y-%m-%d %H:%M:%S',
23 '%Y-%m-%d %H:%M',
24 '%Y-%m-%d',
25 ]
26 for format in formats:
27 try:
28 return datetime.strptime(value, format)
29 except ValueError:
30 pass
31 raise OptionValueError(
32 "option %s: invalid datetime value: %r" % (opt, value))
33
34
35class LPOption(Option):
36 """Extended optparse Option class.
37
38 Adds a 'datetime' option type.
39 """
40 TYPES = Option.TYPES + ("datetime",)
41 TYPE_CHECKER = copy(Option.TYPE_CHECKER)
42 TYPE_CHECKER["datetime"] = _check_datetime
43
44
45class LPOptionParser(OptionParser):
46 """Extended optparse OptionParser.
47
48 Adds a 'datetime' option type.
49
50 Automatically adds our standard --verbose, --quiet options that
51 tie into our logging system.
52 """
53 def __init__(self, *args, **kw):
54 kw.setdefault('option_class', LPOption)
55 OptionParser.__init__(self, *args, **kw)
56 logger_options(self)
57
058
=== added file 'lib/lp/scripts/utilities/pageperformancereport.py'
--- lib/lp/scripts/utilities/pageperformancereport.py 1970-01-01 00:00:00 +0000
+++ lib/lp/scripts/utilities/pageperformancereport.py 2010-02-03 14:58:22 +0000
@@ -0,0 +1,387 @@
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"""Page performance report generated from zserver trace logs."""
5
6__metaclass__ = type
7__all__ = ['main']
8
9import bz2
10from cgi import escape as html_quote
11from ConfigParser import RawConfigParser
12from datetime import datetime
13import gzip
14import re
15import sre_constants
16import os.path
17from textwrap import dedent
18import time
19
20import numpy
21import simplejson as json
22from zc.zservertracelog.tracereport import Request, parsedt
23
24from canonical.config import config
25from canonical.launchpad.scripts.logger import log
26from lp.scripts.helpers import LPOptionParser
27
28
29class Category:
30 """A Category in our report.
31
32 Requests belong to a Category if the URL matches a regular expression.
33 """
34 def __init__(self, title, regexp, timeout):
35 self.title = title
36 self.regexp = regexp
37 self._compiled_regexp = re.compile(regexp, re.I | re.X)
38 self.times = Times(timeout)
39
40 def add(self, request):
41 """Add a request to a Category if it belongs.
42
43 Does nothing if the request does not belong in this Category.
44 """
45 if self._compiled_regexp.search(request.url) is not None:
46 self.times.add(request)
47
48 def __cmp__(self, other):
49 return cmp(self.title.lower(), other.title.lower())
50
51
52class Times:
53 """Collection of request times."""
54 def __init__(self, timeout):
55 self.request_times = []
56 self.timeout = timeout
57
58 def add(self, request):
59 """Add the application time from the request to the collection.
60
61 The application time is capped to our timeout.
62 """
63 self.request_times.append(min(request.app_seconds, self.timeout))
64
65 def stats(self):
66 """Generate statistics about our request times.
67
68 Returns (mean, median, standard_deviation, histogram).
69
70 The histogram is a list of request counts per 1 second bucket.
71 ie. histogram[0] contains the number of requests taking between 0 and
72 1 second, histogram[1] contains the number of requests taking between
73 1 and 2 seconds etc. histogram is None if there are no requests in
74 this Category.
75 """
76
77 if not self.request_times:
78 return 0, 0, 0, None
79 array = numpy.asarray(self.request_times, numpy.float32)
80 mean = numpy.mean(array)
81 median = numpy.median(array)
82 standard_deviation = numpy.std(array)
83 histogram = numpy.histogram(
84 array, normed=True,
85 range=(0, self.timeout), bins=self.timeout)
86 histogram = zip(histogram[1], histogram[0])
87 return mean, median, standard_deviation, histogram
88
89 def __str__(self):
90 results = self.stats()
91 mean, median, standard_deviation, histogram = results
92 hstr = " ".join("%2d" % v for v in histogram)
93 return "%2.2f %2.2f %2.2f %s" % (
94 mean, median, standard_deviation, hstr)
95
96
97def main():
98 parser = LPOptionParser("%prog [args] tracelog [...]")
99 parser.add_option(
100 "-c", "--config", dest="config",
101 default=os.path.join(
102 config.root, "utilities", "page-performance-report.ini"),
103 metavar="FILE", help="Load configuration from FILE")
104 parser.add_option(
105 "--timeout", dest="timeout", type="int",
106 default=20, metavar="SECS",
107 help="Requests taking more than SECS seconds are timeouts")
108 parser.add_option(
109 "--from", dest="from_ts", type="datetime",
110 default=None, metavar="TIMESTAMP",
111 help="Ignore log entries before TIMESTAMP")
112 parser.add_option(
113 "--until", dest="until_ts", type="datetime",
114 default=None, metavar="TIMESTAMP",
115 help="Ignore log entries after TIMESTAMP")
116 options, args = parser.parse_args()
117 if len(args) == 0:
118 parser.error("At least one zserver tracelog file must be provided")
119
120 if options.from_ts is not None and options.until_ts is not None:
121 if options.from_ts > options.until_ts:
122 parser.error(
123 "--from timestamp %s is before --until timestamp %s"
124 % (options.from_ts, options.until_ts))
125
126 for filename in args:
127 if not os.path.exists(filename):
128 parser.error("Tracelog file %s not found." % filename)
129
130 if not os.path.exists(options.config):
131 parser.error("Config file %s not found." % options.config)
132
133 # Need a better config mechanism as ConfigParser doesn't preserve order.
134 script_config = RawConfigParser()
135 script_config.optionxform = str # Make keys case sensitive.
136 script_config.readfp(open(options.config))
137
138 categories = [] # A list of Category, in report order.
139 for option in script_config.options('categories'):
140 regexp = script_config.get('categories', option)
141 try:
142 categories.append(Category(option, regexp, options.timeout))
143 except sre_constants.error, x:
144 log.fatal("Unable to compile regexp %r (%s)" % (regexp, x))
145 return 1
146 categories.sort()
147
148 if len(categories) == 0:
149 parser.error("No data in [categories] section of configuration.")
150
151 parse(args, categories, options)
152
153 print_html_report(categories)
154
155 return 0
156
157
158def smart_open(filename, mode='r'):
159 """Open a file, transparently handling compressed files.
160
161 Compressed files are detected by file extension.
162 """
163 ext = os.path.splitext(filename)[1]
164 if ext == '.bz2':
165 return bz2.BZ2File(filename, mode)
166 elif ext == '.gz':
167 return gzip.open(filename, mode)
168 else:
169 return open(filename, mode)
170
171
172class MalformedLine(Exception):
173 """A malformed line was found in the trace log."""
174
175
176_ts_re = re.compile(
177 '^(\d{4})-(\d\d)-(\d\d)\s(\d\d):(\d\d):(\d\d)(?:.(\d{6}))?$')
178
179
180def parse_timestamp(ts_string):
181 match = _ts_re.search(ts_string)
182 if match is None:
183 raise ValueError("Invalid timestamp")
184 return datetime(
185 *(int(elem) for elem in match.groups() if elem is not None))
186
187
188def parse(tracefiles, categories, options):
189 requests = {}
190 total_requests = 0
191 for tracefile in tracefiles:
192 log.info('Processing %s', tracefile)
193 for line in smart_open(tracefile):
194 line = line.rstrip()
195 try:
196 record = line.split(' ',7)
197 try:
198 record_type, request_id, date, time_ = record[:4]
199 except ValueError:
200 raise MalformedLine()
201
202 if record_type == 'S':
203 # Short circuit - we don't care about these entries.
204 continue
205
206 # Parse the timestamp.
207 ts_string = '%s %s' % (date, time_)
208 try:
209 dt = parse_timestamp(ts_string)
210 except ValueError:
211 raise MalformedLine(
212 'Invalid timestamp %s' % repr(ts_string))
213
214 # Filter entries by command line date range.
215 if options.from_ts is not None and dt < options.from_ts:
216 continue # Skip to next line.
217 if options.until_ts is not None and dt > options.until_ts:
218 break # Skip to next log file.
219
220 args = record[4:]
221
222 def require_args(count):
223 if len(args) < count:
224 raise MalformedLine()
225
226 if record_type == 'B': # Request begins.
227 require_args(2)
228 requests[request_id] = Request(dt, args[0], args[1])
229 continue
230
231 request = requests.get(request_id, None)
232 if request is None: # Just ignore partial records.
233 continue
234
235 if record_type == '-': # Extension record from Launchpad.
236 # Launchpad outputs the full URL to the tracelog,
237 # including protocol & hostname. Use this in favor of
238 # the ZServer logged path.
239 require_args(1)
240 request.url = args[0]
241
242 elif record_type == 'I': # Got request input.
243 require_args(1)
244 request.I(dt, args[0])
245
246 elif record_type == 'C': # Entered application thread.
247 request.C(dt)
248
249 elif record_type == 'A': # Application done.
250 require_args(2)
251 request.A(dt, args[0], args[1])
252
253 elif record_type == 'E': # Request done.
254 del requests[request_id]
255 request.E(dt)
256 total_requests += 1
257 if total_requests % 10000 == 0:
258 log.debug("Parsed %d requests", total_requests)
259 for category in categories:
260 category.add(request)
261
262 else:
263 raise MalformedLine('Unknown record type %s', record_type)
264 except MalformedLine, x:
265 log.error(
266 "Malformed line %s %s (%s)" % (repr(line), repr(args), x))
267
268
269def print_html_report(categories):
270
271 print dedent('''\
272 <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN"
273 "http://www.w3.org/TR/html4/loose.dtd">
274 <html>
275 <head>
276 <meta http-equiv="Content-Type" content="text/html; charset=utf-8">
277 <title>Launchpad Page Performance Report %(date)s</title>
278 <script language="javascript" type="text/javascript"
279 src="http://people.canonical.com/~stub/flot/jquery.min.js"
280 ></script>
281 <script language="javascript" type="text/javascript"
282 src="http://people.canonical.com/~stub/flot/jquery.flot.min.js"
283 ></script>
284 <style type="text/css">
285 h2 { font-weight: normal; font-size: 100%%; }
286 thead th { padding-left: 1em; padding-right: 1em; }
287 .category-title { text-align: right; padding-right: 2em; }
288 .regexp { font-size: x-small; font-weight: normal; }
289 .mean { text-align: right; padding-right: 1em; }
290 .median { text-align: right; padding-right: 1em; }
291 .standard-deviation { text-align: right; padding-right: 1em; }
292 .histogram { padding: 0.5em 1em; width:400px; height:250px; }
293 .odd-row { background-color: #eeeeff; }
294 .even-row { background-color: #ffffee; }
295 </style>
296 </head>
297 <body>
298 <h1>Launchpad Page Performance Report</h1>
299 <h2>%(date)s</h2>
300
301 <table class="launchpad-performance-report">
302 <thead>
303 <tr>
304 <td></td>
305 <th>Mean</th>
306 <th>Median</th>
307 <th>Standard<br/>Deviation</th>
308 <th>Distribution</th>
309 </tr>
310 </thead>
311 <tbody>
312 ''' % {'date': time.ctime()})
313
314 histograms = []
315 for i, category in enumerate(categories):
316 row_class = "even-row" if i % 2 else "odd-row"
317 mean, median, standard_deviation, histogram = category.times.stats()
318 histograms.append(histogram)
319 print dedent("""\
320 <tr class="%s">
321 <th class="category-title">%s <div class="regexp">%s</span></th>
322 <td class="mean">%.2f s</td>
323 <td class="median">%.2f s</td>
324 <td class="standard-deviation">%.2f s</td>
325 <td>
326 <div class="histogram" id="histogram%d"></div>
327 </td>
328 </tr>
329 """ % (
330 row_class,
331 html_quote(category.title), html_quote(category.regexp),
332 mean, median, standard_deviation, i))
333
334 print dedent("""\
335 <script language="javascript" type="text/javascript">
336 $(function () {
337 var options = {
338 series: {
339 bars: {show: true}
340 },
341 xaxis: {
342 tickDecimals: 0,
343 tickFormatter: function (val, axis) {
344 return val.toFixed(axis.tickDecimals) + "s";
345 }
346 },
347 yaxis: {
348 min: 0,
349 max: 1,
350 transform: function (v) {
351 return Math.pow(Math.log(v*100+1)/Math.LN2, 0.5);
352 },
353 inverseTransform: function (v) {
354 return Math.pow(Math.exp(v*100+1)/Math.LN2, 2);
355 },
356 tickDecimals: 1,
357 tickFormatter: function (val, axis) {
358 return (val * 100).toFixed(axis.tickDecimals) + "%";
359 },
360 ticks: [0.001,0.01,0.10,0.50,1.0]
361 },
362 grid: {
363 aboveData: true,
364 labelMargin: 15
365 }
366 };
367 """)
368
369 for i, histogram in enumerate(histograms):
370 if histogram is None:
371 continue
372 print dedent("""\
373 var d = %s;
374
375 $.plot(
376 $("#histogram%d"),
377 [{data: d}], options);
378
379 """ % (json.dumps(histogram), i))
380
381 print dedent("""\
382 });
383 </script>
384 </body>
385 </html>
386 """)
387
0388
=== added file 'utilities/page-performance-report.ini'
--- utilities/page-performance-report.ini 1970-01-01 00:00:00 +0000
+++ utilities/page-performance-report.ini 2010-02-03 14:58:22 +0000
@@ -0,0 +1,31 @@
1[categories]
2All Launchpad=.
3
4Registry=^https?://(edge\.)?launchpad\.
5Registry - Person Index=/(~|%7E)[^/]+$
6Registry - Pillar Index=^https?://(edge\.)?launchpad.[^/]+/\w[^/]*$
7
8Answers=^https?://answers\.(edge\.)?launchpad\.
9
10Blueprints=^https?://blueprints\.(edge\.)?launchpad\.
11
12Bugs=^https?://bugs\.(edge\.)?launchpad\.
13Bugs - Bug Page=\+bug/\d+$
14Bugs - Pillar Index=^https?://bugs\.(edge\.)?launchpad\.[^/]+/\w[^/]*$
15Bugs - Search=/\+bugs\?
16
17Code=^https?://code\.(edge\.)?launchpad\.
18Code - PPA Index=/\+archive/[^/]+$
19Code - Pillar Branches=^https?://code\.(edge\.)?launchpad\.[^/]+/\w[^/]*$
20Code - Branch Page=^https?://code\.(edge\.)?launchpad\.[^/]+/(~|%7E)[^/]+/[^/]+/[^/]+$
21Code - Merge Proposal=/\+merge/\d+$
22
23Translations=^https?://translations\.(edge\.)?launchpad\.
24Translations - Overview=^https?://translations\..*/\+lang/\w+$
25
26API=^https?://api\.(edge\.)?launchpad\.
27Public XML-RPC=^https?://xmlrpc\.(edge\.)launchpad\.
28Private XML-RPC=^https?://xmlrpc-private\.(edge\.)launchpad\.
29Shipit=^https?://shipit\.
30Launchpad Homepage=^https?://(edge\.)?launchpad\.
31
032
=== added file 'utilities/page-performance-report.py'
--- utilities/page-performance-report.py 1970-01-01 00:00:00 +0000
+++ utilities/page-performance-report.py 2010-02-03 14:58:22 +0000
@@ -0,0 +1,18 @@
1#!/usr/bin/python2.5
2#
3# Copyright 2010 Canonical Ltd. This software is licensed under the
4# GNU Affero General Public License version 3 (see the file LICENSE).
5
6"""Page performance report generated from zserver tracelogs."""
7
8__metaclass__ = type
9
10import _pythonpath
11
12import sys
13
14from lp.scripts.utilities.pageperformancereport import main
15
16
17if __name__ == '__main__':
18 sys.exit(main())