L
L
LearnJava
Search…
看懂gc日志

一、什么时候触发GC

首先我们回顾一下什么时候会触发GC:
Minor GC触发条件:当Eden区满时,触发Minor GC。
Full GC触发条件:
(1)调用System.gc时,系统建议执行Full GC,但是不必然执行
(2)老年代空间不足
(3)方法区空间不足
(4)通过Minor GC后进入老年代的平均大小大于老年代的可用内存
(5)由Eden区、From Space区向To Space区复制时,对象大小大于To Space可用内存,则把该对象转存到老年代,且老年代的可用内存小于该对象大小

二、看懂日志

打开gc日志后,日志文件里面会打印类似下面的日志:
2018-06-15T10:44:26.630-0800: [GC (System.gc()) [PSYoungGen: 2673K->496K(38400K)] 2673K->504K(125952K), 0.0010649 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2018-06-15T10:44:26.631-0800: [Full GC (System.gc()) [PSYoungGen: 496K->0K(38400K)] [ParOldGen: 8K->402K(87552K)] 504K->402K(125952K), [Metaspace: 3300K->3300K(1056768K)], 0.0066154 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2018-06-15T10:44:26.632-0800:Total time for which application threads were stopped: 0.0010226 seconds, Stopping threads took: 0.0001058 seconds
Minor GC
2018-06-15T10:44:26.630-0800: [GC (System.gc()) [PSYoungGen: 2673K->496K(38400K)] 2673K->504K(125952K), 0.0010649 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
从左到右表示
[GC类型 (System.gc()][新生代:GC前该内存区域已使用容量->GC后该内存区域已使用容量(该内存区域的总容量)] GC前Java堆已使用容量->GC后Java堆已使用容量(Java堆总容量), [GC耗时: 用户态消耗的CPU时间 内核态消耗的CPU时间, 整个过程实际所经过的墙钟时间(Wall Clock Time)]
user+sys是CPU时间,每个CPU core单独计算,所以这个时间可能会是real的好几倍。CPU时间和墙钟时间的差别是,墙钟时间包括各种非运算的等待耗时,例如等待磁盘I/O、等待线程阻塞,而CPU时间不包括这些耗时。
时钟时间(墙上时钟时间wall clock time):从进程从开始运行到结束,时钟走过的时间,这其中包含了进程在阻塞和等待状态的时间。 用户CPU时间:就是用户的进程获得了CPU资源以后,在用户态执行的时间。 系统CPU时间:用户进程获得了CPU资源以后,在内核态的执行时间。
Full GC
2018-06-15T10:44:26.631-0800: [Full GC (System.gc()) [PSYoungGen: 496K->0K(38400K)] [ParOldGen: 8K->402K(87552K)] 504K->402K(125952K), [Metaspace: 3300K->3300K(1056768K)], 0.0066154 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
从左到右表示
[GC类型 (System.gc()) [Young区: GC前Young的内存占用->GC后Young的内存占用(Young区域总大小)] [old老年代: GC前Old的内存占用->GC后Old的内存占用(Old区域总大小)] GC前堆内存占用->GC后堆内存占用(JVM堆总大小), [永久代区: GC前占用大小->C后占用大小(永久代区总大小)], GC用户耗时] [Times:用户耗时 sys=系统时间, real=实际时间]
stop-the-world(STW)时间
2018-06-15T10:44:26.632-0800:Total time for which application threads were stopped: 0.0010226 seconds, Stopping threads took: 0.0001058 seconds
application threads stopped的时间表示应用暂停时间,Stopping threads took 的时间表示等待所有的应用线程都到达安全点花费的时间。只有应用程序线程到达安全点后,JVM才会做些特殊处理,比如垃圾收集、偏向锁擦除等等。
在java9中,G1 GC成为默认的垃圾收集器,G1 垃圾收集器的关键特性之一是能够在不牺牲吞吐量的同时,限制 GC 暂停时间(即可以设置所需的最大停顿时间)。下面看下G1的gc日志格式:
# Minor GC日志格式
2020-02-27T14:49:36.648+0800: 4.417: [GC pause (G1 Evacuation Pause) (young), 0.0382006 secs]
[Parallel Time: 8.7 ms, GC Workers: 18]
[GC Worker Start (ms): Min: 4416.8, Avg: 4416.8, Max: 4416.9, Diff: 0.2]
[Ext Root Scanning (ms): Min: 0.1, Avg: 0.3, Max: 1.7, Diff: 1.6, Sum: 6.3]
[Update RS (ms): Min: 0.0, Avg: 0.9, Max: 1.4, Diff: 1.4, Sum: 16.7]
[Processed Buffers: Min: 0, Avg: 3.1, Max: 11, Diff: 11, Sum: 56]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 6.6, Avg: 7.0, Max: 7.2, Diff: 0.7, Sum: 125.2]
[Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 2.2]
[Termination Attempts: Min: 1, Avg: 88.1, Max: 134, Diff: 133, Sum: 1585]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.5]
[GC Worker Total (ms): Min: 8.3, Avg: 8.4, Max: 8.5, Diff: 0.2, Sum: 151.2]
[GC Worker End (ms): Min: 4425.2, Avg: 4425.2, Max: 4425.3, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 29.3 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 28.4 ms]
[Ref Enq: 0.4 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.1 ms]
[Eden: 75.0M(75.0M)->0.0B(2048.0K) Survivors: 2048.0K->10.0M Heap: 135.3M(245.0M)->106.8M(245.0M)]
[Times: user=0.17 sys=0.00, real=0.04 secs]
2020-02-27T14:49:36.686+0800: 4.455: Total time for which application threads were stopped: 0.0385317 seconds, Stopping threads took: 0.0000317 seconds
2020-02-27T14:49:36.691+0800: 4.460: Application time: 0.0045216 seconds
# 第一部分
2020-02-27T14:49:36.648+0800: 4.417
表示gc发生的时间,其中4.417表示java进程启动4.417秒后发生了GC。
# 第二部分
[GC pause (G1 Evacuation Pause) (young), 0.0382006 secs]
疏散停顿(Evacuation Pause)是将活着的对象从一个区域(young or young + old)拷贝到另一个区域的阶段。(young) — 表示这是一个 Young GC 事件,0.0382006 secs表示GC的时间。
# 第三部分
[Parallel Time: 8.7 ms, GC Workers: 18]
并行收集任务在运行过程中引发的STW(Stop The World)时间为8.7ms, GC Workers: 18 表示GC的工作线程是18个。
# 第四部分
[Eden: 75.0M(75.0M)->0.0B(2048.0K) Survivors: 2048.0K->10.0M Heap: 135.3M(245.0M)->106.8M(245.0M)]
Eden:GC前使用内存(总内存)->GC后使用内存(总内存) Survivors:由于年轻代的回收处理,survivor空间从2M涨到了10M GC前堆内存(堆总内存)->GC后堆内存(堆总内存)
# 第五部分
[Times: user=0.17 sys=0.00, real=0.04 secs]
[gc时间:用户态时间 内核态时间 墙钟时间]
# Full GC日志格式
2020-02-27T14:49:33.330+0800: 1.099: [Full GC (System.gc()) 63M->24M(81M), 0.1139604 secs]
[Eden: 62.0M(100.0M)->0.0B(24.0M) Survivors: 0.0B->0.0B Heap: 63.5M(2016.0M)->24.1M(81.0M)], [Metaspace: 14509K->14509K(1062912K)]
[Times: user=0.14 sys=0.02, real=0.12 secs]
# 第一部分
表示gc发生的时间,其中1.099表示java进程启动1.099秒后发生了Full GC。
# 第二部分
[Full GC (System.gc()) 63M->24M(81M), 0.1139604 secs] [Eden: 62.0M(100.0M)->0.0B(24.0M) Survivors: 0.0B->0.0B Heap: 63.5M(2016.0M)->24.1M(81.0M)], [Metaspace: 14509K->14509K(1062912K)]
[Full GC (出发原因) GC前占用内存->GC后占用内存(总内存), gc耗时][Eden:GC前占用内存(总内存)->GC后占用内存(总内存) Survivors:GC前占用内存->GC后占用内存 堆内存:GC前占用内存(总内存)->GC后占用内存(总内存)], [Metaspace空间: GC前占用内存->GC后占用内存(总内存)]
# 第三部分
[Times: user=0.14 sys=0.02, real=0.12 secs]
[gc时间:用户态时间 内核态时间 墙钟时间]
参考:
Copy link
On this page
一、什么时候触发GC
二、看懂日志