kafka進程crash-OOM原因分析及解決

1. 現象

由于種種原因，kafka進程宕機了一段時間（比如可能是被人為kill了）玫镐。然后在某個時間點嘗試啟動kafka的時候倒戏，發(fā)現啟動失敗，進程起不起來恐似，查看日志杜跷，發(fā)現日志報錯OOM，類似如下

[2018-11-27 13:54:58,726] INFO Recovering unflushed segment 0 in log dcs_async_scr_info-4. (kafka.log.Log)
[2018-11-27 13:54:58,727] INFO Completed load of log dcs_async_scr_info-4 with log end offset 0 (kafka.log.Log)
[2018-11-27 13:54:58,731] INFO Recovering unflushed segment 92049 in log dcs_async_dev_sid_info-6. (kafka.log.Log)
[2018-11-27 13:54:58,737] INFO Completed load of log dcs_async_dev_sid_info-6 with log end offset 92146 (kafka.log.Log)
...skipping...
[2018-11-27 13:54:59,450] INFO Recovering unflushed segment 0 in log dcs_storm_collect_info-3. (kafka.log.Log)
[2018-11-27 13:54:59,552] ERROR There was an error in one of the threads during logs loading: java.io.IOException: Map failed (kafka.log.LogManager)
[2018-11-27 13:54:59,554] FATAL [Kafka Server 0], Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer)
java.io.IOException: Map failed
        at sun.nio.ch.FileChannelImpl.map(FileChannelImpl.java:919)
        at kafka.log.OffsetIndex$$anonfun$resize$1.apply(OffsetIndex.scala:286)
        at kafka.log.OffsetIndex$$anonfun$resize$1.apply(OffsetIndex.scala:276)
        at kafka.utils.Utils$.inLock(Utils.scala:535)
        at kafka.log.OffsetIndex.resize(OffsetIndex.scala:276)
        at kafka.log.LogSegment.recover(LogSegment.scala:170)
        at kafka.log.Log.recoverLog(Log.scala:205)
        at kafka.log.Log.loadSegments(Log.scala:177)
        at kafka.log.Log.<init>(Log.scala:67)
        at kafka.log.LogManager$$anonfun$loadLogs$2$$anonfun$3$$anonfun$apply$7$$anonfun$apply$1.apply$mcV$sp(LogManager.scala:142)
        at kafka.utils.Utils$$anon$1.run(Utils.scala:54)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.OutOfMemoryError: Map failed
        at sun.nio.ch.FileChannelImpl.map0(Native Method)
        at sun.nio.ch.FileChannelImpl.map(FileChannelImpl.java:916)
        ... 15 more
[2018-11-27 13:54:59,556] INFO [Kafka Server 0], shutting down (kafka.server.KafkaServer)

2. 資源監(jiān)控

因為日志報錯是說內存溢出矫夷，因此啟動過程中啟動過程中抓取進程的資源消耗消息葛闷，發(fā)現如下

2.1 查看內存狀態(tài)

因為報錯OOM，因此首先抓取了內存狀態(tài)

             total       used       free     shared    buffers     cached
Mem:          7761       5794       1966         16        150       3048
-/+ buffers/cache:       2595       5165
Swap:            0          0          0

整個過程中抓了好幾次双藕，每次結果都可以看出淑趾，可用內存還是很充足的

2.2 查看內存映射文件

kafka會將所有的分區(qū)數據片段的index文件做mmap，以加速文件讀寫忧陪。另我們知道m(xù)ap是有大小限制的扣泊，因此抓取map數量驳概，看看是否超過map控制。

抓取結果：

