tools/android/loading: Add the renderer activity to the PNG output.

Adds edge annotations showing the amount of time spent executing the
initiating script, parsing the initiating document, and doing "other"
work.

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

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

12 files changed, 364 insertions, 137 deletions

diff --git a/tools/android/loading/activity_lens.py b/tools/android/loading/activity_lens.py
index 2973ac4..92ffd14 100644
--- a/tools/android/loading/activity_lens.py
+++ b/tools/android/loading/activity_lens.py
@@ -12,6 +12,8 @@ import collections
 import logging
 import operator
 
+import request_track
+
 
 class ActivityLens(object):
   """Reconstructs the activity of the main renderer thread between requests."""
@@ -24,6 +26,8 @@ class ActivityLens(object):
     self._trace = trace
     events = trace.tracing_track.GetEvents()
     self._renderer_main_tid = self._GetRendererMainThreadId(events)
+    self._tracing = self._trace.tracing_track.TracingTrackForThread(
+        self._renderer_main_tid)
 
   @classmethod
   def _GetRendererMainThreadId(cls, events):
@@ -60,9 +64,8 @@ class ActivityLens(object):
              tid_events_counts[0][1], tid_events_counts[1][1]))
     return tid_events_counts[0][0]
 
-  def _OverlappingEventsForTid(self, tid, start_msec, end_msec):
-    events = self._trace.tracing_track.OverlappingEvents(start_msec, end_msec)
-    return [e for e in events if e.tracing_event['tid'] == tid]
+  def _OverlappingMainRendererThreadEvents(self, start_msec, end_msec):
+    return self._tracing.OverlappingEvents(start_msec, end_msec)
 
   @classmethod
   def _ClampedDuration(cls, event, start_msec, end_msec):
@@ -136,7 +139,7 @@ class ActivityLens(object):
       url_to_duration[url] += clamped_duration
     return dict(url_to_duration)
 
-  def ExplainEdgeCost(self, dep):
+  def GenerateEdgeActivity(self, dep):
     """For a dependency between two requests, returns the renderer activity
     breakdown.
 
@@ -148,19 +151,48 @@ class ActivityLens(object):
       {'edge_cost': (float) ms, 'busy': (float) ms,
        'parsing': {'url' -> time_ms}, 'script' -> {'url' -> time_ms}}
     """
-    (first, second, _) = dep
-    # TODO(lizeb): Refactor the edge cost computations.
-    start_msec = first.start_msec
-    end_msec = second.start_msec
+    (first, second, reason) = dep
+    (start_msec, end_msec) = request_track.IntervalBetween(
+        first, second, reason)
     assert end_msec - start_msec >= 0.
-    tid = self._renderer_main_tid
-    events = self._OverlappingEventsForTid(tid, start_msec, end_msec)
+    events = self._OverlappingMainRendererThreadEvents(start_msec, end_msec)
     result = {'edge_cost': end_msec - start_msec,
               'busy': self._ThreadBusiness(events, start_msec, end_msec),
               'parsing': self._Parsing(events, start_msec, end_msec),
               'script': self._ScriptsExecuting(events, start_msec, end_msec)}
     return result
 
+  def BreakdownEdgeActivityByInitiator(self, dep):
+    """For a dependency between two requests, categorizes the renderer activity.
+
+    Args:
+      dep: (Request, Request, str) As returned from
+           RequestDependencyLens.GetRequestDependencies().
+
+    Returns:
+      {'script': float, 'parsing': float, 'other': float, 'unknown': float}
+      where the values are durations in ms:
+      - script: The initiating file was executing.
+      - parsing: The initiating file was being parsed.
+      - other: Other scripts and/or parsing activities.
+      - unknown: Activity which is not associated with a URL.
+    """
+    activity = self.GenerateEdgeActivity(dep)
+    related = {'script': 0, 'parsing': 0, 'other_url': 0, 'unknown_url': 0}
+    for kind in ('script', 'parsing'):
+      for (script_name, duration_ms) in activity[kind].items():
+        if not script_name:
+          related['unknown_url'] += duration_ms
+        elif script_name == dep[0].url:
+          related[kind] += duration_ms
+        else:
+          # A lot of "ParseHTML" tasks are mostly about executing
+          # scripts. Don't double-count.
+          # TODO(lizeb): Better handle TraceEvents nesting.
+          if kind == 'script':
+            related['other_url'] += duration_ms
+    return related
+
 
 if __name__ == '__main__':
   import sys
@@ -176,4 +208,4 @@ if __name__ == '__main__':
       loading_trace)
   deps = dependencies_lens.GetRequestDependencies()
   for requests_dep in deps:
-    print activity_lens.ExplainEdgeCost(requests_dep)
+    print activity_lens.GenerateEdgeActivity(requests_dep)
diff --git a/tools/android/loading/activity_lens_unittest.py b/tools/android/loading/activity_lens_unittest.py
index a84c864..3b4062f 100644
--- a/tools/android/loading/activity_lens_unittest.py
+++ b/tools/android/loading/activity_lens_unittest.py
@@ -5,6 +5,7 @@
 import unittest
 
 from activity_lens import ActivityLens
+import test_utils
 import tracing
 
 
@@ -170,6 +171,63 @@ class ActivityLensTestCast(unittest.TestCase):
     self.assertTrue(html_url in ActivityLens._Parsing(events, 0, 1000))
     self.assertEquals(42, ActivityLens._Parsing(events, 0, 1000)[html_url])
 
