记一次应用频繁gc原因分析

发表于

问题背景

发布应用后，通过gclog日志和jstat命令发现gc频繁，而应用的调用量不多。很奇怪，有必要进一步分析。

应用环境：jdk1.7.0_45 tomcat8.0.32

如何排查jvm相关问题

在JDK1.7u40之后，java内置了一个jdk分析诊断工具平台–JMC，也是Oracle官方推荐使用的工具。

生成jfr文件

tomcat启动参数配置

1
2
-Dcom.sun.management.jmxremote=true -Dcom.sun.management.jmxremote.port=3000 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Djava.rmi.server.hostname=127.0.0.1
-XX:+UnlockCommercialFeatures -XX:+FlightRecorder

使用jcmd命令生成记录文件

1
jcmd <pid> JFR.start name=MyRecording settings=/home/appadmin/profile.jfc delay=2s duration=2m filename=myrecording.jfr

注：settings指定的文件在$JAVA_HOME/jre/lie/jfr中会有一份默认配置的，我这里将method-sampling-interval和socket read/write从默认的10ms改为1ms

更多关于jmc jfr jcmd 参见官方文档
Oracle troubleshoot doc

分析jfr文件

内存概览中观察到gc频繁，为TLAB分配的内存超过7G

Imgur

内存-分配-新TLAB中的分配-按线程分配，可以看到占用内存最多的线程ContainerBackgroundProcessor[StandardEngine[Catalina]]

Imgur

事件-图形，根据线程筛选，勾选上事件类型：Allocation in new TLAB

Imgur

图中橙色部分堆栈跟踪

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
Allocation in new TLAB
 ...
 位于 org.apache.catalina.webresources.AbstractArchiveResourceSet.getResource(String)
 位于 org.apache.catalina.webresources.StandardRoot.getResourceInternal(String, boolean)
 位于 org.apache.catalina.webresources.Cache.getResource(String, boolean)
 位于 org.apache.catalina.webresources.StandardRoot.getResource(String, boolean, boolean)
 位于 org.apache.catalina.webresources.StandardRoot.getClassLoaderResource(String)
 位于 org.apache.catalina.loader.WebappClassLoaderBase.modified()
 位于 org.apache.catalina.loader.WebappLoader.modified()
 位于 org.apache.catalina.loader.WebappLoader.backgroundProcess()
 位于 org.apache.catalina.core.StandardContext.backgroundProcess()
 位于 org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(Container)
 位于 org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(Container)
 位于 org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(Container)
 位于 org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run()
 位于 java.lang.Thread.run()

紫色部分

1
2
3
4
Java Thread Sleep
 位于 java.lang.Thread.sleep(long)
 位于 org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run()
 位于 java.lang.Thread.run()

TLAB(Thread Local Allocation Buffer)
位于Eden区，线程私有

问题定位&解决

通过上面的信息可以定位到问题出在ContainerBackgroundProcessor.run()方法上，这个线程会定期检查webapps下是否有变动，将jar加载到内存中。

但理论上不会有这么大量的内存产生啊

将tomcat -> conf/server.xml -> reloadable = false，可以解决这个问题。