kafka_rebalance过长问题排查_request joining group due to: group is already reb

问题简介

  最近kafka集群频繁出现了长时间rebalance(耗时5min级别)，kafka在rebalance期间对应的consumer group中的consumer都是无法poll()下来数据的，导致consumer消费kafka当中数据出现了较大的延迟。

使用场景

a,b,c 三个consumer同属于一个group test_scheduled
但是a,b都是定时任务型的,c是持续消费的。

比如a在13:10:00启动，每隔3个小时启动一次
b在13:15:00 启动，每隔3小时启动一次
定时任务的consumer 在处理完任务后会暂停，调用的是pause方法

consumer.pause(partitionList)
/**
 * @see KafkaConsumer#pause(Collection)
 *public void pause(Collection<TopicPartition> partitions);
 */
   
1
2
3
4
5
6

consumer的设置是

        props.put("enable.auto.commit", "true");
        props.put("auto.commit.interval.ms", 1000);
        props.put("session.timeout.ms", 120000);
        props.put("max.poll.interval.ms",600000);
        props.put("max.poll.records", 100);
        props.put("key.deserializer", "org.apache.kafka.common.serialization.StringDeserializer");
        props.put("value.deserializer", "org.apache.kafka.common.serialization.StringDeserializer");
1
2
3
4
5
6
7

这个时候在某些情况下可能会导致rebalance的时间过长
具体的情景是
a在13:10:00启动 这个时候进行了一次rebalance，很快（秒级），但是a只花费了不到1分钟就把kafka里面积攒了3个小时的数据处理完了，所以a在13:10:05 进入了pause()

当时间到达了13:15:00 的时候后b启动了，这个时候又触发了rebalance,但是这个时候的rebalance直到
13:20:00 才能结束 （通过日志查看是在a 在max.poll.interval.ms过期的时候离开test_scheduled 然后rebalance 结束）

server.log中的有用信息有

rebalance的开始和结束
[2019-02-18 13:15:00,015] INFO [GroupCoordinator 2]: Preparing to rebalance group test_scheduled with old generation 702 (__consumer_offsets-4) (kafka.coordinator.group.GroupCoordinator)
...

2019-02-18 13:20:00,245] DEBUG [GroupCoordinator 2]: Member consumer-68-e26f835f-4e14-4e3e-9768-8dbdbeac06f3 in group test_scheduled has left, removing it from the group (kafka.coordinator.group.GroupCoordinator)
[2019-02-18 13:20:00,245] INFO [GroupCoordinator 2]: Stabilized group test_scheduled generation 703 (__consumer_offsets-4) (kafka.coordinator.group.GroupCoordinator)

1
2
3
4
5
6
7

client端的一些信息
a离开group的信息

2019-02-18 13:20:00.243		kafka-coordinator-heartbeat-thread | test_scheduled	DEBUG	org.apache.kafka.clients.consumer.internals.AbstractCoordinator :183	[Consumer clientId=consumer-68, groupId=test_scheduled] Sending LeaveGroup request to coordinator 10.9.17.46:9092 (id: 2147483645 rack: null)
2019-02-18 13:20:00.244		kafka-coordinator-heartbeat-thread | test_scheduled	DEBUG	org.apache.kafka.clients.consumer.internals.AbstractCoordinator :177	[Consumer clientId=consumer-68, groupId=test_scheduled] Disabling heartbeat thread

1
2
3

同时，上面的问题只是一部分情况，有些时候并不在定时任务启动或者离开的时候也会发生很多次rebalance，但是相对来说快一些，有些也达到几十秒。

原因分析

  为了解决以上问题，调研了一下kafka consumer的原理，下面主要围绕几个重要的配置项展开。

