tools/profiling/latency_profile/profile_analyzer.py

   1 #!/usr/bin/env python2.7
   2 # Copyright 2015 gRPC authors.
   3 #
   4 # Licensed under the Apache License, Version 2.0 (the "License");
   5 # you may not use this file except in compliance with the License.
   6 # You may obtain a copy of the License at
   7 #
   8 #     http://www.apache.org/licenses/LICENSE-2.0
   9 #
  10 # Unless required by applicable law or agreed to in writing, software
  11 # distributed under the License is distributed on an "AS IS" BASIS,
  12 # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13 # See the License for the specific language governing permissions and
  14 # limitations under the License.
  15
  16 import argparse
  17 import collections
  18 import hashlib
  19 import itertools
  20 import json
  21 import math
  22 import sys
  23 import tabulate
  24 import time
  25
  26 SELF_TIME = object()
  27 TIME_FROM_SCOPE_START = object()
  28 TIME_TO_SCOPE_END = object()
  29 TIME_FROM_STACK_START = object()
  30 TIME_TO_STACK_END = object()
  31 TIME_FROM_LAST_IMPORTANT = object()
  32
  33 argp = argparse.ArgumentParser(
  34     description='Process output of basic_prof builds')
  35 argp.add_argument('--source', default='latency_trace.txt', type=str)
  36 argp.add_argument('--fmt', choices=tabulate.tabulate_formats, default='simple')
  37 argp.add_argument('--out', default='-', type=str)
  38 args = argp.parse_args()
  39
  40
  41 class LineItem(object):
  42
  43     def __init__(self, line, indent):
  44         self.tag = line['tag']
  45         self.indent = indent
  46         self.start_time = line['t']
  47         self.end_time = None
  48         self.important = line['imp']
  49         self.filename = line['file']
  50         self.fileline = line['line']
  51         self.times = {}
  52
  53
  54 class ScopeBuilder(object):
  55
  56     def __init__(self, call_stack_builder, line):
  57         self.call_stack_builder = call_stack_builder
  58         self.indent = len(call_stack_builder.stk)
  59         self.top_line = LineItem(line, self.indent)
  60         call_stack_builder.lines.append(self.top_line)
  61         self.first_child_pos = len(call_stack_builder.lines)
  62
  63     def mark(self, line):
  64         line_item = LineItem(line, self.indent + 1)
  65         line_item.end_time = line_item.start_time
  66         self.call_stack_builder.lines.append(line_item)
  67
  68     def finish(self, line):
  69         assert line['tag'] == self.top_line.tag, (
  70             'expected %s, got %s; thread=%s; t0=%f t1=%f' %
  71             (self.top_line.tag, line['tag'], line['thd'],
  72              self.top_line.start_time, line['t']))
  73         final_time_stamp = line['t']
  74         assert self.top_line.end_time is None
  75         self.top_line.end_time = final_time_stamp
  76         self.top_line.important = self.top_line.important or line['imp']
  77         assert SELF_TIME not in self.top_line.times
  78         self.top_line.times[
  79             SELF_TIME] = final_time_stamp - self.top_line.start_time
  80         for line in self.call_stack_builder.lines[self.first_child_pos:]:
  81             if TIME_FROM_SCOPE_START not in line.times:
  82                 line.times[
  83                     TIME_FROM_SCOPE_START] = line.start_time - self.top_line.start_time
  84                 line.times[TIME_TO_SCOPE_END] = final_time_stamp - line.end_time
  85
  86
  87 class CallStackBuilder(object):
  88
  89     def __init__(self):
  90         self.stk = []
  91         self.signature = hashlib.md5()
  92         self.lines = []
  93
  94     def finish(self):
  95         start_time = self.lines[0].start_time
  96         end_time = self.lines[0].end_time
  97         self.signature = self.signature.hexdigest()
  98         last_important = start_time
  99         for line in self.lines:
 100             line.times[TIME_FROM_STACK_START] = line.start_time - start_time
 101             line.times[TIME_TO_STACK_END] = end_time - line.end_time
 102             line.times[
 103                 TIME_FROM_LAST_IMPORTANT] = line.start_time - last_important
 104             if line.important:
 105                 last_important = line.end_time
 106         last_important = end_time
 107
 108     def add(self, line):
 109         line_type = line['type']
 110         self.signature.update(line_type)
 111         self.signature.update(line['tag'])
 112         if line_type == '{':
 113             self.stk.append(ScopeBuilder(self, line))
 114             return False
 115         elif line_type == '}':
 116             assert self.stk, (
 117                 'expected non-empty stack for closing %s; thread=%s; t=%f' %
 118                 (line['tag'], line['thd'], line['t']))
 119             self.stk.pop().finish(line)
 120             if not self.stk:
 121                 self.finish()
 122                 return True
 123             return False
 124         elif line_type == '.' or line_type == '!':
 125             if self.stk:
 126                 self.stk[-1].mark(line)
 127             return False
 128         else:
 129             raise Exception('Unknown line type: \'%s\'' % line_type)
 130
 131
 132 class CallStack(object):
 133
 134     def __init__(self, initial_call_stack_builder):
 135         self.count = 1
 136         self.signature = initial_call_stack_builder.signature
 137         self.lines = initial_call_stack_builder.lines
 138         for line in self.lines:
 139             for key, val in line.times.items():
 140                 line.times[key] = [val]
 141
 142     def add(self, call_stack_builder):
 143         assert self.signature == call_stack_builder.signature
 144         self.count += 1
 145         assert len(self.lines) == len(call_stack_builder.lines)
 146         for lsum, line in itertools.izip(self.lines, call_stack_builder.lines):
 147             assert lsum.tag == line.tag
 148             assert lsum.times.keys() == line.times.keys()
 149             for k, lst in lsum.times.iteritems():
 150                 lst.append(line.times[k])
 151
 152     def finish(self):
 153         for line in self.lines:
 154             for lst in line.times.itervalues():
 155                 lst.sort()
 156
 157
 158 builder = collections.defaultdict(CallStackBuilder)
 159 call_stacks = collections.defaultdict(CallStack)
 160
 161 lines = 0
 162 start = time.time()
 163 with open(args.source) as f:
 164     for line in f:
 165         lines += 1
 166         inf = json.loads(line)
 167         thd = inf['thd']
 168         cs = builder[thd]
 169         if cs.add(inf):
 170             if cs.signature in call_stacks:
 171                 call_stacks[cs.signature].add(cs)
 172             else:
 173                 call_stacks[cs.signature] = CallStack(cs)
 174             del builder[thd]
 175 time_taken = time.time() - start
 176
 177 call_stacks = sorted(call_stacks.values(),
 178                      key=lambda cs: cs.count,
 179                      reverse=True)
 180 total_stacks = 0
 181 for cs in call_stacks:
 182     total_stacks += cs.count
 183     cs.finish()
 184
 185
 186 def percentile(N, percent, key=lambda x: x):
 187     """
 188     Find the percentile of an already sorted list of values.
 189
 190     @parameter N - is a list of values. MUST be already sorted.
 191     @parameter percent - a float value from [0.0,1.0].
 192     @parameter key - optional key function to compute value from each element of N.
 193
 194     @return - the percentile of the values
 195     """
 196     if not N:
 197         return None
 198     float_idx = (len(N) - 1) * percent
 199     idx = int(float_idx)
 200     result = key(N[idx])
 201     if idx < len(N) - 1:
 202         # interpolate with the next element's value
 203         result += (float_idx - idx) * (key(N[idx + 1]) - key(N[idx]))
 204     return result
 205
 206
 207 def tidy_tag(tag):
 208     if tag[0:10] == 'GRPC_PTAG_':
 209         return tag[10:]
 210     return tag
 211
 212
 213 def time_string(values):
 214     num_values = len(values)
 215     return '%.1f/%.1f/%.1f' % (1e6 * percentile(values, 0.5), 1e6 * percentile(
 216         values, 0.9), 1e6 * percentile(values, 0.99))
 217
 218
 219 def time_format(idx):
 220
 221     def ent(line, idx=idx):
 222         if idx in line.times:
 223             return time_string(line.times[idx])
 224         return ''
 225
 226     return ent
 227
 228
 229 BANNER = {'simple': 'Count: %(count)d', 'html': '<h1>Count: %(count)d</h1>'}
 230
 231 FORMAT = [
 232     ('TAG', lambda line: '..' * line.indent + tidy_tag(line.tag)),
 233     ('LOC', lambda line: '%s:%d' %
 234      (line.filename[line.filename.rfind('/') + 1:], line.fileline)),
 235     ('IMP', lambda line: '*' if line.important else ''),
 236     ('FROM_IMP', time_format(TIME_FROM_LAST_IMPORTANT)),
 237     ('FROM_STACK_START', time_format(TIME_FROM_STACK_START)),
 238     ('SELF', time_format(SELF_TIME)),
 239     ('TO_STACK_END', time_format(TIME_TO_STACK_END)),
 240     ('FROM_SCOPE_START', time_format(TIME_FROM_SCOPE_START)),
 241     ('SELF', time_format(SELF_TIME)),
 242     ('TO_SCOPE_END', time_format(TIME_TO_SCOPE_END)),
 243 ]
 244
 245 out = sys.stdout
 246 if args.out != '-':
 247     out = open(args.out, 'w')
 248
 249 if args.fmt == 'html':
 250     print >> out, '<html>'
 251     print >> out, '<head>'
 252     print >> out, '<title>Profile Report</title>'
 253     print >> out, '</head>'
 254
 255 accounted_for = 0
 256 for cs in call_stacks:
 257     print >> out, '\n'
 258     if args.fmt in BANNER:
 259         print >> out, BANNER[args.fmt] % {
 260             'count': cs.count,
 261         }
 262     header, _ = zip(*FORMAT)
 263     table = []
 264     for line in cs.lines:
 265         fields = []
 266         for _, fn in FORMAT:
 267             fields.append(fn(line))
 268         table.append(fields)
 269     print >> out, tabulate.tabulate(table, header, tablefmt=args.fmt)
 270     accounted_for += cs.count
 271     if accounted_for > .99 * total_stacks:
 272         break
 273
 274 if args.fmt == 'html':
 275     print '</html>'