【JVM一】JVM垃圾回收日志

将JVM垃圾回收的日志记录下来，对于分析垃圾回收的运行状态，进而调整内存分配(年轻代，老年代，永久代的内存分配)等是很有意义的。JVM与垃圾回收日志相关的参数包括：

• -XX:+PrintGC
• -XX:+PrintGCDetails
• -XX:+PrintGCTimeStamps
• -XX:+PrintGCDateStamps
• -Xloggc

-XX:+PrintGC

通过这个参数可以简单的打印GC的信息，包括当前JVM总的堆内存容量，GC开始运行时JVM已经使用的堆容量，GC垃圾回收后JVM使用的堆容量以及GC运行的时间。

简单GC日志会记录两行，分别表示年轻代垃圾回收的状况以及全垃圾回收的状况

 

 比如：

 

[GC 246656K->243120K(376320K), 0,0929090 secs]
[Full GC 243120K->241951K(629760K), 1,5589690 secs]

 


246656k表示GC运行前，年轻代使用的内存，243120K表示GC后年轻代使用的内存。376320K表示分配给年轻代的内存容量，耗时0.092秒

 

简单GC日志的不足

1.当前GC采用的是什么GC算法

2.无法得知，在年轻代GC时，有多少对象从年轻代进入了老年代

 

-XX:+PrintGCDetails

 

年轻代的垃圾回收日志

 

[GC
    [PSYoungGen: 142816K->10752K(142848K)] 246648K->243136K(375296K),
    0,0935090 secs
]
[Times: user=0,55 sys=0,10, real=0,09 secs]

 

年轻带GC日志说明：

 

1. 年轻代垃圾回收使用了吞吐量垃圾回收(如何看出来的？)

2. 年轻代垃圾回收使得JVM堆空间从246648K下降到243136K，整个JVM的堆空间为375296K

3. GC耗时0.0935秒

4. GC完成后，年轻代堆空间从142816K下降到10752K。因为JVM为年轻代分配的堆空间总量是142848K，而年轻代已经使用了142816K，因此只剩下32K的容量。这就是说，GC被触发的原因是年轻代堆空间几乎用尽

5.JVM堆空间从246648K下降到243136K，只有2312K空间被回收，所以，大多数的原来处于年轻代的对象并没有被清除，只是移动到了老年代(也就是说，老年代在这轮GC中，它咋用的堆内存极有可能增大)

6.Times部分详细记录了GG的耗时时间，实际时间是0.09秒，但是用户和系统占用的时间之和是0.55+0.10=0.65秒，元超过0.09秒，这是因为系统采用的是多线程GC的方式，所有县城的总运行时间是0.65秒(这个结果是8个线程进行GC)

 

全垃圾回收日志

 

 

[Full GC
    [PSYoungGen: 10752K->9707K(142848K)]
    [ParOldGen: 232384K->232244K(485888K)] 243136K->241951K(628736K)
    [PSPermGen: 3162K->3161K(21504K)],
    1,5265450 secs
]
[Times: user=10,96 sys=0,06, real=1,53 secs]

 

1. 全垃圾回收日志详细记录了年轻代，老年代和永久代的内存空间变化情况

2. 年轻代从10752K下降到9707K，总的堆内存分配是142848K

3. 老年代从232384K下降到232244K，总的对内存分配是485888K

4. 永久代从3162K下降到3161K，总的分配是21504K

5. 整个堆内存从243136下降到241951K，总的分配是628736K

6.注意：

JVM占用的堆空间241951K = 年轻代的占用空间9707K + 老年代的占用空间232244K；并且，总的容量628736K = 年轻代142848K + 老年代485888K。

这就是说,JVM堆空间是由年轻代和老年代计算出来的，而永久代不占用堆空间？那么永久代占用的空间是哪？

7.从上面的日志可以看到，年轻代，老年代和永久代都没有显著的内存收回，那么是谁触发了GC操作？GC一方面可以由应用本身显式的通过调用System.runFinalization()发起GC，

此时日志的行开头变成Full GC(System)，而不是这里的Full GC。另一方面也跟GC算法有关，比如，吞吐量GC算法不要求某代的内存快用光了才发起GC，它也有可能同时采取了某种定时GC的功能。

 

-XX:+PrintGCTimeStamps

在日志的每一行开头显示一个秒数，这个秒数等于打印此行日志时间减去JVM启动时间

 

-XX:+PrintGCDateStamps

显示GC执行的绝对时间，这类似于普通日志都要记录这条日志打印的时间点以知道运行到此时的时间。

 

例如：

 

2014-01-03T12:08:38.102-0100: [GC 66048K->53077K(251392K), 0,0959470 secs]
2014-01-03T12:08:38.239-0100: [GC 119125K->114661K(317440K), 0,1421720 secs]
2014-01-03T12:08:38.513-0100: [GC 246757K->243133K(375296K), 0,2761000 secs]

 

 

 

-Xloggc

记录gc垃圾回收的日志记录位置，例如：-Xloggc:/home/tom/logs/gc.log

 

实例

 

本文参考https://blog.codecentric.de/en/2014/01/useful-jvm-flags-part-8-gc-logging/