操作
調査 #164
未完了log4j2の設定による性能の差異を把握する
開始日:
2020/07/25
期日:
進捗率:
80%
予定工数:
説明
調査目的¶
log4j 2.xのAppender、ログ出力設定（Pattern）により性能がどれだけ変わるのか凡その把握をする。
調査結果¶
シングルスレッドのアプリケーション（JavaFXアプリケーション）で繰り返し処理（1万回強）の中にログ出力を埋め込み、処理時間の比較でログの負荷を評価した。
| No. | 概要 | 時間[ms] | 備考 |
|---|---|---|---|
| 1 | 同期ログ出力 | 906 | |
| 2 | 同期ログ出力（動的コンテキスト取得） | 2213 | |
| 3 | 非同期ログ出力 | 653 | |
| 4 | 非同期ログ出力（動的コンテキスト取得） | 1857 |
- 動的コンテキスト取得は、ファイル名、行番号、メソッド名の取得
実行環境¶
| OS | Windows 10 1909 64bit 日本語版 |
| CPU | AMD PhenomⅡ 1050T |
| JDK | Liberica JDK 14 Full |
| log4j | 2.13.3 |
| disruptor | 3.4.2 |
完了条件¶
- 標準の同期ロガーと非同期ロガー（LMAX disruptorを内部で使用）との性能差が把握できた
- Pattern に動的な要素（ログを実行したメソッド名等）を入れた場合の性能劣化が把握できた
高橋 徹 さんが3年以上前に更新
- ステータス を 新規 から 進行中 に変更
- 進捗率 を 0 から 50 に変更
シングルスレッド下での多量のログ出力に要する時間を把握する調査¶
JavaFXでグラフ描画をする次のアプリケーションにおいてドメインデータからXYラインデータを生成する処理にログ出力文を埋め込み、JavaFXアプリケーションスレッド（シングルスレッド）上でおよそ1万強のログ出力に要する時間を測定した。
SpectrumFileViewerアプリケーション
- ケース0 ログレベルで出力抑制時
- ケース1 FileAppenderに、日時、レベル、ロガー名、スレッド名、メッセージを出力時
- ケース2 FileAppenderに、ケース1に加えてファイル名、行番号、メソッド名を出力時
- ケース3 ケース1のログ出力を非同期（LMAX Disruptor使用）にしたもの
- ケース4 ケース2のログ出力を非同期（LMAX Disruptor使用）にしたもの
| ケース | アペンダー | パターン | 所要時間[ms] | 備考 |
|---|---|---|---|---|
| ケース0 | ー | ー | 149 | ログ出力レベル抑制 |
| ケース1 | FileAppender | %d %p %c{1.} [%t] %m%n |
906 | |
| ケース2 | FileAppender | %d %p %c{1.} %F:%L (%M) [%t] %m%n |
2213 |
高橋 徹 さんが3年以上前に更新
log4j で非同期ロガーを使用する方法を調査した。
クラスパスにLMAX disruptorライブラリを配置し、次のいずれかの設定を行う。
- システムプロパティ
log4j2.contextSelectorに、次の値を設定org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
全てのロガーが非同期として扱われる - ログ設定ファイルで、
AsyncLoggerや、AsyncRootを指定
Asyncタイプのロガーを指定した所が非同期として扱われる
LMAX disrupterライブラリはmodule-info.classを含まないのでモジュール対応していない。
モジュールパスでロードされるlog4j2 から disruptor が適用できないもよう。
高橋 徹 さんが3年以上前に更新
モジュールパスとクラスパスの混在では、非同期ロガーが構成できない模様。
よって、全てをクラスパスとして実行した。
| ケース | アペンダー | パターン | 所要時間[ms] | 備考 |
|---|---|---|---|---|
| ケース3 | FileAppender | %d %p %c{1.} [%t] %m%n |
653 | |
| ケース4 | FileAppender | %d %p %c{1.} %F:%L (%M) [%t] %m%n |
1857 |
- 注1 ケース4で、非同期ロガーにてファイル名、行番号、メソッド名を動的に取る際は設定ファイルで対象ロガーに属性includeLocation="true"を指定する。（親ロガーには指定不要）
非同期ロガーが有効かどうかの判定方法は、log4jの内部ログ出力をTRACEレベルに設定し、例えば以下のログが出ていることを確認します。
DEBUG LoggerContext[name=AsyncContext@6d06d69c, org.apache.logging.log4j.core.async.AsyncLoggerContext@747a34a1] started OK.
操作