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_INTERVAL: The number of seconds to wait in-between each

[dennis_jeffrey, 2012/04/17 01:20:27]

nit: add a blank line above this to separate the Deep Memory Profiler variables
from the other variables.

[dennis_jeffrey, 2012/04/17 01:20:27]

Right now, this variable seems to control whether or not the Deep Memory
Profiler is used.  By default, it seems to be turned on.  Do you think we should
use another variable, "DEEP_HEAP_PROFILE", to instead decide whether or not to
use the Deep Profiler?  And maybe we should set it to False by default (it
requires a DEBUG build, right?).

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Done.

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

I thought about such a flag to turn on/off, but I stopped the choice since too
many envs don't sound good.

Deep Memory Profiler is disabled when it's zero.  How about to set the default
to zero?

[dennis_jeffrey, 2012/04/17 22:36:14]

I thought about setting the default to 0, but then it's more difficult if we
want to: (1) turn on the Deep Profiler, and (2) want to use the same interval as
PER_STATS_INTERVAL.

Maybe it's ok to add a new env variable named "DEEP_HEAP_PROFILE", since anyway
that's a variable that would need to be set if using the Deep Profiler, right? 
We can just move the definition from within this test, to outside the test - if
the user of Chrome Endure wants to turn on the Deep Profiler.  What do you
think?

[Dai Mikurube (NOT FULLTIME), 2012/04/18 04:59:51]

Basically agreed.  Added an env "DEEP_MEMORY_PROFILE".
But actually, I didn't understand "We can just move the definition from within
this test, to outside the test"... you mean moving '_DEEP_MEMORY_PROFILE' out of
ChromeEndureBaseTest?