2055 7f1549679000-7f154a079000 rw-s 00000000 fd:01 1704740                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/__consumer_offsets-2/00000000000000000000.index
2056 7f154a079000-7f154aa79000 rw-s 00000000 fd:01 1704740                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/__consumer_offsets-2/00000000000000000000.index
2057 7f154aa79000-7f154b479000 rw-s 00000000 fd:01 1704740                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/__consumer_offsets-2/00000000000000000000.index
2058 7f154b479000-7f154be79000 rw-s 00000000 fd:01 1704505                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_storm_collect_info-14/00000000000000000000.index
2059 7f154be79000-7f154c879000 rw-s 00000000 fd:01 1704505                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_storm_collect_info-14/00000000000000000000.index
2060 7f154c879000-7f154d279000 rw-s 00000000 fd:01 1704505                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_storm_collect_info-14/00000000000000000000.index
2061 7f154d279000-7f154dc79000 rw-s 00000000 fd:01 1704840                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/__consumer_offsets-47/00000000000000000000.index
2062 7f154dd2b000-7f154e72b000 rw-s 00000000 fd:01 1704840                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/__consumer_offsets-47/00000000000000000000.index
2063 7f154e72b000-7f154f12b000 rw-s 00000000 fd:01 1704840                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/__consumer_offsets-47/00000000000000000000.index
2064 7f154f12b000-7f154fb2b000 rw-s 00000000 fd:01 1704530                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_storm_collect_info_gray-6/00000000000000000000.index
2065 7f154fb2b000-7f155052b000 rw-s 00000000 fd:01 1704530                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_storm_collect_info_gray-6/00000000000000000000.index
2066 7f15505d9000-7f1550fd9000 rw-s 00000000 fd:01 1704530                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_storm_collect_info_gray-6/00000000000000000000.index
2067 7f1550fd9000-7f15519d9000 rw-s 00000000 fd:01 1704852                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/__consumer_offsets-28/00000000000000000000.index
2068 7f15519d9000-7f15523d9000 rw-s 00000000 fd:01 1704852                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/__consumer_offsets-28/00000000000000000000.index
2069 7f15523d9000-7f1552dd9000 rw-s 00000000 fd:01 1704852                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/__consumer_offsets-28/00000000000000000000.index
2070 7f1552dd9000-7f15537d9000 rw-s 00000000 fd:01 1704783                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/__consumer_offsets-15/00000000000000000000.index
2071 7f15537d9000-7f15541d9000 rw-s 00000000 fd:01 1704783                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/__consumer_offsets-15/00000000000000000000.index
2072 7f15541d9000-7f1554bd9000 rw-s 00000000 fd:01 1704783                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/__consumer_offsets-15/00000000000000000000.index
2073 7f1554bd9000-7f15555d9000 rw-s 00000000 fd:01 1704990                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_dev_info_batch_del-7/00000000000000057329.index
2074 7f15555d9000-7f15555da000 rw-s 00000000 fd:01 1704990                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_dev_info_batch_del-7/00000000000000057329.index
2075 7f15555da000-7f1555fda000 rw-s 00000000 fd:01 1704990                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_dev_info_batch_del-7/00000000000000057329.index
2076 7f1555fda000-7f15569da000 rw-s 00000000 fd:01 1704990                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_dev_info_batch_del-7/00000000000000057329.index
2077 7f15569da000-7f15573da000 rw-s 00000000 fd:01 1705044                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_device_to_db-10/00000000000000183949.index
2078 7f15573da000-7f15573db000 rw-s 00000000 fd:01 1705044                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_device_to_db-10/00000000000000183949.index
2079 7f15573db000-7f1557ddb000 rw-s 00000000 fd:01 1705044                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_device_to_db-10/00000000000000183949.index
2080 7f1557ddb000-7f15587db000 rw-s 00000000 fd:01 1705044                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_device_to_db-10/00000000000000183949.index
2081 7f15587db000-7f15591db000 rw-s 00000000 fd:01 1704654                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_scr_info-5/00000000000000000000.index
2082 7f15591db000-7f1559bdb000 rw-s 00000000 fd:01 1704654                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_scr_info-5/00000000000000000000.index
2083 7f1559bdb000-7f155a5db000 rw-s 00000000 fd:01 1704654                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_scr_info-5/00000000000000000000.index
2084 7f155a5db000-7f155afdb000 rw-s 00000000 fd:01 1704682                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_device_to_db-9/00000000000000091638.index
2085 7f155afdb000-7f155afdc000 rw-s 00000000 fd:01 1704682                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_device_to_db-9/00000000000000091638.index
2086 7f155afdc000-7f155b9dc000 rw-s 00000000 fd:01 1704682                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_device_to_db-9/00000000000000091638.index
2087 7f155b9dc000-7f155c3dc000 rw-s 00000000 fd:01 1704682                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_device_to_db-9/00000000000000091638.index
2088 7f155c3dc000-7f155cddc000 rw-s 00000000 fd:01 1704870                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_scr_info-13/00000000000000000000.index
2089 7f155cddc000-7f155d7dc000 rw-s 00000000 fd:01 1704870                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_scr_info-13/00000000000000000000.index
2090 7f155d7dc000-7f155e1dc000 rw-s 00000000 fd:01 1704870                    /home/dcs_extas/usr/kafka_test_env/kafka-logs/dcs_async_scr_info-13/00000000000000000000.index

