Kafka 0.8 宕机问题排查步骤

CPU 利用率高的排查方法

看看该机器的连接数是不是比其他机器多,监听的端口数:netstat -anlp | wc -l

Kafka-0.8的停止和启动

启动: cd /usr/local/kafka-0.8.0-release/ && nohup ./bin/kafka-server-start.sh config/server.properties &

停止: ps ax | grep -i 'kafka.Kafka' | grep -v grep | awk '{print $1}' | xargs kill -SIGTERM

kafka -0.10的启动和停止

启动:sh /usr/local/kafka/kafka-release/bin/kafka-server-start.sh -daemon /usr/local/kafka/kafka-release/config/server.properties &

停止: kill

1 问题描述

broker 连接Session超时,在zookeeper的临时节点删除,出发告警。查明超时的原因。

2 步骤

1.hpm查看byte-out,网络情况

2.hpm查看当时时间点的load

3.sar命令查看broker当时的网络负载:sar -n ALL -f /var/log/sa/sa08 | grep bond0 > ~/netinfo

3 tips

空闲的时候,查一下2016.7.22 4:27,broker:10.39.48.158的问题原因。

4 一个详细的问题

10.39.48.158机器出现了2次Session Time Out的问题。第二次现象:2016-7-24 12:36网络入口流量byte_in猛增到230M/s,load 达到70。它的其他情况是几M/s,load 稳定在1左右。由于它已经宕机过一次,所以该机器上没有作为任何topic的leader。这个猛增的流量是从何处来的呢?

排查作为topic partition的follower是否有BytesInPerSec这个metrics值

leader有,follower没有。方法:jmx获取同一个topic partition的leader和follower的BytesInPerSec值。

2.排查是否该机器作为follower在某时刻,由于leader所在的topic入口流量猛增,follower同步,导致入口流量猛增。

topic:weibomobile,在那时刻入口流量130M/s,48.158机器需要同步它的6个partition。还有别的小入口流量的topic,合计起来,增大了48.158机器的流量。

3.解决

如果在出现类似的问题,将48.158机器的Session Time Out时间从6s,设置成30s,待观察。

5 机器48.158再次出现ZK节点丢失

1.现象

12:58获取到报警,即在12:57节点丢失后,在1min内没有连接上,因此触发报警。

观察该机器,

load_one 12:55:30-12:59:00 负载稳定在 75;

cpu_system 13:00:00-13:02:00 利用率在 12.8%

bytes_in 13:02:30 流量突增到 243M

2.分析

分析该机器上所有的46个topic所在的48.158的partition是否有激增的流量。该数据目前没有,需要收集。

在分析这46个topic的LogEndOffsetIncrease指标,发现12:55:00,所有topic的增加量猛增。

(???会不会是这个时间刻发生了GC)

原有的进程已经被kill重新启动了,查看了新启动的Kafka进程的GC,如下,是正常情况:YC 一次平均耗时38毫秒,FC 一次平均耗时325毫秒。

jstat-gcutil7089S0S1EOPYGCYGCTFGCFGCTGCT5.180.0068.2914.5460.00308028 11991.5041258  409.27412400.778

很重要的一次GC信息 from 杰哥

kafka 宕机的时候,由于负载很高,流量很高,cms gc的remark耗时7s,导致kafka挂掉。(remark stop the word)

## 6 机器4.215、4.216、4.217 在ZK的节点丢失一次。

1.现象+分析

