Enable Deep Memory Profiler in perf_endure.py.

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
       of performance/memory statistics.
+
+  DEEP_MEMORY_PROFILE: Enable the Deep Memory Profiler if it's set to 'True'.
+  DEEP_MEMORY_PROFILE_INTERVAL: The number of seconds to wait in-between each
+      sampling for the Deep Memory Profiler.
+  DEEP_MEMORY_PROFILE_SAVE: Don't clean up dump files if it's set to 'True'.
 """
 
+from datetime import datetime
+import json
 import logging
 import os
 import re
+import subprocess
+import tempfile
 import time
 
 import perf
 import pyauto_functional  # Must be imported before pyauto.
 import pyauto
+import pyauto_utils
 import remote_inspector_client
 import selenium.common.exceptions
 from selenium.webdriver.support.ui import WebDriverWait
 

[dennis_jeffrey, 2012/05/09 04:31:47]

add 1 more blank line here

[Dai Mikurube (NOT FULLTIME), 2012/05/09 07:44:34]

Done.

-
 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 * 10  # Measure perf stats every 10 minutes.
   _ERROR_COUNT_THRESHOLD = 300  # Number of ChromeDriver errors to tolerate.
+  _DEEP_MEMORY_PROFILE = False
+  _DEEP_MEMORY_PROFILE_INTERVAL = _GET_PERF_STATS_INTERVAL
+  _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')
+
+  _CHROME_BIN_PATH = os.path.join(perf.BasePerfTest.BrowserPath(), 'chrome')

[dennis_jeffrey, 2012/05/09 04:31:47]

I think we can just say "self.BrowserPath()" here

[Dai Mikurube (NOT FULLTIME), 2012/05/09 07:44:34]

Since it's not in "def something(self)", we can't use self here.  I couldn't use
just "BrowserPath()" and "BasePerfTest.BrowserPath()", too..

[dennis_jeffrey, 2012/05/09 23:03:55]

Ah, you're right!

 
   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, False)
+    print self._deep_memory_profile

[dennis_jeffrey, 2012/05/09 04:31:47]

i recommend using logging.debug or logging.info, or else remove this line

[Dai Mikurube (NOT FULLTIME), 2012/05/09 07:44:34]

Thanks.  Removed this line.

+
+    self._deep_memory_profile_interval = self.GetDeepMemoryProfileEnv(
+        'DEEP_MEMORY_PROFILE_INTERVAL', int,
+        self._DEEP_MEMORY_PROFILE_INTERVAL, 0)
+
+    if self._deep_memory_profile:
+      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'
+      # TODO(dmikurube): Stop to set HEAP_PROFILE_TIME_INTERVAL when PyAuto
+      # supports to dump renderer heap profile.
+      os.environ['HEAP_PROFILE_TIME_INTERVAL'] = (
+          '%d' % self._deep_memory_profile_interval)

[dennis_jeffrey, 2012/05/09 04:31:47]

os.environ['HEAP_PROFILE_TIME_INTERVAL'] = (
    str(self._deep_memory_profile_interval))

[Dai Mikurube (NOT FULLTIME), 2012/05/09 07:44:34]

Done.

+
     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, False)
+
     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 every %d seconds.',
+                   self._deep_memory_profile_interval)
+      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.')
 
     # 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._iteration_num = 0

[dennis_jeffrey, 2012/05/09 04:31:47]

i think this line is unnecessary

[Dai Mikurube (NOT FULLTIME), 2012/05/09 07:44:34]

Thanks.  It may be mixed when I rebased.

+    self._deep_memory_profile_json_file = None
+    self._deep_memory_profile_last_json_filename = ''
+    self._deep_memory_profile_proc = None
+    self._deep_memory_profile_records = []
+    self._deep_memory_profile_last_index = 0
 
   def tearDown(self):
     logging.info('Terminating connection to remote inspector...')
     self._remote_inspector_client.Stop()
     logging.info('Connection to remote inspector terminated.')
-    perf.BasePerfTest.tearDown(self)  # Must be done at end of this function.
+    if self._deep_memory_profile:
+      # TODO(dmikurube): Stop to set HEAP_PROFILE_TIME_INTERVAL in setUp when
+      # PyAuto supports to dump renderer heap profile.
+      del os.environ['HEAP_PROFILE_TIME_INTERVAL']
+      del os.environ['DEEP_HEAP_PROFILE']
+      del os.environ['HEAP_PROFILE_MMAP']
+      del os.environ['HEAPPROFILE']
+
+    # 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(

[dennis_jeffrey, 2012/05/09 04:31:47]

prefix the function name with an underscore if it's meant to be used only
locally to this function.

[Dai Mikurube (NOT FULLTIME), 2012/05/09 07:44:34]

Done.

+      self, env_name, converter, default, not_supported):
+    """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.
+      not_supported: A value used if the Deep Memory Profiler is not supported.
+
+    Returns:
+      A value converted from the environment variable with 'converter'.
+    """
+    result = not_supported

[dennis_jeffrey, 2012/05/09 04:31:47]

rather than having a "not_supported" value, should we just raise an exception if
the current platform is not supported?

[Dai Mikurube (NOT FULLTIME), 2012/05/09 07:44:34]

Done.  Introduced a new RuntimeError: NotSupportedEnvironmentError.

+    if self.IsLinux():
+      result = converter(os.environ.get(env_name, default))
+    return result
+
+  def WaitForDeepMemoryProfiler(self):

[dennis_jeffrey, 2012/05/09 04:31:47]

prefix the function name with an underscore if it's meant to be used only
locally to this function.

[Dai Mikurube (NOT FULLTIME), 2012/05/09 07:44:34]

Done.

+    """Waits for the Deep Memory Profiler finished if running.

