Merge lp:~gary/launchpad/bug838878 into lp:launchpad

Proposed by Gary Poster
Status: Merged
Approved by: Gary Poster
Approved revision: no longer in the source branch.
Merged at revision: 13858
Proposed branch: lp:~gary/launchpad/bug838878
Merge into: lp:launchpad
Prerequisite: lp:~gary/launchpad/bug838869
Diff against target: 913 lines (+430/-117)
3 files modified
lib/lp/services/profile/profile.pt (+121/-36)
lib/lp/services/profile/profile.py (+153/-53)
lib/lp/services/profile/tests.py (+156/-28)
To merge this branch: bzr merge lp:~gary/launchpad/bug838878
Reviewer Review Type Date Requested Status
j.c.sackett (community) Approve
Review via email: mp+73702@code.launchpad.net

Commit message

[r=jcsackett][bug=838878] ++profile++ has a new conditional sqltrace feature and a new sql option.

Description of the change

This branch lets ++profile++ expose the new conditional sqltrace functionality enabled by changes in lp:~gary/launchpad/bug838869 .

This branch is just over the limit, for which I apologize.

The new features for ++profile++ are as follows:

 - ++profile++sqltrace adds a mini-language for specifying what SQL requests you want to trace. ++profile++sqltrace continues to get tracebacks for all SQL. "++profile++sqltrace:includes STRING" only gets tracebacks for SQL statements that include STRING (whitespace- and case-normalized). "++profile++sqltrace:startswith STRING" gets tracebacks for SQL statements that start with STRING. "++profile++sqltrace:endswith STRING" does the same if the SQL ends with STRING. They can be combined with a pipe, "|", meaning logical or. Therefore, "++profile++sqltrace:includes FOOBAR BAZ| includes shazam" will match SQL statements that include "FOOBAR BAZ" or "SHAZAM" (again, case- and whitespace- normalized).

 - ++profile++sql is now available, only giving SQL without any profiling or stacktrace information.

The changes for ++profile++ are as follows:

You combine requests in ++profile++ with "&" now, not ",", so "++profile++show,pstats" becomes "++profile++show&pstats". This is so that the strings used by the conditions described above can include commas, which SQL often does.

Lint is happy except for its usual confusion with the beginning of the template.

Trying this out on a dev machine should be as easy as going to https://launchpad.dev/++profile++ and messing around with some of the new options, like "https://launchpad.dev/++profile++sql" and "https://launchpad.dev/++profile++sqltrace:includes AccountPassword.id".

QA should be similar: https://qastaging.launchpad.net/++profile++ should still work, and https://qastaging.launchpad.net/++profile++show and https://qastaging.launchpad.net/++profile++sql and https://qastaging.launchpad.net/++profile++sqltrace and "https://qastaging.launchpad.net/++profile++sqltrace:includes AccountPassword.id".

To post a comment you must log in.
Revision history for this message
j.c.sackett (jcsackett) wrote :

Gary--

This looks good. I see one possible problem in the updated profile template, pointed out below.

> === modified file 'lib/lp/services/profile/profile.pt'
> --- lib/lp/services/profile/profile.pt 2011-08-22 17:08:02 +0000
> +++ lib/lp/services/profile/profile.pt 2011-09-01 17:17:32 +0000
> @@ -64,15 +64,21 @@
> get immediate profiling results in the browser, use
> <code>++profile++show</code>.</tal:block> <tal:block condition="not:
> always_log">In order to get profiling results, you need to ask for an HTML
> - view (<code>++profile++show</code>), a KCacheGrind-friendly log on the
> + view of the profile and OOPS data including SQL calls
> + (<code>++profile++show</code>), a KCacheGrind-friendly log on the
> filesystem (<code>++profile++callgrind</code>), a PStats-friendly log
> (Python standard library) on the filesystem
> - (<code>++profile++pstats</code>), or an HTML view of the SQL and the
> + (<code>++profile++pstats</code>), an HTML view of the SQL and the
> Python stacktrace when each SQL call was made
> - (<code>++profile++sqltrace</code>). You can also combine these
> - (<code>++profile++show,callgrind</code> or
> - <code>++profile++show,pstats</code> or others,
> - with each action separated with commas).</tal:block></p>
> + (<code>++profile++sqltrace</code>), or an HTML view of only the SQL
> + (<code>++profile++sql</code>). You can also combine these
> + (<code>++profile++show&callgrind</code> or
> + <code>++profile++show&pstats</code> or others, with each action separated
> + with commas).</tal:block></p>

I may be misunderstanding this, but shouldn't this be "separated with ambersands" as shown in the example?

> === modified file 'lib/lp/services/profile/profile.py'
> @@ -505,24 +521,108 @@
> # include traversal in the profile.
> actions, slash, tail = end.partition('/')
> result.update(
> - action for action in (
> - item.strip().lower() for item in actions.split(','))
> - if action)
> + (name.strip(), config.strip())
> + for name, partition, config in (
> + item.strip().lower().partition(':')
> + for item in actions.split('&'))
> + if name.strip())

There's no problem in the above bit, just thought that was one hell of a generator expression. :-P

review: Approve
Revision history for this message
Gary Poster (gary) wrote :

On Sep 1, 2011, at 3:45 PM, j.c.sackett wrote:

> Review: Approve
> Gary--
>
> This looks good. I see one possible problem in the updated profile template, pointed out below.

...

>
> I may be misunderstanding this, but shouldn't this be "separated with ambersands" as shown in the example?

Ah, yes, thanks, good catch!

...

> There's no problem in the above bit, just thought that was one hell of a generator expression. :-P

Yeah...not the prettiest thing in the world. Maybe I should have been more explicit/less concise...

Thanks again,

