grpc/tools/profiling/latency_profile/profile_analyzer.py

#!/usr/bin/env python2.7
# Copyright 2015 gRPC authors.
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
#     http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.

import argparse
import collections
import hashlib
import itertools
import json
import math
import sys
import tabulate
import time

SELF_TIME = object()
TIME_FROM_SCOPE_START = object()
TIME_TO_SCOPE_END = object()
TIME_FROM_STACK_START = object()
TIME_TO_STACK_END = object()
TIME_FROM_LAST_IMPORTANT = object()

argp = argparse.ArgumentParser(
    description='Process output of basic_prof builds')
argp.add_argument('--source', default='latency_trace.txt', type=str)
argp.add_argument('--fmt', choices=tabulate.tabulate_formats, default='simple')
argp.add_argument('--out', default='-', type=str)
args = argp.parse_args()


class LineItem(object):

    def __init__(self, line, indent):
        self.tag = line['tag']
        self.indent = indent
        self.start_time = line['t']
        self.end_time = None
        self.important = line['imp']
        self.filename = line['file']
        self.fileline = line['line']
        self.times = {}


class ScopeBuilder(object):

    def __init__(self, call_stack_builder, line):
        self.call_stack_builder = call_stack_builder
        self.indent = len(call_stack_builder.stk)
        self.top_line = LineItem(line, self.indent)
        call_stack_builder.lines.append(self.top_line)
        self.first_child_pos = len(call_stack_builder.lines)

    def mark(self, line):
        line_item = LineItem(line, self.indent + 1)
        line_item.end_time = line_item.start_time
        self.call_stack_builder.lines.append(line_item)

    def finish(self, line):
        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']))
        final_time_stamp = line['t']
        assert self.top_line.end_time is None
        self.top_line.end_time = final_time_stamp
        self.top_line.important = self.top_line.important or line['imp']
        assert SELF_TIME not in self.top_line.times
        self.top_line.times[
            SELF_TIME] = final_time_stamp - self.top_line.start_time
        for line in self.call_stack_builder.lines[self.first_child_pos:]:
            if TIME_FROM_SCOPE_START not in line.times:
                line.times[
                    TIME_FROM_SCOPE_START] = line.start_time - self.top_line.start_time
                line.times[TIME_TO_SCOPE_END] = final_time_stamp - line.end_time


class CallStackBuilder(object):

    def __init__(self):
        self.stk = []
        self.signature = hashlib.md5()
        self.lines = []

    def finish(self):
        start_time = self.lines[0].start_time
        end_time = self.lines[0].end_time
        self.signature = self.signature.hexdigest()
        last_important = start_time
        for line in self.lines:
            line.times[TIME_FROM_STACK_START] = line.start_time - start_time
            line.times[TIME_TO_STACK_END] = end_time - line.end_time
            line.times[
                TIME_FROM_LAST_IMPORTANT] = line.start_time - last_important
            if line.important:
                last_important = line.end_time
        last_important = end_time

    def add(self, line):
        line_type = line['type']
        self.signature.update(line_type)
        self.signature.update(line['tag'])
        if line_type == '{':
            self.stk.append(ScopeBuilder(self, line))
            return False
        elif line_type == '}':
            assert self.stk, (
                'expected non-empty stack for closing %s; thread=%s; t=%f' %
                (line['tag'], line['thd'], line['t']))
            self.stk.pop().finish(line)
            if not self.stk:
                self.finish()
                return True
            return False
        elif line_type == '.' or line_type == '!':
            if self.stk:
                self.stk[-1].mark(line)
            return False
        else:
            raise Exception('Unknown line type: \'%s\'' % line_type)


class CallStack(object):

    def __init__(self, initial_call_stack_builder):
        self.count = 1
        self.signature = initial_call_stack_builder.signature
        self.lines = initial_call_stack_builder.lines
        for line in self.lines:
            for key, val in line.times.items():
                line.times[key] = [val]

    def add(self, call_stack_builder):
        assert self.signature == call_stack_builder.signature
        self.count += 1
        assert len(self.lines) == len(call_stack_builder.lines)
        for lsum, line in itertools.izip(self.lines, call_stack_builder.lines):
            assert lsum.tag == line.tag
            assert lsum.times.keys() == line.times.keys()
            for k, lst in lsum.times.iteritems():
                lst.append(line.times[k])

    def finish(self):
        for line in self.lines:
            for lst in line.times.itervalues():
                lst.sort()


