Merge lp:~cjwatson/launchpad/remove-tickcount into lp:launchpad
- remove-tickcount
- Merge into devel
Status: | Rejected |
---|---|
Rejected by: | Colin Watson |
Proposed branch: | lp:~cjwatson/launchpad/remove-tickcount |
Merge into: | lp:launchpad |
Diff against target: |
601 lines (+214/-116) 3 files modified
lib/lp/services/webapp/doc/webapp-publication.txt (+129/-75) lib/lp/services/webapp/publication.py (+78/-34) lib/lp/services/webapp/servers.py (+7/-7) |
To merge this branch: | bzr merge lp:~cjwatson/launchpad/remove-tickcount |
Related bugs: |
Reviewer | Review Type | Date Requested | Status |
---|---|---|---|
Launchpad code reviewers | Pending | ||
Review via email: mp+373347@code.launchpad.net |
Commit message
Remove tickcount and track traversal/
Description of the change
tickcount can't work on Python 3, so in the long term we don't have much choice here. We do want to be able to spot contention, but tracking thread time should be enough here. (Unfortunately, as far as I can tell this is only possible with Python >= 3.3.)
This does change the access log format slightly (logging durations rather than ticks), but as far as I can tell nothing cares.
Colin Watson (cjwatson) wrote : | # |
Unmerged revisions
- 19064. By Colin Watson
-
Remove tickcount and track traversal/
publication durations instead. tickcount can't work on Python 3, so in the long term we don't have much
choice here. We do want to be able to spot contention, but tracking thread
time should be enough here. (Unfortunately, as far as I can tell this is
only possible with Python >= 3.3.)This does change the access log format slightly (logging durations rather
than ticks), but as far as I can tell nothing cares.
Preview Diff
1 | === modified file 'lib/lp/services/webapp/doc/webapp-publication.txt' |
2 | --- lib/lp/services/webapp/doc/webapp-publication.txt 2019-05-22 14:57:45 +0000 |
3 | +++ lib/lp/services/webapp/doc/webapp-publication.txt 2019-09-27 22:43:03 +0000 |
4 | @@ -621,52 +621,62 @@ |
5 | TestContext:TestView |
6 | |
7 | |
8 | -Tick counts |
9 | ------------ |
10 | +Durations |
11 | +--------- |
12 | |
13 | Similarly to our page IDs, our publication implementation will store the |
14 | -tick counts for the traversal and object publication processes in WSGI |
15 | +durations for the traversal and object publication processes in WSGI |
16 | variables which aren't set originally. |
17 | |
18 | - >>> import tickcount |
19 | + >>> import time |
20 | >>> request, publication = get_request_and_publication() |
21 | >>> request.setPrincipal(auth_utility.unauthenticatedPrincipal()) |
22 | >>> logout() |
23 | |
24 | -For traversal we start counting the ticks during the beforeTraversal() |
25 | -hook and stop the count in afterTraversal(). The tick count is then |
26 | -available as launchpad.traversalticks in the WSGI environment. |
27 | +For traversal we start counting the duration during the beforeTraversal() |
28 | +hook and stop the count in afterTraversal(). The duration is then available |
29 | +as launchpad.traversalduration in the WSGI environment. On Python >= 3.3, |
30 | +there is also launchpad.traversalthreadduration with the time spent in the |
31 | +current thread. |
32 | |
33 | - >>> 'launchpad.traversalticks' in request._orig_env |
34 | + >>> 'launchpad.traversalduration' in request._orig_env |
35 | + False |
36 | + >>> 'launchpad.traversalthreadduration' in request._orig_env |
37 | False |
38 | >>> publication.beforeTraversal(request) |
39 | - >>> tickcount.difference( |
40 | - ... request._traversalticks_start, tickcount.tickcount()) > 0 |
41 | - True |
42 | - |
43 | >>> publication.afterTraversal(request, None) |
44 | - >>> request._orig_env['launchpad.traversalticks'] < 200 |
45 | - True |
46 | - |
47 | -For publication we start counting the ticks during the callObject() |
48 | -hook and stop the count in afterCall(). The tick count is then |
49 | -available as launchpad.publicationticks in the WSGI environment. |
50 | - |
51 | - >>> 'launchpad.publicationticks' in request._orig_env |
52 | + >>> 'launchpad.traversalduration' in request._orig_env |
53 | + True |
54 | + >>> if hasattr(time, 'CLOCK_THREAD_CPUTIME_ID'): |
55 | + ... 'launchpad.traversalthreadduration' in request._orig_env |
56 | + ... else: |
57 | + ... True |
58 | + True |
59 | + |
60 | +For publication we start counting the duration during the callObject() |
61 | +hook and stop the count in afterCall(). The duration is then available as |
62 | +launchpad.publicationduration in the WSGI environment. On Python >= 3.3, |
63 | +there is also launchpad.publicationthreadduration with the time spent in the |
64 | +current thread. |
65 | + |
66 | + >>> 'launchpad.publicationduration' in request._orig_env |
67 | + False |
68 | + >>> 'launchpad.publicationthreadduration' in request._orig_env |
69 | False |
70 | >>> publication.callObject(request, TestView(TestContext(), request)) |
71 | u'Result' |
72 | - >>> tickcount.difference( |
73 | - ... request._publicationticks_start, tickcount.tickcount()) > 0 |
74 | - True |
75 | - |
76 | >>> publication.afterCall(request, None) |
77 | - >>> request._orig_env['launchpad.publicationticks'] < 60 |
78 | + >>> 'launchpad.publicationduration' in request._orig_env |
79 | + True |
80 | + >>> if hasattr(time, 'CLOCK_THREAD_CPUTIME_ID'): |
81 | + ... 'launchpad.publicationthreadduration' in request._orig_env |
82 | + ... else: |
83 | + ... True |
84 | True |
85 | >>> publication.endRequest(request, None) |
86 | |
87 | If an exception is raised during traversal or object publication, we'll |
88 | -store the ticks up to the point in which the exception is raised. This |
89 | +store the durations up to the point in which the exception is raised. This |
90 | is done inside the handleException() hook. (The hook also sets and resets |
91 | the request timer from lp.services.webapp.adapter, so you'll notice |
92 | some calls to prepare that code to what handleException expects.) |
93 | @@ -687,26 +697,37 @@ |
94 | >>> set_request_started() |
95 | >>> publication.handleException( |
96 | ... None, request, exc_info, retry_allowed=False) |
97 | - >>> 'launchpad.traversalticks' in request._orig_env |
98 | - False |
99 | - >>> 'launchpad.publicationticks' in request._orig_env |
100 | + >>> 'launchpad.traversalduration' in request._orig_env |
101 | + False |
102 | + >>> 'launchpad.traversalthreadduration' in request._orig_env |
103 | + False |
104 | + >>> 'launchpad.publicationduration' in request._orig_env |
105 | + False |
106 | + >>> 'launchpad.publicationthreadduration' in request._orig_env |
107 | False |
108 | >>> clear_request_started() |
109 | |
110 | If we started the traversal, but haven't finished it, we'll only have |
111 | -the ticks for the traversal and not for the publication. |
112 | +the duration for the traversal and not for the publication. |
113 | |
114 | >>> publication.beforeTraversal(request) |
115 | >>> publication.handleException( |
116 | ... None, request, exc_info, retry_allowed=False) |
117 | - >>> request._orig_env['launchpad.traversalticks'] < 200 |
118 | - True |
119 | - >>> 'launchpad.publicationticks' in request._orig_env |
120 | + >>> 'launchpad.traversalduration' in request._orig_env |
121 | + True |
122 | + >>> if hasattr(time, 'CLOCK_THREAD_CPUTIME_ID'): |
123 | + ... 'launchpad.traversalthreadduration' in request._orig_env |
124 | + ... else: |
125 | + ... True |
126 | + True |
127 | + >>> 'launchpad.publicationduration' in request._orig_env |
128 | + False |
129 | + >>> 'launchpad.publicationthreadduration' in request._orig_env |
130 | False |
131 | >>> clear_request_started() |
132 | |
133 | If we started the publication (which means the traversal has been |
134 | -completed), we'll have the ticks for the traversal and the ticks for |
135 | +completed), we'll have the duration for the traversal and the duration for |
136 | the publication, up to the point where it was forcefully stopped. |
137 | |
138 | >>> publication.afterTraversal(request, None) |
139 | @@ -715,22 +736,34 @@ |
140 | >>> set_request_started() |
141 | >>> publication.handleException( |
142 | ... None, request, exc_info, retry_allowed=False) |
143 | - >>> request._orig_env['launchpad.traversalticks'] < 500 |
144 | - True |
145 | - >>> request._orig_env['launchpad.publicationticks'] < 50 |
146 | + >>> 'launchpad.traversalduration' in request._orig_env |
147 | + True |
148 | + >>> if hasattr(time, 'CLOCK_THREAD_CPUTIME_ID'): |
149 | + ... 'launchpad.traversalthreadduration' in request._orig_env |
150 | + ... else: |
151 | + ... True |
152 | + True |
153 | + >>> 'launchpad.publicationduration' in request._orig_env |
154 | + True |
155 | + >>> if hasattr(time, 'CLOCK_THREAD_CPUTIME_ID'): |
156 | + ... 'launchpad.publicationthreadduration' in request._orig_env |
157 | + ... else: |
158 | + ... True |
159 | True |
160 | >>> publication.endRequest(request, None) |
161 | >>> logger.setLevel(old_level) |
162 | |
163 | When a Retry or DisconnectionError exception is raised and the request |
164 | supports retry, it will be retried with a copy of the WSGI environment. |
165 | -If that happens, though, we'll remove the [publication,traversal]ticks |
166 | -variables from there. |
167 | +If that happens, though, we'll remove the |
168 | +{publication,traversal}{,thread}duration variables from there. |
169 | |
170 | >>> request, publication = get_request_and_publication() |
171 | >>> request.setPrincipal(auth_utility.unauthenticatedPrincipal()) |
172 | - >>> request._orig_env['launchpad.traversalticks'] = 500 |
173 | - >>> request._orig_env['launchpad.publicationticks'] = 500 |
174 | + >>> request._orig_env['launchpad.traversalduration'] = 0.5 |
175 | + >>> request._orig_env['launchpad.traversalthreadduration'] = 0.4 |
176 | + >>> request._orig_env['launchpad.publicationduration'] = 0.5 |
177 | + >>> request._orig_env['launchpad.publicationthreadduration'] = 0.4 |
178 | >>> request.supportsRetry() |
179 | True |
180 | >>> from zope.publisher.interfaces import Retry |
181 | @@ -744,15 +777,21 @@ |
182 | ... |
183 | Retry: foo |
184 | |
185 | - >>> 'launchpad.publicationticks' in request._orig_env |
186 | - False |
187 | - >>> 'launchpad.traversalticks' in request._orig_env |
188 | + >>> 'launchpad.publicationduration' in request._orig_env |
189 | + False |
190 | + >>> 'launchpad.publicationthreadduration' in request._orig_env |
191 | + False |
192 | + >>> 'launchpad.traversalduration' in request._orig_env |
193 | + False |
194 | + >>> 'launchpad.traversalthreadduration' in request._orig_env |
195 | False |
196 | |
197 | >>> request, publication = get_request_and_publication() |
198 | >>> request.setPrincipal(auth_utility.unauthenticatedPrincipal()) |
199 | - >>> request._orig_env['launchpad.traversalticks'] = 500 |
200 | - >>> request._orig_env['launchpad.publicationticks'] = 500 |
201 | + >>> request._orig_env['launchpad.traversalduration'] = 0.5 |
202 | + >>> request._orig_env['launchpad.traversalthreadduration'] = 0.4 |
203 | + >>> request._orig_env['launchpad.publicationduration'] = 0.5 |
204 | + >>> request._orig_env['launchpad.publicationthreadduration'] = 0.4 |
205 | >>> request.supportsRetry() |
206 | True |
207 | >>> from storm.exceptions import DisconnectionError |
208 | @@ -766,19 +805,25 @@ |
209 | ... |
210 | Retry: foo DisconnectionError |
211 | |
212 | - >>> 'launchpad.publicationticks' in request._orig_env |
213 | - False |
214 | - >>> 'launchpad.traversalticks' in request._orig_env |
215 | + >>> 'launchpad.publicationduration' in request._orig_env |
216 | + False |
217 | + >>> 'launchpad.publicationthreadduration' in request._orig_env |
218 | + False |
219 | + >>> 'launchpad.traversalduration' in request._orig_env |
220 | + False |
221 | + >>> 'launchpad.traversalthreadduration' in request._orig_env |
222 | False |
223 | |
224 | Of course, any request can only be retried a certain number of times and |
225 | -when we reach that number of retries we don't pop the tick conts from the |
226 | +when we reach that number of retries we don't pop the durations from the |
227 | WSGI env. |
228 | |
229 | >>> request, publication = get_request_and_publication() |
230 | >>> request.setPrincipal(auth_utility.unauthenticatedPrincipal()) |
231 | - >>> request._orig_env['launchpad.traversalticks'] = 500 |
232 | - >>> request._orig_env['launchpad.publicationticks'] = 500 |
233 | + >>> request._orig_env['launchpad.traversalduration'] = 0.5 |
234 | + >>> request._orig_env['launchpad.traversalthreadduration'] = 0.4 |
235 | + >>> request._orig_env['launchpad.publicationduration'] = 0.5 |
236 | + >>> request._orig_env['launchpad.publicationthreadduration'] = 0.4 |
237 | >>> request.supportsRetry = lambda: False |
238 | >>> request.supportsRetry() |
239 | False |
240 | @@ -792,10 +837,14 @@ |
241 | ... |
242 | Retry: foo |
243 | |
244 | - >>> request._orig_env['launchpad.publicationticks'] |
245 | - 500 |
246 | - >>> request._orig_env['launchpad.traversalticks'] |
247 | - 500 |
248 | + >>> request._orig_env['launchpad.publicationduration'] |
249 | + 0.5 |
250 | + >>> request._orig_env['launchpad.publicationthreadduration'] |
251 | + 0.4 |
252 | + >>> request._orig_env['launchpad.traversalduration'] |
253 | + 0.5 |
254 | + >>> request._orig_env['launchpad.traversalthreadduration'] |
255 | + 0.4 |
256 | |
257 | (A bit of cleanup so the test can continue) |
258 | |
259 | @@ -818,11 +867,12 @@ |
260 | >>> print request.principal |
261 | None |
262 | |
263 | - # Our afterCall() implementation expects to find a |
264 | - # _publicationticks_start in its request, which is set by |
265 | + # Our afterCall() implementation expects to find _publication_start and |
266 | + # _publication_thread_start in its request, which are set by |
267 | # callObject(). Since we don't want to callObject() here, we'll |
268 | # have to change the request manually. |
269 | - >>> request._publicationticks_start = 1345 |
270 | + >>> request._publication_start = 1.345 |
271 | + >>> request._publication_thread_start = None |
272 | >>> publication.afterCall(request, None) |
273 | >>> txn.user |
274 | '' |
275 | @@ -883,11 +933,12 @@ |
276 | |
277 | >>> request, publication = get_request_and_publication(method='GET') |
278 | |
279 | - # Our afterCall() implementation expects to find a |
280 | - # _publicationticks_start in its request, which is set by |
281 | + # Our afterCall() implementation expects to find _publication_start and |
282 | + # _publication_thread_start in its request, which are set by |
283 | # callObject(). Since we don't want to callObject() here, we'll |
284 | # have to change the request manually. |
285 | - >>> request._publicationticks_start = 1345 |
286 | + >>> request._publication_start = 1.345 |
287 | + >>> request._publication_thread_start = None |
288 | >>> publication.afterCall(request, None) |
289 | >>> txn = transaction.begin() |
290 | >>> foo_bar = get_foo_bar_person() |
291 | @@ -901,11 +952,12 @@ |
292 | |
293 | >>> request, publication = get_request_and_publication(method='POST') |
294 | |
295 | - # Our afterCall() implementation expects to find a |
296 | - # _publicationticks_start in its request, which is set by |
297 | + # Our afterCall() implementation expects to find _publication_start and |
298 | + # _publication_thread_start in its request, which are set by |
299 | # callObject(). Since we don't want to callObject() here, we'll |
300 | # have to change the request manually. |
301 | - >>> request._publicationticks_start = 1345 |
302 | + >>> request._publication_start = 1.345 |
303 | + >>> request._publication_thread_start = None |
304 | >>> publication.afterCall(request, None) |
305 | >>> txn = transaction.begin() |
306 | >>> print get_foo_bar_person().description |
307 | @@ -934,11 +986,12 @@ |
308 | >>> txn.isDoomed() |
309 | True |
310 | |
311 | - # Our afterCall() implementation expects to find a |
312 | - # _publicationticks_start in its request, which is set by |
313 | + # Our afterCall() implementation expects to find _publication_start and |
314 | + # _publication_thread_start in its request, which are set by |
315 | # callObject(). Since we don't want to callObject() here, we'll |
316 | # have to change the request manually. |
317 | - >>> request._publicationticks_start = 1345 |
318 | + >>> request._publication_start = 1.345 |
319 | + >>> request._publication_thread_start = None |
320 | |
321 | >>> publication.afterCall(request, None) |
322 | Aborted |
323 | @@ -976,11 +1029,12 @@ |
324 | >>> response = request.response |
325 | >>> response.setResult('Content that will disappear.') |
326 | |
327 | - # Our afterCall() implementation expects to find a |
328 | - # _publicationticks_start in its request, which is set by |
329 | + # Our afterCall() implementation expects to find _publication_start and |
330 | + # _publication_thread_start in its request, which are set by |
331 | # callObject(). Since we don't want to callObject() here, we'll |
332 | # have to change the request manually. |
333 | - >>> request._publicationticks_start = 1345 |
334 | + >>> request._publication_start = 1.345 |
335 | + >>> request._publication_thread_start = None |
336 | >>> publication.afterCall(request, None) |
337 | >>> request.response.consumeBody() |
338 | '' |
339 | @@ -992,11 +1046,12 @@ |
340 | >>> response = request.response |
341 | >>> response.setResult('Some boring content.') |
342 | |
343 | - # Our afterCall() implementation expects to find a |
344 | - # _publicationticks_start in its request, which is set by |
345 | + # Our afterCall() implementation expects to find _publication_start and |
346 | + # _publication_thread_start in its request, which are set by |
347 | # callObject(). Since we don't want to callObject() here, we'll |
348 | # have to change the request manually. |
349 | - >>> request._publicationticks_start = 1345 |
350 | + >>> request._publication_start = 1.345 |
351 | + >>> request._publication_thread_start = None |
352 | >>> publication.afterCall(request, None) |
353 | >>> print request.response.consumeBody() |
354 | Some boring content. |
355 | @@ -1060,7 +1115,6 @@ |
356 | principal's access_level and scope will match what was specified in the |
357 | token. |
358 | |
359 | - >>> import time |
360 | >>> from lp.registry.interfaces.product import IProductSet |
361 | >>> from lp.services.database.policy import MasterDatabasePolicy |
362 | >>> from lp.services.database.interfaces import IStoreSelector |
363 | |
364 | === modified file 'lib/lp/services/webapp/publication.py' |
365 | --- lib/lp/services/webapp/publication.py 2015-12-07 21:03:40 +0000 |
366 | +++ lib/lp/services/webapp/publication.py 2019-09-27 22:43:03 +0000 |
367 | @@ -1,4 +1,4 @@ |
368 | -# Copyright 2009-2011 Canonical Ltd. This software is licensed under the |
369 | +# Copyright 2009-2019 Canonical Ltd. This software is licensed under the |
370 | # GNU Affero General Public License version 3 (see the file LICENSE). |
371 | |
372 | __metaclass__ = type |
373 | @@ -11,6 +11,7 @@ |
374 | import sys |
375 | import thread |
376 | import threading |
377 | +import time |
378 | import traceback |
379 | import urllib |
380 | |
381 | @@ -26,7 +27,6 @@ |
382 | IntegrityError, |
383 | ) |
384 | from storm.zope.interfaces import IZStorm |
385 | -import tickcount |
386 | import transaction |
387 | from zc.zservertracelog.interfaces import ITraceLog |
388 | import zope.app.publication.browser |
389 | @@ -192,6 +192,17 @@ |
390 | return self |
391 | |
392 | |
393 | +def _get_thread_time(): |
394 | + """Get the CPU time spent in the current thread. |
395 | + |
396 | + This requires Python >= 3.3, and otherwise returns None. |
397 | + """ |
398 | + if hasattr(time, 'CLOCK_THREAD_CPUTIME_ID'): |
399 | + return time.clock_gettime(time.CLOCK_THREAD_CPUTIME_ID) |
400 | + else: |
401 | + return None |
402 | + |
403 | + |
404 | class LaunchpadBrowserPublication( |
405 | zope.app.publication.browser.BrowserPublication): |
406 | """Subclass of z.a.publication.BrowserPublication that removes ZODB. |
407 | @@ -240,7 +251,8 @@ |
408 | |
409 | def beforeTraversal(self, request): |
410 | notify(StartRequestEvent(request)) |
411 | - request._traversalticks_start = tickcount.tickcount() |
412 | + request._traversal_start = time.time() |
413 | + request._traversal_thread_start = _get_thread_time() |
414 | threadid = thread.get_ident() |
415 | threadrequestfile = open_for_writing( |
416 | 'logs/thread-%s.request' % threadid, 'w') |
417 | @@ -416,7 +428,8 @@ |
418 | It also sets the launchpad.userid and launchpad.pageid WSGI |
419 | environment variables. |
420 | """ |
421 | - request._publicationticks_start = tickcount.tickcount() |
422 | + request._publication_start = time.time() |
423 | + request._publication_thread_start = _get_thread_time() |
424 | if request.response.getStatus() in [301, 302, 303, 307]: |
425 | return '' |
426 | |
427 | @@ -470,12 +483,17 @@ |
428 | Because of this we cannot chain to the superclass and implement |
429 | the whole behaviour here. |
430 | """ |
431 | - assert hasattr(request, '_publicationticks_start'), ( |
432 | - 'request._publicationticks_start, which should have been set by ' |
433 | + assert hasattr(request, '_publication_start'), ( |
434 | + 'request._publication_start, which should have been set by ' |
435 | 'callObject(), was not found.') |
436 | - ticks = tickcount.difference( |
437 | - request._publicationticks_start, tickcount.tickcount()) |
438 | - request.setInWSGIEnvironment('launchpad.publicationticks', ticks) |
439 | + publication_duration = time.time() - request._publication_start |
440 | + if request._publication_thread_start is not None: |
441 | + publication_thread_duration = ( |
442 | + _get_thread_time() - request._publication_thread_start) |
443 | + else: |
444 | + publication_thread_duration = None |
445 | + request.setInWSGIEnvironment( |
446 | + 'launchpad.publicationduration', publication_duration) |
447 | |
448 | # Calculate SQL statement statistics. |
449 | sql_statements = da.get_request_statements() |
450 | @@ -483,10 +501,16 @@ |
451 | endtime - starttime |
452 | for starttime, endtime, id, statement, tb in sql_statements) |
453 | |
454 | - # Log publication tickcount, sql statement count, and sql time |
455 | - # to the tracelog. |
456 | - tracelog(request, 't', '%d %d %d' % ( |
457 | - ticks, len(sql_statements), sql_milliseconds)) |
458 | + # Log publication duration (in milliseconds), sql statement count, |
459 | + # and sql time (in milliseconds) to the tracelog. If we have the |
460 | + # publication time spent in this thread, then log that too (in |
461 | + # milliseconds). |
462 | + tracelog_entry = '%d %d %d' % ( |
463 | + publication_duration * 1000, |
464 | + len(sql_statements), sql_milliseconds) |
465 | + if publication_thread_duration is not None: |
466 | + tracelog_entry += ' %d' % (publication_thread_duration * 1000) |
467 | + tracelog(request, 't', tracelog_entry) |
468 | |
469 | # Annotate the transaction with user data. That was done by |
470 | # zope.app.publication.zopepublication.ZopePublication. |
471 | @@ -547,12 +571,17 @@ |
472 | # Log the URL including vhost information to the ZServer tracelog. |
473 | tracelog(request, 'u', request.getURL()) |
474 | |
475 | - assert hasattr(request, '_traversalticks_start'), ( |
476 | - 'request._traversalticks_start, which should have been set by ' |
477 | + assert hasattr(request, '_traversal_start'), ( |
478 | + 'request._traversal_start, which should have been set by ' |
479 | 'beforeTraversal(), was not found.') |
480 | - ticks = tickcount.difference( |
481 | - request._traversalticks_start, tickcount.tickcount()) |
482 | - request.setInWSGIEnvironment('launchpad.traversalticks', ticks) |
483 | + traversal_duration = time.time() - request._traversal_start |
484 | + request.setInWSGIEnvironment( |
485 | + 'launchpad.traversalduration', traversal_duration) |
486 | + if request._traversal_thread_start is not None: |
487 | + traversal_thread_duration = ( |
488 | + _get_thread_time() - request._traversal_thread_start) |
489 | + request.setInWSGIEnvironment( |
490 | + 'launchpad.traversalthreadduration', traversal_thread_duration) |
491 | |
492 | def _maybePlacefullyAuthenticate(self, request, ob): |
493 | """ This should never be called because we've excised it in |
494 | @@ -569,22 +598,35 @@ |
495 | db_policy = None |
496 | |
497 | orig_env = request._orig_env |
498 | - ticks = tickcount.tickcount() |
499 | - if (hasattr(request, '_publicationticks_start') and |
500 | - ('launchpad.publicationticks' not in orig_env)): |
501 | + now = time.time() |
502 | + thread_now = _get_thread_time() |
503 | + if (hasattr(request, '_publication_start') and |
504 | + ('launchpad.publicationduration' not in orig_env)): |
505 | # The traversal process has been started but hasn't completed. |
506 | - assert 'launchpad.traversalticks' in orig_env, ( |
507 | + assert 'launchpad.traversalduration' in orig_env, ( |
508 | 'We reached the publication process so we must have finished ' |
509 | 'the traversal.') |
510 | - ticks = tickcount.difference( |
511 | - request._publicationticks_start, ticks) |
512 | - request.setInWSGIEnvironment('launchpad.publicationticks', ticks) |
513 | - elif (hasattr(request, '_traversalticks_start') and |
514 | - ('launchpad.traversalticks' not in orig_env)): |
515 | + publication_duration = now - request._publication_start |
516 | + request.setInWSGIEnvironment( |
517 | + 'launchpad.publicationduration', publication_duration) |
518 | + if thread_now is not None: |
519 | + publication_thread_duration = ( |
520 | + thread_now - request._publication_thread_start) |
521 | + request.setInWSGIEnvironment( |
522 | + 'launchpad.publicationthreadduration', |
523 | + publication_thread_duration) |
524 | + elif (hasattr(request, '_traversal_start') and |
525 | + ('launchpad.traversalduration' not in orig_env)): |
526 | # The traversal process has been started but hasn't completed. |
527 | - ticks = tickcount.difference( |
528 | - request._traversalticks_start, ticks) |
529 | - request.setInWSGIEnvironment('launchpad.traversalticks', ticks) |
530 | + traversal_duration = now - request._traversal_start |
531 | + request.setInWSGIEnvironment( |
532 | + 'launchpad.traversalduration', traversal_duration) |
533 | + if thread_now is not None: |
534 | + traversal_thread_duration = ( |
535 | + thread_now - request._traversal_thread_start) |
536 | + request.setInWSGIEnvironment( |
537 | + 'launchpad.traversalthreadduration', |
538 | + traversal_thread_duration) |
539 | else: |
540 | # The exception wasn't raised in the middle of the traversal nor |
541 | # the publication, so there's nothing we need to do here. |
542 | @@ -639,10 +681,12 @@ |
543 | # is a normal part of operation. |
544 | if should_retry(exc_info): |
545 | if request.supportsRetry(): |
546 | - # Remove variables used for counting ticks as this request is |
547 | - # going to be retried. |
548 | - orig_env.pop('launchpad.traversalticks', None) |
549 | - orig_env.pop('launchpad.publicationticks', None) |
550 | + # Remove variables used for counting publication/traversal |
551 | + # durations as this request is going to be retried. |
552 | + orig_env.pop('launchpad.traversalduration', None) |
553 | + orig_env.pop('launchpad.traversalthreadduration', None) |
554 | + orig_env.pop('launchpad.publicationduration', None) |
555 | + orig_env.pop('launchpad.publicationthreadduration', None) |
556 | # Our endRequest needs to know if a retry is pending or not. |
557 | request._wants_retry = True |
558 | # Abort any in-progress transaction and reset any |
559 | |
560 | === modified file 'lib/lp/services/webapp/servers.py' |
561 | --- lib/lp/services/webapp/servers.py 2019-09-11 13:25:14 +0000 |
562 | +++ lib/lp/services/webapp/servers.py 2019-09-27 22:43:03 +0000 |
563 | @@ -1,4 +1,4 @@ |
564 | -# Copyright 2009-2018 Canonical Ltd. This software is licensed under the |
565 | +# Copyright 2009-2019 Canonical Ltd. This software is licensed under the |
566 | # GNU Affero General Public License version 3 (see the file LICENSE). |
567 | |
568 | """Definition of the internet servers that Launchpad uses.""" |
569 | @@ -1067,8 +1067,8 @@ |
570 | response bytes written |
571 | number of nonpython statements (sql, email, memcache, rabbit etc) |
572 | request duration |
573 | - number of ticks during traversal |
574 | - number of ticks during publication |
575 | + traversal duration |
576 | + publication duration |
577 | launchpad user id |
578 | launchpad page id |
579 | REFERER |
580 | @@ -1088,8 +1088,8 @@ |
581 | pageid = cgi_env.get('launchpad.pageid', '') |
582 | nonpython_actions = cgi_env.get('launchpad.nonpythonactions', 0) |
583 | request_duration = cgi_env.get('launchpad.requestduration', 0) |
584 | - traversal_ticks = cgi_env.get('launchpad.traversalticks', 0) |
585 | - publication_ticks = cgi_env.get('launchpad.publicationticks', 0) |
586 | + traversal_duration = cgi_env.get('launchpad.traversalduration', 0) |
587 | + publication_duration = cgi_env.get('launchpad.publicationduration', 0) |
588 | referer = request_headers.get('REFERER', '') |
589 | user_agent = request_headers.get('USER_AGENT', '') |
590 | |
591 | @@ -1106,8 +1106,8 @@ |
592 | bytes_written, |
593 | nonpython_actions, |
594 | request_duration, |
595 | - traversal_ticks, |
596 | - publication_ticks, |
597 | + traversal_duration, |
598 | + publication_duration, |
599 | userid, |
600 | pageid, |
601 | referer, |
Superseded by https:/ /code.launchpad .net/~cjwatson/ launchpad/ +git/launchpad/ +merge/ 373764.