GC日志配置与格式

GC日志配置与日志格式

1. -XX:+PrintGC或者-verbose:gc：开启日志打印功能，即JVM会将运行期间的每次GC事件都以日志方式输出出来。配置之后打印如下：

   [GC 118250K->113543K(130112K), 0.0094143 secs]
   [Full GC 121376K->10414K(130112K), 0.0650971 secs]

   GC表示为Minor GC，Full GC表示为Full GC，即表示收集类型。
   • 其中118250K->113543K(130112K) 0.0094143 secs 表示：118250K为GC回收之前堆空间的大小，113543K为GC回收后堆空间的大小，130112K为堆空间的大小，0.0094143 secs表示以秒为单位的GC执行时间。

2. -Xloggc:：GC日志文件配置，日志将会输出到GC日志到该指定的文件。

3. -XX:PrintGCDetails：GC时输出更多详细的信息，如使用的GC回收器类型，新生代或者老年代的回收情况等，不同的垃圾回收器略有不同，如下：

   Serial + ParNew

   新生代：ParNew（par new generation）
   • 老年代：Tenured
   • 永久代：Perm

4. ParNew + CMS + Serial Old

   新生代：DefNew(def new generation)
   • 老年代：CMS
   • 永久代：CMS Perm

5. Parallel Scavenge + Parallel Old

   新生代：PSYoungGen
   • 老年代：ParOldGen
   • 永久代：PSPermGen

6. 如下为Parallel并发回收器的Minor GC和Full GC的回收日志：

   [GC [PSYoungGen: 7307K->480K(9216K)] 7307K->6624K(19456K), 0.0072860 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]
   [Full GC [PSYoungGen: 480K->0K(9216K)] [ParOldGen: 6144K->6476K(10240K)] 6624K->6476K(19456K) [PSPermGen: 2920K->2919K(21504K)], 0.0178620 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

   [PSYoungGen: 7307K->480K(9216K)]表示新生代的垃圾回收前后的大小情况，回收前内存占用为7307K，回收后内存占用为480K，新生代总大小为9216K；
   • 7307K->6624K(19456K)表示此次GC的堆的内存变化情况，堆的总大小为19456K。
   • 0.0072860 secs为此次GC的实际耗时。
   • [Times: user=0.01 sys=0.01, real=0.00 secs]：user表示用户态CPU耗时，sys为系统态CPU耗时，real为GC实际执行耗时。user + sys 时间为GC执行实际使用的CPU时间。注意这里指所有的 CPU的累加值，因此如果在进程里有多个线程的话，这个时间可能会超过real所表示的时钟时间。
   • 如果user + sys 时间的和比 real 时间要大，是因为real对应的日志时间是从JVM中获得的，而这个JVM 在多核的处理器上被配置了多个GC 线程，由于多个线程并行地执行GC，因此整个GC 工作被这些线程共享，最终导致实际的时钟时间（real）小于总的 CPU 时间（user + sys）。

7. -XX:PrintGCDateStamps：以日期格式打印此处GC事件发生的时间点，如下：

   2019-03-23T01:49:18.778+0800: 7.315: [GC [PSYoungGen: 393216K->60678K(458752K)] 393216K->60686K(720896K), 0.1241514 secs] [Times: user=0.13 sys=0.05, real=0.12 secs]

8. -XX:PrintGCTimeStamps：以相对于JVM进程启动时间的时间点，即在JVM执行执行了多久时，发生了此处GC事件，如下：

   289.556: [GC [PSYoungGen: 314113K->15937K(300928K)] 405513K->107901K(407680K), 0.0178568 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

9. -XX:PrintGCApplicationStoppedTime：应用程序在此次GC期间暂停的时间如下：

   21.773: Total time for which application threads were stopped: 0.0542506 seconds

10. -XX:PrintHeapAtGC：打印GC前后堆的详细信息：

    {Heap before GC invocations=4 (full 0):
    PSYoungGen      total 17408K, used 17392K [0x00000000fdf00000, 0x0000000100000000, 0x0000000100000000)
    eden space 16384K, 100% used [0x00000000fdf00000,0x00000000fef00000,0x00000000fef00000)
    from space 1024K, 98% used [0x00000000fef00000,0x00000000feffc010,0x00000000ff000000)
    to   space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
    ParOldGen       total 68608K, used 34096K [0x00000000f9c00000, 0x00000000fdf00000, 0x00000000fdf00000)
    object space 68608K, 49% used [0x00000000f9c00000,0x00000000fbd4c000,0x00000000fdf00000)
    Metaspace       used 2612K, capacity 4486K, committed 4864K, reserved 1056768K
    class space    used 285K, capacity 386K, committed 512K, reserved 1048576K
    
    [GC (Allocation Failure) [PSYoungGen: 17392K->1024K(32768K)] 51488K->52816K(101376K), 0.0101398 secs] [Times: user=0.00 sys=0.00, real=0.00
    
    Heap after GC invocations=4 (full 0):
    PSYoungGen      total 32768K, used 1024K [0x00000000fdf00000, 0x0000000100000000, 0x0000000100000000)
    eden space 31744K, 0% used [0x00000000fdf00000,0x00000000fdf00000,0x00000000ffe00000)
    from space 1024K, 100% used [0x00000000fff00000,0x0000000100000000,0x0000000100000000)
    to   space 1024K, 0% used [0x00000000ffe00000,0x00000000ffe00000,0x00000000fff00000)
    ParOldGen       total 68608K, used 51792K [0x00000000f9c00000, 0x00000000fdf00000, 0x00000000fdf00000)
    object space 68608K, 75% used [0x00000000f9c00000,0x00000000fce94050,0x00000000fdf00000)
    Metaspace       used 2612K, capacity 4486K, committed 4864K, reserved 1056768K
    class space    used 285K, capacity 386K, committed 512K, reserved 1048576K
    }

GC日志的在线分析

• 可以将GC日志文件上传到这个网站进行在线分析：
  GC Easy