[Telemetry] Improvements to OS X powermetrics integration

[Telemetry] Improvements to OS X powermetrics integration

* Make StartMonitoringPowerAsync() synchronous in terms of starting the powermetrics process by waiting for output file to be created before returning.
* Handle parse errors in powermetrics output - empirically while I was able to quite easily get powermetrics into a state where it exited in the middle of writing a sample, I was completely unable to get it not write out at least one sample completely.
* Modify unit test to start/stop powermetrics faster than it's refresh rate to try to trigger malformed output - test fails without rest of this patch, passes with this patch.

BUG=338808
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=247871

[tonyg, 2014-01-29 00:47:41]

https://codereview.chromium.org/145353012/diff/1/tools/telemetry/telemetry/co...
File tools/telemetry/telemetry/core/platform/mac_platform_backend.py (right):

https://codereview.chromium.org/145353012/diff/1/tools/telemetry/telemetry/co...
tools/telemetry/telemetry/core/platform/mac_platform_backend.py:53: #
powermetrics writes lots of output to stderr, don't echo unless verbose
Is there nothing in stderr we could observe? Might be cleaner and faster if so.

[jeremy, 2014-01-29 01:26:54]

https://codereview.chromium.org/145353012/diff/1/tools/telemetry/telemetry/co...
File tools/telemetry/telemetry/core/platform/mac_platform_backend.py (right):

https://codereview.chromium.org/145353012/diff/1/tools/telemetry/telemetry/co...
tools/telemetry/telemetry/core/platform/mac_platform_backend.py:53: #
powermetrics writes lots of output to stderr, don't echo unless verbose
Not that I observed unfortunately :(

If we ask for textual output rather than a plist then there are a couple of
lines that are printed to stdout but we want plists :/

[tonyg, 2014-01-29 06:07:00]

https://codereview.chromium.org/145353012/diff/1/tools/telemetry/telemetry/co...
File tools/telemetry/telemetry/core/platform/mac_platform_backend.py (right):

https://codereview.chromium.org/145353012/diff/1/tools/telemetry/telemetry/co...
tools/telemetry/telemetry/core/platform/mac_platform_backend.py:62: # Block
until output file is written to ensure this function call is
I know powermetrics is capable of buffering, but not sure it does by default.

If we buffer, then this blocks too long and we dilute our data. If we don't
buffer, then we risk affecting benchmarks by writing to disk during them.

Do the plists have timestamps in them or anything so that we could determine
when collection actually started?

[jeremy, 2014-01-29 20:39:49]

Ready for another look.

[tonyg, 2014-01-29 21:11:05]

lgtm

[commit-bot: I haz the power, 2014-01-29 21:37:49]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/jeremy@chromium.org/145353012/60001

[commit-bot: I haz the power, 2014-01-29 21:37:52]

Failed to apply patch for
tools/telemetry/telemetry/core/platform/mac_platform_backend.py:
While running patch -p1 --forward --force --no-backup-if-mismatch;
  patching file tools/telemetry/telemetry/core/platform/mac_platform_backend.py
  Hunk #1 FAILED at 7.
  Hunk #2 FAILED at 24.
  Hunk #3 FAILED at 34.
  Hunk #4 succeeded at 49 with fuzz 2 (offset 2 lines).
  Hunk #5 succeeded at 66 (offset 2 lines).
  Hunk #6 succeeded at 195 (offset 2 lines).
  Hunk #7 succeeded at 261 (offset 2 lines).
  Hunk #8 succeeded at 301 (offset 2 lines).
  3 out of 8 hunks FAILED -- saving rejects to file
tools/telemetry/telemetry/core/platform/mac_platform_backend.py.rej

Patch:       tools/telemetry/telemetry/core/platform/mac_platform_backend.py
Index: tools/telemetry/telemetry/core/platform/mac_platform_backend.py
diff --git a/tools/telemetry/telemetry/core/platform/mac_platform_backend.py
b/tools/telemetry/telemetry/core/platform/mac_platform_backend.py
index
fb75a15af4514c070c013cf9b9df402e25ac4fa6..64062e63d2f322653c8bc1447f149f9cc66bf6d6
100644
--- a/tools/telemetry/telemetry/core/platform/mac_platform_backend.py
+++ b/tools/telemetry/telemetry/core/platform/mac_platform_backend.py
@@ -7,16 +7,19 @@ import ctypes
 import logging
 import os
 import plistlib
+import shutil
 import signal
 import subprocess
 import tempfile
 import time
+import xml.parsers.expat
 try:
   import resource  # pylint: disable=F0401
 except ImportError:
   resource = None  # Not available on all platforms
 
 from ctypes import util
+from telemetry.core import util
 from telemetry.core.platform import posix_platform_backend
 
 class MacPlatformBackend(posix_platform_backend.PosixPlatformBackend):
@@ -24,7 +27,9 @@ class
MacPlatformBackend(posix_platform_backend.PosixPlatformBackend):
   class PowerMetricsUtility(object):
     def __init__(self):
       self._powermetrics_process = None
-      self._powermetrics_output_file = None
+      self._powermetrics_output_filename = None
+      self._ouput_directory = None
+      self._output_filename = None
 
     @property
     def binary_path(self):
@@ -34,9 +39,19 @@ class
MacPlatformBackend(posix_platform_backend.PosixPlatformBackend):
       assert not self._powermetrics_process, (
           "Must call StopMonitoringPowerAsync().")
       SAMPLE_INTERVAL_MS = 1000 / 20 # 20 Hz, arbitrary.
-      self._powermetrics_output_file = tempfile.NamedTemporaryFile()
+      # Empirically powermetrics creates an empty output file immediately upon
+      # starting.  We detect file creation as a signal that measurement has
+      # started.  In order to avoid various race conditions in tempfile
creation
+      # we create a temp directory and have powermetrics create it's output
+      # there rather than say, creating a tempfile, deleting it and reusing its
+      # name.
+      self._ouput_directory = tempfile.mkdtemp()
+      self._output_filename = os.path.join(self._ouput_directory,
+          'powermetrics.output')
+
       args = [self.binary_path, '-f', 'plist', '-i',
-          '%d' % SAMPLE_INTERVAL_MS, '-u', self._powermetrics_output_file.name]
+          '%d' % SAMPLE_INTERVAL_MS,
+          '-u', self._output_filename]
 
       # powermetrics writes lots of output to stderr, don't echo unless verbose
       # logging enabled.