這里給出的只是各種index的片段旷赖，還有其他的映射文件顺又，比如加載的jar包等，此處忽略等孵。

統(tǒng)計量下map的總數量稚照，600多。查看系統(tǒng)限制

cat /proc/sys/vm/max_map_count
65530

可以看到俯萌，map size遠小于系統(tǒng)限制

2.3 查看進程status

然后抓取status果录，

cat /proc/$PID/status

可以看出，VmPeak和VMSize比較大咐熙，快7G

----------------------------------------Tue Nov 27 13:54:59 CST 2018 catch process status info start--------------------------------
Name:   java
State:  S (sleeping)
Tgid:   7492
Pid:    7492
PPid:   7491
TracerPid:      0
Uid:    1006    1006    1006    1006
Gid:    1000    1000    1000    1000
FDSize: 256
Groups: 16 33 1000 
VmPeak:  6899700 kB
VmSize:  6899700 kB
VmLck:         0 kB
VmPin:         0 kB
VmHWM:    106168 kB
VmRSS:    106104 kB
VmData:  2416668 kB
VmStk:       140 kB
VmExe:         4 kB
VmLib:     14460 kB
VmPTE:      1248 kB
VmSwap:        0 kB
Threads:        17
SigQ:   0/127537
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 0000000000000000
SigIgn: 0000000000000003
SigCgt: 2000000181005ccc
CapInh: 0000000000000000
CapPrm: 0000000000000000
CapEff: 0000000000000000
CapBnd: ffffffffffffffff
Cpus_allowed:   f
Cpus_allowed_list:      0-3
Mems_allowed:   00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00
000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000001
Mems_allowed_list:      0
voluntary_ctxt_switches:        7
nonvoluntary_ctxt_switches:     3
----------------------------------------Tue Nov 27 13:54:59 CST 2018 catch process status info end--------------------------------

因此懷疑是VmPeak反映出的虛擬內存占用過大導致的

2.4 查看ulimit限制

查看ulimit

core file size          (blocks, -c) unlimited
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 127537
max locked memory       (kbytes, -l) 64
max memory size         (kbytes, -m) 7331164
open files                      (-n) 1024
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 127537
virtual memory          (kbytes, -v) 6899920
file locks                      (-x) unlimited

可以發(fā)現弱恒， virtual memory的上線也是快7G，因此大概率是vm不夠用了棋恼。

3. 調大vm-解決

申請了root權限返弹，調整了ulimit -v

ulimit -v unlimited

再啟動kafka，完美啟動爪飘。查看status

Name:   java
State:  S (sleeping)
Tgid:   19687
Pid:    19687
PPid:   1
TracerPid:      0
Uid:    1006    1006    1006    1006
Gid:    1000    1000    1000    1000
FDSize: 512
Groups: 16 33 1000 
VmPeak:  7566500 kB
VmSize:  4704148 kB
VmLck:         0 kB
VmPin:         0 kB
VmHWM:    261668 kB
VmRSS:    261668 kB
VmData:  2453684 kB
VmStk:       140 kB
VmExe:         4 kB
VmLib:     14460 kB
VmPTE:      1788 kB
VmSwap:        0 kB
Threads:        59
SigQ:   0/127537

可以看出义起，vm峰值的確超過了7G，可以應證是之前的vm限制問題师崎。

總結