+  def testBreakdownEdgeActivityByInitiator(self):
+    requests = [test_utils.MakeRequest(0, 1, 10, 20, 30),
+                test_utils.MakeRequest(0, 1, 50, 60, 70)]
+    raw_events = [
+        {u'args': {u'beginData': {u'url': requests[0].url}},
+         u'cat': u'devtools.timeline',
+         u'dur': 12 * 1000,
+         u'name': u'ParseHTML',
+         u'ph': u'X',
+         u'pid': 1,
+         u'tid': 1,
+         u'ts': 25 * 1000},
+        {u'args': {u'data': {'scriptName': requests[0].url}},
+         u'cat': u'devtools.timeline,v8',
+         u'dur': 0,
+         u'name': u'EvaluateScript',
+         u'ph': u'X',
+         u'pid': 1,
+         u'tid': 1,
+         u'ts': 0}]
+    activity = self._ActivityLens(requests, raw_events)
+    dep = (requests[0], requests[1], 'parser')
+    self.assertEquals(
+        {'script': 0, 'parsing': 12, 'other_url': 0, 'unknown_url': 0},
+        activity.BreakdownEdgeActivityByInitiator(dep))
+    dep = (requests[0], requests[1], 'other')
+    # Truncating the event from the parent xrequest end.
+    self.assertEquals(
+        {'script': 0, 'parsing': 7, 'other_url': 0, 'unknown_url': 0},
+        activity.BreakdownEdgeActivityByInitiator(dep))
+    # Unknown URL
+    raw_events[0]['args']['beginData']['url'] = None
+    activity = self._ActivityLens(requests, raw_events)
+    dep = (requests[0], requests[1], 'parser')
+    self.assertEquals(
+        {'script': 0, 'parsing': 0, 'other_url': 0, 'unknown_url': 12},
+        activity.BreakdownEdgeActivityByInitiator(dep))
+    # Script
+    raw_events[1]['ts'] = 40 * 1000
+    raw_events[1]['dur'] = 6 * 1000
+    activity = self._ActivityLens(requests, raw_events)
+    dep = (requests[0], requests[1], 'script')
+    self.assertEquals(
+        {'script': 6, 'parsing': 0, 'other_url': 0, 'unknown_url': 7},
+        activity.BreakdownEdgeActivityByInitiator(dep))
+    # Other URL
+    raw_events[1]['args']['data']['scriptName'] = 'http://other.com/url'
+    activity = self._ActivityLens(requests, raw_events)
+    self.assertEquals(
+        {'script': 0., 'parsing': 0., 'other_url': 6., 'unknown_url': 7.},
+        activity.BreakdownEdgeActivityByInitiator(dep))
+
+  def _ActivityLens(self, requests, raw_events):
+    loading_trace = test_utils.LoadingTraceFromEvents(
+        requests, None, raw_events)
+    return ActivityLens(loading_trace)
+
 
 if __name__ == '__main__':
   unittest.main()
diff --git a/tools/android/loading/analyze.py b/tools/android/loading/analyze.py
index fdf18da..1c31de0 100755
--- a/tools/android/loading/analyze.py
+++ b/tools/android/loading/analyze.py
@@ -24,6 +24,7 @@ sys.path.append(os.path.join(_SRC_DIR, 'build', 'android'))
 import devil_chromium
 from pylib import constants
 
+import activity_lens
 import content_classification_lens
 import device_setup
 import frame_load_lens
@@ -158,7 +159,9 @@ def _ProcessRequests(filename):
         content_classification_lens.ContentClassificationLens.WithRulesFiles(
             trace, OPTIONS.ad_rules, OPTIONS.tracking_rules))
     frame_lens = frame_load_lens.FrameLoadLens(trace)
-    graph = loading_model.ResourceGraph(trace, content_lens, frame_lens)
+    activity = activity_lens.ActivityLens(trace)
+    graph = loading_model.ResourceGraph(
+        trace, content_lens, frame_lens, activity)
     if OPTIONS.noads:
       graph.Set(node_filter=graph.FilterAds)
     return graph
diff --git a/tools/android/loading/loading_model.py b/tools/android/loading/loading_model.py
index d2889e8..5deec03 100644
--- a/tools/android/loading/loading_model.py
+++ b/tools/android/loading/loading_model.py
@@ -20,17 +20,22 @@ import os
 import urlparse
 import sys
 
+import activity_lens
 import dag
 import loading_trace
 import request_dependencies_lens
+import request_track
 
 class ResourceGraph(object):
-  """A model of loading by a DAG (tree?) of resource dependancies.
+  """A model of loading by a DAG of resource dependencies.
 
-  Set parameters:
-    cache_all: if true, assume zero loading time for all resources.
+  See model parameters in Set().
   """
-  def __init__(self, trace, content_lens=None, frame_lens=None):
+  EDGE_KIND_KEY = 'edge_kind'
+  EDGE_KINDS = request_track.Request.INITIATORS + (
+      'script_inferred', 'after-load', 'before-load', 'timing')
+  def __init__(self, trace, content_lens=None, frame_lens=None,
+               activity=None):
     """Create from a LoadingTrace (or json of a trace).
 
     Args:
@@ -38,12 +43,15 @@ class ResourceGraph(object):
       content_lens: (ContentClassificationLens) Lens used to annotate the
                     nodes, or None.
       frame_lens: (FrameLoadLens) Lens used to augment graph with load nodes.
+      activity:   (ActivityLens) Lens used to augment the edges with the
+                   activity.
     """
     if type(trace) == dict:
       trace = loading_trace.LoadingTrace.FromJsonDict(trace)
     self._trace = trace
     self._content_lens = content_lens
     self._frame_lens = frame_lens
+    self._activity_lens = activity
     self._BuildDag(trace)
     # Sort before splitting children so that we can correctly dectect if a
     # reparented child is actually a dependency for a child of its new parent.
@@ -58,7 +66,7 @@ class ResourceGraph(object):
 
   @classmethod
   def CheckImageLoadConsistency(cls, g1, g2):
-    """Check that images have the same dependancies between ResourceGraphs.
+    """Check that images have the same dependencies between ResourceGraphs.
 
     Image resources are identified by their short names.
 
@@ -101,10 +109,10 @@ class ResourceGraph(object):
     """Set model parameters.
 
     TODO(mattcary): add parameters for caching certain types of resources (just
-    scripts, just cachable, etc).
+    scripts, just cacheable, etc).
 
     Args:
