src/native_client/tools/process_perf_output.py

   1 #!/usr/bin/python
   2 # Copyright (c) 2011 The Native Client Authors. All rights reserved.
   3 # Use of this source code is governed by a BSD-style license that can be
   4 # found in the LICENSE file.
   5
   6 import re
   7 import sys
   8
   9 # Process log output from various components (e.g., sel_ldr, browser tester),
  10 # line-by-line and prints out a summary of TIME performance measurements.
  11 #
  12 # ================
  13 # LOG INPUTS:
  14 # ================
  15 # Logs can contain information from any number of Sources.
  16 #
  17 # For example, the sel_ldr logs and browser test logs might be Sources.
  18 #
  19 # This processor expects to match at least one line of info from each
  20 # Source. If a source does not provide any events, then this is an error
  21 # (the motivation being that we will pick up on log format changes this way).
  22 # TODO(jvoung): Allow an escape hatch for some Sources.
  23 #
  24 # Each Eventful line with time info should contain:
  25 #
  26 # (a) an event name
  27 # (b) a time value
  28 #
  29 # The time values can be in any unit, but will be converted to millisecs.
  30 #
  31 # NOTE: If multiple events with the same event name are present, then
  32 # the time values will be summed. This is useful, for example, to get the
  33 # total validation time of all dynamic libraries that are loaded.
  34 # However, this means that if a nexe is loaded twice, then the two time
  35 # values will get merged into one.
  36 # TODO(jvoung): provide a mechanism to split multiple merged event streams.
  37 #
  38 # ================
  39 # SUMMARY OUTPUT:
  40 # ================
  41 # Should be formatted according to the chrome buildbot format.
  42
  43 def GetEventPatterns():
  44   return [
  45       # NaClPerfCounterInterval (${SERIES} ${EVENT_A}:*${EVENT_B}): N microsecs
  46       # -->
  47       # RESULT ${GRAPH}: ${EVENT_B}_${SETUP_INFO}= N/1000 ms
  48       # Thus, this assumes that the EVENT_B provides the useful name
  49       # E.g., EVENT_A might be "Pre-Validation"
  50       # while EVENT_B is "Validation" (so this times validation)
  51       # Note, there is an asterisk in EVENT_B to indicate that it is important
  52       # enough to be included here.
  53       Pattern('SelLdr',
  54               'NaClPerfCounterInterval\(.*:\*(.*)\): (\d+) microsecs',
  55               1, 2, 0.001),
  56
  57       # NaClPerf [${EVENT_NAME}]: N millisecs
  58       # -->
  59       # RESULT ${GRAPH}: ${EVENT_NAME}_${SETUP_INFO}= N ms
  60       Pattern('BrowserTester',
  61               'NaClPerf \[(.*)\] (\d+\.*\d*) millisecs',
  62               1, 2, 1.0),
  63       ]
  64
  65 class Pattern(object):
  66   def __init__(self,
  67                name,
  68                patternRE,
  69                eventIndex,
  70                timeIndex,
  71                scaleToMilli):
  72     self.name = name
  73     self.re = re.compile(patternRE)
  74     self.eventIndex = eventIndex
  75     self.timeIndex = timeIndex
  76     self.scaleToMilli = scaleToMilli
  77     self.didMatch = False
  78     self.accumulatedTimes = {}
  79
  80   def _eventLabel(self, match):
  81     return match.group(self.eventIndex)
  82
  83   def _timeInMillis(self, match):
  84     return float(match.group(self.timeIndex)) * self.scaleToMilli
  85
  86   def _match(self, s):
  87     return self.re.search(s)
  88
  89   def ProcessLine(self, line):
  90     match = self._match(line)
  91     if not match:
  92       return False
  93     self.didMatch = True
  94     event = self._eventLabel(match)
  95     time = self._timeInMillis(match)
  96     # Sum up the times for a particular event.
  97     self.accumulatedTimes[event] = self.accumulatedTimes.get(event, 0) + time
  98     return True
  99
 100   def SanityCheck(self):
 101     # Make sure all patterns matched at least once.
 102     if not self.didMatch:
 103       sys.stderr.write(('Pattern for %s did not match anything.\n'
 104                         'Perhaps the format has changed.\n') % self.name)
 105       assert False
 106
 107   def PrintSummary(self, graph_label, trace_label_extra):
 108     for event, time in self.accumulatedTimes.iteritems():
 109       sys.stdout.write('RESULT %s: %s_%s= %f ms\n' %
 110                        (graph_label, event, trace_label_extra, time))
 111
 112 def Main():
 113   usage = 'usage: %prog graphLabel traceExtra < stdin\n'
 114   if len(sys.argv) != 3:
 115     sys.stderr.write(usage)
 116     return 1
 117   graph_label = sys.argv[1]
 118   trace_label_extra = sys.argv[2]
 119   event_patterns = GetEventPatterns()
 120   for line in sys.stdin.readlines():
 121     for pat in event_patterns:
 122       if pat.ProcessLine(line):
 123         continue
 124     # Also echo the original data for debugging.
 125     sys.stdout.write(line)
 126   # Print the summary in the end.
 127   for pat in event_patterns:
 128     pat.SanityCheck()
 129     pat.PrintSummary(graph_label, trace_label_extra)
 130   return 0
 131
 132 if __name__ == '__main__':
 133   sys.exit(Main())