JVM日志查看

作者: justonemoretry | 来源:发表于2022-05-16 20:20 被阅读0次

JVM日志查看
代码验证手动触发 Full GC
jvm
jvm 内存分区及回收
jvm gc日志查看
查看 jvm GC日志
垃圾回收机制算法分析
JVM性能监控工具介绍
查看jvm gc日志（学习）
Java GC机制

parNew young gc 日志分析

36402.792: [GC (Allocation Failure) 36402.792: [ParNew: 2105440K->7584K(2359296K), 0.0124564 secs]  
4517143K->2419327K(4980736K), 0.0129547 secs]
 [Times: user=0.13 sys=0.00, real=0.01 secs]

36402.792是gc相对于进程起来的时间，gc后面的Allocation Failure是发生gc的原因，ParNew是新生代收集器的名称，这是个新生代多线程并发收集器。
2105440K->7584K(2359296K)是指新生代gc前为2105440K，gc后为7584K，后面的2359296K是新生代的总空间，再后面的时间是gc耗时，0.0124564 s。
4517143K->2419327K(4980736K)，这个是gc前整个堆为4517143K，gc后整个堆为2419327K，后面堆的总空间为4980736K, 这里是找了个马上要进行老年代gc的日志，所以可以看到gc前整个堆空间已经快满了。
由于我们为了减少young gc的频次，并没有用常用的新生代和老年代1比2的比例，而是用了1比1的比例。
gc耗时方面：[Times: user=0.13 sys=0.00, real=0.01 secs]
user代表各个cpu加起来的gc耗时
sys代表回收器自身行为耗时
real是真正的gc耗时，对于并发的收集来说，一般是(user + sys) / 并发数 = real。

cms old gc 日志分析

36402.810: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2411743K(2621440K)] 2419601K(4980736K), 0.0037437 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
36402.814: [CMS-concurrent-mark-start]
36403.622: [CMS-concurrent-mark: 0.800/0.808 secs] [Times: user=5.73 sys=0.26, real=0.81 secs] 
36403.623: [CMS-concurrent-preclean-start]
36403.801: [CMS-concurrent-preclean: 0.177/0.178 secs] [Times: user=0.69 sys=0.05, real=0.18 secs] 
36403.801: [CMS-concurrent-abortable-preclean-start]
36403.998: [GC (Allocation Failure) 36403.998: [ParNew: 2104736K->7273K(2359296K), 0.0122722 secs] 4516479K->2419078K(4980736K), 0.0127518 secs] [Times: user=0.13 sys=0.01, real=0.02 secs] 
36404.672: [CMS-concurrent-abortable-preclean: 0.826/0.870 secs] [Times: user=3.39 sys=0.26, real=0.87 secs] 
36404.677: [GC (CMS Final Remark) [YG occupancy: 1097431 K (2359296 K)]36404.677: [GC (CMS Final Remark) 36404.678: [ParNew: 1097431K->7946K(2359296K), 0.0146413 secs] 3509235K->2419797K(4980736K), 0.0151127 secs] [Times: user=0.17 sys=0.00, real=0.02 secs] 
36404.693: [Rescan (parallel) , 0.0044661 secs]36404.697: [weak refs processing, 1.6796757 secs]36406.377: [class unloading, 0.1835045 secs]36406.560: [scrub symbol table, 0.0291043 secs]36406.590: [scrub string table, 0.0029833 secs][1 CMS-remark: 2411851K(2621440K)] 2419797K(4980736K), 2.1253433 secs] [Times: user=2.33 sys=0.00, real=2.13 secs] 
36406.803: [CMS-concurrent-sweep-start]
36409.458: [GC (Allocation Failure) 36409.458: [ParNew: 2105098K->53837K(2359296K), 0.0675226 secs] 4328721K->2277488K(4980736K), 0.0681548 secs] [Times: user=0.86 sys=0.00, real=0.07 secs] 
36410.035: [GC (Allocation Failure) 36410.035: [ParNew: 2150989K->63917K(2359296K), 0.0566114 secs] 4128382K->2041367K(4980736K), 0.0572665 secs] [Times: user=0.71 sys=0.00, real=0.06 secs] 
36410.966: [GC (Allocation Failure) 36410.966: [ParNew: 2161069K->51123K(2359296K), 0.0144844 secs] 3640286K->1530366K(4980736K), 0.0149783 secs] [Times: user=0.16 sys=0.00, real=0.02 secs] 
36411.552: [CMS-concurrent-sweep: 2.287/4.749 secs] [Times: user=23.03 sys=1.41, real=4.75 secs] 
36411.552: [CMS-concurrent-reset-start]
36411.558: [CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]

CMS Full GC 拆分开来，涉及的阶段比较多，下面分别来介绍各个阶段的情况。

阶段1：initial mark阶段

