Enable Deep Memory Profiler in perf_endure.py.

chrome/test/functional/perf_endure.py

Index: chrome/test/functional/perf_endure.py
diff --git a/chrome/test/functional/perf_endure.py b/chrome/test/functional/perf_endure.py
old mode 100644
new mode 100755
index df80e73fdedb323f19f132d46f88c635cc189edb..780a57e32bee1302a4f7bd1ba601e8d3225883e4
--- a/chrome/test/functional/perf_endure.py
+++ b/chrome/test/functional/perf_endure.py
@@ -9,11 +9,18 @@ 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
@@ -23,7 +30,6 @@ 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.
 
@@ -33,8 +39,47 @@ class ChromeEndureBaseTest(perf.BasePerfTest):
   _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(
@@ -42,9 +87,20 @@ class ChromeEndureBaseTest(perf.BasePerfTest):
     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...')
@@ -60,12 +116,22 @@ class ChromeEndureBaseTest(perf.BasePerfTest):
     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.
@@ -73,10 +139,20 @@ class ChromeEndureBaseTest(perf.BasePerfTest):
     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):
@@ -100,6 +176,7 @@ class ChromeEndureBaseTest(perf.BasePerfTest):
     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
@@ -111,6 +188,14 @@ class ChromeEndureBaseTest(perf.BasePerfTest):
                       '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(
@@ -124,8 +209,12 @@ class ChromeEndureBaseTest(perf.BasePerfTest):
 
       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.
@@ -178,10 +267,11 @@ class ChromeEndureBaseTest(perf.BasePerfTest):
     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:
@@ -223,6 +313,60 @@ class ChromeEndureBaseTest(perf.BasePerfTest):
     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',
@@ -244,6 +388,7 @@ class ChromeEndureBaseTest(perf.BasePerfTest):
         '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.