Breakdown nonprofiled memory regions (f.k.a. 'unknown'), and add new policy files.

tools/deep_memory_profiler/dmprof

 #!/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.
 
 """The deep heap profiler script for Chrome."""
 
 from datetime import datetime
 import json
 import os
@@ skipping 10 matching lines @@
 NULL_REGEX = re.compile('')
 PPROF_PATH = os.path.join(os.path.dirname(__file__),
                           os.pardir,
                           os.pardir,
                           'third_party',
                           'tcmalloc',
                           'chromium',
                           'src',
                           'pprof')
 
 # Heap Profile Dump versions

[Alexander Potapenko, 2012/04/12 12:51:33]

Are you going to support all the versions? I guess at some moment the list can
be flattened to contain only 1-2 last versions.

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

I'm planning to support all versions for a while since I have much old data
locally and I'm comparing them.  I'll be flatten them at some future date.

 
 # DUMP_DEEP_1 DOES NOT distinct mmap regions and malloc chunks.
 # Their stacktraces DO contain mmap* or tc-* at their tops.
 # They should be processed by POLICY_DEEP_1.
 DUMP_DEEP_1 = 'DUMP_DEEP_1'
 
 # DUMP_DEEP_2 DOES distinct mmap regions and malloc chunks.
 # Their stacktraces still DO contain mmap* or tc-*.
 # They should be processed by POLICY_DEEP_1.
 DUMP_DEEP_2 = 'DUMP_DEEP_2'
 
 # DUMP_DEEP_3 DOES distinct mmap regions and malloc chunks.
 # Their stacktraces DO NOT contain mmap* or tc-*.
 # They should be processed by POLICY_DEEP_2.
 DUMP_DEEP_3 = 'DUMP_DEEP_3'
 
+# DUMP_DEEP_4 adds some features to DUMP_DEEP_3:
+# 1. Support comments starting with '#'
+# 2. Support additional global stats: e.g. nonprofiled-*.
+DUMP_DEEP_4 = 'DUMP_DEEP_4'

[Alexander Potapenko, 2012/04/12 12:51:33]

I think it's time to stop adding DUMP_DEEP_X constants. Maybe just parse
log_version string and strip DUMP_DEEP_ away instead?

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

I was planning to add other versions than 'DUMP_DEEP_', but I guess it'll need
more time.  I'll change it in another CL or the next DUMP_DEEP_ version.

+
 # Heap Profile Policy versions
 
 # POLICY_DEEP_1 DOES NOT include allocation_type columns.
 # mmap regions are distincted w/ mmap frames in the pattern column.
 POLICY_DEEP_1 = 'POLICY_DEEP_1'
 
 # POLICY_DEEP_2 DOES include allocation_type columns.
 # mmap regions are distincted w/ the allocation_type column.
 POLICY_DEEP_2 = 'POLICY_DEEP_2'
 
@@ skipping 44 matching lines @@
   def __init__(self, stacktrace):
     self.stacktrace = stacktrace
     self.component = ''
 
 
 class Log(object):
 
   """A class representing one dumped log data."""
   def __init__(self, log_path, buckets):
     self.log_path = log_path
+    self.log_lines = []

[M-A Ruel, 2012/04/12 12:40:36]

Here's an example how to rewrite it in a functional way:
lines = (l.strip() for l in open(self.log_path, 'r'))
self.log_lines = [l for l in lines if l and not l.startswith('#')]

I don't know if you care about whitespaces and \n. Also your code will throw on
empty lines.

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

Finally, replaced it with:
self.log_lines = [l for l in open(self.log_path, 'r') if l and not
l.startswith('#')]

     with open(self.log_path, mode='r') as log_f:
-      self.log_lines = log_f.readlines()
+      for log_line in log_f:
+        if log_line[0] != '#':

[Alexander Potapenko, 2012/04/12 12:51:33]

I think "not log_line.startswith('#')" is more readable, but YMMV.

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

Exactly.  I used startswith as above.

+          self.log_lines.append(log_line)
     self.log_version = ''
     sys.stderr.write('parsing a log file:%s\n' % log_path)
     self.mmap_stacktrace_lines = []
     self.malloc_stacktrace_lines = []
     self.counters = {}
     self.log_time = os.stat(self.log_path).st_mtime
     self.parse_log(buckets)
 
   @staticmethod
   def dump_stacktrace_lines(stacktrace_lines, buckets):
