JVM日志和GC日志-CFANZ编程社区

JVM日志

1.JVM参数格式
(1).以-开头
查看JDK版本。

java -version

(2).以-X开头
设置最大堆内存大小为50m。

java -Xmx50m

(3).以-XX开头
使用G1垃圾回收器

java -XX:+UseG1GC

2.JVM参数分类
(1).标准选项
用于执行常见操作，例如检查JDK版本、设置路径、启用详细输出等。格式不统一，使用java -help查看支持的参数。

java -help

(2).非标准选项
HotSpot的通用选项，格式统一，使用java -X查看支持的参数。

java -X

(3).高级选项
高级选项是为开发人员提供的选项，用于调整Java HotSpot虚拟机特定区域的，这些区域通常具有特定的系统要求，并且可能需要配置访问权限。格式统一，使用如下命令可以查看支持的参数。

java -XX:+UnlockExperimentalVMOptions -XX:+UnlockDiagnosticVMOptions -XX:+PrintFlagsInitial

3.常见JVM参数

参数	含义
-Xms50m	最小堆内存
-Xmx50m	最大堆内存
-Xss	线程栈内存
-Xmn	年轻代大小
-XX:MetaspaceSize=1m	元空间初始化内存
-XX:MaxMetaspaceSize=1m	元空间最大内存
-XX:+UseG1GC	使用G1垃圾收集器
-XX:+UseConcurrentMarkSweepGC	使用CMS垃圾收集器
-XX:+PrintGCDetails	垃圾收集详情
-XX:+PrintGCDateStamps	垃圾收集日期
-XX:+PrintGCTimeStamps	垃圾收集时间戳
-XX:+PrintGCCause	垃圾收集原因
-Xloggc:/Users/wenlei/Documents/gc.log	GC日志文件
-XX:+TraceClassLoading	类加载情况
-XX:+TraceBiasedLocking	偏向锁信息

4.实战

-Xms50m -Xmx50m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause -Xloggc:/Users/wenlei/Documents/gc.log

Java HotSpot(TM) 64-Bit Server VM (25.144-b01) for bsd-amd64 JRE (1.8.0_144-b01), built on Jul 21 2017 22:07:42 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 16777216k(109268k free)

/proc/meminfo:

CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=52428800 -XX:+ManagementServer -XX:MaxHeapSize=52428800 -XX:+PrintGC -XX:+PrintGCCause -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2022-12-25T22:14:33.422-0800: 0.517: [GC (Allocation Failure) [PSYoungGen: 12800K->2037K(14848K)] 12800K->2683K(49152K), 0.0091926 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 
2022-12-25T22:14:36.198-0800: 3.293: [GC (Metadata GC Threshold) [PSYoungGen: 3833K->342K(14336K)] 21349K->18514K(48640K), 0.0010944 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-12-25T22:14:36.199-0800: 3.294: [Full GC (Metadata GC Threshold) [PSYoungGen: 342K->0K(14336K)] [ParOldGen: 18171K->15222K(34304K)] 18514K->15222K(48640K), [Metaspace: 33795K->33795K(1079296K)], 0.0669281 secs] [Times: user=0.26 sys=0.02, real=0.07 secs]

GC日志

1.YoungGC

XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2022-12-25T22:14:33.422-0800: 0.517: [GC (Allocation Failure) [PSYoungGen: 12800K->2037K(14848K)] 12800K->2683K(49152K), 0.0091926 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]

2022-12-25T22:14:33.422-0800:当前时间戳，由PrintGCDateStamps打印
0.517:当前相对时间戳，表示应用启动多久后触发，由PrintGCTimeStamps打印
GC (Allocation Failure):造成GC的原因，由PrintGCCause打印
PSYoungGen:12800K->2037K(14848K)

PSYoungGen:垃圾收集器类型

PSYoungGen:Parallel Scavenge
ParNew:ParNew
DefNew:Serial
G1:G1

12800K:回收前，年轻代使用的大小
2037K:回收后，年轻代使用的大小
14848K:年轻代总大小
12800K:回收之前，堆内存使用的大小
2683K:回收之后，堆内存使用的大小
49152K:堆内存总大小
0.0091926 secs:垃圾收集器判断出需要垃圾回收到垃圾回收结束所花费的时间

user=0.02:用户耗时
sys=0.01:系统耗时
real=0.01 secs:实际耗时

2.FullGC

2022-12-25T22:14:36.199-0800: 3.294: [Full GC (Metadata GC Threshold) [PSYoungGen: 342K->0K(14336K)] [ParOldGen: 18171K->15222K(34304K)] 18514K->15222K(48640K), [Metaspace: 33795K->33795K(1079296K)], 0.0669281 secs] [Times: user=0.26 sys=0.02, real=0.07 secs]

2022-12-25T22:14:36.199-0800:当前时间戳，由PrintGCDateStamps打印
3.294:当前相对时间戳，表示应用启动多久后触发，由PrintGCTimeStamps打印
Full GC (Metadata GC Threshold):造成GC的原因，由PrintGCCause打印
ParOldGen: 18171K->15222K(34304K)

ParOldGen:垃圾收集器类型

ParOldGen:Parallel Old
DefNew:Serial Old
CMS:CMS

18171K:回收前，老年代使用的大小
15222K:回收后，老年代使用的大小
34304K:老年代总大小
18514K:回收之前，堆内存使用的大小
15222K:回收之后，堆内存使用的大小
48640K:堆内存总大小
0.0669281 secs:垃圾收集器判断出需要垃圾回收到垃圾回收结束所花费的时间

3.使用G1垃圾收集器

-Xms50m -Xmx50m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause -XX:+UseG1GC -Xloggc:/Users/wenlei/Documents/gc.log

#1.初始标记(Stop The World)
2022-12-25T22:49:27.545-0800: 1.191: [GC pause (Metadata GC Threshold) (young) (initial-mark), 0.0044215 secs]
   [Parallel Time: 3.8 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 1190.7, Avg: 1190.8, Max: 1190.9, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 0.9, Avg: 1.4, Max: 1.8, Diff: 0.9, Sum: 10.8]
      [Update RS (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 1.4]
         [Processed Buffers: Min: 0, Avg: 2.1, Max: 5, Diff: 5, Sum: 17]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.4, Max: 1.8, Diff: 1.8, Sum: 3.4]
      [Object Copy (ms): Min: 0.3, Avg: 1.1, Max: 1.7, Diff: 1.4, Sum: 9.2]
      [Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.6, Diff: 0.6, Sum: 4.1]
         [Termination Attempts: Min: 1, Avg: 16.5, Max: 28, Diff: 27, Sum: 132]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 3.5, Avg: 3.6, Max: 3.7, Diff: 0.2, Sum: 29.1]
      [GC Worker End (ms): Min: 1194.4, Avg: 1194.4, Max: 1194.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 26.0M(26.0M)->0.0B(26.0M) Survivors: 4096.0K->4096.0K Heap: 38.1M(50.0M)->12.8M(50.0M)]
 [Times: user=0.02 sys=0.00, real=0.01 secs]
#开始扫描初始标记阶段Survivor区的Roots对象
2022-12-25T22:49:27.550-0800: 1.195: [GC concurrent-root-region-scan-start]
#扫描完成
2022-12-25T22:49:27.552-0800: 1.197: [GC concurrent-root-region-scan-end, 0.0014173 secs]
#2.并发标记
2022-12-25T22:49:27.552-0800: 1.197: [GC concurrent-mark-start]
#并发标记结束
2022-12-25T22:49:27.553-0800: 1.199: [GC concurrent-mark-end, 0.0019070 secs]
#3.最终标记
2022-12-25T22:49:27.554-0800: 1.199: [GC remark 2022-12-25T22:49:27.554-0800: 1.199: [Finalize Marking, 0.0001990 secs] 2022-12-25T22:49:27.554-0800: 1.200: [GC ref-proc, 0.0000403 secs] 2022-12-25T22:49:27.554-0800: 1.200: [Unloading, 0.0065358 secs], 0.0070309 secs]
 [Times: user=0.01 sys=0.01, real=0.01 secs]
#4.筛选回收(Stop The World)
#没有存活对象的Old Region和Humongous Region将被释放和清空
#为了准备下次GC，在CSet的Old Region会根据他们的回收收益进行排序
2022-12-25T22:49:27.561-0800: 1.207: [GC cleanup 14M->12M(50M), 0.0002877 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]
#并发清理开始
2022-12-25T22:49:27.563-0800: 1.208: [GC concurrent-cleanup-start]
#并发清理结束
2022-12-25T22:49:27.563-0800: 1.208: [GC concurrent-cleanup-end, 0.0000083 secs]