Tracing tack for devtools monitor.

This just dumps tracing events, and doesn't do any processing of those events yet.

I experimented with fetching trace data as a stream. It appears to not be
beneficial but I have left the option in. I also refactored some of the device
setup work to make it easier to switch between local and device debugging,
changing devtools ports, etc. Note that I also changed the FlagChanger context
to make it more explicit what's going on w/rt adding or replacing flags.

BUG=

Review URL: https://codereview.chromium.org/1589843002

Cr-Commit-Position: refs/heads/master@{#370028}

6 files changed, 301 insertions, 41 deletions

diff --git a/tools/android/loading/device_setup.py b/tools/android/loading/device_setup.py
index 24becb7..4d5d40b 100644
--- a/tools/android/loading/device_setup.py
+++ b/tools/android/loading/device_setup.py
@@ -17,17 +17,21 @@ sys.path.append(os.path.join(_SRC_DIR, 'build', 'android'))
 from pylib import constants
 from pylib import flag_changer
 
+import devtools_monitor
+
 DEVTOOLS_PORT = 9222
 DEVTOOLS_HOSTNAME = 'localhost'
+DEFAULT_CHROME_PACKAGE = 'chrome'
 
 @contextlib.contextmanager
-def FlagChanger(device, command_line_path, new_flags):
-  """Changes the flags in a context, restores them afterwards.
+def FlagReplacer(device, command_line_path, new_flags):
+  """Replaces chrome flags in a context, restores them afterwards.
 
   Args:
-    device: Device to target, from DeviceUtils.
+    device: Device to target, from DeviceUtils. Can be None, in which case this
+      context manager is a no-op.
     command_line_path: Full path to the command-line file.
-    new_flags: Flags to add.
+    new_flags: Flags to replace.
   """
   # If we're logging requests from a local desktop chrome instance there is no
   # device.
@@ -35,7 +39,7 @@ def FlagChanger(device, command_line_path, new_flags):
     yield
     return
   changer = flag_changer.FlagChanger(device, command_line_path)
-  changer.AddFlags(new_flags)
+  changer.ReplaceFlags(new_flags)
   try:
     yield
   finally:
@@ -63,28 +67,30 @@ def _SetUpDevice(device, package_info):
   device.KillAll(package_info.package, quiet=True)
 
 
-def SetUpAndExecute(device, package, fn):
-  """Start logging process.
+@contextlib.contextmanager
+def DeviceConnection(device,
+                     package=DEFAULT_CHROME_PACKAGE,
+                     hostname=DEVTOOLS_HOSTNAME,
+                     port=DEVTOOLS_PORT):
+  """Context for starting recording on a device.
 
-  Sets up any device and tracing appropriately and then executes the core
-  logging function.
+  Sets up and restores any device and tracing appropriately
 
   Args:
-    device: Android device, or None for a local run.
+    device: Android device, or None for a local run (in which case chrome needs
+      to have been started with --remote-debugging-port=XXX).
     package: the key for chrome package info.
-    fn: the function to execute that launches chrome and performs the
-        appropriate instrumentation, see _Log*Internal().
 
   Returns:
-    As fn() returns.
+    A context manager type which evaluates to a DevToolsConnection.
   """
   package_info = constants.PACKAGE_INFO[package]
   command_line_path = '/data/local/chrome-command-line'
   new_flags = ['--enable-test-events',
-               '--remote-debugging-port=%d' % DEVTOOLS_PORT]
+               '--remote-debugging-port=%d' % port]
   if device:
     _SetUpDevice(device, package_info)
