torutkのブログ読者になるtorutkのブログソフトウェア・エンジニアのブログ2011-04-15マルチスレッド下におけるログ出力性能測定Java一つのJavaプログラムについて、処理をマルチスレッドで並行性を持つように記述し、複数CPU(マルチコア)上でそのプログラムを実行することにより並列処理を実現しようとした際、ログ出力が実行性能にどれだけ影響を及ぼすのかを把握したい、と考えています。プログラムの開発(特にデバッグ)においては、ログが使えないと苦労します。ログを埋め込むと、性能に影響を及ぼします。ログレベルを抑制し、実際にはログ出力がなかったとしても、ログレベルの判定処理が動くことで、多少の影響はあります。最近のログ出力ライブラリはスレッドセーフに作られていますが、それは内部で排他区間を持つことになるので、並列処理においては排他による性能への影響は無視できません。そこで、同一プロセス内でマルチスレッドにより並行実行するプログラムを作成・実行し、複数スレッドからログを出力すると、実行性能にどれだけ影響を及ぼすかを調査してみました。プログラムは、CPUバウンドが主となるものとして「エラトステネスのふるい」を作成し、それをマルチスレッドで複数同時に開始し、各スレッドでの処理が完了するまでの時間を測定します。並行数は1つのとき、CPU(コア)数から1を引いた数のときを計ります。5のときの測定値は、各スレッドでの素数判定処理に要した時間を平均した値です。12776.841msファイル出力は、(1)FileAppender、(2)RollingFileAppender、(3)AsyncAppender経由FileAppender注記1ここでファイル出力時の処理時間も記載していますが、ファイル出力はI/Oバウンドが主であり、マルチスレッド性能とは別要因が支配的となるため、あくまで参考です。ログローテーションは実施していません。並行数が1つのとき、ログ呼び出しコードがないときとログ呼び出しを追加(レベルは抑制)したときを比べると、Java標準ロギング、logbackともに2ミリ秒程度の負荷ですが、log4jについては20ミリ秒の負荷となっていました。これは、ログAPIの設計の違いによるもので、ログ呼び出しメソッドの引数指定において、Java標準およびlogback(slf4j)では文字列と変数の結合は行っていませんが、log4jでは行っているからと思われます。java.util.loggingのログメソッドは以下のように記述できます。メッセージ文字列と数値データをそのまま渡しています。i);一方、log4jの場合、以下のようにログメソッドの引数に数値から文字列化および文字列結合結果を渡す必要があります。i);なお、log4jのFAQには性能を気にするならif文をかませて、ログレベルが抑制される場合、文字列処理を回避するとありますが、ログメソッドを呼ぶ場所で以下のように書くのは、手間もあるし、何より主要機能ではないログ処理にコードが占められ、煩雑(可読性劣化)になります。}次に、並行数が5のとき、同じくログ呼び出しコードがないときとログ呼び出しコードを追加(レベルは抑制)したときを比べると、Java標準ロギング、logbackともに4-5ミリ秒程度の負荷ですが、log4jについては45ミリ秒の負荷となっていました。並行数1のときに比べていずれもログ出力を追加したことによるオーバーヘッドが増えていますが、log4jについては顕著に増えています。log4jはスレッドセーフであるとFAQにはありましたが、マルチスレッド下での性能はいまいちのようです。log4jはSLF4Jと組み合わせることができます。この場合、SLF4JのAPIでは前述のように文字列結合を遅延しているので、log4j単独よりも性能向上が期待できます。エラトステネスのふるい。素数を探す整数範囲の最大値。2以上Integer.MAX_VALUE以下。9はてなブログをはじめよう!torutkさんは、はてなブログを使っています。ブログを報告する引用をストックしましたストック一覧を見る閉じる引用するにはまずログインしてくださいログイン閉じる引用をストックできませんでした。再度お試しください閉じる限定公開記事のため引用できません。