LogbackからLog4j 2への移行によるアプリケーションのスループット改善 ( JJUG CCC 2021 Fall )

ULS
Copyright © 2011-2021 UL Systems, Inc. All rights reserved.
Proprietary & Confidential
LogbackからLog4j 2への移行による
アプリケーションのスループット改善

ULS
Proprietary & Confidential 1
アジェンダ
1.自己紹介
2.LogbackからLog4j 2へ変更した際のQPS
3.Log4j 2のloggerの特徴
4.アプリケーションでのベンチマーク結果
5.Log4j 2の注意事項
6.まとめ

ULS 2
自己紹介

ULS
磯田浩靖
- 所属：ウルシステムズ株式会社
- 連絡先：hironobu.isoda@ulsystems.co.jp
- twitter：hiroisojp
- Javaエンジニア、認定スクラムマスタ
自己紹介

ULS 4
LogbackからLog4j 2へ変更した際のQPS

ULS
LogbackからLog4j 2へ変更した際のQPS
Logback
Log4j 2
同じアプリケーションコードでロギングライブラリを変更した際のQPSが
20%程度向上した
QPS = Queries Per Second、1秒間で処理できる件数

ULS
Log4j 2はLogbackとアーキテクチャが異なる
- Log4j 2 はロックフリーのデータ構造
- 内部でLMAX Disruptorというライブラリを用い、Ring Bufferを使ったデータ構造
- Logback はロック競合あり
- ArrayBlockingQueue
この違いによりQPSに差が出たのではないかと思われる
なぜQPSが向上したか
https://www.slideshare.net/Stephan.Schmidt/lmax-architecture-jax-conference

ULS
マルチスレッドであるほどロックフリーの恩恵が大きい
（参考）公式サイトのベンチマーク
https://logging.apache.org/log4j/2.x/performance.html
Logback
Log4j 2

ULS 8
Log4j 2のloggerの特徴

ULS
Log4j2のloggerはsync/asyncがあり以下の組み合わせで設定できる
all loggers asyncが最もパフォーマンスがよい
利用する場合はJVMパラメータを指定する
- log4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
all loggers async
種類設定方法
sync log4j2.xmlにLoggerとして指定
<Logger name="foo.Bar" level="info"></Logger>
async log4j2.xmlにAsyncLoggerとして指定
<AsyncLogger name="foo.Baz" level="trace"></AsyncLogger>
mixed
sync/async
log4j2.xmlにLogger, AsyncLoggerをそれぞれ指定
all loggers
async
log4j2.xmlにLoggerとして指定＋以下のJVMオプションを指定
-
Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.As
yncLoggerContextSelector
all loggers asyncが
最もパフォーマンスがよい

ULS
Log4j 2（2.6以降）ではガベージフリーなロギングが可能
ログ出力におけるGCが発生しにくい
ガベージフリーロギング
メモリ割り当て
が発生
メモリ割り当て
がほとんどない
2.5 2.6
https://logging.apache.org/log4j/2.x/manual/garbagefree.html

ULS 11
アプリケーションでのベンチマーク結果

ULS
Log4j 2利用によるベンチマーク確認
all loggers async
QPSが向上
するか
GC傾向が
変化するか
Log4j 2の特徴がアプリケーションにも寄与するかをベンチマークにて確認

ULS
オンライン広告入札を行うアプリケーション
- 秒間40万件のリクエストを処理（1台あたりは5k〜7k程度）
- 3〜5ms以内のレスポンス
リクエストごとに分析基盤で用いるログを出力している
アプリケーション概要

ULS
- 処理数
- 秒間5k〜7k
- 1行あたりのサイズ
- 1.6kb
- ファイルサイズ
- 1GB（1分間）
- アプリケーションスレッド数
- 84（CPUコア数 * 3）
アプリケーション概要（ログ周辺）

ULS
<appender name="ASYNC_FOO_LOG"
class="ch.qos.logback.classic.AsyncAppender">
<appender-ref ref="FOO_LOG" />
<queueSize>20000</queueSize>
<discardingThreshold>0</discardingThreshold>
</appender>
<appender name="FOO_LOG"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>foo.tsv</file>
<rollingPolicy
class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>foo.%d{yyyy-MM-dd.HH-mm}.tsv
</fileNamePattern>
</rollingPolicy>
<encoder>
<pattern>
<![CDATA[%d{yyyy-MM-dd HH:mm:ss.SSS z}¥t%msg%n]]>
</pattern>
</encoder>
</appender>
Log4j 2、Logbackの設定概要
いずれもAsync Loggerにてログ出力処理を行う
Logback
Log4j 2
<RollingFile name="FOO_LOG" fileName="foo" filePattern="foo.%d{yyyy-
MM-dd.HH-mm}.tsv">
<PatternLayout>
<Pattern>
<![CDATA[%d{yyyy-MM-dd HH:mm:ss.SSS z}¥t%msg%n]]>
</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy />
</Policies>
</RollingFile>
logback.xml
log4j2.xml
(all loggers asyncを使う設定)
-
Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLogger
ContextSelector
-DAsyncLogger.WaitStrategy=busyspin
-DAsyncLogger.SynchronizeEnqueueWhenQueueFull=false
JVMオプション