[dennis_jeffrey, 2012/05/09 04:31:47]

'finished' --> 'to finish'

[Dai Mikurube (NOT FULLTIME), 2012/05/09 07:44:34]

Done.

+    """

[dennis_jeffrey, 2012/05/09 04:31:47]

move this to the previous line if it fits there

[Dai Mikurube (NOT FULLTIME), 2012/05/09 07:44:34]

Done.

+    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
 
   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, False)
+
     # Ensure Chrome enables remote debugging on port 9222.  This is required to
     # interact with Chrome's remote inspector.
-    return (perf.BasePerfTest.ExtraChromeFlags(self) +
-            ['--remote-debugging-port=9222'])
+    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.
 
     Args:
       event_info: A dictionary containing raw information associated with a
          timeline event received from Chrome's remote inspector.  Refer to
          chrome/src/third_party/WebKit/Source/WebCore/inspector/Inspector.json
          for the format of this dictionary.
     """
@@ skipping 37 matching lines @@
         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
 
+      # TODO(dmikurube): Call HeapProfilerDump when PyAuto supports dumping for
+      # renderer processes.
+      # TODO(dmikurube): Need pid of the target process.
+
       if time.time() - last_perf_stats_time >= self._get_perf_stats_interval:
         last_perf_stats_time = time.time()
         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()
 
     self._remote_inspector_client.StopTimelineEventMonitoring()
+    # TODO(dmikurube): Call HeapProfilerDump when PyAuto supports dumping for
+    # renderer processes.
+
     self._GetPerformanceStats(
-        webapp_name, test_description, tab_title_substring)
+        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.
 
     Returns:
       A dictionary containing information about the browser and specified tab
       process:
       {
         'browser_private_mem': integer,  # Private memory associated with the
                                          # browser process, in KB.
         'tab_private_mem': integer,  # Private memory associated with the tab
                                      # process, in KB.
+        'tab_pid': integer,  # Process ID of the tab process.
       }
     """
     browser_process_name = (
         self.GetBrowserInfo()['properties']['BrowserProcessExecutableName'])
     info = self.GetProcessInfo()
 
     # Get the information associated with the browser process.
     browser_proc_info = []
     for browser_info in info['browsers']:
       if browser_info['process_name'] == browser_process_name:
@@ skipping 16 matching lines @@
                      msg='Expected to find 1 %s tab process, but found %d '
                          'instead.\nCurrent process info:\n%s.' % (
                          tab_title_substring, len(tab_proc_info),
                          self.pformat(info)))
 
     browser_proc_info = browser_proc_info[0]
     tab_proc_info = tab_proc_info[0]
     return {
       'browser_private_mem': browser_proc_info['working_set_mem']['priv'],
       'tab_private_mem': tab_proc_info['working_set_mem']['priv'],
+      'tab_pid': tab_proc_info['pid'],
     }
 
   def _GetPerformanceStats(self, webapp_name, test_description,
-                           tab_title_substring):
+                           tab_title_substring, is_last=False):
     """Gets performance statistics and outputs the results.
 
     Args:
       webapp_name: A string name for the webapp being tested.  Should not
           include spaces.  For example, 'Gmail', 'Docs', or 'Plus'.
       test_description: A string description of what the test does, used for
           outputting results to be graphed.  Should not contain spaces.  For
           example, 'ComposeDiscard' for Gmail.
       tab_title_substring: A unique substring contained within the title of
           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 %s %s' % (self._DMPROF_SCRIPT_PATH,
