#!/usr/bin/env python
# Copyright (c) 2012 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.

"""Jerkiness performance test for video playback.

Uses jerky tool, (http://go/jerky), to record a jerkiness metric for videos
sensitive to jerkiness.

Jerkiness is defined as a percentage of the average on screen frame time by the
formula below.  Where smoothed_frame_time[i] represents a frame's on screen time
plus amortized measurement gap error (time taken to capture each frame).

sqrt(average((avg_frame_time - smoothed_frame_time[i])^2, i=m..n))
------------------------------------------------------------------
                          avg_frame_time

Currently, only the Linux binaries are checked in for this test since we only
have a Linux performance bot.  The current binary is a custom build with some
fixes from veganjerky (http://go/veganjerky) for timing, waiting, and stdout
flushing.

TODO(dalecurtis): Move Jerky tool sources into the Chromium tree.

TODO(dalecurtis): Jerky tool uses a questionable method for determining torn
frames, determine if it is actually worth recording.
"""

import glob
import logging
import os
import re
import subprocess
import tempfile

import pyauto_media
import pyauto
import pyauto_utils

# HTML test path; relative to src/chrome/test/data.
_TEST_HTML_PATH = os.path.join('media', 'html', 'media_jerky.html')

# Path under data path for test files.
_TEST_MEDIA_PATH = os.path.join('pyauto_private', 'media', 'birds')

# Path to Jerky tool executable.
_JERKY_PATH = os.path.join('pyauto_private', 'media', 'tools', 'jerky')

# Regular expression for extracting jerkiness percentage.  Sample line:
#   using 1:9 title 'test.log (35.36% jerky, 0 teared frames)' lw 2 with lines
_JERKY_LOG_REGEX = re.compile(
    r'\((\d{0,3}\.?\d{0,2})% jerky, (\d+) teared frames\)')

# Regular expression for extracting computed fps.  Sample line:
# INFO: 33797 us per frame => 29.6 fps.
_JERKY_LOG_FPS_REGEX = re.compile(r' => (\d+\.\d+) fps')

# Minimum and maximum number of iterations for each test.  Due to timing issues
# the jerky tool may not always calculate the fps correctly.  When invalid
# results are detected, the test is rerun up to the maxium # of times set below.
_JERKY_ITERATIONS_MIN = 3
_JERKY_ITERATIONS_MAX = 10

# The media files used for testing.  Each entry represents a tuple of (filename,
# width, height, fps).  The width and height are used to create a calibration
# pattern for jerky tool.  The fps is used to ensure Jerky tool computed a valid
# result.
_TEST_VIDEOS = [('birds540.webm', 960, 540, 29.9)]


def GetTempFilename():
  """Returns an absolute path to an empty temp file."""
  f, path = tempfile.mkstemp(prefix='jerky_tmp')
  os.close(f)
  return path


