| #!/usr/bin/env python3 |
| # Copyright 2015 gRPC authors. |
| # |
| # Licensed under the Apache License, Version 2.0 (the "License"); |
| # you may not use this file except in compliance with the License. |
| # You may obtain a copy of the License at |
| # |
| # http://www.apache.org/licenses/LICENSE-2.0 |
| # |
| # Unless required by applicable law or agreed to in writing, software |
| # distributed under the License is distributed on an "AS IS" BASIS, |
| # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| # See the License for the specific language governing permissions and |
| # limitations under the License. |
| |
| import argparse |
| import collections |
| import hashlib |
| import json |
| import math |
| import sys |
| import time |
| |
| from six.moves import zip |
| import tabulate |
| |
| SELF_TIME = object() |
| TIME_FROM_SCOPE_START = object() |
| TIME_TO_SCOPE_END = object() |
| TIME_FROM_STACK_START = object() |
| TIME_TO_STACK_END = object() |
| TIME_FROM_LAST_IMPORTANT = 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') |
| argp.add_argument('--out', default='-', type=str) |
| 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 |
| self.top_line.important = self.top_line.important or line['imp'] |
| 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() |
| last_important = start_time |
| 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 |
| line.times[ |
| TIME_FROM_LAST_IMPORTANT] = line.start_time - last_important |
| if line.important: |
| last_important = line.end_time |
| last_important = end_time |
| |
| def add(self, line): |
| line_type = line['type'] |
| self.signature.update(line_type.encode('UTF-8')) |
| self.signature.update(line['tag'].encode('UTF-8')) |
| 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 == '!': |
| if self.stk: |
| 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 list(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 zip(self.lines, call_stack_builder.lines): |
| assert lsum.tag == line.tag |
| assert list(lsum.times.keys()) == list(line.times.keys()) |
| for k, lst in list(lsum.times.items()): |
| lst.append(line.times[k]) |
| |
| def finish(self): |
| for line in self.lines: |
| for lst in list(line.times.values()): |
| 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(list(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 an already sorted list of values. |
| |
| @parameter N - is a list of values. MUST be already sorted. |
| @parameter percent - a float value from [0.0,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 |
| float_idx = (len(N) - 1) * percent |
| idx = int(float_idx) |
| result = key(N[idx]) |
| if idx < len(N) - 1: |
| # interpolate with the next element's value |
| result += (float_idx - idx) * (key(N[idx + 1]) - key(N[idx])) |
| return result |
| |
| |
| 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 |
| |
| |
| BANNER = {'simple': 'Count: %(count)d', 'html': '<h1>Count: %(count)d</h1>'} |
| |
| FORMAT = [ |
| ('TAG', lambda line: '..' * line.indent + tidy_tag(line.tag)), |
| ('LOC', lambda line: '%s:%d' % |
| (line.filename[line.filename.rfind('/') + 1:], line.fileline)), |
| ('IMP', lambda line: '*' if line.important else ''), |
| ('FROM_IMP', time_format(TIME_FROM_LAST_IMPORTANT)), |
| ('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)), |
| ] |
| |
| out = sys.stdout |
| if args.out != '-': |
| out = open(args.out, 'w') |
| |
| if args.fmt == 'html': |
| out.write('<html>') |
| out.write('<head>') |
| out.write('<title>Profile Report</title>') |
| out.write('</head>') |
| |
| accounted_for = 0 |
| for cs in call_stacks: |
| out.write('\n') |
| if args.fmt in BANNER: |
| out.write(BANNER[args.fmt] % { |
| 'count': cs.count, |
| }) |
| header, _ = list(zip(*FORMAT)) |
| table = [] |
| for line in cs.lines: |
| fields = [] |
| for _, fn in FORMAT: |
| fields.append(fn(line)) |
| table.append(fields) |
| out.write(tabulate.tabulate(table, header, tablefmt=args.fmt)) |
| accounted_for += cs.count |
| if accounted_for > .99 * total_stacks: |
| break |
| |
| if args.fmt == 'html': |
| print('</html>') |