@@ skipping 172 matching lines @@
         line number in log_lines.
     """
     ln = self.skip_lines_while(
         ln, len(log_lines), lambda n: not log_lines[n].split()[0].isdigit())
     stacktrace_lines_start = ln
     ln = self.skip_lines_while(
         ln, len(log_lines),
         lambda n: self.check_stacktrace_line(log_lines[n], buckets))
     return (log_lines[stacktrace_lines_start:ln], ln)
 
-  def parse_stacktraces(self, buckets):
+  def parse_stacktraces(self, buckets, ln):
     """Parses lines in self.log_lines as stacktrace.
 
     Valid stacktrace lines are stored into self.mmap_stacktrace_lines and
     self.malloc_stacktrace_lines.
 
     Args:
         buckets: A dict mapping bucket ids and their corresponding Bucket
             objects.
-
-    Returns:
-        A string representing a version of the stacktrace dump.  '' for invalid
-        dump.
+        ln: An integer representing the starting line number in log_lines.

[Alexander Potapenko, 2012/04/12 12:51:33]

Please don't select short cryptic names for the function arguments. Let the
reader understand the meaning of the argument from its name.

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

Done.

     """
-    version = ''
-
-    # Skip until an identifiable line.
-    headers = ('STACKTRACES:\n', 'MMAP_STACKTRACES:\n', 'heap profile: ')
-    ln = self.skip_lines_while(
-        0, len(self.log_lines),
-        lambda n: not self.log_lines[n].startswith(headers))
-
-    # Identify a version.
-    if self.log_lines[ln].startswith('heap profile: '):
-      version = self.log_lines[ln][13:].strip()
-      if version == DUMP_DEEP_2 or version == DUMP_DEEP_3:
-        ln = self.skip_lines_while(
-            ln, len(self.log_lines),
-            lambda n: self.log_lines[n] != 'MMAP_STACKTRACES:\n')
-      else:
-        sys.stderr.write('  invalid heap profile dump version:%s\n' % version)
-        return ''
-    elif self.log_lines[ln] == 'STACKTRACES:\n':
-      version = DUMP_DEEP_1
-    elif self.log_lines[ln] == 'MMAP_STACKTRACES:\n':
-      version = DUMP_DEEP_2
-
-    if version == DUMP_DEEP_3:
-      sys.stderr.write('  heap profile dump version: %s\n' % version)
+    if self.log_version == DUMP_DEEP_3 or self.log_version == DUMP_DEEP_4:

[Alexander Potapenko, 2012/04/12 12:51:33]

self.log_version in [DUMP_DEEP_3, DUMP_DEEP_4]

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

Done.

+      sys.stderr.write('  heap profile dump version: %s\n' % self.log_version)

[Alexander Potapenko, 2012/04/12 12:51:33]

Please move this line to the top of the method, as it's printed for every log
version.
If you don't feel like checking for all the versions at the top of the function
(that should become easier if you drop all those DUMP_DEEP_ constants), at least
consider putting the common string into a constant. 

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

Done.

       (self.mmap_stacktrace_lines, ln) = self.parse_stacktraces_while_valid(
           buckets, self.log_lines, ln)
       ln = self.skip_lines_while(
           ln, len(self.log_lines),
           lambda n: self.log_lines[n] != 'MALLOC_STACKTRACES:\n')
       (self.malloc_stacktrace_lines, ln) = self.parse_stacktraces_while_valid(
           buckets, self.log_lines, ln)
-      return version
 
-    elif version == DUMP_DEEP_2:
-      sys.stderr.write('  heap profile dump version: %s\n' % version)
+    elif self.log_version == DUMP_DEEP_2:
+      sys.stderr.write('  heap profile dump version: %s\n' % self.log_version)
       (self.mmap_stacktrace_lines, ln) = self.parse_stacktraces_while_valid(
           buckets, self.log_lines, ln)
       ln = self.skip_lines_while(
           ln, len(self.log_lines),
           lambda n: self.log_lines[n] != 'MALLOC_STACKTRACES:\n')
       (self.malloc_stacktrace_lines, ln) = self.parse_stacktraces_while_valid(
           buckets, self.log_lines, ln)
       self.malloc_stacktrace_lines.extend(self.mmap_stacktrace_lines)
       self.mmap_stacktrace_lines = []
-      return version
 
-    elif version == DUMP_DEEP_1:
-      sys.stderr.write('  heap profile dump version: %s\n' % version)
+    elif self.log_version == DUMP_DEEP_1:
+      sys.stderr.write('  heap profile dump version: %s\n' % self.log_version)
       (self.malloc_stacktrace_lines, ln) = self.parse_stacktraces_while_valid(
           buckets, self.log_lines, ln)
-      return version
 
     else:
-      sys.stderr.write('  invalid heap profile dump version:%s\n' % version)
-      return ''
+      sys.stderr.write('  invalid heap profile dump version:%s\n' % (
+          self.log_version))
 
   def parse_global_stats(self):
     """Parses lines in self.log_lines as global stats."""
     ln = self.skip_lines_while(
         0, len(self.log_lines),
         lambda n: self.log_lines[n] != 'GLOBAL_STATS:\n')
 
-    for prefix in ['total', 'file', 'anonymous', 'other', 'mmap', 'tcmalloc']:
+    if self.log_version == DUMP_DEEP_4:
+      global_stat_names = [
+          'total', 'file-exec', 'file-nonexec', 'anonymous', 'stack', 'other',
+          'nonprofiled-absent', 'nonprofiled-anonymous',
+          'nonprofiled-file-exec', 'nonprofiled-file-nonexec',
+          'nonprofiled-stack', 'nonprofiled-other',
+          'profiled-mmap', 'profiled-malloc']
+    else:
+      global_stat_names = [
+          'total', 'file', 'anonymous', 'other', 'mmap', 'tcmalloc']
+
+    for prefix in global_stat_names:
       ln = self.skip_lines_while(
           ln, len(self.log_lines),
           lambda n: self.log_lines[n].split()[0] != prefix)
       words = self.log_lines[ln].split()
       self.counters[prefix + '_virtual'] = int(words[-2])
       self.counters[prefix + '_committed'] = int(words[-1])
 
+
+  def parse_version(self):
+    """Parses a version string in self.log_lines.
+
+    Returns:
+        A string representing a version of the stacktrace dump.  '' for invalid

