Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
excel-bat opened this issue Mar 14, 2019 · 0 comments
Closed

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

excel-bat opened this issue Mar 14, 2019 · 0 comments

Comments

@excel-bat
Copy link

excel-bat commented Mar 14, 2019

安利一下


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

问题抽象


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

占用cpu高的线程

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

抽丝剥茧


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

cpu 占用

然后开始想,既然占用cpu 多,那就把方法时间打出来吧,通过log的方式记录下来,发下每千次调用的平均时间是毫秒级,而且稳定不会递增。

这个时候又没了思路,用arthas 开始记录该方法的耗时,一行命令就记录如下,每5s记录一次平均时间,而且不用改代码,这可是福音啊

monitor占用结果

基本跟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平稳了

原文地址

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants