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.
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.
15 # Logs can contain information from any number of Sources.
17 # For example, the sel_ldr logs and browser test logs might be Sources.
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.
24 # Each Eventful line with time info should contain:
29 # The time values can be in any unit, but will be converted to millisecs.
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.
41 # Should be formatted according to the chrome buildbot format.
43 def GetEventPatterns():
45 # NaClPerfCounterInterval (${SERIES} ${EVENT_A}:*${EVENT_B}): N microsecs
47 # RESULT ${GRAPH}: ${EVENT_B}_${SETUP_INFO}= N/1000 millisecs
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.
54 'NaClPerfCounterInterval\(.*:\*(.*)\): (\d+) microsecs',
57 # NaClPerf [${EVENT_NAME}]: N millisecs
59 # RESULT ${GRAPH}: ${EVENT_NAME}_${SETUP_INFO}= N millisecs
60 Pattern('BrowserTester',
61 'NaClPerf \[(.*)\] (\d+\.*\d*) millisecs',
65 class Pattern(object):
73 self.re = re.compile(patternRE)
74 self.eventIndex = eventIndex
75 self.timeIndex = timeIndex
76 self.scaleToMilli = scaleToMilli
78 self.accumulatedTimes = {}
80 def _eventLabel(self, match):
81 return match.group(self.eventIndex)
83 def _timeInMillis(self, match):
84 return float(match.group(self.timeIndex)) * self.scaleToMilli
87 return self.re.search(s)
89 def ProcessLine(self, line):
90 match = self._match(line)
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
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)
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 millisecs\n' %
110 (graph_label, event, trace_label_extra, time))
113 usage = 'usage: %prog graphLabel traceExtra < stdin\n'
114 if len(sys.argv) != 3:
115 sys.stderr.write(usage)
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):
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:
129 pat.PrintSummary(graph_label, trace_label_extra)
132 if __name__ == '__main__':