Perfetto Trace を SQL で読む

Perfetto は内蔵の Trace Processor を使ってトレーシング結果を SQL で集計できる。SQL を使って興味のあるデータを取り出すことで

標準の Perfetto UI では読み取りにくい傾向を可視化したり、
可視化を通して気づいた傾向を定量的に比較できるようになる。

これは Systrace にはなかった大きな利点だ。この記事では Twitter と Instagram アプリのスクロール性能を評価する実例を交え Trace Processor の SQL インターフェイスを紹介する。

Twitter vs. Instagram

ある Podcast を聞いていたら、ホストの iPhone ユーザが気まぐれで触った Android 端末をレビューしていた。彼によれば Android の Twitter アプリは iPhone に比べスクロールの出来が非常に悪いという、一方で Instagram のスクロールはそれほど悪くないと評していた。

この主張を評価するため、Trace Processor を使って Twitter と Instagram のスクロール性能を比較してみよう。

アプリの起動後にトレースを開始、その後一秒おきに画面を五回スワイプしてフィードをスクロールダウンし、所定のスワイプが終わった時点でトレースを打ち切る(スクリプト)。このトレースを SQL で集計、比較していく。なおアプリは Pixel 2 にインストールした LineageOS 17.1 (Android 10) で動かしている。

トレース結果は以下のリンクでダウンロードできる: Twitter, Instagram.

Perfetto UI 上での比較

まずは二つのトレースを Perfetto UI で眺めてみよう。UI thread に着目する。

Twitter:

Twitter on Perfetto UI

Instagram:

Twitter on Perfetto UI

たしかに Twitter の UI thread は Instagram にくらべて混み合っている。とはいえこの混雑がどのくらいスクロールの jank (frame drop, コマ落ち) につながっているのかは、ひと目見ただけだとわからない。もっと定量的に評価したい。

Trace Processor Python API

そこで Trace Processor を使い frame drop を数えてみよう。Trace Processor にはいくつかの使い方があるが、ここでは可視化の都合で Jupyter notebook から Python API を使う。

詳しいインストール方法などは公式資料を参照するとして、データはこんなかんじでロードする:

!pip install perfetto

from perfetto.trace_processor import TraceProcessor
import altair as alt

tw = TraceProcessor(file_path='twitter-scroll.pftrace.gz')
ig = TraceProcessor(file_path='ig-scroll.pftrace.gz')

さて、フレーム間隔が 16ms 以上かかったらその frame は drop したとみなすことにしよう。トレース上でフレーム間隔を数えるには各フレームの末尾、つまり Choreographer#doFrame セクションの末尾同士の間隔を測れば良い。以下の赤線が間隔ひとつ分。

Twitter on Perfetto UI

Trace Processor の SQL にするとこうなる:

WITH
-- Extract Choreographer#doFrame as '_frames'
_frames AS (
  SELECT
    slice.dur dur,
    slice.ts  ts,
    slice.dur + slice.ts frame
  FROM
    slice
  INNER JOIN thread_track ON (slice.track_id = thread_track.id)
  INNER JOIN thread       ON (thread_track.utid = thread.utid)
  INNER JOIN process      ON (thread.upid       = process.upid)
  WHERE
        thread.is_main_thread = 1      
    AND process.name = '{p}'
    AND slice.name = 'Choreographer#doFrame'
),
-- Pick the earliest frame from _frames as '_first_frame'
_first_frame AS (
  SELECT MIN(_frames.ts) ts
  FROM _frames
)
-- Count the intervals between _frames.
SELECT
  (_frames.frame - (lag(_frames.frame)
    OVER (ORDER BY _frames.ts ROWS BETWEEN 1 PRECEDING AND CURRENT ROW)))
    / (1000 * 1000) interval,
  (_frames.ts - _first_frame.ts) / (1000 * 1000) ts
FROM _frames, _first_frame

この SQL はフレーム時刻 ts とフレーム間隔 interval のリストを返す。単位はミリ秒。上の SQL を使い、Twitter と Instagram それぞれの結果を時系列プロットとヒストグラムにしてみよう。

interval_query = """... Use the SQL above ..."""

twdf = tw.query(interval_query.format(p='com.twitter.android')).as_pandas_dataframe()
igdf = ig.query(interval_query.format(p='com.instagram.android')).as_pandas_dataframe()

def chart_pair(df, color):
    return (alt.Chart(df).mark_point(color=color).encode(
                x='ts',
                y=alt.Y('interval', scale=alt.Scale(domain=(0, 200)))) | \
            alt.Chart(df).mark_bar(color=color).encode(
                x=alt.X('interval', bin=alt.Bin(step=5),
                        scale=alt.Scale(domain=(0, 200))),
                y='count()'))

chart_pair(twdf, color='lightblue') & chart_pair(igdf, color='palevioletred')

Twitter on Perfetto UI

間隔が 16ms 付近に集中している Instagram (紫) に対し、Twitter (青) の間隔はずいぶんとばらついている。

ヒストグラムによる可視化で傾向がわかったら、次は指標を定量化する。

ダブルバッファリングなどで多少の遅延は隠されるのでざっくり 20ms 以上かかったフレームを frame drop として数え、 frame drop の発生頻度を指標としよう。これを frame drop rate と呼ぶ。Instagram の frame drop rate は 5%, Twitter は 35% だった。

なおトレースに現れない事実として、Instagram は画像のロード待ちなどで途中二回くらいスクロールが止まり跳ね返っている。（時系列プロットの 1000 と 4000 付近)。一方の Twitter は計測中ずっとスクロールし続けていた。だから Instagram もトレースだけの印象ほど完璧ではない。とはいえそれを差し引いてもスクロールの jank は Twitter より Instagram の方が少ないと言ってよいだろう。

