一次jvm虚拟机cpu高占用问题分析

怼烎@ 2022-05-12 11:56 214阅读 0赞

问题现象：  
Java进程6732 CPU使用率始终位于450%左右。即使在压测停止后，cpu使用率依然高居不下。  
问题分析：  
1.分析发现6732的8个子进程始终处于cpu占用率90%以上（如下图）。8个进程都为JVM虚拟机的垃圾回收线程，故转而分析JVM的内存使用情况。  
![在这里插入图片描述][70]  
2.JVM 内存Heap分析  
![在这里插入图片描述][70 1]  
发现eden区和年老代内存使用率都近乎100%，也印证了为什么8个垃圾回收线程一直CPU占用率很高。故问题转换为分析“为什么两个区的内存几乎被占满”。  
3.导出java虚拟机的Heap Dump，分析发现logback日志框架父节点持有内存高达99%。  
![在这里插入图片描述][70 2]  
4.分析Thread Dump发现，stack中约有170多个dubbo work线程及20个其他线程阻塞在同一个锁上0x00000007800049b8。分析logback源码发现，在logback的OutputStreamAppender类中subAppend方法使用ReentrantLock 锁。  
在打印日志时，先加锁，然后输出日志，最后释放锁，见代码。

源码：  
![在这里插入图片描述][70 3]  
5.存在问题总结  
从线程阻塞情况来看，200个线程中有170多个是dubbo work线程，自定义的dubbo 日志 filter 阻塞在日志输出上，系统已处于僵死状态。  
建议：  
1、使用logback 异步asynappender替代当前同步appender，并适当调整日志asynappender 队列参数。  
2、减少不必要的日志输出。  
3、对日志的appender进行细化分类，增加输出log文件数量，减少太多日志共用一个appender情况。

6.回归验证  
按上述调整后，压测调优，观察日志输出阻塞情况。  
7.其他问题  
(1)虚拟机的Perm区设置了512M，实际使用了55M，该区基本不会再出现大的变化，建议调整为100M以内。  
(2)虚拟机内存参数目前多个值处于默认值，如SuvivorRatio， NewRatio。可长期观察适当做优化处理

[70]: /images/20220512/1d89bd7c3d5041ba8dd0ea48ee06c0bf.png
[70 1]: /images/20220512/43222639b11e46419dff8314ee41d38d.png
[70 2]: /images/20220512/28b0428bedac47db96afb1f4632f5bfb.png
[70 3]: /images/20220512/b6aa4878928641a3934a93573696f347.png