记一次 Kafka 写入超时问题详细分析
本篇文章介绍了一次 Flume 写入 Kafka 集群时,程序出现超时的问题定位和优化分析,供大家参考。

一、问题概要
客户在使用 Flume 写入 Kafka 集群时,程序发生超时异常,已知两个异常信息堆栈,需要定位分析解决。这个问题分大致两个方向考虑,一个方面从客户端分析,另一方面从服务端分析。同时需要通过iperf3
、dstat
、iftop
等命令来验证两个集群之间是否存在网络瓶颈。
1. Expiring 1 record(s) for GDxxxx due to 303679 ms has passed since batch creation plus linger time.

2. The server disconnected before a response was received.

二、客户端优化分析
经过分析客户端进程,有几处可以进行优化:1)优化 kafka producer 的参数,2)优化单机写入并行度,3)优化高耗 CPU。
1. 生产者参数优化
参数根据分区数和单条消息大小进行优化调整
○ request.timeout.ms
○ linger.ms
○ batch.size
○ buffer.memory
2. 优化并行度
用户会认为单机 producer 越多越好(设置 30 个左右)。其实并不是这样,因为单个 producer 可以发送的最大吞吐在 300-400MB,随着 producer 的数量越多,每个批次的 ack 时间也会变成,最终导致超过request.timeout.ms
,体现为The server disconnected before a response was received
异常。
3. 优化消耗 CPU 逻辑
客户端进程中同时存在高消耗 CPU 线程,此问题同样会导致 producer 无法及时进行网络线程调度,最终导致客户端写入发生异常。

三、服务端优化分析
在进行服务器端分析优化时,我们需要考虑的点是:1)环境是否存在问题 2)服务参数优化。
1. 参数优化
根据实际情况,调整线程数
○ num.io.threads
○ num.network.threads
2. 环境问题
通过对环境的观察发现,由于我们现网使用的 ARM 的机器,JDK 的版本采用的是基于 OpenJDK 的 ARM 版本。这个版本很容易在生产环境导致进程 hang 住,进而导致分区不能同步,分区,同时我们也不能进行使用jstack
命令强制打印堆栈,所以决定切换为基于 OracleJDK 的 ARM 版本。效果比较明显,我们在替换之后,观察一周,服务端和客户端未发现问题(之前几乎每天都存在 2-3 个 broker 节点 hang 情况)。
3. Kafka 节点丢失分析
在经过以上客户端、服务端的常规优化之后,集群也正常运行一周。发现有一个 broker 节点丢失,JVM 指标数据丢失,进程不存在。

a) 丢失分析
需要通过/var/run/kafka/kafka.pid
获知之前进程的 pid,找到hs_err_pid21213.log
文件。从文件中指示,系统内存不够,其实通过监控可以发现当时系统内存(384g)充足。

在这个 core dump 文件中,JNI 会调用 os::pd_create_stack_guard_pages 来分配内存页,通过 os::Linux::commit_memory_impl 函数最终会调用 mmap 系统映射。

b) 分析 GC
检查 grafana 监控指标以查找进程内存使用情况的线索。通过下图中的 gc 监控情况,可以发现有个别机器 gc 后内存占用明显减少,甚至可以观察到 broker 明显重启。此时我们可以观察到 gc 异常的 broker 已经 crash 了,可以判断 crash 可能和 gc 有关。

通过分析 gc 日志,full gc 之前的 YoungGen 和 old OldGen 使用率不高,gc 的次数也不是很频繁,所以 GC Locker 基本不可能,所以最有可能是 System GC。那么 System GC 什么时候会发生呢?
○ 显式代码调用。
○ RMI(远程方法调用)中的定时调用。
○ 由于堆外内存不足而调用。
这些情况基本可以排除。通过查看 kafka 代码,没有发现 System GC 调用。1)RMI 也是不可能的,看不到 GC Deamon 线程,所以没有 RMI 调用。2)可以排除 DirectByteBuffer 堆外内存满引起的 System GC。
c) 确定根本问题
所以查看了 JDK 代码以查找可能引发 System GC 的情况。在 sun.nio.ch.FileChannelImpl.map0 发现了类似的逻辑,Java_sun_nio_ch_FileChannelImpl_map0 的 native 方法实现,这可能是触发 crash 的地方,然后我们看下面的逻辑。由于崩溃确实引发了 OOM 异常,可以确定 mmap 返回的 errno 是 ENOMEM。

ENOMEM 的描述:1)没有可用的内存 2)将超过进程的最大映射数。物理节点是有足够的物理内存,所以只能怀疑是否已达到最大映射数。

经过以上分析过程,确定问题所在。kafka 做了很多索引文件的内存映射,这些索引文件一直在占用内存没有释放,随着索引文件数量的增加慢慢达到内存限制。创建索引文件时,都会触发 mmap 系统调用,在 mmap 期间检查是否达到了最大限制,即/etc/sysctl.conf 中的 vm.max_map_count 的值 262144,我们可以进行增大 max_map_count 的值来解决问题。
分析这个问题是一个系统工程,经过几次的优化,集群已趋于稳定,我们也持续在关注。
评论