纯干货:线上出现fullGC次数很多的排查思路以及实践总结

最近线上发布了一个版本，导致full gc次数忽然就上去了，虽然对线上业务造成的影响还不是很大，但是为了以防万一还是对这个问题做了相关排查。

GC命令排查

一开始还是从堆的变化开始:

# 查看每秒的堆发生的变化以及gc的次数
jstat -gcutil pid 1000

相关参数:

s0 : Heap上的 Survivor space 0 区已使用空间的百分比
s1 : Heap上的 Survivor space 1 区已使用空间的百分比
E : Heap上的 Eden space 区已使用空间的百分比
O : Heap上的 Old space 区已使用空间的百分比
P : Perm space 区已使用空间的百分比
M：元数据区使用比例
CCS：压缩使用比例
YGC : 从应用程序启动到采样时发生 Young GC 的次数
YGCT : 从应用程序启动到采样时 Young GC 所用的时间(单位秒) FGC — 从应用程序启动到采样时发生 Full GC 的次数
FGCT- 从应用程序启动到采样时 Full GC 所用的时间(单位秒) GCT — 从应用程序启动到采样时用于垃圾回收的总时间(单位秒)

抓到了一个fullgc 升级的截图:

从这里发现在触发full gc的时候只有新生代的堆发生了明显的回收，但是老年代几乎没发生变化。

所以不是老年代的内存不足导致的，然而第一感觉是会不会有大对象直接越过新生代直接到了老年代呢？但是现在想想应该也不太会，因为gc完之后老年代没有很明显的上升变化。

既然这里看不出什么就开始另寻他路了。

gc的日志分析：

GC参数 建议线上都把这些日志打开
JVM的GC日志的主要参数包括如下几个：

-XX:+PrintGC # 输出GC日志
-XX:+PrintGCDetails #输出GC的详细日志
-XX:+PrintGCTimeStamps #输出GC的时间戳（以基准时间的形式）
-XX:+PrintGCDateStamps #输出GC的时间戳（以日期的形式，如 2017-09-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC #在进行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log #日志文件的输出路径

拿到gc日志一行行看太麻烦了，这里推荐一个在线分析gc日志的神器：

gceasy

从线上拿到日志之后，上传到该网站，就会得到很多可视化的结果。

堆的分配情况

GC时间的区域划分

这里可以看到:

最大的一次gc时间超过了1秒钟，平均的时间都在35ms之间。
大部分时间都是在1秒以内,只有2次gc时间超过1秒。

GC前后的可视化图

红色的代表full gc时候的堆大小，都没有超过300M。
minorgc是挺多,但是都在堆接近满了的情况。

GC停顿的情况

我们这里比较关注full gc在198次，停顿时间在1分钟左右，每8分钟的样子就会触发一次。

GC触发的原因

这个图里面包含了很多关键的信息：

System.gc()触发的总数过多，达到300+次。
其他的都是空间分配不足导致的gc，但是大部分是minor gc 这个是可以接受的。

得到上面的信息可以发现绝大部分的full gc引发的原因就是System.gc() 导致的，至于为什么超过300次？明明不是198次吗？稍后解答.

到底是哪里调用了System.gc?

这个是个很尴尬的问题，有可能是框架，也有可能是业务代码中。

想了解这个原因的时候联想到了阿里开源的arthas

神器啊!

他有个功能能够在不重启的应用和改代码的情况下，对指定的方法进行拦截。
不说了，开干！

启动

curl -O https://alibaba.github.io/arthas/arthas-boot.jar
java -jar arthas-boot.jar

开启安全方法拦截

[arthas@18792]$ options unsafe trueNAME    BEFORE-VALUE  AFTER-VALUE
-----------------------------------                                                                                                                                                                              unsafe  false         true

拦截指定的方法

[arthas@18792]$ stack java.lang.System gc
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 277 ms
# 然后安静的等待调用出现吧!!!!!

然后安静的等待调用出现吧!!!

我这里贴一个我拦截的结果:

