マルチスレッド下におけるログ出力性能測定
一つのJavaプログラムについて、処理をマルチスレッドで並行性を持つように記述し、複数CPU（マルチコア）上でそのプログラムを実行することにより並列処理を実現しようとした際、ログ出力が実行性能にどれだけ影響を及ぼすのかを把握したい、と考えています。
プログラムの開発（特にデバッグ）においては、ログが使えないと苦労します。ただし、ログを埋め込むと、性能に影響を及ぼします。また、ログレベルを抑制し、実際にはログ出力がなかったとしても、ログレベルの判定処理が動くことで、多少の影響はあります。
最近のログ出力ライブラリはスレッドセーフに作られていますが、それは内部で排他区間を持つことになるので、並列処理においては排他による性能への影響は無視できません。
そこで、同一プロセス内でマルチスレッドにより並行実行するプログラムを作成・実行し、複数スレッドからログを出力すると、実行性能にどれだけ影響を及ぼすかを調査してみました。
プログラムは、CPUバウンドが主となるものとして「エラトステネスのふるい」を作成し、それをマルチスレッドで複数同時に開始し、各スレッドでの処理が完了するまでの時間を測定します。並行数は1つのとき、CPU（コア）数から1を引いた数のときを計ります。次に、処理の中で繰り返し実行される箇所にログ出力呼び出しを埋め、ログレベルを制御して実際にログを吐くとき、吐かないときの実行時間を測定します。
測定条件
| 項目 | 内容 | 備考 |
|---|---|---|
| 計算機 | AMD Phenom II X6 1055T | 2.8GHz |
| OS | Windows 7 64bit | |
| JavaVM | Java 6 Up24 HotSpot Client VM | build 1.9.1-b02 |
| 計測手段 | System.nanoTime() | |
| log4jバージョン | 1.2.16 | |
| slf4jバージョン | 1.6.1 | |
| logbackバージョン | 0.9.28 | |
| 素数検索範囲 | 〜10万 | |
| ログ呼び出し回数 | 10万+素数発見個数 |
測定結果
並行数が5のときの測定値は、各スレッドでの素数判定処理に要した時間を平均した値です。
Java標準ロギングAPI（java.util.logging)
| 並行数 | ログコードなし | ログレベルを出力抑制 | ファイル出力(1) | ファイル出力(2) |
|---|---|---|---|---|
| 1 | 16.681ms | 18.930ms | 4401.680ms | 4654.211ms |
| 5 | 19.991ms | 24.832ms | 16747.193ms | 19248.895ms |
- ファイル出力は、(1)FileHandler、(2)FileHandlerでローテーションあり（100MB）
slf4j & logback
| 並行数 | ログコードなし | ログレベルを出力抑制 | ファイル出力(1) | ファイル出力(2) |
|---|---|---|---|---|
| 1 | 19.221ms | 21.188ms | 1022.111ms | 6239.505ms |
| 5 | 20.005ms | 24.414ms | 8802.492ms | 38424.939ms |
- ファイル出力は、(1)FileAppender、(2)RollingFileAppender
log4j
| 並行数 | ログコードなし | ログレベルを出力抑制 | ファイル出力(1) | ファイル出力(2) | ファイル出力(3) |
|---|---|---|---|---|---|
| 1 | 17.118ms | 38.703ms | 4952.577ms | 5190.590ms | 40.658ms |
| 5 | 18.776ms | 64.124ms | 38251.261ms | 42264.759ms | 12776.841ms |
- ファイル出力は、(1)FileAppender、(2)RollingFileAppender、(3)AsyncAppender経由FileAppender
検討
並行数が1つのとき、ログ呼び出しコードがないときとログ呼び出しを追加（レベルは抑制）したときを比べると、Java標準ロギング、logbackともに2ミリ秒程度の負荷ですが、log4jについては20ミリ秒の負荷となっていました。
これは、ログAPIの設計の違いによるもので、ログ呼び出しメソッドの引数指定において、Java標準およびlogback(slf4j)では文字列と変数の結合は行っていませんが、log4jでは行っているからと思われます。
java.util.loggingのログメソッドは以下のように記述できます。メッセージ文字列と数値データをそのまま渡しています。
LOGGER.log(Level.FINEST, "found prime {0}", i);
一方、log4jの場合、以下のようにログメソッドの引数に数値から文字列化および文字列結合結果を渡す必要があります。
LOGGER.trace("found prime " + i);
なお、log4jのFAQには性能を気にするならif文をかませて、ログレベルが抑制される場合、文字列処理を回避するとありますが、ログメソッドを呼ぶ場所で以下のように書くのは、手間もあるし、何より主要機能ではないログ処理にコードが占められ、煩雑（可読性劣化）になります。
if (LOGGER.isTraceEnabled()) { LOGGER.trace("checked number " + number); }
次に、並行数が5のとき、同じくログ呼び出しコードがないときとログ呼び出しコードを追加（レベルは抑制）したときを比べると、Java標準ロギング、logbackともに4-5ミリ秒程度の負荷ですが、log4jについては45ミリ秒の負荷となっていました。
並行数１のときに比べていずれもログ出力を追加したことによるオーバーヘッドが増えていますが、log4jについては顕著に増えています。log4jはスレッドセーフであるとFAQにはありましたが、マルチスレッド下での性能はいまいちのようです。
なお、log4jはSLF4Jと組み合わせることができます。この場合、SLF4JのAPIでは前述のように文字列結合を遅延しているので、log4j単独よりも性能向上が期待できます。
サンプルコード
エラトステネスのふるいを実装するクラス
public class Eratosthenes { private static final Logger LOGGER = Logger.getLogger(Eratosthenes.class.getName()); /** * エラトステネスのふるい。 * @param max 素数を探す整数範囲の最大値。2以上Integer.MAX_VALUE以下。 * @return 素数のリスト（昇順） */ public static List<Integer> sieve(int max) { BitSet numberBits = new BitSet(max + 1); numberBits.set(2, max + 1); int number = 2; do { for (int i = number * 2; i <= max; i += number) { numberBits.clear(i); } LOGGER.log(Level.FINEST, "checked number {0}", number); } while (++number < max); List<Integer> primes = new ArrayList<Integer>(); for (int i = 0; i <= max; i++) { if (numberBits.get(i)) { primes.add(i); LOGGER.log(Level.FINEST, "found prime {0}", i); } } return primes; } }
マルチスレッドで呼び出すメインクラス（抜粋）
private static void launch(int numThread) { ExecutorService executor = Executors.newFixedThreadPool(numThread); Collection<Callable<Integer>> tasks = new ArrayList<Callable<Integer>>(); for (int i = 0; i < numThread; i++) { tasks.add(new Callable<Integer>() { @Override public Integer call() throws Exception { long start = System.nanoTime(); List<Integer> results = Eratosthenes.sieve(100000); long stop = System.nanoTime(); return (int) TimeUnit.NANOSECONDS.toMicros(stop - start); } }); } List<Future<Integer>> futures = null; try { futures = executor.invokeAll(tasks); executor.shutdown(); } catch (InterruptedException ex) { Logger.getLogger(RunWithJul.class.getName()).log(Level.SEVERE, "割り込み例外発生", ex); return; } for (Future<Integer> future : futures) { try { int takes = future.get(); Logger.getLogger("").log(Level.INFO, "It takes {0} [us]", takes); } catch (InterruptedException ex) { Logger.getLogger(RunWithJul.class.getName()).log(Level.SEVERE, "割り込み例外発生", ex); Thread.currentThread().interrupt(); } catch (ExecutionException ex) { Logger.getLogger(RunWithJul.class.getName()).log(Level.SEVERE, "タスク実行中に例外発生", ex); } } }
