排查分析cpu飙到200%问题(log4j2+kafka日志输出导致)

前言:本文主要介绍排查分析Java应用log4j2+kafka日志输出导致cpu飙到200%问题的过程。

备注:因为排查问题时没有记录到对应每个步骤的截图,所以下面部分图片是解决问题后,在正常的机器环境下截取的。

1、使用 top 命令,查看占用cpu高的进程pid。出现问题时,可以看到%CPU列显示大于100%。PID为进程ID。

排查分析cpu飙到200%问题(log4j2+kafka日志输出导致)

2、使用 ps -mp PID -o THREAD,tid,time | sort -rn 命令,查找进程对应的线程ID,并查找出对应的占用CPU时间。当时故障现场是存在大量线程占用CPU时间为1分钟左右。这里注意,大量线程,并且阻塞时间都差不多,根据经验,可以往阻塞时间方向去思考问题。因为CPU占用过高,最经典的是两种原因:线程死循环和阻塞。因为这里是大量线程出现问题,并且时间都是1分钟左右,时间比较短,所以猜测是阻塞。如果占用时间很长,例如达到30分钟以上,就很大可能是线程死循环导致。

排查分析cpu飙到200%问题(log4j2+kafka日志输出导致)

3、使用 printf "%x\n" TID 命令,将十进制线程ID转换为十六进程,因为在线程堆栈日志中,记录的线程ID为十六进制。

排查分析cpu飙到200%问题(log4j2+kafka日志输出导致)

4、使用 jstack PID | grep TID -A 30 命令,查看线程堆栈日志。打印线程堆栈信息后,可以看到线程阻塞在detect()方法中,于是就直接从代码入手继续排查。

排查分析cpu飙到200%问题(log4j2+kafka日志输出导致)

5、打开代码中的detect()方法,发现这里只是简单调用Logger.info()打印一段日志,大家应该跟我一样,一脸懵逼?为什么只是打印一段日志,会导致线程阻塞呢?这时就需要继续挖掘log4j2的源码了。

排查分析cpu飙到200%问题(log4j2+kafka日志输出导致)

6、 查看log4j2配置文件发现,detect()方法对应的类的日志appender为feignKafkaAppender,对应使用了log4j2默认的Kafka plugin,于是继续分析log4j2源码中的KafkaAppender类。排查分析cpu飙到200%问题(log4j2+kafka日志输出导致)

7、分析log4j2源码中的KafkaAppender类

7.1、查看org.apache.logging.log4j.core.appender.mom.kafka.KafkaAppender#append方法,调用了org.apache.logging.log4j.core.appender.mom.kafka.KafkaAppender#tryAppend方法。

排查分析cpu飙到200%问题(log4j2+kafka日志输出导致)

 7.2、查看org.apache.logging.log4j.core.appender.mom.kafka.KafkaAppender#tryAppend方法,调用了org.apache.logging.log4j.core.appender.mom.kafka.KafkaManager#send方法,

 排查分析cpu飙到200%问题(log4j2+kafka日志输出导致)

7.3、查看org.apache.kafka.clients.producer.KafkaProducer#send(org.apache.kafka.clients.producer.ProducerRecord<K,V>, org.apache.kafka.clients.producer.Callback)方法,调用了org.apache.kafka.clients.producer.KafkaProducer#doSend方法 

排查分析cpu飙到200%问题(log4j2+kafka日志输出导致)

7.4、查看org.apache.kafka.clients.producer.KafkaProducer#doSend方法,在该方法中,调用了org.apache.kafka.clients.producer.KafkaProducer#waitOnMetadata,看到了wait字眼,瞬间觉得离真相不远了哈哈。

排查分析cpu飙到200%问题(log4j2+kafka日志输出导致)

7.5、查看org.apache.kafka.clients.producer.KafkaProducer#waitOnMetadata方法,发现在该方法中,会根据kafka topic循环去获取partitionsCount,如果获取不到,则阻塞等待变量maxWaitMs毫秒数。因为该变量是传递进来了,于是往上查找该变量对应的值,对应的是this.maxBlockTimeMs变量。

排查分析cpu飙到200%问题(log4j2+kafka日志输出导致)

7.6、继续查找this.maxBlockTimeMs变量,发现初始化时,调用了config.getLong("max.block.ms")方法来初始化默认值。因为该配置属于kafka的默认配置,于是可以通过kafka官网文档查找该变量对应的默认值。

排查分析cpu飙到200%问题(log4j2+kafka日志输出导致)

8、打开kafka官网文档,http://kafka.apache.org/documentation.html#producerconfigs,查找max.block.ms变量,发现默认值为60000毫秒(1分钟)。这时已经接近真相了,跟步骤2查看到的大量线程阻塞1分钟左右完全匹配,剩下就是排查为什么步骤7.5中获取topic对应partitionsCount会失败的问题了。

排查分析cpu飙到200%问题(log4j2+kafka日志输出导致)

9、至于为什么步骤7.5获取topic对应partitionsCount失败?这个属于内部技术实现的问题了,因为该日志组件属于公司公用的组件,使用该日志组件的服务都是部署在公司内部机房的,都有对应的kafka环境,因为出现问题的服务,属于子公司的项目,对应应用部署在阿里云机器的,这个项目借助了该日志组件,使用其部分功能,没有用到其输出日志到kafka功能,就没有部署kafka环境。所以出现了kafka阻塞导致机器cpu飙升的问题了。对应解决办法就是日志组件增加多一个log4j2配置文件,移除对应的kafka appender,即可解决问题。