Nathaniel Manista | ae4fbcd | 2015-09-23 16:29:44 +0000 | [diff] [blame] | 1 | #!/usr/bin/env python2.7 |
Craig Tiller | 897e4fe | 2015-12-22 15:03:40 -0800 | [diff] [blame] | 2 | # Copyright 2015, Google Inc. |
| 3 | # All rights reserved. |
| 4 | # |
| 5 | # Redistribution and use in source and binary forms, with or without |
| 6 | # modification, are permitted provided that the following conditions are |
| 7 | # met: |
| 8 | # |
| 9 | # * Redistributions of source code must retain the above copyright |
| 10 | # notice, this list of conditions and the following disclaimer. |
| 11 | # * Redistributions in binary form must reproduce the above |
| 12 | # copyright notice, this list of conditions and the following disclaimer |
| 13 | # in the documentation and/or other materials provided with the |
| 14 | # distribution. |
| 15 | # * Neither the name of Google Inc. nor the names of its |
| 16 | # contributors may be used to endorse or promote products derived from |
| 17 | # this software without specific prior written permission. |
| 18 | # |
| 19 | # THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS |
| 20 | # "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT |
| 21 | # LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR |
| 22 | # A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT |
| 23 | # OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, |
| 24 | # SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT |
| 25 | # LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, |
| 26 | # DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY |
| 27 | # THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT |
| 28 | # (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE |
| 29 | # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. |
| 30 | |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 31 | import argparse |
Craig Tiller | bd9f924 | 2015-05-01 16:24:41 -0700 | [diff] [blame] | 32 | import collections |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 33 | import hashlib |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 34 | import itertools |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 35 | import json |
| 36 | import math |
| 37 | import tabulate |
| 38 | import time |
Craig Tiller | bd9f924 | 2015-05-01 16:24:41 -0700 | [diff] [blame] | 39 | |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 40 | |
| 41 | SELF_TIME = object() |
| 42 | TIME_FROM_SCOPE_START = object() |
| 43 | TIME_TO_SCOPE_END = object() |
| 44 | TIME_FROM_STACK_START = object() |
| 45 | TIME_TO_STACK_END = object() |
| 46 | |
| 47 | |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 48 | argp = argparse.ArgumentParser(description='Process output of basic_prof builds') |
| 49 | argp.add_argument('--source', default='latency_trace.txt', type=str) |
| 50 | argp.add_argument('--fmt', choices=tabulate.tabulate_formats, default='simple') |
| 51 | args = argp.parse_args() |
| 52 | |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 53 | class LineItem(object): |
| 54 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 55 | def __init__(self, line, indent): |
| 56 | self.tag = line['tag'] |
| 57 | self.indent = indent |
| 58 | self.start_time = line['t'] |
| 59 | self.end_time = None |
| 60 | self.important = line['imp'] |
Craig Tiller | 1f41b6b | 2015-10-09 15:07:02 -0700 | [diff] [blame] | 61 | self.filename = line['file'] |
| 62 | self.fileline = line['line'] |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 63 | self.times = {} |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 64 | |
| 65 | |
| 66 | class ScopeBuilder(object): |
| 67 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 68 | def __init__(self, call_stack_builder, line): |
| 69 | self.call_stack_builder = call_stack_builder |
| 70 | self.indent = len(call_stack_builder.stk) |
| 71 | self.top_line = LineItem(line, self.indent) |
| 72 | call_stack_builder.lines.append(self.top_line) |
| 73 | self.first_child_pos = len(call_stack_builder.lines) |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 74 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 75 | def mark(self, line): |
| 76 | line_item = LineItem(line, self.indent + 1) |
| 77 | line_item.end_time = line_item.start_time |
| 78 | self.call_stack_builder.lines.append(line_item) |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 79 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 80 | def finish(self, line): |
Craig Tiller | 61ead3e | 2015-11-03 11:03:48 -0800 | [diff] [blame] | 81 | 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']) |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 82 | final_time_stamp = line['t'] |
| 83 | assert self.top_line.end_time is None |
| 84 | self.top_line.end_time = final_time_stamp |
| 85 | assert SELF_TIME not in self.top_line.times |
| 86 | self.top_line.times[SELF_TIME] = final_time_stamp - self.top_line.start_time |
| 87 | for line in self.call_stack_builder.lines[self.first_child_pos:]: |
| 88 | if TIME_FROM_SCOPE_START not in line.times: |
| 89 | line.times[TIME_FROM_SCOPE_START] = line.start_time - self.top_line.start_time |
| 90 | line.times[TIME_TO_SCOPE_END] = final_time_stamp - line.end_time |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 91 | |
| 92 | |
| 93 | class CallStackBuilder(object): |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 94 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 95 | def __init__(self): |
| 96 | self.stk = [] |
| 97 | self.signature = hashlib.md5() |
| 98 | self.lines = [] |
| 99 | |
| 100 | def finish(self): |
| 101 | start_time = self.lines[0].start_time |
| 102 | end_time = self.lines[0].end_time |
| 103 | self.signature = self.signature.hexdigest() |
| 104 | for line in self.lines: |
| 105 | line.times[TIME_FROM_STACK_START] = line.start_time - start_time |
| 106 | line.times[TIME_TO_STACK_END] = end_time - line.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 == '}': |
Craig Tiller | 61ead3e | 2015-11-03 11:03:48 -0800 | [diff] [blame] | 116 | assert self.stk, 'expected non-empty stack for closing %s; thread=%s; t=%f' % (line['tag'], line['thd'], line['t']) |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 117 | self.stk.pop().finish(line) |
| 118 | if not self.stk: |
| 119 | self.finish() |
| 120 | return True |
| 121 | return False |
| 122 | elif line_type == '.' or line_type == '!': |
| 123 | self.stk[-1].mark(line) |
| 124 | return False |
| 125 | else: |
| 126 | raise Exception('Unknown line type: \'%s\'' % line_type) |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 127 | |
| 128 | |
| 129 | class CallStack(object): |
| 130 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 131 | def __init__(self, initial_call_stack_builder): |
| 132 | self.count = 1 |
| 133 | self.signature = initial_call_stack_builder.signature |
| 134 | self.lines = initial_call_stack_builder.lines |
| 135 | for line in self.lines: |
| 136 | for key, val in line.times.items(): |
| 137 | line.times[key] = [val] |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 138 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 139 | def add(self, call_stack_builder): |
| 140 | assert self.signature == call_stack_builder.signature |
| 141 | self.count += 1 |
| 142 | assert len(self.lines) == len(call_stack_builder.lines) |
| 143 | for lsum, line in itertools.izip(self.lines, call_stack_builder.lines): |
| 144 | assert lsum.tag == line.tag |
| 145 | assert lsum.times.keys() == line.times.keys() |
| 146 | for k, lst in lsum.times.iteritems(): |
| 147 | lst.append(line.times[k]) |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 148 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 149 | def finish(self): |
| 150 | for line in self.lines: |
| 151 | for lst in line.times.itervalues(): |
| 152 | lst.sort() |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 153 | |
| 154 | builder = collections.defaultdict(CallStackBuilder) |
| 155 | call_stacks = collections.defaultdict(CallStack) |
| 156 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 157 | lines = 0 |
| 158 | start = time.time() |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 159 | with open(args.source) as f: |
David Garcia Quintas | 9b0a94b | 2015-05-06 20:50:49 -0700 | [diff] [blame] | 160 | for line in f: |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 161 | lines += 1 |
Craig Tiller | 504ed59 | 2015-10-08 07:38:43 -0700 | [diff] [blame] | 162 | inf = json.loads(line) |
| 163 | thd = inf['thd'] |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 164 | cs = builder[thd] |
| 165 | if cs.add(inf): |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 166 | if cs.signature in call_stacks: |
| 167 | call_stacks[cs.signature].add(cs) |
| 168 | else: |
| 169 | call_stacks[cs.signature] = CallStack(cs) |
| 170 | del builder[thd] |
| 171 | time_taken = time.time() - start |
David Garcia Quintas | 5b2ea29 | 2015-05-06 09:57:49 -0700 | [diff] [blame] | 172 | |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 173 | call_stacks = sorted(call_stacks.values(), key=lambda cs: cs.count, reverse=True) |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 174 | total_stacks = 0 |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 175 | for cs in call_stacks: |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 176 | total_stacks += cs.count |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 177 | cs.finish() |
| 178 | |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 179 | def percentile(N, percent, key=lambda x:x): |
| 180 | """ |
| 181 | Find the percentile of a list of values. |
| 182 | |
| 183 | @parameter N - is a list of values. Note N MUST BE already sorted. |
| 184 | @parameter percent - a float value from 0.0 to 1.0. |
| 185 | @parameter key - optional key function to compute value from each element of N. |
| 186 | |
| 187 | @return - the percentile of the values |
| 188 | """ |
| 189 | if not N: |
| 190 | return None |
| 191 | k = (len(N)-1) * percent |
| 192 | f = math.floor(k) |
| 193 | c = math.ceil(k) |
| 194 | if f == c: |
| 195 | return key(N[int(k)]) |
| 196 | d0 = key(N[int(f)]) * (c-k) |
| 197 | d1 = key(N[int(c)]) * (k-f) |
| 198 | return d0+d1 |
| 199 | |
| 200 | def tidy_tag(tag): |
| 201 | if tag[0:10] == 'GRPC_PTAG_': |
| 202 | return tag[10:] |
| 203 | return tag |
| 204 | |
| 205 | def time_string(values): |
| 206 | num_values = len(values) |
| 207 | return '%.1f/%.1f/%.1f' % ( |
| 208 | 1e6 * percentile(values, 0.5), |
| 209 | 1e6 * percentile(values, 0.9), |
| 210 | 1e6 * percentile(values, 0.99)) |
| 211 | |
| 212 | def time_format(idx): |
| 213 | def ent(line, idx=idx): |
| 214 | if idx in line.times: |
| 215 | return time_string(line.times[idx]) |
| 216 | return '' |
| 217 | return ent |
| 218 | |
| 219 | FORMAT = [ |
| 220 | ('TAG', lambda line: '..'*line.indent + tidy_tag(line.tag)), |
Craig Tiller | 1f41b6b | 2015-10-09 15:07:02 -0700 | [diff] [blame] | 221 | ('LOC', lambda line: '%s:%d' % (line.filename[line.filename.rfind('/')+1:], line.fileline)), |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 222 | ('FROM_STACK_START', time_format(TIME_FROM_STACK_START)), |
| 223 | ('SELF', time_format(SELF_TIME)), |
| 224 | ('TO_STACK_END', time_format(TIME_TO_STACK_END)), |
| 225 | ('FROM_SCOPE_START', time_format(TIME_FROM_SCOPE_START)), |
| 226 | ('SELF', time_format(SELF_TIME)), |
| 227 | ('TO_SCOPE_END', time_format(TIME_TO_SCOPE_END)), |
| 228 | ] |
David Garcia Quintas | 9b0a94b | 2015-05-06 20:50:49 -0700 | [diff] [blame] | 229 | |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 230 | BANNER = { |
| 231 | 'simple': 'Count: %(count)d', |
| 232 | 'html': '<h1>Count: %(count)d</h1>' |
| 233 | } |
| 234 | |
| 235 | if args.fmt == 'html': |
| 236 | print '<html>' |
| 237 | print '<head>' |
| 238 | print '<title>Profile Report</title>' |
| 239 | print '</head>' |
| 240 | |
| 241 | accounted_for = 0 |
Craig Tiller | 9bb0161 | 2015-10-08 08:43:48 -0700 | [diff] [blame] | 242 | for cs in call_stacks: |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 243 | if args.fmt in BANNER: |
| 244 | print BANNER[args.fmt] % { |
| 245 | 'count': cs.count, |
| 246 | } |
Craig Tiller | 86253ca | 2015-10-08 13:31:02 -0700 | [diff] [blame] | 247 | header, _ = zip(*FORMAT) |
| 248 | table = [] |
| 249 | for line in cs.lines: |
| 250 | fields = [] |
| 251 | for _, fn in FORMAT: |
| 252 | fields.append(fn(line)) |
| 253 | table.append(fields) |
Craig Tiller | dd25694 | 2015-10-08 14:42:47 -0700 | [diff] [blame] | 254 | print tabulate.tabulate(table, header, tablefmt=args.fmt) |
| 255 | accounted_for += cs.count |
| 256 | if accounted_for > .99 * total_stacks: |
| 257 | break |
| 258 | |
| 259 | if args.fmt == 'html': |
| 260 | print '</html>' |
| 261 | |