class MediaJerkyPerfTest(pyauto.PyUITest):
  """PyAuto test container.  See file doc string for more information."""

  def StartJerkyCapture(self):
    """Starts jerky tool in capture mode and waits until its ready to capture.

    Returns:
      A tuple of the jerky process and an absolute path to the capture log.
    """
    jerky_log = GetTempFilename()
    logging.debug('Logging data to %s', jerky_log)
    process = subprocess.Popen(
        [os.path.join(self.DataDir(), _JERKY_PATH),
         'capture', '--log', jerky_log],
        stdout=subprocess.PIPE)

    # Set the jerky tool process to soft-realtime w/ round-robin scheduling.
    subprocess.check_call(['sudo', 'chrt', '-r', '-p', str(process.pid)])

    # Wait for server to start up.
    line = True
    while line:
      line = process.stdout.readline()
      if 'Waiting for calibration pattern to disappear' in line:
        return process, jerky_log
    self.fail('Failed to launch Jerky tool.')

  def AnalyzeJerkyCapture(self, jerky_log):
    """Run jerky analyze on the specified log and return various metrics.

    Once analyze has completed, the jerky_log and associated outputs will be
    removed.

    Args:
      jerky_log: Absolute path to the capture log.

    Returns:
      Tuple of fps, jerkiness, and torn frames.
    """
    results_log_base = GetTempFilename()
    process = subprocess.Popen(
        [os.path.join(self.DataDir(), _JERKY_PATH),
         'analyze', '--ref', jerky_log, '--out', results_log_base],
        stdout=subprocess.PIPE)

    # Wait for process to end w/o risking deadlock.
    stdout = process.communicate()[0]
    self.assertEquals(process.returncode, 0)

    # Scrape out the calculated FPS.
    fps_match = None
    for line in stdout.splitlines():
      fps_match = _JERKY_LOG_FPS_REGEX.search(line)
      if fps_match:
        break

    # Open *.error.gnuplot and scrape out jerkiness.
    jerky_match = None
    with open('%s.error.gnuplot' % results_log_base) as results:
      for line in results:
        jerky_match = _JERKY_LOG_REGEX.search(line)
        if jerky_match:
          break

    # Cleanup all the temp and results files jerky spits out.
    for log in glob.glob('%s*' % results_log_base) + [jerky_log]:
      os.unlink(log)

    if fps_match and jerky_match:
      return (float(fps_match.group(1)), float(jerky_match.group(1)),
              int(jerky_match.group(2)))
    return None, None, None

  def testMediaJerkyPerformance(self):
    """Launches Jerky tool and records jerkiness for HTML5 videos.

    For each video, the test starts up jerky tool then plays until the Jerky
    tool collects enough information.  Next the capture log is analyzed using
    Jerky's analyze command.  If the computed fps matches the expected fps the
    jerkiness metric is recorded.

    The test will run up to _JERKY_ITERATIONS_MAX times in an attempt to get at
    least _JERKY_ITERATIONS_MIN valid values.  The results are recorded under
    the 'jerkiness' variable for graphing on the bots.
    """
    self.NavigateToURL(self.GetFileURLForDataPath(_TEST_HTML_PATH))

    # Xvfb on the bots is restricted to 1024x768 at present.  Ensure we're using
    # all of the real estate we can.  Jerky tool needs a clear picture of every
    # frame, so we can't clip the video in any way.
    self.SetWindowDimensions(0, 0, 1024, 768)

    for name, width, height, expected_fps in _TEST_VIDEOS:
      jerkiness = []
      torn_frames = []
      file_url = self.GetFileURLForDataPath(
          os.path.join(_TEST_MEDIA_PATH, name))

      # Initialize the calibration area for Jerky tool.
      self.assertTrue(self.ExecuteJavascript(
          'initializeTest(%d, %d);' % (width, height)))

      runs_left = _JERKY_ITERATIONS_MIN
      runs_total = 0
      while runs_left > 0 and runs_total < _JERKY_ITERATIONS_MAX:
        runs_total += 1
        logging.info('Running Jerky perf test #%d for %s.', runs_total, name)

        # Startup Jerky tool in capture mode.
        jerky_process, jerky_log = self.StartJerkyCapture()

        # Start playback of the test video.
        self.assertTrue(self.ExecuteJavascript("startTest('%s');" % file_url))

        # Wait for jerky tool to finish if it hasn't already.
        self.assertTrue(jerky_process.wait() == 0)

        # Stop playback of the test video so the next run can cleanly find the
        # calibration zone.
        self.assertTrue(self.ExecuteJavascript('stopTest();'))

        # Analyze the results.
        jerky_fps, jerky_percent, jerky_torn_frames = self.AnalyzeJerkyCapture(
            jerky_log)
        if (jerky_fps is None or jerky_percent is None or
            jerky_torn_frames is None):
          logging.error('No metrics recorded for this run.')
          continue

        # Ensure the results for this run are valid.
        if jerky_fps != expected_fps:
          logging.error(
              'Invalid fps detected (actual: %f, expected: %f, jerkiness: %f). '
              'Discarding results for this run.', jerky_fps, expected_fps,
              jerky_percent)
          continue

        jerkiness.append(jerky_percent)
        torn_frames.append(jerky_torn_frames)
        runs_left -= 1

      pyauto_utils.PrintPerfResult('jerkiness', name, jerkiness, '%')


if __name__ == '__main__':
  pyauto_media.Main()