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

[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.

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

[William Grant (wgrant)]

review: Approve (code)

diff --git a/lib/lp/services/webapp/doc/webapp-publication.txt b/lib/lp/services/webapp/doc/webapp-publication.txt
index 4406d41..a8ad43a 100644
--- a/lib/lp/services/webapp/doc/webapp-publication.txt
+++ b/lib/lp/services/webapp/doc/webapp-publication.txt
@@ -621,52 +621,62 @@ name of the context class and the view class name.
     TestContext:TestView
 
 
-Tick counts
------------
+Durations
+---------
 
 Similarly to our page IDs, our publication implementation will store the
-tick counts for the traversal and object publication processes in WSGI
+durations for the traversal and object publication processes in WSGI
 variables which aren't set originally.
 
-    >>> import tickcount
+    >>> import time
     >>> request, publication = get_request_and_publication()
     >>> request.setPrincipal(auth_utility.unauthenticatedPrincipal())
     >>> logout()
 
-For traversal we start counting the ticks during the beforeTraversal()
-hook and stop the count in afterTraversal().  The tick count is then
-available as launchpad.traversalticks in the WSGI environment.
+For traversal we start counting the duration during the beforeTraversal()
+hook and stop the count in afterTraversal().  The duration is then available
+as launchpad.traversalduration in the WSGI environment.  On Python >= 3.3,
+there is also launchpad.traversalthreadduration with the time spent in the
+current thread.
 
-    >>> 'launchpad.traversalticks' in request._orig_env
+    >>> 'launchpad.traversalduration' in request._orig_env
+    False
+    >>> 'launchpad.traversalthreadduration' in request._orig_env
     False
     >>> publication.beforeTraversal(request)
-    >>> tickcount.difference(
-    ...     request._traversalticks_start, tickcount.tickcount()) > 0
-    True
-
     >>> publication.afterTraversal(request, None)
-    >>> request._orig_env['launchpad.traversalticks'] < 200
+    >>> 'launchpad.traversalduration' in request._orig_env
+    True
+    >>> if hasattr(time, 'CLOCK_THREAD_CPUTIME_ID'):
+    ...     'launchpad.traversalthreadduration' in request._orig_env
+    ... else:
+    ...     True
     True
 
-For publication we start counting the ticks during the callObject()
-hook and stop the count in afterCall().  The tick count is then
-available as launchpad.publicationticks in the WSGI environment.
+For publication we start counting the duration during the callObject()
+hook and stop the count in afterCall().  The duration is then available as
+launchpad.publicationduration in the WSGI environment.  On Python >= 3.3,
+there is also launchpad.publicationthreadduration with the time spent in the
+current thread.
 
-    >>> 'launchpad.publicationticks' in request._orig_env
+    >>> 'launchpad.publicationduration' in request._orig_env
+    False
+    >>> 'launchpad.publicationthreadduration' in request._orig_env
     False
     >>> publication.callObject(request, TestView(TestContext(), request))
     u'Result'
-    >>> tickcount.difference(
-    ...     request._publicationticks_start, tickcount.tickcount()) > 0
-    True
-
     >>> publication.afterCall(request, None)
-    >>> request._orig_env['launchpad.publicationticks'] < 60
+    >>> 'launchpad.publicationduration' in request._orig_env
+    True
+    >>> if hasattr(time, 'CLOCK_THREAD_CPUTIME_ID'):
+    ...     'launchpad.publicationthreadduration' in request._orig_env
+    ... else:
+    ...     True
     True
     >>> publication.endRequest(request, None)
 
 If an exception is raised during traversal or object publication, we'll
-store the ticks up to the point in which the exception is raised.  This
+store the durations up to the point in which the exception is raised.  This
 is done inside the handleException() hook.  (The hook also sets and resets
 the request timer from lp.services.webapp.adapter, so you'll notice
 some calls to prepare that code to what handleException expects.)
@@ -687,26 +697,37 @@ there's nothing to store.
     >>> set_request_started()
     >>> publication.handleException(
     ...     None, request, exc_info, retry_allowed=False)
-    >>> 'launchpad.traversalticks' in request._orig_env
+    >>> 'launchpad.traversalduration' in request._orig_env
+    False
+    >>> 'launchpad.traversalthreadduration' in request._orig_env
     False
-    >>> 'launchpad.publicationticks' in request._orig_env
+    >>> 'launchpad.publicationduration' in request._orig_env
+    False
+    >>> 'launchpad.publicationthreadduration' in request._orig_env
     False
     >>> clear_request_started()
 
 If we started the traversal, but haven't finished it, we'll only have
-the ticks for the traversal and not for the publication.
+the duration for the traversal and not for the publication.
 
     >>> publication.beforeTraversal(request)
     >>> publication.handleException(
     ...     None, request, exc_info, retry_allowed=False)
-    >>> request._orig_env['launchpad.traversalticks'] < 200
+    >>> 'launchpad.traversalduration' in request._orig_env
+    True
+    >>> if hasattr(time, 'CLOCK_THREAD_CPUTIME_ID'):
+    ...     'launchpad.traversalthreadduration' in request._orig_env
+    ... else:
+    ...     True
     True
-    >>> 'launchpad.publicationticks' in request._orig_env
+    >>> 'launchpad.publicationduration' in request._orig_env
+    False
+    >>> 'launchpad.publicationthreadduration' in request._orig_env
     False
     >>> clear_request_started()
 
 If we started the publication (which means the traversal has been
-completed), we'll have the ticks for the traversal and the ticks for
+completed), we'll have the duration for the traversal and the duration for
 the publication, up to the point where it was forcefully stopped.
 
     >>> publication.afterTraversal(request, None)
