~launchpad-pqm/launchpad/devel

« back to all changes in this revision

Viewing changes to lib/lp/services/profile/profile.pt

  • Committer: Graham Binns
  • Date: 2011-09-07 15:59:13 UTC
  • mto: This revision was merged to the branch mainline in revision 13914.
  • Revision ID: graham@canonical.com-20110907155913-p97tx2e34ysbcgp3
Added an XXX.

Show diffs side-by-side

added added

removed removed

Lines of Context:
 
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;}
 
25
</style>
1
26
<div class="profiling_info">
2
27
  <div class="hide_reveal_profiling" id="reveal_profiling">
3
 
  Click to REVEAL profiling information
 
28
  <a href="#">Click to REVEAL profiling information</a>
4
29
  </div>
5
30
</div>
6
31
<div class="profiling_info" id="profiling_info"
22
47
                 multiple_profiles options/multiple_profiles|nothing;
23
48
                 inline_ignored actions/inline_ignored|nothing;
24
49
                 inline actions/inline|nothing;
 
50
                 sqltrace actions/sql|nothing;
 
51
                 sqltrace_steps options/sqltrace|nothing;
25
52
                 ">
26
53
  <div class="hide_reveal_profiling" id="hide_profiling">
27
 
  Click to HIDE profiling information
 
54
  <a href="#">Click to HIDE profiling information</a>
28
55
  </div>
29
56
  <h1>Profiling Information</h1>
30
57
  <tal:block condition="help">
37
64
    get immediate profiling results in the browser, use
38
65
    <code>++profile++show</code>.</tal:block> <tal:block condition="not:
39
66
    always_log">In order to get profiling results, you need to ask for an HTML
40
 
    view (<code>++profile++show</code>), a KCacheGrind-friendly log on the
41
 
    filesystem (<code>++profile++callgrind</code>), or a PStats-friendly log
 
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
42
70
    (Python standard library) on the filesystem
43
 
    (<code>++profile++pstats</code>). You can also ask for local HTML
44
 
    profiling plus one of the two log files
45
 
    (<code>++profile++show,callgrind</code> or
46
 
    <code>++profile++show,pstats</code>).</tal:block></p>
 
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 &quot;SQL trace&quot; section below on how to do this.</p>
47
82
    <p>The "++profile++" path segment can usually go anywhere in the URL
48
83
    (e.g., <code>http://launchpad.dev/++profile++show</code> or
49
84
    <code>http://launchpad.dev/++profile++show/Firefox</code> or
90
125
    as in <code>++profile++pstats</code>.  Profiles are logged to <tal:block
91
126
    replace="dump_path" />.</p>
92
127
    <p> You can see both the log information and immediate results with
93
 
    <code>++profile++callgrind,show</code> or
94
 
    <code>++profile++pstats,show</code>.</p>
 
128
    <code>++profile++callgrind&show</code> or
 
129
    <code>++profile++pstats&show</code>.</p>
95
130
  </tal:block>
96
131
  <tal:block condition="log">
97
132
    <p tal:condition="always_log"><strong>You have configured every
111
146
    href="http://docs.python.org/library/profile.html#instant-user-s-manual"
112
147
    >Python documentation</a>.</p>
113
148
  </tal:block>
 
149
  <h2>SQL trace</h2>
 
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>
 
163
    <dl>
 
164
    <dt><code>/++profile++sqltrace: includes Product.blueprints_usage/</code>
 
165
    </dt>
 
166
    <dd>This will get a stacktrace for any SQL statement that has the
 
167
    string &quot;Product.blueprints_usage&quot; 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 &quot;SELECT Distribution.answers_usage&quot; in it.</dd>
 
172
    <dt><code>/++profile++sqltrace:endswith WHERE Project.id = 5 LIMIT
 
173
    1/</code> </dt>
 
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>
 
177
    </dl>
 
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>
 
182
  </tal:block>
 
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
 
193
      conditions.</p>
 
194
      <tal:block
 
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
 
199
      example.</p>
 
200
      <pre>++profile++sqltrace: includes Product.blueprints_usage/</pre>
 
201
      </tal:block>
 
202
      <ul>
 
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>
 
206
      </li>
 
207
      </ul>
 
208
      <tal:block condition="options/sql_traceback_conditions/ignored">
 
209
        <p><strong>Warning</strong>: these conditions were not understood, and
 
210
        so ignored.</p>
 
211
        <ul>
 
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>
 
215
        </li>
 
216
        </ul>
 
217
      </tal:block>
 
218
    </tal:block>
 
219
    <h3>Top 10 SQL times</h3>
 
220
    <ol>
 
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)
 
