Nathaniel Manista | ae4fbcd | 2015-09-23 16:29:44 +0000 | [diff] [blame] | 1 | #!/usr/bin/env python2.7 |
Jan Tattermusch | 7897ae9 | 2017-06-07 22:57:36 +0200 | [diff] [blame] | 2 | # Copyright 2015 gRPC authors. |
Craig Tiller | 897e4fe | 2015-12-22 15:03:40 -0800 | [diff] [blame] | 3 | # |
Jan Tattermusch | 7897ae9 | 2017-06-07 22:57:36 +0200 | [diff] [blame] | 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 |
Craig Tiller | 897e4fe | 2015-12-22 15:03:40 -0800 | [diff] [blame] | 7 | # |
Jan Tattermusch | 7897ae9 | 2017-06-07 22:57:36 +0200 | [diff] [blame] | 8 | # http://www.apache.org/licenses/LICENSE-2.0 |
Craig Tiller | 897e4fe | 2015-12-22 15:03:40 -0800 | [diff] [blame] | 9 | # |
Jan Tattermusch | 7897ae9 | 2017-06-07 22:57:36 +0200 | [diff] [blame] | 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. |
Craig Tiller | 897e4fe | 2015-12-22 15:03:40 -0800 | [diff] [blame] | 15 | |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 16 | import argparse |
Craig Tiller | bd9f924 | 2015-05-01 16:24:41 -0700 | [diff] [blame] | 17 | import collections |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 18 | import hashlib |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 19 | import itertools |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 20 | import json |
| 21 | import math |
Craig Tiller | 7dc4ea6 | 2017-02-02 16:08:05 -0800 | [diff] [blame] | 22 | import sys |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 23 | import tabulate |
| 24 | import time |
Craig Tiller | bd9f924 | 2015-05-01 16:24:41 -0700 | [diff] [blame] | 25 | |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 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() |
Craig Tiller | 268a47a | 2016-07-19 12:57:18 -0700 | [diff] [blame] | 31 | TIME_FROM_LAST_IMPORTANT = object() |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 32 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 33 | argp = argparse.ArgumentParser( |
| 34 | description='Process output of basic_prof builds') |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 35 | argp.add_argument('--source', default='latency_trace.txt', type=str) |
| 36 | argp.add_argument('--fmt', choices=tabulate.tabulate_formats, default='simple') |
Craig Tiller | 7dc4ea6 | 2017-02-02 16:08:05 -0800 | [diff] [blame] | 37 | argp.add_argument('--out', default='-', type=str) |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 38 | args = argp.parse_args() |
| 39 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 40 | |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 41 | class LineItem(object): |
| 42 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 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 = {} |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 52 | |
| 53 | |
| 54 | class ScopeBuilder(object): |
| 55 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 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) |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 62 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 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) |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 67 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 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 |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 85 | |
| 86 | |
| 87 | class CallStackBuilder(object): |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 88 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 89 | def __init__(self): |
| 90 | self.stk = [] |
| 91 | self.signature = hashlib.md5() |
| 92 | self.lines = [] |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 93 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 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 |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 107 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 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 == '!': |
yang-g | 20ea5b8 | 2018-01-31 10:43:48 -0800 | [diff] [blame] | 125 | if self.stk: |
| 126 | self.stk[-1].mark(line) |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 127 | return False |
| 128 | else: |
| 129 | raise Exception('Unknown line type: \'%s\'' % line_type) |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 130 | |
| 131 | |
| 132 | class CallStack(object): |
| 133 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 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] |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 141 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 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]) |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 151 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 152 | def finish(self): |
| 153 | for line in self.lines: |
| 154 | for lst in line.times.itervalues(): |
| 155 | lst.sort() |
| 156 | |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 157 | |
| 158 | builder = collections.defaultdict(CallStackBuilder) |
| 159 | call_stacks = collections.defaultdict(CallStack) |
| 160 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 161 | lines = 0 |
| 162 | start = time.time() |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 163 | with open(args.source) as f: |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 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] |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 175 | time_taken = time.time() - start |
David Garcia Quintas | 5b2ea29 | 2015-05-06 09:57:49 -0700 | [diff] [blame] | 176 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 177 | call_stacks = sorted( |
| 178 | call_stacks.values(), key=lambda cs: cs.count, reverse=True) |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 179 | total_stacks = 0 |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 180 | for cs in call_stacks: |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 181 | total_stacks += cs.count |
| 182 | cs.finish() |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 183 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 184 | |
| 185 | def percentile(N, percent, key=lambda x: x): |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 186 | """ |
| 187 | Find the percentile of a list of values. |
| 188 | |
| 189 | @parameter N - is a list of values. Note N MUST BE already sorted. |
| 190 | @parameter percent - a float value from 0.0 to 1.0. |
| 191 | @parameter key - optional key function to compute value from each element of N. |
| 192 | |
| 193 | @return - the percentile of the values |
| 194 | """ |
| 195 | if not N: |
| 196 | return None |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 197 | k = (len(N) - 1) * percent |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 198 | f = math.floor(k) |
| 199 | c = math.ceil(k) |
| 200 | if f == c: |
| 201 | return key(N[int(k)]) |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 202 | d0 = key(N[int(f)]) * (c - k) |
| 203 | d1 = key(N[int(c)]) * (k - f) |
| 204 | return d0 + d1 |
| 205 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 206 | |
| 207 | def tidy_tag(tag): |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 208 | if tag[0:10] == 'GRPC_PTAG_': |
| 209 | return tag[10:] |
| 210 | return tag |
| 211 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 212 | |
| 213 | def time_string(values): |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 214 | num_values = len(values) |
| 215 | return '%.1f/%.1f/%.1f' % (1e6 * percentile(values, 0.5), |
| 216 | 1e6 * percentile(values, 0.9), |
| 217 | 1e6 * percentile(values, 0.99)) |
| 218 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 219 | |
| 220 | def time_format(idx): |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 221 | |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 222 | def ent(line, idx=idx): |
| 223 | if idx in line.times: |
| 224 | return time_string(line.times[idx]) |
| 225 | return '' |
| 226 | |
| 227 | return ent |
| 228 | |
| 229 | |
| 230 | BANNER = {'simple': 'Count: %(count)d', 'html': '<h1>Count: %(count)d</h1>'} |
Craig Tiller | 268a47a | 2016-07-19 12:57:18 -0700 | [diff] [blame] | 231 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 232 | FORMAT = [ |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 233 | ('TAG', lambda line: '..' * line.indent + tidy_tag(line.tag)), |
| 234 | ('LOC', |
| 235 | lambda line: '%s:%d' % (line.filename[line.filename.rfind('/') + 1:], line.fileline) |
| 236 | ), |
| 237 | ('IMP', lambda line: '*' if line.important else ''), |
| 238 | ('FROM_IMP', time_format(TIME_FROM_LAST_IMPORTANT)), |
| 239 | ('FROM_STACK_START', time_format(TIME_FROM_STACK_START)), |
| 240 | ('SELF', time_format(SELF_TIME)), |
| 241 | ('TO_STACK_END', time_format(TIME_TO_STACK_END)), |
| 242 | ('FROM_SCOPE_START', time_format(TIME_FROM_SCOPE_START)), |
| 243 | ('SELF', time_format(SELF_TIME)), |
| 244 | ('TO_SCOPE_END', time_format(TIME_TO_SCOPE_END)), |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 245 | ] |
David Garcia Quintas | 9b0a94b | 2015-05-06 20:50:49 -0700 | [diff] [blame] | 246 | |
Craig Tiller | 7dc4ea6 | 2017-02-02 16:08:05 -0800 | [diff] [blame] | 247 | out = sys.stdout |
| 248 | if args.out != '-': |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 249 | out = open(args.out, 'w') |
Craig Tiller | 7dc4ea6 | 2017-02-02 16:08:05 -0800 | [diff] [blame] | 250 | |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 251 | if args.fmt == 'html': |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 252 | print >> out, '<html>' |
| 253 | print >> out, '<head>' |
| 254 | print >> out, '<title>Profile Report</title>' |
| 255 | print >> out, '</head>' |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 256 | |
| 257 | accounted_for = 0 |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 258 | for cs in call_stacks: |
yang-g | 20ea5b8 | 2018-01-31 10:43:48 -0800 | [diff] [blame] | 259 | print >> out, '\n' |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 260 | if args.fmt in BANNER: |
| 261 | print >> out, BANNER[args.fmt] % { |
| 262 | 'count': cs.count, |
| 263 | } |
| 264 | header, _ = zip(*FORMAT) |
| 265 | table = [] |
| 266 | for line in cs.lines: |
| 267 | fields = [] |
| 268 | for _, fn in FORMAT: |
| 269 | fields.append(fn(line)) |
| 270 | table.append(fields) |
| 271 | print >> out, tabulate.tabulate(table, header, tablefmt=args.fmt) |
| 272 | accounted_for += cs.count |
| 273 | if accounted_for > .99 * total_stacks: |
| 274 | break |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 275 | |
| 276 | if args.fmt == 'html': |
ncteisen | 173c477 | 2017-12-11 16:52:44 -0800 | [diff] [blame] | 277 | print '</html>' |