前文如下：
今天实战基于昨天的jvm配置，实战看一下打出来的日志文件，看看具体日志输出怎么解析。
1. 查看启动参数
#设置启动参数 ## 测试工程 export PRO_NAME=test-project ## 工程目录 export DEPLOY_PATH=/home/admin/java/test-project ## 启动参数 export JAVA_OPTS="-server -Xms3072M -Xmx3072M -XX:PretenureSizeThreshold=64m -XX: -OmitStackTraceInFastThrow -XX:+PrintCommandLineFlags -XX:MetaspaceSize=600m -XX:MaxMetaspaceSize=600m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/admin/java/test-project/logs/ -Xlog:gc*,gc+ref=debug,gc+heap=debug,gc+age=trace:file=logs/gc.log:tags,uptime,time ,level:filecount=10,filesize=200m" #设置启动脚本 exec nohup java -Dproject.home=$DEPLOY_PATH $JAVA_OPTS -jar $PRO_NAME >> /dev/null 2>&1 & #查看启动进程 [admin@ 127.0.0.1]$ ps -ef|grep java admin 1345636 1 2 Aug27 ? 04:55:38 java -Dproject.home=/home/admin/java/test-project -server -Xms3072M -Xmx3072M -XX:PretenureSizeThreshold=64m -XX:-OmitStackTraceInFastThrow -XX:+PrintCommandLineFlags -XX:MetaspaceSize=600m -XX:MaxMetaspaceSize=600m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/admin/java/test-project/logs/ -Xlog:gc*,gc+ref=debug,gc+heap=debug,gc+age=trace:file=logs/gc.log:tags,uptime,time, level:filecount=10,filesize=200m -jar test-project.jar [admin@ 127.0.0.1]$ jps 1345636 test-project.jar 2245365 Jps ## 其中jdk1.9带入xlog，当前配置如下： Xlog:gc*,gc+ref=debug,gc+heap=debug,gc+age=trace:file=logs/gc.log:tags,uptime,time, level:filecount=10,filesize=200m tag：add, **age**, alloc, annotation, aot, arguments, attach, barrier, biasedlocking, blocks, bot, breakpoint, bytecode, cds, census, class, classhisto, cleanup, codecache, compaction, compilation, constantpool, constraints, container, coops, cpu, cset, data, datacreation, dcmd, decoder, defaultmethods, director, dump, dynamic, ergo, event, exceptions, exit, fingerprint, free, freelist, **gc**, handshake, hashtables, **heap**, humongous, ihop, iklass, init, inlining, install, interpreter, itables, jfr, jit, jni, jvmti, liveness, load, loader, logging, malloc, mark, marking, membername, memops, metadata, metaspace, methodcomparator, mirror, mmu, module, monitorinflation, monitormismatch, nestmates, nmethod, normalize, numa, objecttagging, obsolete, oldobject, oom, oopmap, oops, oopstorage, os, pagesize, parser, patch, path, perf, periodic, phases, plab, preorder, preview, promotion, protectiondomain, ptrqueue, purge, record, redefine, **ref**, refine, region, reloc, remset, resolve, safepoint, sampling, scavenge, setting, smr, stackmap, stacktrace, stackwalk, start, startuptime, state, stats, streaming, stringdedup, stringtable, subclass, survivor, sweep, symboltable, system, table, task, thread, time, timer, tlab, tracking, unload, unshareable, update, verification, verify, vmmutex, vmoperation, vmthread, vtables, vtablestubs, workgang levels:off, trace, debug, info, warning, error decorators：time (t), utctime (utc), uptime (u), timemillis (tm), uptimemillis (um), timenanos (tn), uptimenanos (un), hostname (hn), pid (p), tid (ti), level (l), tags (tg) # 分析如下：会打的gc日志内容如下： Xlog:gc*, gc+ref=debug, gc+heap=debug, gc+age=trace:file=logs/gc.log //gc日志+日志级别+日志文件 :tags,uptime,time,level //decorators 哪些内容到日志：tag，更新时间，时间，级别 :filecount=10,filesize=200m //文件数量和文件大小
2. 查看日志
oom堆栈日志目录：/home/admin/java/test-project/logs/ [admin@ 127.0.0.1]$ ls gc.log gc.log.0 gc.log.1 gc.log.2 gc.log.3 gc.log.4 gc.log.5 gc.log.6 gc.log.7 gc.log.8 gc.log.9 #十个文件 [admin@127.0.0.1]$ more gc.log [2022-08-20T16:11:15.076+0800][0.005s][info][gc,heap] Heap region size: 1M [2022-08-20T16:11:15.076+0800][0.005s][debug][gc,heap] Minimum heap 3221225472 Initial heap 3221225472 Maximum heap 3221225472 [2022-08-20T16:11:15.100+0800][0.029s][info ][gc ] Using G1 [2022-08-20T16:11:15.100+0800][0.029s][info ][gc,heap,coops] Heap address: 0x0000000740000000, size: 3072 MB, Compressed Oops mode: Zero based, Oop shift amount: 3 [2022-08-20T16:11:15.100+0800][0.029s][info ][gc,cds ] Mark closed archive regions in map: [0x00000007bff00000, 0x00000007bff6aff8] [2022-08-20T16:11:15.100+0800][0.029s][info ][gc,cds ] Mark open archive regions in map: [0x00000007bfe00000, 0x00000007bfe47ff8] #########第一次gc前准备######### [2022-08-20T16:11:15.789+0800][0.718s][debug][gc,heap ] GC(0) Heap before GC invocations=0 (full 0): garbage-first heap total 3145728K, used 165580K [0x0000000740000000, 0x0000000800000000)####堆内存3GB,已用161MB[2022-08-20T16:11:15.789+0800][0.718s][debug][gc,heap ] GC(0) region size 1024K, 153 young (156672K), 0 survivors (0K) [2022-08-20T16:11:15.789+0800][0.718s][debug][gc,heap ] GC(0) Metaspace used 3718K, capacity 6014K, committed 6272K, reserved 614400K [2022-08-20T16:11:15.789+0800][0.718s][debug][gc,heap ] GC(0) class space used 388K, capacity 629K, committed 640K, reserved 606208K #########下面开始第一次gc######### [2022-08-20T16:11:15.789+0800][0.718s][info ][gc,start ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) ###在新生代进行垃圾回收 [2022-08-20T16:11:15.792+0800][0.721s][info ][gc,task ] GC(0) Using 8 workers of 8 for evacuation ###使用8条垃圾回收线程 [2022-08-20T16:11:15.792+0800][0.721s][debug][gc,age ] GC(0) Desired survivor size 10485760 bytes, new threshold 15 (max threshold 15) ###survivor大小和复制年龄大小15次 [2022-08-20T16:11:15.801+0800][0.730s][debug][gc,ref ] GC(0) Skipped phase1 of Reference Processing due to unavailable references [2022-08-20T16:11:15.801+0800][0.731s][debug][gc,ref ] GC(0) Skipped phase3 of Reference Processing due to unavailable references [2022-08-20T16:11:15.802+0800][0.731s][trace][gc,age ] GC(0) Age table with threshold 15 (max threshold 15) [2022-08-20T16:11:15.802+0800][0.731s][trace][gc,age ] GC(0) - age 1: 8217848 bytes, 8217848 total [2022-08-20T16:11:15.802+0800][0.731s][info ][gc,phases ] GC(0) Pre Evacuate Collection Set: 0.1ms [2022-08-20T16:11:15.802+0800][0.731s][info ][gc,phases ] GC(0) Evacuate Collection Set: 9.0ms [2022-08-20T16:11:15.802+0800][0.731s][info ][gc,phases ] GC(0) Post Evacuate Collection Set: 0.9ms [2022-08-20T16:11:15.802+0800][0.731s][info ][gc,phases ] GC(0) Other: 3.4ms [2022-08-20T16:11:15.802+0800][0.731s][info ][gc,heap ] GC(0) Eden regions: 153->0(145) ###Eden区回收 [2022-08-20T16:11:15.802+0800][0.731s][info ][gc,heap ] GC(0) Survivor regions: 0->8(20) ###Survivor区复制 [2022-08-20T16:11:15.802+0800][0.731s][info ][gc,heap ] GC(0) Old regions: 2->2 ###old区 [2022-08-20T16:11:15.802+0800][0.731s][info ][gc,heap ] GC(0) Humongous regions: 9->0 [2022-08-20T16:11:15.802+0800][0.731s][info ][gc,metaspace ] GC(0) Metaspace: 3718K->3718K(614400K) ###元空间 [2022-08-20T16:11:15.802+0800][0.731s][debug][gc,heap ] GC(0) Heap after GC invocations=1 (full 0): garbage-first heap total 3145728K, used 8817K [0x0000000740000000, 0x0000000800000000) ####第一次回收之后堆内存3GB,已用8.6MB[2022-08-20T16:11:15.802+0800][0.731s][debug][gc,heap ] GC(0) region size 1024K, 8 young (8192K), 8 survivors (8192K) [2022-08-20T16:11:15.802+0800][0.731s][debug][gc,heap ] GC(0) Metaspace used 3718K, capacity 6014K, committed 6272K, reserved 614400K [2022-08-20T16:11:15.802+0800][0.731s][debug][gc,heap ] GC(0) class space used 388K, capacity 629K, committed 640K, reserved 606208K [2022-08-20T16:11:15.802+0800][0.731s][info ][gc ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 162M->8M(3072M) 13.380ms ####第一次回收之后年轻代占用从162->8M [2022-08-20T16:11:15.802+0800][0.731s][info ][gc,cpu ] GC(0) User=0.04s Sys=0.01s Real=0.01s #### 第一次回收之后CPU使用时间 #########第二次gc前准备######### [2022-08-20T16:11:16.258+0800][1.187s][debug][gc,heap ] GC(1) Heap before GC invocations=1 (full 0): garbage-first heap total 3145728K, used 157297K [0x0000000740000000, 0x0000000800000000)[2022-08-20T16:11:16.258+0800][1.187s][debug][gc,heap ] GC(1) region size 1024K, 153 young (156672K), 8 survivors (8192K) [2022-08-20T16:11:16.258+0800][1.187s][debug][gc,heap ] GC(1) Metaspace used 6669K, capacity 8145K, committed 8448K, reserved 614400K [2022-08-20T16:11:16.258+0800][1.187s][debug][gc,heap ] GC(1) class space used 748K, capacity 918K, committed 1024K, reserved 606208K #########下面开始第二次gc######### [2022-08-20T16:11:16.258+0800][1.187s][info ][gc,start ] GC(1) Pause Young (Normal) (G1 Evacuation Pause) [2022-08-20T16:11:16.258+0800][1.187s][info ][gc,task ] GC(1) Using 8 workers of 8 for evacuation [2022-08-20T16:11:16.258+0800][1.187s][debug][gc,age ] GC(1) Desired survivor size 10485760 bytes, new threshold 15 (max threshold 15) [2022-08-20T16:11:16.263+0800][1.192s][debug][gc,ref ] GC(1) Skipped phase1 of Reference Processing due to unavailable references [2022-08-20T16:11:16.264+0800][1.193s][debug][gc,ref ] GC(1) Skipped phase3 of Reference Processing due to unavailable references [2022-08-20T16:11:16.264+0800][1.193s][trace][gc,age ] GC(1) Age table with threshold 15 (max threshold 15) [2022-08-20T16:11:16.264+0800][1.193s][trace][gc,age ] GC(1) - age 1: 611136 bytes, 611136 total [2022-08-20T16:11:16.264+0800][1.193s][trace][gc,age ] GC(1) - age 2: 8155368 bytes, 8766504 total [2022-08-20T16:11:16.264+0800][1.193s][info ][gc,phases ] GC(1) Pre Evacuate Collection Set: 0.1ms [2022-08-20T16:11:16.264+0800][1.193s][info ][gc,phases ] GC(1) Evacuate Collection Set: 4.6ms [2022-08-20T16:11:16.264+0800][1.193s][info ][gc,phases ] GC(1) Post Evacuate Collection Set: 0.8ms [2022-08-20T16:11:16.264+0800][1.193s][info ][gc,phases ] GC(1) Other: 0.6ms [2022-08-20T16:11:16.264+0800][1.193s][info ][gc,heap ] GC(1) Eden regions: 145->0(144) [2022-08-20T16:11:16.264+0800][1.193s][info ][gc,heap ] GC(1) Survivor regions: 8->9(20) [2022-08-20T16:11:16.264+0800][1.193s][info ][gc,heap ] GC(1) Old regions: 2->2 [2022-08-20T16:11:16.264+0800][1.193s][info ][gc,heap ] GC(1) Humongous regions: 0->0 [2022-08-20T16:11:16.264+0800][1.193s][info ][gc,metaspace ] GC(1) Metaspace: 6669K->6669K(614400K) [2022-08-20T16:11:16.264+0800][1.193s][debug][gc,heap ] GC(1) Heap after GC invocations=2 (full 0): garbage-first heap total 3145728K, used 9617K [0x0000000740000000, 0x0000000800000000)[2022-08-20T16:11:16.264+0800][1.193s][debug][gc,heap ] GC(1) region size 1024K, 9 young (9216K), 9 survivors (9216K) [2022-08-20T16:11:16.264+0800][1.193s][debug][gc,heap ] GC(1) Metaspace used 6669K, capacity 8145K, committed 8448K, reserved 614400K [2022-08-20T16:11:16.264+0800][1.193s][debug][gc,heap ] GC(1) class space used 748K, capacity 918K, committed 1024K, reserved 606208K [2022-08-20T16:11:16.264+0800][1.193s][info ][gc ] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 153M->9M(3072M) 6.076ms [2022-08-20T16:11:16.264+0800][1.193s][info ][gc,cpu ] GC(1) User=0.05s Sys=0.00s Real=0.01s [2022-08-20T16:11:16.722+0800][1.652s][debug][gc,heap ] GC(2) Heap before GC invocations=2 (full 0): garbage-first heap total 3145728K, used 157073K [0x0000000740000000, 0x0000000800000000)[2022-08-20T16:11:16.723+0800][1.652s][debug][gc,heap ] GC(2) region size 1024K, 153 young (156672K), 9 survivors (9216K) [2022-08-20T16:11:16.723+0800][1.652s][debug][gc,heap ] GC(2) Metaspace used 8150K, capacity 9495K, committed 9728K, reserved 616448K [2022-08-20T16:11:16.723+0800][1.652s][debug][gc,heap ] GC(2) class space used 977K, capacity 1155K, committed 1280K, reserved 606208K [2022-08-20T16:11:16.723+0800][1.652s][info ][gc,start ] GC(2) Pause Young (Normal) (G1 Evacuation Pause) [2022-08-20T16:11:16.723+0800][1.652s][info ][gc,task ] GC(2) Using 8 workers of 8 for evacuation [2022-08-20T16:11:16.723+0800][1.652s][debug][gc,age ] GC(2) Desired survivor size 10485760 bytes, new threshold 15 (max threshold 15) [2022-08-20T16:11:16.728+0800][1.657s][debug][gc,ref ] GC(2) Skipped phase1 of Reference Processing due to unavailable references [2022-08-20T16:11:16.728+0800][1.657s][debug][gc,ref ] GC(2) Skipped phase3 of Reference Processing due to unavailable references [2022-08-20T16:11:16.728+0800][1.657s][trace][gc,age ] GC(2) Age table with threshold 15 (max threshold 15) [2022-08-20T16:11:16.728+0800][1.657s][trace][gc,age ] GC(2) - age 1: 406104 bytes, 406104 total [2022-08-20T16:11:16.728+0800][1.657s][trace][gc,age ] GC(2) - age 2: 550944 bytes, 957048 total [2022-08-20T16:11:16.728+0800][1.657s][trace][gc,age ] GC(2) - age 3: 8151656 bytes, 9108704 total [2022-08-20T16:11:16.729+0800][1.658s][info ][gc,phases ] GC(2) Pre Evacuate Collection Set: 0.1ms [2022-08-20T16:11:16.729+0800][1.658s][info ][gc,phases ] GC(2) Evacuate Collection Set: 4.8ms [2022-08-20T16:11:16.729+0800][1.658s][info ][gc,phases ] GC(2) Post Evacuate Collection Set: 0.9ms [2022-08-20T16:11:16.729+0800][1.658s][info ][gc,phases ] GC(2) Other: 0.6ms [2022-08-20T16:11:16.729+0800][1.658s][info ][gc,heap ] GC(2) Eden regions: 144->0(171) [2022-08-20T16:11:16.729+0800][1.658s][info ][gc,heap ] GC(2) Survivor regions: 9->10(20) [2022-08-20T16:11:16.729+0800][1.658s][info ][gc,heap ] GC(2) Old regions: 2->2 [2022-08-20T16:11:16.729+0800][1.658s][info ][gc,heap ] GC(2) Humongous regions: 0->0 [2022-08-20T16:11:16.729+0800][1.658s][info ][gc,metaspace ] GC(2) Metaspace: 8150K->8150K(616448K) [2022-08-20T16:11:16.729+0800][1.658s][debug][gc,heap ] GC(2) Heap after GC invocations=3 (full 0): garbage-first heap total 3145728K, used 10302K [0x0000000740000000, 0x0000000800000000)[2022-08-20T16:11:16.729+0800][1.658s][debug][gc,heap ] GC(2) region size 1024K, 10 young (10240K), 10 survivors (10240K) [2022-08-20T16:11:16.729+0800][1.658s][debug][gc,heap ] GC(2) Metaspace used 8150K, capacity 9495K, committed 9728K, reserved 616448K [2022-08-20T16:11:16.729+0800][1.658s][debug][gc,heap ] GC(2) class space used 977K, capacity 1155K, committed 1280K, reserved 606208K [2022-08-20T16:11:16.729+0800][1.658s][info ][gc ] GC(2) Pause Young (Normal) (G1 Evacuation Pause) 153M->10M(3072M) 6.374ms [2022-08-20T16:11:16.729+0800][1.658s][info ][gc,cpu ] GC(2) User=0.04s Sys=0.01s Real=0.01s
日志解析
- 从上面可以看出，打印的日志确实是gc相关日志，打印在了gc.log文件，
- 一共十个历史文件，分别后缀gc.log.0-gc.log.9；一个主文件。
- 每行日志信息会带有时间，耗时，tag信息和日志级别
- heap事件打印debug以上级别日志；ref事件打印debug以上级别；age打印trace以上级别
- 开始的几行日志，打印了Heap region size；//每个region大小 Minimum heap 3221225472
Initial heap 3221225472
Maximum heap 3221225472堆内存大小 3GB
Using G1 使用G1垃圾回收器（jdk11默认） Heap address: 0x0000000740000000, size: 3072 MB 分配堆内存地址， Compressed Oops mode: Zero based 开启指针压缩，零基压缩 Oop shift amount: 3 对象默认以 8 字节对齐，移动3位（2^3 = 8） - Mark closed archive regions in map;Mark open archive regions in map。参考：探究 Java 应用的启动速度优化标记open/Closed Archive regions 为了适应多种场景，OpenJDK的HeapArchive还提供了Open和Closed两种级别：
不允许引用Open Archive 和Heap中的对象 可以引用Closed Archive内部的对象只读，不可写 Open Archive 可以引用任何对象可写 这样设计的原因是对于一些只读结构，放在Closed Archive 中可以做到对GC完全无开销。网络异常，图片无法展示|
- 当前日志只看到年轻代的回收，老年代后续继续解析
3. 扩展
3.1 JVM之压缩指针——Compressed oops
参考文档: JVM之压缩指针——Compressed oopsJVM测试指针压缩
3.1.1 什么是 OOP ?
在堆中，32位的对象引用（指针）占4个字节，而64位的对象引用占8个字节。也就是说，64位的对象引用大小是32位的2倍。64位JVM在支持更大堆的同时，由于对象引用变大却带来了性能问题：
- 增加了GC开销：64位对象引用需要占用更多的堆空间，留给其他数据的空间将会减少，从而加快了GC的发生，更频繁的进行GC。
- 降低CPU缓存命中率：64位对象引用增大了，CPU能缓存的oop将会更少，从而降低了CPU缓存的效率。 为了能够保持32位的性能，oop必须保留32位。那么，如何用32位oop来引用更大的堆内存呢？答案是——压缩指针（CompressedOops）。
OOP = “ordinary object pointer” 普通对象指针。 启用CompressOops后，会压缩的对象：
- 每个Class的属性指针（静态成员变量）
- 每个对象的属性指针
- 普通对象数组的每个元素指针 当然，压缩也不是万能的，针对一些特殊类型的指针，JVM是不会优化的。 比如指向PermGen的Class对象指针，本地变量，堆栈元素，入参，返回值，NULL指针不会被压缩。
3.1.2 CompressedOops原理
64位地址分为堆的基地址+偏移量，当堆内存<32GB时候，在压缩过程中，把偏移量/8后保存到32位地址。在解压再把32位地址放大8倍，所以启用CompressedOops的条件是堆内存要在4GB*8=32GB以内。
CompressedOops，可以让跑在64位平台下的JVM，不需要因为更宽的寻址，而付出Heap容量损失的代价。 不过它的实现方式是在机器码中植入压缩与解压指令，可能会给JVM增加额外的开销。
3.1.3 零基压缩优化(Zero Based Compressd Oops)
零基压缩是针对压解压动作的进一步优化。 它通过改变正常指针的随机地址分配特性，强制堆地址从零开始分配（需要OS支持），进一步提高了压解压效率。要启用零基压缩，你分配给JVM的内存大小必须控制在4G以上，32G以下。
3.1.4 总结：
- 如果GC堆大小在4G以下，直接砍掉高32位，避免了编码解码过程；
- 如果GC堆大小在4G以上32G以下，则启用UseCompressedOop；
- 如果GC堆大小大于32G，压指失效，使用原来的64位（所以说服务器内存太大不好......） 注：
32位HotSpot VM是不支持UseCompressedOops参数的，只有64位HotSpot VM才支持。Oracle JDK从6 update 23开始在64位系统上会默认开启压缩指针。