-      cache_all: boolean that if true ignores emperical resource load times for
+      cache_all: boolean that if true ignores empirical resource load times for
         all resources.
       node_filter: a Node->boolean used to restrict the graph for most
         operations.
@@ -167,7 +175,6 @@ class ResourceGraph(object):
       if self._node_filter(n.Node()) and n.Url() in other_map:
         yield(n, other_map[n.Url()])
 
-
   def Cost(self, path_list=None):
     """Compute cost of current model.
 
@@ -279,9 +286,9 @@ class ResourceGraph(object):
     """Convenience function for redirecting to NodeInfo."""
     return self.NodeInfo(parent).EdgeCost(self.NodeInfo(child))
 
-  def EdgeAnnotation(self, parent, child):
+  def EdgeAnnotations(self, parent, child):
     """Convenience function for redirecting to NodeInfo."""
-    return self.NodeInfo(parent).EdgeAnnotation(self.NodeInfo(child))
+    return self.NodeInfo(parent).EdgeAnnotations(self.NodeInfo(child))
 
   ##
   ## Internal items
@@ -372,7 +379,7 @@ class ResourceGraph(object):
     def EndTime(self):
       return self.StartTime() + self._node_cost
 
-    def EdgeAnnotation(self, s):
+    def EdgeAnnotations(self, s):
       assert s.Node() in self.Node().Successors()
       return self._edge_annotations.get(s, [])
 
@@ -411,9 +418,9 @@ class ResourceGraph(object):
       assert child.Node() in self._node.Successors()
       self._edge_costs[child] = cost
 
-    def AddEdgeAnnotation(self, s, annotation):
+    def AddEdgeAnnotations(self, s, annotations):
       assert s.Node() in self._node.Successors()
-      self._edge_annotations.setdefault(s, []).append(annotation)
+      self._edge_annotations.setdefault(s, {}).update(annotations)
 
     def ReparentTo(self, old_parent, new_parent):
       """Move costs and annotatations from old_parent to new_parent.
@@ -429,13 +436,12 @@ class ResourceGraph(object):
       """
       assert old_parent.Node() in self.Node().Predecessors()
       assert new_parent.Node() not in self.Node().Predecessors()
-      edge_annotations = old_parent._edge_annotations.pop(self, [])
+      edge_annotations = old_parent._edge_annotations.pop(self, {})
       edge_cost =  old_parent._edge_costs.pop(self)
       old_parent.Node().RemoveSuccessor(self.Node())
       new_parent.Node().AddSuccessor(self.Node())
       new_parent.SetEdgeCost(self, edge_cost)
-      for a in edge_annotations:
-        new_parent.AddEdgeAnnotation(self, a)
+      new_parent.AddEdgeAnnotations(self, edge_annotations)
 
     def __eq__(self, o):
       """Note this works whether o is a Node or a NodeInfo."""
@@ -473,10 +479,11 @@ class ResourceGraph(object):
 
     dependencies = request_dependencies_lens.RequestDependencyLens(
         trace).GetRequestDependencies()
-    for parent_rq, child_rq, reason in dependencies:
+    for dep in dependencies:
+      (parent_rq, child_rq, reason) = dep
       parent = self._node_info[index_by_request[parent_rq]]
       child = self._node_info[index_by_request[child_rq]]
-      edge_cost = child.StartTime() - parent.EndTime()
+      edge_cost = request_track.TimeBetween(parent_rq, child_rq, reason)
       if edge_cost < 0:
         edge_cost = 0
         if child.StartTime() < parent.StartTime():
@@ -486,7 +493,10 @@ class ResourceGraph(object):
           # fair amount in practice.
       parent.Node().AddSuccessor(child.Node())
       parent.SetEdgeCost(child, edge_cost)
-      parent.AddEdgeAnnotation(child, reason)
+      parent.AddEdgeAnnotations(child, {self.EDGE_KIND_KEY: reason})
+      if self._activity_lens:
+        activity = self._activity_lens.BreakdownEdgeActivityByInitiator(dep)
+        parent.AddEdgeAnnotations(child, {'activity': activity})
 
     self._AugmentFrameLoads(index_by_request)
 
@@ -507,12 +517,12 @@ class ResourceGraph(object):
       parent = self._node_info[load_index_to_node[load_idx]]
       child = self._node_info[index_by_request[rq]]
       parent.Node().AddSuccessor(child.Node())
-      parent.AddEdgeAnnotation(child, 'after-load')
+      parent.AddEdgeAnnotations(child, {self.EDGE_KIND_KEY: 'after-load'})
     for rq, load_idx in frame_deps[1]:
       child = self._node_info[load_index_to_node[load_idx]]
       parent = self._node_info[index_by_request[rq]]
       parent.Node().AddSuccessor(child.Node())
-      parent.AddEdgeAnnotation(child, 'before-load')
+      parent.AddEdgeAnnotations(child, {self.EDGE_KIND_KEY: 'before-load'})
 
   def _SplitChildrenByTime(self, parent):
     """Split children of a node by request times.
@@ -535,7 +545,7 @@ class ResourceGraph(object):
     This is refined by only considering assets which we believe actually create
     a dependency. We only split if the original parent is a script, and the new
     parent a data file. We confirm these relationships heuristically by loading
