Merge lp:~lifeless/launchpad/oops into lp:launchpad

[Robert Collins]

Create lp.services.timeline for accruing/reporting on external/blocking actions.

Create a more generic environment for accruing/reporting on external/blocking actions.

[Jeroen T. Vermeulen (jtv)]

This was not one of those rubber-stamp reviews. :-)

The biggest sticking point, if a small one, was the dead code left in there to document the expected future state of the code. Please resolve that situation as soon as possible, of course.

We found that Timeline.baseline was at risk of ambiguity, because the Timeline could in principle be created on-demand in the middle of handling a request. We considered always having a "Start timeline" action, but decided against it. Ultimately you went with the option of creating the Timeline early on when handling a request, so that the baseline is always more or less the time we start handling the request.

review: Approve

=== modified file 'lib/canonical/launchpad/pagetests/basics/page-request-summaries.txt'
--- lib/canonical/launchpad/pagetests/basics/page-request-summaries.txt	2009-09-18 18:04:16 +0000
+++ lib/canonical/launchpad/pagetests/basics/page-request-summaries.txt	2010-09-03 03:44:47 +0000
@@ -1,12 +1,13 @@
-Launchpad pages end with a comment that displays how many queries we've issued
-to render the page. Note that we say "at least" because unfortunately
-some queries may be issued after the page may finish rendering -- the
-authoritative source is in OOPS reports or in the web app's stderr.
+Launchpad pages end with a comment that displays how many actions outside of
+the regular python code we've issued to satisfy the request. Note that we say "at
+least" because unfortunately some queries may be issued after the page may
+finish rendering -- the authoritative source is in OOPS reports or in the web
+app's stderr.
 
   >>> browser.open('http://launchpad.dev/')
   >>> print browser.contents
   <!DOCTYPE...
-  ...<!--... At least ... queries issued in ... seconds ...-->...
+  ...<!--... At least ... actions issued in ... seconds ...-->...
 
 It's available for any page:
 
@@ -14,4 +15,4 @@
   >>> browser.open('http://launchpad.dev/~mark/')
   >>> print browser.contents
   <!DOCTYPE...
-  ...<!--... At least ... queries issued in ... seconds ...-->...
+  ...<!--... At least ... actions issued in ... seconds ...-->...

=== modified file 'lib/canonical/launchpad/pagetests/basics/user-requested-oops.txt'
--- lib/canonical/launchpad/pagetests/basics/user-requested-oops.txt	2010-06-17 16:56:04 +0000
+++ lib/canonical/launchpad/pagetests/basics/user-requested-oops.txt	2010-09-03 03:44:47 +0000
@@ -3,7 +3,7 @@
 OOPSes happen from time to time in Launchpad, and they contain lots of
 interesting information for helping debug.  Sometimes though it is useful to
 get some of this information even if there hasn't been a problem.  The major
-use case for this is to get a dump of the database queries that a page does.
+use case for this is to get a dump of the blocking activities that a page does.
 
 A user can request an oops for a page by using the ++oops++ namespace in any
 page traversal.
@@ -15,7 +15,7 @@
     >>> (page, summary) = browser.contents.split('</html>')
     >>> print summary
     <!-- ...
-    At least ... queries issued in ... seconds OOPS-...
+    At least ... actions issued in ... seconds OOPS-...
     <BLANKLINE>
     r...
     -->
@@ -26,7 +26,7 @@
     >>> (page, summary) = browser.contents.split('</html>')
     >>> print summary
     <!-- ...
-    At least ... queries issued in ... seconds OOPS-...
+    At least ... actions issued in ... seconds OOPS-...
     <BLANKLINE>
     r...
     -->

=== modified file 'lib/canonical/launchpad/webapp/adapter.py'
--- lib/canonical/launchpad/webapp/adapter.py	2010-08-20 20:31:18 +0000
+++ lib/canonical/launchpad/webapp/adapter.py	2010-09-03 03:44:47 +0000
@@ -6,6 +6,7 @@
 
 __metaclass__ = type
 