这个是 CMS 两次 stop-the-wolrd 事件的其中一次，这个阶段的目标是：标记那些直接被 GC root 引用或者被年轻代存活对象所引用的所有对象，标记后示例如下所示。

image.png

这个阶段对应的日志信息如下：

36402.810: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2411743K(2621440K)] 2419601K(4980736K), 0.0037437 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

逐行分析上面日志的含义：

CMS-initial-mark cms初始化标记阶段，它会标记GC roots直接引用的对象
2411743K 代表老年代当前使用空间大小
(2621440K) 老年代可用的最大空间
2419601K 代表当前堆使用空间大小
(4980736K) 代表堆的最大使用空间
0.0037437 secs 这个阶段使用时间
[Times: user=0.02 sys=0.00, real=0.01 secs] 使用时间，real是实际耗时

阶段2：并发标记

在这个阶段 Garbage Collector 会遍历老年代，然后标记所有存活的对象，它会根据上个阶段找到的 GC Roots 遍历查找。并发标记阶段，它会与用户的应用程序并发运行。并不是老年代所有的存活对象都会被标记，因为在标记期间用户的程序可能会改变一些引用，如下图所示：

image.png

在上面的图中，与阶段1的图进行对比，就会发现有一个对象的引用已经发生了变化，这个阶段相应的日志信息如下：

36402.814: [CMS-concurrent-mark-start]
36403.622: [CMS-concurrent-mark: 0.800/0.808 secs] [Times: user=5.73 sys=0.26, real=0.81 secs]

这里详细对上面的日志解释，如下所示：

CMS-concurrent-mark：并发收集阶段，这个阶段会遍历老年代，并标记所有存活的对象；
0.800/0.808 secs: 这个阶段的持续时间与时钟时间
[Times: user=5.73 sys=0.26, real=0.81 secs] : 如前面所示，但是这部的时间，其实意义不大，因为它是从并发标记的开始时间开始计算，这期间因为是并发进行，不仅仅包含 GC 线程的工作。

阶段3：Concurrent Preclean

Concurrent Preclean：这也是一个并发阶段，与应用的线程并发运行，并不会 stop 应用的线程。在并发运行的过程中，一些对象的引用可能会发生变化，但是这种情况发生时，JVM 会将包含这个对象的区域（Card）标记为 Dirty，这也就是 Card Marking。如下图所示：

image.png

在pre-clean阶段，那些能够从 Dirty 对象到达的对象也会被标记，这个标记做完之后，dirty card 标记就会被清除了，如下：

image.png
这个阶段相应的日志信息如下：

36403.623: [CMS-concurrent-preclean-start]
36403.801: [CMS-concurrent-preclean: 0.177/0.178 secs] [Times: user=0.69 sys=0.05, real=0.18 secs]

其含义为：

CMS-concurrent-preclean：Concurrent Preclean 阶段，对在前面并发标记阶段中引用发生变化的对象进行标记；
0.177/0.178 secs: 这个阶段的持续时间与时钟时间；
[Times: user=0.69 sys=0.05, real=0.18 secs] 同并发标记阶段的时间含义

阶段4：Concurrent Abortable Preclean

这也是一个并发阶段，但是同样不会影响影响用户的应用线程，这个阶段是为了尽量承担 STW（stop-the-world）中最终标记阶段的工作。这个阶段持续时间依赖于很多的因素，由于这个阶段是在重复做很多相同的工作，直接满足一些条件（比如：重复迭代的次数、完成的工作量或者时钟时间等）。这个阶段的日志信息如下：

36403.801: [CMS-concurrent-abortable-preclean-start]
36403.998: [GC (Allocation Failure) 36403.998: [ParNew: 2104736K->7273K(2359296K), 0.0122722 secs] 4516479K->2419078K(4980736K), 0.0127518 secs] [Times: user=0.13 sys=0.01, real=0.02 secs] 
36404.672: [CMS-concurrent-abortable-preclean: 0.826/0.870 secs] [Times: user=3.39 sys=0.26, real=0.87 secs]

CMS-concurrent-abortable-preclean：Concurrent Abortable Preclean 阶段；
0.826/0.870 secs: 这个阶段的持续时间与时钟时间
Times: user=3.39 sys=0.26, real=0.87 secs: 和前面相同

阶段5：Final Remark

这是第二个 STW 阶段，也是 CMS 中的最后一个，这个阶段的目标是标记所有老年代所有的存活对象，由于之前的阶段是并发执行的，gc 线程可能跟不上应用程序的变化，为了完成标记老年代所有存活对象的目标，STW 就非常有必要了。
通常 CMS 的 Final Remark 阶段会在年轻代尽可能干净的时候运行，目的是为了减少连续 STW 发生的可能性（年轻代存活对象过多的话，也会导致老年代涉及的存活对象会很多）。这个阶段会比前面的几个阶段更复杂一些，相关日志如下：