-    pages multiple times and ensuring that dependacies do not change; see
+    pages multiple times and ensuring that dependencies do not change; see
     CheckImageLoadConsistency() for details.
 
     We incorporate this heuristic by skipping over any non-script/json resources
@@ -583,7 +593,8 @@ class ResourceGraph(object):
                   # eligible.
       if children_by_end_time[end_mark].EndTime() <= current.StartTime():
         current.ReparentTo(parent, children_by_end_time[end_mark])
-        children_by_end_time[end_mark].AddEdgeAnnotation(current, 'timing')
+        children_by_end_time[end_mark].AddEdgeAnnotations(
+            current, {self.EDGE_KIND_KEY: 'timing'})
 
   def _ExtractImages(self):
     """Return interesting image resources.
diff --git a/tools/android/loading/loading_model_unittest.py b/tools/android/loading/loading_model_unittest.py
index 7afe8ef..44dcbae3 100644
--- a/tools/android/loading/loading_model_unittest.py
+++ b/tools/android/loading/loading_model_unittest.py
@@ -24,8 +24,9 @@ class SimpleLens(object):
       assert rq.url not in url_to_rq
       url_to_rq[rq.url] = rq
     for rq in self._trace.request_track.GetEvents():
-      if rq.initiator in url_to_rq:
-        deps.append(( url_to_rq[rq.initiator], rq, ''))
+      initiating_url = rq.initiator['url']
+      if initiating_url in url_to_rq:
+        deps.append((url_to_rq[initiating_url], rq, rq.initiator['type']))
     return deps
 
 
@@ -34,31 +35,10 @@ class LoadingModelTestCase(unittest.TestCase):
   def setUp(self):
     self.old_lens = request_dependencies_lens.RequestDependencyLens
     request_dependencies_lens.RequestDependencyLens = SimpleLens
-    self._next_request_id = 0
 
   def tearDown(self):
     request_dependencies_lens.RequestDependencyLens = self.old_lens
 
-  def MakeParserRequest(self, url, source_url, start_time, end_time,
-                        magic_content_type=False):
-    timing = request_track.TimingAsList(request_track.TimingFromDict({
-        # connectEnd should be ignored.
-        'connectEnd': (end_time - start_time) / 2,
-        'receiveHeadersEnd': end_time - start_time,
-        'requestTime': start_time / 1000.0}))
-    rq = request_track.Request.FromJsonDict({
-        'timestamp': start_time / 1000.0,
-        'request_id': self._next_request_id,
-        'url': 'http://' + str(url),
-        'initiator': 'http://' + str(source_url),
-        'response_headers': {'Content-Type':
-                             'null' if not magic_content_type
-                             else 'magic-debug-content' },
-        'timing': timing
-        })
-    self._next_request_id += 1
-    return rq
-
   def MakeGraph(self, requests):
     return loading_model.ResourceGraph(
         test_utils.LoadingTraceFromEvents(requests))
@@ -72,10 +52,11 @@ class LoadingModelTestCase(unittest.TestCase):
   def test_DictConstruction(self):
     graph = loading_model.ResourceGraph(
         {'request_track': {
-            'events': [self.MakeParserRequest(0, 'null', 100, 101).ToJsonDict(),
-                       self.MakeParserRequest(1, 0, 102, 103).ToJsonDict(),
-                       self.MakeParserRequest(2, 0, 102, 103).ToJsonDict(),
-                       self.MakeParserRequest(3, 2, 104, 105).ToJsonDict()],
+            'events': [
+                test_utils.MakeRequest(0, 'null', 100, 100.5, 101).ToJsonDict(),
+                test_utils.MakeRequest(1, 0, 102, 102.5, 103).ToJsonDict(),
+                test_utils.MakeRequest(2, 0, 102, 102.5, 103).ToJsonDict(),
+                test_utils.MakeRequest(3, 2, 104, 114.5, 105).ToJsonDict()],
             'metadata': {
                 request_track.RequestTrack._DUPLICATES_KEY: 0,
                 request_track.RequestTrack._INCONSISTENT_INITIATORS_KEY: 0}},
@@ -89,13 +70,13 @@ class LoadingModelTestCase(unittest.TestCase):
     self.assertEqual(self.SuccessorIndicies(graph._nodes[3]), [])
 
   def test_Costing(self):
-    requests = [self.MakeParserRequest(0, 'null', 100, 110),
-                self.MakeParserRequest(1, 0, 115, 120),
-                self.MakeParserRequest(2, 0, 112, 120),
-                self.MakeParserRequest(3, 1, 122, 126),
-                self.MakeParserRequest(4, 3, 127, 128),
-                self.MakeParserRequest(5, 'null', 100, 105),
-                self.MakeParserRequest(6, 5, 105, 110)]
+    requests = [test_utils.MakeRequest(0, 'null', 100, 105, 110),
+                test_utils.MakeRequest(1, 0, 115, 117, 120),
+                test_utils.MakeRequest(2, 0, 112, 116, 120),
+                test_utils.MakeRequest(3, 1, 122, 124, 126),
+                test_utils.MakeRequest(4, 3, 127, 127.5, 128),
+                test_utils.MakeRequest(5, 'null', 100, 103, 105),
+                test_utils.MakeRequest(6, 5, 105, 107, 110)]
     graph = self.MakeGraph(requests)
     self.assertEqual(self.SuccessorIndicies(graph._nodes[0]), [1, 2])
     self.assertEqual(self.SuccessorIndicies(graph._nodes[1]), [3])
@@ -110,16 +91,16 @@ class LoadingModelTestCase(unittest.TestCase):
     self.assertEqual(8, graph.Cost())
 
   def test_MaxPath(self):
-    requests = [self.MakeParserRequest(0, 'null', 100, 110),
-                self.MakeParserRequest(1, 0, 115, 120),
-                self.MakeParserRequest(2, 0, 112, 120),
-                self.MakeParserRequest(3, 1, 122, 126),
-                self.MakeParserRequest(4, 3, 127, 128),
-                self.MakeParserRequest(5, 'null', 100, 105),
-                self.MakeParserRequest(6, 5, 105, 110)]
+    requests = [test_utils.MakeRequest(0, 'null', 100, 110, 111),
+                test_utils.MakeRequest(1, 0, 115, 120, 121),
+                test_utils.MakeRequest(2, 0, 112, 120, 121),
+                test_utils.MakeRequest(3, 1, 122, 126, 127),
+                test_utils.MakeRequest(4, 3, 127, 128, 129),
+                test_utils.MakeRequest(5, 'null', 100, 105, 106),
+                test_utils.MakeRequest(6, 5, 105, 110, 111)]
     graph = self.MakeGraph(requests)
     path_list = []
-    self.assertEqual(28, graph.Cost(path_list))
+    self.assertEqual(29, graph.Cost(path_list))
     self.assertEqual([0, 1, 3, 4], [n.Index() for n in path_list])
 
     # More interesting would be a test when a node has multiple predecessors,
@@ -127,16 +108,17 @@ class LoadingModelTestCase(unittest.TestCase):
 
   def test_TimingSplit(self):
     # Timing adds node 1 as a parent to 2 but not 3.
-    requests = [self.MakeParserRequest(0, 'null', 100, 110,
-                                       magic_content_type=True),
-                self.MakeParserRequest(1, 0, 115, 120,
-                                       magic_content_type=True),
-                self.MakeParserRequest(2, 0, 121, 122,
-                                       magic_content_type=True),
-                self.MakeParserRequest(3, 0, 112, 119,
-                                       magic_content_type=True),
-                self.MakeParserRequest(4, 2, 122, 126),
-                self.MakeParserRequest(5, 2, 122, 126)]
+    requests = [
+        test_utils.MakeRequest(0, 'null', 100, 110, 110,
+                               magic_content_type=True),
+        test_utils.MakeRequest(1, 0, 115, 120, 120,
+                               magic_content_type=True),
+        test_utils.MakeRequest(2, 0, 121, 122, 122,
+                               magic_content_type=True),
+        test_utils.MakeRequest(3, 0, 112, 119, 119,
+                               magic_content_type=True),
+        test_utils.MakeRequest(4, 2, 122, 126, 126),
+        test_utils.MakeRequest(5, 2, 122, 126, 126)]
     graph = self.MakeGraph(requests)
     self.assertEqual(self.SuccessorIndicies(graph._nodes[0]), [1, 3])
     self.assertEqual(self.SuccessorIndicies(graph._nodes[1]), [2])
@@ -147,8 +129,8 @@ class LoadingModelTestCase(unittest.TestCase):
     self.assertEqual(self.SortedIndicies(graph), [0, 1, 3, 2, 4, 5])
 
     # Change node 1 so it is a parent of 3, which becomes the parent of 2.
-    requests[1] = self.MakeParserRequest(1, 0, 110, 111,
-                                         magic_content_type=True)
+    requests[1] = test_utils.MakeRequest(
+        1, 0, 110, 111, 111, magic_content_type=True)
     graph = self.MakeGraph(requests)
     self.assertEqual(self.SuccessorIndicies(graph._nodes[0]), [1])
     self.assertEqual(self.SuccessorIndicies(graph._nodes[1]), [3])
@@ -159,13 +141,13 @@ class LoadingModelTestCase(unittest.TestCase):
     self.assertEqual(self.SortedIndicies(graph), [0, 1, 3, 2, 4, 5])
 
     # Add an initiator dependence to 1 that will become the parent of 3.
-    requests[1] = self.MakeParserRequest(1, 0, 110, 111,
-                                         magic_content_type=True)
-    requests.append(self.MakeParserRequest(6, 1, 111, 112))
+    requests[1] = test_utils.MakeRequest(
+        1, 0, 110, 111, 111, magic_content_type=True)
+    requests.append(test_utils.MakeRequest(6, 1, 111, 112, 112))
     graph = self.MakeGraph(requests)
     # Check it doesn't change until we change the content type of 6.
     self.assertEqual(self.SuccessorIndicies(graph._nodes[6]), [])
-    requests[6] = self.MakeParserRequest(6, 1, 111, 112,
+    requests[6] = test_utils.MakeRequest(6, 1, 111, 112, 112,
                                          magic_content_type=True)
     graph = self.MakeGraph(requests)
     self.assertEqual(self.SuccessorIndicies(graph._nodes[0]), [1])
@@ -179,12 +161,12 @@ class LoadingModelTestCase(unittest.TestCase):
 
   def test_TimingSplitImage(self):
     # If we're all image types, then we shouldn't split by timing.
-    requests = [self.MakeParserRequest(0, 'null', 100, 110),
-                self.MakeParserRequest(1, 0, 115, 120),
-                self.MakeParserRequest(2, 0, 121, 122),
-                self.MakeParserRequest(3, 0, 112, 119),
-                self.MakeParserRequest(4, 2, 122, 126),
-                self.MakeParserRequest(5, 2, 122, 126)]
+    requests = [test_utils.MakeRequest(0, 'null', 100, 110, 110),
+                test_utils.MakeRequest(1, 0, 115, 120, 120),
+                test_utils.MakeRequest(2, 0, 121, 122, 122),
+                test_utils.MakeRequest(3, 0, 112, 119, 119),
+                test_utils.MakeRequest(4, 2, 122, 126, 126),
+                test_utils.MakeRequest(5, 2, 122, 126, 126)]
     for r in requests:
       r.response_headers['Content-Type'] = 'image/gif'
     graph = self.MakeGraph(requests)
diff --git a/tools/android/loading/model_graph.py b/tools/android/loading/model_graph.py
index 5c0bf09..591bd7f 100644
--- a/tools/android/loading/model_graph.py
+++ b/tools/android/loading/model_graph.py
@@ -7,6 +7,8 @@
 import dag
 import itertools
 
+import loading_model
+
 
 class GraphVisualization(object):
   """Manipulate visual representations of a resource graph.
