mirror of https://github.com/grpc/grpc.git
David G. Quintas
9 years ago
commit
93cec49197
49 changed files with 715 additions and 497 deletions
@ -0,0 +1,89 @@ |
||||
/*
|
||||
* |
||||
* Copyright 2015, Google Inc. |
||||
* All rights reserved. |
||||
* |
||||
* Redistribution and use in source and binary forms, with or without |
||||
* modification, are permitted provided that the following conditions are |
||||
* met: |
||||
* |
||||
* * Redistributions of source code must retain the above copyright |
||||
* notice, this list of conditions and the following disclaimer. |
||||
* * Redistributions in binary form must reproduce the above |
||||
* copyright notice, this list of conditions and the following disclaimer |
||||
* in the documentation and/or other materials provided with the |
||||
* distribution. |
||||
* * Neither the name of Google Inc. nor the names of its |
||||
* contributors may be used to endorse or promote products derived from |
||||
* this software without specific prior written permission. |
||||
* |
||||
* THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS |
||||
* "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT |
||||
* LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR |
||||
* A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT |
||||
* OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, |
||||
* SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT |
||||
* LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, |
||||
* DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY |
||||
* THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT |
||||
* (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE |
||||
* OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. |
||||
* |
||||
*/ |
||||
|
||||
#include <grpc/support/log.h> |
||||
#include <grpc/support/time.h> |
||||
#include <stdio.h> |
||||
|
||||
#ifdef GRPC_TIMERS_RDTSC |
||||
#if defined(__i386__) |
||||
static void gpr_get_cycle_counter(long long int *clk) { |
||||
long long int ret; |
||||
__asm__ volatile("rdtsc" : "=A"(ret)); |
||||
*clk = ret; |
||||
} |
||||
|
||||
// ----------------------------------------------------------------
|
||||
#elif defined(__x86_64__) || defined(__amd64__) |
||||
static void gpr_get_cycle_counter(long long int *clk) { |
||||
unsigned long long low, high; |
||||
__asm__ volatile("rdtsc" : "=a"(low), "=d"(high)); |
||||
*clk = (long long)(high << 32) | (long long)low; |
||||
} |
||||
#endif |
||||
|
||||
static double cycles_per_second = 0; |
||||
static long long int start_cycle; |
||||
void gpr_precise_clock_init(void) { |
||||
time_t start; |
||||
long long end_cycle; |
||||
gpr_log(GPR_DEBUG, "Calibrating timers"); |
||||
start = time(NULL); |
||||
while (time(NULL) == start) |
||||
; |
||||
gpr_get_cycle_counter(&start_cycle); |
||||
while (time(NULL) <= start + 10) |
||||
; |
||||
gpr_get_cycle_counter(&end_cycle); |
||||
cycles_per_second = (double)(end_cycle - start_cycle) / 10.0; |
||||
gpr_log(GPR_DEBUG, "... cycles_per_second = %f\n", cycles_per_second); |
||||
} |
||||
|
||||
void gpr_precise_clock_now(gpr_timespec *clk) { |
||||
long long int counter; |
||||
double secs; |
||||
gpr_get_cycle_counter(&counter); |
||||
secs = (double)(counter - start_cycle) / cycles_per_second; |
||||
clk->clock_type = GPR_CLOCK_PRECISE; |
||||
clk->tv_sec = (time_t)secs; |
||||
clk->tv_nsec = (int)(1e9 * (secs - (double)clk->tv_sec)); |
||||
} |
||||
|
||||
#else /* GRPC_TIMERS_RDTSC */ |
||||
void gpr_precise_clock_init(void) {} |
||||
|
||||
void gpr_precise_clock_now(gpr_timespec *clk) { |
||||
*clk = gpr_now(GPR_CLOCK_REALTIME); |
||||
clk->clock_type = GPR_CLOCK_PRECISE; |
||||
} |
||||
#endif /* GRPC_TIMERS_RDTSC */ |
||||
@ -1,188 +0,0 @@ |
||||
#!/usr/bin/env python2.7 |
||||
# Copyright 2015, Google Inc. |
||||
# All rights reserved. |
||||
# |
||||
# Redistribution and use in source and binary forms, with or without |
||||
# modification, are permitted provided that the following conditions are |
||||
# met: |
||||
# |
||||
# * Redistributions of source code must retain the above copyright |
||||
# notice, this list of conditions and the following disclaimer. |
||||
# * Redistributions in binary form must reproduce the above |
||||
# copyright notice, this list of conditions and the following disclaimer |
||||
# in the documentation and/or other materials provided with the |
||||
# distribution. |
||||
# * Neither the name of Google Inc. nor the names of its |
||||
# contributors may be used to endorse or promote products derived from |
||||
# this software without specific prior written permission. |
||||
# |
||||
# THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS |
||||
# "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT |
||||
# LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR |
||||
# A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT |
||||
# OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, |
||||
# SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT |
||||
# LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, |
||||
# DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY |
||||
# THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT |
||||
# (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE |
||||
# OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. |
||||
|
||||
""" |
||||
Read GRPC basic profiles, analyze the data. |
||||
|
||||
Usage: |
||||
bins/basicprof/qps_smoke_test > log |
||||
cat log | tools/profile_analyzer/profile_analyzer.py |
||||
""" |
||||
|
||||
|
||||
import collections |
||||
import itertools |
||||
import math |
||||
import re |
||||
|
||||
# Create a regex to parse output of the C core basic profiler, |
||||
# as defined in src/core/profiling/basic_timers.c. |
||||
_RE_LINE = re.compile(r'GRPC_LAT_PROF ' + |
||||
r'([0-9]+\.[0-9]+) 0x([0-9a-f]+) ([{}.!]) ([0-9]+) ' + |
||||
r'([^ ]+) ([^ ]+) ([0-9]+)') |
||||
|
||||
Entry = collections.namedtuple( |
||||
'Entry', |
||||
['time', 'thread', 'type', 'tag', 'id', 'file', 'line']) |
||||
|
||||
|
||||
class ImportantMark(object): |
||||
def __init__(self, entry, stack): |
||||
self._entry = entry |
||||
self._pre_stack = stack |
||||
self._post_stack = list() |
||||
self._n = len(stack) # we'll also compute times to that many closing }s |
||||
|
||||
@property |
||||
def entry(self): |
||||
return self._entry |
||||
|
||||
@property |
||||
def max_depth(self): |
||||
return self._n |
||||
|
||||
def append_post_entry(self, post_entry): |
||||
if self._n > 0 and post_entry.thread == self._entry.thread: |
||||
self._post_stack.append(post_entry) |
||||
self._n -= 1 |
||||
|
||||
def get_deltas(self): |
||||
pre_and_post_stacks = itertools.chain(self._pre_stack, self._post_stack) |
||||
return collections.OrderedDict((stack_entry, |
||||
abs(self._entry.time - stack_entry.time)) |
||||
for stack_entry in pre_and_post_stacks) |
||||
|
||||
|
||||
def print_block_statistics(block_times): |
||||
print '{:<12s} {:>12s} {:>12s} {:>12s} {:>12s}'.format( |
||||
'Block tag', '50th p.', '90th p.', '95th p.', '99th p.') |
||||
for tag, tag_times in sorted(block_times.iteritems()): |
||||
times = sorted(tag_times) |
||||
print '{:<12d}: {:>12.3f} {:>12.3f} {:>12.3f} {:>12.3f}'.format( |
||||
tag, percentile(times, 50), percentile(times, 90), |
||||
percentile(times, 95), percentile(times, 99)) |
||||
print |
||||
|
||||
def print_grouped_imark_statistics(group_key, imarks_group): |
||||
values = collections.OrderedDict() |
||||
for imark in imarks_group: |
||||
deltas = imark.get_deltas() |
||||
for relative_entry, time_delta_us in deltas.iteritems(): |
||||
key = '{tag} {type} ({file}:{line})'.format(**relative_entry._asdict()) |
||||
l = values.setdefault(key, list()) |
||||
l.append(time_delta_us) |
||||
|
||||
print group_key |
||||
print '{:<50s} {:>12s} {:>12s} {:>12s} {:>12s}'.format( |
||||
'Relative mark', '50th p.', '90th p.', '95th p.', '99th p.') |
||||
for key, time_values in values.iteritems(): |
||||
time_values = sorted(time_values) |
||||
print '{:<50s}: {:>12.3f} {:>12.3f} {:>12.3f} {:>12.3f}'.format( |
||||
key, percentile(time_values, 50), percentile(time_values, 90), |
||||
percentile(time_values, 95), percentile(time_values, 99)) |
||||
print |
||||
|
||||
def percentile(vals, percent): |
||||
""" Calculates the interpolated percentile given a sorted sequence and a |
||||
percent (in the usual 0-100 range).""" |
||||
assert vals, "Empty input sequence." |
||||
percent /= 100.0 |
||||
k = (len(vals)-1) * percent |
||||
f = math.floor(k) |
||||
c = math.ceil(k) |
||||
if f == c: |
||||
return vals[int(k)] |
||||
# else, interpolate |
||||
d0 = vals[int(f)] * (c-k) |
||||
d1 = vals[int(c)] * (k-f) |
||||
return d0 + d1 |
||||
|
||||
def entries(f): |
||||
for line in f: |
||||
m = _RE_LINE.match(line) |
||||
if not m: continue |
||||
yield Entry(time=float(m.group(1)), |
||||
thread=m.group(2), |
||||
type=m.group(3), |
||||
tag=int(m.group(4)), |
||||
id=m.group(5), |
||||
file=m.group(6), |
||||
line=m.group(7)) |
||||
|
||||
def main(f): |
||||
percentiles = (50, 90, 95, 99) |
||||
threads = collections.defaultdict(lambda: collections.defaultdict(list)) |
||||
times = collections.defaultdict(list) |
||||
important_marks = collections.defaultdict(list) |
||||
stack_depth = collections.defaultdict(int) |
||||
for entry in entries(f): |
||||
thread = threads[entry.thread] |
||||
if entry.type == '{': |
||||
thread[entry.tag].append(entry) |
||||
stack_depth[entry.thread] += 1 |
||||
if entry.type == '!': |
||||
# Save a snapshot of the current stack inside a new ImportantMark instance. |
||||
# Get all entries _for any tag in the thread_. |
||||
stack = [e for entries_for_tag in thread.itervalues() |
||||
for e in entries_for_tag] |
||||
imark_group_key = '{tag}/{thread}@{file}:{line}'.format(**entry._asdict()) |
||||
important_marks[imark_group_key].append(ImportantMark(entry, stack)) |
||||
elif entry.type == '}': |
||||
last = thread[entry.tag].pop() |
||||
times[entry.tag].append(entry.time - last.time) |
||||
# only access the last "depth" imarks for the tag. |
||||
depth = stack_depth[entry.thread] |
||||
for imarks_group in important_marks.itervalues(): |
||||
for imark in imarks_group[-depth:]: |
||||
# if at a '}' deeper than where the current "imark" was found, ignore. |
||||
if depth > imark.max_depth: continue |
||||
imark.append_post_entry(entry) |
||||
stack_depth[entry.thread] -= 1 |
||||
|
||||
print |
||||
print 'Block marks:' |
||||
print '============' |
||||
print_block_statistics(times) |
||||
|
||||
print |
||||
print 'Important marks:' |
||||
print '================' |
||||
for group_key, imarks_group in important_marks.iteritems(): |
||||
print_grouped_imark_statistics(group_key, imarks_group) |
||||
|
||||
|
||||
if __name__ == '__main__': |
||||
# If invoked without arguments, read off sys.stdin. If one argument is given, |
||||
# take it as a file name and open it for reading. |
||||
import sys |
||||
f = sys.stdin |
||||
if len(sys.argv) == 2: |
||||
f = open(sys.argv[1], 'r') |
||||
main(f) |
||||
@ -0,0 +1,231 @@ |
||||
#!/usr/bin/env python2.7 |
||||
import argparse |
||||
import collections |
||||
import hashlib |
||||
import itertools |
||||
import json |
||||
import math |
||||
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() |
||||
|
||||
|
||||
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') |
||||
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' % (self.top_line.tag, line['tag']) |
||||
final_time_stamp = line['t'] |
||||
assert self.top_line.end_time is None |
||||
self.top_line.end_time = final_time_stamp |
||||
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() |
||||
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 |
||||
|
||||
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 == '}': |
||||
self.stk.pop().finish(line) |
||||
if not self.stk: |
||||
self.finish() |
||||
return True |
||||
return False |
||||
elif line_type == '.' or line_type == '!': |
||||
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 a list of values. |
||||
|
||||
@parameter N - is a list of values. Note N MUST BE already sorted. |
||||
@parameter percent - a float value from 0.0 to 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 |
||||
k = (len(N)-1) * percent |
||||
f = math.floor(k) |
||||
c = math.ceil(k) |
||||
if f == c: |
||||
return key(N[int(k)]) |
||||
d0 = key(N[int(f)]) * (c-k) |
||||
d1 = key(N[int(c)]) * (k-f) |
||||
return d0+d1 |
||||
|
||||
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 |
||||
|
||||
FORMAT = [ |
||||
('TAG', lambda line: '..'*line.indent + tidy_tag(line.tag)), |
||||
('LOC', lambda line: '%s:%d' % (line.filename[line.filename.rfind('/')+1:], line.fileline)), |
||||
('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)), |
||||
] |
||||
|
||||
BANNER = { |
||||
'simple': 'Count: %(count)d', |
||||
'html': '<h1>Count: %(count)d</h1>' |
||||
} |
||||
|
||||
if args.fmt == 'html': |
||||
print '<html>' |
||||
print '<head>' |
||||
print '<title>Profile Report</title>' |
||||
print '</head>' |
||||
|
||||
accounted_for = 0 |
||||
for cs in call_stacks: |
||||
if args.fmt in BANNER: |
||||
print 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 tabulate.tabulate(table, header, tablefmt=args.fmt) |
||||
accounted_for += cs.count |
||||
if accounted_for > .99 * total_stacks: |
||||
break |
||||
|
||||
if args.fmt == 'html': |
||||
print '</html>' |
||||
|
||||
@ -0,0 +1,29 @@ |
||||
#!/bin/bash |
||||
|
||||
set -ex |
||||
|
||||
cd $(dirname $0)/../../.. |
||||
|
||||
BINS="sync_unary_ping_pong_test sync_streaming_ping_pong_test" |
||||
CPUS=`python -c 'import multiprocessing; print multiprocessing.cpu_count()'` |
||||
|
||||
make CONFIG=basicprof -j$CPUS $BINS |
||||
|
||||
mkdir -p reports |
||||
|
||||
echo '<html><head></head><body>' > reports/index.html |
||||
for bin in $BINS |
||||
do |
||||
bins/basicprof/$bin |
||||
mv latency_trace.txt $bin.trace |
||||
echo "<a href='$bin.txt'>$bin</a><br/>" >> reports/index.html |
||||
done |
||||
for bin in $BINS |
||||
do |
||||
tools/profiling/latency_profile/profile_analyzer.py \ |
||||
--source=$bin.trace --fmt=simple > reports/$bin.txt & |
||||
done |
||||
echo '</body></html>' >> reports/index.html |
||||
|
||||
wait |
||||
|
||||
Loading…
Reference in new issue