• 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 itertools
20import json
21import math
22import sys
23import tabulate
24import time
25
26SELF_TIME = object()
27TIME_FROM_SCOPE_START = object()
28TIME_TO_SCOPE_END = object()
29TIME_FROM_STACK_START = object()
30TIME_TO_STACK_END = object()
31TIME_FROM_LAST_IMPORTANT = object()
32
33argp = argparse.ArgumentParser(
34    description='Process output of basic_prof builds')
35argp.add_argument('--source', default='latency_trace.txt', type=str)
36argp.add_argument('--fmt', choices=tabulate.tabulate_formats, default='simple')
37argp.add_argument('--out', default='-', type=str)
38args = argp.parse_args()
39
40
41class 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
54class 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
87class 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
132class 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
158builder = collections.defaultdict(CallStackBuilder)
159call_stacks = collections.defaultdict(CallStack)
160
161lines = 0
162start = time.time()
163with 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]
175time_taken = time.time() - start
176
177call_stacks = sorted(
178    call_stacks.values(), key=lambda cs: cs.count, reverse=True)
179total_stacks = 0
180for cs in call_stacks:
181    total_stacks += cs.count
182    cs.finish()
183
184
185def percentile(N, percent, key=lambda x: x):
186    """
187    Find the percentile of an already sorted list of values.
188
189    @parameter N - is a list of values. MUST be already sorted.
190    @parameter percent - a float value from [0.0,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
197    float_idx = (len(N) - 1) * percent
198    idx = int(float_idx)
199    result = key(N[idx])
200    if idx < len(N) - 1:
201        # interpolate with the next element's value
202        result += (float_idx - idx) * (key(N[idx + 1]) - key(N[idx]))
203    return result
204
205
206def tidy_tag(tag):
207    if tag[0:10] == 'GRPC_PTAG_':
208        return tag[10:]
209    return tag
210
211
212def time_string(values):
213    num_values = len(values)
214    return '%.1f/%.1f/%.1f' % (1e6 * percentile(values, 0.5),
215                               1e6 * percentile(values, 0.9),
216                               1e6 * percentile(values, 0.99))
217
218
219def 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
229BANNER = {'simple': 'Count: %(count)d', 'html': '<h1>Count: %(count)d</h1>'}
230
231FORMAT = [
232    ('TAG', lambda line: '..' * line.indent + tidy_tag(line.tag)),
233    ('LOC',
234     lambda line: '%s:%d' % (line.filename[line.filename.rfind('/') + 1:], line.fileline)
235    ),
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    print >> out, '<html>'
252    print >> out, '<head>'
253    print >> out, '<title>Profile Report</title>'
254    print >> out, '</head>'
255
256accounted_for = 0
257for cs in call_stacks:
258    print >> out, '\n'
259    if args.fmt in BANNER:
260        print >> out, 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    print >> out, 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