@@ -23,6 +25,7 @@ class GraphVisualization(object):
       'font':            'grey70',
       'image':           'orange',    # This probably catches gifs?
       'video':           'hotpink1',
+      'audio':           'hotpink2',
       }
 
   _CONTENT_TYPE_TO_COLOR = {
@@ -41,6 +44,19 @@ class GraphVisualization(object):
       'synthetic':       'yellow',
       }
 
+  _EDGE_KIND_TO_COLOR = {
+    'redirect': 'black',
+    'parser': 'red',
+    'script': 'blue',
+    'script_inferred': 'purple',
+    'after-load': 'forestgreen',
+    'before-load': 'forestgreen',
+  }
+
+  _ACTIVITY_TYPE_LABEL = (
+      ('script', 'S'), ('parsing', 'P'), ('other_url', 'O'),
+      ('unknown_url', 'U'))
+
   def __init__(self, graph):
     """Initialize.
 
@@ -98,22 +114,27 @@ class GraphVisualization(object):
         if s not in visited_nodes:
           continue
         style = 'color = orange'
-        annotations = self._graph.EdgeAnnotation(n, s)
-        if 'redirect' in annotations:
-          style = 'color = black'
-        elif 'parser' in annotations:
-          style = 'color = red'
-        elif 'stack' in annotations:
-          style = 'color = blue'
-        elif 'script_inferred' in annotations:
-          style = 'color = purple'
-        if 'after-load' in annotations or 'before-load' in annotations:
-          style = 'color = forestgreen'
-        if 'timing' in annotations:
+        label = '%.02f' % self._graph.EdgeCost(n, s)
+        annotations = self._graph.EdgeAnnotations(n, s)
+        edge_kind = annotations.get(
+            loading_model.ResourceGraph.EDGE_KIND_KEY, None)
+        assert ((edge_kind is None)
+                or (edge_kind in loading_model.ResourceGraph.EDGE_KINDS))
+        style = 'color = %s' % self._EDGE_KIND_TO_COLOR[edge_kind]
+        if edge_kind == 'timing':
           style += '; style=dashed'
         if self._graph.EdgeCost(n, s) > self._LONG_EDGE_THRESHOLD_MS:
           style += '; penwidth=5; weight=2'
-        arrow = '[%s; label="%s"]' % (style, self._graph.EdgeCost(n, s))
+
+        label = '%.02f' % self._graph.EdgeCost(n, s)
+        if 'activity' in annotations:
+          activity = annotations['activity']
+          separator = ' - '
+          for activity_type, activity_label in self._ACTIVITY_TYPE_LABEL:
+            label += '%s%s:%.02f ' % (
+                separator, activity_label, activity[activity_type])
+            separator = ' '
+        arrow = '[%s; label="%s"]' % (style, label)
         output.write('%d -> %d %s;\n' % (n.Index(), s.Index(), arrow))
     output.write('}\n')
 
diff --git a/tools/android/loading/model_graph_unittest.py b/tools/android/loading/model_graph_unittest.py
index 510e945..831b1e1 100644
--- a/tools/android/loading/model_graph_unittest.py
+++ b/tools/android/loading/model_graph_unittest.py
@@ -27,3 +27,7 @@ class ModelGraphTestCase(unittest.TestCase):
       graph = loading_model.ResourceGraph(trace=trace, frame_lens=frame_lens)
       visualization = model_graph.GraphVisualization(graph)
       visualization.OutputDot(tmp)
+
+
+if __name__ == '__main__':
+  unittest.main()
diff --git a/tools/android/loading/request_track.py b/tools/android/loading/request_track.py
index a19c5e5..89e3a5d 100644
--- a/tools/android/loading/request_track.py
+++ b/tools/android/loading/request_track.py
@@ -29,6 +29,40 @@ _TIMING_NAMES_MAPPING = {
 Timing = collections.namedtuple('Timing', _TIMING_NAMES_MAPPING.values())
 
 
+def IntervalBetween(first, second, reason):
+  """Returns the start and end of the inteval between two requests, in ms.
+
+  This is defined as:
+  - [first.headers, second.start] if reason is 'parser'. This is to account
+    for incremental parsing.
+  - [first.end, second.start] if reason is 'script', 'redirect' or 'other'.
+
+  Args:
+    first: (Request) First request.
+    second: (Request) Second request.
+    reason: (str) Link between the two requests, in Request.INITIATORS.
+
+  Returns:
+    (start_msec (float), end_msec (float)),
+  """
+  assert reason in Request.INITIATORS
+  second_ms = second.timing.request_time * 1000
+  if reason == 'parser':
+    first_offset_ms = first.timing.receive_headers_end
+  else:
+    first_offset_ms = max(
+        [0] + [t for f, t in first.timing._asdict().iteritems()
+               if f != 'request_time'])
+  return (first.timing.request_time * 1000 + first_offset_ms, second_ms)
+
+
+def TimeBetween(first, second, reason):
+  """(end_msec - start_msec), with the values as returned by IntervalBetween().
+  """
+  (first_ms, second_ms) = IntervalBetween(first, second, reason)
+  return second_ms - first_ms
+
+
 def TimingAsList(timing):
   """Transform Timing to a list, eg as is used in JSON output.
 
