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

```
pull/1496/head
David Garcia Quintas 10 years ago
parent 78193bf035
commit 776075a80a
  1. 62
      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)

Loading…
Cancel
Save