@@ -47,6 +62,13 @@ class
MacPlatformBackend(posix_platform_backend.PosixPlatformBackend):
       self._powermetrics_process = subprocess.Popen(args,
           stdout=subprocess.PIPE, stderr=stderror_destination)
 
+      # Block until output file is written to ensure this function call is
+      # synchronous in respect to powermetrics starting.
+      def _OutputFileExists():
+        return os.path.isfile(self._output_filename)
+      timeout_sec = 2 * (SAMPLE_INTERVAL_MS / 1000.)
+      util.WaitFor(_OutputFileExists, timeout_sec)
+
     def StopMonitoringPowerAsync(self):
       assert self._powermetrics_process, (
           "StartMonitoringPowerAsync() not called.")
@@ -57,10 +79,11 @@ class
MacPlatformBackend(posix_platform_backend.PosixPlatformBackend):
         returncode = self._powermetrics_process.wait()
         assert returncode in [0, -15], (
             "powermetrics return code: %d" % returncode)
-        return open(self._powermetrics_output_file.name, 'r').read()
+
+        return open(self._output_filename, 'rb').read()
       finally:
-        self._powermetrics_output_file.close()
-        self._powermetrics_output_file = None
+        shutil.rmtree(self._ouput_directory)
+        self._powermetrics_output_filename = None
         self._powermetrics_process = None
 
   def __init__(self):
@@ -185,6 +208,21 @@ class
MacPlatformBackend(posix_platform_backend.PosixPlatformBackend):
   def StartMonitoringPowerAsync(self):
     self.powermetrics_tool_.StartMonitoringPowerAsync()
 
+  def _ParsePlistString(self, plist_string):
+    """Wrapper to parse a plist from a string and catch any errors.
+
+    Sometimes powermetrics will exit in the middle of writing it's output,
+    empirically it seems that it always writes at least one sample in it's
+    entirety so we can safely ignore any errors in it's output.
+
+    Returns:
+        Parser output on succesful parse, None on parse error.
+    """
+    try:
+      return plistlib.readPlistFromString(plist_string)
+    except xml.parsers.expat.ExpatError:
+      return None
+
   def _ParsePowerMetricsOutput(self, powermetrics_output):
     """Parse output of powermetrics command line utility.
 
@@ -236,7 +274,11 @@ class
MacPlatformBackend(posix_platform_backend.PosixPlatformBackend):
     raw_plists = [x for x in raw_plists if len(x) > 0]
 
     # -------- Examine contents of first plist for systems specs. --------
-    plist = plistlib.readPlistFromString(raw_plists[0])
+    plist = self._ParsePlistString(raw_plists[0])
+    if not plist:
+      logging.warning("powermetrics produced invalid output, output length: "
+          "%d" % len(powermetrics_output))
+      return {}
 
     if 'GPU' in plist:
       metrics.extend([
@@ -272,7 +314,9 @@ class
MacPlatformBackend(posix_platform_backend.PosixPlatformBackend):
 
     # -------- Parse Data Out of Plists --------
     for raw_plist in raw_plists:
-      plist = plistlib.readPlistFromString(raw_plist)
+      plist = self._ParsePlistString(raw_plist)
+      if not plist:
+        continue
 
       # Duration of this sample.
       sample_duration_ms = int(plist['elapsed_ns']) / 10**6

[commit-bot: I haz the power, 2014-01-29 22:14:02]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/jeremy@chromium.org/145353012/80001

[commit-bot: I haz the power, 2014-01-30 00:02:15]

Retried try job too often on win_rel for step(s) content_unittests
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=win_rel&nu...

[commit-bot: I haz the power, 2014-01-30 00:22:49]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/jeremy@chromium.org/145353012/80001

[commit-bot: I haz the power, 2014-01-30 07:28:29]

Change committed as 247871