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

JJUG CCC 2021 Fall の発表資料です。
（SlideShareより移行）

Transcript

1. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential LogbackからLog4j 2への移行による アプリケーションのスループット改善
2. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 1 アジェンダ 1.自己紹介 2.LogbackからLog4j 2へ変更した際のQPS 3.Log4j 2のloggerの特徴 4.アプリケーションでのベンチマーク結果 5.Log4j 2の注意事項 6.まとめ
3. ULS 2 Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 自己紹介
4. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 3 磯田 浩靖 - 所属：ウルシステムズ株式会社 - 連絡先：hironobu.isoda@ulsystems.co.jp - twitter：hiroisojp - Javaエンジニア、認定スクラムマスタ 自己紹介
5. ULS 4 Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential LogbackからLog4j 2へ変更した際のQPS
6. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 5 LogbackからLog4j 2へ変更した際のQPS Logback Log4j 2 同じアプリケーションコードでロギングライブラリを変更した際のQPSが 20%程度向上した QPS = Queries Per Second、1秒間で処理できる件数
7. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 6 Log4j 2はLogbackとアーキテクチャが異なる - Log4j 2 はロックフリーのデータ構造 - 内部でLMAX Disruptorというライブラリを用い、Ring Bufferを使ったデータ構造 - Logback はロック競合あり - ArrayBlockingQueue この違いによりQPSに差が出たのではないかと思われる なぜQPSが向上したか https://www.slideshare.net/Stephan.Schmidt/lmax-architecture-jax-conference
8. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 7 マルチスレッドであるほどロックフリーの恩恵が大きい （参考）公式サイトのベンチマーク https://logging.apache.org/log4j/2.x/performance.html Logback Log4j 2
9. ULS 8 Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential Log4j 2のloggerの特徴
10. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 9 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が 最もパフォーマンスがよい
11. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 10 Log4j 2（2.6以降）ではガベージフリーなロギングが可能 ログ出力におけるGCが発生しにくい ガベージフリーロギング メモリ割り当て が発生 メモリ割り当て がほとんどない 2.5 2.6 https://logging.apache.org/log4j/2.x/manual/garbagefree.html
12. ULS 11 Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential アプリケーションでのベンチマーク結果
13. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 12 Log4j 2利用によるベンチマーク確認 ガベージフリーロギング all loggers async QPSが向上 するか GC傾向が 変化するか Log4j 2の特徴がアプリケーションにも寄与するかをベンチマークにて確認
14. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 13 オンライン広告入札を行うアプリケーション - 秒間40万件のリクエストを処理（1台あたりは5k〜7k程度） - 3〜5ms以内のレスポンス リクエストごとに分析基盤で用いるログを出力している アプリケーション概要
15. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 14 - 処理数 - 秒間5k〜7k - 1行あたりのサイズ - 1.6kb - ファイルサイズ - 1GB（1分間） - アプリケーションスレッド数 - 84（CPUコア数 * 3） アプリケーション概要（ログ周辺）
16. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 15 <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オプション
17. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 16 Log4j 2、Logbackを利用した時のQPS Logback Log4j 2 QPS = Queries Per Second、1秒間で処理できる件数 Log4j 2 = 約6,000QPS Logback = 約5,000QPS ロギングライブラリの変更により20%程度の向上がみられた
18. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 17 負荷をかけている内の1時間、JFRを取得しFlameGraphで確認 Log4j 2ではログ出力処理に関する部分が高速化された JFR（FlameGraph） Logback Log4j 2 幅が短いほうが、ある時間内の 処理時間の割合が低い＝速い処理 Log4j 2より幅が広い = 処理に時間がかかっている
19. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 18 ログ出力処理のみにフォーカスすると LogbackではArrayBlockingQueue以降に時間を消費している JFR（FlameGraph） Logback Log4j 2
20. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 19 10-20ms帯ではややLog4j 2の方がGCが短い傾向がみられた GC傾向 Logback Log4j 2 Logbackより短いGC の割合が増えている
21. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 20 Log4j 2利用によるベンチマーク結果 ガベージフリーロギング all loggers async QPSが向上 するか GC傾向が 変化するか QPSは向上し、GC傾向も10-20ms帯でやや短くなる割合が増えた Logback時よりもQPSは向上した 10-20ms帯で改善が少しみられた
22. ULS 21 Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential Log4j 2の注意事項
23. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 22 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
24. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 23 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
25. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 24 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 クラシック
26. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 25 ログ出力時に%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
27. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 26 ほぼそのまま移行できたため、大きな問題はなかった アプリケーションで利用していた範囲ではif conditionのみ影響があった （設定ファイル自体を分けて対応） <if condition='property("type").contains("staging")'> <then> (ステージング環境用の設定) </then> <else> (本番環境用の設定) </else> </if> Log4j 2では左記のLogbackの ように条件分岐できない （参考）ログ設定ファイルの移行 logback.xml
28. ULS 27 Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential まとめ
29. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 28 - アプリケーションのQPSが向上 & GCも多少改善した - Logbackからロギングライブラリの置き換えを試して見る価値あり - 何度か計測して同じ傾向であったことは確認済 - Log4j 2 Async, ガベージフリーの恩恵は設定や環境制約がある - WaitStrategyのチューニングをする - ガベージフリーはWebアプリケーションではデフォルトは低ガベージモードとなる ので、ガベージフリーモードが利用できるかをチェック - ログ出力時のPatternに位置情報を含めないようにする まとめ
30. ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 29