事故起因
2018.10.13日Kafka出现了无法启动问题,安稳了一天,结果第二天晚上又出现了新的问题,发现有些程序无法正常消费Kafka了。
这个问题在网上找了一下,发现有类似的经历,都是Kafka进程异常挂掉之后,起来无法消费的问题,但是试了一下,发现每次事故还是都有它的独特之处,所以这里专门记录一下。
调查过程
基本环境信息:
软件版本:使用的Kakfa的版本是1.1.0版本,之前因为从0.8.2升级过一次,所以消息格式仍然是沿用支持0.8.2的消息格式。
集群:6个节点,broker id分别是:0,1,2,3,4,5
节点配置:内存:64G 硬盘:4T * 12
网卡:万兆
其中0,1两个节点的Kafka出现过异常挂掉。
出现问题的时候,也不是所有的程序都无法消费,而是部分节点无法消费了,查了一下机器的负载情况,0号节点负载非常高,达到11了,磁盘利用率非常高,而其他的几个节点的负载都非常低。
这里我们简单重温一下消费的原理:
同一个组的消费者会加入到一起,向Coordinator请求加入消费组,Coordinator会向每个消费者分配消费的分区。
那么Coordinator是怎么确定的呢?一般一个消费者启动后,会随机想一个节点请求去获取它的Coordinator所在节点。
获取Coordinator所在的节点的原理与我们的消费组的消费偏移量信息是存储__consumer_offsets对应的分区上。
所以最终定位到Kafka是如何选择__consumer_offsets这个topic的分区来存储对应的偏移量。
以消费组名为ttt为例来说明:
int hashCode = Math.abs("ttt".hashCode());
int partition = hashCode % 50;
先计算group的hashCode,再除以分区数(50),可以得到partition的值为:44。
再通过kafka-topic.sh命令查看该partition的leader在哪个节点,那么就可以确定tttt这个消费组的Coordinator落在哪个节点了。
在消费过程中,消费不了的原因是说对应的Coordinator无效,日志如下:
[2018-10-14 21:20:28,860] INFO [Consumer clientId=consumer-1, groupId=console-consumer-28334] Discovered group coordinator wxoddc2nn1:9092 (id: 2147483647 rack: null) (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)
[2018-10-14 21:20:28,860] INFO [Consumer clientId=consumer-1, groupId=console-consumer-28334] Group coordinator wxoddc2nn1:9092 (id: 2147483647 rack: null) is unavailable or invalid, will attempt rediscovery (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)
[2018-10-14 21:20:28,962] INFO [Consumer clientId=consumer-1, groupId=console-consumer-28334] Discovered group coordinator wxoddc2nn1:9092 (id: 2147483647 rack: null) (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)
[2018-10-14 21:20:28,962] INFO [Consumer clientId=consumer-1, groupId=console-consumer-28334] (Re-)joining group (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)
[2018-10-14 21:20:28,964] INFO [Consumer clientId=consumer-1, groupId=console-consumer-28334] Group coordinator wxoddc2nn1:9092 (id: 2147483647 rack: null) is unavailable or invalid, will attempt rediscovery (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)
[2018-10-14 21:20:29,065] INFO [Consumer clientId=consumer-1, groupId=console-consumer-28334] Discovered group coordinator wxoddc2nn1:9092 (id: 2147483647 rack: null) (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)
[2018-10-14 21:20:29,066] INFO [Consumer clientId=consumer-1, groupId=console-consumer-28334] Group coordinator wxoddc2nn1:9092 (id: 2147483647 rack: null) is unavailable or invalid, will attempt rediscovery (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)
日志中的wx0ddc2nn1主机就是我们的0号节点,客户端无法消费的原因是发现Coordinator在0号节点,但是0号节点认为该Coordinator无效,刚开始怀疑是负载较大,我们查询了一下__consumer_offsets这个topic的leader居然全部是0号节点,而且只有两个副本,另外一个副本在1号节点上。
- 第一次尝试
把一些分区的leader调整到1号节点,发现也无法正常消费。
基本说明了一个问题,消费问题与负载不相关,但是可能与这两个节点异常启动过有关。
解决问题的过程
对__consumer_offsets进行整体的分区调整,调整为3个分区,并且把leader和副本分区均匀分配在6个节点上,发出了调整指令后,半个小时左右,有部分节点的leader调整到其他节点了。
我们按照前面的消费组所处__consumer_offsets的分区的计算算法,找到合适的group名,譬如:tttt,它的partition为44,发现44这个分区的leader落在了2号节点,然后,我们启动命令行消费者:
hadoop@wxoddc2dn4:~/kafka_2.11-1.1.0$ bin/kafka-console-consumer.sh --zookeeper zk01 --topic test --max-messages 2 --group tttt
{"app":{"businessid":"4","source":"java_sdk_1.3.3","ports":";18901;","ips":";127.0.0.1;","clientname":"guess.mobile_guess","srvid":"86787","time":1539593926175},"@timestamp":"2018-10-15T08:58:46.175Z","docid":"Akh+2+aRqtHXO7e+WQytelELbGNkZuxGVeBXQTxYNi8=WZ28vYfDhbvty","btKey":"Akh+2+aRqtHXO7e+WQytelELbGNkZuxGVeBXQTxYNi8=","model":{"ctx":{"activeThreads":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"queueId":2,"activeTimeWaiting":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"activeRunnable":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"minThreads":500,"activeBlocked":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"activeWaiting":{"avg":500.0,"count":1,"max":500,"min":500,"sum":500},"queueMaxSize":100000,"maxThreads":500,"queueCurSize":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"currentThreads":{"avg":500.0,"count":1,"max":500,"min":500,"sum":500},"maxUsedThreads":500},"id":"mainPool","type":1},"businessType":"queueState","batchid":"Dhbvty"}
{"app":{"businessid":"4","source":"java_sdk_1.3.3","ports":";18901;","ips":";127.0.0.1;","clientname":"guess.mobile_guess","srvid":"86787","time":1539593926175},"@timestamp":"2018-10-15T08:58:46.175Z","docid":"/kD1spNQhiu4VwtsuOVyX12y+kG/70S0/AH7ITcRwoQ=WZ28vYfDhbvty","btKey":"/kD1spNQhiu4VwtsuOVyX12y+kG/70S0/AH7ITcRwoQ=","model":{"ctx":{"activeThreads":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"queueId":1,"activeTimeWaiting":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"activeRunnable":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"minThreads":4,"activeBlocked":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"activeWaiting":{"avg":4.0,"count":1,"max":4,"min":4,"sum":4},"queueMaxSize":1000000,"maxThreads":4,"queueCurSize":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"currentThreads":{"avg":4.0,"count":1,"max":4,"min":4,"sum":4},"maxUsedThreads":4},"id":"processor-threadpool","type":1},"businessType":"queueState","batchid":"Dhbvty"}
发现就能够正常消费了,所以怀疑是0,1两个节点的问题,因为这两个节点异常启动过。
等待__consumer_offsets重新调整的过程很长,有一些超级大的分区,我们把一些超过3天以上的数据删除了,加快了一点速度,但是调整完毕后,仍然有一部分分区的leader是在0,1上,使用落在这些分区的消费组消费,仍然不行。
- 第二轮调整
再次把__consumer_offsets进行了分区调整,把所有的分区都迁移到其他2,3,4,5节点上。
在这次调整后,使用所有的消费组名,都能够消费了。
总结
整个故障的解决时间比较长,而且中间做了各种尝试,所以对部分业务也造成了影响,好在我们kafka集群和数据都是双机房备份的,核心的业务做了切换。
现在Kafka的复杂性越来越高,不在代码层面去研究,碰到问题都很难解决,像这次的问题,我们虽然没有在去基于代码层面进行研究,但是最终结果只是暂时让我们的集群恢复正常了。而0,1号节点无法消费的原因,我们还没有找到。
后续会继续对这个问题进行更进一步的调研,如果有更进一步的结论,会继续完善该文档。
后记
经过了上次的调整以后,0和1这两个节点已经不再存储任何__consumer_offsets这个topic的分区了,我尝试把一个分区重新放回0和1,并且让它们做leader,结果发现也能消费了。
从这个现象看起来,初步怀疑是节点的异常重启造成了__consumer_offsets的部分分区数据异常,但是经过数据的迁移之后,由于0和1已经没有相关的数据,再次迁移回来,数据是全新的,所以不再有异常了,总得来说,还是该版本的kafka有隐藏的bug。
【20181022】
最近分析发现,Kafka进程启动后一直在加载对应的__consumer_offsets分区的数据,由于对应的logclean逻辑因为某个原因出问题了,造成对应的__consumer_offsets的清理一直没有进行,积累了大量的历史数据,最多的分区达到了2T,系统一直加载__consumer_offsets,所以对应的__consumer_offsets无法正常工作,从而提示Coordinator invalid。
解决方案很简单,删除__consumer_offsets的历史文件,再启动Kafka进程即可。