Proguard を利用してリリース apk からログ出力をストリップする方法 & ベンチマークをとってみた

はじめに

皆さんは Android アプリにログ出力をどの程度仕込んでいるでしょうか。
適切にログ出力が施されたアプリは、問題追跡がしやすいですし、あの糞重いデバッガを起動しなくて済む事が多いです。

個人的には、verbose or debug レベルでは、ふんだんにログ出力を仕込みたいと考えていますが、あまりログを仕込みたがらない人がいるのも事実です。
ログ出力普及委員会(会員1名)の市場調査結果では、その理由として大きく下記の2つがある様でした。

標準の Android Log の仕様上、リリースされた apk でもログがすべて参照できてしまう = 気軽に内部データのログ出力を書けない
ログ出力によるパフォーマンスの低下の懸念

これらの問題へのソリューションとしてはいくつか方法がありますが、この記事では proguard を利用した下記の方法を検証してみました。

ログが見えてしまう → proguard の設定で、リリース apk ではログ出力のメソッドコール自体を消す
パフォーマンス低下の懸念 → 上記の様なバイトコードレベルでのメソッド除去を行えば、理論的にはログ出力がパフォーマンスに与える影響はないはず。これをベンチマークを測定し検証してみる。

つまり、これらをはっきりさせ、みんなにログをもっと書いてもらおうというのがこの記事の主旨です。

検証コード

検証用のコードとして下記の様なものを準備しました。
処理内容は、テキストビューに 10000 回のログ出力にかかった時間を出力するだけのものです。

LogBenchmark.java

public class LogBenchmarkActivity extends Activity {

    private static final String TAG = LogBenchmarkActivity.class.getSimpleName();
    private static final String LINE_SEPARATOR = System.getProperty("line.separator");

    @Override
    public void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.main);

        for (int i=0; i<10; i++) {
            performBenchmark();
        }
    }

    protected void performBenchmark() {
        TextView empty = (TextView) findViewById(R.id.empty);
        TextView standard = (TextView) findViewById(R.id.normal);
        TextView wrapper = (TextView) findViewById(R.id.wrapper);

        // パフォーマンス測定用 基準値
        long s0 = System.currentTimeMillis();
        for (int i=0; i<10000; i++) {
            // 空のループ
        }
        long e0 = System.currentTimeMillis();
        empty.setText(empty.getText() + LINE_SEPARATOR + (e0 - s0 + " ms"));

        // Android 標準の Log クラスを使用
        long s1 = System.currentTimeMillis();
        for (int i=0; i<10000; i++) {
            Log.d(TAG, "i: " + i);
        }
        long e1 = System.currentTimeMillis();
        standard.setText(standard.getText() + LINE_SEPARATOR + (e1 - s1 + " ms"));

        // 独自の Logger クラスを利用 ※詳細は後述
        long s2 = System.currentTimeMillis();
        for (int i=0; i<10000; i++) {
            Logger.d(TAG, "i: %s", i);
        }
        long e2 = System.currentTimeMillis();
        wrapper.setText(wrapper.getText() + LINE_SEPARATOR + (e2 - s2 + " ms"));
    }

}

次に、proguard の設定で、各 Log クラスのメソッド呼び出しをすべて除去します。
※-assumenosideeffects は、「返値が利用されていないと判断できる」という意味です。

proguard.cfg

# 標準で設定されるものは省略

# strip logging
-assumenosideeffects class android.util.Log {
    <methods>;
}

-assumenosideeffects class me.tlync.android.example.Logger {
    <methods>;
}

上記のソースコードと設定では、Android 標準の Log クラスの他に、自作の Logger クラスを定義、それに対する設定を追加しています。

これは、ログストリップ時の更なるパフォーマンス向上(と利便性)の為に定義しているもので、標準の Log クラスを使った事がある方はご存知の通り、引数に可変長引数や配列を取る様になっていない為、上記コードの様な Log.d(TAG, "i: " + i) が呼ばれた時点で、第2引数の文字列構築が発生し、このコストがログストリップを施したリリース apk 上でも残ってしまいます。
その為、対策として、メソッドコールの時点で文字列構築が行われない様に、下記の様な可変長引数を用いたラッパー関数を定義しています。

