cyglog: Phased ordefile processing.

Adds analysis of phased lightweight instrumentation, that is
instrumentation which records several memory dumps for different
phases of program execution, such as startup or interaction.

Bug: 758566
Change-Id: Id84b2bd8f5a48865e3175d9164e8a6575d5be819
Reviewed-on: https://chromium-review.googlesource.com/883448Reviewed-by: Egor Pasko <pasko@chromium.org>
Reviewed-by: Benoit L <lizeb@chromium.org>
Commit-Queue: Matthew Cary <mattcary@chromium.org>
Cr-Commit-Position: refs/heads/master@{#532849}

tools/cygprofile/phased_orderfile.py

+#!/usr/bin/python
+# Copyright 2018 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.
+
+"""Utilities for creating a phased orderfile.
+
+This kind of orderfile is based on cygprofile lightweight instrumentation. The
+profile dump format is described in process_profiles.py. These tools assume
+profiling has been done with two phases.
+
+The first phase, labeled 0 in the filename, is called "startup" and the second,
+labeled 1, is called "interaction". These two phases are used to create an
+orderfile with three parts: the code touched only in startup, the code
+touched only during interaction, and code common to the two phases. We refer to
+these parts as the orderfile phases.
+"""
+
+import argparse
+import collections
+import glob
+import itertools
+import logging
+import os.path
+
+import process_profiles
+
+
+# Files matched when using this script to analyze directly (see main()).
+PROFILE_GLOB = 'cygprofile-*.txt_*'
+
+
+OrderfilePhaseOffsets = collections.namedtuple(
+    'OrderfilePhaseOffsets', ('startup', 'common', 'interaction'))
+
+
+class PhasedAnalyzer(object):
+  """A class which collects analysis around phased orderfiles.
+
+  It maintains common data such as symbol table information to make analysis
+  more convenient.
+  """
+  # These figures are taken from running memory and speedometer telemetry
+  # benchmarks, and are still subject to change as of 2018-01-24.
+  STARTUP_STABILITY_THRESHOLD = 1.5
+  COMMON_STABILITY_THRESHOLD = 1.75
+  INTERACTION_STABILITY_THRESHOLD = 2.5
+
+  def __init__(self, profiles, processor):
+    """Intialize.
+
+    Args:
+      profiles (ProfileManager) Manager of the profile dump files.
+      processor (SymbolOffsetProcessor) Symbol table processor for the dumps.
+    """
+    self._profiles = profiles
+    self._processor = processor
+    self._phase_offsets = None
+
+  def IsStableProfile(self):
+    """Verify that the profiling has been stable.
+
+    See ComputeStability for details.
+
+    Returns:
+      True if the profile was stable as described above.
+    """
+    (startup_stability, common_stability,
+     interaction_stability) = self.ComputeStability()
+
+    stable = True
+    if startup_stability > self.STARTUP_STABILITY_THRESHOLD:
+      logging.error('Startup unstable: %.3f', startup_stability)
+      stable = False
+    if common_stability > self.COMMON_STABILITY_THRESHOLD:
+      logging.error('Common unstable: %.3f', common_stability)
+      stable = False
+    if interaction_stability > self.INTERACTION_STABILITY_THRESHOLD:
+      logging.error('Interaction unstable: %.3f', interaction_stability)
+      stable = False
+
+    return stable
+
+  def ComputeStability(self):
+    """Compute heuristic phase stability metrics.
+
+    This computes the ratio in size of symbols between the union and
+    intersection of all orderfile phases. Intuitively if this ratio is not too
+    large it means that the profiling phases are stable with respect to the code
+    they cover.
+
+    Returns:
+      (float, float, float) A heuristic stability metric for startup, common and
+          interaction orderfile phases, respectively.
+    """
+    phase_offsets = self._GetOrderfilePhaseOffsets()
+    assert len(phase_offsets) > 1  # Otherwise the analysis is silly.
+
+    startup_union = set(phase_offsets[0].startup)
+    startup_intersection = set(phase_offsets[0].startup)
+    common_union = set(phase_offsets[0].common)
+    common_intersection = set(phase_offsets[0].common)
+    interaction_union = set(phase_offsets[0].interaction)
+    interaction_intersection = set(phase_offsets[0].interaction)
+    for offsets in phase_offsets[1:]:
+      startup_union |= set(offsets.startup)
+      startup_intersection &= set(offsets.startup)
+      common_union |= set(offsets.common)
+      common_intersection &= set(offsets.common)
+      interaction_union |= set(offsets.interaction)
+      interaction_intersection &= set(offsets.interaction)
+    startup_stability = self._SafeDiv(
+        self._processor.OffsetsPrimarySize(startup_union),
+        self._processor.OffsetsPrimarySize(startup_intersection))
+    common_stability = self._SafeDiv(
+        self._processor.OffsetsPrimarySize(common_union),
+        self._processor.OffsetsPrimarySize(common_intersection))
+    interaction_stability = self._SafeDiv(
+        self._processor.OffsetsPrimarySize(interaction_union),
+        self._processor.OffsetsPrimarySize(interaction_intersection))
+    return (startup_stability, common_stability, interaction_stability)
+
+  def _GetOrderfilePhaseOffsets(self):
+    """Compute the phase offsets for each run.
+
+    Returns:
+      [OrderfilePhaseOffsets] Each run corresponds to an OrderfilePhaseOffsets,
+          which groups the symbol offsets discovered in the runs.
+    """
+    if self._phase_offsets is not None:
+      return self._phase_offsets
+
+    assert self._profiles.GetPhases() == set([0, 1]), 'Unexpected phases'
+    self._phase_offsets = []
+    for first, second in zip(self._profiles.GetRunGroupOffsets(phase=0),
+                             self._profiles.GetRunGroupOffsets(phase=1)):
+      all_first_offsets = self._processor.GetReachedOffsetsFromDump(first)
+      all_second_offsets = self._processor.GetReachedOffsetsFromDump(second)
+      first_offsets_set = set(all_first_offsets)
+      second_offsets_set = set(all_second_offsets)
+      common_offsets_set = first_offsets_set & second_offsets_set
+      first_offsets_set -= common_offsets_set
+      second_offsets_set -= common_offsets_set
+
+      startup = [x for x in all_first_offsets
+                 if x in first_offsets_set]
+
+      interaction = [x for x in all_second_offsets
+                     if x in second_offsets_set]
+
+      common_seen = set()
+      common = []
+      for x in itertools.chain(all_first_offsets, all_second_offsets):
+        if x in common_offsets_set and x not in common_seen:
+          common_seen.add(x)
+          common.append(x)
+
+      self._phase_offsets.append(OrderfilePhaseOffsets(
+          startup=startup,
+          interaction=interaction,
+          common=common))
+
+    return self._phase_offsets
+
+  @classmethod
+  def _SafeDiv(cls, a, b):
+    if not b:
+      return None
+    return float(a) / b
+
+
+def _CreateArgumentParser():
+  parser = argparse.ArgumentParser(
+      description='Compute statistics on phased orderfiles')
+  parser.add_argument('--profile-directory', type=str, required=True,
+                      help=('Directory containing profile runs. Files '
+                            'matching {} are used.'.format(PROFILE_GLOB)))
+  parser.add_argument('--instrumented-build-dir', type=str,
+                      help='Path to the instrumented build', required=True)
+  parser.add_argument('--library-name', default='libchrome.so',
+                      help=('Chrome shared library name (usually libchrome.so '
+                            'or libmonochrome.so'))
+  return parser
+
+
+def main():
+  logging.basicConfig(level=logging.INFO)
+  parser = _CreateArgumentParser()
+  args = parser.parse_args()
+  profiles = process_profiles.ProfileManager(
+      glob.glob(os.path.join(args.profile_directory, PROFILE_GLOB)))
+  processor = process_profiles.SymbolOffsetProcessor(os.path.join(
+      args.instrumented_build_dir, 'lib.unstripped', args.library_name))
+  phaser = PhasedAnalyzer(profiles, processor)
+  print 'Stability: {:.2f} {:.2f} {:.2f}'.format(*phaser.ComputeStability())
+
+
+if __name__ == '__main__':
+  main()

tools/cygprofile/phased_orderfile_unittest.py

+# Copyright 2018 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.
+
+"""Tests for phased_orderfile.py."""
+
+import collections
+import unittest
+
+import phased_orderfile
+import process_profiles
+
+SymbolInfo = collections.namedtuple('SymbolInfo', ['name', 'offset', 'size'])
+
+
+class TestProfileManager(process_profiles.ProfileManager):
+  def __init__(self, filecontents_mapping):
+    super(TestProfileManager, self).__init__(filecontents_mapping.keys())
+    self._filecontents_mapping = filecontents_mapping
+
+  def _ReadOffsets(self, filename):
+    return self._filecontents_mapping[filename]
+
+
+class TestSymbolOffsetProcessor(process_profiles.SymbolOffsetProcessor):
+  def __init__(self, symbol_infos):
+    super(TestSymbolOffsetProcessor, self).__init__(None)
+    self._symbol_infos = symbol_infos
+
+
+class Mod10Processor(object):
+  """A restricted mock for a SymbolOffsetProcessor.
+
+  This only implements GetReachedOffsetsFromDump, and works by mapping a dump
+  offset to offset - (offset % 10). If the dump offset is negative, it is marked
+  as not found.
+  """
+  def GetReachedOffsetsFromDump(self, dump):
+    return [x - (x % 10) for x in dump if x >= 0]
+
+
+class PhasedOrderfileTestCase(unittest.TestCase):
+
+  def setUp(self):
+    self._file_counter = 0
+
+  def File(self, timestamp_sec, phase):
+    self._file_counter += 1
+    return 'file-{}-{}.txt_{}'.format(
+        self._file_counter, timestamp_sec * 1000 * 1000 * 1000, phase)
+
+  def testProfileStability(self):
+    symbols = [SymbolInfo(str(i), i, 10)
+               for i in xrange(20)]
+    phaser = phased_orderfile.PhasedAnalyzer(
+        None, TestSymbolOffsetProcessor(symbols))
+    opo = lambda s, c, i: phased_orderfile.OrderfilePhaseOffsets(
+        startup=s, common=c, interaction=i)
+    phaser._phase_offsets = [opo(range(5), range(6, 10), range(11,15)),
+                             opo(range(4), range(6, 10), range(18, 20))]
+    self.assertEquals((1.25, 1, None), phaser.ComputeStability())
+
+  def testIsStable(self):
+    symbols = [SymbolInfo(str(i), i, 10)
+               for i in xrange(20)]
+    phaser = phased_orderfile.PhasedAnalyzer(
+        None, TestSymbolOffsetProcessor(symbols))
+    opo = lambda s, c, i: phased_orderfile.OrderfilePhaseOffsets(
+        startup=s, common=c, interaction=i)
+    phaser._phase_offsets = [opo(range(5), range(6, 10), range(11,15)),
+                             opo(range(4), range(6, 10), range(18, 20))]
+    phaser.STARTUP_STABILITY_THRESHOLD = 1.1
+    self.assertFalse(phaser.IsStableProfile())
+    phaser.STARTUP_STABILITY_THRESHOLD = 1.5
+    self.assertTrue(phaser.IsStableProfile())
+
+  def testGetOrderfilePhaseOffsets(self):
+    mgr = TestProfileManager({
+        self.File(0, 0): [12, 21, -1, 33],
+        self.File(0, 1): [31, 49, 52],
+        self.File(100, 0): [113, 128],
+        self.File(200, 1): [132, 146],
+        self.File(300, 0): [19, 20, 32],
+        self.File(300, 1): [24, 39]})
+    phaser = phased_orderfile.PhasedAnalyzer(mgr, Mod10Processor())
+    opo = lambda s, c, i: phased_orderfile.OrderfilePhaseOffsets(
+        startup=s, common=c, interaction=i)
+    self.assertListEqual([opo([10, 20], [30], [40, 50]),
+                          opo([110, 120], [], []),
+                          opo([], [], [130, 140]),
+                          opo([10], [20, 30], [])],
+                         phaser._GetOrderfilePhaseOffsets())

tools/cygprofile/process_profiles.py

@@ -111,6 +111,17 @@ class SymbolOffsetProcessor(object):
 
     return self._offset_to_primary
 
+  def OffsetsPrimarySize(self, offsets):
+    """Computes the total primary size of a set of offsets.
+
+    Args:
+      offsets (int iterable) a set of offsets.
+
+    Returns
+      int The sum of the primary size of the offsets.
+    """
+    return sum(self.OffsetToPrimaryMap()[x].size for x in offsets)
+
   def GetReachedOffsetsFromDump(self, dump):
     """Find the symbol offsets from a list of binary offsets.
 
@@ -220,7 +231,6 @@ class ProfileManager(object):
     time. This files can be grouped into run sets that are within 30 seconds of
     each other. Each run set is then grouped into phases as before.
   """
-
   class _RunGroup(object):
     RUN_GROUP_THRESHOLD_NS = 30e9
 
@@ -251,6 +261,14 @@ class ProfileManager(object):
     self._filenames = sorted(filenames, key=self._Timestamp)
     self._run_groups = None
 
+  def GetPhases(self):
+    """Return the set of phases of all orderfiles.
+
+    Returns:
+      set(int)
+    """
+    return set(self._Phase(f) for f in self._filenames)
+
   def GetMergedOffsets(self, phase=None):
     """Merges files, as if from a single dump.
 

tools/cygprofile/process_profiles_unittest.py

@@ -83,14 +83,21 @@ class ProcessProfilesTestCase(unittest.TestCase):
     processor = TestSymbolOffsetProcessor(symbol_infos)
     self.assertDictEqual({8: symbol_infos[1]}, processor.OffsetToPrimaryMap())
 
-
   def testMatchSymbols(self):
-    symbols_b = [SymbolInfo('W', 30, 10),
+    symbols = [SymbolInfo('W', 30, 10),
                  SymbolInfo('Y', 60, 5),
                  SymbolInfo('X', 100, 10)]
-    processor_b = TestSymbolOffsetProcessor(symbols_b)
-    self.assertListEqual(symbols_b[1:3],
-                         processor_b.MatchSymbolNames(['Y', 'X']))
+    processor = TestSymbolOffsetProcessor(symbols)
+    self.assertListEqual(symbols[1:3],
+                         processor.MatchSymbolNames(['Y', 'X']))
+
+  def testOffsetsPrimarySize(self):
+    symbols = [SymbolInfo('W', 10, 1),
+               SymbolInfo('X', 20, 2),
+               SymbolInfo('Y', 30, 4),
+               SymbolInfo('Z', 40, 8)]
+    processor = TestSymbolOffsetProcessor(symbols)
+    self.assertEqual(13, processor.OffsetsPrimarySize([10, 30, 40]))
 
   def testMedian(self):
     self.assertEquals(None, process_profiles._Median([]))
@@ -155,6 +162,15 @@ class ProcessProfilesTestCase(unittest.TestCase):
     self.assertEquals(2, len(offsets_list))
     self.assertListEqual([5, 6, 7, 1, 2, 3, 4], offsets_list[0])
 
+  def testPhases(self):
+    mgr = TestProfileManager({
+        self.File(40, 0): [],
+        self.File(150, 0): [],
+        self.File(30, 1): [],
+        self.File(30, 2): [],
+        self.File(30, 0): []})
+    self.assertEquals(set([0,1,2]), mgr.GetPhases())
+
 
 if __name__ == '__main__':
   unittest.main()