+                                      self._CHROME_BIN_PATH,
+                                      os.path.join(self._DMPROF_DIR_PATH,
+                                                   'policy.l0.txt'),
+                                      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.')
 
     # 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']
     self._OutputPerfGraphValue(
         'EventListenerCount', [(elapsed_time, event_listener_count)],
         'listeners',
         graph_name='%s%s-EventListeners' % (webapp_name, test_description),
         units_x='seconds')
 
     # Browser process private memory.
-    proc_info = self._GetProcessInfo(tab_title_substring)
     self._OutputPerfGraphValue(
         'BrowserPrivateMemory',
         [(elapsed_time, proc_info['browser_private_mem'])], 'KB',
         graph_name='%s%s-BrowserMem-Private' % (webapp_name, test_description),
         units_x='seconds')
 
     # Tab process private memory.
     self._OutputPerfGraphValue(
         'TabPrivateMemory',
         [(elapsed_time, proc_info['tab_private_mem'])], 'KB',
         graph_name='%s%s-TabMem-Private' % (webapp_name, test_description),
         units_x='seconds')
 
     # V8 memory used.
     v8_info = self.GetV8HeapStats()  # First window, first tab.
     v8_mem_used = v8_info['v8_memory_used'] / 1024.0  # Convert to KB.
     self._OutputPerfGraphValue(
         'V8MemoryUsed', [(elapsed_time, v8_mem_used)], 'KB',
         graph_name='%s%s-V8MemUsed' % (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':
+          for component in json_data['legends']:
+            deep_memory_profile_results[component] = []
+            for snapshot in json_data['snapshots']:
+              deep_memory_profile_results[component].append(snapshot[component])
+      if deep_memory_profile_results:
+        for index in range(self._deep_memory_profile_last_index,

[dennis_jeffrey, 2012/05/09 04:31:47]

rather than looping through each index and separately calling
_OutputPerfGraphValue for each one, we could build up a list of tuples and then
output the whole list of tuples in a single call to _OutputPerfGraphValue.

[Dai Mikurube (NOT FULLTIME), 2012/05/09 07:44:34]

Done.  Now it prints like following repeatedly:

RESULT ControlAttachDetachDOMTree-DMP-TCUsed: DMP-TCMallocUsed=
[(0.0,4906.142578125),(20.070510864257812,8683.955078125),(40.041018962860107,6970.5869140625),(60.301534175872803,23050.8740234375),(80.172039747238159,13989.8486328125)]
KB seconds

+                           len(deep_memory_profile_results['second'])):
+          self._OutputPerfGraphValue(
+              'DMP-TCMallocUsed',
+              [(deep_memory_profile_results['second'][index],
+                deep_memory_profile_results['tc-used-all'][index] / 1024.0)],
+              'KB',
+              graph_name='%s%s-DMP-TCUsed' % (webapp_name, test_description),
+              units_x='seconds')
+        self._deep_memory_profile_last_index = (
+            len(deep_memory_profile_results['second']))
+      # TODO(dmikurube): Output graph values (for multi-lined graphs), here.
+      # 'deep_memory_profile_results' is the value to be output.
+
     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)
 
     # Output any new timeline events that have occurred.
     if self._events_to_output:
@@ skipping 609 matching lines @@
           self._driver, self._wait, 'id("state")[text()="offline"]'):
         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()