Kafka(五)----记一次Kafka实时ETL程序CPU占用率过高的线上问题排查

最新推荐文章于 2024-07-09 20:53:22 发布

new个对象先

最新推荐文章于 2024-07-09 20:53:22 发布

阅读量4.9k

点赞数 2

分类专栏： Kafka 大数据开发

本文链接：https://blog.csdn.net/weixin_40861707/article/details/102465838

版权

大数据开发同时被 2 个专栏收录

36 篇文章 3 订阅

订阅专栏

Kafka

9 篇文章 5 订阅

订阅专栏

Kafka实时ETL程序CPU占用率过高的线上问题排查

本篇博客要点如下:

问题描述
问题排查

Kafka Manager界面查看基本信息
CPU占用率过高问题定位

问题解决

一. 问题描述

收到运维电话反馈,Kafka实时ETL程序部署的机器CPU占用率居高不下.
同时,每天的定时邮件校验数据条数与源端存在较大差异.
邮件内容如下 : 其中,第一列展示的数据是源端,后面的两列则是实时ETL写入的数据,
可以看到,这里的差距还是有点大的!
在这里插入图片描述

二. 问题排查

2.1 通过Kafka Manager,通过界面了解基本信息

首先登录kafka manager发现程序对应的消费者组存在比较高的偏移量堆积,
证明是程序性能出现了严重问题
在这里插入图片描述

2.2 CPU占用率过高问题定位

2.2.1 问题进程定位

使用top命令,查看程序部署机器的cpu状态:

通过下面的图片可以看到.
PID为312463进程的CPU使用率高到了恐怖的 2649!
在这里插入图片描述

2.2.2 问题线程定位

通过上一步,我们得到了异常进程的PID为312463,
接下来,我们要找到这个进程里面异常的线程情况:

使用命令,命令格式如下:

ps -mp <pid> -o THREAD,tid,time

查看这个进程每个线程的详细信息
具体命令如下:

ps -mp 312463 -o THREAD,tid,time

在这里插入图片描述
部分执行结果如下图所示 :

上图中显示的结果是很恐怖的,
有20个左右的线程明显异常,平均每个线程大约占用75%的cpu资源,并且占用的资源迟迟不进行释放!

2.2.3 问题线程堆栈信息

我们从异常线程中选取一个进行分析,选取线程的:

TID为:312621,使用printf “%x\n” tid命令将TID转换为16进制

printf "%x\n" 312621
4c52d

使用jstack命令打印线程堆栈信息，
命令格式：

jstack pid |grep tid -A 100

打印出该线程的堆栈信息

jstack 312463|grep 4c52d -A 100

执行结果如下(篇幅所限,最下面的非关键堆栈信息我没有截取):

"org.springframework.kafka.KafkaListenerEndpointContainer#0-28-C-1" #124 prio=5 os_prio=0 tid=0x00007f2c1a16f660 nid=0x4c52d runnable [0x00007f2b310ce000]
   java.lang.Thread.State: RUNNABLE
	at org.springframework.beans.PropertyMatches.calculateStringDistance(PropertyMatches.java:159)
	at org.springframework.beans.PropertyMatches.access$100(PropertyMatches.java:43)
	at org.springframework.beans.PropertyMatches$BeanPropertyMatches.calculateMatches(PropertyMatches.java:207)
	at org.springframework.beans.PropertyMatches$BeanPropertyMatches.<init>(PropertyMatches.java:192)
	at org.springframework.beans.PropertyMatches.forProperty(PropertyMatches.java:67)
	at org.springframework.beans.PropertyMatches.forProperty(PropertyMatches.java:57)
	at org.springframework.data.mapping.PropertyReferenceException.detectPotentialMatches(PropertyReferenceException.java:149)
	at org.springframework.data.mapping.PropertyReferenceException.<init>(PropertyReferenceException.java:63)
	at org.springframework.data.mapping.PropertyPath.<init>(PropertyPath.java:94)
	at org.springframework.data.mapping.PropertyPath.create(PropertyPath.java:382)
	at org.springframework.data.mapping.PropertyPath.create(PropertyPath.java:416)
	at org.springframework.data.mapping.PropertyPath.create(PropertyPath.java:358)
	at org.springframework.data.mapping.PropertyPath.lambda$from$0(PropertyPath.java:311)
	at org.springframework.data.mapping.PropertyPath$$Lambda$621/393376017.apply(Unknown Source)
	at java.util.concurrent.ConcurrentMap.computeIfAbsent(ConcurrentMap.java:324)
	at org.springframework.data.mapping.PropertyPath.from(PropertyPath.java:293)
	at org.springframework.data.mongodb.core.convert.QueryMapper$MetadataBackedField.getPath(QueryMapper.java:953)
	at org.springframework.data.mongodb.core.convert.QueryMapper$MetadataBackedField.<init>(QueryMapper.java:837)
	at org.springframework.data.mongodb.core.convert.QueryMapper$MetadataBackedField.<init>(QueryMapper.java:814)
	at org.springframework.data.mongodb.core.convert.UpdateMapper$MetadataBackedUpdateField.<init>(UpdateMapper.java:289)
	at org.springframework.data.mongodb.core.convert.UpdateMapper.createPropertyField(UpdateMapper.java:249)
	at org.springframework.data.mongodb.core.convert.QueryMapper.getMappedObject(QueryMapper.java:141)
	at org.springframework.data.mongodb.core.convert.UpdateMapper.getMappedObject(UpdateMapper.java:67)
	at org.springframework.data.mongodb.core.convert.QueryMapper.convertSimpleOrDocument(QueryMapper.java:419)
	at org.springframework.data.mongodb.core.convert.QueryMapper.getMappedKeyword(QueryMapper.java:281)
	at org.springframework.data.mongodb.core.convert.QueryMapper.getMappedObject(QueryMapper.java:117)
	at org.springframework.data.mongodb.core.convert.UpdateMapper.getMappedObject(UpdateMapper.java:67)
	at org.springframework.data.mongodb.core.MongoTemplate$8.doInCollection(MongoTemplate.java:1566)
	at org.springframework.data.mongodb.core.MongoTemplate$8.doInCollection(MongoTemplate.java:1547)
	at org.springframework.data.mongodb.core.MongoTemplate.execute(MongoTemplate.java:535)
	at org.springframework.data.mongodb.core.MongoTemplate.doUpdate(MongoTemplate.java:1547)
	at org.springframework.data.mongodb.core.MongoTemplate.updateMulti(MongoTemplate.java:1537)
	at com.yspay.service.impl.HisDetailServiceImpl.updateOffLineTrade(HisDetailServiceImpl.java:250)
	at com.yspay.service.impl.HisDetailServiceImpl.doSave(HisDetailServiceImpl.java:127)
	at com.yspay.kaf_listener.HisDetailListener.listen0(HisDetailListener.java:39)
	at sun.reflect.GeneratedMethodAccessor78.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.messaging.handler.invocation.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:189)

