Dump data for stacked graphs in Chrome Endure.

chrome/test/functional/perf_endure.py

 #!/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.
 
 """Performance tests for Chrome Endure (long-running perf tests on Chrome).
 
 This module accepts the following environment variable inputs:
   TEST_LENGTH: The number of seconds in which to run each test.
   PERF_STATS_INTERVAL: The number of seconds to wait in-between each sampling
@@ skipping 19 matching lines @@
 import pyauto_utils
 import remote_inspector_client
 import selenium.common.exceptions
 from selenium.webdriver.support.ui import WebDriverWait
 
 
 class NotSupportedEnvironmentError(RuntimeError):
   """Represent an error raised since the environment (OS) is not supported."""
   pass
 
+
+class DeepMemoryProfiler(object):

[dennis_jeffrey, 2012/09/05 17:34:12]

add a docstring for this class

[Dai Mikurube (NOT FULLTIME), 2012/09/06 05:30:10]

Done.

+  DEEP_MEMORY_PROFILE = False
+  DEEP_MEMORY_PROFILE_SAVE = False
+
+  _DMPROF_DIR_PATH = os.path.join(
+      os.path.dirname(__file__), os.pardir, os.pardir, os.pardir,
+      'tools', 'deep_memory_profiler')
+  _DMPROF_SCRIPT_PATH = os.path.join(_DMPROF_DIR_PATH, 'dmprof')
+
+  def __init__(self):
+    self._enabled = self.GetDeepMemoryProfileEnv(
+        'DEEP_MEMORY_PROFILE', bool, self.DEEP_MEMORY_PROFILE)
+    self._save = False
+    self._json_file = None
+    self._last_json_filename = ''
+    self._proc = None
+    self._last_time = -1.0
+
+  def SetUp(self, is_linux):
+    if self._enabled:

[dennis_jeffrey, 2012/09/05 17:34:12]

Rather than adding the "is enabled" checks at the start of all of these
functions, maybe we should do the check at the call site instead (i.e., right
before the function is invoked in the first place).  I think that will enhance
readability at the call sites because it makes it clear that those functions
will only execute if DMP is enabled.

[Dai Mikurube (NOT FULLTIME), 2012/09/06 05:30:10]

Added checks at the call sites, but kept DeepMemoryProfiler-side as is for
safety.

+      if not is_linux:
+        raise NotSupportedEnvironmentError(
+            'Deep Memory Profiler is not supported in this environment (OS).')
+      dir_prefix = 'endure.%s.' % datetime.today().strftime('%Y%m%d.%H%M%S')
+      self._tempdir = tempfile.mkdtemp(prefix=dir_prefix)
+      os.environ['HEAPPROFILE'] = os.path.join(self._tempdir, 'endure')
+      os.environ['HEAP_PROFILE_MMAP'] = '1'
+      os.environ['DEEP_HEAP_PROFILE'] = '1'
+      self._save = self.GetDeepMemoryProfileEnv(
+          'DEEP_MEMORY_PROFILE_SAVE', bool, self.DEEP_MEMORY_PROFILE_SAVE)
+
+  def TearDown(self):
+    if self._enabled:
+      del os.environ['DEEP_HEAP_PROFILE']
+      del os.environ['HEAP_PROFILE_MMAP']
+      del os.environ['HEAPPROFILE']
+
+  def RemoveTemporaryFiles(self):
+    """Remove the temporary directory after Chrome finishes."""
+    if self._enabled and not self._save and self._tempdir:
+      pyauto_utils.RemovePath(self._tempdir)
+
+  def IsEnabled(self):
+    return self._enabled
+
+  def LogFirstMessage(self):
+    if self._enabled:
+      logging.info('Running with the Deep Memory Profiler.')
+      if self._save:
+        logging.info('  Dumped files won\'t be cleaned.')
+      else:
+        logging.info('  Dumped files will be cleaned up after every test.')
+
+  def GetDeepMemoryProfileEnv(self, env_name, converter, default):
+    """Returns a converted environment variable for the Deep Memory Profiler.
+
+    Args:
+      env_name: A string name of an environment variable.
+      converter: A function taking a string to convert an environment variable.
+      default: A value used if the environment variable is not specified.
+
+    Returns:
+      A value converted from the environment variable with 'converter'.
+    """
+    return converter(os.environ.get(env_name, default))
+
+  def StartProfiler(self, proc_info, is_last):
+    """Starts Deep Memory Profiler in background."""
+    if self._enabled:
+      logging.info('  Profiling with the Deep Memory Profiler...')
+
+      # Wait for a running dmprof process for last _GetPerformanceStat call to
+      # cover last dump files.
+      if is_last:
+        logging.info('    Waiting for the last dmprof.')
+        self._WaitForDeepMemoryProfiler()
+
+      if self._proc and self._proc.poll() is None:
+        logging.info('    Last dmprof is still running.')
+      else:
+        if self._json_file:
+          self._last_json_filename = self._json_file.name
+          self._json_file.close()
+          self._json_file = None
+        first_dump = ''
+        last_dump = ''
+        for filename in sorted(os.listdir(self._tempdir)):
+          if re.match('^endure.%05d.\d+.heap$' % proc_info['tab_pid'],
+                      filename):
+            logging.info('    Profiled dump file: %s' % filename)
+            last_dump = filename
+            if not first_dump:
+              first_dump = filename
+        if first_dump:
+          logging.info('    First dump file: %s' % first_dump)
+          matched = re.match('^endure.\d+.(\d+).heap$', last_dump)
+          last_sequence_id = matched.group(1)
+          self._json_file = open(
+              os.path.join(self._tempdir,
+                           'endure.%05d.%s.json' % (proc_info['tab_pid'],
+                                                    last_sequence_id)), 'w+')
+          self._proc = subprocess.Popen(
+              '%s json %s' % (self._DMPROF_SCRIPT_PATH,
+                              os.path.join(self._tempdir, first_dump)),
+              shell=True, stdout=self._json_file)
+          # Don't wait for the new process since dmprof may take long time.
+

[dennis_jeffrey, 2012/09/05 17:34:12]

remove this blank line; the comment above goes with the 2 lines below

[Dai Mikurube (NOT FULLTIME), 2012/09/06 05:30:10]

Done.

+          if is_last:
+            self._WaitForDeepMemoryProfiler()
+
+        else:
+          logging.info('    No dump files.')
+
+  def ParseResultAndOutputPerfGraphValues(
+      self, webapp_name, test_description, output_perf_graph_value):
+    """Parses Deep Memory Profiler result, and outputs perf graph values."""
+    if self._enabled:
+      results = {}
+      if self._last_json_filename:
+        json_data = {}
+        with open(self._last_json_filename) as json_f:
+          json_data = json.load(json_f)
+        if json_data['version'] == 'JSON_DEEP_1':
+          results = json_data['snapshots']
+        elif json_data['version'] == 'JSON_DEEP_2':
+          results = json_data['policies']['l2']['snapshots']
+      if results and results[-1]['second'] > self._last_time:
+        started = False
+        for legend in json_data['policies']['l2']['legends']:
+          if legend == 'FROM_HERE_FOR_TOTAL':
+            started = True
+          elif legend == 'UNTIL_HERE_FOR_TOTAL':
+            break
+          elif started:
+            output_perf_graph_value(
+                legend.encode('utf-8'), [
+                    (int(round(snapshot['second'])), snapshot[legend] / 1024)
+                    for snapshot in results
+                    if snapshot['second'] > self._last_time],
+                'KB',
+                graph_name='%s%s-DMP' % (webapp_name, test_description),
+                units_x='seconds', is_stacked=True)
+        self._last_time = results[-1]['second']
+
+  def _WaitForDeepMemoryProfiler(self):
+    """Waits for the Deep Memory Profiler to finish if running."""
+    if self._enabled and self._proc:
+      self._proc.wait()
+      self._proc = None
+      if self._json_file:
+        self._last_json_filename = self._json_file.name
+        self._json_file.close()
+        self._json_file = None
+
+
 class ChromeEndureBaseTest(perf.BasePerfTest):
   """Implements common functionality for all Chrome Endure tests.
 
   All Chrome Endure test classes should inherit from this class.
   """
 
   _DEFAULT_TEST_LENGTH_SEC = 60 * 60 * 6  # Tests run for 6 hours.
   _GET_PERF_STATS_INTERVAL = 60 * 5  # Measure perf stats every 5 minutes.
   # TODO(dennisjeffrey): Do we still need to tolerate errors?
   _ERROR_COUNT_THRESHOLD = 50  # Number of ChromeDriver errors to tolerate.
-  _DEEP_MEMORY_PROFILE = False
-  _DEEP_MEMORY_PROFILE_SAVE = False
-
-  _DMPROF_DIR_PATH = os.path.join(
-      os.path.dirname(__file__), os.pardir, os.pardir, os.pardir,
-      'tools', 'deep_memory_profiler')
-
-  _DMPROF_SCRIPT_PATH = os.path.join(_DMPROF_DIR_PATH, 'dmprof')
 
   def setUp(self):
     # The environment variables for the Deep Memory Profiler must be set
     # before perf.BasePerfTest.setUp() to inherit them to Chrome.
-    self._deep_memory_profile = self._GetDeepMemoryProfileEnv(
-        'DEEP_MEMORY_PROFILE', bool, self._DEEP_MEMORY_PROFILE)
-
-    if self._deep_memory_profile:
-      if not self.IsLinux():
-        raise NotSupportedEnvironmentError(
-            'Deep Memory Profiler is not supported in this environment (OS).')
-      dir_prefix = 'endure.%s.' % datetime.today().strftime('%Y%m%d.%H%M%S')
-      self._deep_tempdir = tempfile.mkdtemp(prefix=dir_prefix)
-      os.environ['HEAPPROFILE'] = os.path.join(self._deep_tempdir, 'endure')
-      os.environ['HEAP_PROFILE_MMAP'] = 'True'
-      os.environ['DEEP_HEAP_PROFILE'] = 'True'
+    self._dmprof = DeepMemoryProfiler()
+    self._dmprof.SetUp(self.IsLinux())
 
     perf.BasePerfTest.setUp(self)
 
     self._test_length_sec = int(
         os.environ.get('TEST_LENGTH', self._DEFAULT_TEST_LENGTH_SEC))
     self._get_perf_stats_interval = int(
         os.environ.get('PERF_STATS_INTERVAL', self._GET_PERF_STATS_INTERVAL))
 
-    self._deep_memory_profile_save = self._GetDeepMemoryProfileEnv(
-        'DEEP_MEMORY_PROFILE_SAVE', bool, self._DEEP_MEMORY_PROFILE_SAVE)
-
     logging.info('Running test for %d seconds.', self._test_length_sec)
     logging.info('Gathering perf stats every %d seconds.',
                  self._get_perf_stats_interval)
-    if self._deep_memory_profile:
-      logging.info('Running with the Deep Memory Profiler.')
-      if self._deep_memory_profile_save:
-        logging.info('  Dumped files won\'t be cleaned.')
-      else:
-        logging.info('  Dumped files will be cleaned up after every test.')
+
+    self._dmprof.LogFirstMessage()
 
     # Set up a remote inspector client associated with tab 0.
     logging.info('Setting up connection to remote inspector...')
     self._remote_inspector_client = (
         remote_inspector_client.RemoteInspectorClient())
     logging.info('Connection to remote inspector set up successfully.')
 
     self._test_start_time = 0
     self._num_errors = 0
     self._events_to_output = []
-    self._deep_memory_profile_json_file = None
-    self._deep_memory_profile_last_json_filename = ''
-    self._deep_memory_profile_proc = None
 
   def tearDown(self):
     logging.info('Terminating connection to remote inspector...')
     self._remote_inspector_client.Stop()
     logging.info('Connection to remote inspector terminated.')
-    if self._deep_memory_profile:
-      del os.environ['DEEP_HEAP_PROFILE']
-      del os.environ['HEAP_PROFILE_MMAP']
-      del os.environ['HEAPPROFILE']
+
+    self._dmprof.TearDown()
 
     # Must be done at end of this function except for post-cleaning after
     # Chrome finishes.
     perf.BasePerfTest.tearDown(self)
 
-    # Remove the temporary directory after Chrome finishes in tearDown.
-    if (self._deep_memory_profile and
-        not self._deep_memory_profile_save and
-        self._deep_tempdir):
-      pyauto_utils.RemovePath(self._deep_tempdir)
-
-  def _GetDeepMemoryProfileEnv(self, env_name, converter, default):
-    """Returns a converted environment variable for the Deep Memory Profiler.
-
-    Args:
-      env_name: A string name of an environment variable.
-      converter: A function taking a string to convert an environment variable.
-      default: A value used if the environment variable is not specified.
-
-    Returns:
-      A value converted from the environment variable with 'converter'.
-    """
-    return converter(os.environ.get(env_name, default))
-
-  def _WaitForDeepMemoryProfiler(self):
-    """Waits for the Deep Memory Profiler to finish if running."""
-    if self._deep_memory_profile and self._deep_memory_profile_proc:
-      self._deep_memory_profile_proc.wait()
-      self._deep_memory_profile_proc = None
-      if self._deep_memory_profile_json_file:
-        self._deep_memory_profile_last_json_filename = (
-            self._deep_memory_profile_json_file.name)
-        self._deep_memory_profile_json_file.close()
-        self._deep_memory_profile_json_file = None
+    self._dmprof.RemoveTemporaryFiles()

[dennis_jeffrey, 2012/09/05 17:34:12]

is there a reason this is done after calling the base class's tearDown()?  If
not, maybe we could move it up above to just below line 241, so the two function
calls related to DMP are invoked one after the other.

[Dai Mikurube (NOT FULLTIME), 2012/09/06 05:30:10]

It must be called after Chrome finishes.  Chrome may dump last files at the end.

Finally, merged the two functions into TearDown().  Now, it is called after
perf.BasePerfTest.tearDown().

 
   def ExtraChromeFlags(self):
     """Ensures Chrome is launched with custom flags.
 
     Returns:
       A list of extra flags to pass to Chrome when it is launched.
     """
     # The same with setUp, but need to fetch the environment variable since
     # ExtraChromeFlags is called before setUp.
-    deep_memory_profile = self._GetDeepMemoryProfileEnv(
-        'DEEP_MEMORY_PROFILE', bool, self._DEEP_MEMORY_PROFILE)
+    deep_memory_profile = self._dmprof.GetDeepMemoryProfileEnv(
+        'DEEP_MEMORY_PROFILE', bool, self._dmprof.DEEP_MEMORY_PROFILE)
 
     # Ensure Chrome enables remote debugging on port 9222.  This is required to
     # interact with Chrome's remote inspector.
     extra_flags = ['--remote-debugging-port=9222']
     if deep_memory_profile:
       extra_flags.append('--no-sandbox')
     return (perf.BasePerfTest.ExtraChromeFlags(self) + extra_flags)
 
   def _OnTimelineEvent(self, event_info):
     """Invoked by the Remote Inspector Client when a timeline event occurs.