+      sampling for the Deep Memory Profiler.
+  DEEP_MEMORY_PROFILE_SAVE: Don't clean-up profile dump files if it's set.
 """
 
+from datetime import datetime
 import logging
 import os
 import re
+import shutil
+import subprocess
+import tempfile
 import time
 
 import perf
 import pyauto_functional  # Must be imported before pyauto.
 import pyauto
 import remote_inspector_client
 import selenium.common.exceptions
 from selenium.webdriver.support.ui import WebDriverWait
 
-
 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_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')

[dennis_jeffrey, 2012/04/17 01:20:27]

I recommend fitting as many parameters as you can on a line:

_DMPROF_DIR_PATH = os.path.join(
    os.path.dirname(__file__), os.pardir, os.pardir, os.pardir, 
    'tools', 'deep_memory_profiler')

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Done.

+
+  _DMPROF_SCRIPT_PATH = os.path.join(_DMPROF_DIR_PATH,
+                                     'dmprof')

[dennis_jeffrey, 2012/04/17 01:20:27]

this can probably fit on the previous line

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Done.

+
+  # TODO(dmikurube): Need to find an actual running chrome.
+  _CHROME_BIN_PATH = os.path.join(os.path.dirname(__file__),
+                                  os.pardir,
+                                  os.pardir,
+                                  os.pardir,
+                                  'out',
+                                  'Debug',
+                                  'chrome')

[dennis_jeffrey, 2012/04/17 01:20:27]

same comment as line 50 above

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Done.

 
   def setUp(self):
+    # These environment variables for the Deep Memory Profiler must be set
+    # before perf.BasePerfTest.setUp() to inherit them to Chrome.
+    self._deep_memory_profile_interval = 0
+    if self.IsLinux():
+      self._deep_memory_profile_interval = int(
+          os.environ.get('DEEP_MEMORY_PROFILE_INTERVAL',
+                         self._DEEP_MEMORY_PROFILE_INTERVAL))
+
+    if self._deep_memory_profile_interval > 0:
+      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): Remove it when renderer dump is supported in PyAuto

[dennis_jeffrey, 2012/04/17 01:20:27]

remove what - the following environment variable definition?

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Changed it to:
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)
+
     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 = False
+    if self.IsLinux():
+      self._deep_memory_profile_save = bool(
+          os.environ.get('DEEP_MEMORY_PROFILE_SAVE',
+                         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_interval > 0:
+      logging.info('Running with the Deep Memory Profiler every %d seconds.',
+                   self._deep_memory_profile_interval)
+      if self._deep_memory_profile_save:
+        logging.info('Dump files by the Deep Memory Profiler are not cleaned.')
 
     # 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._dom_node_count_results = []
     self._event_listener_count_results = []
     self._browser_process_private_mem_results = []
     self._tab_process_private_mem_results = []
     self._v8_mem_used_results = []
     self._test_start_time = 0
     self._num_errors = 0
     self._iteration_num = 0
+    self._deep_memory_profile_json = None

[dennis_jeffrey, 2012/04/17 01:20:27]

The variable name here suggests that it will store a JSON string, but it instead
stores a file object.  Maybe we should make that more clear in the variable name

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Added '_f'.

+    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_interval > 0:
+      # TODO(dmikurube): Remove it when renderer dump is supported in PyAuto

[dennis_jeffrey, 2012/04/17 01:20:27]

remove what? the next line? the next 4 lines?

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Changed in the same way above.

+      del os.environ['HEAP_PROFILE_TIME_INTERVAL']
+      del os.environ['DEEP_HEAP_PROFILE']
+      del os.environ['HEAP_PROFILE_MMAP']
+      del os.environ['HEAPPROFILE']
     perf.BasePerfTest.tearDown(self)  # Must be done at end of this function.
+    if not self._deep_memory_profile_save:
+      shutil.rmtree(self._deep_tempdir)

[dennis_jeffrey, 2012/04/17 01:20:27]

we can invoke pyauto_utils.RemovePath() here instead (import pyauto_utils at the
top of the file, rather than shutil).

[dennis_jeffrey, 2012/04/17 01:20:27]

be careful, I don't think we can assume that self._deep_tempdir would have
necessarily been defined once we get here.

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Added conditions.

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Done... but top of the file?

 
   def ExtraChromeFlags(self):
     """Ensures Chrome is launched with custom flags.
 
     Returns:
       A list of extra flags to pass to Chrome when it is launched.
     """
+    deep_memory_profile_interval = 0
+    if self.IsLinux():
+      deep_memory_profile_interval = int(
+          os.environ.get('DEEP_MEMORY_PROFILE_INTERVAL',
+                         self._DEEP_MEMORY_PROFILE_INTERVAL))

[dennis_jeffrey, 2012/04/17 01:20:27]

isn't this work already done in setUp() above?

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

ExtraChromeFlags looks like called before setUp().

[dennis_jeffrey, 2012/04/17 22:36:14]

Ok - then maybe it's best to write a little helper function to look up this
environment variable?  That way we don't have to duplicate the code in both
places.  Or, maybe we should read the environment variable here only, and not in
setUp?

[Dai Mikurube (NOT FULLTIME), 2012/04/18 04:59:51]

Since I'm not sure that ExtraChromeFlags is always called before setUp in
future, I introduces a new helper function 'GetDeepMemoryProfileEnv'.

+
     # 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'])
+    if deep_memory_profile_interval > 0:
+      return (perf.BasePerfTest.ExtraChromeFlags(self) +
+              ['--remote-debugging-port=9222', '--no-sandbox'])
+    else:
+      return (perf.BasePerfTest.ExtraChromeFlags(self) +
+              ['--remote-debugging-port=9222'])

[dennis_jeffrey, 2012/04/17 01:20:27]

extra_flags = ['--remote-debugging-port=9222']
if deep_memory_profile_interval > 0:
  extra_flags.append('--no-sandbox')
return perf.BasePerfTest.ExtraChromeFlags(self) + extra_flags

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Done.

 
   def _RunEndureTest(self, webapp_name, tab_title_substring, test_description,
                      do_scenario):
     """The main test harness function to run a general Chrome Endure test.
 
     After a test has performed any setup work and has navigated to the proper
     starting webpage, this function should be invoked to run the endurance test.
 
     Args:
       webapp_name: A string name for the webapp being tested.  Should not
           include spaces.  For example, 'Gmail', 'Docs', or 'Plus'.
       tab_title_substring: A unique substring contained within the title of
           the tab to use, for identifying the appropriate tab.
       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.
       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.
     """
     self._num_errors = 0
     self._test_start_time = time.time()
     last_perf_stats_time = time.time()
+    last_deep_memory_profile_time = time.time()
     self._GetPerformanceStats(
         webapp_name, test_description, tab_title_substring)
     self._iteration_num = 0
     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
 
+      # Note: this block will be removed when committing.

[dennis_jeffrey, 2012/04/17 01:20:27]

if this block will get removed before committing, remember also to delete the
variable defined at line 179 above

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Ok, added a commment.

+      # TODO(dmikurube): Need pid of the target process.
+      if (self._deep_memory_profile_interval > 0 and
+          time.time() - last_deep_memory_profile_time >=
+              self._deep_memory_profile_interval):
+        last_deep_memory_profile_time = time.time()
+        logging.info('HeapProfileDump would be called here.')
+
       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()
 
+    # Note: this block will be removed when committing.
+    if self._deep_memory_profile_interval > 0:
+      logging.info('HeapProfileDump would be called here.')
+
     self._GetPerformanceStats(
-        webapp_name, test_description, tab_title_substring)
+        webapp_name, test_description, tab_title_substring, True)

[dennis_jeffrey, 2012/04/17 01:20:27]

is_last=True

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Done.

 
   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
@@ skipping 32 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.

[dennis_jeffrey, 2012/04/17 01:20:27]

describe the new is_last argument

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Done.

     """
     logging.info('Gathering performance stats...')
     elapsed_time = time.time() - self._test_start_time
     elapsed_time = int(round(elapsed_time))
 
     memory_counts = self._remote_inspector_client.GetMemoryObjectCounts()
 
     dom_node_count = memory_counts['DOMNodeCount']
     logging.info('  Total DOM node count: %d nodes' % dom_node_count)
     self._dom_node_count_results.append((elapsed_time, dom_node_count))