@@ -715,22 +736,34 @@ the publication, up to the point where it was forcefully stopped.
     >>> set_request_started()
     >>> publication.handleException(
     ...     None, request, exc_info, retry_allowed=False)
-    >>> request._orig_env['launchpad.traversalticks'] < 500
+    >>> 'launchpad.traversalduration' in request._orig_env
+    True
+    >>> if hasattr(time, 'CLOCK_THREAD_CPUTIME_ID'):
+    ...     'launchpad.traversalthreadduration' in request._orig_env
+    ... else:
+    ...     True
+    True
+    >>> 'launchpad.publicationduration' in request._orig_env
     True
-    >>> request._orig_env['launchpad.publicationticks'] < 50
+    >>> if hasattr(time, 'CLOCK_THREAD_CPUTIME_ID'):
+    ...     'launchpad.publicationthreadduration' in request._orig_env
+    ... else:
+    ...     True
     True
     >>> publication.endRequest(request, None)
     >>> logger.setLevel(old_level)
 
 When a Retry or DisconnectionError exception is raised and the request
 supports retry, it will be retried with a copy of the WSGI environment.
-If that happens, though, we'll remove the [publication,traversal]ticks
-variables from there.
+If that happens, though, we'll remove the
+{publication,traversal}{,thread}duration variables from there.
 
     >>> request, publication = get_request_and_publication()
     >>> request.setPrincipal(auth_utility.unauthenticatedPrincipal())
-    >>> request._orig_env['launchpad.traversalticks'] = 500
-    >>> request._orig_env['launchpad.publicationticks'] = 500
+    >>> request._orig_env['launchpad.traversalduration'] = 0.5
+    >>> request._orig_env['launchpad.traversalthreadduration'] = 0.4
+    >>> request._orig_env['launchpad.publicationduration'] = 0.5
+    >>> request._orig_env['launchpad.publicationthreadduration'] = 0.4
     >>> request.supportsRetry()
     True
     >>> from zope.publisher.interfaces import Retry
@@ -744,15 +777,21 @@ variables from there.
     ...
     Retry: foo
 
-    >>> 'launchpad.publicationticks' in request._orig_env
+    >>> 'launchpad.publicationduration' in request._orig_env
     False
-    >>> 'launchpad.traversalticks' in request._orig_env
+    >>> 'launchpad.publicationthreadduration' in request._orig_env
+    False
+    >>> 'launchpad.traversalduration' in request._orig_env
+    False
+    >>> 'launchpad.traversalthreadduration' in request._orig_env
     False
 
     >>> request, publication = get_request_and_publication()
     >>> request.setPrincipal(auth_utility.unauthenticatedPrincipal())
