记一次日志输出大对象导致频繁FullGC问题

       在性能测试过程中，发现有一个交易在5个并发的情况下单机单jvm的时候交易响应时间变长，由于该交易外调了3个系统，所以刚开始是怀疑其他系统的响应时间变长了，但是通过日志分析，发现其他系统响应时间基本稳定，所以排除其他系统的问题，后来通过jstat查看jvm垃圾回收信息原来是频繁fullGC导致的交易响应时间变长，记录一下本次问题排查的过程：

1、通过以下命令查看jvm垃圾回收的统计信息：
jstat -gcutil PID 1s

意思是查看java进程为PID 的jvm每1s中的垃圾回收信息，通过这个命令看到FGC这个参数每次都在递增，基本上是1次FULLGC/1s 频繁的fullgc导致交易响应时间变慢。

2、获取堆栈信息文件，然后通过java自带的内存分析工具进行分析

获取堆栈信息文件命令如下：jmap -dump:file=/export/App/user/20210406.hprof PID

然后用jvisual VM 工具装入上述生成的文件，具体信息如下：

 

通过上述信息可以发现里面有很多的INFO输出，初步判断是日志打印的问题，而且这个交易是有三张图片的base64的串传过来的，这三个串在日志中占了绝大多数的空间，jvm在创建对象的时候，如果新生代内存不足的时候会直接在老年代进行创建，而老年代又在频繁的fullgc，所以并没有出现OOM的异常(我是这么理解的)，而且日志输出文件是按照异步的方式输出的。

3、第一次解决方案是把日志级别调整为ERROR，然后进行测试发现就没有问题了，也不存在fullgc，所以可以基本断定是写日志的问题了，但是生产环境刚上线的话要求日志级别必须是INFO，所以就只能在日志输出上想想办法

4、查看jvm参数配置，参数配置如下：本次列出部分jvm参数配置

-Xms4096m -Xmx4096m -XX:SurvivorRatio=6  -Xmn1536m

整个jvm内存大小为4G，其中新生代内存大小为1.5G ，E:S0:S1为6:2:2，目前服务器配置是4c8g，所以调整了一下jvm参数为：-Xms6144m -Xmx6144m -XX:SurvivorRatio=6  -Xmn2560m ，并将日志中的大字段进行过滤(异步这篇文章查看怎样过滤)，调整之后再次进行测试发现并没有很明显的改善，在15个并发左右又开始出现频繁FULLGC，所以这种方式不行。

5、还是调整log4j2中的日志输出，这次的话是将输出日志的长度进行限制，比如日志长度超过2000就只输出2000个字符后续不再输出(具体调整方式移步这篇文章)，并且在代码中将获取到的请求报文中的大字段进行拆分，拆分为独立的字符串然后再把这些字段在请求报文中remove掉，因为整个请求报文在整个交易中都是有地方进行引用的，而这几个字符串只是在部分地方使用，所以拆分为独立的字符串之后，在特定的地方使用结束之后就将这个字符串置为null，方便jvm尽快进行回收，这样就能够更快释放新生代空间。按照上述方案进行调整之后进行测试，问题解决。