高速化日記 (4) - Tracing

ちょっとした API が binder call 2つ向こうのプロセスでがっつり CPU と I/O を食いつぶしているのを見つけてしまう。これを今まで見過ごしていたとはと後悔の念が募る。

Systrace はだいたい Dapper みたいなものというなんとなくの評価をしていたが、この問題を見逃したのは Systrace が Dapper みたい「ではない」からだと思い至った。ダメなところがいくつかある。

ひとつ目かつ最大の不足は、前にも書いたように binder のフローを可視化できないところ。これはもうダメとしかいいようがない。RPC/IPC を可視化できない分散トレーシングとかトレースしてないじゃん。アホか。

ふたつ目は、これはひとつ目の原因の一つとみなすことができるが、トレースにスコープの概念がないこと。

Dapper のような分散トレーシングにおいては、ブラウザやアプリからの API request が届いた瞬間がスコープのはじまりで、response を返した瞬間がスコープの終わりである。そしてスコープの起点となったリクエストのコンテクストに紐付いたバックエンドのリクエストだけがトレーシングの対象である。

一方の Systrace は、atrace なり perfetto なりのコマンドを起動した瞬間がはじまりで、ログのバッファがいっぱいになった時点がおわりである。そしてシステム全体の活動がすべて記録、表示される。一方、アプリケーション開発者つまり自分の関心のスコープは、アプリのプロセスの起動・・・というかもっといえば Intent の発行から、最初の画像が画面に表示されるまでである。そしてアプリの画面表示に必要となった(つまり自分のアプリが起点となった)システムの活動だけに関心がある。

自分の関心に対し Systrace の表示は不必要な情報が多すぎる。つまり noisy である。現状ですら十分にノイジーなので、そこに binder の flow を(バグなしに)表示できたとしても画面がぐちゃぐちゃでわけがわからくなってしまい、有用性が低い。

Systrace はもともとシステム全体の性能をみる performance team の人や、システムの定常状態での描画パイプラインのもたつきを調べたい graphics team の人が使うツールだった。こういう人たちはアプリのレイヤでできない system global な挙動や stochastic な挙動が知りたいので、スコープのないシステム全体の view を見ることにも意味があるかもしれない。でもアプリ開発者は自分のアプリに関係ある挙動だけが知りたいのだよ。Dapper よこせ!

もちろんアプリのスコープの外でおきたロードがアプリを遅くすることがある。たとえば GPS シグナルを要求したらなぜか geofencing のブロードキャストで寝ているアプリを起こしてしまうとか、裏で Play がアプリをアップデートしてましたとか Wifi シグナルの変化で起きるアプリがいましたとか(ぼちぼちある)、LMK 起きまくってましたとか(よくある)、LMK どころか trimMemory でいらんアプリが目を覚まし page が大混雑でしたとか、つらい。がしかし、そういうのは総体としてはマイナーな話だし、アプリ開発者にできることはあまり無い。クラウドで同じハードウェアに同居してる別の VM が悪さしてもできることないのと同じ。(影響はずっとでかいけど・・・)

なお Android には reportFullyDrawn() という API が「興味のあるスコープ」をシステムと communicate する方法として推奨されている。しかしアプリにしてみるとログが一行でるだけなので普通にログを書くのと大差ない。OS の中の人が標準アプリのベンチマーク自動化などで使っているらしいが・・・知るかよってかんじ。もうちょっと使えるもんよこせと言いたい。

というかもうちょっと使えるもんくださいと頼まないとな・・・いま仕事ふやしたくないので締め切りおわったらね・・・とかいってるといつまでたってもなにもできないな・・・そしてこういう話するのに適切なフォーラムどこかな社内・・・はー。