ULS
Log4j 2、Logbackを利用した時のQPS
Logback
Log4j 2
QPS = Queries Per Second、1秒間で処理できる件数
Log4j 2 = 約6,000QPS
Logback = 約5,000QPS
ロギングライブラリの変更により20%程度の向上がみられた

ULS
負荷をかけている内の1時間、JFRを取得しFlameGraphで確認
Log4j 2ではログ出力処理に関する部分が高速化された
JFR（FlameGraph）
Logback
Log4j 2 幅が短いほうが、ある時間内の
処理時間の割合が低い＝速い処理
Log4j 2より幅が広い
= 処理に時間がかかっている

ULS
ログ出力処理のみにフォーカスすると
LogbackではArrayBlockingQueue以降に時間を消費している
JFR（FlameGraph）
Logback
Log4j 2

ULS
10-20ms帯ではややLog4j 2の方がGCが短い傾向がみられた
GC傾向
Logback
Log4j 2
Logbackより短いGC
の割合が増えている

ULS
Log4j 2利用によるベンチマーク結果
all loggers async
QPSが向上
するか
GC傾向が
変化するか
QPSは向上し、GC傾向も10-20ms帯でやや短くなる割合が増えた
Logback時よりもQPSは向上した
10-20ms帯で改善が少しみられた

ULS 21
Log4j 2の注意事項

ULS
WaitStrategy、SynchronizeEnqueueWhenQueueFullの設定によっても
FlameGraphの結果はかなり変わるのでアプリケーションにあった組み合わ
せを探索する
WaitStrategyの種類
- timeout（デフォルト）
- block
- sleep
- yield
- busyspin
SynchronizeEnqueueWhenQueueFull
- true/false
all loggers asyncに関する注意事項
https://logging.apache.org/log4j/2.x/manual/async.html

ULS
WaitStrategy、SynchronizeEnqueueWhenQueueFullの組み合わせによる
FlameGraphの例
all loggers asyncに関する注意事項
JVMパラメータ FlameGraph（赤枠内はlog4j 2の処理部分）
AsyncLogger.WaitStrategy=busyspin
AsyncLogger.SynchronizeEnqueueWhenQueueFull=false
AsyncLogger.WaitStrategy=timeout
AsyncLogger.WaitStrategy=busyspin
AsyncLogger.SynchronizeEnqueueWhenQueueFull=true

ULS
Webアプリケーション（javax.servlet.Servletがクラスパスに存在する）の
場合、デフォルトは低ガベージモードとなる
（log4j2.enable.threadlocalsがfalseに設定される）
ガベージフリーに関する注意事項
https://logging.apache.org/log4j/2.x/manual/garbagefree.html
JVMパラメータモード
log4j2.enable.threadlocals=true
log4j2.enable.direct.encoders=true
ガベージフリー
log4j2.enable.threadlocals=false
log4j2.enable.direct.encoders=true
低ガベージ
log4j2.enable.threadlocals=false
log4j2.enable.direct.encoders=false
クラシック

ULS
ログ出力時に%d（日付）などPatternを指定し値を変換することができる
このうち位置情報を含むPatternを用いるとパフォーマンスが大きく落ちる
Patternに関する注意事項
Pattern 出力例
%C or %class foo.Bar
%F or %file Bar.java
%l or %location foo.Bar.exec(Bar.java:123)
%L or %line 123
%M or %method exec
位置情報を含むPattern
Asyncのときにも
パフォーマンス影響
が大きい
https://logging.apache.org/log4j/2.x/performance.html#asyncLoggingWithLocation

ULS
ほぼそのまま移行できたため、大きな問題はなかった
アプリケーションで利用していた範囲ではif conditionのみ影響があった
（設定ファイル自体を分けて対応）
<if condition='property("type").contains("staging")'>
<then>
(ステージング環境用の設定)
</then>
<else>
(本番環境用の設定)
</else>
</if>
Log4j 2では左記のLogbackの
ように条件分岐できない
（参考）ログ設定ファイルの移行
logback.xml

ULS 27
まとめ

ULS
- アプリケーションのQPSが向上 & GCも多少改善した
- Logbackからロギングライブラリの置き換えを試して見る価値あり
- 何度か計測して同じ傾向であったことは確認済
- Log4j 2 Async, ガベージフリーの恩恵は設定や環境制約がある
- WaitStrategyのチューニングをする
- ガベージフリーはWebアプリケーションではデフォルトは低ガベージモードとなる
ので、ガベージフリーモードが利用できるかをチェック
- ログ出力時のPatternに位置情報を含めないようにする
まとめ

ULS

LogbackからLog4j 2への移行によるアプリケーションのスループット改善 ( JJUG CCC 2021 Fall )

More Related Content

LogbackからLog4j 2への移行によるアプリケーションのスループット改善 ( JJUG CCC 2021 Fall )