-    >>> request._orig_env['launchpad.traversalticks'] = 500
-    >>> request._orig_env['launchpad.publicationticks'] = 500
+    >>> request._orig_env['launchpad.traversalduration'] = 0.5
+    >>> request._orig_env['launchpad.traversalthreadduration'] = 0.4
+    >>> request._orig_env['launchpad.publicationduration'] = 0.5
+    >>> request._orig_env['launchpad.publicationthreadduration'] = 0.4
     >>> request.supportsRetry()
     True
     >>> from storm.exceptions import DisconnectionError
@@ -766,19 +805,25 @@ variables from there.
     ...
     Retry: foo DisconnectionError
 
-    >>> 'launchpad.publicationticks' in request._orig_env
+    >>> 'launchpad.publicationduration' in request._orig_env
+    False
+    >>> 'launchpad.publicationthreadduration' in request._orig_env
     False
-    >>> 'launchpad.traversalticks' in request._orig_env
+    >>> 'launchpad.traversalduration' in request._orig_env
+    False
+    >>> 'launchpad.traversalthreadduration' in request._orig_env
     False
 
 Of course, any request can only be retried a certain number of times and
-when we reach that number of retries we don't pop the tick conts from the
+when we reach that number of retries we don't pop the durations from the
 WSGI env.
 
     >>> request, publication = get_request_and_publication()
     >>> request.setPrincipal(auth_utility.unauthenticatedPrincipal())
-    >>> request._orig_env['launchpad.traversalticks'] = 500
-    >>> request._orig_env['launchpad.publicationticks'] = 500
+    >>> request._orig_env['launchpad.traversalduration'] = 0.5
+    >>> request._orig_env['launchpad.traversalthreadduration'] = 0.4
+    >>> request._orig_env['launchpad.publicationduration'] = 0.5
+    >>> request._orig_env['launchpad.publicationthreadduration'] = 0.4
     >>> request.supportsRetry = lambda: False
     >>> request.supportsRetry()
     False
@@ -792,10 +837,14 @@ WSGI env.
     ...
     Retry: foo
 
-    >>> request._orig_env['launchpad.publicationticks']
-    500
-    >>> request._orig_env['launchpad.traversalticks']
-    500
+    >>> request._orig_env['launchpad.publicationduration']
+    0.5
+    >>> request._orig_env['launchpad.publicationthreadduration']
+    0.4
+    >>> request._orig_env['launchpad.traversalduration']
+    0.5
+    >>> request._orig_env['launchpad.traversalthreadduration']
+    0.4
 
 (A bit of cleanup so the test can continue)
 
@@ -818,11 +867,12 @@ The user attribute is an empty string, when no user is logged in.
     >>> print request.principal
     None
 
-    # Our afterCall() implementation expects to find a
-    # _publicationticks_start in its request, which is set by
+    # Our afterCall() implementation expects to find _publication_start and
+    # _publication_thread_start in its request, which are set by
     # callObject(). Since we don't want to callObject() here, we'll
     # have to change the request manually.
-    >>> request._publicationticks_start = 1345
+    >>> request._publication_start = 1.345
+    >>> request._publication_thread_start = None
     >>> publication.afterCall(request, None)
     >>> txn.user
     ''
@@ -883,11 +933,12 @@ be automatically reverted in a GET request.
 
     >>> request, publication = get_request_and_publication(method='GET')
 
-    # Our afterCall() implementation expects to find a
-    # _publicationticks_start in its request, which is set by
+    # Our afterCall() implementation expects to find _publication_start and
+    # _publication_thread_start in its request, which are set by
     # callObject(). Since we don't want to callObject() here, we'll
     # have to change the request manually.
-    >>> request._publicationticks_start = 1345
+    >>> request._publication_start = 1.345
+    >>> request._publication_thread_start = None
     >>> publication.afterCall(request, None)
     >>> txn = transaction.begin()
     >>> foo_bar = get_foo_bar_person()
@@ -901,11 +952,12 @@ But not if the request uses POST, the changes will be preserved.
 
     >>> request, publication = get_request_and_publication(method='POST')
 
-    # Our afterCall() implementation expects to find a
-    # _publicationticks_start in its request, which is set by
+    # Our afterCall() implementation expects to find _publication_start and
+    # _publication_thread_start in its request, which are set by
     # callObject(). Since we don't want to callObject() here, we'll
     # have to change the request manually.
