Merge lp:~gary/launchpad/bug838878 into lp:launchpad
- bug838878
- Merge into devel
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 |
Related bugs: |
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+
- ++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+
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:/
QA should be similar: https:/
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
1 | === modified file 'lib/lp/services/profile/profile.pt' | |||
2 | --- lib/lp/services/profile/profile.pt 2011-08-22 17:08:02 +0000 | |||
3 | +++ lib/lp/services/profile/profile.pt 2011-09-02 16:34:47 +0000 | |||
4 | @@ -47,7 +47,7 @@ | |||
5 | 47 | multiple_profiles options/multiple_profiles|nothing; | 47 | multiple_profiles options/multiple_profiles|nothing; |
6 | 48 | inline_ignored actions/inline_ignored|nothing; | 48 | inline_ignored actions/inline_ignored|nothing; |
7 | 49 | inline actions/inline|nothing; | 49 | inline actions/inline|nothing; |
9 | 50 | sqltrace actions/sqltrace|nothing; | 50 | sqltrace actions/sql|nothing; |
10 | 51 | sqltrace_steps options/sqltrace|nothing; | 51 | sqltrace_steps options/sqltrace|nothing; |
11 | 52 | "> | 52 | "> |
12 | 53 | <div class="hide_reveal_profiling" id="hide_profiling"> | 53 | <div class="hide_reveal_profiling" id="hide_profiling"> |
13 | @@ -64,15 +64,21 @@ | |||
14 | 64 | get immediate profiling results in the browser, use | 64 | get immediate profiling results in the browser, use |
15 | 65 | <code>++profile++show</code>.</tal:block> <tal:block condition="not: | 65 | <code>++profile++show</code>.</tal:block> <tal:block condition="not: |
16 | 66 | always_log">In order to get profiling results, you need to ask for an HTML | 66 | always_log">In order to get profiling results, you need to ask for an HTML |
18 | 67 | view (<code>++profile++show</code>), a KCacheGrind-friendly log on the | 67 | view of the profile and OOPS data including SQL calls |
19 | 68 | (<code>++profile++show</code>), a KCacheGrind-friendly log on the | ||
20 | 68 | filesystem (<code>++profile++callgrind</code>), a PStats-friendly log | 69 | filesystem (<code>++profile++callgrind</code>), a PStats-friendly log |
21 | 69 | (Python standard library) on the filesystem | 70 | (Python standard library) on the filesystem |
23 | 70 | (<code>++profile++pstats</code>), or an HTML view of the SQL and the | 71 | (<code>++profile++pstats</code>), an HTML view of the SQL and the |
24 | 71 | Python stacktrace when each SQL call was made | 72 | Python stacktrace when each SQL call was made |
29 | 72 | (<code>++profile++sqltrace</code>). You can also combine these | 73 | (<code>++profile++sqltrace</code>), or an HTML view of only the SQL |
30 | 73 | (<code>++profile++show,callgrind</code> or | 74 | (<code>++profile++sql</code>). You can also combine these |
31 | 74 | <code>++profile++show,pstats</code> or others, | 75 | (<code>++profile++show&callgrind</code> or |
32 | 75 | with each action separated with commas).</tal:block></p> | 76 | <code>++profile++show&pstats</code> or others, with each action separated |
33 | 77 | with ampersands).</tal:block></p> | ||
34 | 78 | <p>The <code>++profile++sqltrace</code> can take too much time to let a | ||
35 | 79 | page practically render, especially on qastaging and staging. You can | ||
36 | 80 | filter to only get the stacktraces you want in this case; see information | ||
37 | 81 | in the "SQL trace" section below on how to do this.</p> | ||
38 | 76 | <p>The "++profile++" path segment can usually go anywhere in the URL | 82 | <p>The "++profile++" path segment can usually go anywhere in the URL |
39 | 77 | (e.g., <code>http://launchpad.dev/++profile++show</code> or | 83 | (e.g., <code>http://launchpad.dev/++profile++show</code> or |
40 | 78 | <code>http://launchpad.dev/++profile++show/Firefox</code> or | 84 | <code>http://launchpad.dev/++profile++show/Firefox</code> or |
41 | @@ -119,8 +125,8 @@ | |||
42 | 119 | as in <code>++profile++pstats</code>. Profiles are logged to <tal:block | 125 | as in <code>++profile++pstats</code>. Profiles are logged to <tal:block |
43 | 120 | replace="dump_path" />.</p> | 126 | replace="dump_path" />.</p> |
44 | 121 | <p> You can see both the log information and immediate results with | 127 | <p> You can see both the log information and immediate results with |
47 | 122 | <code>++profile++callgrind,show</code> or | 128 | <code>++profile++callgrind&show</code> or |
48 | 123 | <code>++profile++pstats,show</code>.</p> | 129 | <code>++profile++pstats&show</code>.</p> |
49 | 124 | </tal:block> | 130 | </tal:block> |
50 | 125 | <tal:block condition="log"> | 131 | <tal:block condition="log"> |
51 | 126 | <p tal:condition="always_log"><strong>You have configured every | 132 | <p tal:condition="always_log"><strong>You have configured every |
52 | @@ -144,11 +150,72 @@ | |||
53 | 144 | <tal:block condition="not:sqltrace"> | 150 | <tal:block condition="not:sqltrace"> |
54 | 145 | <p>Use <code>++profile++sqltrace</code> in your URL to see the SQL that | 151 | <p>Use <code>++profile++sqltrace</code> in your URL to see the SQL that |
55 | 146 | the page runs, along with start and stop times, the database used, and the | 152 | the page runs, along with start and stop times, the database used, and the |
59 | 147 | stacktrace for when each sql call is made.</p> <p>Note that if you do not | 153 | stacktrace for when each sql call is made.</p> |
60 | 148 | want the tracebacks, <code>++profile++show</code> will include OOPS data | 154 | <p>If you only want SQL and not the tracebacks, |
61 | 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 |
62 | 156 | <code>++profile++show</code> will include OOPS data at the end of the | ||
63 | 157 | profiling information.</p> | ||
64 | 158 | <p>If you want stacktraces only for certain SQL statements, you can do | ||
65 | 159 | that too. You can use <code>startswith</code>, <code>endswith</code> | ||
66 | 160 | or <code>includes</code> to specify parts of the SQL that you want to use | ||
67 | 161 | as triggers. Note that this is whitespace and case normalized, so you | ||
68 | 162 | just need to get the spelling right. Here are some examples.</p> | ||
69 | 163 | <dl> | ||
70 | 164 | <dt><code>/++profile++sqltrace: includes Product.blueprints_usage/</code> | ||
71 | 165 | </dt> | ||
72 | 166 | <dd>This will get a stacktrace for any SQL statement that has the | ||
73 | 167 | string "Product.blueprints_usage" in it.</dd> | ||
74 | 168 | <dt><code>/++profile++sqltrace:startswith SELECT | ||
75 | 169 | Distribution.answers_usage/</code> </dt> | ||
76 | 170 | <dd>This will get a stacktrace for any SQL statement that starts with the | ||
77 | 171 | string "SELECT Distribution.answers_usage" in it.</dd> | ||
78 | 172 | <dt><code>/++profile++sqltrace:endswith WHERE Project.id = 5 LIMIT | ||
79 | 173 | 1/</code> </dt> | ||
80 | 174 | <dd>This will get a stacktrace for any SQL statement that ends with the | ||
81 | 175 | string given. Note that it does not end in a semicolon, and note that | ||
82 | 176 | parameters are filled in.</dd> | ||
83 | 177 | </dl> | ||
84 | 178 | <p>You can also combine requests with the <code>|</code> mark (the | ||
85 | 179 | pipe). Here's an example: | ||
86 | 180 | <code>/++profile++sqltrace:startswith SELECT Distribution.answers_usage | | ||
87 | 181 | includes Product.blueprints_usage/</code>.</p> | ||
88 | 150 | </tal:block> | 182 | </tal:block> |
89 | 151 | <tal:block condition="sqltrace"> | 183 | <tal:block condition="sqltrace"> |
90 | 184 | <p tal:condition="options/sql_traceback_all|nothing">You have requested | ||
91 | 185 | tracebacks for all SQL statements. You can filter these with conditions | ||
92 | 186 | like <code>startswith</code>, <code>endswith</code> or | ||
93 | 187 | <code>includes</code>. Here's a simple example: | ||
94 | 188 | <code>/++profile++sqltrace: includes Product.blueprints_usage/</code>.</p> | ||
95 | 189 | <p tal:condition="options/sql_traceback_none|nothing">You have requested no | ||
96 | 190 | tracebacks. Use <code>++profile++sqltrace</code> to get tracebacks.</p> | ||
97 | 191 | <tal:block condition="options/sql_traceback_conditions|nothing"> | ||
98 | 192 | <p>You have requested tracebacks for statements that match only certain | ||
99 | 193 | conditions.</p> | ||
100 | 194 | <tal:block | ||
101 | 195 | condition="not:options/sql_traceback_conditions/included"> | ||
102 | 196 | <p><strong> You had no valid conditions, so no tracebacks were | ||
103 | 197 | included.</strong> The available conditions are <code>startswith</code>, | ||
104 | 198 | <code>endswith</code> or <code>includes</code>. Here's a simple | ||
105 | 199 | example.</p> | ||
106 | 200 | <pre>++profile++sqltrace: includes Product.blueprints_usage/</pre> | ||
107 | 201 | </tal:block> | ||
108 | 202 | <ul> | ||
109 | 203 | <li tal:repeat="condition options/sql_traceback_conditions/included"> | ||
110 | 204 | <em tal:content="condition/constraint">CONSTRAINT</em> | ||
111 | 205 | <span tal:replace="condition/value">VALUE</span> | ||
112 | 206 | </li> | ||
113 | 207 | </ul> | ||
114 | 208 | <tal:block condition="options/sql_traceback_conditions/ignored"> | ||
115 | 209 | <p><strong>Warning</strong>: these conditions were not understood, and | ||
116 | 210 | so ignored.</p> | ||
117 | 211 | <ul> | ||
118 | 212 | <li tal:repeat="condition options/sql_traceback_conditions/ignored"> | ||
119 | 213 | <em tal:content="condition/constraint">CONSTRAINT</em> | ||
120 | 214 | <span tal:replace="condition/value">VALUE</span> | ||
121 | 215 | </li> | ||
122 | 216 | </ul> | ||
123 | 217 | </tal:block> | ||
124 | 218 | </tal:block> | ||
125 | 152 | <h3>Top 10 SQL times</h3> | 219 | <h3>Top 10 SQL times</h3> |
126 | 153 | <ol> | 220 | <ol> |
127 | 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"> |
128 | @@ -158,6 +225,14 @@ | |||
129 | 158 | </li> | 225 | </li> |
130 | 159 | </ol> | 226 | </ol> |
131 | 160 | <h3>Top 10 Python times</h3> | 227 | <h3>Top 10 Python times</h3> |
132 | 228 | <p tal:condition="options/sql_traceback_all|nothing">Note that generating | ||
133 | 229 | stacktraces can add significantly to these numbers, and skew results. Use | ||
134 | 230 | <code>++profile++sql</code> for a more accurate view.</p> | ||
135 | 231 | <p tal:condition="options/sql_traceback_conditions|nothing">Note that | ||
136 | 232 | generating stacktraces can add significantly to these numbers, and | ||
137 | 233 | selectively choosing when to generate stacktraces will produce so much | ||
138 | 234 | skew as to potentially make these values meaningless. Use | ||
139 | 235 | <code>++profile++sql</code> for the most accurate view.</p> | ||
140 | 161 | <ol> | 236 | <ol> |
141 | 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"> |
142 | 163 | <a tal:attributes="href string:#pythonstep-${info/ix}">Before query | 238 | <a tal:attributes="href string:#pythonstep-${info/ix}">Before query |
143 | @@ -165,32 +240,37 @@ | |||
144 | 165 | replace="info/value"></tal:block> milliseconds) | 240 | replace="info/value"></tal:block> milliseconds) |
145 | 166 | </li> | 241 | </li> |
146 | 167 | </ol> | 242 | </ol> |
165 | 168 | <h3>Repeated Python SQL Triggers</h3> | 243 | <tal:block condition="not: options/sql_traceback_none|nothing"> |
166 | 169 | <p tal:condition="not: options/top_triggers">None.</p> | 244 | <h3>Repeated Python SQL Triggers</h3> |
167 | 170 | <div tal:condition="options/top_triggers"> | 245 | <p tal:condition="options/sql_traceback_conditions|nothing">These are |
168 | 171 | <p>Typically, these show loops. The traceback may show extra | 246 | only calculated for the stacktraces that were collected.</p> |
169 | 172 | information, such as from page templates, that indicate the variable | 247 | <p tal:condition="not: options/top_triggers">None.</p> |
170 | 173 | within the loop. If you want to add more information to identify the | 248 | <div tal:condition="options/top_triggers"> |
171 | 174 | variables in the loop, in your Python add either an informational string | 249 | <p>Typically, these show loops. The traceback may show extra |
172 | 175 | with the variable name <code>__traceback_info__</code>, or add a | 250 | information, such as from page templates, that indicate the variable |
173 | 176 | <code>__traceback_supplement__</code> as used in | 251 | within the loop. If you want to add more information to identify the |
174 | 177 | lp.services.stacktrace.</p> | 252 | variables in the loop, in your Python add either an informational |
175 | 178 | <div tal:repeat="trigger options/top_triggers"> | 253 | string with the variable name <code>__traceback_info__</code>, or add |
176 | 179 | <div>File "<tal:block replace="trigger/filename"></tal:block>", | 254 | a <code>__traceback_supplement__</code> as used in |
177 | 180 | line <tal:block replace="trigger/lineno"></tal:block></div> | 255 | lp.services.stacktrace.</p> |
178 | 181 | <div class="querylinks"> | 256 | <div tal:repeat="trigger options/top_triggers"> |
179 | 182 | <tal:block replace="trigger/count"></tal:block> related queries (<a | 257 | <div>File "<tal:block |
180 | 183 | href="#" class="expandall">expand all tracebacks</a>): <span | 258 | replace="trigger/filename"></tal:block>", line <tal:block |
181 | 184 | tal:repeat="ix trigger/indexes"> <a tal:attributes="href | 259 | replace="trigger/lineno"></tal:block></div> |
182 | 185 | string:#sqlstep-${ix}" tal:content="ix"></a> </span> | 260 | <div class="querylinks"> <tal:block |
183 | 261 | replace="trigger/count"></tal:block> related queries (<a href="#" | ||
184 | 262 | class="expandall">expand all tracebacks</a>): <span tal:repeat="ix | ||
185 | 263 | trigger/indexes"> <a tal:attributes="href string:#sqlstep-${ix}" | ||
186 | 264 | tal:content="ix"></a> </span> </div> | ||
187 | 186 | </div> | 265 | </div> |
188 | 187 | </div> | 266 | </div> |
190 | 188 | </div> | 267 | </tal:block> |
191 | 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> |
192 | 190 | <p>Each sql line begins with the start time and the stop time, along with | 269 | <p>Each sql line begins with the start time and the stop time, along with |
193 | 191 | the name of the database on which the query ran. Times are in | 270 | the name of the database on which the query ran. Times are in |
194 | 192 | milliseconds since request start.</p> | 271 | milliseconds since request start.</p> |
196 | 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="#" |
197 | 273 | id="show-all-tracebacks">Show all tracebacks</a> / <a href="#" | ||
198 | 194 | id="hide-all-tracebacks">Hide all tracebacks</a></div> | 274 | id="hide-all-tracebacks">Hide all tracebacks</a></div> |
199 | 195 | <div tal:repeat="step sqltrace_steps"> | 275 | <div tal:repeat="step sqltrace_steps"> |
200 | 196 | <div tal:condition="step/python_rank|nothing" tal:attributes="class | 276 | <div tal:condition="step/python_rank|nothing" tal:attributes="class |
201 | @@ -210,9 +290,10 @@ | |||
202 | 210 | tal:condition="step/sql_rank|nothing"><strong>Top ten (# <tal:block | 290 | tal:condition="step/sql_rank|nothing"><strong>Top ten (# <tal:block |
203 | 211 | replace="step/sql_rank"></tal:block>):</strong> SQL took <span | 291 | replace="step/sql_rank"></tal:block>):</strong> SQL took <span |
204 | 212 | tal:replace="step/sql_time" /> milliseconds</span></div> <a href="#" | 292 | tal:replace="step/sql_time" /> milliseconds</span></div> <a href="#" |
206 | 213 | class="clicktext">Click to toggle Python traceback.</a> | 293 | class="clicktext" tal:condition="step/stack">Click to toggle Python |
207 | 294 | traceback.</a><span tal:condition="not:step/stack">--</span> | ||
208 | 214 | </div> | 295 | </div> |
210 | 215 | <div class="trace"><div class="inner"> | 296 | <div class="trace" tal:condition="step/stack"><div class="inner"> |
211 | 216 | <div class="appstack" tal:define="stack step/app_stack"> | 297 | <div class="appstack" tal:define="stack step/app_stack"> |
212 | 217 | <div tal:repeat="frame stack" metal:define-macro="draw-stack"> | 298 | <div tal:repeat="frame stack" metal:define-macro="draw-stack"> |
213 | 218 | <div>File "<tal:block replace="frame/filename"></tal:block>", | 299 | <div>File "<tal:block replace="frame/filename"></tal:block>", |
214 | @@ -247,8 +328,8 @@ | |||
215 | 247 | <h2>Profile quick view</h2> | 328 | <h2>Profile quick view</h2> |
216 | 248 | <tal:block condition="not:show"> | 329 | <tal:block condition="not:show"> |
217 | 249 | <p>Use <code>++profile++show</code> in your URL in order to see immediate | 330 | <p>Use <code>++profile++show</code> in your URL in order to see immediate |
220 | 250 | profile results (or <code>++profile++callgrind,show</code> or | 331 | profile results (or <code>++profile++callgrind&show</code> or |
221 | 251 | <code>++profile++pstats,show</code> to see both the log information and | 332 | <code>++profile++pstats&show</code> to see both the log information and |
222 | 252 | immediate results).</p> | 333 | immediate results).</p> |
223 | 253 | </tal:block> | 334 | </tal:block> |
224 | 254 | <tal:block condition="show"> | 335 | <tal:block condition="show"> |
225 | @@ -275,6 +356,10 @@ | |||
226 | 275 | Y.one('div#profiling_info').setStyle('display', 'none'); | 356 | Y.one('div#profiling_info').setStyle('display', 'none'); |
227 | 276 | e.preventDefault(); | 357 | e.preventDefault(); |
228 | 277 | }); | 358 | }); |
229 | 359 | }); | ||
230 | 360 | </script> | ||
231 | 361 | <script tal:condition="not:options/sql_traceback_none|nothing"> | ||
232 | 362 | LPS.use('node', 'lp', 'transition', function (Y) { | ||
233 | 278 | function slideIn(target) { | 363 | function slideIn(target) { |
234 | 279 | target.transition({ | 364 | target.transition({ |
235 | 280 | easing: 'ease-in', | 365 | easing: 'ease-in', |
236 | 281 | 366 | ||
237 | === modified file 'lib/lp/services/profile/profile.py' | |||
238 | --- lib/lp/services/profile/profile.py 2011-09-01 14:55:10 +0000 | |||
239 | +++ lib/lp/services/profile/profile.py 2011-09-02 16:34:47 +0000 | |||
240 | @@ -13,9 +13,11 @@ | |||
241 | 13 | import contextlib | 13 | import contextlib |
242 | 14 | from cProfile import Profile | 14 | from cProfile import Profile |
243 | 15 | from datetime import datetime | 15 | from datetime import datetime |
244 | 16 | from functools import partial | ||
245 | 16 | import heapq | 17 | import heapq |
246 | 17 | import os | 18 | import os |
247 | 18 | import pstats | 19 | import pstats |
248 | 20 | import re | ||
249 | 19 | import StringIO | 21 | import StringIO |
250 | 20 | import sys | 22 | import sys |
251 | 21 | import threading | 23 | import threading |
252 | @@ -210,11 +212,14 @@ | |||
253 | 210 | _profilers.actions = actions | 212 | _profilers.actions = actions |
254 | 211 | _profilers.profiling = True | 213 | _profilers.profiling = True |
255 | 212 | if config.profiling.profile_all_requests: | 214 | if config.profiling.profile_all_requests: |
257 | 213 | actions.add('callgrind') | 215 | actions['callgrind'] = '' |
258 | 214 | if actions: | 216 | if actions: |
262 | 215 | if 'sqltrace' in actions: | 217 | if 'sql' in actions: |
263 | 216 | da.start_sql_logging(tracebacks_if=True) | 218 | condition = actions['sql'] |
264 | 217 | if 'show' in actions or actions.intersection(available_profilers): | 219 | if condition not in (True, False): |
265 | 220 | condition = condition['condition'] | ||
266 | 221 | da.start_sql_logging(condition) | ||
267 | 222 | if 'show' in actions or available_profilers.intersection(actions): | ||
268 | 218 | _profilers.profiler = Profiler() | 223 | _profilers.profiler = Profiler() |
269 | 219 | _profilers.profiler.start() | 224 | _profilers.profiler.start() |
270 | 220 | if config.profiling.memory_profile_log: | 225 | if config.profiling.memory_profile_log: |
271 | @@ -233,12 +238,14 @@ | |||
272 | 233 | actions = _profilers.actions | 238 | actions = _profilers.actions |
273 | 234 | profiler = _profilers.profiler | 239 | profiler = _profilers.profiler |
274 | 235 | if actions is None: | 240 | if actions is None: |
276 | 236 | actions = _profilers.actions = set() | 241 | actions = _profilers.actions = {} |
277 | 237 | _profilers.profiling = True | 242 | _profilers.profiling = True |
280 | 238 | elif actions.difference(('help',)) and 'inline' not in actions: | 243 | elif 'inline' not in actions and ( |
281 | 239 | actions.add('inline_ignored') | 244 | 'show' in actions or available_profilers.intersection(actions)): |
282 | 245 | # We have a request-based profile in progress. That wins. | ||
283 | 246 | actions['inline_ignored'] = '' | ||
284 | 240 | return | 247 | return |
286 | 241 | actions.update(('pstats', 'show', 'inline')) | 248 | actions.update((k, '') for k in ('pstats', 'show', 'inline')) |
287 | 242 | if profiler is None: | 249 | if profiler is None: |
288 | 243 | profiler = _profilers.profiler = Profiler() | 250 | profiler = _profilers.profiler = Profiler() |
289 | 244 | profiler.start() | 251 | profiler.start() |
290 | @@ -261,8 +268,10 @@ | |||
291 | 261 | @contextlib.contextmanager | 268 | @contextlib.contextmanager |
292 | 262 | def profiling(): | 269 | def profiling(): |
293 | 263 | start() | 270 | start() |
296 | 264 | yield | 271 | try: |
297 | 265 | stop() | 272 | yield |
298 | 273 | finally: | ||
299 | 274 | stop() | ||
300 | 266 | 275 | ||
301 | 267 | 276 | ||
302 | 268 | @adapter(IEndRequestEvent) | 277 | @adapter(IEndRequestEvent) |
303 | @@ -293,8 +302,7 @@ | |||
304 | 293 | _major, _minor, content_type_params = parse(content_type) | 302 | _major, _minor, content_type_params = parse(content_type) |
305 | 294 | is_html = _major == 'text' and _minor == 'html' | 303 | is_html = _major == 'text' and _minor == 'html' |
306 | 295 | template_context = { | 304 | template_context = { |
309 | 296 | # Dicts are easier for tal expressions. | 305 | 'actions': dict((key, True) for key in actions), |
308 | 297 | 'actions': dict((action, True) for action in actions), | ||
310 | 298 | 'always_log': config.profiling.profile_all_requests} | 306 | 'always_log': config.profiling.profile_all_requests} |
311 | 299 | dump_path = config.profiling.profile_dir | 307 | dump_path = config.profiling.profile_dir |
312 | 300 | if _profilers.profiler is not None: | 308 | if _profilers.profiler is not None: |
313 | @@ -345,16 +353,15 @@ | |||
314 | 345 | # Try to free some more memory. | 353 | # Try to free some more memory. |
315 | 346 | del prof_stats | 354 | del prof_stats |
316 | 347 | trace = None | 355 | trace = None |
318 | 348 | if 'sqltrace' in actions: | 356 | if 'sql' in actions: |
319 | 349 | trace = da.stop_sql_logging() or () | 357 | trace = da.stop_sql_logging() or () |
328 | 350 | # The trace is a list of dicts, each with the keys "sql" and | 358 | # The trace is a list of dicts, each with the keys "sql" and "stack". |
329 | 351 | # "stack". "sql" is a tuple of start time, stop time, database | 359 | # "sql" is a tuple of start time, stop time, database name (with a |
330 | 352 | # name (with a "SQL-" prefix), and sql statement. "stack" is a | 360 | # "SQL-" prefix), and sql statement. "stack" is None or a tuple of |
331 | 353 | # tuple of filename, line number, function name, text, module | 361 | # filename, line number, function name, text, module name, optional |
332 | 354 | # name, optional supplement dict, and optional info string. The | 362 | # supplement dict, and optional info string. The supplement dict has |
333 | 355 | # supplement dict has keys 'source_url', 'line', 'column', | 363 | # keys 'source_url', 'line', 'column', 'expression', 'warnings' (an |
334 | 356 | # 'expression', 'warnings' (an iterable), and 'extra', any of | 364 | # iterable), and 'extra', any of which may be None. |
327 | 357 | # which may be None. | ||
335 | 358 | top_sql = [] | 365 | top_sql = [] |
336 | 359 | top_python = [] | 366 | top_python = [] |
337 | 360 | triggers = {} | 367 | triggers = {} |
338 | @@ -366,29 +373,30 @@ | |||
339 | 366 | step['id'] = ix | 373 | step['id'] = ix |
340 | 367 | step['sql'] = dict(zip( | 374 | step['sql'] = dict(zip( |
341 | 368 | ('start', 'stop', 'name', 'statement'), step['sql'])) | 375 | ('start', 'stop', 'name', 'statement'), step['sql'])) |
365 | 369 | # Divide up the stack into the more unique (app) and less | 376 | if step['stack'] is not None: |
366 | 370 | # unique (db) bits. | 377 | # Divide up the stack into the more unique (app) and less |
367 | 371 | app_stack = step['app_stack'] = [] | 378 | # unique (db) bits. |
368 | 372 | db_stack = step['db_stack'] = [] | 379 | app_stack = step['app_stack'] = [] |
369 | 373 | storm_found = False | 380 | db_stack = step['db_stack'] = [] |
370 | 374 | for f in step['stack']: | 381 | storm_found = False |
371 | 375 | f_data = dict(zip( | 382 | for f in step['stack']: |
372 | 376 | ('filename', 'lineno', 'name', 'line', 'module', | 383 | f_data = dict(zip( |
373 | 377 | 'supplement', 'info'), f)) | 384 | ('filename', 'lineno', 'name', 'line', 'module', |
374 | 378 | storm_found = storm_found or ( | 385 | 'supplement', 'info'), f)) |
375 | 379 | f_data['module'] and | 386 | storm_found = storm_found or ( |
376 | 380 | f_data['module'].startswith('storm.')) | 387 | f_data['module'] and |
377 | 381 | if storm_found: | 388 | f_data['module'].startswith('storm.')) |
378 | 382 | db_stack.append(f_data) | 389 | if storm_found: |
379 | 383 | else: | 390 | db_stack.append(f_data) |
380 | 384 | app_stack.append(f_data) | 391 | else: |
381 | 385 | # Begin to gather what app code is triggering the most SQL | 392 | app_stack.append(f_data) |
382 | 386 | # calls. | 393 | # Begin to gather what app code is triggering the most SQL |
383 | 387 | trigger_key = tuple( | 394 | # calls. |
384 | 388 | (f['filename'], f['lineno']) for f in app_stack) | 395 | trigger_key = tuple( |
385 | 389 | if trigger_key not in triggers: | 396 | (f['filename'], f['lineno']) for f in app_stack) |
386 | 390 | triggers[trigger_key] = [] | 397 | if trigger_key not in triggers: |
387 | 391 | triggers[trigger_key].append(ix) | 398 | triggers[trigger_key] = [] |
388 | 399 | triggers[trigger_key].append(ix) | ||
389 | 392 | # Get the nbest (n=10) sql and python times | 400 | # Get the nbest (n=10) sql and python times |
390 | 393 | step['python_time'] = step['sql']['start'] - last_stop_time | 401 | step['python_time'] = step['sql']['start'] - last_stop_time |
391 | 394 | step['sql_time'] = step['sql']['stop'] - step['sql']['start'] | 402 | step['sql_time'] = step['sql']['stop'] - step['sql']['start'] |
392 | @@ -449,6 +457,14 @@ | |||
393 | 449 | top_python=top_python_ids, | 457 | top_python=top_python_ids, |
394 | 450 | top_triggers=top_triggers, | 458 | top_triggers=top_triggers, |
395 | 451 | sql_count=len(trace))) | 459 | sql_count=len(trace))) |
396 | 460 | if actions['sql'] is True: | ||
397 | 461 | template_context['sql_traceback_all'] = True | ||
398 | 462 | elif actions['sql'] is False: | ||
399 | 463 | template_context['sql_traceback_none'] = True | ||
400 | 464 | else: | ||
401 | 465 | conditions = actions['sql'].copy() | ||
402 | 466 | del conditions['condition'] | ||
403 | 467 | template_context['sql_traceback_conditions'] = conditions | ||
404 | 452 | template_context['dump_path'] = os.path.abspath(dump_path) | 468 | template_context['dump_path'] = os.path.abspath(dump_path) |
405 | 453 | if actions and is_html: | 469 | if actions and is_html: |
406 | 454 | # Hack the new HTML in at the end of the page. | 470 | # Hack the new HTML in at the end of the page. |
407 | @@ -488,7 +504,7 @@ | |||
408 | 488 | URL. Note that ++profile++ alone without actions is interpreted as | 504 | URL. Note that ++profile++ alone without actions is interpreted as |
409 | 489 | the "help" action. | 505 | the "help" action. |
410 | 490 | """ | 506 | """ |
412 | 491 | result = set() | 507 | result = dict() |
413 | 492 | path_info = request.get('PATH_INFO') | 508 | path_info = request.get('PATH_INFO') |
414 | 493 | if path_info: | 509 | if path_info: |
415 | 494 | # if not, this is almost certainly a test not bothering to set up | 510 | # if not, this is almost certainly a test not bothering to set up |
416 | @@ -505,24 +521,108 @@ | |||
417 | 505 | # include traversal in the profile. | 521 | # include traversal in the profile. |
418 | 506 | actions, slash, tail = end.partition('/') | 522 | actions, slash, tail = end.partition('/') |
419 | 507 | result.update( | 523 | result.update( |
423 | 508 | action for action in ( | 524 | (name.strip(), config.strip()) |
424 | 509 | item.strip().lower() for item in actions.split(',')) | 525 | for name, partition, config in ( |
425 | 510 | if action) | 526 | item.strip().lower().partition(':') |
426 | 527 | for item in actions.split('&')) | ||
427 | 528 | if name.strip()) | ||
428 | 511 | # 'log' is backwards compatible for 'callgrind'. | 529 | # 'log' is backwards compatible for 'callgrind'. |
429 | 512 | if 'log' in result: | 530 | if 'log' in result: |
432 | 513 | result.remove('log') | 531 | result['callgrind'] = result.pop('log') |
433 | 514 | result.add('callgrind') | 532 | if 'sqltrace' in result: |
434 | 533 | condition = result['sqltrace'] | ||
435 | 534 | if condition: | ||
436 | 535 | condition = _make_condition_function(condition) | ||
437 | 536 | else: | ||
438 | 537 | condition = True | ||
439 | 538 | del result['sqltrace'] | ||
440 | 539 | result['sql'] = condition | ||
441 | 540 | elif 'sql' in result: | ||
442 | 541 | result['sql'] = False | ||
443 | 515 | # Only honor the available options. | 542 | # Only honor the available options. |
445 | 516 | available_options = set(('show', 'sqltrace', 'help')) | 543 | available_options = set(('show', 'sql', 'help')) |
446 | 517 | available_options.update(available_profilers) | 544 | available_options.update(available_profilers) |
448 | 518 | result.intersection_update(available_options) | 545 | # .keys() gives a list, not mutated during iteration. |
449 | 546 | for key in result.keys(): | ||
450 | 547 | if key not in available_options: | ||
451 | 548 | del result[key] | ||
452 | 519 | # If we didn't end up with any known actions, we need to help the | 549 | # If we didn't end up with any known actions, we need to help the |
453 | 520 | # user. | 550 | # user. |
454 | 521 | if not result: | 551 | if not result: |
456 | 522 | result.add('help') | 552 | result['help'] = '' |
457 | 523 | return result | 553 | return result |
458 | 524 | 554 | ||
459 | 525 | 555 | ||
460 | 556 | def _make_startswith(value): | ||
461 | 557 | """Return a function that returns true if its argument startswith value""" | ||
462 | 558 | def startswith(sql): | ||
463 | 559 | return sql.startswith(value) | ||
464 | 560 | return startswith | ||
465 | 561 | |||
466 | 562 | |||
467 | 563 | def _make_endswith(value): | ||
468 | 564 | """Return a function that returns true if its argument endswith value""" | ||
469 | 565 | def endswith(sql): | ||
470 | 566 | return sql.endswith(value) | ||
471 | 567 | return endswith | ||
472 | 568 | |||
473 | 569 | |||
474 | 570 | def _make_includes(value): | ||
475 | 571 | """Return a function that returns true if its argument includes value""" | ||
476 | 572 | def includes(sql): | ||
477 | 573 | return value in sql | ||
478 | 574 | return includes | ||
479 | 575 | |||
480 | 576 | _condition_functions = { | ||
481 | 577 | 'STARTSWITH': _make_startswith, | ||
482 | 578 | 'ENDSWITH': _make_endswith, | ||
483 | 579 | 'INCLUDES': _make_includes | ||
484 | 580 | } | ||
485 | 581 | |||
486 | 582 | _normalize_whitespace = partial(re.compile('\s+').sub, ' ') | ||
487 | 583 | |||
488 | 584 | |||
489 | 585 | def _make_condition_function(condition_string): | ||
490 | 586 | """Given DSL string, return dict including function implementing string. | ||
491 | 587 | |||
492 | 588 | DSL is very simple. Conditions are separated by semicolons, which | ||
493 | 589 | represent logical or. Each condition should begin with (case insensitive) | ||
494 | 590 | "startswith ", "endswith ", or "includes ". The part of the condition | ||
495 | 591 | after this word and before the next semicolon or end-of-string is the | ||
496 | 592 | match string, which is case-insensitive and whitespace-normalized. | ||
497 | 593 | |||
498 | 594 | Returned dict has three elements: the function that implements the DSL, | ||
499 | 595 | the list of conditions that were included, and the list of conditions | ||
500 | 596 | that were excluded (because they were not understood). | ||
501 | 597 | """ | ||
502 | 598 | conditions = [] | ||
503 | 599 | included = [] | ||
504 | 600 | ignored = [] | ||
505 | 601 | for constraint, partition, value in ( | ||
506 | 602 | c.strip().partition(' ') for c | ||
507 | 603 | in condition_string.upper().split('|')): | ||
508 | 604 | # Process each condition. | ||
509 | 605 | constraint = constraint.strip() | ||
510 | 606 | if not constraint: | ||
511 | 607 | # This was something ignorable, like a trailing | or something. | ||
512 | 608 | continue | ||
513 | 609 | value = _normalize_whitespace(value.strip()) | ||
514 | 610 | description = dict(constraint=constraint, value=value) | ||
515 | 611 | if constraint in _condition_functions: | ||
516 | 612 | conditions.append(_condition_functions[constraint](value)) | ||
517 | 613 | included.append(description) | ||
518 | 614 | else: | ||
519 | 615 | ignored.append(description) | ||
520 | 616 | |||
521 | 617 | def condition_aggregate(sql): | ||
522 | 618 | for condition in conditions: | ||
523 | 619 | if condition(sql): | ||
524 | 620 | return True | ||
525 | 621 | return False | ||
526 | 622 | return dict( | ||
527 | 623 | condition=condition_aggregate, included=included, ignored=ignored) | ||
528 | 624 | |||
529 | 625 | |||
530 | 526 | class ProfileNamespace(view): | 626 | class ProfileNamespace(view): |
531 | 527 | """A see-through namespace that handles traversals with ++profile++.""" | 627 | """A see-through namespace that handles traversals with ++profile++.""" |
532 | 528 | 628 | ||
533 | 529 | 629 | ||
534 | === modified file 'lib/lp/services/profile/tests.py' | |||
535 | --- lib/lp/services/profile/tests.py 2011-09-01 14:55:10 +0000 | |||
536 | +++ lib/lp/services/profile/tests.py 2011-09-02 16:34:47 +0000 | |||
537 | @@ -43,6 +43,85 @@ | |||
538 | 43 | EXAMPLE_HTML = EXAMPLE_HTML_START + EXAMPLE_HTML_END | 43 | EXAMPLE_HTML = EXAMPLE_HTML_START + EXAMPLE_HTML_END |
539 | 44 | 44 | ||
540 | 45 | 45 | ||
541 | 46 | class SQLDSLTest(TestCase): | ||
542 | 47 | |||
543 | 48 | def assertCondition(self, | ||
544 | 49 | condition_string, succeeds, fails, included, ignored): | ||
545 | 50 | results = profile._make_condition_function(condition_string) | ||
546 | 51 | self.assertEqual(included, results['included']) | ||
547 | 52 | self.assertEqual(ignored, results['ignored']) | ||
548 | 53 | for example in succeeds: | ||
549 | 54 | self.assertTrue(results['condition'](example)) | ||
550 | 55 | for example in fails: | ||
551 | 56 | self.assertFalse(results['condition'](example)) | ||
552 | 57 | |||
553 | 58 | def test_startswith(self): | ||
554 | 59 | self.assertCondition( | ||
555 | 60 | 'startswith foo bar', | ||
556 | 61 | succeeds=['FOO BARBAZ'], | ||
557 | 62 | fails=['BARBAZ FOO'], | ||
558 | 63 | included=[dict(constraint='STARTSWITH', value='FOO BAR')], | ||
559 | 64 | ignored=[]) | ||
560 | 65 | |||
561 | 66 | def test_endswith(self): | ||
562 | 67 | self.assertCondition( | ||
563 | 68 | 'endswith foo bar', | ||
564 | 69 | succeeds=['BAZ FOO BAR'], | ||
565 | 70 | fails=['BARBAZ FOO'], | ||
566 | 71 | included=[dict(constraint='ENDSWITH', value='FOO BAR')], | ||
567 | 72 | ignored=[]) | ||
568 | 73 | |||
569 | 74 | def test_includes(self): | ||
570 | 75 | self.assertCondition( | ||
571 | 76 | 'includes foo bar', | ||
572 | 77 | succeeds=['BAZ FOO BAR BING'], | ||
573 | 78 | fails=['BARBAZ FOO'], | ||
574 | 79 | included=[dict(constraint='INCLUDES', value='FOO BAR')], | ||
575 | 80 | ignored=[]) | ||
576 | 81 | |||
577 | 82 | def test_whitespace_normalized(self): | ||
578 | 83 | self.assertCondition( | ||
579 | 84 | ' startswith foo bar ', | ||
580 | 85 | succeeds=['FOO BARBAZ'], | ||
581 | 86 | fails=['BARBAZ FOO'], | ||
582 | 87 | included=[dict(constraint='STARTSWITH', value='FOO BAR')], | ||
583 | 88 | ignored=[]) | ||
584 | 89 | |||
585 | 90 | def test_many_conditions(self): | ||
586 | 91 | self.assertCondition( | ||
587 | 92 | 'startswith foo bar | endswith shazam|includes balooba', | ||
588 | 93 | succeeds=['FOO BARBAZ', 'SALAMI SHAZAM', 'FORTUNA BALOOBA CAT'], | ||
589 | 94 | fails=['BARBAZ FOO'], | ||
590 | 95 | included=[dict(constraint='STARTSWITH', value='FOO BAR'), | ||
591 | 96 | dict(constraint='ENDSWITH', value='SHAZAM'), | ||
592 | 97 | dict(constraint='INCLUDES', value='BALOOBA')], | ||
593 | 98 | ignored=[]) | ||
594 | 99 | |||
595 | 100 | def test_trailing_or(self): | ||
596 | 101 | self.assertCondition( | ||
597 | 102 | 'startswith foo bar|', | ||
598 | 103 | succeeds=['FOO BARBAZ'], | ||
599 | 104 | fails=['BARBAZ FOO'], | ||
600 | 105 | included=[dict(constraint='STARTSWITH', value='FOO BAR')], | ||
601 | 106 | ignored=[]) | ||
602 | 107 | |||
603 | 108 | def test_one_ignored(self): | ||
604 | 109 | self.assertCondition( | ||
605 | 110 | 'matches foo bar', | ||
606 | 111 | succeeds=[], | ||
607 | 112 | fails=['BARBAZ FOO'], | ||
608 | 113 | included=[], | ||
609 | 114 | ignored=[dict(constraint='MATCHES', value='FOO BAR')]) | ||
610 | 115 | |||
611 | 116 | def test_one_included_one_ignored(self): | ||
612 | 117 | self.assertCondition( | ||
613 | 118 | 'matches kumquat | startswith foo bar', | ||
614 | 119 | succeeds=['FOO BAR HAMSTER'], | ||
615 | 120 | fails=['BARBAZ FOO'], | ||
616 | 121 | included=[dict(constraint='STARTSWITH', value='FOO BAR')], | ||
617 | 122 | ignored=[dict(constraint='MATCHES', value='KUMQUAT')]) | ||
618 | 123 | |||
619 | 124 | |||
620 | 46 | class BaseTest(TestCase): | 125 | class BaseTest(TestCase): |
621 | 47 | 126 | ||
622 | 48 | def _get_request(self, path='/'): | 127 | def _get_request(self, path='/'): |
623 | @@ -99,7 +178,7 @@ | |||
624 | 99 | profiling_allowed='False', profile_all_requests='True', | 178 | profiling_allowed='False', profile_all_requests='True', |
625 | 100 | memory_profile_log='.') | 179 | memory_profile_log='.') |
626 | 101 | profile.start_request(self._get_start_event( | 180 | profile.start_request(self._get_start_event( |
628 | 102 | '/++profile++show,callgrind')) | 181 | '/++profile++show&callgrind')) |
629 | 103 | self.assertCleanProfilerState('config was ignored') | 182 | self.assertCleanProfilerState('config was ignored') |
630 | 104 | 183 | ||
631 | 105 | def test_optional_profiling_without_marked_request_has_no_profile(self): | 184 | def test_optional_profiling_without_marked_request_has_no_profile(self): |
632 | @@ -107,7 +186,7 @@ | |||
633 | 107 | # request. | 186 | # request. |
634 | 108 | self.pushProfilingConfig(profiling_allowed='True') | 187 | self.pushProfilingConfig(profiling_allowed='True') |
635 | 109 | profile.start_request(self._get_start_event('/')) | 188 | profile.start_request(self._get_start_event('/')) |
637 | 110 | self.assertEqual(profile._profilers.actions, set()) | 189 | self.assertEqual(profile._profilers.actions, {}) |
638 | 111 | self.assertIs(getattr(profile._profilers, 'profiler', None), None) | 190 | self.assertIs(getattr(profile._profilers, 'profiler', None), None) |
639 | 112 | self.assertIs( | 191 | self.assertIs( |
640 | 113 | getattr(profile._profilers, 'memory_profile_start', None), None) | 192 | getattr(profile._profilers, 'memory_profile_start', None), None) |
641 | @@ -121,7 +200,7 @@ | |||
642 | 121 | self.assertIs( | 200 | self.assertIs( |
643 | 122 | getattr(profile._profilers, 'memory_profile_start', None), | 201 | getattr(profile._profilers, 'memory_profile_start', None), |
644 | 123 | None) | 202 | None) |
646 | 124 | self.assertEquals(profile._profilers.actions, set(('show', ))) | 203 | self.assertEquals(set(profile._profilers.actions), set(('show', ))) |
647 | 125 | 204 | ||
648 | 126 | def test_optional_profiling_with_callgrind_request_starts_profiling(self): | 205 | def test_optional_profiling_with_callgrind_request_starts_profiling(self): |
649 | 127 | # If profiling is allowed and a request with the "callgrind" marker | 206 | # If profiling is allowed and a request with the "callgrind" marker |
650 | @@ -132,7 +211,8 @@ | |||
651 | 132 | self.assertIs( | 211 | self.assertIs( |
652 | 133 | getattr(profile._profilers, 'memory_profile_start', None), | 212 | getattr(profile._profilers, 'memory_profile_start', None), |
653 | 134 | None) | 213 | None) |
655 | 135 | self.assertEquals(profile._profilers.actions, set(('callgrind', ))) | 214 | self.assertEquals( |
656 | 215 | set(profile._profilers.actions), set(('callgrind', ))) | ||
657 | 136 | 216 | ||
658 | 137 | def test_optional_profiling_with_log_request_starts_profiling(self): | 217 | def test_optional_profiling_with_log_request_starts_profiling(self): |
659 | 138 | # If profiling is allowed and a request with the "log" marker URL | 218 | # If profiling is allowed and a request with the "log" marker URL |
660 | @@ -143,20 +223,21 @@ | |||
661 | 143 | self.assertIs( | 223 | self.assertIs( |
662 | 144 | getattr(profile._profilers, 'memory_profile_start', None), | 224 | getattr(profile._profilers, 'memory_profile_start', None), |
663 | 145 | None) | 225 | None) |
665 | 146 | self.assertEquals(profile._profilers.actions, set(('callgrind', ))) | 226 | self.assertEquals( |
666 | 227 | set(profile._profilers.actions), set(('callgrind', ))) | ||
667 | 147 | 228 | ||
668 | 148 | def test_optional_profiling_with_combined_request_starts_profiling(self): | 229 | def test_optional_profiling_with_combined_request_starts_profiling(self): |
669 | 149 | # If profiling is allowed and a request with the "callgrind" and | 230 | # If profiling is allowed and a request with the "callgrind" and |
670 | 150 | # "show" marker URL segment is made, profiling starts. | 231 | # "show" marker URL segment is made, profiling starts. |
671 | 151 | self.pushProfilingConfig(profiling_allowed='True') | 232 | self.pushProfilingConfig(profiling_allowed='True') |
672 | 152 | profile.start_request( | 233 | profile.start_request( |
674 | 153 | self._get_start_event('/++profile++callgrind,show/')) | 234 | self._get_start_event('/++profile++callgrind&show/')) |
675 | 154 | self.assertIsInstance(profile._profilers.profiler, profile.Profiler) | 235 | self.assertIsInstance(profile._profilers.profiler, profile.Profiler) |
676 | 155 | self.assertIs( | 236 | self.assertIs( |
677 | 156 | getattr(profile._profilers, 'memory_profile_start', None), | 237 | getattr(profile._profilers, 'memory_profile_start', None), |
678 | 157 | None) | 238 | None) |
679 | 158 | self.assertEquals( | 239 | self.assertEquals( |
681 | 159 | profile._profilers.actions, set(('callgrind', 'show'))) | 240 | set(profile._profilers.actions), set(('callgrind', 'show'))) |
682 | 160 | 241 | ||
683 | 161 | def test_optional_profiling_with_reversed_request_starts_profiling(self): | 242 | def test_optional_profiling_with_reversed_request_starts_profiling(self): |
684 | 162 | # If profiling is allowed and a request with the "show" and the | 243 | # If profiling is allowed and a request with the "show" and the |
685 | @@ -166,13 +247,13 @@ | |||
686 | 166 | # difference from the previous test. Also, it doesn't have a | 247 | # difference from the previous test. Also, it doesn't have a |
687 | 167 | # trailing slash. :-P | 248 | # trailing slash. :-P |
688 | 168 | profile.start_request( | 249 | profile.start_request( |
690 | 169 | self._get_start_event('/++profile++show,callgrind')) | 250 | self._get_start_event('/++profile++show&callgrind')) |
691 | 170 | self.assertIsInstance(profile._profilers.profiler, profile.Profiler) | 251 | self.assertIsInstance(profile._profilers.profiler, profile.Profiler) |
692 | 171 | self.assertIs( | 252 | self.assertIs( |
693 | 172 | getattr(profile._profilers, 'memory_profile_start', None), | 253 | getattr(profile._profilers, 'memory_profile_start', None), |
694 | 173 | None) | 254 | None) |
695 | 174 | self.assertEquals( | 255 | self.assertEquals( |
697 | 175 | profile._profilers.actions, set(('callgrind', 'show'))) | 256 | set(profile._profilers.actions), set(('callgrind', 'show'))) |
698 | 176 | 257 | ||
699 | 177 | def test_optional_profiling_with_pstats_request_starts_profiling(self): | 258 | def test_optional_profiling_with_pstats_request_starts_profiling(self): |
700 | 178 | # If profiling is allowed and a request with the "pstats" marker, | 259 | # If profiling is allowed and a request with the "pstats" marker, |
701 | @@ -185,7 +266,7 @@ | |||
702 | 185 | self.assertIs( | 266 | self.assertIs( |
703 | 186 | getattr(profile._profilers, 'memory_profile_start', None), | 267 | getattr(profile._profilers, 'memory_profile_start', None), |
704 | 187 | None) | 268 | None) |
706 | 188 | self.assertEquals(profile._profilers.actions, set(('pstats',))) | 269 | self.assertEquals(set(profile._profilers.actions), set(('pstats',))) |
707 | 189 | 270 | ||
708 | 190 | def test_optional_profiling_with_log_pstats(self): | 271 | def test_optional_profiling_with_log_pstats(self): |
709 | 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" |
710 | @@ -193,13 +274,13 @@ | |||
711 | 193 | # and pstats request. | 274 | # and pstats request. |
712 | 194 | self.pushProfilingConfig(profiling_allowed='True') | 275 | self.pushProfilingConfig(profiling_allowed='True') |
713 | 195 | profile.start_request( | 276 | profile.start_request( |
715 | 196 | self._get_start_event('/++profile++log,pstats/')) | 277 | self._get_start_event('/++profile++log&pstats/')) |
716 | 197 | self.assertIsInstance(profile._profilers.profiler, profile.Profiler) | 278 | self.assertIsInstance(profile._profilers.profiler, profile.Profiler) |
717 | 198 | self.assertIs( | 279 | self.assertIs( |
718 | 199 | getattr(profile._profilers, 'memory_profile_start', None), | 280 | getattr(profile._profilers, 'memory_profile_start', None), |
719 | 200 | None) | 281 | None) |
720 | 201 | self.assertEquals( | 282 | self.assertEquals( |
722 | 202 | profile._profilers.actions, set(('callgrind', 'pstats',))) | 283 | set(profile._profilers.actions), set(('callgrind', 'pstats',))) |
723 | 203 | 284 | ||
724 | 204 | def test_optional_profiling_with_callgrind_pstats(self): | 285 | def test_optional_profiling_with_callgrind_pstats(self): |
725 | 205 | # If profiling is allowed and a request with both the "pstats" and | 286 | # If profiling is allowed and a request with both the "pstats" and |
726 | @@ -207,14 +288,14 @@ | |||
727 | 207 | # profiler. | 288 | # profiler. |
728 | 208 | self.pushProfilingConfig(profiling_allowed='True') | 289 | self.pushProfilingConfig(profiling_allowed='True') |
729 | 209 | profile.start_request( | 290 | profile.start_request( |
731 | 210 | self._get_start_event('/++profile++pstats,callgrind/')) | 291 | self._get_start_event('/++profile++pstats&callgrind/')) |
732 | 211 | self.assertIsInstance(profile._profilers.profiler, | 292 | self.assertIsInstance(profile._profilers.profiler, |
733 | 212 | profile.Profiler) | 293 | profile.Profiler) |
734 | 213 | self.assertIs( | 294 | self.assertIs( |
735 | 214 | getattr(profile._profilers, 'memory_profile_start', None), | 295 | getattr(profile._profilers, 'memory_profile_start', None), |
736 | 215 | None) | 296 | None) |
737 | 216 | self.assertEquals( | 297 | self.assertEquals( |
739 | 217 | profile._profilers.actions, set(('pstats', 'callgrind'))) | 298 | set(profile._profilers.actions), set(('pstats', 'callgrind'))) |
740 | 218 | 299 | ||
741 | 219 | def test_forced_profiling_registers_action(self): | 300 | def test_forced_profiling_registers_action(self): |
742 | 220 | # profile_all_requests should register as a callgrind action. | 301 | # profile_all_requests should register as a callgrind action. |
743 | @@ -225,7 +306,8 @@ | |||
744 | 225 | self.assertIs( | 306 | self.assertIs( |
745 | 226 | getattr(profile._profilers, 'memory_profile_start', None), | 307 | getattr(profile._profilers, 'memory_profile_start', None), |
746 | 227 | None) | 308 | None) |
748 | 228 | self.assertEquals(profile._profilers.actions, set(('callgrind', ))) | 309 | self.assertEquals( |
749 | 310 | set(profile._profilers.actions), set(('callgrind', ))) | ||
750 | 229 | 311 | ||
751 | 230 | def test_optional_profiling_with_wrong_request_helps(self): | 312 | def test_optional_profiling_with_wrong_request_helps(self): |
752 | 231 | # If profiling is allowed and a request with the marker URL segment | 313 | # If profiling is allowed and a request with the marker URL segment |
753 | @@ -236,7 +318,7 @@ | |||
754 | 236 | self.assertIs( | 318 | self.assertIs( |
755 | 237 | getattr(profile._profilers, 'memory_profile_start', None), | 319 | getattr(profile._profilers, 'memory_profile_start', None), |
756 | 238 | None) | 320 | None) |
758 | 239 | self.assertEquals(profile._profilers.actions, set(('help', ))) | 321 | self.assertEquals(set(profile._profilers.actions), set(('help', ))) |
759 | 240 | 322 | ||
760 | 241 | def test_forced_profiling_with_wrong_request_helps(self): | 323 | def test_forced_profiling_with_wrong_request_helps(self): |
761 | 242 | # If profiling is forced and a request with the marker URL segment | 324 | # If profiling is forced and a request with the marker URL segment |
762 | @@ -249,7 +331,7 @@ | |||
763 | 249 | getattr(profile._profilers, 'memory_profile_start', None), | 331 | getattr(profile._profilers, 'memory_profile_start', None), |
764 | 250 | None) | 332 | None) |
765 | 251 | self.assertEquals( | 333 | self.assertEquals( |
767 | 252 | profile._profilers.actions, set(('help', 'callgrind'))) | 334 | set(profile._profilers.actions), set(('help', 'callgrind'))) |
768 | 253 | 335 | ||
769 | 254 | def test_memory_profile_start(self): | 336 | def test_memory_profile_start(self): |
770 | 255 | self.pushProfilingConfig( | 337 | self.pushProfilingConfig( |
771 | @@ -258,7 +340,7 @@ | |||
772 | 258 | self.assertIs(getattr(profile._profilers, 'profiler', None), None) | 340 | self.assertIs(getattr(profile._profilers, 'profiler', None), None) |
773 | 259 | self.assertIsInstance(profile._profilers.memory_profile_start, tuple) | 341 | self.assertIsInstance(profile._profilers.memory_profile_start, tuple) |
774 | 260 | self.assertEqual(len(profile._profilers.memory_profile_start), 2) | 342 | self.assertEqual(len(profile._profilers.memory_profile_start), 2) |
776 | 261 | self.assertEqual(profile._profilers.actions, set()) | 343 | self.assertEqual(profile._profilers.actions, {}) |
777 | 262 | 344 | ||
778 | 263 | def test_combo_memory_and_profile_start(self): | 345 | def test_combo_memory_and_profile_start(self): |
779 | 264 | self.pushProfilingConfig( | 346 | self.pushProfilingConfig( |
780 | @@ -267,13 +349,30 @@ | |||
781 | 267 | self.assertIsInstance(profile._profilers.profiler, profile.Profiler) | 349 | self.assertIsInstance(profile._profilers.profiler, profile.Profiler) |
782 | 268 | self.assertIsInstance(profile._profilers.memory_profile_start, tuple) | 350 | self.assertIsInstance(profile._profilers.memory_profile_start, tuple) |
783 | 269 | self.assertEqual(len(profile._profilers.memory_profile_start), 2) | 351 | self.assertEqual(len(profile._profilers.memory_profile_start), 2) |
785 | 270 | self.assertEquals(profile._profilers.actions, set(('show', ))) | 352 | self.assertEquals(set(profile._profilers.actions), set(('show', ))) |
786 | 271 | 353 | ||
787 | 272 | def test_sqltrace_start(self): | 354 | def test_sqltrace_start(self): |
788 | 273 | self.pushProfilingConfig(profiling_allowed='True') | 355 | self.pushProfilingConfig(profiling_allowed='True') |
789 | 274 | profile.start_request(self._get_start_event('/++profile++sqltrace/')) | 356 | profile.start_request(self._get_start_event('/++profile++sqltrace/')) |
790 | 275 | self.assertIs(getattr(profile._profilers, 'profiler', None), None) | 357 | self.assertIs(getattr(profile._profilers, 'profiler', None), None) |
792 | 276 | self.assertEquals(profile._profilers.actions, set(('sqltrace', ))) | 358 | self.assertEquals(profile._profilers.actions, dict(sql=True)) |
793 | 359 | self.assertEqual([], da.stop_sql_logging()) | ||
794 | 360 | |||
795 | 361 | def test_sql_start(self): | ||
796 | 362 | self.pushProfilingConfig(profiling_allowed='True') | ||
797 | 363 | profile.start_request(self._get_start_event('/++profile++sql/')) | ||
798 | 364 | self.assertIs(getattr(profile._profilers, 'profiler', None), None) | ||
799 | 365 | self.assertEquals(profile._profilers.actions, dict(sql=False)) | ||
800 | 366 | self.assertEqual([], da.stop_sql_logging()) | ||
801 | 367 | |||
802 | 368 | def test_sqltrace_filtered_start(self): | ||
803 | 369 | self.pushProfilingConfig(profiling_allowed='True') | ||
804 | 370 | profile.start_request(self._get_start_event( | ||
805 | 371 | '/++profile++sqltrace:includes bugsubscription/')) | ||
806 | 372 | self.assertIs(getattr(profile._profilers, 'profiler', None), None) | ||
807 | 373 | self.assertEquals(set(profile._profilers.actions), set(('sql', ))) | ||
808 | 374 | data = profile._profilers.actions['sql'] | ||
809 | 375 | self.assertTrue(data['condition']('SELECT BUGSUBSCRIPTION FROM FOO')) | ||
810 | 277 | self.assertEqual([], da.stop_sql_logging()) | 376 | self.assertEqual([], da.stop_sql_logging()) |
811 | 278 | 377 | ||
812 | 279 | 378 | ||
813 | @@ -380,7 +479,7 @@ | |||
814 | 380 | self.pushProfilingConfig( | 479 | self.pushProfilingConfig( |
815 | 381 | profiling_allowed='False', profile_all_requests='True', | 480 | profiling_allowed='False', profile_all_requests='True', |
816 | 382 | memory_profile_log=self.memory_profile_log) | 481 | memory_profile_log=self.memory_profile_log) |
818 | 383 | request = self.endRequest('/++profile++show,callgrind') | 482 | request = self.endRequest('/++profile++show&callgrind') |
819 | 384 | self.assertIs(getattr(request, 'oops', None), None) | 483 | self.assertIs(getattr(request, 'oops', None), None) |
820 | 385 | self.assertEqual(self.getAddedResponse(request), '') | 484 | self.assertEqual(self.getAddedResponse(request), '') |
821 | 386 | self.assertEqual(self.getMemoryLog(), []) | 485 | self.assertEqual(self.getMemoryLog(), []) |
822 | @@ -469,7 +568,7 @@ | |||
823 | 469 | # If profiling is allowed and a request with the "callgrind" and | 568 | # If profiling is allowed and a request with the "callgrind" and |
824 | 470 | # "show" marker URL segment is made, profiling starts. | 569 | # "show" marker URL segment is made, profiling starts. |
825 | 471 | self.pushProfilingConfig(profiling_allowed='True') | 570 | self.pushProfilingConfig(profiling_allowed='True') |
827 | 472 | request = self.endRequest('/++profile++callgrind,show') | 571 | request = self.endRequest('/++profile++callgrind&show') |
828 | 473 | self.assertProfilePaths( | 572 | self.assertProfilePaths( |
829 | 474 | self.assertBasicProfileExists(request, show=True)) | 573 | self.assertBasicProfileExists(request, show=True)) |
830 | 475 | 574 | ||
831 | @@ -499,7 +598,7 @@ | |||
832 | 499 | # "pstats" markers is made, profiling starts with the callgrind | 598 | # "pstats" markers is made, profiling starts with the callgrind |
833 | 500 | # approach only. | 599 | # approach only. |
834 | 501 | self.pushProfilingConfig(profiling_allowed='True') | 600 | self.pushProfilingConfig(profiling_allowed='True') |
836 | 502 | request = self.endRequest('/++profile++callgrind,pstats/') | 601 | request = self.endRequest('/++profile++callgrind&pstats/') |
837 | 503 | self.assertBothProfiles(self.assertBasicProfileExists(request)) | 602 | self.assertBothProfiles(self.assertBasicProfileExists(request)) |
838 | 504 | # We had a bug in which the callgrind file was actually a pstats | 603 | # We had a bug in which the callgrind file was actually a pstats |
839 | 505 | # file. What we can do minimally to prevent this in the future is | 604 | # file. What we can do minimally to prevent this in the future is |
840 | @@ -606,14 +705,14 @@ | |||
841 | 606 | profiling_allowed='False', profile_all_requests='True', | 705 | profiling_allowed='False', profile_all_requests='True', |
842 | 607 | memory_profile_log='.') | 706 | memory_profile_log='.') |
843 | 608 | event = BeforeTraverseEvent(None, | 707 | event = BeforeTraverseEvent(None, |
845 | 609 | self._get_request('/++profile++show,callgrind')) | 708 | self._get_request('/++profile++show&callgrind')) |
846 | 610 | with FeatureFixture({'profiling.enabled': 'on'}): | 709 | with FeatureFixture({'profiling.enabled': 'on'}): |
847 | 611 | profile.before_traverse(event) | 710 | profile.before_traverse(event) |
848 | 612 | self.assertTrue(profile._profilers.profiling) | 711 | self.assertTrue(profile._profilers.profiling) |
849 | 613 | self.assertIsInstance( | 712 | self.assertIsInstance( |
850 | 614 | profile._profilers.profiler, profile.Profiler) | 713 | profile._profilers.profiler, profile.Profiler) |
851 | 615 | self.assertEquals( | 714 | self.assertEquals( |
853 | 616 | set(('show', 'callgrind')), profile._profilers.actions) | 715 | set(('show', 'callgrind')), set(profile._profilers.actions)) |
854 | 617 | 716 | ||
855 | 618 | 717 | ||
856 | 619 | class TestInlineProfiling(BaseRequestEndHandlerTest): | 718 | class TestInlineProfiling(BaseRequestEndHandlerTest): |
857 | @@ -643,7 +742,7 @@ | |||
858 | 643 | # ++profile++ wins over inline. | 742 | # ++profile++ wins over inline. |
859 | 644 | self.pushProfilingConfig(profiling_allowed='True') | 743 | self.pushProfilingConfig(profiling_allowed='True') |
860 | 645 | request = self.endRequest( | 744 | request = self.endRequest( |
862 | 646 | '/++profile++show,callgrind', work=self.make_work()) | 745 | '/++profile++show&callgrind', work=self.make_work()) |
863 | 647 | response = self.assertBasicProfileExists(request, show=True) | 746 | response = self.assertBasicProfileExists(request, show=True) |
864 | 648 | self.assertCallgrindProfile(response) | 747 | self.assertCallgrindProfile(response) |
865 | 649 | self.assertIn('Inline request ignored', response) | 748 | self.assertIn('Inline request ignored', response) |
866 | @@ -658,12 +757,23 @@ | |||
867 | 658 | self.assertBasicProfileExists(request, show=True)) | 757 | self.assertBasicProfileExists(request, show=True)) |
868 | 659 | 758 | ||
869 | 660 | 759 | ||
871 | 661 | class TestSqlTrace(TestCaseWithFactory, BaseRequestEndHandlerTest): | 760 | class TestSqlLogging(TestCaseWithFactory, BaseRequestEndHandlerTest): |
872 | 662 | 761 | ||
873 | 663 | layer = layers.DatabaseFunctionalLayer | 762 | layer = layers.DatabaseFunctionalLayer |
874 | 664 | 763 | ||
875 | 665 | def testLogging(self): | 764 | def testLogging(self): |
877 | 666 | # This is basically a smoketest. The underlying machinery has tests. | 765 | self.pushProfilingConfig(profiling_allowed='True') |
878 | 766 | request = self.endRequest( | ||
879 | 767 | '/++profile++sql/', work=self.factory.makeBug) | ||
880 | 768 | response = self.getAddedResponse(request) | ||
881 | 769 | self.assertIn('Top 10 SQL times', response) | ||
882 | 770 | self.assertIn('Query number', response) | ||
883 | 771 | self.assertIn('Top 10 Python times', response) | ||
884 | 772 | self.assertIn('Before query', response) | ||
885 | 773 | self.assertTrue('Repeated Python SQL Triggers' not in response) | ||
886 | 774 | self.assertTrue('Show all tracebacks' not in response) | ||
887 | 775 | |||
888 | 776 | def testTraceLogging(self): | ||
889 | 667 | self.pushProfilingConfig(profiling_allowed='True') | 777 | self.pushProfilingConfig(profiling_allowed='True') |
890 | 668 | request = self.endRequest( | 778 | request = self.endRequest( |
891 | 669 | '/++profile++sqltrace/', work=self.factory.makeBug) | 779 | '/++profile++sqltrace/', work=self.factory.makeBug) |
892 | @@ -676,3 +786,21 @@ | |||
893 | 676 | self.assertIn('Show all tracebacks', response) | 786 | self.assertIn('Show all tracebacks', response) |
894 | 677 | # This file should be part of several of the tracebacks. | 787 | # This file should be part of several of the tracebacks. |
895 | 678 | self.assertIn(__file__.replace('.pyc', '.py'), response) | 788 | self.assertIn(__file__.replace('.pyc', '.py'), response) |
896 | 789 | |||
897 | 790 | def testTraceLoggingConditionally(self): | ||
898 | 791 | self.pushProfilingConfig(profiling_allowed='True') | ||
899 | 792 | request = self.endRequest( | ||
900 | 793 | '/++profile++sqltrace:includes SELECT/', | ||
901 | 794 | work=self.factory.makeBug) | ||
902 | 795 | response = self.getAddedResponse(request) | ||
903 | 796 | self.assertIn('Top 10 SQL times', response) | ||
904 | 797 | self.assertIn('Query number', response) | ||
905 | 798 | self.assertIn('Top 10 Python times', response) | ||
906 | 799 | self.assertIn('Before query', response) | ||
907 | 800 | self.assertIn('Repeated Python SQL Triggers', response) | ||
908 | 801 | self.assertIn('Show all tracebacks', response) | ||
909 | 802 | self.assertIn( | ||
910 | 803 | 'You have requested tracebacks for statements that match only', | ||
911 | 804 | response) | ||
912 | 805 | # This file should be part of several of the tracebacks. | ||
913 | 806 | self.assertIn(__file__.replace('.pyc', '.py'), response) |
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' services/ profile/ profile. pt 2011-08-22 17:08:02 +0000 services/ profile/ profile. pt 2011-09-01 17:17:32 +0000 +profile+ +show</ code>.< /tal:block> <tal:block condition="not: ++profile+ +show</ code>), a KCacheGrind- friendly log on the ++profile+ +show</ code>), a KCacheGrind- friendly log on the ++profile+ +callgrind< /code>) , a PStats-friendly log ++profile+ +pstats< /code>) , or an HTML view of the SQL and the ++profile+ +pstats< /code>) , an HTML view of the SQL and the ++profile+ +sqltrace< /code>) . You can also combine these ++profile+ +show,callgrind </code> or +profile+ +show,pstats< /code> or others, .</tal: block>< /p> ++profile+ +sqltrace< /code>) , or an HTML view of only the SQL ++profile+ +sql</code> ). You can also combine these ++profile+ +show&callgrind </code> or +profile+ +show&pstats< /code> or others, with each action separated .</tal: block>< /p>
> --- lib/lp/
> +++ lib/lp/
> @@ -64,15 +64,21 @@
> get immediate profiling results in the browser, use
> <code>+
> always_log">In order to get profiling results, you need to ask for an HTML
> - view (<code>
> + view of the profile and OOPS data including SQL calls
> + (<code>
> filesystem (<code>
> (Python standard library) on the filesystem
> - (<code>
> + (<code>
> Python stacktrace when each SQL call was made
> - (<code>
> - (<code>
> - <code>+
> - with each action separated with commas)
> + (<code>
> + (<code>
> + (<code>
> + <code>+
> + with commas)
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' ).lower( ) for item in actions.split(',')) ).lower( ).partition( ':')
> @@ -505,24 +521,108 @@
> # include traversal in the profile.
> actions, slash, tail = end.partition('/')
> result.update(
> - action for action in (
> - item.strip(
> - if action)
> + (name.strip(), config.strip())
> + for name, partition, config in (
> + item.strip(
> + 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