Merge ~cjwatson/launchpad:remove-tickcount into launchpad:master

Proposed by Colin Watson on 2019-10-07
Status: Merged
Approved by: Colin Watson on 2019-10-11
Approved revision: 85a4bb4795ff19b480b3cf4996ac577b59c591ac
Merge reported by: Otto Co-Pilot
Merged at revision: not available
Proposed branch: ~cjwatson/launchpad:remove-tickcount
Merge into: launchpad:master
Diff against target: 594 lines (+206/-108)
3 files modified
lib/lp/services/webapp/doc/webapp-publication.txt (+121/-67)
lib/lp/services/webapp/publication.py (+78/-34)
lib/lp/services/webapp/servers.py (+7/-7)
Reviewer Review Type Date Requested Status
William Grant code 2019-10-07 Approve on 2019-10-11
Review via email: mp+373764@code.launchpad.net

Commit message

Remove tickcount and track traversal/publication durations instead

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.

This is essentially the same as https://code.launchpad.net/~cjwatson/launchpad/remove-tickcount/+merge/373347, converted to git and rebased on master.

To post a comment you must log in.
William Grant (wgrant) :
review: Approve (code)

Preview Diff

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

Subscribers

People subscribed via source and target branches