Gary

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
=== modified file 'lib/lp/services/profile/profile.pt'
--- lib/lp/services/profile/profile.pt 2011-08-22 17:08:02 +0000
+++ lib/lp/services/profile/profile.pt 2011-09-02 16:34:47 +0000
@@ -47,7 +47,7 @@
47 multiple_profiles options/multiple_profiles|nothing;47 multiple_profiles options/multiple_profiles|nothing;
48 inline_ignored actions/inline_ignored|nothing;48 inline_ignored actions/inline_ignored|nothing;
49 inline actions/inline|nothing;49 inline actions/inline|nothing;
50 sqltrace actions/sqltrace|nothing;50 sqltrace actions/sql|nothing;
51 sqltrace_steps options/sqltrace|nothing;51 sqltrace_steps options/sqltrace|nothing;
52 ">52 ">
53 <div class="hide_reveal_profiling" id="hide_profiling">53 <div class="hide_reveal_profiling" id="hide_profiling">
@@ -64,15 +64,21 @@
64 get immediate profiling results in the browser, use64 get immediate profiling results in the browser, use
65 <code>++profile++show</code>.</tal:block> <tal:block condition="not:65 <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 HTML66 always_log">In order to get profiling results, you need to ask for an HTML
67 view (<code>++profile++show</code>), a KCacheGrind-friendly log on the67 view of the profile and OOPS data including SQL calls
68 (<code>++profile++show</code>), a KCacheGrind-friendly log on the
68 filesystem (<code>++profile++callgrind</code>), a PStats-friendly log69 filesystem (<code>++profile++callgrind</code>), a PStats-friendly log
69 (Python standard library) on the filesystem70 (Python standard library) on the filesystem
70 (<code>++profile++pstats</code>), or an HTML view of the SQL and the71 (<code>++profile++pstats</code>), an HTML view of the SQL and the
71 Python stacktrace when each SQL call was made72 Python stacktrace when each SQL call was made
72 (<code>++profile++sqltrace</code>). You can also combine these73 (<code>++profile++sqltrace</code>), or an HTML view of only the SQL
73 (<code>++profile++show,callgrind</code> or74 (<code>++profile++sql</code>). You can also combine these
74 <code>++profile++show,pstats</code> or others,75 (<code>++profile++show&callgrind</code> or
75 with each action separated with commas).</tal:block></p>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>
76 <p>The "++profile++" path segment can usually go anywhere in the URL82 <p>The "++profile++" path segment can usually go anywhere in the URL
77 (e.g., <code>http://launchpad.dev/++profile++show</code> or83 (e.g., <code>http://launchpad.dev/++profile++show</code> or
78 <code>http://launchpad.dev/++profile++show/Firefox</code> or84 <code>http://launchpad.dev/++profile++show/Firefox</code> or
@@ -119,8 +125,8 @@
119 as in <code>++profile++pstats</code>. Profiles are logged to <tal:block125 as in <code>++profile++pstats</code>. Profiles are logged to <tal:block
120 replace="dump_path" />.</p>126 replace="dump_path" />.</p>
121 <p> You can see both the log information and immediate results with127 <p> You can see both the log information and immediate results with
122 <code>++profile++callgrind,show</code> or128 <code>++profile++callgrind&show</code> or
123 <code>++profile++pstats,show</code>.</p>129 <code>++profile++pstats&show</code>.</p>
124 </tal:block>130 </tal:block>
125 <tal:block condition="log">131 <tal:block condition="log">
126 <p tal:condition="always_log"><strong>You have configured every132 <p tal:condition="always_log"><strong>You have configured every
@@ -144,11 +150,72 @@
144 <tal:block condition="not:sqltrace">150 <tal:block condition="not:sqltrace">
145 <p>Use <code>++profile++sqltrace</code> in your URL to see the SQL that151 <p>Use <code>++profile++sqltrace</code> in your URL to see the SQL that
146 the page runs, along with start and stop times, the database used, and the152 the page runs, along with start and stop times, the database used, and the
147 stacktrace for when each sql call is made.</p> <p>Note that if you do not153 stacktrace for when each sql call is made.</p>
148 want the tracebacks, <code>++profile++show</code> will include OOPS data154 <p>If you only want SQL and not the tracebacks,
149 at the end of the profiling information, which has what what you want.</p>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>
150 </tal:block>182 </tal:block>
151 <tal:block condition="sqltrace">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>
152 <h3>Top 10 SQL times</h3>219 <h3>Top 10 SQL times</h3>
153 <ol>220 <ol>
154 <li tal:repeat="info options/top_sql" tal:attributes="class info/cls">221 <li tal:repeat="info options/top_sql" tal:attributes="class info/cls">
@@ -158,6 +225,14 @@
158 </li>225 </li>
159 </ol>226 </ol>
160 <h3>Top 10 Python times</h3>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>
161 <ol>236 <ol>
162 <li tal:repeat="info options/top_python" tal:attributes="class info/cls">237 <li tal:repeat="info options/top_python" tal:attributes="class info/cls">
163 <a tal:attributes="href string:#pythonstep-${info/ix}">Before query238 <a tal:attributes="href string:#pythonstep-${info/ix}">Before query
@@ -165,32 +240,37 @@
165 replace="info/value"></tal:block> milliseconds)240 replace="info/value"></tal:block> milliseconds)
166 </li>241 </li>
167 </ol>242 </ol>
168 <h3>Repeated Python SQL Triggers</h3>243 <tal:block condition="not: options/sql_traceback_none|nothing">
169 <p tal:condition="not: options/top_triggers">None.</p>244 <h3>Repeated Python SQL Triggers</h3>
170 <div tal:condition="options/top_triggers">245 <p tal:condition="options/sql_traceback_conditions|nothing">These are
171 <p>Typically, these show loops. The traceback may show extra246 only calculated for the stacktraces that were collected.</p>
172 information, such as from page templates, that indicate the variable247 <p tal:condition="not: options/top_triggers">None.</p>
173 within the loop. If you want to add more information to identify the248 <div tal:condition="options/top_triggers">
174 variables in the loop, in your Python add either an informational string249 <p>Typically, these show loops. The traceback may show extra
175 with the variable name <code>__traceback_info__</code>, or add a250 information, such as from page templates, that indicate the variable
176 <code>__traceback_supplement__</code> as used in251 within the loop. If you want to add more information to identify the
177 lp.services.stacktrace.</p>252 variables in the loop, in your Python add either an informational
178 <div tal:repeat="trigger options/top_triggers">253 string with the variable name <code>__traceback_info__</code>, or add
179 <div>File &quot;<tal:block replace="trigger/filename"></tal:block>&quot;,254 a <code>__traceback_supplement__</code> as used in
180 line <tal:block replace="trigger/lineno"></tal:block></div>255 lp.services.stacktrace.</p>
181 <div class="querylinks">256 <div tal:repeat="trigger options/top_triggers">
182 <tal:block replace="trigger/count"></tal:block> related queries (<a257 <div>File &quot;<tal:block
183 href="#" class="expandall">expand all tracebacks</a>): <span258 replace="trigger/filename"></tal:block>&quot;, line <tal:block
184 tal:repeat="ix trigger/indexes"> <a tal:attributes="href259 replace="trigger/lineno"></tal:block></div>
185 string:#sqlstep-${ix}" tal:content="ix"></a> </span>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>
186 </div>265 </div>
187 </div>266 </div>
188 </div>267 </tal:block>
189 <h3>SQL (<tal:block replace="options/sql_count"></tal:block> queries)</h3>268 <h3>SQL (<tal:block replace="options/sql_count"></tal:block> queries)</h3>
190 <p>Each sql line begins with the start time and the stop time, along with269 <p>Each sql line begins with the start time and the stop time, along with
191 the name of the database on which the query ran. Times are in270 the name of the database on which the query ran. Times are in
192 milliseconds since request start.</p>271 milliseconds since request start.</p>
193 <div><a href="#" id="show-all-tracebacks">Show all tracebacks</a> / <a href="#"272 <div tal:condition="not:options/sql_traceback_none|nothing"><a href="#"
273 id="show-all-tracebacks">Show all tracebacks</a> / <a href="#"
194 id="hide-all-tracebacks">Hide all tracebacks</a></div>274 id="hide-all-tracebacks">Hide all tracebacks</a></div>
195 <div tal:repeat="step sqltrace_steps">275 <div tal:repeat="step sqltrace_steps">
196 <div tal:condition="step/python_rank|nothing" tal:attributes="class276 <div tal:condition="step/python_rank|nothing" tal:attributes="class
@@ -210,9 +290,10 @@
210 tal:condition="step/sql_rank|nothing"><strong>Top ten (# <tal:block290 tal:condition="step/sql_rank|nothing"><strong>Top ten (# <tal:block
211 replace="step/sql_rank"></tal:block>):</strong> SQL took <span291 replace="step/sql_rank"></tal:block>):</strong> SQL took <span
212 tal:replace="step/sql_time" /> milliseconds</span></div> <a href="#"292 tal:replace="step/sql_time" /> milliseconds</span></div> <a href="#"
213 class="clicktext">Click to toggle Python traceback.</a>293 class="clicktext" tal:condition="step/stack">Click to toggle Python
294 traceback.</a><span tal:condition="not:step/stack">--</span>
214 </div>295 </div>
215 <div class="trace"><div class="inner">296 <div class="trace" tal:condition="step/stack"><div class="inner">
216 <div class="appstack" tal:define="stack step/app_stack">297 <div class="appstack" tal:define="stack step/app_stack">
217 <div tal:repeat="frame stack" metal:define-macro="draw-stack">298 <div tal:repeat="frame stack" metal:define-macro="draw-stack">
218 <div>File &quot;<tal:block replace="frame/filename"></tal:block>&quot;,299 <div>File &quot;<tal:block replace="frame/filename"></tal:block>&quot;,
@@ -247,8 +328,8 @@
247 <h2>Profile quick view</h2>328 <h2>Profile quick view</h2>
248 <tal:block condition="not:show">329 <tal:block condition="not:show">
249 <p>Use <code>++profile++show</code> in your URL in order to see immediate330 <p>Use <code>++profile++show</code> in your URL in order to see immediate
250 profile results (or <code>++profile++callgrind,show</code> or331 profile results (or <code>++profile++callgrind&show</code> or
251 <code>++profile++pstats,show</code> to see both the log information and332 <code>++profile++pstats&show</code> to see both the log information and
252 immediate results).</p>333 immediate results).</p>
253 </tal:block>334 </tal:block>
254 <tal:block condition="show">335 <tal:block condition="show">
@@ -275,6 +356,10 @@
275 Y.one('div#profiling_info').setStyle('display', 'none');356 Y.one('div#profiling_info').setStyle('display', 'none');
276 e.preventDefault();357 e.preventDefault();
277 });358 });
359});
360</script>
361<script tal:condition="not:options/sql_traceback_none|nothing">
362LPS.use('node', 'lp', 'transition', function (Y) {
278 function slideIn(target) {363 function slideIn(target) {
279 target.transition({364 target.transition({
280 easing: 'ease-in',365 easing: 'ease-in',
281366
=== modified file 'lib/lp/services/profile/profile.py'
--- lib/lp/services/profile/profile.py 2011-09-01 14:55:10 +0000
+++ lib/lp/services/profile/profile.py 2011-09-02 16:34:47 +0000
@@ -13,9 +13,11 @@
13import contextlib13import contextlib
14from cProfile import Profile14from cProfile import Profile
15from datetime import datetime15from datetime import datetime
16from functools import partial
16import heapq17import heapq
17import os18import os
18import pstats19import pstats
20import re
19import StringIO21import StringIO
20import sys22import sys
21import threading23import threading
@@ -210,11 +212,14 @@
210 _profilers.actions = actions212 _profilers.actions = actions
211 _profilers.profiling = True213 _profilers.profiling = True
212 if config.profiling.profile_all_requests:214 if config.profiling.profile_all_requests:
213 actions.add('callgrind')215 actions['callgrind'] = ''
214 if actions:216 if actions:
215 if 'sqltrace' in actions:217 if 'sql' in actions:
216 da.start_sql_logging(tracebacks_if=True)218 condition = actions['sql']
217 if 'show' in actions or actions.intersection(available_profilers):219 if condition not in (True, False):
220 condition = condition['condition']
221 da.start_sql_logging(condition)
222 if 'show' in actions or available_profilers.intersection(actions):
218 _profilers.profiler = Profiler()223 _profilers.profiler = Profiler()
219 _profilers.profiler.start()224 _profilers.profiler.start()
220 if config.profiling.memory_profile_log:225 if config.profiling.memory_profile_log:
@@ -233,12 +238,14 @@
233 actions = _profilers.actions238 actions = _profilers.actions
234 profiler = _profilers.profiler239 profiler = _profilers.profiler
235 if actions is None:240 if actions is None:
236 actions = _profilers.actions = set()241 actions = _profilers.actions = {}
237 _profilers.profiling = True242 _profilers.profiling = True
238 elif actions.difference(('help',)) and 'inline' not in actions:243 elif 'inline' not in actions and (
239 actions.add('inline_ignored')244 'show' in actions or available_profilers.intersection(actions)):
245 # We have a request-based profile in progress. That wins.
246 actions['inline_ignored'] = ''
240 return247 return
241 actions.update(('pstats', 'show', 'inline'))248 actions.update((k, '') for k in ('pstats', 'show', 'inline'))
242 if profiler is None:249 if profiler is None:
243 profiler = _profilers.profiler = Profiler()250 profiler = _profilers.profiler = Profiler()
244 profiler.start()251 profiler.start()
@@ -261,8 +268,10 @@
261@contextlib.contextmanager268@contextlib.contextmanager
262def profiling():269def profiling():
263 start()270 start()
264 yield271 try:
265 stop()272 yield
273 finally:
274 stop()
266275
267276
268@adapter(IEndRequestEvent)277@adapter(IEndRequestEvent)
@@ -293,8 +302,7 @@
293 _major, _minor, content_type_params = parse(content_type)302 _major, _minor, content_type_params = parse(content_type)
294 is_html = _major == 'text' and _minor == 'html'303 is_html = _major == 'text' and _minor == 'html'
295 template_context = {304 template_context = {
296 # Dicts are easier for tal expressions.305 'actions': dict((key, True) for key in actions),
297 'actions': dict((action, True) for action in actions),
298 'always_log': config.profiling.profile_all_requests}306 'always_log': config.profiling.profile_all_requests}
299 dump_path = config.profiling.profile_dir307 dump_path = config.profiling.profile_dir
300 if _profilers.profiler is not None:308 if _profilers.profiler is not None:
@@ -345,16 +353,15 @@
345 # Try to free some more memory.353 # Try to free some more memory.
346 del prof_stats354 del prof_stats
347 trace = None355 trace = None
348 if 'sqltrace' in actions:356 if 'sql' in actions:
349 trace = da.stop_sql_logging() or ()357 trace = da.stop_sql_logging() or ()
350 # The trace is a list of dicts, each with the keys "sql" and358 # The trace is a list of dicts, each with the keys "sql" and "stack".
351 # "stack". "sql" is a tuple of start time, stop time, database359 # "sql" is a tuple of start time, stop time, database name (with a
352 # name (with a "SQL-" prefix), and sql statement. "stack" is a360 # "SQL-" prefix), and sql statement. "stack" is None or a tuple of
353 # tuple of filename, line number, function name, text, module361 # filename, line number, function name, text, module name, optional
354 # name, optional supplement dict, and optional info string. The362 # supplement dict, and optional info string. The supplement dict has
355 # supplement dict has keys 'source_url', 'line', 'column',363 # keys 'source_url', 'line', 'column', 'expression', 'warnings' (an
356 # 'expression', 'warnings' (an iterable), and 'extra', any of364 # iterable), and 'extra', any of which may be None.
357 # which may be None.
358 top_sql = []365 top_sql = []
359 top_python = []366 top_python = []
360 triggers = {}367 triggers = {}
@@ -366,29 +373,30 @@
366 step['id'] = ix373 step['id'] = ix
367 step['sql'] = dict(zip(374 step['sql'] = dict(zip(
368 ('start', 'stop', 'name', 'statement'), step['sql']))375 ('start', 'stop', 'name', 'statement'), step['sql']))
369 # Divide up the stack into the more unique (app) and less376 if step['stack'] is not None:
370 # unique (db) bits.377 # Divide up the stack into the more unique (app) and less
371 app_stack = step['app_stack'] = []378 # unique (db) bits.
372 db_stack = step['db_stack'] = []379 app_stack = step['app_stack'] = []
373 storm_found = False380 db_stack = step['db_stack'] = []
374 for f in step['stack']:381 storm_found = False
375 f_data = dict(zip(382 for f in step['stack']:
376 ('filename', 'lineno', 'name', 'line', 'module',383 f_data = dict(zip(
377 'supplement', 'info'), f))384 ('filename', 'lineno', 'name', 'line', 'module',
378 storm_found = storm_found or (385 'supplement', 'info'), f))
379 f_data['module'] and386 storm_found = storm_found or (
380 f_data['module'].startswith('storm.'))387 f_data['module'] and
381 if storm_found:388 f_data['module'].startswith('storm.'))
382 db_stack.append(f_data)389 if storm_found:
383 else:390 db_stack.append(f_data)
384 app_stack.append(f_data)391 else:
385 # Begin to gather what app code is triggering the most SQL392 app_stack.append(f_data)
386 # calls.393 # Begin to gather what app code is triggering the most SQL
387 trigger_key = tuple(394 # calls.
388 (f['filename'], f['lineno']) for f in app_stack)395 trigger_key = tuple(
389 if trigger_key not in triggers:396 (f['filename'], f['lineno']) for f in app_stack)
390 triggers[trigger_key] = []397 if trigger_key not in triggers:
391 triggers[trigger_key].append(ix)398 triggers[trigger_key] = []
399 triggers[trigger_key].append(ix)
392 # Get the nbest (n=10) sql and python times400 # Get the nbest (n=10) sql and python times
393 step['python_time'] = step['sql']['start'] - last_stop_time401 step['python_time'] = step['sql']['start'] - last_stop_time
394 step['sql_time'] = step['sql']['stop'] - step['sql']['start']402 step['sql_time'] = step['sql']['stop'] - step['sql']['start']
@@ -449,6 +457,14 @@
449 top_python=top_python_ids,457 top_python=top_python_ids,
450 top_triggers=top_triggers,458 top_triggers=top_triggers,
451 sql_count=len(trace)))459 sql_count=len(trace)))
460 if actions['sql'] is True:
461 template_context['sql_traceback_all'] = True
462 elif actions['sql'] is False:
463 template_context['sql_traceback_none'] = True
464 else:
465 conditions = actions['sql'].copy()
466 del conditions['condition']
467 template_context['sql_traceback_conditions'] = conditions
452 template_context['dump_path'] = os.path.abspath(dump_path)468 template_context['dump_path'] = os.path.abspath(dump_path)
453 if actions and is_html:469 if actions and is_html:
454 # Hack the new HTML in at the end of the page.470 # Hack the new HTML in at the end of the page.
@@ -488,7 +504,7 @@
488 URL. Note that ++profile++ alone without actions is interpreted as504 URL. Note that ++profile++ alone without actions is interpreted as
489 the "help" action.505 the "help" action.
490 """506 """
491 result = set()507 result = dict()
492 path_info = request.get('PATH_INFO')508 path_info = request.get('PATH_INFO')
493 if path_info:509 if path_info:
494 # if not, this is almost certainly a test not bothering to set up510 # if not, this is almost certainly a test not bothering to set up
@@ -505,24 +521,108 @@
505 # include traversal in the profile.521 # include traversal in the profile.
506 actions, slash, tail = end.partition('/')522 actions, slash, tail = end.partition('/')
507 result.update(523 result.update(
508 action for action in (524 (name.strip(), config.strip())
509 item.strip().lower() for item in actions.split(','))525 for name, partition, config in (
510 if action)526 item.strip().lower().partition(':')
527 for item in actions.split('&'))
528 if name.strip())
511 # 'log' is backwards compatible for 'callgrind'.529 # 'log' is backwards compatible for 'callgrind'.
512 if 'log' in result:530 if 'log' in result:
513 result.remove('log')531 result['callgrind'] = result.pop('log')
514 result.add('callgrind')532 if 'sqltrace' in result:
533 condition = result['sqltrace']
534 if condition:
535 condition = _make_condition_function(condition)
536 else:
537 condition = True
538 del result['sqltrace']
539 result['sql'] = condition
540 elif 'sql' in result:
541 result['sql'] = False
515 # Only honor the available options.542 # Only honor the available options.
516 available_options = set(('show', 'sqltrace', 'help'))543 available_options = set(('show', 'sql', 'help'))
517 available_options.update(available_profilers)544 available_options.update(available_profilers)
518 result.intersection_update(available_options)545 # .keys() gives a list, not mutated during iteration.
546 for key in result.keys():
547 if key not in available_options:
548 del result[key]
519 # If we didn't end up with any known actions, we need to help the549 # If we didn't end up with any known actions, we need to help the
520 # user.550 # user.
521 if not result:551 if not result:
522 result.add('help')552 result['help'] = ''
523 return result553 return result
524554
525555
556def _make_startswith(value):
557 """Return a function that returns true if its argument startswith value"""
558 def startswith(sql):
559 return sql.startswith(value)
560 return startswith
561
562
563def _make_endswith(value):
564 """Return a function that returns true if its argument endswith value"""
565 def endswith(sql):
566 return sql.endswith(value)
567 return endswith
568
569
570def _make_includes(value):
571 """Return a function that returns true if its argument includes value"""
572 def includes(sql):
573 return value in sql
574 return includes
575
576_condition_functions = {
577 'STARTSWITH': _make_startswith,
578 'ENDSWITH': _make_endswith,
579 'INCLUDES': _make_includes
580 }
581
582_normalize_whitespace = partial(re.compile('\s+').sub, ' ')
583
584
585def _make_condition_function(condition_string):
586 """Given DSL string, return dict including function implementing string.
587
588 DSL is very simple. Conditions are separated by semicolons, which
589 represent logical or. Each condition should begin with (case insensitive)
590 "startswith ", "endswith ", or "includes ". The part of the condition
591 after this word and before the next semicolon or end-of-string is the
592 match string, which is case-insensitive and whitespace-normalized.
593
594 Returned dict has three elements: the function that implements the DSL,
595 the list of conditions that were included, and the list of conditions
596 that were excluded (because they were not understood).
597 """
598 conditions = []
599 included = []
600 ignored = []
601 for constraint, partition, value in (
602 c.strip().partition(' ') for c
603 in condition_string.upper().split('|')):
604 # Process each condition.
605 constraint = constraint.strip()
606 if not constraint:
607 # This was something ignorable, like a trailing | or something.
608 continue
609 value = _normalize_whitespace(value.strip())
610 description = dict(constraint=constraint, value=value)
611 if constraint in _condition_functions:
612 conditions.append(_condition_functions[constraint](value))
613 included.append(description)
614 else:
615 ignored.append(description)
616
617 def condition_aggregate(sql):
618 for condition in conditions:
619 if condition(sql):
620 return True
621 return False
622 return dict(
623 condition=condition_aggregate, included=included, ignored=ignored)
624
625
526class ProfileNamespace(view):626class ProfileNamespace(view):
527 """A see-through namespace that handles traversals with ++profile++."""627 """A see-through namespace that handles traversals with ++profile++."""
528628
529629
=== modified file 'lib/lp/services/profile/tests.py'
--- lib/lp/services/profile/tests.py 2011-09-01 14:55:10 +0000
+++ lib/lp/services/profile/tests.py 2011-09-02 16:34:47 +0000
@@ -43,6 +43,85 @@
43EXAMPLE_HTML = EXAMPLE_HTML_START + EXAMPLE_HTML_END43EXAMPLE_HTML = EXAMPLE_HTML_START + EXAMPLE_HTML_END
4444
4545
46class SQLDSLTest(TestCase):
47
48 def assertCondition(self,
49 condition_string, succeeds, fails, included, ignored):
50 results = profile._make_condition_function(condition_string)
51 self.assertEqual(included, results['included'])
52 self.assertEqual(ignored, results['ignored'])
53 for example in succeeds:
54 self.assertTrue(results['condition'](example))
55 for example in fails:
56 self.assertFalse(results['condition'](example))
57
58 def test_startswith(self):
59 self.assertCondition(
60 'startswith foo bar',
61 succeeds=['FOO BARBAZ'],
62 fails=['BARBAZ FOO'],
63 included=[dict(constraint='STARTSWITH', value='FOO BAR')],
64 ignored=[])
65
66 def test_endswith(self):
67 self.assertCondition(
68 'endswith foo bar',
69 succeeds=['BAZ FOO BAR'],
70 fails=['BARBAZ FOO'],
71 included=[dict(constraint='ENDSWITH', value='FOO BAR')],
72 ignored=[])
73
74 def test_includes(self):
75 self.assertCondition(
76 'includes foo bar',
77 succeeds=['BAZ FOO BAR BING'],
78 fails=['BARBAZ FOO'],
79 included=[dict(constraint='INCLUDES', value='FOO BAR')],
80 ignored=[])
81
82 def test_whitespace_normalized(self):
83 self.assertCondition(
84 ' startswith foo bar ',
85 succeeds=['FOO BARBAZ'],
86 fails=['BARBAZ FOO'],
87 included=[dict(constraint='STARTSWITH', value='FOO BAR')],
88 ignored=[])
89
90 def test_many_conditions(self):
91 self.assertCondition(
92 'startswith foo bar | endswith shazam|includes balooba',
93 succeeds=['FOO BARBAZ', 'SALAMI SHAZAM', 'FORTUNA BALOOBA CAT'],
94 fails=['BARBAZ FOO'],
95 included=[dict(constraint='STARTSWITH', value='FOO BAR'),
96 dict(constraint='ENDSWITH', value='SHAZAM'),
97 dict(constraint='INCLUDES', value='BALOOBA')],
98 ignored=[])
99
100 def test_trailing_or(self):
101 self.assertCondition(
102 'startswith foo bar|',
103 succeeds=['FOO BARBAZ'],
104 fails=['BARBAZ FOO'],
105 included=[dict(constraint='STARTSWITH', value='FOO BAR')],
106 ignored=[])
107
108 def test_one_ignored(self):
109 self.assertCondition(
110 'matches foo bar',
111 succeeds=[],
112 fails=['BARBAZ FOO'],
113 included=[],
114 ignored=[dict(constraint='MATCHES', value='FOO BAR')])
115
116 def test_one_included_one_ignored(self):
117 self.assertCondition(
118 'matches kumquat | startswith foo bar',
119 succeeds=['FOO BAR HAMSTER'],
120 fails=['BARBAZ FOO'],
121 included=[dict(constraint='STARTSWITH', value='FOO BAR')],
122 ignored=[dict(constraint='MATCHES', value='KUMQUAT')])
123
124
46class BaseTest(TestCase):125class BaseTest(TestCase):
47126
48 def _get_request(self, path='/'):127 def _get_request(self, path='/'):
@@ -99,7 +178,7 @@
99 profiling_allowed='False', profile_all_requests='True',178 profiling_allowed='False', profile_all_requests='True',
100 memory_profile_log='.')179 memory_profile_log='.')
101 profile.start_request(self._get_start_event(180 profile.start_request(self._get_start_event(
102 '/++profile++show,callgrind'))181 '/++profile++show&callgrind'))
103 self.assertCleanProfilerState('config was ignored')182 self.assertCleanProfilerState('config was ignored')
104183
105 def test_optional_profiling_without_marked_request_has_no_profile(self):184 def test_optional_profiling_without_marked_request_has_no_profile(self):
@@ -107,7 +186,7 @@
107 # request.186 # request.
108 self.pushProfilingConfig(profiling_allowed='True')187 self.pushProfilingConfig(profiling_allowed='True')
109 profile.start_request(self._get_start_event('/'))188 profile.start_request(self._get_start_event('/'))
110 self.assertEqual(profile._profilers.actions, set())189 self.assertEqual(profile._profilers.actions, {})
111 self.assertIs(getattr(profile._profilers, 'profiler', None), None)190 self.assertIs(getattr(profile._profilers, 'profiler', None), None)
112 self.assertIs(191 self.assertIs(
113 getattr(profile._profilers, 'memory_profile_start', None), None)192 getattr(profile._profilers, 'memory_profile_start', None), None)
@@ -121,7 +200,7 @@
121 self.assertIs(200 self.assertIs(
122 getattr(profile._profilers, 'memory_profile_start', None),201 getattr(profile._profilers, 'memory_profile_start', None),
123 None)202 None)
124 self.assertEquals(profile._profilers.actions, set(('show', )))203 self.assertEquals(set(profile._profilers.actions), set(('show', )))
125204
126 def test_optional_profiling_with_callgrind_request_starts_profiling(self):205 def test_optional_profiling_with_callgrind_request_starts_profiling(self):
127 # If profiling is allowed and a request with the "callgrind" marker206 # If profiling is allowed and a request with the "callgrind" marker
@@ -132,7 +211,8 @@
132 self.assertIs(211 self.assertIs(
133 getattr(profile._profilers, 'memory_profile_start', None),212 getattr(profile._profilers, 'memory_profile_start', None),
134 None)213 None)
135 self.assertEquals(profile._profilers.actions, set(('callgrind', )))214 self.assertEquals(
215 set(profile._profilers.actions), set(('callgrind', )))
136216
137 def test_optional_profiling_with_log_request_starts_profiling(self):217 def test_optional_profiling_with_log_request_starts_profiling(self):
138 # If profiling is allowed and a request with the "log" marker URL218 # If profiling is allowed and a request with the "log" marker URL
@@ -143,20 +223,21 @@
143 self.assertIs(223 self.assertIs(
144 getattr(profile._profilers, 'memory_profile_start', None),224 getattr(profile._profilers, 'memory_profile_start', None),
145 None)225 None)
146 self.assertEquals(profile._profilers.actions, set(('callgrind', )))226 self.assertEquals(
227 set(profile._profilers.actions), set(('callgrind', )))
147228
148 def test_optional_profiling_with_combined_request_starts_profiling(self):229 def test_optional_profiling_with_combined_request_starts_profiling(self):
149 # If profiling is allowed and a request with the "callgrind" and230 # If profiling is allowed and a request with the "callgrind" and
150 # "show" marker URL segment is made, profiling starts.231 # "show" marker URL segment is made, profiling starts.
151 self.pushProfilingConfig(profiling_allowed='True')232 self.pushProfilingConfig(profiling_allowed='True')
152 profile.start_request(233 profile.start_request(
153 self._get_start_event('/++profile++callgrind,show/'))234 self._get_start_event('/++profile++callgrind&show/'))
154 self.assertIsInstance(profile._profilers.profiler, profile.Profiler)235 self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
155 self.assertIs(236 self.assertIs(
156 getattr(profile._profilers, 'memory_profile_start', None),237 getattr(profile._profilers, 'memory_profile_start', None),
157 None)238 None)
158 self.assertEquals(239 self.assertEquals(
159 profile._profilers.actions, set(('callgrind', 'show')))240 set(profile._profilers.actions), set(('callgrind', 'show')))
160241
161 def test_optional_profiling_with_reversed_request_starts_profiling(self):242 def test_optional_profiling_with_reversed_request_starts_profiling(self):
162 # If profiling is allowed and a request with the "show" and the243 # If profiling is allowed and a request with the "show" and the
@@ -166,13 +247,13 @@
166 # difference from the previous test. Also, it doesn't have a247 # difference from the previous test. Also, it doesn't have a
167 # trailing slash. :-P248 # trailing slash. :-P
168 profile.start_request(249 profile.start_request(
169 self._get_start_event('/++profile++show,callgrind'))250 self._get_start_event('/++profile++show&callgrind'))
170 self.assertIsInstance(profile._profilers.profiler, profile.Profiler)251 self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
171 self.assertIs(252 self.assertIs(
172 getattr(profile._profilers, 'memory_profile_start', None),253 getattr(profile._profilers, 'memory_profile_start', None),
173 None)254 None)
174 self.assertEquals(255 self.assertEquals(
175 profile._profilers.actions, set(('callgrind', 'show')))256 set(profile._profilers.actions), set(('callgrind', 'show')))
176257
177 def test_optional_profiling_with_pstats_request_starts_profiling(self):258 def test_optional_profiling_with_pstats_request_starts_profiling(self):
178 # If profiling is allowed and a request with the "pstats" marker,259 # If profiling is allowed and a request with the "pstats" marker,
@@ -185,7 +266,7 @@
185 self.assertIs(266 self.assertIs(
186 getattr(profile._profilers, 'memory_profile_start', None),267 getattr(profile._profilers, 'memory_profile_start', None),
187 None)268 None)
188 self.assertEquals(profile._profilers.actions, set(('pstats',)))269 self.assertEquals(set(profile._profilers.actions), set(('pstats',)))
189270
190 def test_optional_profiling_with_log_pstats(self):271 def test_optional_profiling_with_log_pstats(self):
191 # If profiling is allowed and a request with the "log" and "pstats"272 # If profiling is allowed and a request with the "log" and "pstats"
@@ -193,13 +274,13 @@
193 # and pstats request.274 # and pstats request.
194 self.pushProfilingConfig(profiling_allowed='True')275 self.pushProfilingConfig(profiling_allowed='True')
195 profile.start_request(276 profile.start_request(
196 self._get_start_event('/++profile++log,pstats/'))277 self._get_start_event('/++profile++log&pstats/'))
197 self.assertIsInstance(profile._profilers.profiler, profile.Profiler)278 self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
198 self.assertIs(279 self.assertIs(
199 getattr(profile._profilers, 'memory_profile_start', None),280 getattr(profile._profilers, 'memory_profile_start', None),
200 None)281 None)
201 self.assertEquals(282 self.assertEquals(
202 profile._profilers.actions, set(('callgrind', 'pstats',)))283 set(profile._profilers.actions), set(('callgrind', 'pstats',)))
203284
204 def test_optional_profiling_with_callgrind_pstats(self):285 def test_optional_profiling_with_callgrind_pstats(self):
205 # If profiling is allowed and a request with both the "pstats" and286 # If profiling is allowed and a request with both the "pstats" and
@@ -207,14 +288,14 @@
207 # profiler.288 # profiler.
208 self.pushProfilingConfig(profiling_allowed='True')289 self.pushProfilingConfig(profiling_allowed='True')
209 profile.start_request(290 profile.start_request(
210 self._get_start_event('/++profile++pstats,callgrind/'))291 self._get_start_event('/++profile++pstats&callgrind/'))
211 self.assertIsInstance(profile._profilers.profiler,292 self.assertIsInstance(profile._profilers.profiler,
212 profile.Profiler)293 profile.Profiler)
213 self.assertIs(294 self.assertIs(
214 getattr(profile._profilers, 'memory_profile_start', None),295 getattr(profile._profilers, 'memory_profile_start', None),
215 None)296 None)
216 self.assertEquals(297 self.assertEquals(
217 profile._profilers.actions, set(('pstats', 'callgrind')))298 set(profile._profilers.actions), set(('pstats', 'callgrind')))
218299
219 def test_forced_profiling_registers_action(self):300 def test_forced_profiling_registers_action(self):
220 # profile_all_requests should register as a callgrind action.301 # profile_all_requests should register as a callgrind action.
@@ -225,7 +306,8 @@
225 self.assertIs(306 self.assertIs(
226 getattr(profile._profilers, 'memory_profile_start', None),307 getattr(profile._profilers, 'memory_profile_start', None),
227 None)308 None)
228 self.assertEquals(profile._profilers.actions, set(('callgrind', )))309 self.assertEquals(
310 set(profile._profilers.actions), set(('callgrind', )))
229311
230 def test_optional_profiling_with_wrong_request_helps(self):312 def test_optional_profiling_with_wrong_request_helps(self):
231 # If profiling is allowed and a request with the marker URL segment313 # If profiling is allowed and a request with the marker URL segment
@@ -236,7 +318,7 @@
236 self.assertIs(318 self.assertIs(
237 getattr(profile._profilers, 'memory_profile_start', None),319 getattr(profile._profilers, 'memory_profile_start', None),
238 None)320 None)
239 self.assertEquals(profile._profilers.actions, set(('help', )))321 self.assertEquals(set(profile._profilers.actions), set(('help', )))
240322
241 def test_forced_profiling_with_wrong_request_helps(self):323 def test_forced_profiling_with_wrong_request_helps(self):
242 # If profiling is forced and a request with the marker URL segment324 # If profiling is forced and a request with the marker URL segment
@@ -249,7 +331,7 @@
249 getattr(profile._profilers, 'memory_profile_start', None),331 getattr(profile._profilers, 'memory_profile_start', None),
250 None)332 None)
251 self.assertEquals(333 self.assertEquals(
252 profile._profilers.actions, set(('help', 'callgrind')))334 set(profile._profilers.actions), set(('help', 'callgrind')))
253335
254 def test_memory_profile_start(self):336 def test_memory_profile_start(self):
255 self.pushProfilingConfig(337 self.pushProfilingConfig(
@@ -258,7 +340,7 @@
258 self.assertIs(getattr(profile._profilers, 'profiler', None), None)340 self.assertIs(getattr(profile._profilers, 'profiler', None), None)
259 self.assertIsInstance(profile._profilers.memory_profile_start, tuple)341 self.assertIsInstance(profile._profilers.memory_profile_start, tuple)
260 self.assertEqual(len(profile._profilers.memory_profile_start), 2)342 self.assertEqual(len(profile._profilers.memory_profile_start), 2)
261 self.assertEqual(profile._profilers.actions, set())343 self.assertEqual(profile._profilers.actions, {})
262344
263 def test_combo_memory_and_profile_start(self):345 def test_combo_memory_and_profile_start(self):
264 self.pushProfilingConfig(346 self.pushProfilingConfig(
@@ -267,13 +349,30 @@
267 self.assertIsInstance(profile._profilers.profiler, profile.Profiler)349 self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
268 self.assertIsInstance(profile._profilers.memory_profile_start, tuple)350 self.assertIsInstance(profile._profilers.memory_profile_start, tuple)
269 self.assertEqual(len(profile._profilers.memory_profile_start), 2)351 self.assertEqual(len(profile._profilers.memory_profile_start), 2)
270 self.assertEquals(profile._profilers.actions, set(('show', )))352 self.assertEquals(set(profile._profilers.actions), set(('show', )))
271353
272 def test_sqltrace_start(self):354 def test_sqltrace_start(self):
273 self.pushProfilingConfig(profiling_allowed='True')355 self.pushProfilingConfig(profiling_allowed='True')
274 profile.start_request(self._get_start_event('/++profile++sqltrace/'))356 profile.start_request(self._get_start_event('/++profile++sqltrace/'))
275 self.assertIs(getattr(profile._profilers, 'profiler', None), None)357 self.assertIs(getattr(profile._profilers, 'profiler', None), None)
276 self.assertEquals(profile._profilers.actions, set(('sqltrace', )))358 self.assertEquals(profile._profilers.actions, dict(sql=True))
359 self.assertEqual([], da.stop_sql_logging())
360
361 def test_sql_start(self):
362 self.pushProfilingConfig(profiling_allowed='True')
363 profile.start_request(self._get_start_event('/++profile++sql/'))
364 self.assertIs(getattr(profile._profilers, 'profiler', None), None)
365 self.assertEquals(profile._profilers.actions, dict(sql=False))
366 self.assertEqual([], da.stop_sql_logging())
367
368 def test_sqltrace_filtered_start(self):
369 self.pushProfilingConfig(profiling_allowed='True')
370 profile.start_request(self._get_start_event(
371 '/++profile++sqltrace:includes bugsubscription/'))
372 self.assertIs(getattr(profile._profilers, 'profiler', None), None)
373 self.assertEquals(set(profile._profilers.actions), set(('sql', )))
374 data = profile._profilers.actions['sql']
375 self.assertTrue(data['condition']('SELECT BUGSUBSCRIPTION FROM FOO'))
277 self.assertEqual([], da.stop_sql_logging())376 self.assertEqual([], da.stop_sql_logging())
278377
279378
@@ -380,7 +479,7 @@
380 self.pushProfilingConfig(479 self.pushProfilingConfig(
381 profiling_allowed='False', profile_all_requests='True',480 profiling_allowed='False', profile_all_requests='True',
382 memory_profile_log=self.memory_profile_log)481 memory_profile_log=self.memory_profile_log)
383 request = self.endRequest('/++profile++show,callgrind')482 request = self.endRequest('/++profile++show&callgrind')
384 self.assertIs(getattr(request, 'oops', None), None)483 self.assertIs(getattr(request, 'oops', None), None)
385 self.assertEqual(self.getAddedResponse(request), '')484 self.assertEqual(self.getAddedResponse(request), '')
386 self.assertEqual(self.getMemoryLog(), [])485 self.assertEqual(self.getMemoryLog(), [])
@@ -469,7 +568,7 @@
469 # If profiling is allowed and a request with the "callgrind" and568 # If profiling is allowed and a request with the "callgrind" and
470 # "show" marker URL segment is made, profiling starts.569 # "show" marker URL segment is made, profiling starts.
471 self.pushProfilingConfig(profiling_allowed='True')570 self.pushProfilingConfig(profiling_allowed='True')
472 request = self.endRequest('/++profile++callgrind,show')571 request = self.endRequest('/++profile++callgrind&show')
473 self.assertProfilePaths(572 self.assertProfilePaths(
474 self.assertBasicProfileExists(request, show=True))573 self.assertBasicProfileExists(request, show=True))
475574
@@ -499,7 +598,7 @@
499 # "pstats" markers is made, profiling starts with the callgrind598 # "pstats" markers is made, profiling starts with the callgrind
500 # approach only.599 # approach only.
501 self.pushProfilingConfig(profiling_allowed='True')600 self.pushProfilingConfig(profiling_allowed='True')
502 request = self.endRequest('/++profile++callgrind,pstats/')601 request = self.endRequest('/++profile++callgrind&pstats/')
503 self.assertBothProfiles(self.assertBasicProfileExists(request))602 self.assertBothProfiles(self.assertBasicProfileExists(request))
504 # We had a bug in which the callgrind file was actually a pstats603 # We had a bug in which the callgrind file was actually a pstats
505 # file. What we can do minimally to prevent this in the future is604 # file. What we can do minimally to prevent this in the future is
@@ -606,14 +705,14 @@
606 profiling_allowed='False', profile_all_requests='True',705 profiling_allowed='False', profile_all_requests='True',
607 memory_profile_log='.')706 memory_profile_log='.')
608 event = BeforeTraverseEvent(None,707 event = BeforeTraverseEvent(None,
609 self._get_request('/++profile++show,callgrind'))708 self._get_request('/++profile++show&callgrind'))
610 with FeatureFixture({'profiling.enabled': 'on'}):709 with FeatureFixture({'profiling.enabled': 'on'}):
611 profile.before_traverse(event)710 profile.before_traverse(event)
612 self.assertTrue(profile._profilers.profiling)711 self.assertTrue(profile._profilers.profiling)
613 self.assertIsInstance(712 self.assertIsInstance(
614 profile._profilers.profiler, profile.Profiler)713 profile._profilers.profiler, profile.Profiler)
615 self.assertEquals(714 self.assertEquals(
616 set(('show', 'callgrind')), profile._profilers.actions)715 set(('show', 'callgrind')), set(profile._profilers.actions))
617716
618717
619class TestInlineProfiling(BaseRequestEndHandlerTest):718class TestInlineProfiling(BaseRequestEndHandlerTest):
@@ -643,7 +742,7 @@
643 # ++profile++ wins over inline.742 # ++profile++ wins over inline.
644 self.pushProfilingConfig(profiling_allowed='True')743 self.pushProfilingConfig(profiling_allowed='True')
645 request = self.endRequest(744 request = self.endRequest(
646 '/++profile++show,callgrind', work=self.make_work())745 '/++profile++show&callgrind', work=self.make_work())
647 response = self.assertBasicProfileExists(request, show=True)746 response = self.assertBasicProfileExists(request, show=True)
648 self.assertCallgrindProfile(response)747 self.assertCallgrindProfile(response)
649 self.assertIn('Inline request ignored', response)748 self.assertIn('Inline request ignored', response)
@@ -658,12 +757,23 @@
658 self.assertBasicProfileExists(request, show=True))757 self.assertBasicProfileExists(request, show=True))
659758
660759
661class TestSqlTrace(TestCaseWithFactory, BaseRequestEndHandlerTest):760class TestSqlLogging(TestCaseWithFactory, BaseRequestEndHandlerTest):
662761
663 layer = layers.DatabaseFunctionalLayer762 layer = layers.DatabaseFunctionalLayer
664763
665 def testLogging(self):764 def testLogging(self):
666 # This is basically a smoketest. The underlying machinery has tests.765 self.pushProfilingConfig(profiling_allowed='True')
766 request = self.endRequest(
767 '/++profile++sql/', work=self.factory.makeBug)
768 response = self.getAddedResponse(request)
769 self.assertIn('Top 10 SQL times', response)
770 self.assertIn('Query number', response)
771 self.assertIn('Top 10 Python times', response)
772 self.assertIn('Before query', response)
773 self.assertTrue('Repeated Python SQL Triggers' not in response)
774 self.assertTrue('Show all tracebacks' not in response)
775
776 def testTraceLogging(self):
667 self.pushProfilingConfig(profiling_allowed='True')777 self.pushProfilingConfig(profiling_allowed='True')
668 request = self.endRequest(778 request = self.endRequest(
669 '/++profile++sqltrace/', work=self.factory.makeBug)779 '/++profile++sqltrace/', work=self.factory.makeBug)
@@ -676,3 +786,21 @@
676 self.assertIn('Show all tracebacks', response)786 self.assertIn('Show all tracebacks', response)
677 # This file should be part of several of the tracebacks.787 # This file should be part of several of the tracebacks.
678 self.assertIn(__file__.replace('.pyc', '.py'), response)788 self.assertIn(__file__.replace('.pyc', '.py'), response)
789
790 def testTraceLoggingConditionally(self):
791 self.pushProfilingConfig(profiling_allowed='True')
792 request = self.endRequest(
793 '/++profile++sqltrace:includes SELECT/',
794 work=self.factory.makeBug)
795 response = self.getAddedResponse(request)
796 self.assertIn('Top 10 SQL times', response)
797 self.assertIn('Query number', response)
798 self.assertIn('Top 10 Python times', response)
799 self.assertIn('Before query', response)
800 self.assertIn('Repeated Python SQL Triggers', response)
801 self.assertIn('Show all tracebacks', response)
802 self.assertIn(
803 'You have requested tracebacks for statements that match only',
804 response)
805 # This file should be part of several of the tracebacks.
806 self.assertIn(__file__.replace('.pyc', '.py'), response)