kafka的設計和實現中大量使用了PageCache和文件映射默终。其中文件映射需要用到虛擬內存。對于每個topic的每個partition的數據片段犁罩，kafka都將為其生成一個index文件齐蔽，這些index文件會被kafka做mmap映射到內存中，如果index文件太多床估，虛擬內存可能會不夠用含滴，因此有兩處可以緩解這種現象

  • 調整系統(tǒng)vm限制，如本文中設置ulimit -v unlimited
  • 合理配置log.segment.bytes的大小顷窒，不要配置的過小蛙吏，否則在生產環(huán)境中源哩，可能會因為滾動生成太多的segment文件而附加生成太多的index文件鞋吉，最終使得mmap在映射時造成OOM報錯。一般log.segment.bytes配置不小于200M励烦，log.retention.bytes配置推薦為1G即以上（是log.segment.bytes的倍數）

4. 抓取腳本

catchKafkaMemInfo.sh

PID=`jps|grep Kafka|grep -v grep|awk '{print $1}'`
STATUS_FILE=process_status_$PID.log
MAPS_FILE=process_maps_$PID.log
FREEMEM_FILE=process_free_$PID.log
if [ "x$PID" == "x" ] ; then

    echo "no pid found for kafka"
else
    echo "catch status of pid:$PID"
    NOW_TIME=`date`
    echo "----------------------------------------$NOW_TIME catch process status info start--------------------------------"  >>  $FREEMEM_FILE
    free -m  >> $FREEMEM_FILE
    echo "----------------------------------------$NOW_TIME catch process mem info end--------------------------------"  >>  $FREEMEM_FILE
    echo "----------------------------------------$NOW_TIME catch process status info start--------------------------------"  >>  $STATUS_FILE
    cat /proc/$PID/status >> $STATUS_FILE
    echo "----------------------------------------$NOW_TIME catch process status info end--------------------------------"  >>  $STATUS_FILE
    echo "process status file has been created as file  $STATUS_FILE"
    echo "----------------------------------------$NOW_TIME catch process map info start--------------------------------"  >>  $MAPS_FILE
    cat /proc/$PID/maps >> $MAPS_FILE
    echo "----------------------------------------$NOW_TIME catch process map info end--------------------------------"  >>  $MAPS_FILE
    MAP_SIZE=`wc -l $MAPS_FILE|awk '{print $1}'`
    echo "process maps file has been created as file $MAPS_FILE, map size:$MAP_SIZE"
fi

startKafkaAndCatch.sh

//啟動kafka server
nohup bin/kafka-server-start.sh config/server.properties > /dev/null 2>&1 &
//開始抓資源狀態(tài)谓着，每100ms抓取一次
sh catchKafkaMemInfo.sh
for i in {1..10}
do
echo "catch now..."
sh catchKafkaMemInfo.sh
sleep 0.1
done

主要抓取了map count、內存使用信息等坛掠。

status相關字段解釋