@@ skipping 32 matching lines @@
       do_scenario: A callable to be invoked that implements the scenario to be
           performed by this test.  The callable is invoked iteratively for the
           duration of the test.
       frame_xpath: The string xpath of the frame in which to inject javascript
           to clear chromedriver's cache (a temporary workaround until the
           WebDriver team changes how they handle their DOM node cache).
     """
     self._num_errors = 0
     self._test_start_time = time.time()
     last_perf_stats_time = time.time()
-    if self._deep_memory_profile:
+    if self._dmprof.IsEnabled():
       self.HeapProfilerDump('renderer', 'Chrome Endure (first)')
     self._GetPerformanceStats(
         webapp_name, test_description, tab_title_substring)
     self._iteration_num = 0  # Available to |do_scenario| if needed.
 
     self._remote_inspector_client.StartTimelineEventMonitoring(
         self._OnTimelineEvent)
 
     while time.time() - self._test_start_time < self._test_length_sec:
       self._iteration_num += 1
 
       if self._num_errors >= self._ERROR_COUNT_THRESHOLD:
         logging.error('Error count threshold (%d) reached. Terminating test '
                       'early.' % self._ERROR_COUNT_THRESHOLD)
         break
 
       if time.time() - last_perf_stats_time >= self._get_perf_stats_interval:
         last_perf_stats_time = time.time()
-        if self._deep_memory_profile:
+        if self._dmprof.IsEnabled():
           self.HeapProfilerDump('renderer', 'Chrome Endure')
         self._GetPerformanceStats(
             webapp_name, test_description, tab_title_substring)
 
       if self._iteration_num % 10 == 0:
         remaining_time = self._test_length_sec - (time.time() -
                                                   self._test_start_time)
         logging.info('Chrome interaction #%d. Time remaining in test: %d sec.' %
                      (self._iteration_num, remaining_time))
 
       do_scenario()
       # Clear ChromeDriver's DOM node cache so its growth doesn't affect the
       # results of Chrome Endure.
       # TODO(dennisjeffrey): Once the WebDriver team implements changes to
       # handle their DOM node cache differently, we need to revisit this.  It
       # may no longer be necessary at that point to forcefully delete the cache.
       # Additionally, the Javascript below relies on an internal property of
       # WebDriver that may change at any time.  This is only a temporary
       # workaround to stabilize the Chrome Endure test results.
       js = """
         (function() {
           delete document.$wdc_;
           window.domAutomationController.send('done');
         })();
       """
       self.ExecuteJavascript(js, frame_xpath=frame_xpath)
 
     self._remote_inspector_client.StopTimelineEventMonitoring()
 
-    if self._deep_memory_profile:
+    if self._dmprof.IsEnabled():
       self.HeapProfilerDump('renderer', 'Chrome Endure (last)')
     self._GetPerformanceStats(
         webapp_name, test_description, tab_title_substring, is_last=True)
 
   def _GetProcessInfo(self, tab_title_substring):
     """Gets process info associated with an open browser/tab.
 
     Args:
       tab_title_substring: A unique substring contained within the title of
           the tab to use; needed for locating the tab info.
