launchpad-reviewers team mailing list archive

[Robert Collins <robertc@xxxxxxxxxxxxxxxxx>]

Robert Collins has proposed merging lp:~lifeless/launchpad/bug-766786 into lp:launchpad.

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)
Related bugs:
  Bug #766786 in Launchpad itself: "request timeline errors on nested action"
  https://bugs.launchpad.net/launchpad/+bug/766786

For more details, see:
https://code.launchpad.net/~lifeless/launchpad/bug-766786/+merge/58430

Small tweak to let us record nested things - like the openid login process which does remote http calls in a hard-to-instrument-way, but also does sql calls in callbacks.
-- 
https://code.launchpad.net/~lifeless/launchpad/bug-766786/+merge/58430
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~lifeless/launchpad/bug-766786 into lp:launchpad.

=== modified file 'lib/lp/services/timeline/tests/test_timeline.py'
--- lib/lp/services/timeline/tests/test_timeline.py	2010-09-01 02:16:53 +0000
+++ lib/lp/services/timeline/tests/test_timeline.py	2011-04-20 04:09:31 +0000
@@ -37,6 +37,69 @@
         self.assertRaises(OverlappingActionError, timeline.start,
             "Sending mail", "Noone")
 
+    def test_nested_start_permitted(self):
+        # When explicitly requested a nested start can be done
+        timeline = Timeline()
+        action = timeline.start("Calling openid", "hostname", allow_nested=True)
+        child = timeline.start("SQL Callback", "SELECT...")
+
+    def test_nested_start_is_not_transitive(self):
+        # nesting is explicit at each level - not inherited.
+        timeline = Timeline()
+        action = timeline.start("Calling openid", "hostname", allow_nested=True)
+        child = timeline.start("SQL Callback", "SELECT...")
+        self.assertRaises(OverlappingActionError, timeline.start,
+            "Sending mail", "Noone")
+
+    def test_multiple_nested_children_permitted(self):
+        # nesting is not reset by each action that is added.
+        timeline = Timeline()
+        action = timeline.start("Calling openid", "hostname", allow_nested=True)
+        child = timeline.start("SQL Callback", "SELECT...")
+        child.finish()
+        child = timeline.start("SQL Callback", "SELECT...")
+
+    def test_multiple_starts_after_nested_group_prevented(self):
+        # nesting stops being permitted when the nesting action is finished.
+        timeline = Timeline()
+        action = timeline.start("Calling openid", "hostname", allow_nested=True)
+        action.finish()
+        child = timeline.start("SQL Callback", "SELECT...")
+        self.assertRaises(OverlappingActionError, timeline.start,
+            "Sending mail", "Noone")
+
+    def test_nesting_within_nesting_permitted(self):
+        timeline = Timeline()
+        action = timeline.start("Calling openid", "hostname", allow_nested=True)
+        middle = timeline.start("Calling otherlibrary", "", allow_nested=True)
+        child = timeline.start("SQL Callback", "SELECT...")
+
+    def test_finishing_nested_within_nested_leaves_outer_nested_nesting(self):
+        timeline = Timeline()
+        action = timeline.start("Calling openid", "hostname", allow_nested=True)
+        middle = timeline.start("Calling otherlibrary", "", allow_nested=True)
+        middle.finish()
+        child = timeline.start("SQL Callback", "SELECT...")
+
+    def test_nested_actions_recorded_as_two_zero_length_actions(self):
+        timeline = Timeline()
+        action = timeline.start("Calling openid", "hostname", allow_nested=True)
+        child = timeline.start("SQL Callback", "SELECT...")
+        child.finish()
+        action.finish()
+        self.assertEqual(3, len(timeline.actions))
+        self.assertEqual(datetime.timedelta(), timeline.actions[0].duration)
+        self.assertEqual(datetime.timedelta(), timeline.actions[2].duration)
+
+    def test_nested_category_labels(self):
+        # To identify start/stop pairs '-start' and '-stop' are put onto the
+        # category of nested actions:
+        timeline = Timeline()
+        action = timeline.start("Calling openid", "hostname", allow_nested=True)
+        action.finish()
+        self.assertEqual('Calling openid-start', timeline.actions[0].category)
+        self.assertEqual('Calling openid-stop', timeline.actions[1].category)
+
     def test_start_after_finish_works(self):
         timeline = Timeline()
         action = timeline.start("Sending mail", "Noone")

=== modified file 'lib/lp/services/timeline/timedaction.py'
--- lib/lp/services/timeline/timedaction.py	2010-09-17 00:53:33 +0000
+++ lib/lp/services/timeline/timedaction.py	2011-04-20 04:09:31 +0000
@@ -42,9 +42,15 @@
         self.category = category
         self.detail = detail
         self.timeline = timeline
+        self._init()
+
+    def _init(self):
+        # hook for child classes.
+        pass
 
     def __repr__(self):
-        return "<TimedAction %s[%s]>" % (self.category, self.detail[:20])
+        return "<%s %s[%s]>" % (self.__class__, self.category,
+            self.detail[:20])
 
     def logTuple(self):
         """Return a 4-tuple suitable for errorlog's use."""

=== modified file 'lib/lp/services/timeline/timeline.py'
--- lib/lp/services/timeline/timeline.py	2010-09-01 08:51:15 +0000
+++ lib/lp/services/timeline/timeline.py	2011-04-20 04:09:31 +0000
@@ -12,19 +12,25 @@
 from pytz import utc as UTC
 
 from timedaction import TimedAction
+from nestingtimedaction import NestingTimedAction
 
 
 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
+    # To make analysis easy we do not permit overlapping actions by default:
+    # 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.
+    # reports in those situations, this can be changed. In the interim, actions
+    # can be explicitly setup to permit nesting by passing allow_nested=True
+    # which will cause the action to be recorded with 0 duration and a -start
+    # and -stop suffix added to its category. This is potentially lossy but
+    # good enough to get nested metrics and can be iterated on in the future to
+    # do an actual stacked/tree model of actions - if needed.
 
 
 class Timeline:
@@ -48,14 +54,20 @@
         self.actions = actions
         self.baseline = datetime.datetime.now(UTC)
 
-    def start(self, category, detail):
+    def start(self, category, detail, allow_nested=False):
         """Create a new TimedAction at the end of the timeline.
 
         :param category: the category for the action.
         :param detail: The detail for the action.
+        :param allow_nested: If True treat this action as a nested action -
+            record it twice with 0 duration, once at the start and once at the
+            finish.
         :return: A TimedAction for that category and detail.
         """
-        result = TimedAction(category, detail, self)
+        if allow_nested:
+            result = NestingTimedAction(category, detail, self)
+        else:
+            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)