aboutsummaryrefslogtreecommitdiffhomepage
path: root/tools/profile_analyzer
diff options
context:
space:
mode:
authorGravatar David Garcia Quintas <dgq@google.com>2015-05-06 12:59:23 -0700
committerGravatar David Garcia Quintas <dgq@google.com>2015-05-06 14:26:17 -0700
commit776075a80a5d44bca39ee1bf1a5848939c6cd8c4 (patch)
tree4fe908f80a2b408f7ec0d285250d3c8f3704e474 /tools/profile_analyzer
parent78193bf0350069ae67993ce7fa3ee516e9f9fe66 (diff)
Implemented aggregation over important mark times.
Namely, 50,90,95 and 99th percentiles are now reported on important marks. Example output (for a single ! mark between begin-end marks in grpc_tcp_write()): ``` Important marks: ================ 99999@src/core/iomgr/tcp_posix.c:545 Relative mark: 50th p. 90th p. 95th p. 99th p. 205 { (src/core/iomgr/tcp_posix.c:541): 0.037 0.057 0.070 0.087 205 } (src/core/iomgr/tcp_posix.c:556): 15.181 27.021 32.509 41.103 ``` For a fabricated example (see https://gist.github.com/dgquintas/026d333815589cc37269) with the same ! mark in two different frames, the output is: ``` Important marks: ================ 999999@src/core/iomgr/tcp_posix.c:5 Relative mark: 50th p. 90th p. 95th p. 99th p. 205 { (src/core/iomgr/tcp_posix.c:1): 9.500 13.900 14.450 14.890 205 } (src/core/iomgr/tcp_posix.c:6): 3.000 4.600 4.800 4.960 999999@src/core/iomgr/tcp_posix.c:3 Relative mark: 50th p. 90th p. 95th p. 99th p. 205 { (src/core/iomgr/tcp_posix.c:1): 2.500 2.900 2.950 2.990 205 { (src/core/iomgr/tcp_posix.c:2): 1.500 1.900 1.950 1.990 205 } (src/core/iomgr/tcp_posix.c:4): 2.000 2.800 2.900 2.980 205 } (src/core/iomgr/tcp_posix.c:6): 10.000 15.600 16.300 16.860 ```
Diffstat (limited to 'tools/profile_analyzer')
-rwxr-xr-xtools/profile_analyzer/profile_analyzer.py62
1 files changed, 43 insertions, 19 deletions
diff --git a/tools/profile_analyzer/profile_analyzer.py b/tools/profile_analyzer/profile_analyzer.py
index 00b1079466..b540052697 100755
--- a/tools/profile_analyzer/profile_analyzer.py
+++ b/tools/profile_analyzer/profile_analyzer.py
@@ -39,6 +39,7 @@ Usage:
import collections
import itertools
+import math
import re
import sys
@@ -72,9 +73,29 @@ class ImportantMark(object):
def get_deltas(self):
pre_and_post_stacks = itertools.chain(self._pre_stack, self._post_stack)
return collections.OrderedDict((stack_entry,
- (self._entry.time - stack_entry.time))
+ abs(self._entry.time - stack_entry.time))
for stack_entry in pre_and_post_stacks)
+
+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 '{:>40s}: {:>15s} {:>15s} {:>15s} {:>15s}'.format(
+ 'Relative mark', '50th p.', '90th p.', '95th p.', '99th p.')
+ for key, time_values in values.iteritems():
+ print '{:>40s}: {:>15.3f} {:>15.3f} {:>15.3f} {:>15.3f}'.format(
+ key, percentile(time_values, 50), percentile(time_values, 90),
+ percentile(time_values, 95), percentile(time_values, 99))
+ print
+
+
def entries():
for line in sys.stdin:
m = _RE_LINE.match(line)
@@ -89,9 +110,6 @@ def entries():
threads = collections.defaultdict(lambda: collections.defaultdict(list))
times = collections.defaultdict(list)
-
-# Indexed by the mark's tag. Items in the value list correspond to the mark in
-# different stack situations.
important_marks = collections.defaultdict(list)
for entry in entries():
@@ -103,17 +121,31 @@ for entry in entries():
# Get all entries with type '{' from "thread".
stack = [e for entries_for_tag in thread.values()
for e in entries_for_tag if e.type == '{']
- important_marks[entry.tag].append(ImportantMark(entry, stack))
+ imark_group_key = '{tag}@{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)
# Update accounting for important marks.
- for imarks_for_tag in important_marks.itervalues():
- for imark in imarks_for_tag:
+ for imarks_group in important_marks.itervalues():
+ for imark in imarks_group:
imark.append_post_entry(entry)
-def percentile(vals, pct):
- return sorted(vals)[int(len(vals) * pct / 100.0)]
+def percentile(vals, percent):
+ """ Calculates the interpolated percentile given a (possibly unsorted sequence)
+ and a percent (in the usual 0-100 range)."""
+ assert vals, "Empty input sequence."
+ vals = sorted(vals)
+ 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
print 'tag 50%/90%/95%/99% us'
for tag in sorted(times.keys()):
@@ -127,13 +159,5 @@ for tag in sorted(times.keys()):
print
print 'Important marks:'
print '================'
-for tag, imark_for_tag in important_marks.iteritems():
- for imark in imarks_for_tag:
- deltas = imark.get_deltas()
- print '{tag} @ {file}:{line}'.format(**imark.entry._asdict())
- for entry, time_delta_us in deltas.iteritems():
- format_dict = entry._asdict()
- format_dict['time_delta_us'] = time_delta_us
- print '{tag} {type} ({file}:{line}): {time_delta_us:12.3f} us'.format(
- **format_dict)
- print
+for group_key, imarks_group in important_marks.iteritems():
+ print_grouped_imark_statistics(group_key, imarks_group)