public static int d(String tag, String format, Object... args) {
    return Log.d(tag, format(format, args));
}

プロジェクトのソースコードと、Logger の実装例は下記の URL を参照してください。

Project … https://github.com/tlync/android-sandbox/tree/master/LogBenchmark
Logger … https://gist.github.com/1868304

Logger に関しては、独自のものでなく SL4J for android などを使うのもありです。

検証結果

1. ログストリップが出来ているか

ログが見えてしまう事が問題でしたが、上記の proguard の設定を施した apk では想定通りログ出力されていません。

念の為、バイトコードも確認してみましたが、ちゃんとバイトコードレベルで消えてます。

$ diff -u bin/proguard/nonstripped-dump.txt bin/proguard/stripped-dump.txt
--- bin/proguard/nonstripped-dump.txt	2012-02-22 14:36:46.000000000 +0900
+++ bin/proguard/stripped-dump.txt	2012-02-22 14:37:58.000000000 +0900

@@ -31,12 +27,10 @@
   - Fieldref [me/tlync/android/example/LogBenchmarkActivity.b Ljava/lang/String;]
   - Methodref [android/app/Activity.<init> ()V]
   - Methodref [android/app/Activity.onCreate (Landroid/os/Bundle;)V]
-  - Methodref [android/util/Log.d (Ljava/lang/String;Ljava/lang/String;)I] # ちゃんと消せてる

# 略

         - Fieldref [me/tlync/android/example/LogBenchmarkActivity.a Ljava/lang/String;]
         - Class [java/lang/StringBuilder]
         - String [i: ]
         - Methodref [java/lang/StringBuilder.<init> (Ljava/lang/String;)V]
         - Methodref [java/lang/StringBuilder.append (I)Ljava/lang/StringBuilder;]
-      [127] invokevirtual #35
-        - Methodref [java/lang/StringBuilder.toString ()Ljava/lang/String;]
-      [130] invokestatic #23
-        - Methodref [android/util/Log.d (Ljava/lang/String;Ljava/lang/String;)I]  # ちゃんと消せてる
-      [133] pop

# 略

         - Methodref [java/lang/System.currentTimeMillis ()J]
-      [148] lstore v11

2. パフォーマンスに影響はないか

ではパフォーマンスはどうだったでしょうか。
いずれも Proguard をかけた release apk での結果です。

ログストリップ設定なし

ログストリップ設定あり

結果としては、

設定なし … String#format を実行コストが高い為、wrapper 版のログ出力が、標準の Log 出力より遅い
設定あり … 結果が逆転し、文字列構築のコストが浮いた分 wrapper 版のログ出力の方が早い

となっています。

概ね予想通りですが、理論上は wrapper 版は empty 版(空ループ)と同じになるはずなので、若干腑に落ちません。
そこでバイトコードを見てみると、犯人が見つかりました。

        - Fieldref [me/tlync/android/example/LogBenchmarkActivity.a Ljava/lang/String;]
      [201] pop
      [202] iload v15
      [204] invokestatic #22
        - Methodref [java/lang/Integer.valueOf (I)Ljava/lang/Integer;] # Autoboxing!!!!!
      [207] pop
      [208] iinc v15, 1
      [211] iload v15
      [213] sipush 10000
      [216] ificmplt -18 (target=198)
      [219] invokestatic #30
        - Methodref [java/lang/System.currentTimeMillis ()J]

そう、オートボクシングの存在をすっかり忘れてました。

試しにオートボクシングが発生しない様にすると、empty と同様の 1ms などをマークする様になりました。
proguard の設定を詰めれば Integer#valueOf などのコールすらも除去できますが、影響範囲も大きい為、現段階では許容しています。

結果として、パフォーマンス的にも proguard を利用した方法だと、実行速度に殆ど影響がない事が分かりました。
標準のロガーか、可変長引数でラップするロガーを使用するかに関しては、正直そこまで差は無い為、パフォーマンス要件と好みに応じて使い分ければいいと思います。

まとめ

proguard を使えば、ログ出力のメソッドコールそのものを消せるので、内部データも安心して出力でき、パフォーマンス的にも安心

リリース apk でも全部ストリップするのが問題であれば、verbose だけストリップするというのもありでしょう。
いずれにせよ、これで安心してログが書けますね。