问题现象:
Java进程6732 CPU使用率始终位于450%左右。即使在压测停止后,cpu使用率依然高居不下。
问题分析:
1.分析发现6732的8个子进程始终处于cpu占用率90%以上(如下图)。8个进程都为JVM虚拟机的垃圾回收线程,故转而分析JVM的内存使用情况。
2.JVM 内存Heap分析
发现eden区和年老代内存使用率都近乎100%,也印证了为什么8个垃圾回收线程一直CPU占用率很高。故问题转换为分析“为什么两个区的内存几乎被占满”。
3.导出java虚拟机的Heap Dump,分析发现logback日志框架父节点持有内存高达99%。
4.分析Thread Dump发现,stack中约有170多个dubbo work线程及20个其他线程阻塞在同一个锁上0x00000007800049b8。分析logback源码发现,在logback的OutputStreamAppender类中subAppend方法使用ReentrantLock 锁。
在打印日志时,先加锁,然后输出日志,最后释放锁,见代码。
源码:
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。可长期观察适当做优化处理