diff --git a/tools/android/loading/request_track_unittest.py b/tools/android/loading/request_track_unittest.py
index cad4a11..7a85f07 100644
--- a/tools/android/loading/request_track_unittest.py
+++ b/tools/android/loading/request_track_unittest.py
@@ -6,7 +6,32 @@ import copy
 import json
 import unittest
 
-from request_track import (Request, RequestTrack, TimingFromDict)
+from request_track import (TimeBetween, Request, RequestTrack, TimingFromDict)
+
+
+class TimeBetweenTestCase(unittest.TestCase):
+  _REQUEST = Request.FromJsonDict({'url': 'http://bla.com',
+                                   'request_id': '1234.1',
+                                   'frame_id': '123.1',
+                                   'initiator': {'type': 'other'},
+                                   'timestamp': 2,
+                                   'timing': TimingFromDict({})})
+  def setUp(self):
+    super(TimeBetweenTestCase, self).setUp()
+    self.first = copy.deepcopy(self._REQUEST)
+    self.first.timing = TimingFromDict({'requestTime': 123456,
+                                        'receiveHeadersEnd': 100,
+                                        'loadingFinished': 500})
+    self.second = copy.deepcopy(self._REQUEST)
+    self.second.timing = TimingFromDict({'requestTime': 123456 + 1,
+                                        'receiveHeadersEnd': 200,
+                                        'loadingFinished': 600})
+
+  def testTimeBetweenParser(self):
+    self.assertEquals(900, TimeBetween(self.first, self.second, 'parser'))
+
+  def testTimeBetweenScript(self):
+    self.assertEquals(500, TimeBetween(self.first, self.second, 'script'))
 
 
 class RequestTestCase(unittest.TestCase):
