処理時間測定方法(android.util.TimingLogger)

例えば、アプリ内のボトルネック調査するとき、
重そうな処理にアタリつけて処理時間測定しますよね。
ベタにやるとこんな感じ。

// 測定開始
long start = System.currentTimeMillis();

// 測定したい処理

// 測定終了
long end = System.currentTimeMillis();
Log.d(getClass().getName(), "measure: " + (end - start));

何かないかなーと思って公式javadoc見てたら
便利そうなクラスを発見。

android.util.TimingLogger

使い方はざっくりこんな感じ。

• コンストラクタ(測定開始)
  • // 処理1
  • addSplit(処理1 の処理時間測定)
  • // 処理2
  • addSplit(処理2 の処理時間測定)
  • ・・・
• dumpToLog(測定終了＋ログ出力)

テストコード書いてみた。

private void testTimingLogger() {
    // 測定開始
    TimingLogger logger = new TimingLogger("TAG_TEST", "testTimingLogger");

    // 処理1

    logger.addSplit("abeshi");

    // 処理2

    logger.addSplit("hidebu");

    // 測定終了＋ログ出力
    logger.dumpToLog();
}

さっそく実行してみる。
が、ログが出ない。

javadoc見ると、TimingLogger のコンストラクタにこう書いてある。

Create and initialize a TimingLogger object that will log using the specific tag.
If the Log.isLoggable is not enabled to at least the Log.VERBOSE level 
for that tag at creation time then the addSplit and dumpToLog call will do nothing.

参考までにこんな記事も。
stackoverflow - Time code execution in Android

ログ出力レベルを「VERBOSE」にしないと何も出力しないだそうです。

というわけで、ログレベルを「VERBOSE」に変更してみる。
上記ソースの場合、ログレベル変更はこんな感じになりますね。

$ adb shell
# setprop log.tag.TAG_TEST VERBOSE

アプリ実行。

DEBUG/TAG_TEST(940): testTimingLogger: begin
DEBUG/TAG_TEST(940): testTimingLogger:      6 ms, abeshi
DEBUG/TAG_TEST(940): testTimingLogger:      17 ms, hidebu
DEBUG/TAG_TEST(940): testTimingLogger: end, 23 ms

ログ出た。これは便利。