@@ skipping 11 matching lines @@
     logging.info('  Tab process private memory: %d KB' %
                  proc_info['tab_private_mem'])
     self._tab_process_private_mem_results.append(
         (elapsed_time, proc_info['tab_private_mem']))
 
     v8_info = self.GetV8HeapStats()  # First window, first tab.
     v8_mem_used = v8_info['v8_memory_used'] / 1024.0  # Convert to KB.
     logging.info('  V8 memory used: %f KB' % v8_mem_used)
     self._v8_mem_used_results.append((elapsed_time, v8_mem_used))
 
+    if is_last and self._deep_memory_profile_proc:

[dennis_jeffrey, 2012/04/17 01:20:27]

should this check go inside the condition at line 325 below?  It seems that we
don't need to do this check unless we're using the Deep Memory Profiler in the
first place

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Exactly.  Moved this block into :
"if self._deep_memory_profile_interval > 0:"

And, added a comment.  If we don't check it, the last _GetPerformanceStats call
may miss last dump files when a previous dmprof process is still running.

+      self._deep_memory_profile_proc.wait()
+      self._deep_memory_profile_proc = None
+      if self._deep_memory_profile_json:
+        self._deep_memory_profile_json.close()
+        self._deep_memory_profile_json = None
+
+    # TODO(dmikurube): Add --single in dmprof.py?
+    # TODO(dmikurube): Avoid broken (or ongoing) profile dumps in dmprof.
+    if self._deep_memory_profile_interval > 0:
+      logging.info('Profiling with the Deep Memory Profiler...')
+      if (self._deep_memory_profile_proc and
+          self._deep_memory_profile_proc.poll() is None):
+        logging.info('  Last dmprof is still running.')

[dennis_jeffrey, 2012/04/17 01:20:27]