@@ skipping 60 matching lines @@
           the tab to use, for identifying the appropriate tab.
       is_last: A boolean value which should be True if it's the last call of
           _GetPerformanceStats.  The default is False.
     """
     logging.info('Gathering performance stats...')
     elapsed_time = int(round(time.time() - self._test_start_time))
 
     memory_counts = self._remote_inspector_client.GetMemoryObjectCounts()
     proc_info = self._GetProcessInfo(tab_title_substring)
 
-    # Run Deep Memory Profiler in background.
-    if self._deep_memory_profile:
-      logging.info('  Profiling with the Deep Memory Profiler...')
-
-      # Wait for a running dmprof process for last _GetPerformanceStat call to
-      # cover last dump files.
-      if is_last:
-        logging.info('    Waiting for the last dmprof.')
-        self._WaitForDeepMemoryProfiler()
-
-      if (self._deep_memory_profile_proc and
-          self._deep_memory_profile_proc.poll() is None):
-        logging.info('    Last dmprof is still running.')
-      else:
-        if self._deep_memory_profile_json_file:
-          self._deep_memory_profile_last_json_filename = (
-              self._deep_memory_profile_json_file.name)
-          self._deep_memory_profile_json_file.close()
-          self._deep_memory_profile_json_file = None
-        first_dump = ''
-        last_dump = ''
-        for filename in sorted(os.listdir(self._deep_tempdir)):
-          if re.match('^endure.%05d.\d+.heap$' % proc_info['tab_pid'],
-                      filename):
-            logging.info('    Profiled dump file: %s' % filename)
-            last_dump = filename
-            if not first_dump:
-              first_dump = filename
-        if first_dump:
-          logging.info('    First dump file: %s' % first_dump)
-          matched= re.match('^endure.\d+.(\d+).heap$', last_dump)
-          last_sequence_id = matched.group(1)
-          self._deep_memory_profile_json_file = open(
-              os.path.join(self._deep_tempdir,
-                           'endure.%05d.%s.json' % (proc_info['tab_pid'],
-                                                    last_sequence_id)), 'w+')
-          self._deep_memory_profile_proc = subprocess.Popen(
-              '%s json %s' % (self._DMPROF_SCRIPT_PATH,
-                              os.path.join(self._deep_tempdir, first_dump)),
-              shell=True, stdout=self._deep_memory_profile_json_file)
-          # Don't wait for the new process since dmprof may take long time.
-
-          if is_last:
-            self._WaitForDeepMemoryProfiler()
-
-        else:
-          logging.info('    No dump files.')
+    self._dmprof.StartProfiler(proc_info, is_last)
 
     # DOM node count.
     dom_node_count = memory_counts['DOMNodeCount']
     self._OutputPerfGraphValue(
         'TotalDOMNodeCount', [(elapsed_time, dom_node_count)], 'nodes',
         graph_name='%s%s-Nodes-DOM' % (webapp_name, test_description),
         units_x='seconds')
 
     # Event listener count.
     event_listener_count = memory_counts['EventListenerCount']
@@ skipping 25 matching lines @@
         graph_name='%s%s-V8MemUsed' % (webapp_name, test_description),
         units_x='seconds')
 
     # V8 memory allocated.
     v8_mem_allocated = v8_info['v8_memory_allocated'] / 1024.0  # Convert to KB.
     self._OutputPerfGraphValue(
         'V8MemoryAllocated', [(elapsed_time, v8_mem_allocated)], 'KB',
         graph_name='%s%s-V8MemAllocated' % (webapp_name, test_description),
         units_x='seconds')
 
-    # Deep Memory Profiler result.
-    if self._deep_memory_profile:
-      deep_memory_profile_results = {}
-      if self._deep_memory_profile_last_json_filename:
-        json_data = {}
-        with open(self._deep_memory_profile_last_json_filename) as json_f:
-          json_data = json.load(json_f)
-        if json_data['version'] == 'JSON_DEEP_1':
-          deep_memory_profile_results = json_data['snapshots']
-        elif json_data['version'] == 'JSON_DEEP_2':
-          deep_memory_profile_results = json_data['policies']['l0']['snapshots']
-      if deep_memory_profile_results:
-        self._OutputPerfGraphValue(
-            'DMP-TCMallocUsed', [
-                (snapshot['second'], snapshot['tc-used-all'] / 1024.0)
-                for snapshot in deep_memory_profile_results],
-            'KB',
-            graph_name='%s%s-DMP-TCUsed' % (webapp_name, test_description),
-            units_x='seconds')
-      # TODO(dmikurube): Output graph values (for multi-lined graphs), here.
-      # 'deep_memory_profile_results' is the value to be output.
+    self._dmprof.ParseResultAndOutputPerfGraphValues(
+        webapp_name, test_description, self._OutputPerfGraphValue)
 
     logging.info('  Total DOM node count: %d nodes' % dom_node_count)
     logging.info('  Event listener count: %d listeners' % event_listener_count)
     logging.info('  Browser process private memory: %d KB' %
                  proc_info['browser_private_mem'])
     logging.info('  Tab process private memory: %d KB' %
                  proc_info['tab_private_mem'])
     logging.info('  V8 memory used: %f KB' % v8_mem_used)
     logging.info('  V8 memory allocated: %f KB' % v8_mem_allocated)
 
@@ skipping 657 matching lines @@
         self._num_errors += 1
 
       time.sleep(1)
 
     self._RunEndureTest(self._WEBAPP_NAME, self._TAB_TITLE_SUBSTRING,
                         test_description, scenario)
 
 
 if __name__ == '__main__':
   pyauto_functional.Main()