| #!/usr/bin/env python2.7 |
| # Copyright 2015, Google Inc. |
| # All rights reserved. |
| # |
| # Redistribution and use in source and binary forms, with or without |
| # modification, are permitted provided that the following conditions are |
| # met: |
| # |
| # * Redistributions of source code must retain the above copyright |
| # notice, this list of conditions and the following disclaimer. |
| # * Redistributions in binary form must reproduce the above |
| # copyright notice, this list of conditions and the following disclaimer |
| # in the documentation and/or other materials provided with the |
| # distribution. |
| # * Neither the name of Google Inc. nor the names of its |
| # contributors may be used to endorse or promote products derived from |
| # this software without specific prior written permission. |
| # |
| # THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS |
| # "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT |
| # LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR |
| # A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT |
| # OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, |
| # SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT |
| # LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, |
| # DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY |
| # THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT |
| # (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE |
| # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. |
| |
| import argparse |
| import collections |
| import hashlib |
| import itertools |
| import json |
| import math |
| import tabulate |
| import time |
| |
| |
| SELF_TIME = object() |
| TIME_FROM_SCOPE_START = object() |
| TIME_TO_SCOPE_END = object() |
| TIME_FROM_STACK_START = object() |
| TIME_TO_STACK_END = object() |
| |
| |
| argp = argparse.ArgumentParser(description='Process output of basic_prof builds') |
| argp.add_argument('--source', default='latency_trace.txt', type=str) |
| argp.add_argument('--fmt', choices=tabulate.tabulate_formats, default='simple') |
| args = argp.parse_args() |
| |
| class LineItem(object): |
| |
| def __init__(self, line, indent): |
| self.tag = line['tag'] |
| self.indent = indent |
| self.start_time = line['t'] |
| self.end_time = None |
| self.important = line['imp'] |
| self.filename = line['file'] |
| self.fileline = line['line'] |
| self.times = {} |
| |
| |
| class ScopeBuilder(object): |
| |
| def __init__(self, call_stack_builder, line): |
| self.call_stack_builder = call_stack_builder |
| self.indent = len(call_stack_builder.stk) |
| self.top_line = LineItem(line, self.indent) |
| call_stack_builder.lines.append(self.top_line) |
| self.first_child_pos = len(call_stack_builder.lines) |
| |
| def mark(self, line): |
| line_item = LineItem(line, self.indent + 1) |
| line_item.end_time = line_item.start_time |
| self.call_stack_builder.lines.append(line_item) |
| |
| def finish(self, line): |
| assert line['tag'] == self.top_line.tag, 'expected %s, got %s; thread=%s; t0=%f t1=%f' % (self.top_line.tag, line['tag'], line['thd'], self.top_line.start_time, line['t']) |
| final_time_stamp = line['t'] |
| assert self.top_line.end_time is None |
| self.top_line.end_time = final_time_stamp |
| assert SELF_TIME not in self.top_line.times |
| self.top_line.times[SELF_TIME] = final_time_stamp - self.top_line.start_time |
| for line in self.call_stack_builder.lines[self.first_child_pos:]: |
| if TIME_FROM_SCOPE_START not in line.times: |
| line.times[TIME_FROM_SCOPE_START] = line.start_time - self.top_line.start_time |
| line.times[TIME_TO_SCOPE_END] = final_time_stamp - line.end_time |
| |
| |
| class CallStackBuilder(object): |
| |
| def __init__(self): |
| self.stk = [] |
| self.signature = hashlib.md5() |
| self.lines = [] |
| |
| def finish(self): |
| start_time = self.lines[0].start_time |
| end_time = self.lines[0].end_time |
| self.signature = self.signature.hexdigest() |
| for line in self.lines: |
| line.times[TIME_FROM_STACK_START] = line.start_time - start_time |
| line.times[TIME_TO_STACK_END] = end_time - line.end_time |
| |
| def add(self, line): |
| line_type = line['type'] |
| self.signature.update(line_type) |
| self.signature.update(line['tag']) |
| if line_type == '{': |
| self.stk.append(ScopeBuilder(self, line)) |
| return False |
| elif line_type == '}': |
| assert self.stk, 'expected non-empty stack for closing %s; thread=%s; t=%f' % (line['tag'], line['thd'], line['t']) |
| self.stk.pop().finish(line) |
| if not self.stk: |
| self.finish() |
| return True |
| return False |
| elif line_type == '.' or line_type == '!': |
| self.stk[-1].mark(line) |
| return False |
| else: |
| raise Exception('Unknown line type: \'%s\'' % line_type) |
| |
| |
| class CallStack(object): |
| |
| def __init__(self, initial_call_stack_builder): |
| self.count = 1 |
| self.signature = initial_call_stack_builder.signature |
| self.lines = initial_call_stack_builder.lines |
| for line in self.lines: |
| for key, val in line.times.items(): |
| line.times[key] = [val] |
| |
| def add(self, call_stack_builder): |
| assert self.signature == call_stack_builder.signature |
| self.count += 1 |
| assert len(self.lines) == len(call_stack_builder.lines) |
| for lsum, line in itertools.izip(self.lines, call_stack_builder.lines): |
| assert lsum.tag == line.tag |
| assert lsum.times.keys() == line.times.keys() |
| for k, lst in lsum.times.iteritems(): |
| lst.append(line.times[k]) |
| |
| def finish(self): |
| for line in self.lines: |
| for lst in line.times.itervalues(): |
| lst.sort() |
| |
| builder = collections.defaultdict(CallStackBuilder) |
| call_stacks = collections.defaultdict(CallStack) |
| |
| lines = 0 |
| start = time.time() |
| with open(args.source) as f: |
| for line in f: |
| lines += 1 |
| inf = json.loads(line) |
| thd = inf['thd'] |
| cs = builder[thd] |
| if cs.add(inf): |
| if cs.signature in call_stacks: |
| call_stacks[cs.signature].add(cs) |
| else: |
| call_stacks[cs.signature] = CallStack(cs) |
| del builder[thd] |
| time_taken = time.time() - start |
| |
| call_stacks = sorted(call_stacks.values(), key=lambda cs: cs.count, reverse=True) |
| total_stacks = 0 |
| for cs in call_stacks: |
| total_stacks += cs.count |
| cs.finish() |
| |
| def percentile(N, percent, key=lambda x:x): |
| """ |
| Find the percentile of a list of values. |
| |
| @parameter N - is a list of values. Note N MUST BE already sorted. |
| @parameter percent - a float value from 0.0 to 1.0. |
| @parameter key - optional key function to compute value from each element of N. |
| |
| @return - the percentile of the values |
| """ |
| if not N: |
| return None |
| k = (len(N)-1) * percent |
| f = math.floor(k) |
| c = math.ceil(k) |
| if f == c: |
| return key(N[int(k)]) |
| d0 = key(N[int(f)]) * (c-k) |
| d1 = key(N[int(c)]) * (k-f) |
| return d0+d1 |
| |
| def tidy_tag(tag): |
| if tag[0:10] == 'GRPC_PTAG_': |
| return tag[10:] |
| return tag |
| |
| def time_string(values): |
| num_values = len(values) |
| return '%.1f/%.1f/%.1f' % ( |
| 1e6 * percentile(values, 0.5), |
| 1e6 * percentile(values, 0.9), |
| 1e6 * percentile(values, 0.99)) |
| |
| def time_format(idx): |
| def ent(line, idx=idx): |
| if idx in line.times: |
| return time_string(line.times[idx]) |
| return '' |
| return ent |
| |
| FORMAT = [ |
| ('TAG', lambda line: '..'*line.indent + tidy_tag(line.tag)), |
| ('LOC', lambda line: '%s:%d' % (line.filename[line.filename.rfind('/')+1:], line.fileline)), |
| ('FROM_STACK_START', time_format(TIME_FROM_STACK_START)), |
| ('SELF', time_format(SELF_TIME)), |
| ('TO_STACK_END', time_format(TIME_TO_STACK_END)), |
| ('FROM_SCOPE_START', time_format(TIME_FROM_SCOPE_START)), |
| ('SELF', time_format(SELF_TIME)), |
| ('TO_SCOPE_END', time_format(TIME_TO_SCOPE_END)), |
| ] |
| |
| BANNER = { |
| 'simple': 'Count: %(count)d', |
| 'html': '<h1>Count: %(count)d</h1>' |
| } |
| |
| if args.fmt == 'html': |
| print '<html>' |
| print '<head>' |
| print '<title>Profile Report</title>' |
| print '</head>' |
| |
| accounted_for = 0 |
| for cs in call_stacks: |
| if args.fmt in BANNER: |
| print BANNER[args.fmt] % { |
| 'count': cs.count, |
| } |
| header, _ = zip(*FORMAT) |
| table = [] |
| for line in cs.lines: |
| fields = [] |
| for _, fn in FORMAT: |
| fields.append(fn(line)) |
| table.append(fields) |
| print tabulate.tabulate(table, header, tablefmt=args.fmt) |
| accounted_for += cs.count |
| if accounted_for > .99 * total_stacks: |
| break |
| |
| if args.fmt == 'html': |
| print '</html>' |
| |