+import datetime
 import os
 import re
 import sys
@@ -22,6 +23,7 @@
     ISOLATION_LEVEL_SERIALIZABLE,
     QueryCanceledError,
     )
+import pytz
 from storm.database import register_scheme
 from storm.databases.postgres import (
     Postgres,
@@ -63,7 +65,12 @@
     SLAVE_FLAVOR,
     )
 from canonical.launchpad.webapp.opstats import OpStats
-from canonical.lazr.utils import safe_hasattr
+from canonical.lazr.utils import get_current_browser_request, safe_hasattr
+from lp.services.timeline.timeline import Timeline
+from lp.services.timeline.requesttimeline import (
+    get_request_timeline,
+    set_request_timeline,
+    )
 
 
 __all__ = [
@@ -80,6 +87,8 @@
     ]
 
 
+UTC = pytz.utc
+
 classImplements(TimeoutError, IRequestExpired)
 
 
@@ -123,9 +132,9 @@
         pass
 
     def afterCompletion(self, txn):
-        now = time()
-        _log_statement(
-            now, now, None, 'Transaction completed, status: %s' % txn.status)
+        action = get_request_timeline(get_current_browser_request()).start(
+            "SQL-nostore", 'Transaction completed, status: %s' % txn.status)
+        action.finish()
 
 
 def set_request_started(
@@ -151,10 +160,14 @@
     if starttime is None:
         starttime = time()
     _local.request_start_time = starttime
-    if request_statements is None:
-        _local.request_statements = []
-    else:
-        _local.request_statements = request_statements
+    request = get_current_browser_request()
+    if request_statements is not None:
+        # Specify a specific sequence object for the timeline.
+        set_request_timeline(request, Timeline(request_statements))
+    else: 
+        # Ensure a timeline is created, so that time offset for actions is
+        # reasonable.
+        set_request_timeline(request, Timeline())
     _local.current_statement_timeout = None
     _local.enable_timeout = enable_timeout
     if txn is not None:
@@ -167,9 +180,9 @@
     """
     if getattr(_local, 'request_start_time', None) is None:
         warnings.warn('clear_request_started() called outside of a request')
-
     _local.request_start_time = None
-    _local.request_statements = []
+    request = get_current_browser_request()
+    set_request_timeline(request, Timeline())
     commit_logger = getattr(_local, 'commit_logger', None)
     if commit_logger is not None:
         _local.commit_logger.txn.unregisterSynch(_local.commit_logger)
@@ -179,7 +192,8 @@
 def summarize_requests():
     """Produce human-readable summary of requests issued so far."""
     secs = get_request_duration()
-    statements = getattr(_local, 'request_statements', [])
+    request = get_current_browser_request()
+    timeline = get_request_timeline(request)
     from canonical.launchpad.webapp.errorlog import (
         maybe_record_user_requested_oops)
     oopsid = maybe_record_user_requested_oops()
@@ -187,14 +201,15 @@
         oops_str = ""
     else:
         oops_str = " %s" % oopsid
-    log = "%s queries issued in %.2f seconds%s" % (
-        len(statements), secs, oops_str)
+    log = "%s queries/external actions issued in %.2f seconds%s" % (
+        len(timeline.actions), secs, oops_str)
     return log
 
 
 def store_sql_statements_and_request_duration(event):
+    actions = get_request_timeline(get_current_browser_request()).actions
     event.request.setInWSGIEnvironment(
-        'launchpad.sqlstatements', len(get_request_statements()))
+        'launchpad.nonpythonactions', len(actions))
     event.request.setInWSGIEnvironment(
         'launchpad.requestduration', get_request_duration())
 
@@ -205,7 +220,16 @@
     The list is composed of (starttime, endtime, db_id, statement) tuples.
     Times are given in milliseconds since the start of the request.
     """
-    return getattr(_local, 'request_statements', [])
+    result = []
+    request = get_current_browser_request()
+    for action in get_request_timeline(request).actions:
+        if not action.category.startswith("SQL-"):
+            continue
+        # Can't show incomplete requests in this API
+        if action.duration is None:
+            continue
+        result.append(action.logTuple())
+    return result
 
 
 def get_request_start_time():
@@ -224,29 +248,6 @@
     return now - starttime
 
 
-def _log_statement(starttime, endtime, connection_wrapper, statement):
-    """Log that a database statement was executed."""
-    request_starttime = getattr(_local, 'request_start_time', None)
-    if request_starttime is None:
-        return
-
-    # convert times to integer millisecond values
-    starttime = int((starttime - request_starttime) * 1000)
-    endtime = int((endtime - request_starttime) * 1000)
-    # A string containing no whitespace that lets us identify which Store
-    # is being used.
-    if connection_wrapper is not None:
-        database_identifier = connection_wrapper._database.name
-    else:
-        database_identifier = None
-    _local.request_statements.append(
-        (starttime, endtime, database_identifier, statement))
-
-    # store the last executed statement as an attribute on the current
-    # thread
-    threading.currentThread().lp_last_sql_statement = statement
-
-
 def _check_expired(timeout):
     """Checks whether the current request has passed the given timeout."""
     if timeout is None or not getattr(_local, 'enable_timeout', True):
@@ -530,15 +531,23 @@
         if self._debug_sql or self._debug_sql_extra:
             sys.stderr.write(statement + "\n")
             sys.stderr.write("-" * 70 + "\n")
-
-        now = time()
-        connection._lp_statement_start_time = now
+        # store the last executed statement as an attribute on the current
+        # thread
+        threading.currentThread().lp_last_sql_statement = statement
+        request_starttime = getattr(_local, 'request_start_time', None)
+        if request_starttime is None:
+            return
+        action = get_request_timeline(get_current_browser_request()).start(
+            'SQL-%s' % connection._database.name, statement)
+        connection._lp_statement_action = action
 
     def connection_raw_execute_success(self, connection, raw_cursor,
                                        statement, params):
-        end = time()
-        start = getattr(connection, '_lp_statement_start_time', end)
-        _log_statement(start, end, connection, statement)
+        action = getattr(connection, '_lp_statement_action', None)
+        if action is not None:
+            # action may be None if the tracer was installed  the statement was
+            # submitted.
+            action.finish()
 
     def connection_raw_execute_error(self, connection, raw_cursor,
                                      statement, params, error):

=== modified file 'lib/canonical/launchpad/webapp/errorlog.py'
--- lib/canonical/launchpad/webapp/errorlog.py	2010-08-26 02:47:21 +0000
+++ lib/canonical/launchpad/webapp/errorlog.py	2010-09-03 03:44:47 +0000
@@ -31,7 +31,7 @@
 from canonical.launchpad.layers import WebServiceLayer
 from canonical.launchpad.webapp.adapter import (
     get_request_duration,
-    get_request_statements,
+    get_request_start_time,
     soft_timeout_expired,
     )
 from canonical.launchpad.webapp.interfaces import (
@@ -42,7 +42,7 @@
 from canonical.launchpad.webapp.opstats import OpStats
 from canonical.lazr.utils import safe_hasattr
 from lp.services.log.uniquefileallocator import UniqueFileAllocator
-
+from lp.services.timeline.requesttimeline import get_request_timeline
 
 UTC = pytz.utc
 
@@ -451,11 +451,17 @@
         strurl = _safestr(url)
 
         duration = get_request_duration()
-
-        statements = sorted(
-            (start, end, _safestr(database_id), _safestr(statement))
-            for (start, end, database_id, statement)
-                in get_request_statements())
+        # In principle the timeline is per-request, but see bug=623199 -
+        # at this point the request is optional, but get_request_timeline
+        # does not care; when it starts caring, we will always have a 
+        # request object (or some annotations containing object).
+        # RBC 20100901
+        timeline = get_request_timeline(request)
+        statements = []
+        for action in timeline.actions:
+            start, end, category, detail = action.logTuple()
+            statements.append(
+                (start, end, _safestr(category), _safestr(detail)))
 
         oopsid, filename = self.log_namer.newId(now)
 

=== modified file 'lib/canonical/launchpad/webapp/ftests/test_adapter.txt'
--- lib/canonical/launchpad/webapp/ftests/test_adapter.txt	2010-03-25 11:58:42 +0000
+++ lib/canonical/launchpad/webapp/ftests/test_adapter.txt	2010-09-03 03:44:47 +0000
@@ -9,6 +9,7 @@
     >>> import threading
     >>> import transaction
     >>> from zope.component import getUtility
+    >>> from lazr.restful.utils import get_current_browser_request
     >>> from storm.zope.interfaces import IZStorm
     >>> from canonical.launchpad.webapp.interfaces import (
     ...     IStoreSelector, MAIN_STORE, MASTER_FLAVOR)
@@ -17,6 +18,7 @@
     >>> from canonical.launchpad.webapp.adapter import (
     ...     clear_request_started, get_request_statements,
     ...     set_request_started)
+    >>> from lp.services.timeline.requesttimeline import get_request_timeline
 
 There are several possible database connections available via the
 IStoreSelector utility.
@@ -50,6 +52,16 @@
     SELECT 1
     SELECT 2
 
+A timeline is created too:
+
+    >>> timeline = get_request_timeline(get_current_browser_request())
+    >>> for action in timeline.actions:
+    ...    if not action.category.startswith("SQL-"):
+    ...        continue
+    ...    print action.detail
+    SELECT 1
+    SELECT 2
+
 After we complete the request, the statement log is cleared:
 
     >>> clear_request_started()

=== modified file 'lib/canonical/launchpad/webapp/servers.py'
--- lib/canonical/launchpad/webapp/servers.py	2010-09-03 03:12:39 +0000
+++ lib/canonical/launchpad/webapp/servers.py	2010-09-03 03:44:47 +0000
@@ -977,7 +977,7 @@
         request string  (1st line of request)
         response status
         response bytes written
-        number of sql statements
+        number of nonpython statements (sql, email, memcache, rabbit etc)
         request duration
         number of ticks during traversal
         number of ticks during publication
@@ -998,7 +998,7 @@
         bytes_written = task.bytes_written
         userid = cgi_env.get('launchpad.userid', '')
         pageid = cgi_env.get('launchpad.pageid', '')
-        sql_statements = cgi_env.get('launchpad.sqlstatements', 0)
+        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)
@@ -1016,7 +1016,7 @@
                 first_line,
                 status,
                 bytes_written,
-                sql_statements,
+                nonpython_actions,
                 request_duration,
                 traversal_ticks,
                 publication_ticks,

=== modified file 'lib/canonical/launchpad/webapp/tests/test_publication.py'
--- lib/canonical/launchpad/webapp/tests/test_publication.py	2010-08-20 20:31:18 +0000
+++ lib/canonical/launchpad/webapp/tests/test_publication.py	2010-09-03 03:44:47 +0000
@@ -292,7 +292,8 @@
         next_oops = error_reporting_utility.getLastOopsReport()
 
         # Ensure the OOPS mentions the correct exception
-        self.assertTrue(repr(next_oops).find("DisconnectionError") != -1)
+        self.assertTrue(repr(next_oops).find("DisconnectionError") != -1,
+            "next_oops was %r" % next_oops)
 
         # Ensure the OOPS is correctly marked as informational only.
         self.assertEqual(next_oops.informational, 'True')

=== modified file 'lib/canonical/launchpad/webapp/tests/test_user_requested_oops.py'
--- lib/canonical/launchpad/webapp/tests/test_user_requested_oops.py	2010-08-20 20:31:18 +0000
+++ lib/canonical/launchpad/webapp/tests/test_user_requested_oops.py	2010-09-03 03:44:47 +0000
@@ -4,7 +4,6 @@
 
 __metaclass__ = type
 
-import unittest
 
 from lazr.restful.utils import get_current_browser_request
 from zope.component import getUtility
@@ -84,7 +83,3 @@
         self.assertEqual(last_oops.type, 'UserRequestOops')
         self.assertEqual(last_oops.informational, 'True')
 
-
-def test_suite():
-    return unittest.TestLoader().loadTestsFromName(__name__)
-

=== modified file 'lib/lp/app/browser/tests/base-layout.txt'
--- lib/lp/app/browser/tests/base-layout.txt	2010-08-17 15:05:44 +0000
+++ lib/lp/app/browser/tests/base-layout.txt	2010-09-03 03:44:47 +0000
@@ -134,7 +134,7 @@
       Has global search: False
       Has application tabs: False
       Has side portlets: False
-      At least ... queries issued in ... seconds
+      At least ... queries... issued in ... seconds
       Features: {}
       in scopes {}
       r...

=== added directory 'lib/lp/services/timeline'
=== added file 'lib/lp/services/timeline/__init__.py'
--- lib/lp/services/timeline/__init__.py	1970-01-01 00:00:00 +0000
+++ lib/lp/services/timeline/__init__.py	2010-09-03 03:44:47 +0000
@@ -0,0 +1,14 @@
+# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""lp.services.timeline provides a timeline for varied actions.
+
+This is used as part of determining where time goes in a request.
+
+NOTE that it is not LP's timeline-view for products, though they are similar in
+intent and concept (If a better name presents itself, this package may be
+renamed).
+
+Because this is part of lp.services, packages in this namespace can only use
+general LAZR or library functionality.
+"""

=== added file 'lib/lp/services/timeline/requesttimeline.py'
--- lib/lp/services/timeline/requesttimeline.py	1970-01-01 00:00:00 +0000
+++ lib/lp/services/timeline/requesttimeline.py	2010-09-03 03:44:47 +0000
@@ -0,0 +1,51 @@
+# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Manage a Timeline for a request."""
+
+__all__ = [
+    'get_request_timeline',
+    'set_request_timeline',
+    ]
+
+__metaclass__ = type
+
+# XXX RobertCollins 2010-09-01 bug=623199: Undesirable but pragmatic.
+# Because of this bug, rather than using request.annotations we have
+# to work in with the webapp.adapter request model, which is 
+# different to that used by get_current_browser_request.
+from canonical.launchpad import webapp
+from timeline import Timeline
+
+
+def get_request_timeline(request):
+    """Get a `Timeline` for request.
+
+    This should ideally return the request.annotations['timeline'], creating it
+    if necessary. However due to bug 623199 it instead using the adapter
+    context for 'requests'. Once bug 623199 is fixed it will instead use the
+    request annotations.
+
+    :param request: A zope/launchpad request object.
+    :return: A lp.services.timeline.timeline.Timeline object for the request.
+    """
+    try:
+        return webapp.adapter._local.request_timeline
+    except AttributeError:
+        return set_request_timeline(request, Timeline())
+    # Disabled code path: bug 623199, ideally we would use this code path.
+    return request.annotations.setdefault('timeline', Timeline())
+
+
+def set_request_timeline(request, timeline):
+    """Explicitly set a timeline for request.
+
+    This is used by code which wants to manually assemble a timeline.
+
+    :param request: A zope/launchpad request object.
+    :param timeline: A Timeline.
+    """
+    webapp.adapter._local.request_timeline = timeline
+    return timeline
+    # Disabled code path: bug 623199, ideally we would use this code path.
+    request.annotations['timeline'] = timeline

=== added directory 'lib/lp/services/timeline/tests'
=== added file 'lib/lp/services/timeline/tests/__init__.py'
--- lib/lp/services/timeline/tests/__init__.py	1970-01-01 00:00:00 +0000
+++ lib/lp/services/timeline/tests/__init__.py	2010-09-03 03:44:47 +0000
@@ -0,0 +1,4 @@
+# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Tests for lp.services.timeline."""

=== added file 'lib/lp/services/timeline/tests/test_requesttimeline.py'
--- lib/lp/services/timeline/tests/test_requesttimeline.py	1970-01-01 00:00:00 +0000
+++ lib/lp/services/timeline/tests/test_requesttimeline.py	2010-09-03 03:44:47 +0000
@@ -0,0 +1,58 @@
+# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Tests of requesttimeline."""
+
+__metaclass__ = type
+
+import testtools
+from zope.publisher.browser import TestRequest
+
+from canonical.launchpad import webapp
+from lp.services.timeline.requesttimeline import (
+    get_request_timeline,
+    set_request_timeline,
+    )
+from lp.services.timeline.timeline import OverlappingActionError, Timeline
+
+
+class TestRequestTimeline(testtools.TestCase):
+
+    # These disabled tests are for the desired API using request annotations.
+    # bug=623199 describes some issues with why this doesn't work.
+    def disabled_test_new_request_get_request_timeline_works(self):
+        req = TestRequest()
+        timeline = get_request_timeline(req)
+        self.assertIsInstance(timeline, Timeline)
+
+    def disabled_test_same_timeline_repeated_calls(self):
+        req = TestRequest()
+        timeline = get_request_timeline(req)
+        self.assertEqual(timeline, get_request_timeline(req))
+
+    def disabled_test_set_timeline(self):
+        req = TestRequest()
+        timeline = Timeline()
+        set_request_timeline(req, timeline)
+        self.assertEqual(timeline, get_request_timeline(req))
+
+    # Tests while adapter._local contains the timeline --start---
+    # Delete when bug=623199 is fixed and the timeline store moved to
+    # annotations.
+    def test_new_request_get_request_timeline_uses_webapp(self):
+        req = TestRequest()
+        timeline = get_request_timeline(req)
+        self.assertIsInstance(timeline, Timeline)
+        self.assertTrue(webapp.adapter._local.request_timeline is timeline)
+
+    def test_same_timeline_repeated_calls(self):
+        req = TestRequest()
+        timeline = get_request_timeline(req)
+        self.assertEqual(timeline, get_request_timeline(req))
+
+    def test_set_timeline(self):
+        req = TestRequest()
+        timeline = Timeline()
+        set_request_timeline(req, timeline)
+        self.assertEqual(timeline, get_request_timeline(req))
+    # Tests while adapter._local contains the timeline ---end---

=== added file 'lib/lp/services/timeline/tests/test_timedaction.py'
--- lib/lp/services/timeline/tests/test_timedaction.py	1970-01-01 00:00:00 +0000
+++ lib/lp/services/timeline/tests/test_timedaction.py	2010-09-03 03:44:47 +0000
@@ -0,0 +1,61 @@
+# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Tests of the TimedAction class."""
+
+__metaclass__ = type
+
+import datetime
+
+import testtools
+
+from lp.services.timeline.timedaction import TimedAction
+from lp.services.timeline.timeline import Timeline
+
+
+class TestTimedAction(testtools.TestCase):
+
+    def test_starts_now(self):
+        action = TimedAction("Sending mail", None)
+        self.assertIsInstance(action.start, datetime.datetime)
+
+    def test_finish_sets_duration(self):
+        action = TimedAction("Sending mail", None)
+        self.assertEqual(None, action.duration)
+        action.finish()
+        self.assertIsInstance(action.duration, datetime.timedelta)
+
+    def test__init__sets_category(self):
+        action = TimedAction("Sending mail", None)
+        self.assertEqual("Sending mail", action.category)
+
+    def test__init__sets_detail(self):
+        action = TimedAction(None, "[e-mail]")
+        self.assertEqual("[e-mail]", action.detail)
+
+    def test_logTuple(self):
+        timeline = Timeline()
+        action = TimedAction("foo", "bar", timeline)
+        # Set variable for deterministic results
+        action.start = timeline.baseline + datetime.timedelta(0, 0, 0, 2)
+        action.duration = datetime.timedelta(0, 0, 0, 4)
+        log_tuple = action.logTuple()
+        self.assertEqual(4, len(log_tuple), "!= 4 elements %s" % (log_tuple,))
+        self.assertAlmostEqual(2, log_tuple[0])
+        self.assertAlmostEqual(4, log_tuple[1])
+        self.assertEqual("foo", log_tuple[2])
+        self.assertEqual("bar", log_tuple[3])
+
+    def test_logTupleIncomplete(self):
+        # Things that start and hit a timeout *may* not get recorded as
+        # finishing in normal operation.
+        timeline = Timeline()
+        action = TimedAction("foo", "bar", timeline)
+        # Set variable for deterministic results
+        action.start = timeline.baseline + datetime.timedelta(0, 0, 0, 2)
+        log_tuple = action.logTuple()
+        self.assertEqual(4, len(log_tuple), "!= 4 elements %s" % (log_tuple,))
+        self.assertAlmostEqual(2, log_tuple[0])
+        self.assertAlmostEqual(999999, log_tuple[1])
+        self.assertEqual("foo", log_tuple[2])
+        self.assertEqual("bar", log_tuple[3])

=== added file 'lib/lp/services/timeline/tests/test_timeline.py'
--- lib/lp/services/timeline/tests/test_timeline.py	1970-01-01 00:00:00 +0000
+++ lib/lp/services/timeline/tests/test_timeline.py	2010-09-03 03:44:47 +0000
@@ -0,0 +1,50 @@
+# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Tests of the Timeline class."""
+
+__metaclass__ = type
+
+import datetime
+
+import testtools
+
+from lp.services.timeline.timedaction import TimedAction
+from lp.services.timeline.timeline import OverlappingActionError, Timeline
+
+
+class TestTimeline(testtools.TestCase):
+
+    def test_start_returns_action(self):
+        timeline = Timeline()
+        action = timeline.start("Sending mail", "Noone")
+        self.assertIsInstance(action, TimedAction)
+        self.assertEqual("Sending mail", action.category)
+        self.assertEqual("Noone", action.detail)
+        self.assertEqual(None, action.duration)
+        self.assertEqual(timeline, action.timeline)
+
+    def test_can_supply_list(self):
+        actions = "foo"
+        timeline = Timeline(actions)
+        self.assertEqual(actions, timeline.actions)
+
+    def test_start_with_unfinished_action_fails(self):
+        # A design constraint of timeline says that overlapping actions are not
+        # permitted. See the Timeline docstrings.
+        timeline = Timeline()
+        action = timeline.start("Sending mail", "Noone")
+        self.assertRaises(OverlappingActionError, timeline.start,
+            "Sending mail", "Noone")
+
+    def test_start_after_finish_works(self):
+        timeline = Timeline()
+        action = timeline.start("Sending mail", "Noone")
+        action.finish()
+        action = timeline.start("Sending mail", "Noone")
+        action.finish()
+        self.assertEqual(2, len(timeline.actions))
+
+    def test_baseline(self):
+        timeline = Timeline()
+        self.assertIsInstance(timeline.baseline, datetime.datetime)

=== added file 'lib/lp/services/timeline/timedaction.py'
--- lib/lp/services/timeline/timedaction.py	1970-01-01 00:00:00 +0000
+++ lib/lp/services/timeline/timedaction.py	2010-09-03 03:44:47 +0000
@@ -0,0 +1,69 @@
+# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Time a single categorised action."""
+
+
+__all__ = ['TimedAction']
+
+__metaclass__ = type
+
+
+import datetime
+
+import pytz
+
+
+UTC = pytz.utc
+
+
+class TimedAction:
+    """An individual action which has been timed.
+
+    :ivar timeline: The timeline that this action took place within.
+    :ivar start: A datetime object with tz for the start of the action.
+    :ivar duration: A timedelta for the duration of the action. None for
+        actions which have not completed.
+    :ivar category: The category of the action. E.g. "sql".
+    :ivar detail: The detail about the action. E.g. "SELECT COUNT(*) ..."
+    """
+
+    def __init__(self, category, detail, timeline=None):
+        """Create a TimedAction.
+
+        New TimedActions have a start but no duration.
+
+        :param category: The category for the action.
+        :param detail: The detail about the action being timed.
+        :param timeline: The timeline for the action.
+        """
+        self.start = datetime.datetime.now(UTC)
+        self.duration = None
+        self.category = category
+        self.detail = detail
+        self.timeline = timeline
+
+    def logTuple(self):
+        """Return a 4-tuple suitable for errorlog's use."""
+        offset = self._td_to_ms(self.start - self.timeline.baseline)
+        if self.duration is None:
+            # This action wasn't finished: give it a duration that will stand
+            # out. This is pretty normal when action ends are recorded by
+            # callbacks rather than stack-like structures. E.g. storm 
+            # tracers in launchpad:
+            # log-trace START : starts action
+            # timeout-trace START : raises 
+            # log-trace FINISH is never called.
+            length = 999999
+        else:
+            length = self._td_to_ms(self.duration)
+        return (offset, length, self.category, self.detail)
+
+    def _td_to_ms(self, td):
+        """Tweak on a backport from python 2.7"""
+        return (td.microseconds + (
+            td.seconds + td.days * 24 * 3600) * 10**6) / 10**3
+
+    def finish(self):
+        """Mark the TimedAction as finished."""
+        self.duration = datetime.datetime.now(UTC) - self.start

=== added file 'lib/lp/services/timeline/timeline.py'
--- lib/lp/services/timeline/timeline.py	1970-01-01 00:00:00 +0000
+++ lib/lp/services/timeline/timeline.py	2010-09-03 03:44:47 +0000
@@ -0,0 +1,62 @@
+# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Coordinate a sequence of non overlapping TimedActionss."""
+
+__all__ = ['Timeline']
+
+__metaclass__ = type
+
+import datetime
+
+from pytz import utc as UTC
+
+from timedaction import TimedAction
+
+
+class OverlappingActionError(Exception):
+    """A new action was attempted without finishing the prior one."""
+    # To make analysis easy we do not permit overlapping actions: each
+    # action that is being timed and accrued must complete before the next
+    # is started. This means, for instance, that sending mail cannot do SQL
+    # queries, as both are timed and accrued. OTOH it makes analysis and
+    # serialisation of timelines simpler, and for the current use cases in 
+    # Launchpad this is sufficient. This constraint should not be considered
+    # sacrosanct - if, in future, we desire timelines with overlapping actions,
+    # as long as the OOPS analysis code is extended to generate sensible
+    # reports in those situations, this can be changed.
+
+
+class Timeline:
+    """A sequence of TimedActions.
+
+    This is used for collecting expensive/external actions inside Launchpad
+    requests.
+
+    :ivar actions: The actions.
+    :ivar baseline: The point the timeline starts at.
+    """
+
+    def __init__(self, actions=None):
+        """Create a Timeline.
+        
+        :param actions: An optional object to use to store the timeline. This
+            must implement the list protocol.
+        """
+        if actions is None:
+            actions = []
+        self.actions = actions
+        self.baseline = datetime.datetime.now(UTC)
+
+    def start(self, category, detail):
+        """Create a new TimedAction at the end of the timeline.
+
+        :param category: the category for the action.
+        :param detail: The detail for the action.
+        :return: A TimedAction for that category and detail.
+        """
+        result = TimedAction(category, detail, self)
+        if self.actions and self.actions[-1].duration is None:
+            raise OverlappingActionError(self.actions[-1], result)
+        self.actions.append(result)
+        return result