一.问题描述
环境:JDK1.8、CentOS 6.9、容器undertow、Spring boot 1.5.8
最近线上运维,发现gclog里打印了很多Full GC的日志,通关gclog前面的时间可以看到间隔时间都是在10小时左右。
大概看了一下都是调用了System.gc()产生的Full GC,然后查看堆栈信息还远远没到Full GC的条件。
二.问题排查
以下源码均只写出相关部分,其他省略。
1.问题猜测
以前应用都是正常GC,想到最近一次上线代码中引入了apache的cxf包,版本为2.7.6。找到其中一段代码:
package org.apache.cxf.common.logging;
public class JDKBugHacks{
public static void doHacks(){
//省略前面代码...
Method = method;
Class policyClass;
try{
if(!skipHack("org.apache.cxf.JDKBugHacks.gcRequestLatency")){
policyClass = Class.forName("sum.misc.GC");
method = policyClass.getDeclaredMethod("currentLatencyTarget");
Long l = (Long)mehtod.invoke((Object)null);
if(l != null && l.longValue() == 0L){
method = policyClass.getDeclaredMethod("requestLatency",Long.TYPE);
method.invoke((Object)null,36000000L);
}
}
}catch(Throwable var16){
;
}
//省略后面代码...
}
}
这段代码在不同条件下利用反射调用了sun.misc.GC
中的currentLatencyTarget
方法或者requestLatency
方法。而且刚好可以看到在进行requestLatency
方法调用时,传入的第二个参数如果单位是毫秒的话,刚好是10小时。现在就是要看一下GC这个类中的方法。
GC类中相关的源码:
package sum.misc;
public class GC{
private static long latencyTarget = 9223372036854775807L;
private static Thread daemon = null;
public static long currentLatencyTarget(){
long var0 = latencyTarget;
return varo == 9223372036854775807L ? 0L : var0;
}
private static void setLatencyTarget(long var0){
latencyTarget = var0;
if (daemon == null){
GC.Daemon.create();
}else{
lock.notify();
}
}
//内部类:GC守护线程相关源码
private static class Daemon extends Thread{
public void run(){
while(true){
synchronized(GC.lock){
long var1 = GC.latencyTarget;
if (var1 == 9223372036854775807L){
GC.daemon = null;
return;
}
//这是个本地方法,暂时还没搞清楚这个方法的作用。
long var4 = GC.maxObjectInspectionAge();
if (var4 >= var1){
System.gc();
var4 = 0L;
}
try{
GC.lock.wait(var1 - var4);
}catch(InterruptedException var8){
;
}
}
}
}
public static void create(){
PrivilegedAction var0 = new PrivilegedAction<Void>(){
public Void run(){
ThreadGroup var1 = Thread.currentThread.getThreadGroup();
//省略部分代码
GC.Daemon var3 = new GC.Daemon(var1);
var3.setDaemon(true);
var3.setPriority(2);
var3.start();
GC.daemon = var3;
return null;
}
}
}
}
}
2.源码分析
现在先来理一下调用过程,看下是怎么造成定时FGC的。
-
先是apache的cxf包中
JDKBugHacks
这个类中通过反射调用sun.misc.GC
中的方法。policyClass = Class.forName("sum.misc.GC"); method = policyClass.getDeclaredMethod("currentLatencyTarget"); /* 通过上面源码可以看到这个方法首次调用是返回0L的,因为latency初始值为9223372036854775807L。 所以肯定走判断里面的逻辑,开始调用参数为Long的 requestLatency 方法。 */ Long l = (Long)mehtod.invoke((Object)null); if(l != null && l.longValue() == 0L){ method = policyClass.getDeclaredMethod("requestLatency",Long.TYPE); method.invoke((Object)null,36000000L); }
-
第一步走完应该是调用GC类中的
requestLatency
,这个方法关键部分是调用了setLatencyTarget
,这里看下setLatencyTarget
,其他部分暂时省略。private static void setLatencyTarget(long var0){ latencyTarget = var0; if (daemon == null){ GC.Daemon.create(); }else{ lock.notify(); } }
由于GC类中的daemon初始值就是null,然后执行
GC.Daemon.create()
。public static void create(){ PrivilegedAction var0 = new PrivilegedAction<Void>(){ public Void run(){ ThreadGroup var1 = Thread.currentThread.getThreadGroup(); //省略部分代码 GC.Daemon var3 = new GC.Daemon(var1); var3.setDaemon(true); var3.setPriority(2); var3.start(); GC.daemon = var3; return null; } } }
这里就创建了一个名字为GC Daemon(构造方法中设置的名字),优先级为2的GC守护线程。在服务器上利用jstack命令查看线程信息可以看到
-
守护线程执行的操作,在它的run方法中可以看到。
public void run(){ while(true){ synchronized(GC.lock){ long var1 = GC.latencyTarget; if (var1 == 9223372036854775807L){ GC.daemon = null; return; } /* 这是个本地方法,暂时还没搞清楚这个方法的作用。 但是可以猜测一下,由于我们传入的var1为3600000L,判断中每次gc都会将这个值重置为0, 后面的休眠时间刚好为10个小时。 */ long var4 = GC.maxObjectInspectionAge(); if (var4 >= var1){ System.gc(); var4 = 0L; } try{ GC.lock.wait(var1 - var4); }catch(InterruptedException var8){ ; } } } }
三.解决办法
直接在启动项目的JVM参数中加入
-Dorg.apache.cxf.JDKBugHacks.gcRequestLatency=true
来使JDKBugHacks
中的判断为false,然后跳过这段逻辑。
加入这个参数后,观察了一段时间,GC日志中没有出现10个小时一次的Full GC情况了。查看线程信息中也没有出现GC守护线程了。
tips:如果不是cxf包问题,也可以看看自己项目中引入的包是否调用了GC类来确定问题所在。