diff --git a/tools/android/loading/test_utils.py b/tools/android/loading/test_utils.py
index 2e5bb74..654e94bd 100644
--- a/tools/android/loading/test_utils.py
+++ b/tools/android/loading/test_utils.py
@@ -7,6 +7,7 @@
 import devtools_monitor
 import loading_trace
 import page_track
+import request_track
 import tracing
 
 
@@ -40,9 +41,36 @@ class FakePageTrack(devtools_monitor.Track):
     return event['frame_id']
 
 
+def MakeRequest(
+    url, source_url, start_time, headers_time, end_time,
+    magic_content_type=False, initiator_type='other'):
+  assert initiator_type in ('other', 'parser')
+  timing = request_track.TimingAsList(request_track.TimingFromDict({
+      # connectEnd should be ignored.
+      'connectEnd': (end_time - start_time) / 2,
+      'receiveHeadersEnd': headers_time - start_time,
+      'loadingFinished': end_time - start_time,
+      'requestTime': start_time / 1000.0}))
+  rq = request_track.Request.FromJsonDict({
+      'timestamp': start_time / 1000.0,
+      'request_id': str(MakeRequest._next_request_id),
+      'url': 'http://' + str(url),
+      'initiator': {'type': initiator_type, 'url': 'http://' + str(source_url)},
+      'response_headers': {'Content-Type':
+                           'null' if not magic_content_type
+                           else 'magic-debug-content' },
+      'timing': timing
+  })
+  MakeRequest._next_request_id += 1
+  return rq
+
+
+MakeRequest._next_request_id = 0
+
+
 def LoadingTraceFromEvents(requests, page_events=None, trace_events=None):
   """Returns a LoadingTrace instance from a list of requests and page events."""
-  request_track = FakeRequestTrack(requests)
+  request = FakeRequestTrack(requests)
   page_event_track = FakePageTrack(page_events if page_events else [])
   if trace_events:
     tracing_track = tracing.TracingTrack(None)
@@ -51,4 +79,4 @@ def LoadingTraceFromEvents(requests, page_events=None, trace_events=None):
   else:
     tracing_track = None
   return loading_trace.LoadingTrace(
-      None, None, page_event_track, request_track, tracing_track)
+      None, None, page_event_track, request, tracing_track)
diff --git a/tools/android/loading/tracing.py b/tools/android/loading/tracing.py
index c69ffaf..37ee7ce 100644
--- a/tools/android/loading/tracing.py
+++ b/tools/android/loading/tracing.py
@@ -6,6 +6,7 @@
 
 import bisect
 import itertools
+import logging
 
 import devtools_monitor
 
@@ -95,6 +96,20 @@ class TracingTrack(devtools_monitor.Track):
   def ToJsonDict(self):
     return {'events': [e.ToJsonDict() for e in self._events]}
 
+  def TracingTrackForThread(self, tid):
+    """Returns a new TracingTrack with only the events from a given thread.
+
+    Args:
+      tid: (int) Thread ID.
+
+    Returns:
+      A new instance of TracingTrack.
+    """
+    events = [e for e in self._events if e.tracing_event['tid'] == tid]
+    tracing_track = TracingTrack(None)
+    tracing_track._events = events
+    return tracing_track
+
   @classmethod
   def FromJsonDict(cls, json_dict):
     assert 'events' in json_dict
@@ -182,7 +197,7 @@ class TracingTrack(devtools_monitor.Track):
         assert event.IsIndexable()
         if event.start_msec > current_msec:
           break
-        matched_event = spanning_events.Match(event)
+        matched_event = spanning_events.Match(event, strict)
         if matched_event is not None:
           event = matched_event
         if not event.synthetic and (
@@ -220,9 +235,9 @@ class TracingTrack(devtools_monitor.Track):
           None: self._Ignore,
           }
 