スレッドの負荷

一般的にレイテンシは小さいほどよい。理想はゼロ。一方で jank はフレームの処理が 16ms 以内に収まれば消える。だから frame drop rate が十分小さくなったらそれ以上は高速化しても成果が見えない。

しかし実際にはまだ高速化の余地があるかもしれない。同じ frame drop rate でも、フレームの処理が締切半ばの 8ms で終わっているか締切ギリギリの 15ms かかっているかでは余裕の幅が違う。この余裕は測定用デバイスより遅いデバイスでアプリを実行した場合やバックグランドのタスクがアプリと CPU を奪い合っている場合などで体感できる違いを生む。

Frame drop rate を超えて改善を定量化するには、フレームの間隔ではなく各フレームの処理時間を集計すればよい。素朴に考えると Choreographer#doFrame セクションのレイテンシを集計すれば良さそうに思えるが、アプリは doFrame() の外側で計算をすることもある。そうした計算からのレイテンシも漏らさず計上したい。

そこで近似として UI スレッドが実際に CPU を使っている割合を単位時間あたりで数える。このように考える: UI スレッドが 16ms という単位時間のうち 8ms だけ仕事をしていたなら、そのアプリは CPU の遅さが半分になっても jank freedom を達成できるだろう。逆に 16ms の予算のうちギリギリの 15ms を使うアプリは、倍遅い CPU では半分近いフレームを drop してしまうだろう。

集計結果の不要なばらつきをへらすため、単位時間を 100ms として　UI スレッドの利用率 (load) を計算しよう。

-- Extract CPU scheduler timeslice of the UI thread as 'ui_thread_spans_'
WITH
ui_thread_spans_ AS (
  SELECT
    sched.*,
    (sched.ts / (1000 * 1000 * 100)) span
  FROM
    sched
  INNER JOIN thread  ON (sched.utid  = thread.utid)
  INNER JOIN process ON (thread.upid = process.upid)
  WHERE
        thread.is_main_thread = 1      
    AND process.name = '{p}'
),
-- Pick the first timeslice as 'first_span_'
first_span_ AS (
SELECT
    MIN(ui_thread_spans_.span) as span
FROM ui_thread_spans_
)
-- Aggregate and normalize the timeslice for each 100ms.
SELECT
  CAST(SUM(ui_thread_spans_.dur) AS float) / (1000 * 1000 * 100) load,
  ui_thread_spans_.span - first_span_.span span
FROM ui_thread_spans_, first_span_
GROUP BY ui_thread_spans_.span
ORDER BY ui_thread_spans_.span DESC

時系列のプロットとヒストグラムは以下の通り:

load_query = """..."""

igload = ig.query(load_query.format(p='com.instagram.android')).as_pandas_dataframe()
twload = tw.query(load_query.format(p='com.twitter.android')).as_pandas_dataframe()

def sched_chart_pair(df, color):
    return alt.Chart(df).mark_point(color=color).encode(
                 x='span',
                 y=alt.Y('load', scale=alt.Scale(domain=(0, 1)))) | \
           alt.Chart(df).mark_bar(color=color).encode(
                 x=alt.X('load', bin=alt.Bin(step=0.1),
                        scale=alt.Scale(domain=(0, 1))),
                 y='count()')

sched_chart_pair(twload, 'lightblue') & sched_chart_pair(igload, 'palevioletred')

Twitter on Perfetto UI

Twitter は最頻区間が 0.6-0.7 なのに対し、Instagram は左端のアイドル状態分を無視しても 0.2-0.3 が最頻だった。Instagram はローエンドデバイスでもきちんとスクロールできそうだ。

今や UI スレッドの負荷はローエンドデバイスだけの問題でない。最新のハイエンドデバイスはスクリーンが 120Hz の refresh rate を持つ。つまりスクロールなどアニメーションを伴う UI スレッドの load は 60Hz のデバイスの倍になる。この厳しさを乗り越え 120Hz でレンダリングできるアプリが世の中にどれだけあるのか個人的には懐疑的だったが、すくなくとも Instagram はきちんと動きそうに見える。120Hz 対応デバイスを持っている人は試して結果を教えてほしい。

なおこの近似は UI スレッドがスクロールの処理中に IPC や IO でブロックしないと仮定している。Twitter と Instagram に限れば、この仮定はだいたい成り立っている。

この記事を書くために使った notebook はここにアップロードした。

雑多な Trace Processor Tips

Trace Processor の SQL インターフェイスは SQLite の virtual table として実装されている。Schema はある程度文書化されているが、十分でない。実際のデータベースをさわって試行錯誤する方が良い。テーブルは SELECT name FROM perfetto_tables ORDER BY name で一覧できる。
何らかの事情で Python API を使えない場合、コマンドラインのツールをダウンロードして virtual table を SQLite のデータベースとしてダンプできる。ダンプしたデータベースは無印の SQLite で読める。
Python API はなぜか今の所 Colab で使えない。どこかに Jupyter notebook ランタイムが必要。

参考リンク

とりあえず使う Perfetto - Perfetto の最低限の使い方を説明した記事。
Trace Processor - Perfetto Tracing Docs - 公式資料。
perfetto · PyPI - Python API の PyPI package。まだ Alpha である点に留意されたし。
Altair: Declarative Visualization in Python — Altair 4.1.0 documentation - チャート用 Python ライブラリ

MorritaNotes

Perfetto Trace を SQL で読む

Twitter vs. Instagram

Perfetto UI 上での比較

Trace Processor Python API

スレッドの負荷

雑多な Trace Processor Tips

参考リンク

Morrita
Notes