#!/usr/bin/env bash # What a scrolling frame is actually spending its time in, by name. # # The app's own counters can time the code we wrote, and they showed that almost none of the frame # is that code -- roughly a fortieth of the draw phase. The rest is inside the framework, which # already brackets its own work with trace sections (measure, layout, draw, the position-callback # dispatch, the per-node rect bookkeeping, semantics). This turns those on, drives a fling, and adds # up what each section cost, so "the other eighty percent" gets a name instead of a hypothesis. # # atrace's text output rather than perfetto's protobuf on purpose: this needs no trace_processor # build, and the question here is which sections dominate, which the text format answers directly. # # The absolute milliseconds from an emulator are worthless -- it renders in software, and its stock # apps miss frames as badly as ours do. The *ranking* is what transfers, which is what this prints. set -euo pipefail app=com.example.aiapp secs=6 swipes=12 out=/tmp/ai-app-trace.txt top=25 # Empty means whatever `adb` picks by itself, which in this checkout is its own emulator. A phone # needs naming, and a phone is the only place these numbers mean anything -- see the note at the # foot of this file. serial=() while [ $# -gt 0 ]; do case "$1" in -t) secs=$2; shift 2 ;; -n) swipes=$2; shift 2 ;; -o) out=$2; shift 2 ;; --top) top=$2; shift 2 ;; -s) serial=(-s "$2"); shift 2 ;; -h|--help) echo "usage: $0 [-s serial] [-t seconds] [-n swipes] [-o file] [--top n]" exit 0 ;; *) echo "$0: unknown argument $1" >&2; exit 2 ;; esac done if ! adb "${serial[@]}" shell pidof "$app" >/dev/null 2>&1; then echo "$0: $app is not running -- open a session in it first" >&2 exit 1 fi pid=$(adb "${serial[@]}" shell pidof "$app" | tr -d '\r') # `view` carries Compose's measure/layout/draw and the View system's own; `gfx` carries the render # thread and the frame boundaries. Buffer sized for a few seconds of a busy main thread: a fling # emits a great many sections and a full buffer silently drops the end of the trace. # # A blocking capture with the gestures alongside it, rather than atrace's own --async_start / # --async_dump pair: measured on this emulator, the asynchronous form returns a buffer of # `entries-in-buffer: 0/0` however long it runs, and an empty trace reads exactly like an app that # emitted no sections. Blocking, the same categories fill it immediately. # # `-a` is the flag the whole thing turns on. Without it atrace records only what the system emits, # and every section Compose writes -- measure, layout, recomposition -- comes from `android.os.Trace` # inside the app process, which stays switched off. The result looks like a successful capture and # answers the question with the framework's half of the frame, which is not the half being asked # about. adb "${serial[@]}" shell atrace -a "$app" -b 65536 -t "$secs" -c view gfx input 2>/dev/null | tr -d '\r' >"$out" & capture=$! for _ in $(seq "$swipes"); do adb "${serial[@]}" shell input swipe 540 1800 540 700 80 >/dev/null 2>&1 done wait "$capture" if ! grep -q tracing_mark_write "$out"; then echo "$0: the trace holds no sections; another capture may hold the ftrace buffer" >&2 exit 1 fi python3 - "$out" "$pid" "$top" <<'PY' import collections, re, sys path, pid, top = sys.argv[1], sys.argv[2], int(sys.argv[3]) # ftrace text: "- () [cpu] flags : tracing_mark_write: B||" mark = re.compile(r"^\s*\S+-(\d+)\s+\(\s*(\d+|-+)\)[^:]*?\s+(\d+\.\d+):\s+tracing_mark_write:\s+(.*)$") stacks = collections.defaultdict(list) total = collections.Counter() count = collections.Counter() worst = collections.Counter() frames = 0 for line in open(path, errors="replace"): m = mark.match(line) if not m: continue tid, owner, ts, body = m.group(1), m.group(2), float(m.group(3)), m.group(4) parts = body.split("|") if parts[0] == "B" and len(parts) >= 3: if parts[1] != pid: continue stacks[tid].append((parts[2], ts)) elif parts[0] == "E": if not stacks[tid]: continue name, began = stacks[tid].pop() ms = (ts - began) * 1000.0 total[name] += ms count[name] += 1 worst[name] = max(worst[name], ms) if name.startswith("Choreographer#doFrame"): frames += 1 if not total: print("no sections for pid " + pid + " -- was the app in the foreground?") raise SystemExit(1) print(f"{frames} frames traced, {sum(count.values())} sections") print() print(f"{'section':<44}{'calls':>7}{'total ms':>10}{'mean':>8}{'worst':>8}") for name, ms in total.most_common(top): n = count[name] label = name if len(name) <= 43 else name[:40] + "..." print(f"{label:<44}{n:>7}{ms:>10.1f}{ms/n:>8.2f}{worst[name]:>8.1f}") left = len(total) - top if left > 0: print(f"... {left} more sections not shown (--top to raise the limit)") PY # A note on where to run this. # # Not here. Measured on this checkout's emulator, a scrolling frame is 15ms of `Drawing` of which # 10ms is `dequeueBuffer` and `postAndWait` -- the main thread blocked on the buffer queue, because # the emulator renders in software -- while Compose's own `AndroidOwner:draw` is 0.40ms. The # ranking that comes out is the ranking of the emulator's graphics stack, and it says nothing about # a phone whose whole draw phase is 3.6ms. Point it at the device the numbers came from.