排查一个线上接口超时的问题，发现出问题的时间段该机器young gc耗时在2s左右，但是回收的数据量并不大，也没有晋升到老年代的数据。观察其他指标后发现，出问题的机器ioutil很高，由于机器是虚拟机很可能是受宿主机的影响。那么io高是否会影响gc的耗时呢？

为了解答上面的问题，我们来做一个小实验。

实验

public class GC {
    public static void main(String[] args) {
        LargeObject largeObject = null;
        for (int i = 0; i < Integer.MAX_VALUE; i++) {
            largeObject = new LargeObject();
        }
        System.out.println(largeObject);
    }

    public static class LargeObject{
        byte[] bytes = new byte[1024];
    }
}

使用参数java -Xmx500m -Xmx500m -Xmn400m -XX:+PrintGCDetails -Xloggc:gc.log -XX:+PrintGCTimeStamps GC来运行上面的程序，可以看到如下的输出

secs] 
62.990: [GC (Allocation Failure) [PSYoungGen: 510496K->32K(510976K)] 510772K->308K(511488K), 0.0004748 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
63.072: [GC (Allocation Failure) [PSYoungGen: 510496K->32K(510976K)] 510772K->308K(511488K), 0.0004658 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

使用grep “real=0.[1-9]” gc.log来搜索可以看到没有超过100ms的gc。

下面我们来提高一下io的负载，运行如下的脚本会创建7个进程同时写磁盘，每个进程生成一个700MB的文件。

#!/bin/bash

for i in {1..7};do
    dd if=/dev/zero of=test$i bs=1M count=700 &
done

当脚本运行后再次使用上面的grep语句来搜索，可以看到有超过100ms的gc产生了。

21.802: [GC (Allocation Failure) [PSYoungGen: 510496K->32K(510976K)] 510764K->300K(511488K), 0.2630548 secs] [Times: user=0.01 sys=0.00, real=0.26 secs] 
31.790: [GC (Allocation Failure) [PSYoungGen: 510496K->32K(510976K)] 510764K->300K(511488K), 0.2738306 secs] [Times: user=0.00 sys=0.00, real=0.28 secs]

通过上面的实验，我们可以得出结论io会影响gc的耗时。那么是为什么呢？

原理

gc的过程中会将gc日志写入到磁盘中，而gc日志的写入是同步的，如果io负载过高则会导致gc日志的写入被block较长的时间，而这部分时间实际上是算在gc的总耗时的时间内的。