[Alexander Potapenko, 2012/04/12 12:51:33]

Looks like you're returning two values here.

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

Modified as follows :

Returns:
A pair of (a string representing a version of the stacktrace dump, and an
integer indicating a line number next to the version string).

+        dump.
+    """
+    version = ''
+
+    # Skip until an identifiable line.
+    headers = ('STACKTRACES:\n', 'MMAP_STACKTRACES:\n', 'heap profile: ')
+    ln = self.skip_lines_while(
+        0, len(self.log_lines),
+        lambda n: not self.log_lines[n].startswith(headers))
+
+    # Identify a version.
+    if self.log_lines[ln].startswith('heap profile: '):

[Alexander Potapenko, 2012/04/12 12:51:33]

I guess too much machinery is involved in getting the version. Are there ways to
get an incorrect heap profile? Can you just always include the version?

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

The first versions didn't include version strings.  As I wrote above, I'll stop
support for old data in future.

+      version = self.log_lines[ln][13:].strip()
+      if (version == DUMP_DEEP_2 or version == DUMP_DEEP_3 or
+          version == DUMP_DEEP_4):
+        ln = self.skip_lines_while(
+            ln, len(self.log_lines),
+            lambda n: self.log_lines[n] != 'MMAP_STACKTRACES:\n')
+      else:
+        sys.stderr.write('  invalid heap profile dump version:%s\n' % version)

[Alexander Potapenko, 2012/04/12 12:51:33]

Maybe just raise an exception here? You won't need to deal with an incorrect
version string this way.

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

Sounds reasonable.  Just raised an exception.

+        return ''
+    elif self.log_lines[ln] == 'STACKTRACES:\n':
+      version = DUMP_DEEP_1
+    elif self.log_lines[ln] == 'MMAP_STACKTRACES:\n':
+      version = DUMP_DEEP_2
+

[Alexander Potapenko, 2012/04/12 12:51:33]

spare newline

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

Hmm, this newline is helpful for readability for me...  You feel spare?  I'll
remove it if it's against the style guide.

+    return (version, ln)
+
   def parse_log(self, buckets):
+    self.log_version, ln = self.parse_version()
     self.parse_global_stats()
-    self.log_version = self.parse_stacktraces(buckets)
+    self.parse_stacktraces(buckets, ln)
 
   @staticmethod
   def accumulate_size_for_policy(stacktrace_lines,
                                  policy_list, buckets, sizes, mmap):
     for l in stacktrace_lines:
       words = l.split()
       bucket = buckets.get(int(words[BUCKET_ID]))
       component_match = get_component(policy_list, bucket, mmap)
       sizes[component_match] += int(words[COMMITTED])
 
@@ skipping 23 matching lines @@
     """
 
     sys.stderr.write('apply policy:%s\n' % (self.log_path))
     sizes = dict((c, 0) for c in components)
 
     self.accumulate_size_for_policy(self.mmap_stacktrace_lines,
                                     policy_list, buckets, sizes, True)
     self.accumulate_size_for_policy(self.malloc_stacktrace_lines,
                                     policy_list, buckets, sizes, False)
 