ts=2020-03-16 19:30:09;thread_name=http-nio-5314-exec-26;id=102;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@781d050@java.lang.System.gc()at com.elab.core.utils.DateUtils.stringToDate(DateUtils.java:358)at com.elab.marketing.auth.service.impl.AdviserDispatchImpl.dispatch(AdviserDispatchImpl.java:162)at com.elab.marketing.auth.service.impl.AdviserDispatchImpl.dispatch(AdviserDispatchImpl.java:86)at com.elab.marketing.auth.service.impl.AdviserDispatchImpl$$FastClassBySpringCGLIB$$d0a51ab4.invoke(<generated>:-1)at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:52)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:85)at com.elab.log.asepct.CatAspect.aroundMethod(CatAspect.java:65)at com.elab.marketing.auth.config.aspect.ServiceAspectBean.around(ServiceAspectBean.java:47)at sun.reflect.GeneratedMethodAccessor172.invoke(null:-1)at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(Method.java:498)at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:629)at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:618)at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)at com.elab.marketing.auth.service.impl.AdviserDispatchImpl$$EnhancerBySpringCGLIB$$6e910ff2.dispatch(<generated>:-1)at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-2)at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(Method.java:498)at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133)at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at org.springframework.boot.web.filter.ApplicationContextHeaderFilter.doFilterInternal(ApplicationContextHeaderFilter.java:55)at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:110)at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at com.elab.log.filter.CatHttpRequestFilter.doFilter(CatHttpRequestFilter.java:45)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at com.elab.log.filter.HttpCatCrossFliter.doFilter(HttpCatCrossFliter.java:75)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at com.alibaba.arms.filter.EagleEyeFilter.doFilter(EagleEyeFilter.java:24)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:106)at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:504)at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790)at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)at java.lang.Thread.run(Thread.java:748)ts=2020-03-16 19:31:35;thread_name=http-nio-5314-exec-16;id=f6;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@781d050@java.lang.System.gc()at com.elab.core.utils.DateUtils.stringToDate(DateUtils.java:358)at com.elab.marketing.auth.service.impl.AdviserDispatchImpl.dispatch(AdviserDispatchImpl.java:162)at com.elab.marketing.auth.service.impl.AdviserDispatchImpl.dispatch(AdviserDispatchImpl.java:86)at com.elab.marketing.auth.service.impl.AdviserDispatchImpl$$FastClassBySpringCGLIB$$d0a51ab4.invoke(<generated>:-1)at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:52)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:85)at com.elab.log.asepct.CatAspect.aroundMethod(CatAspect.java:65)at com.elab.marketing.auth.config.aspect.ServiceAspectBean.around(ServiceAspectBean.java:47)at sun.reflect.GeneratedMethodAccessor172.invoke(null:-1)at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(Method.java:498)at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:629)at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:618)at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)at com.elab.marketing.auth.service.impl.AdviserDispatchImpl$$EnhancerBySpringCGLIB$$6e910ff2.dispatch(<generated>:-1)at sun.reflect.GeneratedMethodAccessor2519.invoke(null:-1)at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(Method.java:498)at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133)at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at org.springframework.boot.web.filter.ApplicationContextHeaderFilter.doFilterInternal(ApplicationContextHeaderFilter.java:55)at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:110)at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at com.elab.log.filter.CatHttpRequestFilter.doFilter(CatHttpRequestFilter.java:45)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at com.elab.log.filter.HttpCatCrossFliter.doFilter(HttpCatCrossFliter.java:75)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at com.alibaba.arms.filter.EagleEyeFilter.doFilter(EagleEyeFilter.java:24)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:106)at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:504)at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790)at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)at java.lang.Thread.run(Thread.java:748)

我这里出现了两次gc，根据链路去查看了相关源码，发现不知道是谁弄了一个工具类，try catch异常中加入的system.gc。真让人头大

具体代码:

/*** 将Date对象类型转化为指定的格式字符串** @param date<Date>日期* @param format<String>格式* @return String*/public static String dateToString(Date date, String format) {try {if(date!=null)return new SimpleDateFormat(format).format(date);} catch (Exception e) {e.printStackTrace();System.gc();}return null;}

通过链路发现业务调用的时候还是个for循环，所以会出现System.gc成双成对的触发…

我猜也是为什么System.gc调用300+次数,但是fullgc只有198次，可能连续调用两次和一次没啥区别，但是仅仅只是猜测。很有可能是错误的，有知道的大佬可以指点一下。

不报异常不出现，坑死一堆程序员。

总结一下吧:

出现异常可以先通过jstat、jmap等分析一下堆的情况，以及gc情况。
通过分析gc日志可以快速定位gc触发的原因，以及堆的变化。
如果是System.gc主动触发，可以通过阿里开源的arthas去拦截得到调用链。

虽然结果有点坑爹，但是思路是相通的。

如果有更好的思路以及实践

欢迎留言交流，共同学习。