一次JVM中FullGC问题排查过程
这个问题比较常见，我把过程中的日志记录下来了，希望后续大家遇到类似的能快速定位。
1、平均三秒一次FullFC
?sudo -u admin java/bin/jstat -gcutil `pgrep java -u admin` 1000 2000
? S0???? S1???? E????? O????? P???? YGC???? YGCT??? FGC??? FGCT???? GCT??
??0.00?? 0.53? 71.69?? 9.19? 92.42?? 6183? 901.265 54986 48865.327 49766.592
? 0.00?? 0.53? 72.34?? 9.19? 92.42?? 6183? 901.265 54986 48866.617 49767.881
? 0.00?? 0.53? 72.68?? 9.19? 92.42?? 6183? 901.265 54986 48866.617 49767.881
? 0.00?? 0.53? 73.08?? 9.19? 92.42?? 6183? 901.265 54987 48866.617 49767.881
? 0.00?? 0.53? 73.08?? 9.19? 92.42?? 6183? 901.265 54987 48866.617 49767.881
? 0.00?? 0.53? 73.68?? 9.19? 92.42?? 6183? 901.265 54987 48867.875 49769.140
? 0.00?? 0.53? 73.87?? 9.19? 92.42?? 6183? 901.265 54988 48867.875 49769.140
? 0.00?? 0.53? 73.87?? 9.19? 92.42?? 6183? 901.265 54988 48869.260 49770.525
? 0.00?? 0.53? 74.90?? 9.19? 92.42?? 6183? 901.265 54988 48869.260 49770.525
? 0.00?? 0.53? 75.32?? 9.19? 92.42?? 6183? 901.265 54988 48869.260 49770.525
? 0.00?? 0.53? 75.39?? 9.19? 92.42?? 6183? 901.265 54989 48869.260 49770.525
? 0.00?? 0.53? 76.07?? 9.19? 92.42?? 6183? 901.265 54989 48870.539 49771.804
? 0.00?? 0.53? 76.34?? 9.19? 92.42?? 6183? 901.265 54990 48870.539 49771.804
? 0.00?? 0.53? 76.34?? 9.19? 92.42?? 6183? 901.265 54990 48870.539 49771.804
? 0.00?? 0.53? 77.36?? 9.19? 92.42?? 6183? 901.265 54990 48871.973 49773.238
? 0.00?? 0.53? 77.65?? 9.19? 92.42?? 6183? 901.265 54990 48871.973 49773.238
? 0.00?? 0.53? 77.76?? 9.19? 92.42?? 6183? 901.265 54991 48871.973 49773.238
?
2、重启应用之后发现Perm区一直在上涨
?sudo -u admin /java/bin/jstat -gcutil `pgrep java -u admin` 5000 200
? S0???? S1???? E????? O????? P???? YGC???? YGCT??? FGC??? FGCT???? GCT??
??0.00? 71.04? 14.28?? 0.00? 71.46????? 5??? 0.467???? 0??? 0.000??? 0.467
? 0.00? 71.04? 16.19?? 0.00? 71.47????? 5??? 0.467???? 0??? 0.000??? 0.467
? 0.00? 71.04? 18.30?? 0.00? 71.54????? 5??? 0.467???? 0??? 0.000??? 0.467
? 0.00? 71.04? 20.82?? 0.00? 71.54????? 5??? 0.467 ????0??? 0.000??? 0.467
? 0.00? 71.04? 22.77?? 0.00? 71.54????? 5??? 0.467???? 0??? 0.000??? 0.467
? 0.00? 71.04? 24.46?? 0.00? 71.54????? 5??? 0.467???? 0??? 0.000??? 0.467
? 0.00? 71.04? 26.24?? 0.00? 71.54????? 5??? 0.467???? 0??? 0.000??? 0.467
? 0.00 ?71.04? 29.01?? 0.00? 72.66????? 5??? 0.467???? 0??? 0.000??? 0.467
? 0.00? 71.04? 30.84?? 0.00? 72.66????? 5??? 0.467???? 0??? 0.000??? 0.467
? 0.00? 71.04? 32.65?? 0.00? 72.68????? 5??? 0.467???? 0??? 0.000??? 0.467
? 0.00? 71.04? 34.48?? 0.00? 72.68??? ??5??? 0.467???? 0??? 0.000??? 0.467
? 0.00? 71.04? 36.40?? 0.00? 72.69????? 5??? 0.467???? 0??? 0.000??? 0.467
? 0.00? 71.04? 38.10?? 0.00? 72.69????? 5??? 0.467???? 0??? 0.000??? 0.467
? 0.00? 71.04? 39.76?? 0.00? 72.70????? 5??? 0.467???? 0??? 0.000??? 0.467
?
3、Btrace查看后发现HSF的一个类在调用ClassLoader的defineClass方法来创建类：
sudo -u admin sh? btrace -cp /home/admin/btrace/build 4955? /home/admin/btrace/BtraceAll.java
===========================================================================
java.lang.ClassLoader.defineClass
Time taken : 2
java thread method trace:---------------------------------------------------
java.lang.ClassLoader.defineClass(ClassLoader.java:615)
org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.defineClass(DefaultClassLoader.java:165)
org.eclipse.osgi.baseadaptor.loader.ClasspathManager.defineClass(ClasspathManager.java:554)
org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findClassImpl(ClasspathManager.java:524)
org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClassImpl(ClasspathManager.java:455)
org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass_LockClassLoader(ClasspathManager.java:443)
org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:423)
org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:193)
org.eclipse.osgi.framework.internal.core.BundleLoader.findLocalClass(BundleLoader.java:368)
org.eclipse.osgi.framework.internal.core.SingleSourcePackage.loadClass(SingleSourcePackage.java:33)
org.eclipse.osgi.framework.internal.core.BundleLoader.findClassInternal(BundleLoader.java:432)
org.eclipse.osgi.framework.internal.core.BundleLoader.findClass(BundleLoader.java:397)
org.eclipse.osgi.framework.internal.core.BundleLoader.findClass(BundleLoader.java:385)
org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:87)
java.lang.ClassLoader.loadClass(ClassLoader.java:247)
com.taobao.hsf.rpc.tbremoting.provider.ProviderProcessor.handleRequest(ProviderProcessor.java:117)
com.taobao.hsf.rpc.tbremoting.provider.ProviderProcessor.handleRequest(ProviderProcessor.java:55)
com.taobao.remoting.impl.DefaultMsgListener$1.run(DefaultMsgListener.java:98)
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
java.lang.Thread.run(Thread.java:662)
?
4、Perm区配置都是128M，有点小，之前占比90%的时候开始FullGC
VM Flags:
-Dprogram.name=run.sh -Xms4g -Xmx4g -XX:PermSize=128m -XX:MaxPermSize=128m -Xmn2500m -XX:SurvivorRatio=7 -XX:+UseConcMarkSweepGC -XX:+UseCMSCompactAtFullCollection
?
5、应用中war包的lib目录就有177M
在应用刚开始启动的时候，占比70% 左右，也就是90M左右的样子，之后有些类动态加载进来了，到90% 后就回收不了了。
?
临时解决办法：调大Perm区，增大至256m
后续考虑：优化jar包依赖，目前太多没用的被依赖进来，导致包很大。
?
