cleanyourtv/tools/trace_report.py

#!/usr/bin/env python3
"""The standard launcher numbers from traces recorded with tools/trace.py: per run, median and range.

    tools/trace_report.py traces/before                       one set of runs
    tools/trace_report.py traces/before --vs traces/after     before against after, with the change
    tools/trace_report.py ... --markdown                      tables to paste into a pull request

TRACES are .pftrace files or folders of them. Needs the optional `perfetto` package
(tools/venv/bin/pip install -r tools/requirements-perf.txt). Its first run downloads Perfetto's query
engine; --engine PATH uses a trace_processor_shell you downloaded yourself, which has to be a file this
script can run. Read tools/trace.md first.

Exit status: 0 the tables printed, 1 a trace could not be read or the engine failed, 2 --engine names
something that is not a file this script can run.

For a start (cold, coldsys, home and custom traces) it reports the time from the launcher starting
(bindApplication in a new process, else performStart) to its first frame drawn, the lifecycle steps
inside that, and the frames drawn and deadlines missed in the 1.5 s after. For nav traces it reports
frame times and missed deadlines over the whole recording.
"""
import argparse
import glob
import json
import math
import os
import re
import statistics
import sys

PACKAGE = re.compile(r"^[A-Za-z][A-Za-z0-9_]*(\.[A-Za-z][A-Za-z0-9_]*)+$")
WINDOW_NS = 1_500_000_000
MS = 1e6

START_METRICS = [("first frame", "start to first frame drawn (ms)"), ("bindApplication", "bindApplication (ms)"),
                 ("activityStart", "onCreate (activityStart, ms)"), ("onStart", "onStart (performStart, ms)"),
                 ("onResume", "onResume (activityResume, ms)"), ("first traversal", "first layout and draw (ms)"),
                 ("frames", "frames drawn in 1.5 s"), ("missed", "frames that missed their deadline in 1.5 s")]
NAV_METRICS = [("frames", "frames drawn"), ("frame median", "frame time, median (ms)"),
               ("frame p90", "frame time, 90th percentile (ms)"), ("draw median", "RenderThread draw, median (ms)"),
               ("gpu median", "waiting for the GPU, median (ms)"), ("missed", "frames that missed their deadline")]


def one(q, sql, default=None):
    rows = q(sql)
    if not rows:
        return default
    value = next(iter(rows[0].values()))
    return default if value is None else value


def threads(q, package):
    """(upid, main thread utid, RenderThread utid) of the newest process named after the package."""
    upid = one(q, f"select upid from process where name = '{package}' order by upid desc limit 1")
    if upid is None:
        return None, None, None
    main = one(q, f"select utid from thread join process using(upid) where thread.upid = {upid} and thread.tid = process.pid")
    render = one(q, f"select utid from thread where upid = {upid} and name = 'RenderThread' order by utid limit 1")
    return upid, main, render


def slices(utid, where, columns="s.ts, s.dur"):
    return (f"select {columns} from slice s join thread_track tt on s.track_id = tt.id "
            f"where tt.utid = {utid} and {where} order by s.ts")


def start_metrics(q, package):
    """The numbers for a launcher start: cold, coldsys, home or a custom trace that brings Home up."""
    return _start(q, package)[0]


def start_window(q, package):
    """(start, first frame drawn) in ns for a launcher start; either is None when the trace lacks it."""
    return _start(q, package)[1:]