builder = collections.defaultdict(CallStackBuilder)
call_stacks = collections.defaultdict(CallStack)

lines = 0
start = time.time()
with open(args.source) as f:
    for line in f:
        lines += 1
        inf = json.loads(line)
        thd = inf['thd']
        cs = builder[thd]
        if cs.add(inf):
            if cs.signature in call_stacks:
                call_stacks[cs.signature].add(cs)
            else:
                call_stacks[cs.signature] = CallStack(cs)
            del builder[thd]
time_taken = time.time() - start

call_stacks = sorted(
    call_stacks.values(), key=lambda cs: cs.count, reverse=True)
total_stacks = 0
for cs in call_stacks:
    total_stacks += cs.count
    cs.finish()


def percentile(N, percent, key=lambda x: x):
    """
    Find the percentile of an already sorted list of values.

    @parameter N - is a list of values. MUST be already sorted.
    @parameter percent - a float value from [0.0,1.0].
    @parameter key - optional key function to compute value from each element of N.

    @return - the percentile of the values
    """
    if not N:
        return None
    float_idx = (len(N) - 1) * percent
    idx = int(float_idx)
    result = key(N[idx])
    if idx < len(N) - 1:
        # interpolate with the next element's value
        result += (float_idx - idx) * (key(N[idx + 1]) - key(N[idx]))
    return result


def tidy_tag(tag):
    if tag[0:10] == 'GRPC_PTAG_':
        return tag[10:]
    return tag


def time_string(values):
    num_values = len(values)
    return '%.1f/%.1f/%.1f' % (1e6 * percentile(values, 0.5),
                               1e6 * percentile(values, 0.9),
                               1e6 * percentile(values, 0.99))


def time_format(idx):

    def ent(line, idx=idx):
        if idx in line.times:
            return time_string(line.times[idx])
        return ''

    return ent


BANNER = {'simple': 'Count: %(count)d', 'html': '<h1>Count: %(count)d</h1>'}

FORMAT = [
    ('TAG', lambda line: '..' * line.indent + tidy_tag(line.tag)),
    ('LOC',
     lambda line: '%s:%d' % (line.filename[line.filename.rfind('/') + 1:], line.fileline)
    ),
    ('IMP', lambda line: '*' if line.important else ''),
    ('FROM_IMP', time_format(TIME_FROM_LAST_IMPORTANT)),
    ('FROM_STACK_START', time_format(TIME_FROM_STACK_START)),
    ('SELF', time_format(SELF_TIME)),
    ('TO_STACK_END', time_format(TIME_TO_STACK_END)),
    ('FROM_SCOPE_START', time_format(TIME_FROM_SCOPE_START)),
    ('SELF', time_format(SELF_TIME)),
    ('TO_SCOPE_END', time_format(TIME_TO_SCOPE_END)),
]

out = sys.stdout
if args.out != '-':
    out = open(args.out, 'w')

if args.fmt == 'html':
    print >> out, '<html>'
    print >> out, '<head>'
    print >> out, '<title>Profile Report</title>'
    print >> out, '</head>'

accounted_for = 0
for cs in call_stacks:
    print >> out, '\n'
    if args.fmt in BANNER:
        print >> out, BANNER[args.fmt] % {
            'count': cs.count,
        }
    header, _ = zip(*FORMAT)
    table = []
    for line in cs.lines:
        fields = []
        for _, fn in FORMAT:
            fields.append(fn(line))
        table.append(fields)
    print >> out, tabulate.tabulate(table, header, tablefmt=args.fmt)
    accounted_for += cs.count
    if accounted_for > .99 * total_stacks:
        break

if args.fmt == 'html':
    print '</html>'