jvm GC日志分析

1.分析程序

public class Application {
    private static Map<String, String> stringContainer = new HashMap<>();

    public static void main(String[] args) {
        System.out.println("Start of program!");
        String stringWithPrefix = "stringWithPrefix";

        // Load Java Heap with 3 M java.lang.String instances
        for (int i = 0; i < 3000000; i++) {
            String newString = stringWithPrefix + i;
            stringContainer.put(newString, newString);
        }
        System.out.println("MAP size: " + stringContainer.size());

        // Explicit GC!
        System.gc();

        // Remove 2 M out of 3 M
        for (int i = 0; i < 2000000; i++) {
            String newString = stringWithPrefix + i;
            stringContainer.remove(newString);
        }

        System.out.println("容量: " + stringContainer.size());
        System.out.println("stop!");
    }
}

2.添加 jvm 参数
java 8  -XX:+UseSerialGC -Xms1024m -Xmx1024m -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps
java 11  -XX:+UseSerialGC -Xms1024m -Xmx1024m -Xlog:gc=debug:file=gc.txt -Xlog:gc*::time
2.1java 8 输出

Start of program!
2021-07-10T16:52:46.317+0800: 1.632: [GC (Allocation Failure) 2021-07-10T16:52:46.317+0800: 1.632: [DefNew: 279616K->34944K(314560K), 1.1156542 secs] 279616K->229703K(1013632K), 1.1157999 secs] [Times: user=0.69 sys=0.17, real=1.12 secs]
MAP size: 3000000
2021-07-10T16:52:47.742+0800: 3.057: [Full GC (System.gc()) 2021-07-10T16:52:47.742+0800: 3.057: [Tenured: 194759K->368733K(699072K), 1.1881951 secs] 383157K->368733K(1013632K), [Metaspace: 3407K->3407K(1056768K)], 1.1882956 secs] [Times: user=1.06 sys=0.08, real=1.19 secs]
容量: 1000000
stop!
Heap
def new generation   total 314560K, used 204437K [0x00000000c0000000, 0x00000000d5550000, 0x00000000d5550000)
  eden space 279616K, 73% used [0x00000000c0000000, 0x00000000cc7a54c0, 0x00000000d1110000)
  from space 34944K,   0% used [0x00000000d3330000, 0x00000000d3330000, 0x00000000d5550000)
  to   space 34944K,   0% used [0x00000000d1110000, 0x00000000d1110000, 0x00000000d3330000)
tenured generation   total 699072K, used 368733K [0x00000000d5550000, 0x0000000100000000, 0x0000000100000000)
   the space 699072K, 52% used [0x00000000d5550000, 0x00000000ebd674d8, 0x00000000ebd67600, 0x0000000100000000)
Metaspace       used 3421K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 371K, capacity 388K, committed 512K, reserved 1048576K

2021-07-10T16:52:46.317+0800: 1.632: GC发生时间

GC or Full GC – 垃圾收集器的类型 minor gc 和 full gc

Allocation Failure|System.gc() 产生垃圾收集原因

DefNew|Tenured 使用的垃圾收集器类型

279616K->34944K(314560K) gc前内存->gc后内存（该区域总内存）

1.1156542 secs gc所占用的时间

279616K->229703K(1013632K)java 堆gc前内存->java 堆gc后内存（Java堆总内存）

Times: user=0.69 sys=0.17, real=1.12 secs

user 垃圾收集器消耗的总 CPU 时间
sys花费在操作系统调用或等待系统事件上的时间
real这是所有经过的时间，包括其他进程使用的时间片
2.2java 11输出

[2021-07-10T16:55:00.327+0800] -XX:+PrintGCDetails is deprecated. Will use -Xlog:gc* instead.
[2021-07-10T16:55:00.363+0800] Using Serial
[2021-07-10T16:55:00.363+0800] Heap address: 0x00000000c0000000, size: 1024 MB, Compressed Oops mode: 32-bit
Start of program!
[2021-07-10T16:55:02.383+0800] GC(0) Pause Young (Allocation Failure)
[2021-07-10T16:55:03.480+0800] GC(0) DefNew: 279616K->34944K(314560K)
[2021-07-10T16:55:03.480+0800] GC(0) Tenured: 0K->197430K(699072K)
[2021-07-10T16:55:03.480+0800] GC(0) Metaspace: 6578K->6578K(1056768K)
[2021-07-10T16:55:03.480+0800] GC(0) Pause Young (Allocation Failure) 273M->226M(989M) 1097.434ms
[2021-07-10T16:55:03.480+0800] GC(0) User=0.89s Sys=0.20s Real=1.10s
MAP size: 3000000
[2021-07-10T16:55:03.646+0800] GC(1) Pause Full (System.gc())
[2021-07-10T16:55:03.646+0800] GC(1) Phase 1: Mark live objects
[2021-07-10T16:55:04.067+0800] GC(1) Phase 1: Mark live objects 421.200ms
[2021-07-10T16:55:04.067+0800] GC(1) Phase 2: Compute new object addresses
[2021-07-10T16:55:04.264+0800] GC(1) Phase 2: Compute new object addresses 197.401ms
[2021-07-10T16:55:04.264+0800] GC(1) Phase 3: Adjust pointers
[2021-07-10T16:55:04.513+0800] GC(1) Phase 3: Adjust pointers 249.541ms
[2021-07-10T16:55:04.514+0800] GC(1) Phase 4: Move objects
[2021-07-10T16:55:04.635+0800] GC(1) Phase 4: Move objects 121.660ms
[2021-07-10T16:55:04.636+0800] GC(1) DefNew: 105460K->0K(314560K)
[2021-07-10T16:55:04.636+0800] GC(1) Tenured: 197430K->300246K(699072K)
[2021-07-10T16:55:04.636+0800] GC(1) Metaspace: 6578K->6578K(1056768K)
[2021-07-10T16:55:04.636+0800] GC(1) Pause Full (System.gc()) 295M->293M(989M) 990.440ms
[2021-07-10T16:55:04.636+0800] GC(1) User=0.94s Sys=0.03s Real=0.99s
容量: 1000000
stop!
[2021-07-10T16:55:05.863+0800] Heap
[2021-07-10T16:55:05.863+0800] def new generation   total 314560K, used 149253K [0x00000000c0000000, 0x00000000d5550000, 0x00000000d5550000)
[2021-07-10T16:55:05.863+0800]   eden space 279616K, 53% used [0x00000000c0000000, 0x00000000c91c1678, 0x00000000d1110000)
[2021-07-10T16:55:05.863+0800]   from space 34944K,   0% used [0x00000000d3330000, 0x00000000d3330000, 0x00000000d5550000)
[2021-07-10T16:55:05.863+0800]   to   space 34944K,   0% used [0x00000000d1110000, 0x00000000d1110000, 0x00000000d3330000)
[2021-07-10T16:55:05.863+0800] tenured generation   total 699072K, used 300246K [0x00000000d5550000, 0x0000000100000000, 0x0000000100000000)
[2021-07-10T16:55:05.863+0800]    the space 699072K, 42% used [0x00000000d5550000, 0x00000000e7a85918, 0x00000000e7a85a00, 0x0000000100000000)
[2021-07-10T16:55:05.863+0800] Metaspace       used 6602K, capacity 6671K, committed 6784K, reserved 1056768K
[2021-07-10T16:55:05.863+0800]   class space    used 578K, capacity 602K, committed 640K, reserved 1048576K