def _start(q, package):
    """(metrics, start ns, first frame drawn ns) for a launcher start."""
    upid, main, render = threads(q, package)
    if main is None:
        return {}, None, None
    bind = q(slices(main, "s.name = 'bindApplication'"))
    start = q(slices(main, "s.name like 'performStart%'"))
    anchor = bind[0]["ts"] if bind else (start[0]["ts"] if start else None)
    if anchor is None:
        return {}, None, None
    end = None
    resume = q(slices(main, f"s.name = 'activityResume' and s.ts >= {anchor}"))
    out = {}
    if bind and bind[0]["dur"] >= 0:
        out["bindApplication"] = bind[0]["dur"] / MS
    created = q(slices(main, f"s.name = 'activityStart' and s.ts >= {anchor}"))
    if created and created[0]["dur"] >= 0:
        out["activityStart"] = created[0]["dur"] / MS
    if start:
        first_start = [s for s in start if s["ts"] >= anchor] or start
        if first_start[0]["dur"] >= 0:
            out["onStart"] = first_start[0]["dur"] / MS
    if resume and resume[0]["dur"] >= 0:
        out["onResume"] = resume[0]["dur"] / MS
        resumed = resume[0]["ts"] + resume[0]["dur"]
        traversal = q(slices(main, f"s.name = 'traversal' and s.ts >= {resumed}"))
        if traversal and traversal[0]["dur"] >= 0:
            t = traversal[0]
            out["first traversal"] = t["dur"] / MS
            end = t["ts"] + t["dur"]
            if render is not None:
                drawn = q(slices(render, f"s.name like 'DrawFrame%' and s.ts >= {t['ts']}"))
                if drawn:
                    # Perfetto uses -1 when a slice has no end; it is not a completion time.
                    end = max(end, drawn[0]["ts"] + drawn[0]["dur"]) if drawn[0]["dur"] >= 0 else None
            if end is not None:
                out["first frame"] = (end - anchor) / MS
    if render is not None:
        out["frames"] = one(q, f"select count(*) from slice s join thread_track tt on s.track_id = tt.id "
                               f"where tt.utid = {render} and s.name like 'DrawFrame%' and s.dur >= 0 "
                               f"and s.ts >= {anchor} and s.ts < {anchor + WINDOW_NS}", 0)
    if one(q, f"select 1 from actual_frame_timeline_slice where upid = {upid} and dur >= 0 "
              f"and ts >= {anchor} and ts < {anchor + WINDOW_NS} limit 1"):
        out["missed"] = one(q, f"select count(*) from actual_frame_timeline_slice where upid = {upid} "
                               f"and dur >= 0 and jank_type like '%App Deadline Missed%' "
                               f"and ts >= {anchor} and ts < {anchor + WINDOW_NS}", 0)
    return out, anchor, end


def nav_metrics(q, package):
    """Frame numbers over a whole nav recording."""
    upid, main, render = threads(q, package)
    if upid is None:
        return {}
    frames = sorted(r["dur"] / MS for r in q(f"select dur from actual_frame_timeline_slice "
                                            f"where upid = {upid} and dur >= 0"))
    out = {}
    if frames:
        out["frames"] = len(frames)
        out["frame median"] = statistics.median(frames)
        out["frame p90"] = frames[math.ceil(0.9 * len(frames)) - 1]
    if render is not None:
        draws = [r["dur"] / MS for r in q(slices(render, "s.name like 'DrawFrame%' and s.dur >= 0", "s.dur"))]
        if not frames:
            out["frames"] = len(draws)
        if draws:
            out["draw median"] = statistics.median(draws)
        waits = [r["dur"] / MS for r in q(f"select s.dur from slice s join thread_track tt on s.track_id = tt.id "
                                           f"join thread t using(utid) where t.upid = {upid} "
                                           f"and s.name like 'waiting for GPU completion%' and s.dur >= 0")]
        if waits:
            out["gpu median"] = statistics.median(waits)
    if frames:
        out["missed"] = one(q, f"select count(*) from actual_frame_timeline_slice where upid = {upid} "
                               f"and dur >= 0 and jank_type like '%App Deadline Missed%'", 0)
    return out


def scenario_of(path):
    """The scenario trace.py wrote next to the trace, or the start of its file name."""
    sidecar = path[:-len(".pftrace")] + ".json" if path.endswith(".pftrace") else None
    if sidecar and os.path.exists(sidecar):
        try:
            with open(sidecar) as f:
                data = json.load(f)
                if isinstance(data, dict):
                    return data.get("scenario", "")
        except (OSError, ValueError):
            pass
    return os.path.basename(path).split("-")[0]


