问题解决：Full GC固定10小时执行一次问题解决记录

文章目录

• 一.问题描述
• 二.问题排查
• 1.问题猜测
• 2.源码分析
• 三.解决办法

一.问题描述

环境：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守护线程了。