VmPeak: Peak virtual memory usage
VmSize: Current virtual memory usage
VmLck:  Current mlocked memory
VmHWM:  Peak resident set size
VmRSS:  Resident set size
VmData: Size of "data" segment
VmStk:  Size of stack
VmExe:  Size of "text" segment
VmLib:  Shared library usage
VmPTE:  Pagetable entries size
VmSwap: Swap space used
最后編輯于 ：
?著作權歸作者所有,轉載或內容合作請聯系作者
  • 人面猴
    序言：七十年代末赊锚，一起剝皮案震驚了整個濱河市治筒，隨后出現的幾起案子，更是在濱河造成了極大的恐慌舷蒲，老刑警劉巖耸袜，帶你破解...
    沈念sama閱讀 216,402評論 6贊 499
  • 死咒
    序言：濱河連續(xù)發(fā)生了三起死亡事件，死亡現場離奇詭異牲平，居然都是意外死亡堤框，警方通過查閱死者的電腦和手機，發(fā)現死者居然都...
    沈念sama閱讀 92,377評論 3贊 392
  • 救了他兩次的神仙讓他今天三更去死
    文/潘曉璐 我一進店門纵柿，熙熙樓的掌柜王于貴愁眉苦臉地迎上來蜈抓，“玉大人，你說我怎么就攤上這事昂儒」凳梗” “怎么了？”我有些...
    開封第一講書人閱讀 162,483評論 0贊 353
  • 道士緝兇錄：失蹤的賣姜人
    文/不壞的土叔 我叫張陵渊跋，是天一觀的道長腊嗡。 經常有香客問我，道長拾酝，這世上最難降的妖魔是什么叽唱？ 我笑而不...
    開封第一講書人閱讀 58,165評論 1贊 292
  • ?港島之戀（遺憾婚禮）
    正文 為了忘掉前任，我火速辦了婚禮微宝，結果婚禮上棺亭，老公的妹妹穿的比我還像新娘。我一直安慰自己蟋软，他們只是感情好镶摘，可當我...
    茶點故事閱讀 67,176評論 6贊 388
  • 惡毒庶女頂嫁案：這布局不是一般人想出來的
    文/花漫 我一把揭開白布。 她就那樣靜靜地躺著岳守，像睡著了一般凄敢。 火紅的嫁衣襯著肌膚如雪。 梳的紋絲不亂的頭發(fā)上湿痢，一...
    開封第一講書人閱讀 51,146評論 1贊 297
  • 城市分裂傳說
    那天涝缝，我揣著相機與錄音，去河邊找鬼譬重。 笑死拒逮，一個胖子當著我的面吹牛，可吹牛的內容都是我干的臀规。 我是一名探鬼主播滩援，決...
    沈念sama閱讀 40,032評論 3贊 417
  • 雙鴛鴦連環(huán)套：你想象不到人心有多黑
    文/蒼蘭香墨 我猛地睜開眼，長吁一口氣：“原來是場噩夢啊……” “哼塔嬉！你這毒婦竟也來了玩徊？” 一聲冷哼從身側響起租悄，我...
    開封第一講書人閱讀 38,896評論 0贊 274
  • 萬榮殺人案實錄
    序言：老撾萬榮一對情侶失蹤，失蹤者是張志新（化名）和其女友劉穎恩袱，沒想到半個月后泣棋，有當地人在樹林里發(fā)現了一具尸體，經...
    沈念sama閱讀 45,311評論 1贊 310
  • ?護林員之死
    正文 獨居荒郊野嶺守林人離奇死亡畔塔，尸身上長有42處帶血的膿包…… 初始之章·張勛 以下內容為張勛視角 年9月15日...
    茶點故事閱讀 37,536評論 2贊 332
  • ?白月光啟示錄
    正文 我和宋清朗相戀三年外傅，在試婚紗的時候發(fā)現自己被綠了。 大學時的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片俩檬。...
    茶點故事閱讀 39,696評論 1贊 348
  • 活死人
    序言：一個原本活蹦亂跳的男人離奇死亡萎胰，死狀恐怖，靈堂內的尸體忽然破棺而出棚辽，到底是詐尸還是另有隱情技竟，我是刑警寧澤，帶...
    沈念sama閱讀 35,413評論 5贊 343
  • ?日本核電站爆炸內幕
    正文 年R本政府宣布屈藐，位于F島的核電站榔组，受9級特大地震影響，放射性物質發(fā)生泄漏联逻。R本人自食惡果不足惜搓扯，卻給世界環(huán)境...
    茶點故事閱讀 41,008評論 3贊 325
  • 男人毒藥：我在死后第九天來索命
    文/蒙蒙 一、第九天 我趴在偏房一處隱蔽的房頂上張望包归。 院中可真熱鬧锨推，春花似錦、人聲如沸公壤。這莊子的主人今日做“春日...
    開封第一講書人閱讀 31,659評論 0贊 22
  • 一樁弒父案，背后竟有這般陰謀
    文/蒼蘭香墨 我抬頭看了看天上的太陽厦幅。三九已至沾鳄，卻和暖如春，著一層夾襖步出監(jiān)牢的瞬間确憨，已是汗流浹背译荞。 一陣腳步聲響...
    開封第一講書人閱讀 32,815評論 1贊 269
  • 情欲美人皮
    我被黑心中介騙來泰國打工， 沒想到剛下飛機就差點兒被人妖公主榨干…… 1. 我叫王不留休弃，地道東北人吞歼。 一個月前我還...
    沈念sama閱讀 47,698評論 2贊 368
  • 代替公主和親
    正文 我出身青樓，卻偏偏與公主長得像玫芦，于是被迫代替她去往敵國和親浆熔。 傳聞我的和親對象是個殘疾皇子，可洞房花燭夜當晚...
    茶點故事閱讀 44,592評論 2贊 353