225
      </li>
 
226
    </ol>
 
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>
 
236
    <ol>
 
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)
 
241
      </li>
 
242
    </ol>
 
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 &quot;<tal:block
 
258
          replace="trigger/filename"></tal:block>&quot;, 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>
 
265
        </div>
 
266
      </div>
 
267
    </tal:block>
 
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
 
281
      calls.</div>
 
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>
 
295
        </div>
 
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 &quot;<tal:block replace="frame/filename"></tal:block>&quot;,
 
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>
 
309
                </div>
 
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>
 
313
                </div>
 
314
                <pre tal:condition="supp/extra"
 
315
                     tal:content="supp/extra"></pre>
 
316
              </div>
 
317
              <pre tal:condition="frame/info" tal:content="frame/info" class="extrainfo"></pre>
 
318
            </div>
 
319
          </div>
 
320
          <div class="dbstack" tal:define="stack step/db_stack">
 
321
            <div metal:use-macro="template/macros/draw-stack"></div>
 
322
          </div>
 
323
        </div></div>
 
324
        <pre  tal:attributes="class string: sql ${step/sql_class|nothing}" tal:content="step/sql/statement"></pre>
 
325
      </div>
 
326
    </div>
 
327
  </tal:block>
114
328
  <h2>Profile quick view</h2>
115
329
  <tal:block condition="not:show">
116
330
    <p>Use <code>++profile++show</code> in your URL in order to see immediate
117
 
    profile results (or <code>++profile++callgrind,show</code> or
118
 
    <code>++profile++pstats,show</code> to see both the log information and
 
331
    profile results (or <code>++profile++callgrind&show</code> or
 
332
    <code>++profile++pstats&show</code> to see both the log information and
119
333
    immediate results).</p>
120
334
  </tal:block>
121
335
  <tal:block condition="show">
133
347
  </tal:block>
134
348
</div>
135
349
<script>
136
 
LPS.use('node', 'lp', function (Y) {
 
350
LPS.use('node', 'lp', 'transition', function (Y) {
137
351
    Y.one('div#reveal_profiling').on('click', function (e) {
138
352
        Y.one('div#profiling_info').setStyle('display', 'block');
 
353
        e.preventDefault();
139
354
    });
140
355
    Y.one('div#hide_profiling').on('click', function (e) {
141
356
        Y.one('div#profiling_info').setStyle('display', 'none');
 
357
        e.preventDefault();
 
358
    });
 
359
});
 
360
</script>
 
361
<script tal:condition="not:options/sql_traceback_none|nothing">
 
362
LPS.use('node', 'lp', 'transition', function (Y) {
 
363
    function slideIn(target) {
 
364
        target.transition({
 
365
            easing: 'ease-in',
 
366
            duration: 0.75, // seconds
 
367
            height: '0px'
 
368
        }, function() {
 
369
            target.setStyle('display', 'none');
 
370
        });
 
371
    }
 
372
    function slideOut(target) {
 
373
        target.setStyles({display: 'block', height: '0px'});
 
374
        var inner = target.one('.inner');
 
375
        var height = parseInt(inner.getComputedStyle('height'));
 
376
        target.transition({
 
377
            easing: 'ease-out',
 
378
            duration: 0.75, // seconds
 
379
            height: height+'px'
 
380
        }, function() {
 
381
            target.setStyle('height', 'auto');
 
382
        });
 
383
    }
 
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'});
 
389
        e.preventDefault();
 
390
    });
 
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');
 
394
        e.preventDefault();
 
395
    });
 
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') {
 
404
                slideOut(target);
 
405
            }
 
406
        });
 
407
        e.preventDefault();
 
408
    });
 
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') {
 
416
                slideIn(trace);
 
417
            } else {
 
418
                slideOut(trace);
 
419
            }
 
420
            e.preventDefault();
 
421
        });
142
422
    });
143
423
});
144
424
</script>