# perftrace.py - Module for tracing performance # # Copyright 2019 Facebook, Inc. # # This software may be used and distributed according to the terms of the # GNU General Public License version 2 or any later version. import time from contextlib import contextmanager from . import encoding, error spans = [] finished_traces = [] class Span(object): __slots__ = ["name", "start", "end", "children", "flags", "values"] def __init__(self, name): self.name = name self.start = -1 self.end = -1 self.children = [] self.flags = set() self.values = {} def duration(self): return self.end - self.start def traces(): return finished_traces lasttime = 0 def gettime(): # Make it "run-tests.py -i" friendly if "TESTTMP" in encoding.environ: global lasttime lasttime += 1 return lasttime return time.time() @contextmanager def trace(name): try: latest = None if spans: latest = spans[-1] span = Span(name) spans.append(span) if latest: latest.children.append(span) span.start = gettime() yield finally: span.end = gettime() spans.pop(-1) if not spans: finished_traces.append(span) def traceflag(flagname): """Records the given flag name as being associated with the latest trace point.""" if not spans: raise error.ProgrammingError("Attempting to set flag without starting a trace") latest = spans[-1] latest.flags.add(flagname) def tracevalue(name, value): """Records the given name=value as being associated with the latest trace point. This will overwrite any previous value with that name.""" if not spans: raise error.ProgrammingError("Attempting to set value without starting a trace") latest = spans[-1] # TODO: report when overwriting a value latest.values[name] = value def tracebytes(name, value): """Records the given name=value as being associated with the latest trace point. The value is treated as bytes and will be added to any previous value set to the same name.""" if not spans: raise error.ProgrammingError( "Attempting to set bytes value without starting a trace" ) latest = spans[-1] latest.values[name] = latest.values.get(name, 0) + value def tracefunc(name): """Decorator that indicates this entire function should be wrapped in a trace.""" def wrapper(func): def executer(*args, **kwargs): with trace(name): return func(*args, **kwargs) return executer return wrapper def asciirender(span): return _AsciiRenderer(span).render() class _AsciiRenderer(object): def __init__(self, span): self.indentamount = 2 self.span = span self.start = self.span.start # Width of the start column, so we can right justify everything self.start_width = len("{0:0.1f}".format(self.span.end - self.span.start)) # Seconds of missing data to consider as a gap self.gap_threshold = 1 def render(self): output = [] self._render(output, self.span, 0) duration = self.span.end - self.span.start output.append("{0:0.1f}".format(duration)) return "\n".join(output) + "\n" def _render(self, output, span, indent): start = span.start - self.start duration = span.duration() details = _format_duration(duration) if span.flags: details += "; %s" % ("; ".join(sorted(span.flags))) output.append( "{start} {indent} {name} ({details})".format( start=("{0:0.1f}".format(start)).rjust(self.start_width), indent=" " * indent, name=span.name, details=details, ) ) for name, value in sorted(span.values.iteritems()): output.append( "{mark} {indent} * {name}: {value}".format( mark=":".rjust(self.start_width), indent=" " * (indent + self.indentamount), name=name, value=value, ) ) last = span.start for child in span.children: gap = child.start - last self._render_gap(output, last, gap, indent + self.indentamount) self._render(output, child, indent + self.indentamount) last = child.end if len(span.children) > 0: gap = span.end - last self._render_gap(output, last, gap, indent + self.indentamount) def _render_gap(self, output, start, gap, indent): if gap > self.gap_threshold: output.append( "{start} {indent} {name} ({duration})".format( start=("{0:0.1f}".format(start - self.start)).rjust( self.start_width ), indent=" " * indent, name="--missing--", duration=_format_duration(gap), ) ) def _format_duration(seconds): if seconds < 60: return "{0:0.1f}s".format(seconds) if seconds < 3600: return "{0}m {1}s".format(int(seconds / 60), seconds % 60) return "{0}h {1}m".format(int(seconds / 3600), int((seconds % 3600) / 60))