从堆栈信息打印的情况来看,该线程是在执行到HisDetailServiceImpl这个类的第250行代码阻塞住的,即:

at com.yspay.service.impl.HisDetailServiceImpl.updateOffLineTrade(HisDetailServiceImpl.java:250)

阻塞住,把目光聚集到第250行代码

  ysdwMongoTemplate.updateMulti(query, update, HisDetailPojo.class, pospQueryCollectionName);

可以看到,这里是直接调用MongoTemplate类的updateMulti方法,
对符合条件的数据进行批量更新操作.

排查到这里我就产生了困惑,为什么直接调用源码的api会出现阻塞情况呢?
有没有可能仅仅是因为我打印堆栈信息的这个线程恰好执行到这里?

2.2.4 全部线程的堆栈信息

带着上面的疑问,我执行了如下命令,来输出问题进程全部线程的堆栈信息,命令如下:

jstack 312463 >> jstack.out

通过上面的命令,我把pid为312463进程的全部线程的堆栈信息输出到了jstack.out文件里.
取回该文件,进行分析后:
发现了可能异常线程的堆栈信息都是阻塞到了批量更新的updateMulti方法
因篇幅所限,只截取该文件的部分信息:

"kafka-coordinator-heartbeat-thread | qz_ysdw_03" #129 daemon prio=5 os_prio=0 tid=0x00007f2938001360 nid=0x4c532 in Object.wait() [0x00007f2b30bca000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at org.apache.kafka.clients.consumer.internals.AbstractCoordinator$HeartbeatThread.run(AbstractCoordinator.java:1039)
	- locked <0x00000000814b2910> (a org.apache.kafka.clients.consumer.internals.ConsumerCoordinator)

"org.springframework.kafka.KafkaListenerEndpointContainer#0-29-C-1" #128 prio=5 os_prio=0 tid=0x00007f2c1a18b090 nid=0x4c531 runnable [0x00007f2b30cca000]
   java.lang.Thread.State: RUNNABLE
	at org.springframework.beans.PropertyMatches.calculateStringDistance(PropertyMatches.java:159)
	at org.springframework.beans.PropertyMatches.access$100(PropertyMatches.java:43)
	at org.springframework.beans.PropertyMatches$FieldPropertyMatches.lambda$calculateMatches$0(PropertyMatches.java:242)
	at org.springframework.beans.PropertyMatches$FieldPropertyMatches$$Lambda$689/613056088.doWith(Unknown Source)
	at org.springframework.util.ReflectionUtils.doWithFields(ReflectionUtils.java:750)
	at org.springframework.util.ReflectionUtils.doWithFields(ReflectionUtils.java:729)
	at org.springframework.beans.PropertyMatches$FieldPropertyMatches.calculateMatches(PropertyMatches.java:240)
	at org.springframework.beans.PropertyMatches$FieldPropertyMatches.<init>(PropertyMatches.java:235)
	at org.springframework.beans.PropertyMatches.forField(PropertyMatches.java:86)
	at org.springframework.beans.PropertyMatches.forField(PropertyMatches.java:76)
	at org.springframework.data.mapping.PropertyReferenceException.detectPotentialMatches(PropertyReferenceException.java:148)
	at org.springframework.data.mapping.PropertyReferenceException.<init>(PropertyReferenceException.java:63)
	at org.springframework.data.mapping.PropertyPath.<init>(PropertyPath.java:94)
	at org.springframework.data.mapping.PropertyPath.create(PropertyPath.java:382)
	at org.springframework.data.mapping.PropertyPath.create(PropertyPath.java:416)
	at org.springframework.data.mapping.PropertyPath.create(PropertyPath.java:358)
	at org.springframework.data.mapping.PropertyPath.lambda$from$0(PropertyPath.java:311)

