Yahoo! JAPANのデータパイプラインで起きた障害とチューニング - Apache Kafka Meetup Japan #5 -

Yahoo! JAPANのデータパイプラインで 起きた障害とチューニング 2018年12月18日 ヤフー株式会社 データ＆サイエンスソリューション統括本部 データプラットフォーム本部データデリバリー部パイプライン Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 橘 拓馬

自己紹介 橘 拓馬 2018年度新卒 • 8月からパイプラインチームに 配属され、Apache Kafkaを扱い始める IoT周りが好き Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 2

目次 1. はじめに 2. チューニングの実例 1. Request Handler が重い 2. 長時間連続運転すると突然プロセスダウン 3. まとめ Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 3

はじめに ヤフーは多種多様なサービスを抱え、 多数のユーザ様に利用していただいている デイリーユニークブラウザ数(FY17) 運営サービス数 100超 9053万ブラウザ 平均 アプリ合算デイリーアクティブユーザ数(FY17) 4249万人 平均 より良いサービスを提供するために、 各サービスから生み出される大量のデータを横断的に活用できるよう 分析基盤に集約するシステムとしてApache Kafkaを活用 Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. ※各種指標はhttps://about.yahoo.co.jp/ir/jp/archives/data/より引用 4

• https://about.yahoo.co.jp/ir/jp/archives/data/

はじめに ヤフーは多種多様なサービスを抱え、 例：複数のサービスからユーザのWeb行動ログを収集、 多数のユーザ様に利用していただいている 最もユーザが興味の持ちそうな関連コンテンツをレコメンド デイリーユニークブラウザ数(FY17) デイリーユニークブラウザ数(FY17) 平均9053万ブラウザ あなたへの サービスA 運営サービス数 オススメ 平均 ブラウザ 超 サービスB アプリ合算デイリーアクティブユーザ数(FY17) 100 9053万 (FY17) サービスC アプリ合算デイリーアクティブユーザ数 平均4249万人 … 行動を分析 平均 4249万人 より良いサービスを提供するために、 各サービスから生み出される大量のデータを横断的に活用できるよう 分析基盤に集約するシステムとしてApache Kafkaを活用 Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. ※各種指標はhttps://about.yahoo.co.jp/ir/jp/archives/data/より引用 5

• https://about.yahoo.co.jp/ir/jp/archives/data/

そのままでは理想通りに動いてくれない パフォーマンスや安定性の問題が複数発生 • Request Handlerが重い • 長時間連続運転すると突然プロセスがダウン Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 6

Request Handler が重い Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved.

発生状況 複数存在するクラスタのうち一部だけ Request Handler のIdle%が低い 多くのクラスタでのIdle%は90%以上 R/W Idle% 30%を割るクラスタが発生 Produce Request FetchConsumer Request … Request Handler Kafka Broker Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. File System (一部省略) 8

原因調査 各種設定の調査 Idle%が高いクラスタと低いクラスタの設定の違いを確認 • Kafka Broker • OS • JVM • ネットワーク →大きくパフォーマンスに影響する設定の違いはない Brokerに記録されたoffset情報を見てみると offset: 42847546267 … offset: 42847546279 … offset: 42847546291 … 通常のクラスタ +12 offset: 23400841903 … offset: 23400841904 … offset: 23400841905 … 問題のクラスタ offsetの刻み幅がクラスタで異なる Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. +1 9

原因調査 各種設定の調査 Idle%が高いクラスタと低いクラスタの設定の違いを確認 • Kafka Broker • OS • JVM • ネットワーク →大きくパフォーマンスに影響する設定の違いはない Brokerに記録されたoffset情報を見てみると offset: 42847546267 … offset: 23400841903 … +12 全クラスタのProducerで +1 offset: 42847546279 … offset: 23400841904 … offset: 42847546291 producer.properties … offset: 23400841905 … の batch.size の値は同一 通常のクラスタ 問題のクラスタ offsetの刻み幅がクラスタで異なる Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 10

答えはProducerに Producer１台あたりの req/sec＜ Partition数という構成が原因 Producerは全てのPartitionに メッセージを振り分け Partitioner Produce Request … … Message Request Handlerが 高負荷に linger.ms以内に Batch Producer Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 溜まるバッチの大きさが1 Broker 11

