Add sequence ID and widget for it.

The idea of a sequence number/ID is to tie together all messages
associated with a given timed activity, to make performance
analysis easier.

_context.py: Add sequence number with atomic increment
_widget.py: SequenceID widget, which displays this value
_message.py: sequence_id variable storing the sequence for a message.

3 files changed, 27 insertions, 6 deletions

diff --git a/buildstream/_context.py b/buildstream/_context.py
index 725a9c31c..9e4a8fdb5 100644
--- a/buildstream/_context.py
+++ b/buildstream/_context.py
@@ -30,6 +30,7 @@ from ._exceptions import LoadError, LoadErrorReason, BstError
 from ._message import Message, MessageType
 from ._profile import Topics, profile_start, profile_end
 from ._artifactcache import artifact_cache_specs_from_config_node
+from threading import Lock
 
 
 # Context()
@@ -45,6 +46,9 @@ from ._artifactcache import artifact_cache_specs_from_config_node
 #
 class Context():
 
+    # Class-level static variable used to distinguish timed activities
+    sequence_ids = 0
+
     def __init__(self, *, fetch_subprojects=False):
 
         # Filename indicating which configuration file was used, or None for the defaults
@@ -350,10 +354,14 @@ class Context():
     #
     @contextmanager
     def _timed_activity(self, activity_name, *, unique_id=None, detail=None, silent_nested=False):
-
         starttime = datetime.datetime.now()
         stopped_time = None
 
+        with Lock():
+            # Atomically increase the sequence counter
+            Context.sequence_ids += 1
+            sequence_id = Context.sequence_ids
+
         def stop_time():
             nonlocal stopped_time
             stopped_time = datetime.datetime.now()
@@ -367,7 +375,7 @@ class Context():
         with _signals.suspendable(stop_time, resume_time):
             try:
                 # Push activity depth for status messages
-                message = Message(unique_id, MessageType.START, activity_name, detail=detail)
+                message = Message(unique_id, MessageType.START, activity_name, detail=detail, sequence_id=sequence_id)
                 self._message(message)
                 self._push_message_depth(silent_nested)
                 yield
@@ -376,13 +384,13 @@ class Context():
                 # Note the failure in status messages and reraise, the scheduler
                 # expects an error when there is an error.
                 elapsed = datetime.datetime.now() - starttime
-                message = Message(unique_id, MessageType.FAIL, activity_name, elapsed=elapsed)
+                message = Message(unique_id, MessageType.FAIL, activity_name, elapsed=elapsed, sequence_id=sequence_id)
                 self._pop_message_depth()
                 self._message(message)
                 raise
 
             elapsed = datetime.datetime.now() - starttime
-            message = Message(unique_id, MessageType.SUCCESS, activity_name, elapsed=elapsed)
+            message = Message(unique_id, MessageType.SUCCESS, activity_name, elapsed=elapsed, sequence_id=sequence_id)
             self._pop_message_depth()
             self._message(message)
 
diff --git a/buildstream/_frontend/widget.py b/buildstream/_frontend/widget.py
index e6134802d..0f431cec9 100644
--- a/buildstream/_frontend/widget.py
+++ b/buildstream/_frontend/widget.py
@@ -276,6 +276,18 @@ class LogFile(Widget):
         return text
 
 
+class SequenceID(Widget):
+    """ A unique Sequence ID is created for each timed_activity, and can
+        be used to associate all log lines from a particular
+        activity.
+    """
+    def render(self, message):
+        if message.sequence_id is None:
+            return self.content_profile.fmt("-")
+        else:
+            return self.content_profile.fmt(str(message.sequence_id))
+
+
 class MessageOrLogFile(Widget):
     """ START and SUCCESS messages are expected to have no useful
         information in the message text, so we display the logfile name for
diff --git a/buildstream/_message.py b/buildstream/_message.py
index 48b38b732..5183a0df2 100644
--- a/buildstream/_message.py
+++ b/buildstream/_message.py
@@ -59,7 +59,8 @@ class Message():
                  depth=None,
                  logfile=None,
                  sandbox=None,
-                 scheduler=False):
+                 scheduler=False,
+                 sequence_id=None):
         self.message_type = message_type  # Message type
         self.message = message            # The message string
         self.detail = detail              # An additional detail string
@@ -72,6 +73,6 @@ class Message():
         self.unique_id = unique_id        # The plugin object ID issueing the message
         self.task_id = task_id            # The plugin object ID of the task
         self.scheduler = scheduler        # Whether this is a scheduler level message
-
+        self.sequence_id = sequence_id    # Unique ID for a task, so we can track all messages per task
         if message_type in (MessageType.SUCCESS, MessageType.FAIL):
             assert(elapsed is not None)