[DO NOT COMMIT] Refactor systrace to support new clock sync design

systrace/systrace/tracing_controller.py

+#!/usr/bin/env python
+
+# Copyright (c) 2016 The Chromium Authors. All rights reserved.
+# Use of this source code is governed by a BSD-style license that can be
+# found in the LICENSE file.
+
+'''Tracing controller class. This class manages
+multiple tracing agents and collects data from all of them. It also
+manages the clock sync process.
+'''
+
+import ast
+import tempfile
+import uuid
+import sys
+
+import trace_event
+from devil.utils import reraiser_thread
+from devil.utils import timeout_retry
+from systrace.tracing_agents import TracingAgent
+from systrace.tracing_agents import TraceResults
+
+# TODO(alexandermont): Current version of trace viewer does not support
+# the controller tracing agent output. Thus we use this variable to
+# suppress this tracing agent's output. This should be removed once
+# trace viewer is working again.
+output_controller_tracing_agent = False

[Zhen Wang, 2016/03/30 18:11:16]

s/output_controller_tracing_agent/OUTPUT_CONTROLLER_TRACING_AGENT_

I just chatted with Charlie, I think we do need to wait for his CL to make sure
the output with controller log is working correctly. We can keep this for now
and remove this once his work is done.

Later, when adding clock sync support, you also need to add some support to
ftrace to make sure it is working correctly. That should not be very hard.

See updates on https://github.com/catapult-project/catapult/issues/2193 for more
background.

+
+class TracingController(TracingAgent):
+  def __init__(self, options, categories, agents):
+    """Create tracing controller.
+
+    Create a tracing controller object. Note that the tracing
+    controller is also a tracing agent.
+
+    Args:
+       options: Tracing options.
+       categories: Categories of trace events to record.
+       agents: List of tracing agents for this controller.
+    """
+    super(TracingController, self).__init__()
+    self._agents = agents
+    self._options = options
+    self._categories = categories
+    self._trace_in_progress = False
+    self._clock_sync_markers = []
+    self._log_path = None
+    self._all_results = None
+
+  def _StartAgentTracing_func(self):

[Zhen Wang, 2016/03/30 16:14:08]

nit: is this name following the style? Why not just _StartAgentTracing?

Same question for other places.

[alexandermont, 2016/03/30 19:33:25]

Done. Changed to _StartAgentTracingImpl. (Don't want to change it to
_StartAgentTracing, because that's too similar to the name of the public API
function, StartAgentTracing.)

