report_unittest.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.

import unittest

import metrics
import report
from queuing_lens import QueuingLens
import test_utils
import user_satisfied_lens_unittest


class LoadingReportTestCase(unittest.TestCase):
  MILLI_TO_MICRO = 1000
  _NAVIGATION_START_TIME = 12
  _FIRST_REQUEST_TIME = 15
  _CONTENTFUL_PAINT = 120
  _TEXT_PAINT = 30
  _SIGNIFICANT_PAINT = 50
  _DURATION = 400
  _REQUEST_OFFSET = 5
  _LOAD_END_TIME = 1280
  _MAIN_FRAME_ID = 1
  _FIRST_REQUEST_DATA_LENGTH = 128
  _SECOND_REQUEST_DATA_LENGTH = 1024
  _TOPLEVEL_EVENT_OFFSET = 10
  _TOPLEVEL_EVENT_DURATION = 100
  _SCRIPT_EVENT_DURATION = 50
  _PARSING_EVENT_DURATION = 60

  def setUp(self):
    self.trace_creator = test_utils.TraceCreator()
    self.requests = [
        self.trace_creator.RequestAt(self._FIRST_REQUEST_TIME, frame_id=1),
        self.trace_creator.RequestAt(
            self._NAVIGATION_START_TIME + self._REQUEST_OFFSET, self._DURATION)]
    self.requests[0].timing.receive_headers_end = 0
    self.requests[1].timing.receive_headers_end = 0
    self.requests[0].encoded_data_length = self._FIRST_REQUEST_DATA_LENGTH
    self.requests[1].encoded_data_length = self._SECOND_REQUEST_DATA_LENGTH

    self.ad_domain = 'i-ve-got-the-best-ads.com'
    self.ad_url = 'http://www.' + self.ad_domain + '/i-m-really-rich.js'
    self.requests[0].url = self.ad_url

    self.trace_events = [
        {'args': {'name': 'CrRendererMain'}, 'cat': '__metadata',
         'name': 'thread_name', 'ph': 'M', 'pid': 1, 'tid': 1, 'ts': 0},
        {'ts': self._NAVIGATION_START_TIME * self.MILLI_TO_MICRO, 'ph': 'R',
         'cat': 'blink.user_timing', 'pid': 1, 'tid': 1,
         'name': 'navigationStart',
         'args': {'frame': 1}},
        {'ts': self._LOAD_END_TIME * self.MILLI_TO_MICRO, 'ph': 'I',
         'cat': 'devtools.timeline', 'pid': 1, 'tid': 1,
         'name': 'MarkLoad',
         'args': {'data': {'isMainFrame': True}}},
        {'ts': self._CONTENTFUL_PAINT * self.MILLI_TO_MICRO, 'ph': 'I',
         'cat': 'blink.user_timing', 'pid': 1, 'tid': 1,
         'name': 'firstContentfulPaint',
         'args': {'frame': self._MAIN_FRAME_ID}},
        {'ts': self._TEXT_PAINT * self.MILLI_TO_MICRO, 'ph': 'I',
         'cat': 'blink.user_timing', 'pid': 1, 'tid': 1,
         'name': 'firstPaint',
         'args': {'frame': self._MAIN_FRAME_ID}},
        {'ts': 90 * self.MILLI_TO_MICRO, 'ph': 'I',
         'cat': 'blink', 'pid': 1, 'tid': 1,
         'name': 'FrameView::paintTree'},
        {'ts': self._SIGNIFICANT_PAINT * self.MILLI_TO_MICRO, 'ph': 'I',
         'cat': 'foobar', 'name': 'biz', 'pid': 1, 'tid': 1,
         'args': {'counters': {
             'LayoutObjectsThatHadNeverHadLayout': 10}}},
        {'ts': (self._NAVIGATION_START_TIME - self._TOPLEVEL_EVENT_OFFSET)
         * self.MILLI_TO_MICRO,
         'pid': 1, 'tid': 1, 'ph': 'X',
         'dur': self._TOPLEVEL_EVENT_DURATION * self.MILLI_TO_MICRO,
         'cat': 'toplevel', 'name': 'MessageLoop::RunTask'},
        {'ts': self._NAVIGATION_START_TIME * self.MILLI_TO_MICRO,
         'pid': 1, 'tid': 1, 'ph': 'X',
         'dur': self._PARSING_EVENT_DURATION * self.MILLI_TO_MICRO,
         'cat': 'devtools.timeline', 'name': 'ParseHTML',
         'args': {'beginData': {'url': ''}}},
        {'ts': self._NAVIGATION_START_TIME * self.MILLI_TO_MICRO,
         'pid': 1, 'tid': 1, 'ph': 'X',
         'dur': self._SCRIPT_EVENT_DURATION * self.MILLI_TO_MICRO,
         'cat': 'devtools.timeline', 'name': 'EvaluateScript',
         'args': {'data': {'scriptName': ''}}}]

  def _MakeTrace(self):
    trace = self.trace_creator.CreateTrace(
        self.requests, self.trace_events, self._MAIN_FRAME_ID)
    return trace

  def _AddQueuingEvents(self, source_id, url, start_msec, ready_msec, end_msec):
    self.trace_events.extend([
        {'args': {
            'data': {
                'request_url': url,
                'source_id': source_id
            }
          },
         'cat': QueuingLens.QUEUING_CATEGORY,
         'id': source_id,
         'pid': 1, 'tid': 10,
         'name': QueuingLens.ASYNC_NAME,
         'ph': 'b',
         'ts': start_msec * self.MILLI_TO_MICRO
        },
        {'args': {
            'data': {
                'source_id': source_id
            }
          },
         'cat': QueuingLens.QUEUING_CATEGORY,
         'id': source_id,
         'pid': 1, 'tid': 10,
         'name': QueuingLens.READY_NAME,
         'ph': 'n',
         'ts': ready_msec * self.MILLI_TO_MICRO
        },
        {'args': {
            'data': {
                'source_id': source_id
            }
          },
         'cat': QueuingLens.QUEUING_CATEGORY,
         'id': source_id,
         'pid': 1, 'tid': 10,
         'name': QueuingLens.ASYNC_NAME,
         'ph': 'e',
         'ts': end_msec * self.MILLI_TO_MICRO
        }])

  def testGenerateReport(self):
    trace = self._MakeTrace()
    loading_report = report.LoadingReport(trace).GenerateReport()
    self.assertEqual(trace.url, loading_report['url'])
    self.assertEqual(self._TEXT_PAINT - self._NAVIGATION_START_TIME,
                     loading_report['first_text_ms'])
    self.assertEqual(self._SIGNIFICANT_PAINT - self._NAVIGATION_START_TIME,
                     loading_report['significant_ms'])
    self.assertEqual(self._CONTENTFUL_PAINT - self._NAVIGATION_START_TIME,
                     loading_report['contentful_ms'])
    self.assertAlmostEqual(self._LOAD_END_TIME - self._NAVIGATION_START_TIME,
                           loading_report['plt_ms'])
    self.assertEqual(2, loading_report['total_requests'])
    self.assertAlmostEqual(0.34, loading_report['contentful_byte_frac'], 2)
    self.assertAlmostEqual(0.1844, loading_report['significant_byte_frac'], 2)
    self.assertEqual(2, loading_report['plt_requests'])
    self.assertEqual(1, loading_report['first_text_requests'])
    self.assertEqual(1, loading_report['contentful_requests'])
    self.assertEqual(1, loading_report['significant_requests'])
    self.assertEqual(1, loading_report['plt_preloaded_requests'])
    self.assertEqual(1, loading_report['first_text_preloaded_requests'])
    self.assertEqual(1, loading_report['contentful_preloaded_requests'])
    self.assertEqual(1, loading_report['significant_preloaded_requests'])
    self.assertEqual(401, loading_report['plt_requests_cost'])
    self.assertEqual(1, loading_report['first_text_requests_cost'])
    self.assertEqual(1, loading_report['contentful_requests_cost'])
    self.assertEqual(1, loading_report['significant_requests_cost'])
    self.assertEqual(1, loading_report['plt_preloaded_requests_cost'])
    self.assertEqual(1, loading_report['first_text_preloaded_requests_cost'])
    self.assertEqual(1, loading_report['contentful_preloaded_requests_cost'])
    self.assertEqual(1, loading_report['significant_preloaded_requests_cost'])
    self.assertEqual(400, loading_report['plt_predicted_no_state_prefetch_ms'])
    self.assertEqual(14,
        loading_report['first_text_predicted_no_state_prefetch_ms'])
    self.assertEqual(104,
        loading_report['contentful_predicted_no_state_prefetch_ms'])
    self.assertEqual(74,
        loading_report['significant_predicted_no_state_prefetch_ms'])
    self.assertEqual('', loading_report['contentful_inversion'])
    self.assertEqual('', loading_report['significant_inversion'])
    self.assertIsNone(loading_report['ad_requests'])
    self.assertIsNone(loading_report['ad_or_tracking_requests'])
    self.assertIsNone(loading_report['ad_or_tracking_initiated_requests'])
    self.assertIsNone(loading_report['ad_or_tracking_initiated_transfer_size'])
    self.assertIsNone(loading_report['ad_or_tracking_script_frac'])
    self.assertIsNone(loading_report['ad_or_tracking_parsing_frac'])
    self.assertEqual(
        self._FIRST_REQUEST_DATA_LENGTH + self._SECOND_REQUEST_DATA_LENGTH
        + metrics.HTTP_OK_LENGTH * 2,
        loading_report['transfer_size'])
    self.assertEqual(0, loading_report['total_queuing_blocked_msec'])
    self.assertEqual(0, loading_report['total_queuing_load_msec'])
    self.assertEqual(0, loading_report['average_blocking_request_count'])
    self.assertEqual(0, loading_report['median_blocking_request_count'])

  def testInversion(self):
    self.requests[0].timing.loading_finished = 4 * (
        self._REQUEST_OFFSET + self._DURATION)
    self.requests[1].initiator['type'] = 'parser'
    self.requests[1].initiator['url'] = self.requests[0].url
    for e in self.trace_events:
      if e['name'] == 'firstContentfulPaint':
        e['ts'] = self.MILLI_TO_MICRO * (
            self._FIRST_REQUEST_TIME +  self._REQUEST_OFFSET +
            self._DURATION + 1)
        break
    loading_report = report.LoadingReport(self._MakeTrace()).GenerateReport()
    self.assertEqual(self.requests[0].url,
                     loading_report['contentful_inversion'])
    self.assertEqual('', loading_report['significant_inversion'])

  def testPltNoLoadEvents(self):
    trace = self._MakeTrace()
    # Change the MarkLoad events.
    for e in trace.tracing_track.GetEvents():
      if e.name == 'MarkLoad':
        e.tracing_event['name'] = 'dummy'
    loading_report = report.LoadingReport(trace).GenerateReport()
    self.assertAlmostEqual(self._REQUEST_OFFSET + self._DURATION,
                           loading_report['plt_ms'])

  def testAdTrackingRules(self):
    trace = self._MakeTrace()
    loading_report = report.LoadingReport(
        trace, [self.ad_domain], []).GenerateReport()
    self.assertEqual(1, loading_report['ad_requests'])
    self.assertEqual(1, loading_report['ad_or_tracking_requests'])
    self.assertEqual(1, loading_report['ad_or_tracking_initiated_requests'])
    self.assertIsNone(loading_report['tracking_requests'])
    self.assertEqual(
        self._FIRST_REQUEST_DATA_LENGTH + metrics.HTTP_OK_LENGTH,
        loading_report['ad_or_tracking_initiated_transfer_size'])

  def testThreadBusyness(self):
    loading_report = report.LoadingReport(self._MakeTrace()).GenerateReport()
    self.assertAlmostEqual(
        1., loading_report['significant_activity_frac'])
    self.assertAlmostEqual(
        float(self._TOPLEVEL_EVENT_DURATION - self._TOPLEVEL_EVENT_OFFSET)
        / (self._CONTENTFUL_PAINT - self._NAVIGATION_START_TIME),
        loading_report['contentful_activity_frac'])
    self.assertAlmostEqual(
        float(self._TOPLEVEL_EVENT_DURATION - self._TOPLEVEL_EVENT_OFFSET)
        / (self._LOAD_END_TIME - self._NAVIGATION_START_TIME),
        loading_report['plt_activity_frac'])

  def testActivityBreakdown(self):
    loading_report = report.LoadingReport(self._MakeTrace()).GenerateReport()
    load_time = float(self._LOAD_END_TIME - self._NAVIGATION_START_TIME)
    contentful_time = float(
        self._CONTENTFUL_PAINT - self._NAVIGATION_START_TIME)

    self.assertAlmostEqual(self._SCRIPT_EVENT_DURATION / load_time,
                           loading_report['plt_script_frac'])
    self.assertAlmostEqual(
        (self._PARSING_EVENT_DURATION - self._SCRIPT_EVENT_DURATION)
        / load_time,
        loading_report['plt_parsing_frac'])

    self.assertAlmostEqual(1., loading_report['significant_script_frac'])
    self.assertAlmostEqual(0., loading_report['significant_parsing_frac'])

    self.assertAlmostEqual(self._SCRIPT_EVENT_DURATION / contentful_time,
                           loading_report['contentful_script_frac'])
    self.assertAlmostEqual(
        (self._PARSING_EVENT_DURATION - self._SCRIPT_EVENT_DURATION)
        / contentful_time, loading_report['contentful_parsing_frac'])

  def testAdsAndTrackingCost(self):
    load_time = float(self._LOAD_END_TIME - self._NAVIGATION_START_TIME)
    self.trace_events.append(
       {'ts':  load_time / 3. * self.MILLI_TO_MICRO,
        'pid': 1, 'tid': 1, 'ph': 'X',
        'dur': load_time / 2. * self.MILLI_TO_MICRO,
        'cat': 'devtools.timeline', 'name': 'EvaluateScript',
        'args': {'data': {'scriptName': self.ad_url}}})
    loading_report = report.LoadingReport(
        self._MakeTrace(), [self.ad_domain]).GenerateReport()
    self.assertAlmostEqual(.5, loading_report['ad_or_tracking_script_frac'], 2)
    self.assertAlmostEqual(0., loading_report['ad_or_tracking_parsing_frac'])

  def testQueueStats(self):
    # We use three requests, A, B and C. A is not blocked, B is blocked by A,
    # and C blocked by A and B.
    BASE_MSEC = self._FIRST_REQUEST_TIME + 4 * self._DURATION
    self.requests = []
    request_A = self.trace_creator.RequestAt(BASE_MSEC, 5)
    request_B = self.trace_creator.RequestAt(BASE_MSEC + 6, 5)
    request_C = self.trace_creator.RequestAt(BASE_MSEC + 12, 10)
    self.requests.extend([request_A, request_B, request_C])
    self._AddQueuingEvents(10, request_A.url,
                           BASE_MSEC, BASE_MSEC, BASE_MSEC + 5)
    self._AddQueuingEvents(20, request_B.url,
                           BASE_MSEC + 1, BASE_MSEC + 6, BASE_MSEC + 11)
    self._AddQueuingEvents(30, request_C.url,
                           BASE_MSEC + 2, BASE_MSEC + 12, BASE_MSEC + 22)
    loading_report = report.LoadingReport(self._MakeTrace()).GenerateReport()
    self.assertEqual(15, loading_report['total_queuing_blocked_msec'])
    self.assertEqual(35, loading_report['total_queuing_load_msec'])
    self.assertAlmostEqual(1, loading_report['average_blocking_request_count'])
    self.assertEqual(1, loading_report['median_blocking_request_count'])


if __name__ == '__main__':
  unittest.main()