Kafka消息发送致接口超时原因分析与解决

一、现象

在某个下午IM突然弹出告警，提示某核心接口出现超过3秒的慢调用。根据告警打开云日志，发现总共有31条超过3秒的调用： 慢调用会长时间占用宝贵的线程资源，拖慢整个应用响应，对系统危害极大，需要对它进行治理。

二、问题定位

1、apm监控

根据日志中的traceId查看apm监控，如下所示：       从监控上可以看到该请求总共耗时4070ms，下面对各个步骤做个拆解：

• 第1步幂等处理总耗时3ms;
• 第2步黑名单查询耗时4ms;
• 第3步落库持久化耗时2ms；
• 第4步redis操作耗时2ms;
• 第5步推送kafka，未看到具体耗时，但占用绿色线段较短（线段越长代表耗时越长）;
• 第6步推送kafka到风控，同样未看到具体耗时，但绿色线段较短；

各个步骤耗时极短，但整体耗时达到秒级别，时间耗在哪儿了？在疑惑的时候发现一个奇怪的地方：第一次推送完kafka和第二次开始推送kafka之间的时间间隔比较大，将链路追踪切到表格样式如下所示：

从表格中可以看到在11:36:34第一次发送kafka，11:36:38第二次发送Kafka，说明第一次发送后有差不多4秒时延，此时业务线程在干什么？会不会是因为jvm gc造成服务的暂停？

2、gc监控

      从监控上看到11:36左右无gc异常，无长暂停，因此排除gc带来的影响。

3、kafka监控

从监控上看到11:36左右无gc异常，无长暂停，因此排除gc带来的影响。通过以上分析可以得出接口超时是由推送kafka引起，存在两个疑点待解释：

• 为什么Kafka发送耗时这么久？
• 为什么apm上采集kafka耗时和实际发送耗时对不上（apm监控未能展示真实的发送耗时）？

三、问题分析

1、kafka发送耗时分析

kafka发送流程

以上流程可以拆解成以下几步：

• 消息经过拦截器、序列化、分区、更新元信息等处理；

• 从内存池中申请内存，如果申请大小为标准16kb则从free空闲内存列表中获取，否则从内存池中剩余的内存中申请。如果未申请到足够内存，则阻塞等待其他消息完成发送完后释放内存； RecordAccumulator将发送内容组成RecordBatch加入dequeue，同时返回future;

• 发送方调用future.get()进行阻塞等待；

• sender线程从dequeue中拉取可发送消息组成clientRequest，然后交给networkClient发送给kafka broker；

• 如果发送后需要等待服务端响应，则需要等到服务端响应后，通过回调callback终止future等待；      阻塞点分析

• A. 元数据更新：网络畅通，基本可以排除；
• B. 批量发送：批量发送作为kafka中间件高性能的关键设计，聚合发送消息可以提升发送效率，但目前linger.ms为5毫秒，因此可以判断批量发送最多导致有5ms的延时，不会存在秒级的时延，基本可以排除；
• C.申请内存阻塞：内存池作为Kafka亮点设计，通过复用内存降低gc压力。如果sender线程未能快速将消息发送出去或未及时收到响应，则前面消息占用的内存无法释放，会造成申请内存阻塞，造成接口超时，存在这种可能性；
• D.ack参数：ack=0代表无需等待服务端响应，sender线程中会快速返回；ack=1代表消息需要得到服务端所有副本中leader节点确认才返回；ack=all代表消息需要在服务端所有副本确认才能返回。目前客户端ack设置成1，则代表需要等待服务端leader节点的确认。

从以上分析可以看出客户端发送性能受kafka服务端性能影响，影响服务端性能的因素较多，比如网络、硬件、磁盘性能、读写qps等。目前ack=1，对客户端来说服务端性能基本不可控。

2、skwalking采集kafka发送耗时

skywalking通过java agent对监控方法进行增强实现耗时的采集，采用插件机制快速适配各种中间件，因此先找到增强类kafka-plugin：

public class KafkaProducerInstrumentation extends AbstractKafkaInstrumentation {
    public static final String ENHANCE_CLASS = "org.apache.kafka.clients.producer.KafkaProducer";
    public static final String ENHANCE_METHOD = "doSend";
 
    @Override
    public ConstructorInterceptPoint[] getConstructorsInterceptPoints() {
        return new ConstructorInterceptPoint[]{
            new ConstructorInterceptPoint() {
                @Override
                public ElementMatcher<MethodDescription> getConstructorMatcher() {
                    return takesArgumentWithType(0, CONSTRUCTOR_INTERCEPTOR_FLAG);
                }

                @Override
                public String getConstructorInterceptor() {
                    return CONSTRUCTOR_INTERCEPTOR_CLASS;
                }
            }
        };
    }

