引发线程cpu占用率持续飙升的根因分析

安利一下


在最近系统性能调优的过程中,用到了很多工具,由于笔者开发的主要是java应用,从linux
工具到jdk工具,以及全链路追踪工具,都解决了相当多的问题,而完全面向java应用的的工具,笔者墙裂推荐
阿里的arthas,这款工具简单,简单到分析cpu、内存问题分分钟就能找到些蛛丝马迹。

问题抽象


项目最近做了一次大升级,压测后发现项目跑了24小时后,开始出现某个线程cpu占用100%,如下图所示:

重启后,仔细观察该线程,发现线程cpu使用率在逐渐递增,我们通过jvisualvm,快速的找到了问题的堆栈,发现是某个redis操作,这个操作里面调用了lua脚本,并使用了evalsha()的方式执行。

抽丝剥茧


从现象我们理所当然的想到了,会不会是redis集群慢了,拖垮了整个项目,通过redis
monitor 发现单次请求响应变化不大,并且redis cpu 占用率属于正常。使用perf命令记录如下:

然后开始想,既然占用cpu 多,那就把方法时间打出来吧,通过log的方式记录下来,发下每千次调用的平均时间是毫秒级,而且稳定不会递增。
这个时候又没了思路,用arthas 开始记录该方法的耗时,一行命令就记录如下,每5s记录一次平均时间,而且不用改代码,这可是福音啊

基本跟log一致,然后开始使用 thread -n 3 -i 1000
发现另外一个线程,然后同样执行monitor,发现该方法单位时间内的调用次数在增加,什么情况,方法调用难道写了个循环么,打开代码一看,外层调用并没有循环。。。
但是发现方法内存在循环,该循环是从set集合里取数据并判断该数据是否合法,合法就从set中移除,并break循环,看起来貌似没有任何问题。直觉告诉我,这个set会不会过大呢,这个set是用枚举单例的成员变量,想要打印这个变量里面的数据,放在以前打印log,又是一段代码,而且查看起来特别费劲,这个时候,我们又祭出神器,arthas的ognl命令。非常给力

ognl ‘@xxx.common.redis.collections.UniqConcurrentSet@INSTANCE.dataIsNullSet
ognl ‘@xxx.common.redis.collections.UniqConcurrentSet@INSTANCE.dataIsNullSet.size()’

结果这个set都37w
条数据了,而且还在持续上升,但是占用内存很小,单行记录80B左右,总体不到50M,原来真正导致cpu上升的元凶就是数据量大了后,遍历耗时了,定位到了原因,接着及时删除数据,cpu平稳了

那今天先聊到这,休息下眼睛
{% asset_img meizi.jpg 妹纸图 %}
坚持原创技术分享,您的支持将鼓励我继续创作!