パラメータ調整/構成変更で対処？ Producerの数を減らせば良い？ • ビジネス要件で不可能 • サービスのサーバ群が高可用性とパフォーマンスの両立を求めているため、 サーバ台数 (= Producerの台数) が非常に多い。 • Producer1台あたりの req/secは少なく、台数が多い構成を変更できない Partitionを減らせばいい？ • Kafkaの機能制約 • Partitionを減らすオペレーションはKafkaでは簡単にできない linger.msを長くすればいい？ • ビジネス要件で不可能 • レイテンシが大きくなり、転送のリアルタイム性が犠牲になる Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 12

Keyed Messageの導入で解決 ProducerごとにKeyを設定 Producer１台あたりのreq/secが少ないのにも関わらずPartition数が多い → １台のProducerからのメッセージは全て同じPartitionにProduceされるように ProducerごとにKeyの値を固定 … Keyed Message … Keyed Message Partitioner Partition Producer Broker linger.ms以内に溜まるBatchSizeを大きくできる！→ 解決 Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 13

長時間運用時の プロセスダウン Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved.

発生状況 使用したFile Descriptor をKafka Brokerが 掴み続け、解放されないクラスタが存在 問題のクラスタ （解放できず増加しつづける） 通常のクラスタ （逐次解放しているため低位安定） →掴み続けたまま放置（数ヶ月）すると File Descriptorの上限に当たりプロセスダウン Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 15

原因調査 ・Kafka Brokerのkafka.logs.dir 配下ファイル数 をそれぞれ比較 ・Kafka Brokerが掴んでいるファイル数 問題のクラスタ # kafka.logs.dir 配下のファイル数 $ ls –l $KAFKA_LOGS_DIR | wc –l 5500 #プロセスが掴んでいるファイル数 $ sudo lsof -p `sudo jps |grep Kafka|cut -d " " -f 1`| wc -l # kafka.logs.dir 配下のファイル数 $ ls –l $KAFKA_LOGS_DIR | wc –l 25000 #プロセスが掴んでいるファイル数 $ sudo lsof -p `sudo jps |grep Kafka|cut -d " " -f 1`| wc -l 5700 100000 通常のクラスタ 通常のクラスタに比べ、lsとlsofの差分が大きい Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 16

原因調査 ・Kafka Brokerのkafka.logs.dir 配下ファイル数 をそれぞれ比較 ・Kafka Brokerが掴んでいるファイル数 問題のクラスタ # kafka.logs.dir 配下のファイル数 $ ls –l $KAFKA_LOGS_DIR | wc –l 5500 #プロセスが掴んでいるファイル数 $ sudo lsof -p `sudo jps |grep Kafka|cut -d " " -f 1`| wc -l # kafka.logs.dir 配下のファイル数 $ ls –l $KAFKA_LOGS_DIR | wc –l 25000 #プロセスが掴んでいるファイル数 $ sudo lsof -p `sudo jps |grep Kafka|cut -d " " -f 1`| wc -l 5700 100000 通常のクラスタ 中身を確認 $ sudo lsof -p `sudo jps |grep Kafka|cut -d " " -f 1` java 6184 kafka … ….timeindex.deleted (deleted) java 6184 kafka … ….index.deleted (deleted) java 6184 kafka … ….timeindex.deleted (deleted) … JVMのGCで解放されるはずのFile Descriptor(FD)を保持し続けている Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 17

KafkaのLog RetentionとFile Descriptorの関係 • KafkaはLogファイルを定期的にRetentionする FD ….index Open … … FD Open ….index.deleted JVM Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. File System 18

KafkaのLog RetentionとFile Descriptorの関係 • KafkaはLogファイルを定期的にRetentionする • LinuxのFile SystemはRetention後存在しなくなったLogファイルに `(deleted)`とマーキング FD … … FD Open (Openしていた) ….index.deleted (deleted) JVM Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. File System 19