-    >>> request._publicationticks_start = 1345
+    >>> request._publication_start = 1.345
+    >>> request._publication_thread_start = None
     >>> publication.afterCall(request, None)
     >>> txn = transaction.begin()
     >>> print get_foo_bar_person().description
@@ -934,11 +986,12 @@ Doomed transactions are aborted.
     >>> txn.isDoomed()
     True
 
-    # Our afterCall() implementation expects to find a
-    # _publicationticks_start in its request, which is set by
+    # Our afterCall() implementation expects to find _publication_start and
+    # _publication_thread_start in its request, which are set by
     # callObject(). Since we don't want to callObject() here, we'll
     # have to change the request manually.
-    >>> request._publicationticks_start = 1345
+    >>> request._publication_start = 1.345
+    >>> request._publication_thread_start = None
 
     >>> publication.afterCall(request, None)
     Aborted
@@ -976,11 +1029,12 @@ afterCall() publication hook.)
     >>> response = request.response
     >>> response.setResult('Content that will disappear.')
 
-    # Our afterCall() implementation expects to find a
-    # _publicationticks_start in its request, which is set by
+    # Our afterCall() implementation expects to find _publication_start and
+    # _publication_thread_start in its request, which are set by
     # callObject(). Since we don't want to callObject() here, we'll
     # have to change the request manually.
-    >>> request._publicationticks_start = 1345
+    >>> request._publication_start = 1.345
+    >>> request._publication_thread_start = None
     >>> publication.afterCall(request, None)
     >>> request.response.consumeBody()
     ''
@@ -992,11 +1046,12 @@ In other cases, like a GET, the body would be unchanged.
     >>> response = request.response
     >>> response.setResult('Some boring content.')
 
-    # Our afterCall() implementation expects to find a
-    # _publicationticks_start in its request, which is set by
+    # Our afterCall() implementation expects to find _publication_start and
+    # _publication_thread_start in its request, which are set by
     # callObject(). Since we don't want to callObject() here, we'll
     # have to change the request manually.
-    >>> request._publicationticks_start = 1345
+    >>> request._publication_start = 1.345
+    >>> request._publication_thread_start = None
     >>> publication.afterCall(request, None)
     >>> print request.response.consumeBody()
     Some boring content.
@@ -1060,7 +1115,6 @@ associated with the access token specified in the request.  The
 principal's access_level and scope will match what was specified in the
 token.
 
-    >>> import time
     >>> from lp.registry.interfaces.product import IProductSet
     >>> from lp.services.database.policy import MasterDatabasePolicy
     >>> from lp.services.database.interfaces import IStoreSelector
diff --git a/lib/lp/services/webapp/publication.py b/lib/lp/services/webapp/publication.py
index 6ba60b5..1b01f53 100644
--- a/lib/lp/services/webapp/publication.py
+++ b/lib/lp/services/webapp/publication.py
@@ -1,4 +1,4 @@
-# Copyright 2009-2011 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2019 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 __metaclass__ = type
@@ -11,6 +11,7 @@ import re
 import sys
 import thread
 import threading
+import time
 import traceback
 import urllib
 
@@ -26,7 +27,6 @@ from storm.exceptions import (
     IntegrityError,
     )
 from storm.zope.interfaces import IZStorm
-import tickcount
 import transaction
 from zc.zservertracelog.interfaces import ITraceLog
 import zope.app.publication.browser
@@ -192,6 +192,17 @@ class LoginRoot:
             return self
 
 
+def _get_thread_time():
+    """Get the CPU time spent in the current thread.
+
+    This requires Python >= 3.3, and otherwise returns None.
+    """
+    if hasattr(time, 'CLOCK_THREAD_CPUTIME_ID'):
+        return time.clock_gettime(time.CLOCK_THREAD_CPUTIME_ID)
+    else:
+        return None
+
+
 class LaunchpadBrowserPublication(
     zope.app.publication.browser.BrowserPublication):
     """Subclass of z.a.publication.BrowserPublication that removes ZODB.
@@ -240,7 +251,8 @@ class LaunchpadBrowserPublication(
 
     def beforeTraversal(self, request):
         notify(StartRequestEvent(request))
-        request._traversalticks_start = tickcount.tickcount()
+        request._traversal_start = time.time()
+        request._traversal_thread_start = _get_thread_time()
         threadid = thread.get_ident()
         threadrequestfile = open_for_writing(
             'logs/thread-%s.request' % threadid, 'w')
@@ -416,7 +428,8 @@ class LaunchpadBrowserPublication(
         It also sets the launchpad.userid and launchpad.pageid WSGI
         environment variables.
         """