def expand(items):
    paths = []
    for item in items:
        if os.path.isdir(item):
            paths += sorted(glob.glob(os.path.join(item, "*.pftrace")), key=_run_order)
        else:
            paths.append(item)
    return paths


def _run_order(path):
    m = re.search(r"-(\d+)\.pftrace$", path)
    return (re.sub(r"-\d+\.pftrace$", "", path), int(m.group(1)) if m else 0)


def engine_path(engine):
    """The --engine path, judged before Perfetto is imported and before any trace is read.

    tools/trace.md hands out "--engine PATH" to a reader who downloaded trace_processor_shell instead of
    letting Perfetto fetch one, and nothing here read the path: an empty value, a typo, a folder or a file
    without its execute bit went straight into TraceProcessor(trace=..., config=...), which is the first
    thing that starts the engine. Perfetto answers the first three with a bare
    Exception("Path to binary is not valid (<path>)") - not its own error class, so no caller can catch it -
    and the fourth with PermissionError out of subprocess, each a traceback with exit 1, the status a run
    that read a trace and failed returns, naming neither --engine nor tools/trace.md. flamechart.py opens
    its traces with this same opener(), so it is answered here too.
    """
    if engine is None:
        return None
    if not engine.strip():
        raise ValueError("--engine is empty: name the trace_processor_shell you downloaded, or leave "
                         "--engine out to have Perfetto download one (tools/trace.md)")
    if not os.path.isfile(engine):
        raise ValueError(f"--engine {engine} is not a file: it is the trace_processor_shell you downloaded "
                         "yourself (tools/trace.md), or leave --engine out to have Perfetto download one")
    # Windows has no execute bit to read; the engine there is an .exe, and a wrong one fails to start.
    if os.name == "posix" and not os.access(engine, os.X_OK):
        raise ValueError(f"--engine {engine} is not executable: run chmod +x on the trace_processor_shell "
                         "you downloaded (tools/trace.md)")
    # Perfetto passes this to Popen: a bare POSIX filename searches PATH instead of running the file
    # checked above. Keep paths containing / unchanged, including symlinks followed by .. .
    if os.name == "posix" and not os.path.dirname(engine):
        return os.path.join(".", engine)
    return engine


def opener(engine=None):
    """open(path) -> q(sql) returning rows as dicts, plus close(), using Perfetto's query engine."""
    try:
        engine = engine_path(engine)
    except ValueError as e:
        print(f"{e}. No trace was read.", file=sys.stderr)
        sys.exit(2)
    try:
        from perfetto.trace_processor import TraceProcessor, TraceProcessorConfig
    except ImportError:
        sys.exit("trace_report.py needs the optional perfetto package: "
                 "tools/venv/bin/pip install -r tools/requirements-perf.txt (see tools/trace.md)")

    def open_trace(path):
        tp = TraceProcessor(trace=path, config=TraceProcessorConfig(bin_path=engine))

        def q(sql):
            result = tp.query(sql)
            names = result.column_names
            return [dict(zip(names, (getattr(row, n) for n in names))) for row in result]
        return q, tp.close
    return open_trace


def measure(paths, package, open_trace):
    """[(name, metrics)] for each trace, in run order."""
    out = []
    for path in paths:
        q, close = open_trace(path)
        try:
            metrics = nav_metrics(q, package) if scenario_of(path) == "nav" else start_metrics(q, package)
        finally:
            close()
        out.append((os.path.basename(path)[:-len(".pftrace")], metrics))
    return out


def summary(values):
    values = [v for v in values if v is not None]
    if not values:
        return None, None, None
    return statistics.median(values), min(values), max(values)


def fmt(value):
    if value is None:
        return "–"
    return f"{value:.0f}" if abs(value) >= 20 or float(value).is_integer() else f"{value:.1f}"


