今天本来打算愉快的划水,运维小哥突然找我说测试环境应用 cpu 一直居高不下,我一看告警还真是...
cpu 高问题排查思路
首先还是老套路:
- 先查看 cpu 高的线程是哪些
top -Hp <pid>
- 查看线程的堆栈信息
//将线程 id 转换为 16 进制
printf '%x\n' <tid>
//获取线程号后 50 行堆栈信息
jstack <pid> | grep <tid> -A 50
这里我就直接用线程名称去查了。
看堆栈信息定位到是 kafka 消费者消费消息,导致 cpu 居高不下,正常情况下 kafka 消费者 cpu 飚高都是有大量的消息,我第一个感觉就是测试在进行压测,结果一看,打脸了🤔。
可以看到,lag 是 0 或者负数,我又刷新了几次基本上没有多少消息,这里留个心眼,后面我们在好好唠唠。
那么问题就来了,没有消息为啥消费者 cpu 会飚高... 突然灵机一动,会不会是消费者数太多了,导致循环去调用 poll 方法,造成整个节点 cpu 飚高。然后就屁颠屁颠的把所有主题的消费者数调小了,然鹅想想很美好,现实很骨感... 重启后节点的 cpu 依然居高不下。
遇到不懂就问度娘
在网上逛了一圈,看到许多相似的场景,各种操作都试了一遍,还是没什么用🙃,kafka 的 github 仓库我也去逛了一圈,发现也有很多 cpu 高得场景,大多数都是建议升级客户端版本,忘了说我司目前用的还是 0.11.2,总之逛了一圈没有起到太大的帮助。
接着就是一波虾皮操作,显示生成了火焰图,看看 consumer poll 到底为啥一直占用 cpu,下面是一张火焰图:
虽然 poll 方法占用 cpu 耗时很长,但是仔细看又觉得没啥问题,是正常的在处理网络请求,这个时候我甚至一度怀疑是 kafka 客户端的 bug 😂。
有耐心问题迟早能解决
还记的我们之前提了一嘴那张截图吗,没错就是下面这张
图中 lag 出现负数,其实 lag 出现负数还是很常见的,但问题就出在我排查了这么久图中的 lag 好像没变化过,而且一直是负数,那就很值得注意了。
我们还是先说说 lag 是怎么计算的
lag = HW - consumerOffset
HW: 高水位,通常等于所有 ISR 中最小的 LEO,详细的可以看看大佬的博客
consumerOffset: 表示消费者提交的消费位移
那么 lag 为啥会出现负数呢,由于我本身并未看过源码,所以从网上找了一个我认为比较是能说的通的解释:
Producer 的 offset 是通过 JMX 轮询获得的,Consumer 的 offset 是从 kafka 内的 __consumer_offsets 的 topic 中直接读取到的,很明显轮询获取 offset 比 直接从 topic 拿 offset 慢一点,也就可能会出现 Lag 计算后为负数的情况。
OK,回到正题,lag 长时间是负数说明 consumerOffset 一直大于 HW,那么出现这个问题的原因大概率是 HW 一直不更新,因为 HW 只要更新其实 lag 很快就能变回 0。那么 HW 是什么时候更新的呢,其实是 Follower 副本同步 Leader 副本数据时,Leader 副本会对比 Follower 拉取数据的 offset 和 Leader 自身的 LEO 去更新 HW,所以通常 HW 需要 Follower 多同步一轮才会更新。
那么 HW 不更新,只能说明 Follower 没有去同步数据,想到这,我立马去看了下消费组的副本状态,发现有一个 broker 所有的分区副本都不在 ISR 中。那么基本上确定这个 broker 是出现问题了,但是这和我消费者 cpu 高有什么关系呢?
这时运维小哥告诉我,poll 平均每 3ms 就请求一次,导致 cpu 飚高。纳尼???我的 poll timeout 明明是 100ms,怎么 3ms 一次呢,这明显有问题呀,运维小哥发了一下抓包的截图给我:
kafka broker response 中提示 Not Leader For Partition,这不就和上面的猜想对上了吗,看看 chatgpt 给出的解释:
至此问题就排查了差不多了,那么接下来就是解决。由于是在测试环境发现的,解决方式也很粗暴,就是直接把 topic 直接删除了,然后重新创建。
小结
- 遇到涉及网络相关的问题,可以抓个包瞧瞧,说不定思路一下就打开了。
- 如果实在生产环境遇到这类问题,那么该怎么处理 broker 呢,这个得好好琢磨琢磨,目前思路是从 controller 下手。