排除Full GC影响时间流计算的技巧

在日常Java开发中，异步线程处理相关业务是司空见惯的事，在异步线程处理监控中又经常会对其执行时间进行监控分析，比如运行时间是否超时等。这种方法在正常运行的时间是没有问题的，比如发起一个socket请求，服务端在10s内无应答则判断为超时，这样的逻辑是没有问题的；但这种机制忽略了一个Full GC机制，就是在极端情况下，当获取startTime开始时间后，此时发生了Full GC，触发了STW所有线程停止等待垃圾回收，并且这个GC时间不短，那就容易对超时判断造成了影响。如下例子：

long start = System.currentTimeMillis();
//模拟请求
Thread.sleep(4000);
if (new Random().nextBoolean()) {
    //此时发生了Full GC，此GC耗费了10s
    Thread.sleep(2000);
}
//判断是否超时
if (System.currentTimeMillis() - start > 5000) {
    System.out.println("请求超时");
}

根据上述代码，原来代码的业务执行大概需要4秒，但代码执行过程中JVM会随机进入Full GC，耗时2秒，那此时总流程会耗费6秒；但在后面判断时是以是否大于5秒来判断是否超时，这样会将本来正常的请求也被列入异常异常，这明显不是设计的初衷。

因此，在代码开发中碰到需要用耗时来判断是否存在异常时，就需要排除Full GC对其耗时的影响。

如下代码中就实现了判断是否经历过Full GC，从而排除对计时的影响：

public class TestStopSatch {

    public static void main(String[] args) throws InterruptedException, TimeoutException {
        long st = System.currentTimeMillis();
        StopWath stopWath = new StopWath();
        stopWath.start();
        //设置超时时间为20秒
        long et = st + 20000;
        long nextLogTime = st + 1000;
        while (true) {
            //开始计时
            stopWath.restart();

            System.out.println("处理业务逻辑，满足则return");
            long now = System.currentTimeMillis();

            if (now > nextLogTime) {
                nextLogTime = now + 1000;
            }

            long rem = et - now;
            if (rem <= 0) {
                //此处加个判断是否发生了full gc，如果发生了则需要排除full gc的时间影响
                if (stopWath.getElapse() > 5000) { //通过是否大于5秒来判断是否发生full gc
                    //则需要延长超时的时间，重置超时时间
                    et = et + stopWath.getElapse();
                } else {
                    //程序超时
                    throw new TimeoutException();
                }
            }

            rem = Math.min(rem, nextLogTime - now);
            rem = Math.max(rem, 1);

            stopWath.restart();
            //此时也需要排除full gc对线程等待的影响
            wait(rem);
            //排除full gc的影响
            if (stopWath.getElapse() > 5000) {//通过是否大于5秒来判断是否发生full gc
                //则需要延长超时的时间，重置超时时间
                et = et + stopWath.getElapse() - rem;
            }
        }

    }

    public static class StopWath {
        //开始时间
        long start = 0L;
        //统计流逝的时间
        long elapse = 0L;
        public StopWath() {

        }

        /**
         * 重置时间
         *
         * @return StopWath
         */
        public StopWath reset() {
            //开始时间
            start = 0L;
            //统计时间流逝的时间
            elapse = 0L;
            return this;
        }
        /**
         * 开始计时
         *
         * @return StopWath
         */
        public StopWath start() {
            start = System.currentTimeMillis();
            return this;
        }

        /**
         * 重新计时
         *
         * @return StopWath
         */
        public StopWath restart() {
            return this.reset().start();
        }

        /**
         * 计算流逝的时间
         *
         * @return StopWath
         */
        public long getElapse() {
            return System.currentTimeMillis() - start;
        }
    }
}