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

Slide 1

Slide 1 text

Slide 2

Slide 2 text

Slide 3

Slide 3 text

Slide 4

Slide 4 text

Slide 5

Slide 5 text

Slide 6

Slide 6 text

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秒間で処理できる件数

Slide 7

Slide 7 text

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

Slide 8

Slide 8 text

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

Slide 9

Slide 9 text

Slide 10

Slide 10 text

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として指定 async log4j2.xmlに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が最もパフォーマンスがよい

Slide 11

Slide 11 text

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

Slide 12

Slide 12 text

Slide 13

Slide 13 text

ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 12 Log4j 2利用によるベンチマーク確認ガベージフリーロギング all loggers async QPSが向上するか GC傾向が変化するか Log4j 2の特徴がアプリケーションにも寄与するかをベンチマークにて確認

Slide 14

Slide 14 text

Slide 15

Slide 15 text

Slide 16

Slide 16 text

ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 15 20000 0 foo.tsv foo.%d{yyyy-MM-dd.HH-mm}.tsv Log4j 2、Logbackの設定概要いずれもAsync Loggerにてログ出力処理を行う Logback Log4j 2 logback.xml log4j2.xml (all loggers asyncを使う設定) - Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLogger ContextSelector -DAsyncLogger.WaitStrategy=busyspin -DAsyncLogger.SynchronizeEnqueueWhenQueueFull=false JVMオプション

Slide 17

Slide 17 text

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%程度の向上がみられた

Slide 18

Slide 18 text

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より幅が広い = 処理に時間がかかっている

Slide 19

Slide 19 text

Slide 20

Slide 20 text

Slide 21

Slide 21 text

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帯で改善が少しみられた

Slide 22

Slide 22 text

Slide 23

Slide 23 text

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

Slide 24

Slide 24 text

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

Slide 25

Slide 25 text

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 クラシック

Slide 26

Slide 26 text

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

Slide 27

Slide 27 text

ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved. Proprietary & Confidential 26 ほぼそのまま移行できたため、大きな問題はなかったアプリケーションで利用していた範囲ではif conditionのみ影響があった（設定ファイル自体を分けて対応） (ステージング環境用の設定) (本番環境用の設定) Log4j 2では左記のLogbackのように条件分岐できない（参考）ログ設定ファイルの移行 logback.xml

Slide 28

Slide 28 text

Slide 29

Slide 29 text

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