记一次JAVA FULL GC问题处理【2】

1: 线上发生几次Full GC, 一直关注中:

1):YGC几本没有作用(正常的一次YGC会让EU减少, S0U,S01 中的一个清零,另一个变为非零), S0U1, S1U 都还是零的状态。

 2): 可以看出老年代堆已经几乎满了,即使发生一个Full GC内存也没有释放多少。 

 3):可以判断基本上是发生了内存泄露

 

 

 2:  导出内存信息 

jmap -dump:format=b,file=heap.binnew 8 
 
3:于是使用工具jvisualvm 工具查看, 可看查到如下的直方图:

 

现网生成直方图可以用命令: jmap -histo 8 发现内存中,确实存在一些不应该存在的对象。工具不怎么强大, 没有分析出有效的结论。

 

4: MemoryAnalyzer 工具查看,MAT工具有支配树(dominator_tree) 这个视图,这个视图可以看出那个对象所持有的关联对象最大。 

 

 5: 从服务上看,内存占用最多的是tomcat处理请求线程占用最多。

 里面有较多的ThreadLocalMap 对像。第一个是最大的对象为StringBuilder 。 

 

6: 从支配树并不能直接看出问题的所在,这里从StringBuilder对象的内容查问题,内容有如下特点。

1): 发现里面的内容主要为日志内容。

2): 日志的长度较大,都是200-20M大小。支配树显示大的小,就已经可以打内存爆满。

3):日志内容,不是一次的,是多次日志,而且日志关联性不大。

4)   进一步查询日志还发现,后面的日志的前面部分不全。

 

 

 

 7:现清这这个问题,我们回过头来看代码在log4j 2.6.0 的代码

网上有这种说说法:  https://blog.csdn.net/jslcylcy/article/details/104371137 

分析发现原理与上述博客中的是一样的。【搜索Log4j2在什么地方使用了StringBuilder,排查发现org.apache.logging.log4j.message.ParameterizedMessage这个类中有一个复用StringBuilder的代码】

但经过调式,上述的结论不是事实全部,但思路是正确的。

8: 于是重新做个调试: 但启动一个线程,减少干扰。在没有打印日志时,没有Thread没有对应的持有一个Entry没有关于StringBuilder的对象。

 

经过一次log输出: 线程通过ThreadLocal$ThradLocalMap持有了两个StringBuilder对象。

 

问题是在这里的: 上述的数组对象【17位】 实际上占用1024个对象空间。 Entry【19】占用的对象才255

 

 两个对象的来原分别是PatternLayout extends AbstractStringLayout 的threadLocal  这个threadLocal 是重要的在输出前的threadLocal在日志文件中的行数据。

这个threadLocal是个内存复用,用之后除非线程消亡。

 

 

 

 

 

另一个是ParameterizedMessage 这里的使用场景是使用log.info("my name is {}", name) 这种参数代码,才会使用这个StringBuilder做为内存复用。 

 

至此本问题原因解决,是由于日志一次性输出过多,导至线程持有的的一个数组对象过大。一个线程持有近100-200M数据,我们处理线程几十个,内存总归不能用。

解决本问题的办法,减少单次日志的输出。

 

关联问题请阅读: 

https://i.cnblogs.com/posts/edit;postId=14785571

 

 
 
 
posted @ 2021-05-19 17:14  风云快客  阅读(194)  评论(0编辑  收藏  举报