KafkaのLog RetentionとFile Descriptorの関係 • KafkaはLogファイルを定期的にRetentionする • LinuxのFile SystemはRetention後存在しなくなったLogファイルに `(deleted)`とマーキング • マーキングされたファイルを参照するFDは、 GC(Young GC / Mixed GC / etc.)の際に解放される FD Open JVM Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. … … FD GC時に解放 File System 20

GCはどれだけ起きている？ GCのログを確認 通常のクラスタ : $ cat kafkaServer-gc.log XX:XX:XX XX:XX:XX XX:XX:XX XX:XX:XX XX:XX:XX XX:XX:XX XX:XX:XX Mixed GC の発生ログ : [GC concurrent-root-region-scan-start] : [GC concurrent-root-region-scan-end, 0.0607977 secs] : [GC concurrent-mark-start] : [GC concurrent-mark-end, 0.0638311 secs] : [GC remark 2018-06-22T03:25:15.973+0900: 46088.225: [Finalize Marking, 0.0123461 secs] : [GC cleanup 12G->12G(32G), 0.0169348 secs] : [GC pause (G1 Evacuation Pause) (mixed), 0.0065863 secs] 問題のクラスタ : Mixed GC が発生していなかった deleted ファイルの解放をするにはMixed GCが必要と推測 Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 21

なぜGCの頻度が違うのか？ クラスタごとのreq/secの違いが原因 req/secの多いクラスタでは Kafka Brokerで確保するオブジェクトの数や容量も多くなる Young GCの実行頻度が多い $ cat kafkaServer-gc.log | grep young … 17:08:55.853 … [GC pause (G1 Evacuation Pause) (young), … 17:08:57.611 … [GC pause (G1 Evacuation Pause) (young), … 数秒おき 17:08:59.396 … [GC pause (G1 Evacuation Pause) (young), … 17:09:01.185 … [GC pause (G1 Evacuation Pause) (young), … 17:09:03.005 … [GC pause (GCLocker Initiated GC) (young), … Old領域内の使用容量が Mixed GC発生閾値まで上昇しやすい Mixed GC発生 Old領域使用量 Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 22

なぜGCの頻度が違うのか？ クラスタごとのreq/secの違いが原因 問題のクラスタは、req/secが少なく Kafka Brokerで確保するオブジェクトの数や容量も少ない Young GCの実行頻度が少ない $ cat kafkaServer-gc.log | grep young … 16:49:46.896 … [GC pause (G1 Evacuation Pause) (young), … 16:51:35.529 … [GC pause (GCLocker Initiated GC) (young), … 数「分」おき 16:53:23.188 … [GC pause (G1 Evacuation Pause) (young), … 16:55:11.849 … [GC pause (G1 Evacuation Pause) (young), … 16:56:59.696 … [GC pause (G1 Evacuation Pause) (young), … Old領域内の使用容量が Mixed GC発生閾値まで上昇しない Old領域使用量 Mixed GCが発生する前にFDの数が上限に達する Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 23

JVMのGCを起こさせることで解決 GCが発生するよう設定変更 問題のクラスタでJVM起動オプション `-XX:InitiatingHeapOccupancyPercent`の値を変更する（小さくする） ことでGCを発生しやすくするように変更 Mixed GC発生 問題のクラスタが掴んでいるFile Descriptorの解放に成功 → 解決 Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 24

参考 Kafka本体で先行してGCに関する問題が指摘 KafkaのGCに長時間を要する問題(修正済み) (https://issues.apache.org/jira/browse/KAFKA-4614) 上記issueでは forceUnmap() を実行することで 参照先がなくなったら強制的に解放して解決 →結果としてFDも強制的に解放されるように チームではissue適用前のKafkaを一部で運用しているため GCの閾値チューニングで解放を実行 Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 25

まとめ • メッセージの流量や性質に起因するパフォーマンス低下も 存在するため、日頃から設定や構成だけではなく 「どのようにデータを流しているか」も 確認しておくことが重要 • アプリケーションレベルだけでは原因が見つからない場合も あるため、JVM,OSやネットワークなど多くのレイヤの 知識や経験を活用することが解決への近道 Copyright (C) 2018 Yahoo Japan Corporation. All Rights Reserved. 26