session.timeout.ms      默认10000ms
heartbeat.interval.ms	默认3000ms
max.poll.interval.ms    默认300000ms
max.poll.records        默认500条
1
2
3
4

   session.timeout.ms是consumer和kafka server维持一个会话的时间，也就是说consumer和server之间通信的间隔时间最长是这些，超过这个时间的话server就认为consumer不可用，会被从consumer group当中踢掉。因为现在consumer有一个专门的heartbeat后台线程来维持心跳，默认的时间间隔是 heartbeat.interval.ms 默认3000ms,所以这个配置不用担心

  max.poll.interval.ms是consumer在两次poll()之间的最大时间间隔，超过这个时间配置的consumer都会被从consumer group 当中踢掉。这样的话，在两次poll()中间的数据处理时间久需要控制了。默认的时间是 300000，也就是5分钟,同时每次拉下来的数据条数受max.poll.records控制,默认最多为500条。

  回过头来看我们系统情况，我们的数据有些关联数据比较多，可能存在一个批次的数据消费处理时间超过5min。在这种理论基础上，我们将max.poll.interval.ms加大，同时将max.poll.records减小到100，这个时候再观察，发现rebalance的次数明显下降，从原来的每小时30次下降到7次左右。
  但是rebalance耗时比较长的情况仍然存在。这个时候考虑是因为定时任务的启动和结束导致的rebalance，但是为何rebalance耗时5分钟仍然是不可理解的。
后面在kafka的官方文档中有这个的配置:rebalance.timeout.ms文档上介绍的就是rebalance会等待consumer 发起join-group请求的最大时长，默认是60s,但是这个配置是针对的kafka-connect的，不是我们这里的。

进一步探索

多方查找不得结果，最后只能看代码了。

先看server端设置超时的代码

对应源码点击这里

  private def prepareRebalance(group: GroupMetadata, reason: String) {
    // if any members are awaiting sync, cancel their request and have them rejoin
    if (group.is(CompletingRebalance))
      resetAndPropagateAssignmentError(group, Errors.REBALANCE_IN_PROGRESS)

    val delayedRebalance = if (group.is(Empty))
      new InitialDelayedJoin(this,
        joinPurgatory,
        group,
        groupConfig.groupInitialRebalanceDelayMs,
        groupConfig.groupInitialRebalanceDelayMs,
        max(group.rebalanceTimeoutMs - groupConfig.groupInitialRebalanceDelayMs, 0))
    else
      //因为我们发生rebalance的时候一般情况下group不是enpty,所以大多数走的是这个，
      // 可以看到这里用的是group.rebalanceTimeoutMs
      new DelayedJoin(this, group, group.rebalanceTimeoutMs)

    group.transitionTo(PreparingRebalance)

    info(s"Preparing to rebalance group ${group.groupId} in state ${group.currentState} with old generation " +
      s"${group.generationId} (${Topic.GROUP_METADATA_TOPIC_NAME}-${partitionFor(group.groupId)}) (reason: $reason)")

    val groupKey = GroupKey(group.groupId)
    joinPurgatory.tryCompleteElseWatch(delayedRebalance, Seq(groupKey))
  }
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26

从上面的代码中可以看到
这里用的是group.rebalanceTimeoutMs,感觉没啥问题
下面再看看group.rebalanceTimeoutMs具体的实现

对应源码点击这里
在GroupMetadata.scala文件当中

private val members = new mutable.HashMap[String, MemberMetadata]

def rebalanceTimeoutMs = members.values.foldLeft(0) { (timeout, member) =>
    timeout.max(member.rebalanceTimeoutMs)
  }
1
2
3
4
5

从上面可以看出group.rebalanceTimeoutMs是去group中所有consumer的最大的member.rebalanceTimeoutMs
对应的server段在prepare阶段设置的超时时间就是使用的max{consumer.rebalanceTimeoutMs}
对应的member则是MemberMetadata

class MemberMetadata(val memberId: String,
                     val groupId: String,
                     val clientId: String,
                     val clientHost: String,
                     val rebalanceTimeoutMs: Int,
                     val sessionTimeoutMs: Int,
                     val protocolType: String,
                     var supportedProtocols: List[(String, Array[Byte])])
1
2
3
4
5
6
7
8

这里对应的就是每个consumer自己设定的rebalanceTimeoutMs

server端排查了一番，问题不大，而且使用的参数也是consumer传递过来的。那么下面就要看看consumer端的实现了。

consumer 端的rebalanceTimeoutMs

