Clovis: contentful paint upgrades.

tools/android/loading/user_satisfied_lens.py

 # 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.
 
 """Identifies key events related to user satisfaction.
 
 Several lenses are defined, for example FirstTextPaintLens and
 FirstSignificantPaintLens.
+
+When run from the command line, takes a lens name and a trace, and prints the
+fingerprints of the critical resources to stdout.
 """
 import logging
 import operator
 
 import common_util
 
 
 class _UserSatisfiedLens(object):
   """A base class for all user satisfaction metrics.
 
   All of these work by identifying a user satisfaction event from the trace, and
   then building a set of request ids whose loading is needed to achieve that
   event. Subclasses need only provide the time computation. The base class will
   use that to construct the request ids.
   """
   _ATTRS = ['_satisfied_msec', '_event_msec', '_postload_msec',
             '_critical_request_ids']
 
+  def CriticalRequests(self):
+    """Critical requests.
+
+    Returns:
+      A sequence of request_track.Request objects representing an estimate of
+      all requests that are necessary for the user satisfaction defined by this
+      class.
+    """
+    raise NotImplementedError
+
+  def CriticalRequestIds(self):
+    """Ids of critical requests."""
+    return set(rq.request_id for rq in self.CriticalRequests())
+
+  def CriticalFingerprints(self):
+    """Fingerprints of critical requests."""
+    return set(rq.fingerprint for rq in self.CriticalRequests())
+
+  def PostloadTimeMsec(self):
+    """Return postload time.
+
+    The postload time is an estimate of the amount of time needed by chrome to
+    transform the critical results into the satisfying event.
+
+    Returns:
+      Postload time in milliseconds.
+    """
+    return 0
+
+
+class RequestFingerprintLens(_UserSatisfiedLens):
+  """A lens built using requests in a trace that match a set of fingerprints."""
+  def __init__(self, trace, fingerprints):
+    fingerprints = set(fingerprints)
+    self._critical_requests = [rq for rq in trace.request_track.GetEvents()

[Benoit L, 2016/04/27 12:40:50]

The fingerprint is constructed from the URL. What happens when the same URL is
fetched several times?

[mattcary, 2016/04/27 12:47:55]

It's counted as the same request. I wasn't sure what the best way to deal with
multiple requests. Do we want to check that it's the same number of times or not
(ie, http://foo # 2, or http://foo # 2 of 5)? Might fetch order not always be
the same?

Since I think the bigger issue is identifying resources that have different
URLs, rather than splitting those with the same URL, I didn't think it was worth
spending much time on this now.

+                               if rq.fingerprint in fingerprints]
+
+  def CriticalRequests(self):
+    """Ids of critical requests."""
+    return set(self._critical_requests)
+
+
+class _FirstEventLens(_UserSatisfiedLens):
+  """Helper abstract subclass that defines users first event manipulations."""
+  # pylint can't handle abstract subclasses.
+  # pylint: disable=abstract-method
+
   def __init__(self, trace):
     """Initialize the lens.
 
     Args:
       trace: (LoadingTrace) the trace to use in the analysis.
     """
     self._satisfied_msec = None
     self._event_msec = None
     self._postload_msec = None
     self._critical_request_ids = None
     if trace is None:
       return
-    self._CalculateTimes(trace.tracing_track)
-    critical_requests = self._RequestsBefore(
+    self._CalculateTimes(trace)
+    self._critical_requests = self._RequestsBefore(
         trace.request_track, self._satisfied_msec)
-    self._critical_request_ids = set(rq.request_id for rq in critical_requests)
-    if critical_requests:
-      last_load = max(rq.end_msec for rq in critical_requests)
+    self._critical_request_ids = set(rq.request_id
+                                     for rq in self._critical_requests)
+    if self._critical_requests:
+      last_load = max(rq.end_msec for rq in self._critical_requests)
     else:
       last_load = float('inf')
     self._postload_msec = self._event_msec - last_load
 
   def CriticalRequests(self):
-    """Request ids of critical requests.
-
-    Returns:
-      A set of request ids (as strings) of an estimate of all requests that are
-      necessary for the user satisfaction defined by this class.
-    """
-    return self._critical_request_ids
+    """Override."""
+    return self._critical_requests
 
   def PostloadTimeMsec(self):
-    """Return postload time.
-
-    The postload time is an estimate of the amount of time needed by chrome to
-    transform the critical results into the satisfying event.
-
-    Returns:
-      Postload time in milliseconds.
-    """
+    """Override."""
     return self._postload_msec
 
   def ToJsonDict(self):
     return common_util.SerializeAttributesToJsonDict({}, self, self._ATTRS)
 
   @classmethod
   def FromJsonDict(cls, json_dict):
     result = cls(None)
     return common_util.DeserializeAttributesFromJsonDict(
         json_dict, result, cls._ATTRS)
 
-  def _CalculateTimes(self, tracing_track):
+  def _CalculateTimes(self, trace):
     """Subclasses should implement to set _satisfied_msec and _event_msec."""
     raise NotImplementedError
 
   @classmethod
   def _RequestsBefore(cls, request_track, time_ms):
     return [rq for rq in request_track.GetEvents()
             if rq.end_msec <= time_ms]
 
-
-class _FirstEventLens(_UserSatisfiedLens):
-  """Helper abstract subclass that defines users first event manipulations."""
-  # pylint can't handle abstract subclasses.
-  # pylint: disable=abstract-method
-
   @classmethod
-  def _ExtractFirstTiming(cls, times):
+  def _ExtractBestTiming(cls, times):
     if not times:
       return float('inf')
-    if len(times) != 1:
-      # TODO(mattcary): in some cases a trace has two first paint events. Why?
-      logging.error('%d %s with spread of %s', len(times),
-                    str(cls), max(times) - min(times))
-    return float(min(times))
+    assert len(times) == 1, \
+        'Unexpected duplicate {}: {} with spread of {}'.format(
+            str(cls), len(times), max(times) - min(times))
+    return float(max(times))
 
 
 class FirstTextPaintLens(_FirstEventLens):
   """Define satisfaction by the first text paint.
 
   This event is taken directly from a trace.
   """
-  def _CalculateTimes(self, tracing_track):
-    first_paints = [e.start_msec for e in tracing_track.GetEvents()
-                    if e.Matches('blink.user_timing', 'firstPaint')]
+  def _CalculateTimes(self, trace):
+    first_paints = [
+        e.start_msec for e in trace.tracing_track.GetMatchingMainFrameEvents(
+            'blink.user_timing', 'firstPaint')]
     self._satisfied_msec = self._event_msec = \
-        self._ExtractFirstTiming(first_paints)
+        self._ExtractBestTiming(first_paints)
 
 
 class FirstContentfulPaintLens(_FirstEventLens):
   """Define satisfaction by the first contentful paint.
 
   This event is taken directly from a trace. Internally to chrome it's computed
   by filtering out things like background paint from firstPaint.
   """
-  def _CalculateTimes(self, tracing_track):
-    first_paints = [e.start_msec for e in tracing_track.GetEvents()
-                    if e.Matches('blink.user_timing', 'firstContentfulPaint')]
+  def _CalculateTimes(self, trace):
+    first_paints = [
+        e.start_msec for e in trace.tracing_track.GetMatchingMainFrameEvents(
+            'blink.user_timing', 'firstContentfulPaint')]
     self._satisfied_msec = self._event_msec = \
-       self._ExtractFirstTiming(first_paints)
+       self._ExtractBestTiming(first_paints)
 
 
 class FirstSignificantPaintLens(_FirstEventLens):
   """Define satisfaction by the first paint after a big layout change.
 
   Our satisfaction time is that of the layout change, as all resources must have
   been loaded to compute the layout. Our event time is that of the next paint as
   that is the observable event.
   """
   FIRST_LAYOUT_COUNTER = 'LayoutObjectsThatHadNeverHadLayout'
 
-  def _CalculateTimes(self, tracing_track):
+  def _CalculateTimes(self, trace):
     sync_paint_times = []
     layouts = []  # (layout item count, msec).
-    for e in tracing_track.GetEvents():
+    for e in trace.tracing_track.GetEvents():
+      if ('frame' in e.args and
+          e.args['frame'] != trace.tracing_track.GetMainFrameID()):
+        continue
+      # If we don't know have a frame id, we assume it applies to all events.
+
       # TODO(mattcary): is this the right paint event? Check if synchronized
       # paints appear at the same time as the first*Paint events, above.
       if e.Matches('blink', 'FrameView::SynchronizedPaint'):
         sync_paint_times.append(e.start_msec)
       if ('counters' in e.args and
           self.FIRST_LAYOUT_COUNTER in e.args['counters']):
         layouts.append((e.args['counters'][self.FIRST_LAYOUT_COUNTER],
                         e.start_msec))
     assert layouts, ('No layout events, was the disabled-by-default-blink'
                      '.debug.layout category enabled?')
+    assert sync_paint_times, \
+        'No sync paint times, was the blink category disabled?'
     layouts.sort(key=operator.itemgetter(0), reverse=True)
     self._satisfied_msec = layouts[0][1]
-    self._event_msec = self._ExtractFirstTiming([
-        min(t for t in sync_paint_times if t > self._satisfied_msec)])
+    self._event_msec = min(t for t in sync_paint_times
+                           if t > self._satisfied_msec)
+
+
+def main(lens_name, trace_file):
+  assert (lens_name in globals() and
+          not lens_name.startswith('_') and
+          lens_name.endswith('Lens')), 'Bad lens %s' % lens_name
+  lens_cls = globals()[lens_name]
+  trace = loading_trace.LoadingTrace.FromJsonFile(trace_file)
+  lens = lens_cls(trace)
+  for fp in sorted(lens.CriticalFingerprints()):
+    print fp
+
+
+if __name__ == '__main__':
+  import sys
+  import loading_trace
+  main(sys.argv[1], sys.argv[2])