到这里,实际上已经基本确定问题所在

2.2.5 问题进程GC信息

接下来,查看下这个进程的GC信息
命令格式如下 :
jstat -gcutil pid count

具体执行命令如下 :

 jstat -gcutil 312463 10

显示pid为312463进程最近10次的gc情况:
在这里插入图片描述
可以看到,无论是新生代,老年代,Full GC的次数,还是GC时间,基本上都算是正常的

三. 问题解决

基于以上的分析,我们已经可以把问题缩小到MongoTemplate类的updateMulti方法,
是由于批量更新操作阻塞
导致的消费端数据堆积

首先,怀疑是Mongo集群异常

去查看了程序执行日志,发现日志里并没有出现,Mongo查询或者是插入耗时过长的情况.
同时,也没有收到运维同事关于Mongo服务器的告警邮件和电话,
证明Mongo集群在这段期间的服务一直是正常的!

排除了上述的嫌疑之后, 继续根据堆栈信息和日志,kafka-manager界面等信息,分析程序执行状况

发现了更加诡异的情形,
我程序里使用了30个线程进行消费.
其中有24个线程一直处于阻塞状态,
剩下的6个线程则一直处于正常的工作状态!
由于并发严重下降,才导致了消费堆积.

由于堆栈信息定位到的地方是源码的操作,同时程序的GC也算正常,因此,暂时没有考虑是代码的问题

那么就开始思考,实时ETL程序发生数据堆积前后,都进行了哪些操作.

于是我想到了,在这段时间,程序曾因种种原因被暴力的终止过,大约5分钟之后又重新启动
(理论上来说 : 我消费端设置的从最早的偏移量进行消费,所以不会出现数据丢失, 而且插入数据的时候,是按照主键进行插入,如果重复的话,会直接报主键冲突异常抛弃,所以也不会造成数据重复~)

但是,问题也恰恰出现在这里!!!

实际执行的时候,部分线程在进行对数据库批量更新的时候,被异常终止.
这批数据并没有处理完,按照我的消费策略,偏移量并没有提交.
当程序重新开始的时候,这部分未处理完的数据异常数据会重新执行一次批量更新的操作
两次发生的操作发生冲突,导致线程阻塞

既然问题定位到了这里,是不是我不继续针对这部分数据进行处理就能解决这个问题呢?
带着这个想法,我修改了配置文件,指定起始的时间点进行消费.
同时清空这段时间的数据,通过跑批脚本临时对这部分数据进行补充.
继续观察程序执行情况,发现堆积的数据很快被消费完,同时程序的cpu使用情况也处于正常状态!

至此,问题得到解决!

后话:

有细心的读者应该会发现,我这里的数据差异,堆积情况已经非常严重了...
为什么会这么晚才发现解决处理呢?

实际上 : 虽然我的Kafka消费程序在执行正常的情况下,能够达到秒级的消费延迟,
但是当前来说,这个程序提供的是(D+1)级别的服务.
所以,我只要在第二天上午九点之前处理好前一天的数据即可!

当然,后续该程序将会提供实时的查询服务,那时候,监控机制就会很严格,如果在出现这种情况,就是很严重的生产事故了

另外 : 线上环境的程序无论出现什么原因,都不应该简单粗暴的停掉,要事先预估好风险!
希望能够吸取这次教训...

new个对象先

关注

2
点赞
踩
13

收藏

觉得还不错? 一键收藏
0
评论
Kafka(五)----记一次Kafka实时ETL程序CPU占用率过高的线上问题排查

Kafka实时ETL程序CPU占用率过高的线上问题排查本篇博客要点如下:问题描述问题排查Kafka Manager界面查看基本信息CPU占用率过高问题定位问题进程定位问题线程定位问题线程堆栈信息全部线程的堆栈信息问题进程GC信息问题解决一. 问题描述收到运维电话反馈,Kafka实时ETL程序部署的机器CPU占用率居高不下.同时,每天的定时邮件校验数据条数与源...
复制链接

扫一扫

专栏目录