+    """Start tracing for the controller tracing agent.
+
+    Start tracing for the controller tracing agent. Note that
+    the tracing controller records the "controller side"
+    of the clock sync records, and nothing else.
+    """
+    if not trace_event.trace_can_enable():
+      raise RuntimeError, ('Cannot enable trace_event;'
+                           ' ensure catapult_base is in PYTHONPATH')
+
+    controller_log_file = tempfile.NamedTemporaryFile(delete=False)
+    self._log_path = controller_log_file.name
+    controller_log_file.close()
+    trace_event.trace_enable(self._log_path)
+    return True
+
+  def StartAgentTracing(self, options, categories, timeout=10):
+    # pylint: disable=unused-argument
+    # don't need the options and categories arguments in this
+    # case, but including them for consistency with the
+    # function prototypes for other TracingAgents
+    return timeout_retry.Run(self._StartAgentTracing_func,
+                             timeout, 1)
+
+  @property
+  def trace_in_progress(self):
+    return self._trace_in_progress
+
+  def _StopAgentTracing_func(self):
+    """Stops tracing for the controller tracing agent.
+    """
+    # pylint: disable=no-self-use
+    # This function doesn't use self, but making it a member function
+    # for consistency with the other TracingAgents
+    trace_event.trace_disable()
+    return True
+
+  def StopAgentTracing(self, timeout=10):
+    return timeout_retry.Run(self._StopAgentTracing_func,
+                             timeout, 1)
+
+  def _GetResults_func(self):
+    """Gets the log output from the controller tracing agent.
+
+    This output only contains the "controller side" of the clock sync records.
+    """
+    if self._trace_in_progress:
+      raise RuntimeError, 'Cannot get results while trace is in progress'
+    with open(self._log_path, 'r') as outfile:
+      result = outfile.read() + ']'
+    return TraceResults('traceEvents', ast.literal_eval(result))
+
+  def GetResults(self, timeout=30):
+    return timeout_retry.Run(self._GetResults_func,
+                             timeout, 1)
+
+  def StartTracing(self):
+    """Start tracing for all tracing agents.
+
+    This function starts tracing for both the controller tracing agent
+    and the child tracing agents.
+
+    Returns:
+        Boolean indicating whether or not the start tracing succeeded
+        for all agents.
+    """
+    assert not self._trace_in_progress, 'Trace already in progress.'
+    self._trace_in_progress = True
+    if not self.StartAgentTracing(self._options,
+                                  self._categories,
+                                  timeout=self._options.timeout):
+      print 'Unable to start controller tracing agent.'
+      return False
+    succ_agents = []
+    for agent in self._agents:
+      if agent.StartAgentTracing(self._options,
+                                 self._categories,
+                                 timeout=self._options.timeout):
+        succ_agents.append(agent)
+      else:
+        print 'Agent %s not started.' % str(agent)
+    na = len(self._agents)
+    ns = len(succ_agents)
+    if ns < na:
+      print 'Warning: Only %d of %d tracing agents started.' % (na, ns)
+      self._agents = succ_agents
+
+  def StopTracing(self):
+    """Issue clock sync marker and stop tracing for all tracing agents.
+
+    This function stops both the controller tracing agent
+    and the child tracing agents. It issues a clock sync marker prior
+    to stopping tracing.
+
+    Returns:
+        Boolean indicating whether or not the stop tracing succeeded
+        for all agents.
+    """
+    assert self._trace_in_progress, 'No trace in progress.'
+    self._trace_in_progress = False
+    self._IssueClockSyncMarker()
+    succ_agents = []
+    for agent in self._agents:
+      if agent.StopAgentTracing(timeout=self._options.timeout):
+        succ_agents.append(agent)
+      else:
+        print 'Agent %s not stopped.' % str(agent)
+    if not self.StopAgentTracing(timeout=self._options.timeout):
+      print 'Unable to stop controller tracing agent.'
+      return False
+    na = len(self._agents)
+    ns = len(succ_agents)
+    if ns < na:
+      print 'Warning: Only %d of %d tracing agents stopped.' % (na, ns)
+      self._agents = succ_agents
+    self._all_results = {}
+    for agent in self._agents + [self]:
+      try:
+        (key, value) = agent.GetResults(
+            timeout=self._options.collection_timeout)
+        if key in self._all_results:
+          print 'Warning: Duplicate tracing agents'
+        if (agent is not self) or output_controller_tracing_agent:
+          self._all_results[key] = value
+      except reraiser_thread.TimeoutError:
+        print 'Warning: Timeout when getting results.'
+      except:
+        print 'Warning: Other exception when getting results:'
+        print sys.exc_info()[0]
+        raise
+    return True
+
+  def SupportsExplicitClockSync(self):
+    '''Returns whether this supports explicit clock sync.
+
+    Although the tracing controller conceptually supports explicit clock
+    sync, it is not an agent controlled by other controllers so it does not
+    define RecordClockSyncMarker (rather, the recording of the "controller
+    side" of the clock sync marker is done in _IssueClockSyncMarker). Thus,
+    SupportsExplicitClockSync must return false.
+    '''
+    return False
+
+  def RecordClockSyncMarker(self, sync_id, callback):
+    raise NotImplementedError
+
+  def _IssueClockSyncMarker(self):
+    """Issue clock sync markers to all the child tracing agents."""
+    for agent in self._agents:
+      if agent.SupportsExplicitClockSync():
+        sync_id = GetUniqueSyncID()
+        callback = lambda t, s: trace_event.clock_sync(s, issue_ts=t)
+        agent.RecordClockSyncMarker(sync_id, callback)
+
+def GetUniqueSyncID():
+  """Get a unique sync ID.
+
+  Gets a unique sync ID by generating a UUID and converting it to a string
+  (since UUIDs are not JSON serializable)
+  """
+  return str(uuid.uuid4())