-  with FlagChanger(device, command_line_path, new_flags):
+  with FlagReplacer(device, command_line_path, new_flags):
     if device:
       start_intent = intent.Intent(
           package=package_info.package, activity=package_info.activity,
@@ -92,6 +98,25 @@ def SetUpAndExecute(device, package, fn):
       device.StartActivity(start_intent, blocking=True)
       time.sleep(2)
     # If no device, we don't care about chrome startup so skip the about page.
-    with ForwardPort(device, 'tcp:%d' % DEVTOOLS_PORT,
+    with ForwardPort(device, 'tcp:%d' % port,
                      'localabstract:chrome_devtools_remote'):
-      return fn()
+      yield devtools_monitor.DevToolsConnection(hostname, port)
+
+
+def SetUpAndExecute(device, package, fn):
+  """Start logging process.
+
+  Wrapper for DeviceConnection for those functionally inclined.
+
+  Args:
+    device: Android device, or None for a local run.
+    package: the key for chrome package info.
+    fn: the function to execute that launches chrome and performs the
+        appropriate instrumentation. The function will receive a
+        DevToolsConnection as its sole parameter.
+
+  Returns:
+    As fn() returns.
+  """
+  with DeviceConnection(device, package) as connection:
+    return fn(connection)
diff --git a/tools/android/loading/devtools_monitor.py b/tools/android/loading/devtools_monitor.py
index fc652d2..5e8470b 100644
--- a/tools/android/loading/devtools_monitor.py
+++ b/tools/android/loading/devtools_monitor.py
@@ -24,9 +24,62 @@ class DevToolsConnectionException(Exception):
     logging.warning("DevToolsConnectionException: " + message)
 
 
+# Taken from telemetry.internal.backends.chrome_inspector.tracing_backend.
+# TODO(mattcary): combine this with the above and export?
+class _StreamReader(object):
+  def __init__(self, inspector, stream_handle):
+    self._inspector_websocket = inspector
+    self._handle = stream_handle
+    self._callback = None
+    self._data = None
+
+  def Read(self, callback):
+    # Do not allow the instance of this class to be reused, as
+    # we only read data sequentially at the moment, so a stream
+    # can only be read once.
+    assert not self._callback
+    self._data = []
+    self._callback = callback
+    self._ReadChunkFromStream()
+    # Queue one extra read ahead to avoid latency.
+    self._ReadChunkFromStream()
+
+  def _ReadChunkFromStream(self):
+    # Limit max block size to avoid fragmenting memory in sock.recv(),
+    # (see https://github.com/liris/websocket-client/issues/163 for details)
+    req = {'method': 'IO.read', 'params': {
+        'handle': self._handle, 'size': 32768}}
+    self._inspector_websocket.AsyncRequest(req, self._GotChunkFromStream)
+
+  def _GotChunkFromStream(self, response):
+    # Quietly discard responses from reads queued ahead after EOF.
+    if self._data is None:
+      return
+    if 'error' in response:
+      raise DevToolsConnectionException(
+          'Reading trace failed: %s' % response['error']['message'])
+    result = response['result']
+    self._data.append(result['data'])
+    if not result.get('eof', False):
+      self._ReadChunkFromStream()
+      return
+    req = {'method': 'IO.close', 'params': {'handle': self._handle}}
+    self._inspector_websocket.SendAndIgnoreResponse(req)
+    trace_string = ''.join(self._data)
+    self._data = None
+    self._callback(trace_string)
+
+
 class DevToolsConnection(object):
   """Handles the communication with a DevTools server.
   """
+  TRACING_DOMAIN = 'Tracing'
+  TRACING_END_METHOD = 'Tracing.end'
+  TRACING_DATA_METHOD = 'Tracing.dataCollected'
+  TRACING_DONE_EVENT = 'Tracing.tracingComplete'
+  TRACING_STREAM_EVENT = 'Tracing.tracingComplete'  # Same as TRACING_DONE.
+  TRACING_TIMEOUT = 300
+
   def __init__(self, hostname, port):
     """Initializes the connection with a DevTools server.
 
@@ -35,8 +88,11 @@ class DevToolsConnection(object):
       port: port number.
     """
     self._ws = self._Connect(hostname, port)
-    self._listeners = {}
+    self._event_listeners = {}
+    self._domain_listeners = {}
     self._domains_to_enable = set()
+    self._tearing_down_tracing = False
+    self._set_up = False
     self._please_stop = False
 
   def RegisterListener(self, name, listener):
@@ -45,12 +101,16 @@ class DevToolsConnection(object):
     Also takes care of enabling the relevant domain before starting monitoring.
 
     Args:
-      name: (str) Event the listener wants to listen to, e.g.
-            Network.requestWillBeSent.
+      name: (str) Domain or event the listener wants to listen to, e.g.
+            "Network.requestWillBeSent" or "Tracing".
       listener: (Listener) listener instance.
     """
-    domain = name[:name.index('.')]
-    self._listeners[name] = listener
+    if '.' in name:
+      domain = name[:name.index('.')]
+      self._event_listeners[name] = listener
+    else:
+      domain = name
+      self._domain_listeners[domain] = listener
     self._domains_to_enable.add(domain)
 
   def UnregisterListener(self, listener):
@@ -59,10 +119,14 @@ class DevToolsConnection(object):
     Args:
       listener: (Listener) listener to unregister.
     """
-    keys = [k for (k, v) in self._listeners if v is listener]
+    keys = ([k for k, l in self._event_listeners if l is listener] +
+            [k for k, l in self._domain_listeners if l is listener])
     assert keys, "Removing non-existent listener"
     for key in keys:
-      del(self._listeners[key])
+      if key in self._event_listeners:
+        del(self._event_listeners[key])
+      if key in self._domain_listeners:
+        del(self._domain_listeners[key])
 
   def SyncRequest(self, method, params=None):
     """Issues a synchronous request to the DevTools server.
@@ -91,41 +155,103 @@ class DevToolsConnection(object):
       request['params'] = params
     self._ws.SendAndIgnoreResponse(request)
 
+  def SyncRequestNoResponse(self, method, params=None):
+    """As SyncRequest, but asserts that no meaningful response was received.
+
+    Args:
+      method: (str) Method.
+      params: (dict) Optional parameters to the request.
+    """
+    result = self.SyncRequest(method, params)
+    if 'error' in result or ('result' in result and
+                             result['result']):
+      raise DevToolsConnectionException(
+          'Unexpected response for %s: %s' % (method, result))
+
   def SetUpMonitoring(self):
     for domain in self._domains_to_enable:
       self._ws.RegisterDomain(domain, self._OnDataReceived)
-      self.SyncRequest('%s.enable' % domain)
+      if domain != self.TRACING_DOMAIN:
+        self.SyncRequestNoResponse('%s.enable' % domain)
+        # Tracing setup must be done by the tracing track to control filtering
+        # and output.
+    self._tearing_down_tracing = False
+    self._set_up = True
 
   def StartMonitoring(self):
     """Starts monitoring.
 
     DevToolsConnection.SetUpMonitoring() has to be called first.
     """
-    while not self._please_stop:
-      try:
-        self._ws.DispatchNotifications()
-      except websocket.WebSocketTimeoutException:
-        break
-    if not self._please_stop:
-      logging.warning('Monitoring stopped on a timeout.')
+    assert self._set_up, 'DevToolsConnection.SetUpMonitoring not called.'
+    self._Dispatch()
     self._TearDownMonitoring()
 
   def StopMonitoring(self):
     """Stops the monitoring."""
     self._please_stop = True
 
+  def _Dispatch(self, kind='Monitoring', timeout=10):
+    self._please_stop = False
+    while not self._please_stop:
+      try:
+        self._ws.DispatchNotifications(timeout=timeout)
+      except websocket.WebSocketTimeoutException:
+        break
+    if not self._please_stop:
+      logging.warning('%s stopped on a timeout.' % kind)
+
   def _TearDownMonitoring(self):
+    if self.TRACING_DOMAIN in self._domains_to_enable:
+      logging.info('Fetching tracing')
+      self.SyncRequestNoResponse(self.TRACING_END_METHOD)
+      self._tearing_down_tracing = True
+      self._Dispatch(kind='Tracing', timeout=self.TRACING_TIMEOUT)
     for domain in self._domains_to_enable:
-      self.SyncRequest('%s.disable' % domain)
+      if domain != self.TRACING_DOMAIN:
+        self.SyncRequest('%s.disable' % domain)
       self._ws.UnregisterDomain(domain)
     self._domains_to_enable.clear()
-    self._listeners.clear()
+    self._domain_listeners.clear()
+    self._event_listeners.clear()
 
   def _OnDataReceived(self, msg):
-    method = msg.get('method', None)
-    if method not in self._listeners:
+    if 'method' not in msg:
+      raise DevToolsConnectionException('Malformed message: %s' % msg)
+    method = msg['method']
+    domain = method[:method.index('.')]
+
+    if self._tearing_down_tracing and method == self.TRACING_STREAM_EVENT:
+      stream_handle = msg.get('params', {}).get('stream')
+      if not stream_handle:
+        self._tearing_down_tracing = False
+        self.StopMonitoring()
+        # Fall through to regular dispatching.
+      else:
+        _StreamReader(self._ws, stream_handle).Read(self._TracingStreamDone)
+        # Skip regular dispatching.
+        return
+
+    if (method not in self._event_listeners and
+        domain not in self._domain_listeners):
       return
-    self._listeners[method].Handle(method, msg)
+    if method in self._event_listeners:
+      self._event_listeners[method].Handle(method, msg)
+    if domain in self._domain_listeners:
+      self._domain_listeners[domain].Handle(method, msg)
+    if self._tearing_down_tracing and method == self.TRACING_DONE_EVENT:
+      self._tearing_down_tracing = False
+      self.StopMonitoring()
+
+  def _TracingStreamDone(self, data):
+    tracing_events = json.loads(data)
+    for evt in tracing_events:
+      self._OnDataReceived({'method': self.TRACING_DATA_METHOD,
+                            'params': {'value': [evt]}})
+      if self._please_stop:
+        break
+    self._tearing_down_tracing = False
+    self.StopMonitoring()
 
   @classmethod
   def _GetWebSocketUrl(cls, hostname, port):
diff --git a/tools/android/loading/trace_recorder.py b/tools/android/loading/trace_recorder.py
index 6e638c4..cb9aa7a 100755
--- a/tools/android/loading/trace_recorder.py
+++ b/tools/android/loading/trace_recorder.py
@@ -24,7 +24,7 @@ import devtools_monitor
 class PageTrack(devtools_monitor.Track):
   """Records the events from the page track."""
   def __init__(self, connection):
-    super(PageTrack, self).__init__()
+    super(PageTrack, self).__init__(connection)
     self._connection = connection
     self._events = []
     self._main_frame_id = None
@@ -67,9 +67,8 @@ class AndroidTraceRecorder(object):
     self.devtools_connection = None
     self.page_track = None
 
-  def Go(self):
-    self.devtools_connection = devtools_monitor.DevToolsConnection(
-        device_setup.DEVTOOLS_HOSTNAME, device_setup.DEVTOOLS_PORT)
+  def Go(self, connection):
+    self.devtools_connection = connection
     self.page_track = PageTrack(self.devtools_connection)
 
     self.devtools_connection.SetUpMonitoring()
diff --git a/tools/android/loading/trace_to_chrome_trace.py b/tools/android/loading/trace_to_chrome_trace.py
new file mode 100755
index 0000000..998614f3
--- /dev/null
+++ b/tools/android/loading/trace_to_chrome_trace.py
@@ -0,0 +1,23 @@
+#! /usr/bin/python
+# Copyright 2015 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.
+
+"""Convert trace output for Chrome.
+
+Take the tracing track output from tracing_driver.py to a zip'd json that can be
+loading by chrome devtools tracing.
+"""
+
+import argparse
+import gzip
+import json
+
+if __name__ == '__main__':
+  parser = argparse.ArgumentParser()
+  parser.add_argument('input')
+  parser.add_argument('output')
+  args = parser.parse_args()
+  with gzip.GzipFile(args.output, 'w') as output_f, file(args.input) as input_f:
+    events = json.load(input_f)
+    json.dump({'traceEvents': events, 'metadata': {}}, output_f)
diff --git a/tools/android/loading/tracing.py b/tools/android/loading/tracing.py
new file mode 100644
index 0000000..83ad38c
--- /dev/null
+++ b/tools/android/loading/tracing.py
@@ -0,0 +1,38 @@
+# Copyright 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.
+
+"""Monitor tracing events on chrome via chrome remote debugging."""
+
+import devtools_monitor
+
+class TracingTrack(devtools_monitor.Track):
+  def __init__(self, connection, categories=None, fetch_stream=False):
+    """Initialize this TracingTrack.
+
+    Args:
+      connection: a DevToolsConnection.
+      categories: None, or a string, or list of strings, of tracing categories
+        to filter.
+
+      fetch_stream: if true, use a websocket stream to fetch tracing data rather
+        than dataCollected events. It appears based on very limited testing that
+        a stream is slower than the default reporting as dataCollected events.
+    """
+    super(TracingTrack, self).__init__(connection)
+    connection.RegisterListener('Tracing.dataCollected', self)
+    params = {}
+    if categories:
+      params['categories'] = (categories if type(categories) is str
+                              else ','.join(categories))
+    if fetch_stream:
+      params['transferMode'] = 'ReturnAsStream'
+
+    connection.SyncRequestNoResponse('Tracing.start', params)
+    self._events = []
+
+  def Handle(self, method, event):
+    self._events.append(event)
+
+  def GetEvents(self):
+    return self._events
diff --git a/tools/android/loading/tracing_driver.py b/tools/android/loading/tracing_driver.py
new file mode 100755
index 0000000..0996d34
--- /dev/null
+++ b/tools/android/loading/tracing_driver.py
@@ -0,0 +1,49 @@
+#! /usr/bin/python
+# Copyright 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.
+
+"""Drive TracingConnection"""
+
+import argparse
+import json
+import logging
+import os.path
+import sys
+
+_SRC_DIR = os.path.abspath(os.path.join(
+    os.path.dirname(__file__), '..', '..', '..'))
+
+sys.path.append(os.path.join(_SRC_DIR, 'third_party', 'catapult', 'devil'))
+from devil.android import device_utils
+
+sys.path.append(os.path.join(_SRC_DIR, 'build', 'android'))
+import device_setup
+import trace_recorder
+import tracing
+
+
+def main():
+  logging.basicConfig(level=logging.INFO)
+  parser = argparse.ArgumentParser()
+  parser.add_argument('--url', required=True)
+  parser.add_argument('--output', required=True)
+  args = parser.parse_args()
+  url = args.url
+  if not url.startswith('http'):
+    url = 'http://' + url
+  device = device_utils.DeviceUtils.HealthyDevices()[0]
+  with file(args.output, 'w') as output, \
+       file(args.output + '.page', 'w') as page_output, \
+       device_setup.DeviceConnection(device) as connection:
+    track = tracing.TracingTrack(connection, fetch_stream=False)
+    page = trace_recorder.PageTrack(connection)
+    connection.SetUpMonitoring()
+    connection.SendAndIgnoreResponse('Page.navigate', {'url': url})
+    connection.StartMonitoring()
+    json.dump(page.GetEvents(), page_output, sort_keys=True, indent=2)
+    json.dump(track.GetEvents(), output, sort_keys=True, indent=2)
+
+
+if __name__ == '__main__':
+  main()