2010年10月15日金曜日

Android 「TraceView War Story」

http://android-developers.blogspot.com/2010/10/traceview-war-story.html

面白かったので要約してみた。

途中でダレてきたので、訳間違ってるかもしれない。そのときはごめんなさいw



Making Apps Fast

私は、最も経験豊富な開発者と情報共有しているという信念を持っている:
どんなアプリであっても、たとえそれほど複雑でないアプリでも、遅くしている部分がどこなのか予測できるほど我々は賢くない。なぜなら、誰もソフトウェアのボトルネックが変わることを十分予測できないからである。

そのため、速いアプリを作る賢い方法は、そのアプリが動作できる最も単純な方法でビルドすることである。N乗のアルゴリズムなんていう言語道断な愚かな方法や、I/O を Android UI スレッドで行うなどは避けるべきだ。これで十分速いかもしれない。それならそれでおしまい!

もし、それでも速くないなら、なぜなのかを推測してはいけない。プロファイラを使って測って見つける。こうすべきだと言うことを知っていたので、窮地に追いつめられると System.err.println("Entered at" + System.currentTimeMillis()); とかを使っていた。幸いなことに、Android には合理的でまともなプロファイラが付属しているので、こんな醜い方法で取得する必要はない。


Case Study: LifeSaver 2

私は LifeSaver 2 という utility アプリを Android Market に出している。アプリの詳細については私の個人ブログをみてほしい。このアプリはシステムの SMS と phone-call ログを読んで、SD card 内に JSON text ファイルで保存するというものだ。これには少し時間がかかるので、動的なプログレスバーを表示している。しかし、ギガヘルツプロセッサを載せたデバイス上で、数百のレコードをテキストファイルに書き込むだけなのに、どうして時間がかかるのか不思議に思った。

愚かにも上記の私の忠告を聞かなかった人は、システムログの読み込みをする ContentProvider のカーソル処理の失敗や、SD card への書き込みオーバーヘッドが遅くなる原因だと仮定するかもしれない。賢い人ならコードを測って原因を見つけるだろう。ではやってみよう。


Turning On Tracing

Saver.java に以下のコードを入れた


public void run() {

android.os.Debug.startMethodTracing("lsd");

// ... method body elided

android.os.Debug.stopMethodTracing();
}


最初の呼び出しでトレースをオンにする。引数の "lsd" (stands for Life Saver Debug, of course) はトレースログの出力先ファイル名である(/sdcard/lsd.trace に保存される)。WRITE_EXTERNAL_STORAGE permission を AndroidManifest.xml に書くのを忘れずに!そして、必要なくなったら公開する前に削除するのを忘れずに。


[Update:] Android engineer Xavier Ducrohet が教えてくれた: “DDMS には 'device view' 内にプロファイリングの start/stop ボタンがある。stop が押されるまで、TraceView が実行される。詳細な start/stopMethodTracing には向いてないが極めて使いやすい。froyo より前の VM では、パーミッションが必要になる(DDMS は基本的に自動で SD card から trace を取得して traceview が呼ばれる前にローカルに保存する)。 Froyo 以降の VM では、trace file を JDWP connection を通して送ることができるので、もはやパーミッションは必要ない(これは本当に使いやすい)" Thanks, Xav!


アプリの実行が終わったら、デバイスからトレースログを取り出して、traceview コマンドで表示する。


540> adb pull /sdcard/lsd.trace
541> traceview lsd


ここでのポイントは、1. アプリで実際に遅くなっている部分のみトレースをオンにすること。2. トレースファイルは大きい(この場合では 4秒とるのに 8.6M)。 3. traceview の見た目はとっても Cool!



上部のバーはアプリのスレッドを示しており、タイムアウト処理にどの程度のかかるのかがわかる。Nexus One はシングルスレッド CPU なので順番に実行されなければならない。もう一段小さい縮尺にしてみよう。



トップラインは私のアプリでコードが走っている部分(赤い領域は GC が起こっている)で、ミドルラインは UI スレッドを表している。UI thread で Activity が バーストしているところは、プログレスバーの更新が起こっているところだ。3番目の HeapWoker という名前のスレッドはよくわからないが、アプリのランタイムへの寄与は大きくなさそうなので無視しよう。

スクリーンの下部には、本当に重要なデータがある:どのメソッドが時間を消費しているかを示しており、さまざまな異なる方法でソートすることができる。最初の2行をみてみよう。



この結果を翻訳すると、(あれとか、これとか)呼ばれるものすべてが含まれているなら、 top-level routine が 100% の時間を消費しているということを教えてくれている。次の行から本物っぽく面白くなってきた: java.io.PrintStream.println(Object) が何回も呼ばれていて、アプリ全体の 65.25% も使っている。これは、SD card に JSON を書きだしているコードだ。明らかに、電話の ContentProviders からデータを取り出して書きだす処理が、重すぎる処理ではないことが分かる。; it’s the output that’s hurting.

このアプリは SD card への書き込みパフォーマンスが低迷していることで制限されていると結論づけられるだろうか? 想像できる最も明白な point-and-click 手法でもう少し掘り下げてみよう。



うーん。厄介な驚きはない。もちろん、 println は(効果として) 全ての引数に toString() を呼び出している。引数を strings に変換している処理は、時間の半分以上を占めているように見える。それが
、println(Object) から println(String) へディスパッチする前であっても。

println(String) をさらに掘り下げるステップはスキップしよう。しかし、SD card への遅い I/O が起こっているということが示された。今度は String.valueOf() 呼び出しの中をみてみよう。



証拠があった。が、org.json.JSONObject.toString() は我々プロのプログラマーがよく呼び、なれ親しんでいる操作なので、私はここをいじりたくない。いじることは出来るが厄介なことになるだけだ。

我々にできることは、全てのルーチンを "Exclusive" time (ルーチン内で実行されたCPUサイクル数)でソートすることだ。これは、全実行時間の 1% 以上を使っているの一覧だ。



ここには、少しの GC と Android frameword View-wrangling stuff がある。しかし、org.jason と java.lang.StringBuilder コードによってリストが占められている。


The Conclusion

このアプリの場合、実際の結論は、、、確かに私はあまりパフォーマンスを気にしていない。ユーザーは古い電話と新しい電話で1回ずつ合わせて2回実行するが、目を休めるもの(アニメーションとか)がたくさんあるので、問題があるとは思わない。

もし、これをスピードアップしたかったら、やるべきことは明らかだ。最初に、JSON を使うのを止めるかもっとチープなシリアライズ方法を見つける。 2つ目に、println() の呼び出しを減らす; データを一つの大きなバッファにまとめて、単一の I/O 呼び出しでどばっと書き出す。しかし、ここでのキーポイントは、もし私がボトルネックを予測していたら、間違っていただろうということだ。

TraceView は素晴らしいツールで、もしまだ知らないなら自分自身のために学ぶべきだ。

0 件のコメント:

コメントを投稿