-    sizes['mmap-no-log'] = self.counters['mmap_committed'] - sizes[
+    if self.log_version == DUMP_DEEP_4:
+      mmap_prefix = 'profiled-mmap'
+      malloc_prefix = 'profiled-malloc'
+    else:
+      mmap_prefix = 'mmap'
+      malloc_prefix = 'tcmalloc'
+
+    sizes['mmap-no-log'] = self.counters[

[M-A Ruel, 2012/04/12 12:40:36]

I think this would be much more readable:
sizes['mmap-no-log'] = (
    self.counters['%s_committed' % mmap_prefix] - sizes['mmap-total-log'])

Same below. Splitting inside list element lookup operator "[]" is a weird place
to split the line. Use parenthesis () to group the lines as one statement
instead.

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

Agreed.  I think it's more readable.  Actaually, I was said to use this style
(splitting inside []) before...

+        '%s_committed' % mmap_prefix] - sizes[
         'mmap-total-log']
-    sizes['mmap-total-record'] = self.counters['mmap_committed']
-    sizes['mmap-total-record-vm'] = self.counters['mmap_virtual']
+    sizes['mmap-total-record'] = self.counters['%s_committed' % mmap_prefix]
+    sizes['mmap-total-record-vm'] = self.counters['%s_virtual' % mmap_prefix]
 
-    sizes['tc-no-log'] = self.counters['tcmalloc_committed'] - sizes[
+    sizes['tc-no-log'] = self.counters[
+        '%s_committed' % malloc_prefix] - sizes[
         'tc-total-log']
-    sizes['tc-total-record'] = self.counters['tcmalloc_committed']
-    sizes['tc-unused'] = sizes['mmap-tcmalloc'] - self.counters[
-        'tcmalloc_committed']
+    sizes['tc-total-record'] = self.counters['%s_committed' % malloc_prefix]
+    sizes['tc-unused'] = sizes[
+        'mmap-tcmalloc'] - self.counters[
+        '%s_committed' % malloc_prefix]
     sizes['tc-total'] = sizes['mmap-tcmalloc']
 
-    for key, value in { 'total': 'total_committed',
-                        'filemapped': 'file_committed',
-                        'anonymous': 'anonymous_committed',
-                        'other': 'other_committed',
-                        'total-vm': 'total_virtual',
-                        'filemapped-vm': 'file_virtual',
-                        'anonymous-vm': 'anonymous_virtual',
-                        'other-vm': 'other_virtual' }.items():
+    for key, value in {

[Alexander Potapenko, 2012/04/12 12:51:33]

This can be generated automatically:
  map(lambda x: x + '_committed', ['total', 'filemapped'])
is ['total_committed', 'total_filemapped']

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

Just some of them doesn't have corresponding names for example, 'filemapped' =>
'file_committed', for historical reason.  I'm keeping them alive for my local
old data, but remove it in future.

+        'total': 'total_committed',
+        'filemapped': 'file_committed',
+        'file-exec': 'file-exec_committed',
+        'file-nonexec': 'file-nonexec_committed',
+        'anonymous': 'anonymous_committed',
+        'stack': 'stack_committed',
+        'other': 'other_committed',
+        'nonprofiled-absent': 'nonprofiled-absent_committed',
+        'nonprofiled-anonymous': 'nonprofiled-anonymous_committed',
+        'nonprofiled-file-exec': 'nonprofiled-file-exec_committed',
+        'nonprofiled-file-nonexec': 'nonprofiled-file-nonexec_committed',
+        'nonprofiled-stack': 'nonprofiled-stack_committed',
+        'nonprofiled-other': 'nonprofiled-other_committed',
+        'total-vm': 'total_virtual',
+        'filemapped-vm': 'file_virtual',
+        'anonymous-vm': 'anonymous_virtual',
+        'other-vm': 'other_virtual' }.items():

[M-A Ruel, 2012/04/12 12:40:36]

Use iteritems() instead of items()

Otherwise, you're copying it

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

Done.

       if key in sizes:
         sizes[key] = self.counters[value]
 
-    if 'unknown' in sizes:
-      sizes['unknown'] = self.counters['total_committed'] - self.counters[
-          'mmap_committed']
+    if 'mustbezero' in sizes:
+      sizes['mustbezero'] = self.counters[

[M-A Ruel, 2012/04/12 12:40:36]

Use this format instead:
sizes['mustbezero'] = (
    self.counters['total_committed'] -
    self.counters['%s_committed' % mmap_prefix] -
    self.counters['nonprofiled-absent_committed'] -
...)

But at that point, I'd use a loop:
removed = ('%s_committed' % mmap_prefix, 'nonprofiled-absent_committed',
'nonprofiled-anonymous_committed', ...)
sizes['mustbezero'] = self.counters['total_committed'] - sum(self.counters[i]
for i in removed)

[Dai Mikurube (NOT FULLTIME), 2012/04/13 05:41:10]

Chose a loop.  Thanks!

+          'total_committed'] - self.counters[
+          '%s_committed' % mmap_prefix] - self.counters[
+          'nonprofiled-absent_committed'] - self.counters[
+          'nonprofiled-anonymous_committed'] - self.counters[
+          'nonprofiled-file-exec_committed'] - self.counters[
+          'nonprofiled-file-nonexec_committed'] - self.counters[
+          'nonprofiled-stack_committed'] - self.counters[
+          'nonprofiled-other_committed']
     if 'total-exclude-profiler' in sizes:
       sizes['total-exclude-profiler'] = self.counters[
           'total_committed'] - sizes['mmap-profiler']
     if 'hour' in sizes:
       sizes['hour'] = (self.log_time - first_log_time) / 60.0 / 60.0
     if 'minute' in sizes:
       sizes['minute'] = (self.log_time - first_log_time) / 60.0
     if 'second' in sizes:
       sizes['second'] = self.log_time - first_log_time
 
     return sizes
 
   @staticmethod
   def accumulate_size_for_expand(stacktrace_lines, policy_list, buckets,
                                  component_name, depth, sizes, mmap):
     for line in stacktrace_lines:
       words = line.split()
       bucket = buckets.get(int(words[BUCKET_ID]))
       component_match = get_component(policy_list, bucket, mmap)
       if component_match == component_name:
         stacktrace_sequence = ''
-        for address in bucket.stacktrace[1 : min(len(bucket.stacktrace),
+        for address in bucket.stacktrace[0 : min(len(bucket.stacktrace),
                                                  1 + depth)]:
           stacktrace_sequence += address_symbol_dict[address] + ' '
         if not stacktrace_sequence in sizes:
           sizes[stacktrace_sequence] = 0
         sizes[stacktrace_sequence] += int(words[COMMITTED])
 
   def expand(self, policy_list, buckets, component_name, depth):
     """Prints all stacktraces in a given component of given depth.
 
     Args:
@@ skipping 263 matching lines @@
 
   elif action == '--pprof':
     if len(sys.argv) > 5:
       logs[0].dump_for_pprof(policy_list, buckets, maps_lines, sys.argv[5])
     else:
       logs[0].dump_for_pprof(policy_list, buckets, maps_lines, None)
 
 
 if __name__ == '__main__':
   sys.exit(main())