From 776075a80a5d44bca39ee1bf1a5848939c6cd8c4 Mon Sep 17 00:00:00 2001 From: David Garcia Quintas Date: Wed, 6 May 2015 12:59:23 -0700 Subject: 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 ``` --- tools/profile_analyzer/profile_analyzer.py | 62 +++++++++++++++++++++--------- 1 file changed, 43 insertions(+), 19 deletions(-) (limited to 'tools/profile_analyzer/profile_analyzer.py') 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) -- cgit v1.2.3