Upgrade to Pro
— share decks privately, control downloads, hide ads and more …
Speaker Deck
Features
Speaker Deck
PRO
Sign in
Sign up for free
Search
Search
LogbackからLog4j 2への移行によるアプリケーションのスループット改善 ( JJUG...
Search
hiroisojp
November 21, 2021
Programming
0
55
LogbackからLog4j 2への移行によるアプリケーションのスループット改善 ( JJUG CCC 2021 Fall )
JJUG CCC 2021 Fall の発表資料です。
(SlideShareより移行)
hiroisojp
November 21, 2021
Tweet
Share
More Decks by hiroisojp
See All by hiroisojp
Foreign Function & Memory API ( FFM API )を用いたNativeライブラリ呼び出しと既存ライブラリの比較 ( JJUG CCC 2023 Fall )
hiroisojp
1
700
JVMパラメータチューニングにおけるOptunaの活用事例 ( Optuna Meetup #1 )
hiroisojp
0
8
オンライン広告入札システムとZGC ( JJUG CCC 2021 Spring )
hiroisojp
0
15
200,000 Req/sec をさばく広告入札システムを支えるパフォーマンスチューニング術 #jjug_ccc #ccc_g6
hiroisojp
0
6
Logicadの秒間16万リクエストをさばく広告入札システムにおける、gRPCの活用事例 ( JJUG CCC 2018 Spring )
hiroisojp
0
6
Other Decks in Programming
See All in Programming
The Future of Frontend i18n : Intl.MessageFormat
sajikix
1
2.4k
デザインシステムとコンポーネント指向によるフロントエンド開発プロセスの革新 / Innovation in Frontend Development Processes through Design Systems and Component-Oriented Architecture
nrslib
7
5k
Boost Your Performance and Developer Productivity with Jakarta EE 11
ivargrimstad
1
930
座談会 「Strict ConcurrencyとSwift 6が開く新時代: 私たちはどう生きるか?」
shiz
4
2.9k
メモリ最適化を究める!iOSアプリ開発における5つの重要なポイント
yhirakawa333
0
370
私のEbitengineの第一歩
qt_luigi
0
410
ECMAScript、Web標準の型はどう管理されているか / How ECMAScript and Web standards types are maintained
petamoriken
3
370
ECMAScript仕様を読むのに必要な知識 - ダイジェスト版
syumai
4
2.5k
ゲームボーイアドバンスでSwiftを動かそう
k_koheyi
0
510
LangChainの現在とv0.3にむけて
os1ma
3
650
数値を文字列に整形する際の落とし穴とその解決策(iOSDC2024 ルーキーズLT) / iOSDC Japan 2024 Formatting Floating-Point Numbers
glassfiber
0
250
初めてのiOS関連GitHub ActionsをMarketplaceに公開するまでの実録
konifar
3
200
Featured
See All Featured
Writing Fast Ruby
sferik
623
60k
Visualizing Your Data: Incorporating Mongo into Loggly Infrastructure
mongodb
38
9.1k
Imperfection Machines: The Place of Print at Facebook
scottboms
263
13k
How to name files
jennybc
75
97k
Creatively Recalculating Your Daily Design Routine
revolveconf
215
12k
Documentation Writing (for coders)
carmenintech
65
4.3k
Responsive Adventures: Dirty Tricks From The Dark Corners of Front-End
smashingmag
248
20k
Web development in the modern age
philhawksworth
204
10k
Happy Clients
brianwarren
96
6.6k
Raft: Consensus for Rubyists
vanstee
135
6.5k
Stop Working from a Prison Cell
hatefulcrawdad
266
20k
Art, The Web, and Tiny UX
lynnandtonic
294
20k
Transcript
ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved.
Proprietary & Confidential LogbackからLog4j 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.まとめ
ULS 2 Copyright © 2011-2021 UL Systems, Inc. All rights
reserved. Proprietary & Confidential 自己紹介
ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved.
Proprietary & Confidential 3 磯田 浩靖 - 所属:ウルシステムズ株式会社 - 連絡先:
[email protected]
- twitter:hiroisojp - Javaエンジニア、認定スクラムマスタ 自己紹介
ULS 4 Copyright © 2011-2021 UL Systems, Inc. All rights
reserved. Proprietary & Confidential LogbackからLog4j 2へ変更した際のQPS
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秒間で処理できる件数
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
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
ULS 8 Copyright © 2011-2021 UL Systems, Inc. All rights
reserved. Proprietary & Confidential Log4j 2のloggerの特徴
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が 最もパフォーマンスがよい
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
ULS 11 Copyright © 2011-2021 UL Systems, Inc. All rights
reserved. Proprietary & Confidential アプリケーションでのベンチマーク結果
ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved.
Proprietary & Confidential 12 Log4j 2利用によるベンチマーク確認 ガベージフリーロギング all loggers async QPSが向上 するか GC傾向が 変化するか Log4j 2の特徴がアプリケーションにも寄与するかをベンチマークにて確認
ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved.
Proprietary & Confidential 13 オンライン広告入札を行うアプリケーション - 秒間40万件のリクエストを処理(1台あたりは5k〜7k程度) - 3〜5ms以内のレスポンス リクエストごとに分析基盤で用いるログを出力している アプリケーション概要
ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved.
Proprietary & Confidential 14 - 処理数 - 秒間5k〜7k - 1行あたりのサイズ - 1.6kb - ファイルサイズ - 1GB(1分間) - アプリケーションスレッド数 - 84(CPUコア数 * 3) アプリケーション概要(ログ周辺)
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オプション
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%程度の向上がみられた
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より幅が広い = 処理に時間がかかっている
ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved.
Proprietary & Confidential 18 ログ出力処理のみにフォーカスすると LogbackではArrayBlockingQueue以降に時間を消費している JFR(FlameGraph) Logback Log4j 2
ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved.
Proprietary & Confidential 19 10-20ms帯ではややLog4j 2の方がGCが短い傾向がみられた GC傾向 Logback Log4j 2 Logbackより短いGC の割合が増えている
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帯で改善が少しみられた
ULS 21 Copyright © 2011-2021 UL Systems, Inc. All rights
reserved. Proprietary & Confidential Log4j 2の注意事項
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
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
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 クラシック
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
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
ULS 27 Copyright © 2011-2021 UL Systems, Inc. All rights
reserved. Proprietary & Confidential まとめ
ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved.
Proprietary & Confidential 28 - アプリケーションのQPSが向上 & GCも多少改善した - Logbackからロギングライブラリの置き換えを試して見る価値あり - 何度か計測して同じ傾向であったことは確認済 - Log4j 2 Async, ガベージフリーの恩恵は設定や環境制約がある - WaitStrategyのチューニングをする - ガベージフリーはWebアプリケーションではデフォルトは低ガベージモードとなる ので、ガベージフリーモードが利用できるかをチェック - ログ出力時のPatternに位置情報を含めないようにする まとめ
ULS Copyright © 2011-2021 UL Systems, Inc. All rights reserved.
Proprietary & Confidential 29