diff options
| author |  Craig Tiller <ctiller@google.com> | 2016-07-19 12:57:18 -0700 |
|---|---|---|
| committer | Craig Tiller <ctiller@google.com> | 2016-07-19 12:57:18 -0700 |
| commit | 268a47a2b1402d92d924889b52d9b4266f53483c (patch) | |
| tree | 78016ce0c2435b52f15863ab95bf8348084f6c8f /tools/profiling/latency_profile | |
| parent | 2eebe29ec84ed6b2d5c64016b12e1782281d5a38 (diff) | |
Add latency profiling from 'important' marks
Allows seeing directly how long was spent:
- running up to putting bytes on the wire
- between sending and receiving
- between receiving and finishing
Diffstat (limited to 'tools/profiling/latency_profile')
| -rwxr-xr-x | tools/profiling/latency_profile/profile_analyzer.py | 28 |
1 files changed, 21 insertions, 7 deletions
diff --git a/tools/profiling/latency_profile/profile_analyzer.py b/tools/profiling/latency_profile/profile_analyzer.py index dad0712d40..48b8e9b950 100755 --- a/tools/profiling/latency_profile/profile_analyzer.py +++ b/tools/profiling/latency_profile/profile_analyzer.py @@ -43,6 +43,7 @@ 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') @@ -78,10 +79,14 @@ class ScopeBuilder(object): 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']) + 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:]: @@ -101,9 +106,14 @@ class CallStackBuilder(object): 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'] @@ -113,7 +123,9 @@ class CallStackBuilder(object): 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']) + 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() @@ -216,9 +228,16 @@ def time_format(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)), @@ -227,11 +246,6 @@ FORMAT = [ ('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>' |