36404.677: [GC (CMS Final Remark) [YG occupancy: 1097431 K (2359296 K)]36404.677: [GC (CMS Final Remark) 36404.678: [ParNew: 1097431K->7946K(2359296K), 0.0146413 secs] 3509235K->2419797K(4980736K), 0.0151127 secs] [Times: user=0.17 sys=0.00, real=0.02 secs]
36404.693: [Rescan (parallel) , 0.0044661 secs]36404.697: [weak refs processing, 1.6796757 secs]36406.377: [class unloading, 0.1835045 secs]36406.560: [scrub symbol table, 0.0291043 secs]36406.590: [scrub string table, 0.0029833 secs][1 CMS-remark: 2411851K(2621440K)] 2419797K(4980736K), 2.1253433 secs] [Times: user=2.33 sys=0.00, real=2.13 secs]

对上面的日志进行分析：

YG occupancy: 1097431 K (2359296 K)年轻代当前占用量及容量大小
ParNew：触发了一次 young GC，这里触发的原因是为了减少年轻代的存活对象，尽量使年轻代更干净一些；
[Rescan (parallel) , 0.0044661 secs]：这个 Rescan 是当应用暂停的情况下完成对所有存活对象的标记，这个阶段是并行处理的，这里花费了0.0044s
weak refs processing, 1.6796757 secs]: 这是第一个阶段，它的工作是处理弱引用，花了1.679s
[class unloading, 0.1835045 secs]：这是第二个阶段，它的作用是卸载无用的类
[scrub symbol table, 0.0291043 secs]：最后一个子阶段，它的目的是：cleaning up symbol and string tables which hold class-level metadata and internalized string respectively，时钟的暂停也包含在这里；
2411851K(2621440K): 老年代当前使用空间和总空间
2419797K(4980736K)：堆当前使用空间和总空间
2.1253433 secs：最终标记的耗时
Times: user=2.33 sys=0.00, real=2.13 secs] ：耗时情况
经历过这五个阶段之后，老年代所有存活的对象都被标记过了，现在可以通过清除算法去清理那些老年代不再使用的对象。

阶段6：Concurrent Sweep

这里不需要 STW，它是与用户的应用程序并发运行，这个阶段是：清除那些不再使用的对象，回收它们的占用空间为将来使用。如下图所示：

image.png

这个阶段对应的日志如下，这个过程中发生了3次young gc：

36406.803: [CMS-concurrent-sweep-start]
36409.458: [GC (Allocation Failure) 36409.458: [ParNew: 2105098K->53837K(2359296K), 0.0675226 secs] 4328721K->2277488K(4980736K), 0.0681548 secs] [Times: user=0.86 sys=0.00, real=0.07 secs] 
36410.035: [GC (Allocation Failure) 36410.035: [ParNew: 2150989K->63917K(2359296K), 0.0566114 secs] 4128382K->2041367K(4980736K), 0.0572665 secs] [Times: user=0.71 sys=0.00, real=0.06 secs] 
36410.966: [GC (Allocation Failure) 36410.966: [ParNew: 2161069K->51123K(2359296K), 0.0144844 secs] 3640286K->1530366K(4980736K), 0.0149783 secs] [Times: user=0.16 sys=0.00, real=0.02 secs] 
36411.552: [CMS-concurrent-sweep: 2.287/4.749 secs] [Times: user=23.03 sys=1.41, real=4.75 secs]

字段介绍如下：

CMS-concurrent-sweep：cms并发清除阶段，并发清除前面阶段中没有被标记的对象，回收他们占用的空间。
2.287/4.749 secs：该阶段持续时间和时钟时间
Times: user=23.03 sys=1.41, real=4.75 secs] ：时间同上

阶段7：Concurrent Reset.

这个阶段也是并发执行的，它会重设 CMS 内部的数据结构，为下次的 GC 做准备，对应的日志信息如下：

36411.552: [CMS-concurrent-reset-start]
36411.558: [CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]

总结

CMS 通过将大量工作分散到并发处理阶段来在减少 STW 时间，在这块做得非常优秀，但是 CMS 也有一些其他的问题：

CMS 收集器无法处理浮动垃圾（ Floating Garbage），可能出现 “Concurrnet Mode Failure” 失败而导致另一次 Full GC 的产生，可能引发串行 Full GC；
空间碎片，导致无法分配大对象，CMS 收集器提供了一个 -XX:+UseCMSCompactAtFullCollection 开关参数（默认就是开启的），用于在 CMS 收集器顶不住要进行 Full GC 时开启内存碎片的合并整理过程，内存整理的过程是无法并发的，空间碎片问题没有了，但停顿时间不得不变长；
对于堆比较大的应用上，GC 的时间难以预估。