-        request._publicationticks_start = tickcount.tickcount()
+        request._publication_start = time.time()
+        request._publication_thread_start = _get_thread_time()
         if request.response.getStatus() in [301, 302, 303, 307]:
             return ''
 
@@ -470,12 +483,17 @@ class LaunchpadBrowserPublication(
         Because of this we cannot chain to the superclass and implement
         the whole behaviour here.
         """
-        assert hasattr(request, '_publicationticks_start'), (
-            'request._publicationticks_start, which should have been set by '
+        assert hasattr(request, '_publication_start'), (
+            'request._publication_start, which should have been set by '
             'callObject(), was not found.')
-        ticks = tickcount.difference(
-            request._publicationticks_start, tickcount.tickcount())
-        request.setInWSGIEnvironment('launchpad.publicationticks', ticks)
+        publication_duration = time.time() - request._publication_start
+        if request._publication_thread_start is not None:
+            publication_thread_duration = (
+                _get_thread_time() - request._publication_thread_start)
+        else:
+            publication_thread_duration = None
+        request.setInWSGIEnvironment(
+            'launchpad.publicationduration', publication_duration)
 
         # Calculate SQL statement statistics.
         sql_statements = da.get_request_statements()
@@ -483,10 +501,16 @@ class LaunchpadBrowserPublication(
             endtime - starttime
                 for starttime, endtime, id, statement, tb in sql_statements)
 
-        # Log publication tickcount, sql statement count, and sql time
-        # to the tracelog.
-        tracelog(request, 't', '%d %d %d' % (
-            ticks, len(sql_statements), sql_milliseconds))
+        # Log publication duration (in milliseconds), sql statement count,
+        # and sql time (in milliseconds) to the tracelog.  If we have the
+        # publication time spent in this thread, then log that too (in
+        # milliseconds).
+        tracelog_entry = '%d %d %d' % (
+            publication_duration * 1000,
+            len(sql_statements), sql_milliseconds)
+        if publication_thread_duration is not None:
+            tracelog_entry += ' %d' % (publication_thread_duration * 1000)
+        tracelog(request, 't', tracelog_entry)
 
         # Annotate the transaction with user data. That was done by
         # zope.app.publication.zopepublication.ZopePublication.
@@ -547,12 +571,17 @@ class LaunchpadBrowserPublication(
         # Log the URL including vhost information to the ZServer tracelog.
         tracelog(request, 'u', request.getURL())
 
-        assert hasattr(request, '_traversalticks_start'), (
-            'request._traversalticks_start, which should have been set by '
+        assert hasattr(request, '_traversal_start'), (
+            'request._traversal_start, which should have been set by '
             'beforeTraversal(), was not found.')
-        ticks = tickcount.difference(
-            request._traversalticks_start, tickcount.tickcount())
-        request.setInWSGIEnvironment('launchpad.traversalticks', ticks)
+        traversal_duration = time.time() - request._traversal_start
+        request.setInWSGIEnvironment(
+            'launchpad.traversalduration', traversal_duration)
+        if request._traversal_thread_start is not None:
+            traversal_thread_duration = (
+                _get_thread_time() - request._traversal_thread_start)
+            request.setInWSGIEnvironment(
+                'launchpad.traversalthreadduration', traversal_thread_duration)
 
     def _maybePlacefullyAuthenticate(self, request, ob):
         """ This should never be called because we've excised it in
@@ -569,22 +598,35 @@ class LaunchpadBrowserPublication(
             db_policy = None
 
         orig_env = request._orig_env
-        ticks = tickcount.tickcount()
-        if (hasattr(request, '_publicationticks_start') and
-            ('launchpad.publicationticks' not in orig_env)):
+        now = time.time()
+        thread_now = _get_thread_time()
+        if (hasattr(request, '_publication_start') and
+            ('launchpad.publicationduration' not in orig_env)):
             # The traversal process has been started but hasn't completed.
-            assert 'launchpad.traversalticks' in orig_env, (
+            assert 'launchpad.traversalduration' in orig_env, (
                 'We reached the publication process so we must have finished '
                 'the traversal.')
-            ticks = tickcount.difference(
-                request._publicationticks_start, ticks)
-            request.setInWSGIEnvironment('launchpad.publicationticks', ticks)
-        elif (hasattr(request, '_traversalticks_start') and
-              ('launchpad.traversalticks' not in orig_env)):
+            publication_duration = now - request._publication_start
+            request.setInWSGIEnvironment(
+                'launchpad.publicationduration', publication_duration)
+            if thread_now is not None:
+                publication_thread_duration = (
+                    thread_now - request._publication_thread_start)
+                request.setInWSGIEnvironment(
+                    'launchpad.publicationthreadduration',
+                    publication_thread_duration)
+        elif (hasattr(request, '_traversal_start') and
+              ('launchpad.traversalduration' not in orig_env)):
             # The traversal process has been started but hasn't completed.
-            ticks = tickcount.difference(
-                request._traversalticks_start, ticks)
-            request.setInWSGIEnvironment('launchpad.traversalticks', ticks)
+            traversal_duration = now - request._traversal_start
+            request.setInWSGIEnvironment(
+                'launchpad.traversalduration', traversal_duration)
+            if thread_now is not None:
+                traversal_thread_duration = (
+                    thread_now - request._traversal_thread_start)
+                request.setInWSGIEnvironment(
+                    'launchpad.traversalthreadduration',
+                    traversal_thread_duration)
         else:
             # The exception wasn't raised in the middle of the traversal nor
             # the publication, so there's nothing we need to do here.
@@ -639,10 +681,12 @@ class LaunchpadBrowserPublication(
         # is a normal part of operation.
         if should_retry(exc_info):
             if request.supportsRetry():
-                # Remove variables used for counting ticks as this request is
-                # going to be retried.
-                orig_env.pop('launchpad.traversalticks', None)
-                orig_env.pop('launchpad.publicationticks', None)
+                # Remove variables used for counting publication/traversal
+                # durations as this request is going to be retried.
+                orig_env.pop('launchpad.traversalduration', None)
+                orig_env.pop('launchpad.traversalthreadduration', None)
+                orig_env.pop('launchpad.publicationduration', None)
+                orig_env.pop('launchpad.publicationthreadduration', None)
             # Our endRequest needs to know if a retry is pending or not.
             request._wants_retry = True
             # Abort any in-progress transaction and reset any
diff --git a/lib/lp/services/webapp/servers.py b/lib/lp/services/webapp/servers.py
index 6f3e7b8..506f705 100644
--- a/lib/lp/services/webapp/servers.py
+++ b/lib/lp/services/webapp/servers.py
@@ -1,4 +1,4 @@
-# Copyright 2009-2018 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2019 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 """Definition of the internet servers that Launchpad uses."""
@@ -1067,8 +1067,8 @@ class LaunchpadAccessLogger(CommonAccessLogger):
         response bytes written
         number of nonpython statements (sql, email, memcache, rabbit etc)
         request duration
-        number of ticks during traversal
-        number of ticks during publication
+        traversal duration
+        publication duration
         launchpad user id
         launchpad page id
         REFERER
@@ -1088,8 +1088,8 @@ class LaunchpadAccessLogger(CommonAccessLogger):
         pageid = cgi_env.get('launchpad.pageid', '')
         nonpython_actions = cgi_env.get('launchpad.nonpythonactions', 0)
         request_duration = cgi_env.get('launchpad.requestduration', 0)
-        traversal_ticks = cgi_env.get('launchpad.traversalticks', 0)
-        publication_ticks = cgi_env.get('launchpad.publicationticks', 0)
+        traversal_duration = cgi_env.get('launchpad.traversalduration', 0)
+        publication_duration = cgi_env.get('launchpad.publicationduration', 0)
         referer = request_headers.get('REFERER', '')
         user_agent = request_headers.get('USER_AGENT', '')
 
@@ -1106,8 +1106,8 @@ class LaunchpadAccessLogger(CommonAccessLogger):
                 bytes_written,
                 nonpython_actions,
                 request_duration,
-                traversal_ticks,
-                publication_ticks,
+                traversal_duration,
+                publication_duration,
                 userid,
                 pageid,
                 referer,