分析代码

/*
演示GC日志生成与解读
*/
public class GCLogAnalysis {
    private static Random random = new Random();
    public static void main(String[] args) {
        // 当前毫秒时间戳
        long startMillis = System.currentTimeMillis();
        // 持续运行毫秒数; 可根据需要进行修改
        long timeoutMillis = TimeUnit.SECONDS.toMillis(1);
        // 结束时间戳
        long endMillis = startMillis + timeoutMillis;
        LongAdder counter = new LongAdder();
        System.out.println("正在执行...");
        // 缓存一部分对象; 进入老年代
        int cacheSize = 2000;
        Object[] cachedGarbage = new Object[cacheSize];
        // 在此时间范围内,持续循环
        while (System.currentTimeMillis() < endMillis) {
            // 生成垃圾对象
            Object garbage = generateGarbage(100*1024);
            counter.increment();
            int randomIndex = random.nextInt(2 * cacheSize);
            if (randomIndex < cacheSize) {
                cachedGarbage[randomIndex] = garbage;
            }
        }
        System.out.println("执行结束!共生成对象次数:" + counter.longValue());
    }

    // 生成对象
    private static Object generateGarbage(int max) {
        int randomSize = random.nextInt(max);
        int type = randomSize % 4;
        Object result = null;
        switch (type) {
            case 0:
                result = new int[randomSize];
                break;
            case 1:
                result = new byte[randomSize];
                break;
            case 2:
                result = new double[randomSize];
                break;
            default:
                StringBuilder builder = new StringBuilder();
                String randomString = "randomString-Anything";
                while (builder.length() < randomSize) {
                    builder.append(randomString);
                    builder.append(max);
                    builder.append(randomSize);
                }
                result = builder.toString();
                break;
        }
        return result;
    }
}

参数测试

jvm启动参数
-XX:+PrintGCDetails 开启gc日志
-XX:+PrintGCDateStamps gc日志添加时间戳
-Xloggc:gc.demo.log 指定gc日志输出文件

%p ->pid， %t->启动时间戳

-XX:+UseSerialGC 使用串行垃圾收集器
-XX:+UseParallelGC 使用并行垃圾收集器
-XX:+UseConcMarkSweepGC 使用CMS垃圾收集器

等价与 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC
但是只指定-XX:+UseParNewGC则老年代使用SerialGC
使用CMS时，命令行参数中会自动计算出年轻代、老年代的初始值和最大值，以及最大晋升阈值等信息 -XX:+UseG1GC 使用G1垃圾回收器

GC事件的类型

  1. Minor GC 小型GC
    1. 收集年轻代内存，即YGC
    2. 当JVM无法为新对象分配内存空间时就会触发 Minor GC （ 一般就是 Eden 区用满了）。 如果对象的分配速率很快， 那么 Minor GC 的次数也就会很多，频率也就会很快。
    3. Minor GC 事件不处理老年代， 所以会把所有从老年代指向年轻代的引用都当做 GC Root 。从年轻代指向老年代的引用则在标记阶段被忽略。
    4. 与我们一般的认知相反， Minor GC 每次都会引起STW停顿（stop-the-world）， 挂起所有的应用线程。 对大部分应用程序来说， Minor GC 的暂停时间可以忽略不计，因为 Eden 区里面的对象大部分都是垃圾，也不怎么复制到存活区/老年代。 但如果不符合这种情况，那么很多新创建的对象就不能被GC清理， Minor GC 的停顿时间就会增大，就会产生比较明显的GC性能影响。
  2. Major GC 大型GC
    1. 清理老年代空间（Old Space）的GC事件
  3. Full GC 完全GC
    1. 清理整个堆内存空间的GC事件，包括年轻代空间和老年代空间。

日志解读