```

16/08/08 14:42:09 INFO eager.MonitorBrokerDown: -----broker down info:kafka broker had shutdown. Maybe this is a normal behavior. last alive brokers:[19, 48151, 17, 18, 15, 48153, 48152, 16, 13, 48155, 14, 48154, 11, 48157, 12, 48156, 48158, 48159, 48160, 3, 2, 10, 1, 0, 7, 6, 5, 4, 9, 8]. current alive brokers:[19, 48151, 17, 18, 15, 48153, 48152, 16, 13, 48155, 48154, 11, 48157, 12, 48156, 48158, 48159, 48160, 3, 2, 10, 1, 0, 7, 6, 5, 4, 9, 8]. invalid broker ip info:{ "host":"10.39.4.215", "jmx_port":9999, "port":19092, "version":1 }

byte-out下降、byte-in下降、load下降,2.5.

02:30:01 PM bond0 119951.04 125071.66 114175.78 91512.58 0.00 0.00 11.26

02:40:01 PM bond0 118530.20 125037.93 110370.88 95596.69 0.00 0.00 11.13

02:50:01 PM bond0 85377.47 83437.07 90981.47 50017.23 0.00 0.00 10.94

16/08/08 16:35:33 INFO eager.MonitorBrokerDown: -----broker down info:kafka broker had shutdown. Maybe this is a normal behavior. last alive brokers:[19, 48151, 17, 18, 15, 48153, 48152, 16, 13, 48155, 14, 48154, 11, 48157, 12, 48156, 48158, 48159, 48160, 3, 2, 10, 1, 0, 7, 6, 5, 4, 9, 8]. current alive brokers:[19, 48151, 17, 18, 48153, 48152, 16, 13, 48155, 14, 48154, 11, 48157, 12, 48156, 48158, 48159, 48160, 3, 2, 10, 1, 0, 7, 6, 5, 4, 9, 8]. invalid broker ip info:{ "host":"10.39.4.216", "jmx_port":9999, "port":19092, "version":1 }

byte-out:41-62M;byte-in:95-120M;load稳定在3左右。

04:10:01 PM bond0 132737.19 130567.37 138791.12 81211.07 0.00 0.00 11.25

04:20:01 PM bond0 131918.26 134324.10 129449.86 88444.40 0.00 0.00 11.22

04:30:01 PM bond0 97577.10 98807.90 93055.00 61815.56 0.00 0.00 11.32

04:40:01 PM bond0 98629.53 94743.99 108407.71 44847.14 0.00 0.00 11.34

16/08/08 17:08:07 INFO eager.MonitorBrokerDown: -----broker down info:kafka broker had shutdown. Maybe this is a normal behavior. last alive brokers:[19, 48151, 17, 18, 15, 48153, 48152, 16, 13, 48155, 14, 48154, 11, 48157, 12, 48156, 48158, 48159, 48160, 3, 2, 10, 1, 0, 7, 6, 5, 4, 9, 8]. current alive brokers:[19, 48151, 17, 18, 15, 48153, 48152, 13, 48155, 14, 48154, 11, 48157, 12, 48156, 48158, 48159, 48160, 3, 2, 10, 1, 0, 7, 6, 5, 4, 9, 8]. invalid broker ip info:{ "host":"10.39.4.217", "jmx_port":9999, "port":19092, "version":1 }

byte-out:102-182M;byte-in:70-84M;load稳定,在1.6左右。

05:00:01 PM bond0 140487.48 174511.06 82636.05 184825.13 0.00 0.00 11.58

05:10:01 PM bond0 106820.66 125645.42 72597.47 118687.98 0.00 0.00 11.39

05:20:01 PM bond0 69833.26 64922.26 82521.11 24865.14 0.00 0.00 11.47

新出现10.39.4.210一天,zk节点丢失2次。

16/08/09 23:16:37 INFO eager.MonitorBrokerDown: -----broker down info:kafka broker had shutdown. Maybe this is a normal behavior. last alive brokers:[19, 48151, 17, 18, 15, 48153, 16, 48152, 13, 48155, 14, 48154, 11, 48157, 12, 48156, 48158, 48159, 48160, 3, 2, 10, 1, 0, 7, 6, 5, 4, 9, 8]. current alive brokers:[19, 48151, 17, 18, 15, 48153, 16, 48152, 13, 48155, 14, 48154, 11, 48157, 12, 48156, 48158, 48159, 48160, 3, 2, 10, 1, 0, 7, 6, 5, 4, 9]. invalid broker ip info:{ "host":"10.39.4.210", "jmx_port":9999, "port":19092, "version":1 }

分析:

byte-out:5M左右,byte-in:20M左右,load在5左右。Server日志无异常。

11:10:01 PM bond0 109463.54 123069.26 70532.96 107504.21 0.00 0.00 10.76

11:20:02 PM bond0 104557.60 111693.01 66477.78 80714.76 0.00 0.00 10.58

11:30:02 PM bond0 81705.83 73025.27 65993.75 7403.50 0.00 0.00 10.74

16/08/10 04:55:39 INFO eager.MonitorBrokerDown: -----broker down info:kafka broker had shutdown. Maybe this is a normal behavior. last alive brokers:[19, 48151, 17, 18, 15, 48153, 16, 48152, 13, 48155, 14, 48154, 11, 48157, 12, 48156, 48158, 48159, 48160, 3, 2, 10, 1, 0, 7, 6, 5, 4, 9, 8]. current alive brokers:[19, 48151, 17, 18, 15, 48153, 16, 48152, 13, 48155, 14, 48154, 11, 48157, 12, 48156, 48158, 48159, 48160, 3, 2, 10, 1, 0, 7, 6, 5, 4, 9]. invalid broker ip info:{ "host":"10.39.4.210", "jmx_port":9999, "port":19092, "version":1 }

byte-out:2M左右,byte-in:10M左右,load在11左右,

04:50:01 AM bond0 31866.19 28762.38 11614.37 3181.36 0.00 0.00 10.58

05:00:01 AM bond0 30127.26 27063.09 11909.66 3022.31 0.00 0.00 10.54

05:10:01 AM bond0 32618.83 29096.87 13870.89 3218.26 0.00 0.00 10.36

```

7. 机器4.220 kafka进程无法提供服务

1.现象

zk节点丢失。

2.分析

宕机的前几分钟load值从2升到83.

8. 机器4.210 近5天的时间,平均每天出现1次 zookeeper.session.timeout

排查该机器,每次断连的时候load_one的值突然变高,byte_in byte_out cpu 指标正常。

zookeeper连接默认的超时时间是 6000ms,见代码kafka/utils/ZkUtils.scala:743 ("zookeeper.session.timeout.ms", 6000)

解决

提高超时时间,zookeeper.session.timeout.ms=45000

bin/kafka-server-start.sh添加GC日志:export KAFKA_OPTS="-Xms4G -Xmx8G -Xmn3G -XX:+UseConcMarkSweepGC -XX:ParallelGCThreads=4 -server -Dlog4j.configuration=file:$base_dir/config/log4j.properties -Xloggc:/data0/kafka/log/gc.log -verbose:gc -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCApplicationStoppedTime"

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 205,386评论 6 479
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 87,939评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 151,851评论 0 341
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,953评论 1 278
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,971评论 5 369
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,784评论 1 283
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,126评论 3 399
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,765评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 43,148评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,744评论 2 323
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,858评论 1 333
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,479评论 4 322
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,080评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,053评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,278评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,245评论 2 352
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,590评论 2 343

推荐阅读更多精彩内容