blob: 3a7dc4846ff23c7d5e4117a100f5bfa3968aace9 [file] [log] [blame]
# Copyright (c) 2011 The Native Client Authors. All rights reserved.
# Use of this source code is governed by a BSD-style license that can be
# found in the LICENSE file.
import re
import sys
# Process log output from various components (e.g., sel_ldr, browser tester),
# line-by-line and prints out a summary of TIME performance measurements.
# ================
# ================
# Logs can contain information from any number of Sources.
# For example, the sel_ldr logs and browser test logs might be Sources.
# This processor expects to match at least one line of info from each
# Source. If a source does not provide any events, then this is an error
# (the motivation being that we will pick up on log format changes this way).
# TODO(jvoung): Allow an escape hatch for some Sources.
# Each Eventful line with time info should contain:
# (a) an event name
# (b) a time value
# The time values can be in any unit, but will be converted to millisecs.
# NOTE: If multiple events with the same event name are present, then
# the time values will be summed. This is useful, for example, to get the
# total validation time of all dynamic libraries that are loaded.
# However, this means that if a nexe is loaded twice, then the two time
# values will get merged into one.
# TODO(jvoung): provide a mechanism to split multiple merged event streams.
# ================
# ================
# Should be formatted according to the chrome buildbot format.
def GetEventPatterns():
return [
# NaClPerfCounterInterval (${SERIES} ${EVENT_A}:*${EVENT_B}): N microsecs
# -->
# RESULT ${GRAPH}: ${EVENT_B}_${SETUP_INFO}= N/1000 ms
# Thus, this assumes that the EVENT_B provides the useful name
# E.g., EVENT_A might be "Pre-Validation"
# while EVENT_B is "Validation" (so this times validation)
# Note, there is an asterisk in EVENT_B to indicate that it is important
# enough to be included here.
'NaClPerfCounterInterval\(.*:\*(.*)\): (\d+) microsecs',
1, 2, 0.001),
# NaClPerf [${EVENT_NAME}]: N millisecs
# -->
'NaClPerf \[(.*)\] (\d+\.*\d*) millisecs',
1, 2, 1.0),
class Pattern(object):
def __init__(self,
scaleToMilli): = name = re.compile(patternRE)
self.eventIndex = eventIndex
self.timeIndex = timeIndex
self.scaleToMilli = scaleToMilli
self.didMatch = False
self.accumulatedTimes = {}
def _eventLabel(self, match):
def _timeInMillis(self, match):
return float( * self.scaleToMilli
def _match(self, s):
def ProcessLine(self, line):
match = self._match(line)
if not match:
return False
self.didMatch = True
event = self._eventLabel(match)
time = self._timeInMillis(match)
# Sum up the times for a particular event.
self.accumulatedTimes[event] = self.accumulatedTimes.get(event, 0) + time
return True
def SanityCheck(self):
# Make sure all patterns matched at least once.
if not self.didMatch:
sys.stderr.write(('Pattern for %s did not match anything.\n'
'Perhaps the format has changed.\n') %
assert False
def PrintSummary(self, graph_label, trace_label_extra):
for event, time in self.accumulatedTimes.iteritems():
sys.stdout.write('RESULT %s: %s_%s= %f ms\n' %
(graph_label, event, trace_label_extra, time))
def Main():
usage = 'usage: %prog graphLabel traceExtra < stdin\n'
if len(sys.argv) != 3:
return 1
graph_label = sys.argv[1]
trace_label_extra = sys.argv[2]
event_patterns = GetEventPatterns()
for line in sys.stdin.readlines():
for pat in event_patterns:
if pat.ProcessLine(line):
# Also echo the original data for debugging.
# Print the summary in the end.
for pat in event_patterns:
pat.PrintSummary(graph_label, trace_label_extra)
return 0
if __name__ == '__main__':