    @Override
    public InstanceMethodsInterceptPoint[] getInstanceMethodsInterceptPoints() {
        return new InstanceMethodsInterceptPoint[]{
            new InstanceMethodsInterceptPoint() {
                @Override
                public ElementMatcher<MethodDescription> getMethodsMatcher() {
                    return named(ENHANCE_METHOD);
                }

                @Override
                public String getMethodsInterceptor() {
                    return INTERCEPTOR_CLASS;
                }

                @Override
                public boolean isOverrideArgs() {
                    return false;
                }
            }
        };
    }

    @Override
    protected ClassMatch enhanceClass() {
        return byName(ENHANCE_CLASS);
    }
}

public void sendBytes(String topic, byte[] message) {
        Future future = doSend(topic, null, message);
        doGet(future);
    }

   private void doGet(Future future) {
        try {
            future.get();
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        } catch (ExecutionException e) {
            throw new RuntimeException(e);
        }
    }

通过ENHANCE_CLASS和ENHANCE_METHOD可以看到skywalking是对KafkaProducer中doSend方法进行增强即apm采集的是donSend耗时，doSend方法返回类型为Future接口，apm未采集业务调用future.get()阻塞等待耗时，因此可以解释apm采集到的耗时非常短但实际耗时比较长，kafka真正发送耗时应该是发送开始时刻与下一步骤开始执行时刻的差值。

三、解决方案

经过以上分析得出ack=1时客户端性能深受服务端影响，为了保障客户端核心接口性能，此处选择xx。通过额外的手段保证数据的准确性。

1、兜底重试机制

• A、推送kafa前先将数据存入redis zset，为了防止大key，根据xx按分片策略（比如计算key的哈希值对分片数进行取模）进行分片生成不同的redis key，value为推送kafka的消息内容，score为当前时间戳加上过期时间（比如3分钟，此处将redis当作延时队列使用）；

• B、消费方收到推送消息后，携带业务字段步调用生产方callback接口，同时消费端根据券号实现幂等。

• C、生产方callback接口收到请求后，根据券号找到redis key，然后再从zset中删除数据。如果未成功删除，则需要再到mysql中删除数据（因为数据可能已经转移到mysql）。

• D、定时任务1用于遍历redis zset中的key，筛选出分数小于当前时间戳的数据（表示数据已过期）转移到mysql，降低redis存储压力；

• E、定时任务2用于重推kafka，从mysql读取数据重新推送，达到一定推送次数后不再推送；

• F、为了节约存储，引入Snappy压缩算法对内容进行压缩，节约内存。

2、功能实现

重试表设计

CREATE TABLE `retry_push_record` (
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `key` varchar(40) DEFAULT NULL COMMENT '关键业务字段',
  `send_message` varchar(2048) DEFAULT NULL COMMENT '发送内容',
  `retry_times` int(11) DEFAULT '0' COMMENT '重试次数',
  `create_by` varchar(50) DEFAULT NULL COMMENT '创建人名称',
  `create_time` datetime DEFAULT CURRENT_TIMESTAMP COMMENT '创建时间',
  `update_by` varchar(50) DEFAULT NULL COMMENT '修改人',
  `update_time` datetime DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP COMMENT '更新时间',
  `retry_type` int(11) DEFAULT NULL COMMENT '类型',
  PRIMARY KEY (`id`),
  KEY `idx_key` (`key`) USING BTREE
) ENGINE=InnoDB  COMMENT='重推记录表';

redis存储实现

public void saveSendCoupon(String shardingKey, String content) {
        boolean needSaveDb = false;
        if (getSaveRedisSwitch()) {
            try {
                String useCouponKey = String.format(getRedisPrefix(), shardingStrategy.shardingKey(shardingKey, Constant.SHARDING_NUM));
                //当前时间+延时3分钟
                double score = System.currentTimeMillis() + 1000 * getExpireTime();
                sfRedisUtil.zSetAdd(useCouponKey, content, score);
            } catch (Exception e) {
                //如果存入redis异常则直接落库
                needSaveDb = true;
                log.error("saveSendCoupon2Redis error,param:{}", content, e);
            }
        }
        //如果异常或者存入redis开关没打开则
		if(needSaveDb){
		 saveDb(content)
		}
}

四、效果  

该优化方案上线后该核心接口每周超时量从300条左右降到2条左右，经计算，97%的callback删除都在redis中完成，达到预期目的。

四、总结

 借助apm、gc监控等定位到发券接口超时由kafka发送超时引起，经过分析后引出两个疑问：A、apm为什么未能精准采集kafka发送耗时，此疑问通过skywalking中插件源码得以解释；B、kafka发送超时的原因。通过梳理kafka client端发送流程中可能存在的阻塞点，服务端性能会影响客户端。

在服务端不可控的情况，因此提出要将ack设置成0，同时引入额外的重试机制保证数据的完整性。通过两者的结合既能保证接口的性能同时也能保证数据的完整性，重试机制设计中的亮点如下：

• 引入redis作为中转站实现数据的快速存储，同时提升callback接口删除数据的响应效率；

• 依据券号通过分片策略进行分片，降低每个zset key存储的元素个数，避免出现大key；

• 引入Snappy对存储内容进行压缩，节约存储内存；

• 引入callback+重试机制实现数据的完整性；