---
title: Yahoo! JAPANのデータパイプラインで起きた障害とチューニング - Apache Kafka Meetup Japan #5 -
tags: 
author: [Yahoo!デベロッパーネットワーク](https://www.docswell.com/user/ydnjp)
site: [Docswell](https://www.docswell.com/)
thumbnail: https://bcdn.docswell.com/page/MLELQG3VJR.jpg?width=480
description: Apache Kafka Meetup Japan #5 ( https://kafka-apache-jp.connpass.com/event/104465/ ) での発表資料です。
published: December 19, 18
canonical: https://www.docswell.com/s/ydnjp/KWNEYK-2018-12-19-134157
---
# Page. 1

![Page Image](https://bcdn.docswell.com/page/MLELQG3VJR.jpg)

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


# Page. 2

![Page Image](https://bcdn.docswell.com/page/54JM1QDN7W.jpg)

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


# Page. 3

![Page Image](https://bcdn.docswell.com/page/ZPJRL844J9.jpg)

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


# Page. 4

![Page Image](https://bcdn.docswell.com/page/NPEXW82ZJX.jpg)

はじめに
ヤフーは多種多様なサービスを抱え、
多数のユーザ様に利用していただいている
デイリーユニークブラウザ数(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


# Page. 5

![Page Image](https://bcdn.docswell.com/page/63EKVKMVJD.jpg)

はじめに
ヤフーは多種多様なサービスを抱え、
例：複数のサービスからユーザの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


# Page. 6

![Page Image](https://bcdn.docswell.com/page/4L73MZ2QE5.jpg)

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


# Page. 7

![Page Image](https://bcdn.docswell.com/page/V87D6RZWJG.jpg)

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


# Page. 8

![Page Image](https://bcdn.docswell.com/page/4VJPYWDXJ8.jpg)

発生状況
複数存在するクラスタのうち一部だけ
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


# Page. 9

![Page Image](https://bcdn.docswell.com/page/L2EVG813EQ.jpg)

原因調査
各種設定の調査
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


# Page. 10

![Page Image](https://bcdn.docswell.com/page/Z57G852Y7L.jpg)

原因調査
各種設定の調査
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


# Page. 11

![Page Image](https://bcdn.docswell.com/page/V4EQ9ZP6EP.jpg)

答えは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


# Page. 12

![Page Image](https://bcdn.docswell.com/page/DKJ4X3YMJ1.jpg)

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


# Page. 13

![Page Image](https://bcdn.docswell.com/page/PLE1N16YJG.jpg)

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


# Page. 14

![Page Image](https://bcdn.docswell.com/page/8GEW48W172.jpg)

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


# Page. 15

![Page Image](https://bcdn.docswell.com/page/W47Z285XE3.jpg)

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


# Page. 16

![Page Image](https://bcdn.docswell.com/page/KYJ6VP9P7V.jpg)

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


# Page. 17

![Page Image](https://bcdn.docswell.com/page/5GJ5DKNPJ4.jpg)

原因調査
・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 &quot; &quot; -f 1`| wc -l
# kafka.logs.dir 配下のファイル数
$ ls –l $KAFKA_LOGS_DIR | wc –l
25000
#プロセスが掴んでいるファイル数
$ sudo lsof -p `sudo jps |grep Kafka|cut -d &quot; &quot; -f 1`| wc -l
5700
100000
通常のクラスタ
中身を確認
$ sudo lsof -p `sudo jps |grep Kafka|cut -d &quot; &quot; -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


# Page. 18

![Page Image](https://bcdn.docswell.com/page/4LE3MZ26J5.jpg)

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


# Page. 19

![Page Image](https://bcdn.docswell.com/page/V8ED6RZM7G.jpg)

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


# Page. 20

![Page Image](https://bcdn.docswell.com/page/4V7PYWDQ78.jpg)

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


# Page. 21

![Page Image](https://bcdn.docswell.com/page/L2JVG81PJQ.jpg)

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-&gt;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


# Page. 22

![Page Image](https://bcdn.docswell.com/page/Z5EG852QEL.jpg)

なぜ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


# Page. 23

![Page Image](https://bcdn.docswell.com/page/V4JQ9ZPWJP.jpg)

なぜ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


# Page. 24

![Page Image](https://bcdn.docswell.com/page/DK74X3Y171.jpg)

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


# Page. 25

![Page Image](https://bcdn.docswell.com/page/PLJ1N1657G.jpg)

参考
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


# Page. 26

![Page Image](https://bcdn.docswell.com/page/8GJW48WWE2.jpg)

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


