GC日志配置与格式

心已赠人 2022-02-28 06:06 463阅读 0赞

##### 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
     *  ParNew + CMS + Serial Old
        
         *  新生代：DefNew(def new generation)
         *  老年代：CMS
         *  永久代：CMS Perm
     *  Parallel Scavenge + Parallel Old
        
         *  新生代：PSYoungGen
         *  老年代：ParOldGen
         *  永久代：PSPermGen
     *  如下为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）。
4.  \-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]
5.  \-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]
6.  \-XX:PrintGCApplicationStoppedTime：应用程序在此次GC期间暂停的时间如下：
    
        21.773: Total time for which application threads were stopped: 0.0542506 seconds
7.  \-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][]

[GC Easy]: https://gceasy.io/