Is it ok to just skip the dump analysis on this invocation of
_GetPerformanceStats if the previous invocation of dmprof is still running? 
Would it be better to wait for the previous invocation of dmprof to finish
instead?

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Actually, a single dmprof run for 'first_dump' will profile all continuous dump
files.  In an extreme case, we can execute dmprof only at last to generate a
graph eventually.

The reason why I call dmprof in the loop is to generate a graph in semi-real
time.  The current dmprof may take long time...for 3-4 minutes or more.  It
doesn't matter in usual Endure cases (every 10 mins), but, it's a problem for
more frequent cases: it stops _GetPerformanceStats for 3-4 mins.

btw, the reason of dmprof's speed is calling 'pprof --symbols' to get symbol
information from a Chrome binary.  I'm planning to replace it for speed-up.

[dennis_jeffrey, 2012/04/17 22:36:14]

Ok.  This shouldn't have any impact on the memory usage of Chrome or its
renderer processes (i.e., the results of these perf tests), right?

[Dai Mikurube (NOT FULLTIME), 2012/04/18 04:59:51]

No impact.  Profile data have already been dumped to files by
HEAP_PROFILE_TIME_INTERVAL.  It just runs an analyzing script for the dumped
profile data.

+      else:
+        if self._deep_memory_profile_json:
+          self._deep_memory_profile_json.close()
+          self._deep_memory_profile_json = 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 = 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.l2.txt'),
+                                      os.path.join(self._deep_tempdir,
+                                                   first_dump)),
+              shell=True, stdout=self._deep_memory_profile_json)
+          # Don't wait since dmprof may take long time.
+
+          if is_last:
+            self._deep_memory_profile_proc.wait()
+            self._deep_memory_profile_json.close()
+
+        else:
+          logging.info('  No dump files.')
+
+    # 2) Parse .json (including only the latest snapshot) file here.

[dennis_jeffrey, 2012/04/17 01:20:27]

shouldn't this parsing work be inside the "if" at line 325 above?  We should
only do it if we're using the Deep Memory Profiler

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Exactly.  Moved the comment.

+
     # Output the results seen so far, to be graphed.
     self._OutputPerfGraphValue(
         'TotalDOMNodeCount', self._dom_node_count_results, 'nodes',
         graph_name='%s%s-Nodes-DOM' % (webapp_name, test_description),
         units_x='seconds')
     self._OutputPerfGraphValue(
         'EventListenerCount', self._event_listener_count_results, 'listeners',
         graph_name='%s%s-EventListeners' % (webapp_name, test_description),
         units_x='seconds')
     self._OutputPerfGraphValue(
         'BrowserPrivateMemory', self._browser_process_private_mem_results, 'KB',
         graph_name='%s%s-BrowserMem-Private' % (webapp_name, test_description),
         units_x='seconds')
     self._OutputPerfGraphValue(
         'TabPrivateMemory', self._tab_process_private_mem_results, 'KB',
         graph_name='%s%s-TabMem-Private' % (webapp_name, test_description),
         units_x='seconds')
     self._OutputPerfGraphValue(
         'V8MemoryUsed', self._v8_mem_used_results, 'KB',
         graph_name='%s%s-V8MemUsed' % (webapp_name, test_description),
         units_x='seconds')
+    # 3) Do self._OutputPerfGraphValue for multiple lines, here.

[dennis_jeffrey, 2012/04/17 01:20:27]

What multiple lines need to be outputted here?  Should this be a TODO?

[Dai Mikurube (NOT FULLTIME), 2012/04/17 06:33:11]

Maybe a TODO.  I'd like to output data such as:
{
  'webcore-dom': [7210945, 1374271, ...],
  'webcore-fontcache': [21938176, 22740992, ...],
  ...
  # 'component-name': [array of memory sizes in time order]
}

 
   def _GetElement(self, find_by, value):
     """Gets a WebDriver element object from the webpage DOM.
 
     Args:
       find_by: A callable that queries WebDriver for an element from the DOM.
       value: A string value that can be passed to the |find_by| callable.
 
     Returns:
       The identified WebDriver element object, if found in the DOM, or
@@ skipping 581 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()