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