深入理解java虚拟机

  1. 启动参数
    -XX:+PrintGCDetails -Xmx512m -Xms512m -XX:+PrintGCDateStamps -XX:+UseSerialGC

  2. 日志示例
    2021-03-31T22:51:04.086+0800: [GC (Allocation Failure) 2021-03-31T22:51:04.086+0800: [DefNew: 139776K->17471K(157248K), 0.0489886 secs] 139776K->45907K(506816K), 0.0490898 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]
    2021-03-31T22:51:04.702+0800: [GC (Allocation Failure) 2021-03-31T22:51:04.702+0800: [DefNew: 157193K->157193K(157248K), 0.0000609 secs]2021-03-31T22:51:04.702+0800: [Tenured: 330595K->272312K(349568K), 0.0726043 secs] 487788K->272312K(506816K), [Metaspace: 3803K->3803K(1056768K)], 0.0727806 secs] [Times: user=0.03 sys=0.00, real=0.07 secs]
    2021-03-31T23:01:24.859+0800: [Full GC (Allocation Failure) 2021-03-31T23:01:24.859+0800: [Tenured: 204690K->204604K(204800K), 0.0410202 secs] 296740K->222092K(296960K), [Metaspace: 3297K->3297K(1056768K)], 0.0410779 secs] [Times: user=0.03 sys=0.00, real=0.04 secs]

  3. 日志分析
    1. [GC和[Full GC] 说明了这次垃圾收集的停顿类型，Full表示发生了STW,如果是System.gc()触发的收集，则显示[Full GC (System)
    2. [DefNew、[Tenured 表示GC发生的区域，与收集器相关。
    3. 139776K->17471K(157248K) 表示”GC前该内存区域已使用容量->GC后该内存区域已使用容量(该内存区域总容量)”，方括号外296740K->222092K(296960K)表示”GC前Java堆已使用容量->GC后Java堆已使用容量(Java堆总容量)”
    4. 0.0489886 secs 内存区域的GC时间
    5. [Times: user=0.03 sys=0.00, real=0.04 secs] user 为用户态消耗的CPU时间，sys 为内核态消耗的CPU时间，real为操作开始到结束所经过的墙钟时间(Wall Clock Time)

1.Serial GC 串行GC

MinorGC

2021-03-29T21:58:40.680+0800: 0.757: [GC (Allocation Failure) 2021-03-29T21:58:40.680+0800: 0.757: [DefNew: 139434K->17471K(157248K), 0.0356862 secs] 139434K->46698K(506816K), 0.0359163 secs] [Times: user=0.03 sys=0.02, real=0.04 secs]
  1. 0.757 表示GC时间距JVM启动时间间隔
  2. [GC 表示MinorGC 。Allocation Failure 表示触发GC原因，年轻代没有空间来存放新生成对象
  3. DefNew 表示垃圾收集器的名称。表示：年轻代使用的单线程、标记-复制、STW 垃圾收集器。139434K->17471K(157248K) 表示在垃圾收集之前和之后的年轻代使用量。
  4. 139434K->46698K(506816K) 表示在垃圾收集之前和之后整个堆内存的使用情况。
  5. 0.0359163 secs 表示GC事件持续的时间，以秒为单位。
  6. [Times: user=0.03 sys=0.02, real=0.04 secs] 此次GC事件的持续时间，通过三个部分来衡量： user 部分表示所有 GC线程消耗的CPU时间； sys 部分表示系统调用和系统等待事件消耗的时间。 real 则表示应用程序暂停的时间。因为串行垃圾收集器(Serial Garbage Collector)只使用单个线程，所以这里 real = user + system ，0.04秒也就是40毫秒。

img.png

Full GC

2021-03-29T21:58:41.187+0800: 1.265: [GC (Allocation Failure) 2021-03-29T21:58:41.187+0800: 1.265: [DefNew: 157247K->157247K(157248K), 0.0000162 secs]2021-03-29T21:58:41.187+0800: 1.265: [Tenured: 302106K->266132K(349568K), 0.0434255 secs] 459354K->266132K(506816K), [Metaspace: 3795K->3795K(1056768K)], 0.0435465 secs] [Times: user=0.05 sys=0.00, real=0.04 secs]
  1. 1.265 表示GC时间距JVM启动时间间隔
  2. [DefNew: 157247K->157247K(157248K), 0.0000162 secs] 表示MinorGC 。
  3. Tenured 用于清理老年代空间的垃圾收集器名称。 Tenured 表明使用的是单线程的STW垃圾收集器，使用的算法为标记-清除-整理(mark-sweep-compact)。302106K->266132K(349568K) 表示GC前后老年代的使用量，以及老年代的空间大小。0.0434255 是清理老年代所花的时间。
  4. 459354K->266132K(506816K) 在GC前后整个堆内存部分的使用情况，以及可用的堆空间大小。
  5. 0.0359163 secs 表示GC事件持续的时间，以秒为单位。
  6. [Metaspace: 3431K->3431K(1056768K)] Metaspace 空间的变化情况
  7. [Times: user=0.05 sys=0.00，real=0.05 secs]
  8. 总结：FullGC，我们主要关注GC之后内存使用量是否下降，其次关注暂停时间。简单估算，GC后老年代使用量为220MB左右，耗时 50ms。如果内存扩大10倍，GC后老年代内存使用量也扩大10倍，那耗时可能就是500ms甚至更高，就会系统有很明显的影响了。这也是我们说串行GC性能弱的一个原因，服务端一般是不会采用串行GC的。

img.png

2.Par GC 串行GC