1
<!-- Style is supposed to go in the head. We don't have one here. This seems
2
to work for FF and WebKit. -->
3
<style type="text/css">
4
.python_topten {margin-bottom: 4px;}
5
.python_danger {background-color: red;}
6
.python_warning {background-color: yellow;}
7
.sql_danger .sqlstep {background-color: red;}
8
.sql_warning .sqlstep {background-color: yellow;}
9
.trace .dbstack {font-size: smaller; color: gray}
10
.sqlinfo {border-bottom: 1px gray dotted; padding-bottom: 2px;}
11
.sqlstats {margin-left: 1ex;}
12
.sqlstep {border: LightGray solid 1px; margin-bottom: 4px;}
13
.sqlstep.sql_danger {border-color: red;}
14
.sqlstep.sql_warning {border-color: yellow;}
15
.sqlstep .trace {background-color: GhostWhite; font-size: small; clear: both;}
16
.sqlstep .trace .line {margin-left: 2em; font-family: monospace;}
17
.sqlstep .trace .supplement, .sqlstep .trace .extrainfo {
18
font-weight: bold; margin-left: 2em;}
19
.tracebackwarning {color: red;}
20
.col1 {width: 60em; float: left;}
21
a.clicktext {font-weight: normal;}
22
.trace {overflow: hidden;}
23
.trace.inner {height: auto; overflow: hidden;}
24
.querylinks {margin-left: 2em;}
26
1
<div class="profiling_info">
27
2
<div class="hide_reveal_profiling" id="reveal_profiling">
28
<a href="#">Click to REVEAL profiling information</a>
3
Click to REVEAL profiling information
31
6
<div class="profiling_info" id="profiling_info"
32
7
tal:define="actions options/actions;
33
8
help actions/help|nothing;
34
callgrind actions/callgrind|nothing;
35
pstats actions/pstats|nothing;
36
log python: callgrind or pstats;
9
log actions/log|nothing;
37
10
show actions/show|nothing;
38
11
always_log options/always_log;
39
12
dump_path options/dump_path;
40
callgrind_path options/callgrind_path|nothing;
41
pstats_path options/pstats_path|nothing;
42
time options/time|nothing;
43
cumulative options/cumulative|nothing;
44
calls options/calls|nothing;
13
inlinetime options/inlinetime|nothing;
14
totaltime options/totaltime|nothing;
15
callcount options/callcount|nothing;
45
16
oops options/oops|nothing;
46
profile_count options/profile_count|nothing;
47
multiple_profiles options/multiple_profiles|nothing;
48
inline_ignored actions/inline_ignored|nothing;
49
inline actions/inline|nothing;
50
sqltrace actions/sql|nothing;
51
sqltrace_steps options/sqltrace|nothing;
53
18
<div class="hide_reveal_profiling" id="hide_profiling">
54
<a href="#">Click to HIDE profiling information</a>
19
Click to HIDE profiling information
56
21
<h1>Profiling Information</h1>
57
22
<tal:block condition="help">
63
28
you'll always see some logging information below. In order to also
64
29
get immediate profiling results in the browser, use
65
30
<code>++profile++show</code>.</tal:block> <tal:block condition="not:
66
always_log">In order to get profiling results, you need to ask for an HTML
67
view of the profile and OOPS data including SQL calls
68
(<code>++profile++show</code>), a KCacheGrind-friendly log on the
69
filesystem (<code>++profile++callgrind</code>), a PStats-friendly log
70
(Python standard library) on the filesystem
71
(<code>++profile++pstats</code>), an HTML view of the SQL and the
72
Python stacktrace when each SQL call was made
73
(<code>++profile++sqltrace</code>), or an HTML view of only the SQL
74
(<code>++profile++sql</code>). You can also combine these
75
(<code>++profile++show&callgrind</code> or
76
<code>++profile++show&pstats</code> or others, with each action separated
77
with ampersands).</tal:block></p>
78
<p>The <code>++profile++sqltrace</code> can take too much time to let a
79
page practically render, especially on qastaging and staging. You can
80
filter to only get the stacktraces you want in this case; see information
81
in the "SQL trace" section below on how to do this.</p>
82
<p>The "++profile++" path segment can usually go anywhere in the URL
83
(e.g., <code>http://launchpad.dev/++profile++show</code> or
31
always_log">In order to get profiling results, you need to ask for
32
an HTML view (<code>++profile++show</code>), a KCacheGrind-friendly
33
log on the filesystem (<code>++profile++log</code>), or both
34
(<code>++profile++show,log</code>).</tal:block> This can usually go
35
anywhere in the URL (e.g.,
36
<code>http://launchpad.dev/++profile++show</code> or
84
37
<code>http://launchpad.dev/++profile++show/Firefox</code> or
85
<code>http://launchpad.dev/Firefox/++profile++show</code>) but some pages
86
do seem to redirect in surprising ways, so experimentation may be
88
<p>If you are working on a developer instance of Launchpad, you can also
89
insert calls directly in your code to profile certain code paths. Try
90
something like this:</p>
92
from lp.services.profile import profiling
94
# Do the work that you want profiled here!
96
<p>Multiple calls like this within a single request will be aggregated
99
<tal:block condition="inline_ignored">
100
<h2>Inline request ignored</h2>
101
<p>You tried to use a profiling call in your code while also using a
102
conflicting <code>++profile++</code> request (like <code>show</code> or
103
<code>pstats</code> or <code>callgrind</code>). You can't use both at the
104
same time, so you got the full profile of this request. If you want the
105
results of the inline calls instead, try removing the
106
<code>++profile++</code>...<code>/</code> segment from your browser's URL.
109
<tal:block condition="inline">
110
<h2>Inline request</h2>
111
<p>These results are from profiling statements in your code. <tal:block
112
condition="multiple_profiles">This request made <tal:block
113
replace="profile_count" /> individual profiles. The data here represent
114
an aggregate of all the profiles.</tal:block></p>
38
<code>http://launchpad.dev/Firefox/++profile++show</code>) but some
39
pages do seem to redirect in surprising ways, so experimentation may
116
42
<h2>Log information</h2>
117
43
<tal:block condition="not:log">
118
44
<p>Profile was not logged to file.</p>
119
<p>Use <code>++profile++callgrind</code> in your URL in order to log the
120
information to file for later KCacheGrind analysis. KCacheGrind is great
121
for visualizing a profile, but it only allows analyzing a limited depth of
122
calls. If you want a greater profile depth, or if for any other reason
123
you want to use the standard Python library's pstats analysis instead, you
124
can. To do this, use "pstats" instead as part of your ++profile++ request,
125
as in <code>++profile++pstats</code>. Profiles are logged to <tal:block
126
replace="dump_path" />.</p>
127
<p> You can see both the log information and immediate results with
128
<code>++profile++callgrind&show</code> or
129
<code>++profile++pstats&show</code>.</p>
45
<p>Use <code>++profile++log</code> in your URL in order to log the
46
information to file for later KCacheGrind analysis (or
47
<code>++profile++log,show</code> to see both the log information and
48
immediate results). Profiles are logged to
49
<tal:block replace="dump_path" />.</p>
131
51
<tal:block condition="log">
132
52
<p tal:condition="always_log"><strong>You have configured every
134
54
<code>profile_all_requests: True</code> in the
135
55
<code>[profiling]</code> section of your launchpad-lazr.conf.</p>
136
56
<p>Profile was logged to <tal:block replace="dump_path" />.</p>
137
<p tal:condition="callgrind">You should be able to use this
138
simply by entering <code>kcachegrind <tal:block replace="callgrind_path"
139
/></code> in the console for a great visualization of the profile. The <a
57
<p>You should be able to use this simply by entering
58
<code>kcachegrind <tal:block replace="dump_path" /></code> in the
59
console for a great visualization of the profile. The <a
140
60
href="https://dev.launchpad.net/Debugging#Profiling%%20page%%20requests"
141
61
>dev wiki</a> may have more information on how to use this.</p>
142
<p tal:condition="pstats">You should be able to use this
143
simply by entering <code>python -m pstats <tal:block replace="pstats_path"
144
/></code> in the console to use the normal Python profile statistics
145
interface. Type "help" at the prompt, or see the <a
146
href="http://docs.python.org/library/profile.html#instant-user-s-manual"
147
>Python documentation</a>.</p>
150
<tal:block condition="not:sqltrace">
151
<p>Use <code>++profile++sqltrace</code> in your URL to see the SQL that
152
the page runs, along with start and stop times, the database used, and the
153
stacktrace for when each sql call is made.</p>
154
<p>If you only want SQL and not the tracebacks,
155
<code>++profile++sql</code> will give you what you want, or
156
<code>++profile++show</code> will include OOPS data at the end of the
157
profiling information.</p>
158
<p>If you want stacktraces only for certain SQL statements, you can do
159
that too. You can use <code>startswith</code>, <code>endswith</code>
160
or <code>includes</code> to specify parts of the SQL that you want to use
161
as triggers. Note that this is whitespace and case normalized, so you
162
just need to get the spelling right. Here are some examples.</p>
164
<dt><code>/++profile++sqltrace: includes Product.blueprints_usage/</code>
166
<dd>This will get a stacktrace for any SQL statement that has the
167
string "Product.blueprints_usage" in it.</dd>
168
<dt><code>/++profile++sqltrace:startswith SELECT
169
Distribution.answers_usage/</code> </dt>
170
<dd>This will get a stacktrace for any SQL statement that starts with the
171
string "SELECT Distribution.answers_usage" in it.</dd>
172
<dt><code>/++profile++sqltrace:endswith WHERE Project.id = 5 LIMIT
174
<dd>This will get a stacktrace for any SQL statement that ends with the
175
string given. Note that it does not end in a semicolon, and note that
176
parameters are filled in.</dd>
178
<p>You can also combine requests with the <code>|</code> mark (the
179
pipe). Here's an example:
180
<code>/++profile++sqltrace:startswith SELECT Distribution.answers_usage |
181
includes Product.blueprints_usage/</code>.</p>
183
<tal:block condition="sqltrace">
184
<p tal:condition="options/sql_traceback_all|nothing">You have requested
185
tracebacks for all SQL statements. You can filter these with conditions
186
like <code>startswith</code>, <code>endswith</code> or
187
<code>includes</code>. Here's a simple example:
188
<code>/++profile++sqltrace: includes Product.blueprints_usage/</code>.</p>
189
<p tal:condition="options/sql_traceback_none|nothing">You have requested no
190
tracebacks. Use <code>++profile++sqltrace</code> to get tracebacks.</p>
191
<tal:block condition="options/sql_traceback_conditions|nothing">
192
<p>You have requested tracebacks for statements that match only certain
195
condition="not:options/sql_traceback_conditions/included">
196
<p><strong> You had no valid conditions, so no tracebacks were
197
included.</strong> The available conditions are <code>startswith</code>,
198
<code>endswith</code> or <code>includes</code>. Here's a simple
200
<pre>++profile++sqltrace: includes Product.blueprints_usage/</pre>
203
<li tal:repeat="condition options/sql_traceback_conditions/included">
204
<em tal:content="condition/constraint">CONSTRAINT</em>
205
<span tal:replace="condition/value">VALUE</span>
208
<tal:block condition="options/sql_traceback_conditions/ignored">
209
<p><strong>Warning</strong>: these conditions were not understood, and
212
<li tal:repeat="condition options/sql_traceback_conditions/ignored">
213
<em tal:content="condition/constraint">CONSTRAINT</em>
214
<span tal:replace="condition/value">VALUE</span>
219
<h3>Top 10 SQL times</h3>
221
<li tal:repeat="info options/top_sql" tal:attributes="class info/cls">
222
<a tal:attributes="href string:#sqlstep-${info/ix}">Query number
223
<tal:block tal:content="info/ix"></tal:block></a> (<tal:block
224
replace="info/value"></tal:block> milliseconds)
227
<h3>Top 10 Python times</h3>
228
<p tal:condition="options/sql_traceback_all|nothing">Note that generating
229
stacktraces can add significantly to these numbers, and skew results. Use
230
<code>++profile++sql</code> for a more accurate view.</p>
231
<p tal:condition="options/sql_traceback_conditions|nothing">Note that
232
generating stacktraces can add significantly to these numbers, and
233
selectively choosing when to generate stacktraces will produce so much
234
skew as to potentially make these values meaningless. Use
235
<code>++profile++sql</code> for the most accurate view.</p>
237
<li tal:repeat="info options/top_python" tal:attributes="class info/cls">
238
<a tal:attributes="href string:#pythonstep-${info/ix}">Before query
239
number <tal:block tal:content="info/ix"></tal:block></a> (<tal:block
240
replace="info/value"></tal:block> milliseconds)
243
<tal:block condition="not: options/sql_traceback_none|nothing">
244
<h3>Repeated Python SQL Triggers</h3>
245
<p tal:condition="options/sql_traceback_conditions|nothing">These are
246
only calculated for the stacktraces that were collected.</p>
247
<p tal:condition="not: options/top_triggers">None.</p>
248
<div tal:condition="options/top_triggers">
249
<p>Typically, these show loops. The traceback may show extra
250
information, such as from page templates, that indicate the variable
251
within the loop. If you want to add more information to identify the
252
variables in the loop, in your Python add either an informational
253
string with the variable name <code>__traceback_info__</code>, or add
254
a <code>__traceback_supplement__</code> as used in
255
lp.services.stacktrace.</p>
256
<div tal:repeat="trigger options/top_triggers">
257
<div>File "<tal:block
258
replace="trigger/filename"></tal:block>", line <tal:block
259
replace="trigger/lineno"></tal:block></div>
260
<div class="querylinks"> <tal:block
261
replace="trigger/count"></tal:block> related queries (<a href="#"
262
class="expandall">expand all tracebacks</a>): <span tal:repeat="ix
263
trigger/indexes"> <a tal:attributes="href string:#sqlstep-${ix}"
264
tal:content="ix"></a> </span> </div>
268
<h3>SQL (<tal:block replace="options/sql_count"></tal:block> queries)</h3>
269
<p>Each sql line begins with the start time and the stop time, along with
270
the name of the database on which the query ran. Times are in
271
milliseconds since request start.</p>
272
<div tal:condition="not:options/sql_traceback_none|nothing"><a href="#"
273
id="show-all-tracebacks">Show all tracebacks</a> / <a href="#"
274
id="hide-all-tracebacks">Hide all tracebacks</a></div>
275
<div tal:repeat="step sqltrace_steps">
276
<div tal:condition="step/python_rank|nothing" tal:attributes="class
277
string: python_topten ${step/python_class}; id
278
string:pythonstep-${step/id}"><strong>Top ten (# <tal:block
279
replace="step/python_rank"></tal:block>):</strong> Python work took
280
<span tal:replace="step/python_time" /> milliseconds in-between SQL
282
<div tal:attributes="class string: sqlstep ${step/sql_class|nothing};
283
id string:sqlstep-${step/id};">
284
<div class="sqlinfo">
285
<div class="col1"><span><tal:block replace="step/id"></tal:block>.
286
<span class="sqlstats"><span
287
tal:replace="step/sql/start"></span> - <span
288
tal:replace="step/sql/stop"></span> @ <tal:block
289
replace="step/sql/name"></tal:block></span></span> <span
290
tal:condition="step/sql_rank|nothing"><strong>Top ten (# <tal:block
291
replace="step/sql_rank"></tal:block>):</strong> SQL took <span
292
tal:replace="step/sql_time" /> milliseconds</span></div> <a href="#"
293
class="clicktext" tal:condition="step/stack">Click to toggle Python
294
traceback.</a><span tal:condition="not:step/stack">--</span>
296
<div class="trace" tal:condition="step/stack"><div class="inner">
297
<div class="appstack" tal:define="stack step/app_stack">
298
<div tal:repeat="frame stack" metal:define-macro="draw-stack">
299
<div>File "<tal:block replace="frame/filename"></tal:block>",
300
line <tal:block replace="frame/lineno"></tal:block>, in
301
<tal:block replace="frame/name"></tal:block></div>
302
<div tal:condition="frame/line" tal:content="frame/line" class="line"></div>
303
<div tal:define="supp frame/supplement" tal:condition="supp" class="supplement">
304
<div tal:condition="supp/source_url" tal:content="supp/source_url"></div>
305
<div tal:define="line supp/line; column supp/column;"
306
tal:condition="python:line or column">
307
<tal:block condition="line">Line <span tal:replace="line"></span><tal:block condition="column">, </tal:block></tal:block>
308
<tal:block condition="column">Column <span tal:replace="column"></span></tal:block>
310
<div tal:condition="supp/expression">Expression: <code tal:content="supp/expression"></code></div>
311
<div tal:condition="supp/warnings">
312
<div tal:repeat="warning supp/warnings" class="tracebackwarning">Warning: <span tal:replace="supp/warnings"></span></div>
314
<pre tal:condition="supp/extra"
315
tal:content="supp/extra"></pre>
317
<pre tal:condition="frame/info" tal:content="frame/info" class="extrainfo"></pre>
320
<div class="dbstack" tal:define="stack step/db_stack">
321
<div metal:use-macro="template/macros/draw-stack"></div>
324
<pre tal:attributes="class string: sql ${step/sql_class|nothing}" tal:content="step/sql/statement"></pre>
328
63
<h2>Profile quick view</h2>
329
64
<tal:block condition="not:show">
330
<p>Use <code>++profile++show</code> in your URL in order to see immediate
331
profile results (or <code>++profile++callgrind&show</code> or
332
<code>++profile++pstats&show</code> to see both the log information and
333
immediate results).</p>
65
<p>Use <code>++profile++show</code> in your URL in order to see
66
immediate profile results (or <code>++profile++log,show</code> to
67
see both the log information and immediate results).</p>
335
69
<tal:block condition="show">
336
<p tal:condition="multiple_profiles">This request made <tal:block
337
replace="profile_count" /> profiles. The statistics below represent an
338
aggregate of them all.</p>
339
70
<h3>Top Inline Time</h3>
340
<pre tal:content="time" />
71
<pre tal:content="inlinetime" />
341
72
<h3>Top Total Time</h3>
342
<pre tal:content="cumulative" />
73
<pre tal:content="totaltime" />
343
74
<h3>Top Call Count</h3>
344
<pre tal:content="calls" />
75
<pre tal:content="callcount" />
345
76
<h2>Raw OOPS Information</h2>
346
77
<pre tal:content="oops" />
350
LPS.use('node', 'lp', 'transition', function (Y) {
81
LPS.use('node', 'lp', function (Y) {
351
82
Y.one('div#reveal_profiling').on('click', function (e) {
352
83
Y.one('div#profiling_info').setStyle('display', 'block');
355
85
Y.one('div#hide_profiling').on('click', function (e) {
356
86
Y.one('div#profiling_info').setStyle('display', 'none');
361
<script tal:condition="not:options/sql_traceback_none|nothing">
362
LPS.use('node', 'lp', 'transition', function (Y) {
363
function slideIn(target) {
366
duration: 0.75, // seconds
369
target.setStyle('display', 'none');
372
function slideOut(target) {
373
target.setStyles({display: 'block', height: '0px'});
374
var inner = target.one('.inner');
375
var height = parseInt(inner.getComputedStyle('height'));
378
duration: 0.75, // seconds
381
target.setStyle('height', 'auto');
384
// We use "all" on these two as a lazy way to handle the possibility
385
// that the link may not be there.
386
Y.all('#show-all-tracebacks').on('click', function (e) {
387
// For speed, just force them all open without animation.
388
Y.all('.trace').setStyles({display: 'block', height: 'auto'});
391
Y.all('#hide-all-tracebacks').on('click', function (e) {
392
// For speed, just force them all closed without animation.
393
Y.all('.trace').setStyle('display', 'none');
396
Y.all('.expandall').on('click', function (e) {
397
var links = e.currentTarget.ancestor('.querylinks').all('span a');
398
links.each(function (link) {
399
var href = link.get('href');
400
var identifier = href.slice(href.indexOf('#'));
401
var target = Y.one(identifier).one('.trace');
402
// target.setStyles({display: 'block', height: 'auto'});
403
if (target.getStyle('display') !== 'block') {
409
Y.on('load', function(e) {
410
// We hide the tracebacks with Javascript so that, if the Javascript
411
// does not load, we still can easily see the tracebacks.
412
Y.all('.trace').setStyle('display', 'none');
413
Y.all('.sqlinfo').on('click', function(e) {
414
var trace = e.currentTarget.ancestor('.sqlstep').one('.trace');
415
if (trace.getStyle('display') === 'block') {