前面《Consumer 为什么必须调用 poll()》已经看到,处理太慢会让提交失败。这篇换一个视角,看"被踢出"这件事发生的时间线:一个消费者拿到数据后处理 15 秒,另一个同组的备用消费者在旁边等着。记录备用消费者是在什么时刻拿到分区的、拿到的数据和原来那个消费者手里的是不是同一批、原来那个消费者最终收到什么通知。所有消费者设置 max.poll.interval.ms=6000、session.timeout.ms=45000、heartbeat.interval.ms=1000,让这两个超时值差得足够远,看谁在起作用。
命令 · java // topic poll-demo: 1 分区,2000 条;同一个 group.id,group.protocol=classic // A:poll 拿到 100 条后 sleep 15 秒模拟处理,之后 commitSync // B:A 拿到数据后立刻启动,不断 poll,记录第一次拿到数据的时刻和起始 offset
--- 运行 1 --- [ 8847ms] A poll 到 100 条,起始 offset=0;开始处理 15 秒 [ 8889ms] >>> 启动备用消费者 B(同组) [14866ms] B assigned 1 <- 距 A 的 poll 6019ms [14874ms] B 第一次 poll 到数据:100 条,起始 offset=0 --- 运行 2 --- [ 8594ms] A poll 到 100 条,起始 offset=0;开始处理 15 秒 [ 8685ms] >>> 启动备用消费者 B(同组) [14679ms] B assigned 1 <- 距 A 的 poll 6085ms [14691ms] B 第一次 poll 到数据:100 条,起始 offset=0
两次运行里,B 拿到唯一那个分区的时间都比 A 最后一次 poll() 晚约 6 秒(6019ms、6085ms),正好是 max.poll.interval.ms=6000,而 session.timeout.ms=45000 完全没有起作用(要等 45 秒的话,B 应该在 54 秒之后才能拿到)。这说明触发"踢出"的是 max.poll.interval.ms,而不是会话超时:会话超时是 45 秒,6 秒时远没到。我没有抓取 A 的心跳请求,所以"A 的心跳一直正常"只是按配置(heartbeat.interval.ms=1000)和 45 秒会话超时没有触发做出的推断。
同样的输出里:
[14874ms] B 第一次 poll 到数据:100 条,起始 offset=0 ...(A 仍在处理,直到 23848ms 左右) [23859ms] A commitSync 失败: CommitFailedException [23862ms] A LOST 1
B 拿到的第一批数据起始 offset 是 0,和 A 手里那批的起始 offset 相同(A 从未成功提交过,所以这个分区的已提交位置还是起点)。从 14874ms 到 23848ms 左右,A 和 B 同时拥有 offset 0 到 99 这一批数据并各自在"处理",持续约 9 秒。A 处理完之后 commitSync() 失败(CommitFailedException),并且 A 收到的通知是 onPartitionsLost(LOST 1),而不是通常的 onPartitionsRevoked。也就是说,A 到这时才知道自己的分区早就没有了。在这之前的 9 秒里,它对此一无所知,如果处理动作有外部副作用(写数据库、发通知),这 100 条就会被两个消费者各处理一遍。B 后面出现的 revoked 1 是我的测试代码在拿到第一批后就关闭了 B,不是 rebalance 的另一个原因。
max.poll.interval.ms 是一个独立于心跳、会话超时的"处理进度"看门狗:心跳正常也会被踢,被踢出后分区会在大约这个时间长度之后交给别的成员,导致同一批数据被重复处理;被踢的消费者是在处理完之后调用 commitSync 时才通过 CommitFailedException 和 onPartitionsLost 得知的。这次实验里的重叠处理窗口约 9 秒,等于处理耗时减去超时上限。
每一步的时间戳都是本文运行两个同组Java Consumer得到的原始日志。