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

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

[Colin Watson (cjwatson)]

Superseded by https://code.launchpad.net/~cjwatson/launchpad/+git/launchpad/+merge/373764.

Unmerged revisions

19064. By Colin Watson on 2019-09-27

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.

=== modified file 'lib/lp/services/webapp/doc/webapp-publication.txt'
--- lib/lp/services/webapp/doc/webapp-publication.txt	2019-05-22 14:57:45 +0000
+++ lib/lp/services/webapp/doc/webapp-publication.txt	2019-09-27 22:43:03 +0000
@@ -621,52 +621,62 @@
     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
-    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.
-
-    >>> 'launchpad.publicationticks' in request._orig_env
+    >>> '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 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.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 @@
     >>> set_request_started()
     >>> publication.handleException(
     ...     None, request, exc_info, retry_allowed=False)
-    >>> 'launchpad.traversalticks' in request._orig_env
-    False
-    >>> 'launchpad.publicationticks' in request._orig_env
+    >>> 'launchpad.traversalduration' in request._orig_env
+    False
+    >>> 'launchpad.traversalthreadduration' in request._orig_env
+    False
+    >>> '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
-    True
-    >>> 'launchpad.publicationticks' in request._orig_env
+    >>> '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
+    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 @@
     >>> set_request_started()
     >>> publication.handleException(
     ...     None, request, exc_info, retry_allowed=False)
-    >>> request._orig_env['launchpad.traversalticks'] < 500
-    True
-    >>> request._orig_env['launchpad.publicationticks'] < 50
+    >>> '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
+    >>> 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 @@
     ...
     Retry: foo
 
-    >>> 'launchpad.publicationticks' in request._orig_env
-    False
-    >>> 'launchpad.traversalticks' in request._orig_env
+    >>> 'launchpad.publicationduration' in request._orig_env
+    False
+    >>> '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 @@
     ...
     Retry: foo DisconnectionError
 
-    >>> 'launchpad.publicationticks' in request._orig_env
-    False
-    >>> 'launchpad.traversalticks' in request._orig_env
+    >>> 'launchpad.publicationduration' in request._orig_env
+    False
+    >>> 'launchpad.publicationthreadduration' in request._orig_env
+    False
+    >>> '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 @@
     ...
     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 @@
     >>> 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 @@
 
     >>> 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 @@
 
     >>> 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 @@
     >>> 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 @@
     >>> 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 @@
     >>> 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 @@
 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

=== modified file 'lib/lp/services/webapp/publication.py'
--- lib/lp/services/webapp/publication.py	2015-12-07 21:03:40 +0000
+++ lib/lp/services/webapp/publication.py	2019-09-27 22:43:03 +0000
@@ -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 sys
 import thread
 import threading
+import time
 import traceback
 import urllib
 
@@ -26,7 +27,6 @@
     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 @@
             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 @@
 
     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 @@
         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 @@
         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 @@
             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 @@
         # 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 @@
             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 @@
         # 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

=== modified file 'lib/lp/services/webapp/servers.py'
--- lib/lp/services/webapp/servers.py	2019-09-11 13:25:14 +0000
+++ lib/lp/services/webapp/servers.py	2019-09-27 22:43:03 +0000
@@ -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 @@
         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 @@
         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 @@
                 bytes_written,
                 nonpython_actions,
                 request_duration,
-                traversal_ticks,
-                publication_ticks,
+                traversal_duration,
+                publication_duration,
                 userid,
                 pageid,
                 referer,