AbstractCoordinator.sendJoinGroupRequest()中有往server端发送request时候设置的
rebalanceTimeout

    /**
     * Join the group and return the assignment for the next generation. This function handles both
     * JoinGroup and SyncGroup, delegating to {@link #performAssignment(String, String, Map)} if
     * elected leader by the coordinator.
     * @return A request future which wraps the assignment returned from the group leader
     */
    private RequestFuture<ByteBuffer> sendJoinGroupRequest() {
        if (coordinatorUnknown())
            return RequestFuture.coordinatorNotAvailable();

        // send a join group request to the coordinator
        log.info("(Re-)joining group");
        JoinGroupRequest.Builder requestBuilder = new JoinGroupRequest.Builder(
                groupId,
                this.sessionTimeoutMs,
                this.generation.memberId,
                protocolType(),
                //这里设置的rebalanceTimeoutMs
                metadata()).setRebalanceTimeout(this.rebalanceTimeoutMs);

        log.debug("Sending JoinGroup ({}) to coordinator {}", requestBuilder, this.coordinator);
        return client.send(coordinator, requestBuilder)
                .compose(new JoinGroupResponseHandler());
    }

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26

那么coordinator中的rebalanceTimeoutMs又是从哪里设置的呢，这个可以从其构造函数中进行追溯。

    /**
     * Initialize the coordination manager.
     */
    public AbstractCoordinator(LogContext logContext,
                               ConsumerNetworkClient client,
                               String groupId,
                               int rebalanceTimeoutMs,
                               int sessionTimeoutMs,
                               int heartbeatIntervalMs,
                               Metrics metrics,
                               String metricGrpPrefix,
                               Time time,
                               long retryBackoffMs,
                               boolean leaveGroupOnClose) {
        this.log = logContext.logger(AbstractCoordinator.class);
        this.client = client;
        this.time = time;
        this.groupId = groupId;
        this.rebalanceTimeoutMs = rebalanceTimeoutMs;
        this.sessionTimeoutMs = sessionTimeoutMs;
    }

 /**
     * Initialize the coordination manager.
     */
    public ConsumerCoordinator(LogContext logContext,
                               ConsumerNetworkClient client,
                               String groupId,
                               int rebalanceTimeoutMs,
                               int sessionTimeoutMs,
                               int heartbeatIntervalMs,
                               List<PartitionAssignor> assignors,
                               Metadata metadata,
                               SubscriptionState subscriptions,
                               Metrics metrics,
                               String metricGrpPrefix,
                               Time time,
                               long retryBackoffMs,
                               boolean autoCommitEnabled,
                               int autoCommitIntervalMs,
                               ConsumerInterceptors<?, ?> interceptors,
                               boolean excludeInternalTopics,
                               final boolean leaveGroupOnClose) {
        super(logContext,
              client,
              groupId,
              rebalanceTimeoutMs,
              sessionTimeoutMs,
              heartbeatIntervalMs,
              metrics,
              metricGrpPrefix,
              time,
              retryBackoffMs,
              leaveGroupOnClose);
    }



1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58

实际的赋值动作中设置consumer实例的rebalanceTimeoutMs的时候使用的是max.poll.interval.ms
而不是 rebalance.timeout.ms

         this.coordinator = new ConsumerCoordinator(logContext,
                    this.client,
                    groupId,
                    config.getInt(ConsumerConfig.MAX_POLL_INTERVAL_MS_CONFIG),
                    config.getInt(ConsumerConfig.SESSION_TIMEOUT_MS_CONFIG),
                    config.getInt(ConsumerConfig.HEARTBEAT_INTERVAL_MS_CONFIG),
                    assignors,
                    this.metadata,
                    this.subscriptions,
                    metrics,
                    metricGrpPrefix,
                    this.time,
                    retryBackoffMs,
                    config.getBoolean(ConsumerConfig.ENABLE_AUTO_COMMIT_CONFIG),
                    config.getInt(ConsumerConfig.AUTO_COMMIT_INTERVAL_MS_CONFIG),
                    this.interceptors,
                    config.getBoolean(ConsumerConfig.EXCLUDE_INTERNAL_TOPICS_CONFIG),
                    config.getBoolean(ConsumerConfig.LEAVE_GROUP_ON_CLOSE_CONFIG));
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18

哭晕在厕所…

解决方案

将定时任务的consumer单独放在一个分组consumer-group，因为定时任务对rebalance时间的延迟不敏感，这样的话就不会影响实时消费的consumer了，同时建议max.poll.interval.ms 不要设置的太长，否则会影响kafka的rebalance,导致rebalance的耗时过长。如果任务确实比较耗时的话也应该设置为异步处理然后手动提交的方式，同时在consumer端设置pause，避免导致活锁。