def table(runs, names, markdown):
    """Metric rows, one column per run, then the median and range. A run more than twice the median is starred."""
    head = ["", *[r[0] for r in runs], "median", "range"]
    rows = []
    for key, label in names:
        values = [r[1].get(key) for r in runs]
        if all(v is None for v in values):
            continue
        med, lo, hi = summary(values)
        cells = [fmt(v) + ("*" if v is not None and med and key == "first frame" and v > 2 * med else "") for v in values]
        rows.append([label, *cells, fmt(med), f"{fmt(lo)}–{fmt(hi)}"])
    return render(head, rows, markdown)


def compare(before, after, names, markdown):
    rows = []
    for key, label in names:
        b = summary([r[1].get(key) for r in before])[0]
        a = summary([r[1].get(key) for r in after])[0]
        if b is None and a is None:
            continue
        change = f"{100 * (a - b) / b:+.0f}%" if a is not None and b else "–"
        rows.append([label, fmt(b), fmt(a), change])
    return render(["", "before (median)", "after (median)", "change"], rows, markdown)


def render(head, rows, markdown):
    if markdown:
        lines = ["| " + " | ".join(head) + " |", "|" + "---|" * len(head)]
        return "\n".join(lines + ["| " + " | ".join(r) + " |" for r in rows])
    widths = [max(len(str(r[i])) for r in [head] + rows) for i in range(len(head))]
    return "\n".join("  ".join(str(c).ljust(w) for c, w in zip(r, widths)).rstrip() for r in [head] + rows)


def report(before, after, markdown, nav):
    """The tables for one set of runs, or for two with the change in the medians."""
    names = NAV_METRICS if nav else START_METRICS
    parts = [("Before" if after else "Runs") + f" ({len(before)}):", table(before, names, markdown)]
    if after:
        parts += ["", f"After ({len(after)}):", table(after, names, markdown), "",
                  "Change in the median:", compare(before, after, names, markdown)]
    if _has_outlier(before) or (after and _has_outlier(after)):
        parts += ["", "* more than twice the median: often memory pressure on the TV (tools/trace.md). "
                      "Report it rather than dropping it."]
    return "\n".join(parts)


def _has_outlier(runs):
    med = summary([m.get("first frame") for _, m in runs])[0]
    return bool(med) and any((m.get("first frame") or 0) > 2 * med for _, m in runs)


def parse(argv):
    p = argparse.ArgumentParser(description="Launcher numbers from tools/trace.py traces. See tools/trace.md.")
    p.add_argument("traces", nargs="+", help=".pftrace files or folders of them")
    p.add_argument("--vs", nargs="+", metavar="TRACES", help="the traces to compare against the first set")
    p.add_argument("--package", default="com.gathin.tvhome", help="the launcher's package (default com.gathin.tvhome)")
    p.add_argument("--engine", metavar="PATH", help="a trace_processor_shell to use instead of downloading one")
    p.add_argument("--markdown", action="store_true", help="print Markdown tables")
    args = p.parse_args(argv)
    if not PACKAGE.match(args.package):
        p.error(f"not a package name: {args.package!r}")
    return args


def main(argv=None):
    args = parse(sys.argv[1:] if argv is None else argv)
    sets = [expand(args.traces)] + ([expand(args.vs)] if args.vs else [])
    for paths in sets:
        if not paths:
            sys.exit("no .pftrace files found; record some with tools/trace.py")
        missing = [p for p in paths if not os.path.isfile(p)]
        if missing:
            sys.exit("not a file: " + ", ".join(missing))
    families = [{"nav" if scenario_of(p) == "nav" else "start" for p in paths} for paths in sets]
    if any(len(family) > 1 for family in families):
        sys.exit("cannot mix nav and start traces in one set; report them separately")
    if len(families) > 1 and families[0] != families[1]:
        sys.exit("cannot compare nav and start traces with --vs; report them separately")
    open_trace = opener(args.engine)
    measured = [measure(paths, args.package, open_trace) for paths in sets]
    nav = families[0] == {"nav"}
    print(report(measured[0], measured[1] if len(measured) > 1 else None, args.markdown, nav))


if __name__ == "__main__":
    main()