-    def Match(self, event):
+    def Match(self, event, strict=False):
       return self._MATCH_HANDLER.get(
-          event.type, self._Unsupported)(event)
+          event.type, self._Unsupported)(event, strict)
 
     def HasPending(self):
       return (self._duration_stack or
@@ -236,21 +251,21 @@ class TracingTrack(devtools_monitor.Track):
           itertools.chain.from_iterable((
               (e for e in s) for s in self._async_stacks.itervalues())))
 
-    def _AsyncKey(self, event):
+    def _AsyncKey(self, event, _):
       return (event.tracing_event['cat'], event.id)
 
-    def _Ignore(self, _event):
+    def _Ignore(self, _event, _):
       return None
 
-    def _Unsupported(self, event):
+    def _Unsupported(self, event, _):
       raise devtools_monitor.DevToolsConnectionException(
           'Unsupported spanning event type: %s' % event)
 
-    def _DurationBegin(self, event):
+    def _DurationBegin(self, event, _):
       self._duration_stack.append(event)
       return None
 
-    def _DurationEnd(self, event):
+    def _DurationEnd(self, event, _):
       if not self._duration_stack:
         raise devtools_monitor.DevToolsConnectionException(
             'Unmatched duration end: %s' % event)
@@ -258,16 +273,20 @@ class TracingTrack(devtools_monitor.Track):
       start.SetClose(event)
       return start
 
-    def _AsyncStart(self, event):
-      key = self._AsyncKey(event)
+    def _AsyncStart(self, event, strict):
+      key = self._AsyncKey(event, strict)
       self._async_stacks.setdefault(key, []).append(event)
       return None
 
-    def _AsyncEnd(self, event):
-      key = self._AsyncKey(event)
+    def _AsyncEnd(self, event, strict):
+      key = self._AsyncKey(event, strict)
       if key not in self._async_stacks:
-        raise devtools_monitor.DevToolsConnectionException(
-            'Unmatched async end %s: %s' % (key, event))
+        message = 'Unmatched async end %s: %s' % (key, event)
+        if strict:
+          raise devtools_monitor.DevToolsConnectionException(message)
+        else:
+          logging.warning(message)
+        return None
       stack = self._async_stacks[key]
       start = stack.pop()
       if not stack:
@@ -275,7 +294,7 @@ class TracingTrack(devtools_monitor.Track):
       start.SetClose(event)
       return start
 
-    def _ObjectCreated(self, event):
+    def _ObjectCreated(self, event, _):
       # The tracing event format has object deletion timestamps being exclusive,
       # that is the timestamp for a deletion my equal that of the next create at
       # the same address. This asserts that does not happen in practice as it is
@@ -287,7 +306,7 @@ class TracingTrack(devtools_monitor.Track):
       self._objects[event.id] = event
       return None
 
-    def _ObjectDestroyed(self, event):
+    def _ObjectDestroyed(self, event, _):
       if event.id not in self._objects:
         raise devtools_monitor.DevToolsConnectionException(
             'Missing object creation for %s' % event)
diff --git a/tools/android/loading/tracing_unittest.py b/tools/android/loading/tracing_unittest.py
index 0f30dcc..9c1ac3a 100644
--- a/tools/android/loading/tracing_unittest.py
+++ b/tools/android/loading/tracing_unittest.py
@@ -26,12 +26,12 @@ class TracingTrackTestCase(unittest.TestCase):
       {'ts': 15, 'ph': 'D', 'id': 1}]
 
   _EVENTS = [
-      {'ts': 5, 'ph': 'X', 'dur': 1, 'args': {'name': 'B'}},
-      {'ts': 3, 'ph': 'X', 'dur': 4, 'args': {'name': 'A'}},
-      {'ts': 10, 'ph': 'X', 'dur': 1, 'args': {'name': 'C'}},
-      {'ts': 10, 'ph': 'X', 'dur': 2, 'args': {'name': 'D'}},
-      {'ts': 13, 'ph': 'X', 'dur': 1, 'args': {'name': 'F'}},
-      {'ts': 12, 'ph': 'X', 'dur': 3, 'args': {'name': 'E'}}]
+      {'ts': 5, 'ph': 'X', 'dur': 1, 'tid': 1, 'args': {'name': 'B'}},
+      {'ts': 3, 'ph': 'X', 'dur': 4, 'tid': 1, 'args': {'name': 'A'}},
+      {'ts': 10, 'ph': 'X', 'dur': 1, 'tid': 2, 'args': {'name': 'C'}},
+      {'ts': 10, 'ph': 'X', 'dur': 2, 'tid': 2, 'args': {'name': 'D'}},
+      {'ts': 13, 'ph': 'X', 'dur': 1, 'tid': 1, 'args': {'name': 'F'}},
+      {'ts': 12, 'ph': 'X', 'dur': 3, 'tid': 1, 'args': {'name': 'E'}}]
 
   def setUp(self):
     self.track = TracingTrack(None)
@@ -246,6 +246,16 @@ class TracingTrackTestCase(unittest.TestCase):
                      set([e.args['name']
                           for e in self.track.OverlappingEvents(6, 10.1)]))
 
+  def testTracingTrackForThread(self):
+    self.track.Handle(
+        'Tracing.dataCollected', {'params': {'value': [
+            self.EventToMicroseconds(e) for e in self._EVENTS]}})
+    tracing_track = self.track.TracingTrackForThread(1)
+    self.assertTrue(tracing_track is not self.track)
+    self.assertEquals(4, len(tracing_track.GetEvents()))
+    tracing_track = self.track.TracingTrackForThread(42)
+    self.assertEquals(0, len(tracing_track.GetEvents()))
+
 
 if __name__ == '__main__':
   unittest.main()