jvm中GC日志格式详解（十）

迈不过友情╰ 2024-04-18 19:19 52阅读 0赞

### 一、日志相关参数 ###

1.-XX:+PrintGCDetails

2.-XX:+PrintGCTimeStamps 打印时间戳

3.-XX:+PrintGCDateStamps

4.-Xloggc:/tmp/gc.log  将GC日志输出到指定文件

5.-XX:PrintHeapAtGC 发生GC时，打印堆的使用情况

6.-XX:PrintTenuringDistribution 发生GC时，打印young区的年龄信息

### 二、Parallel GC日志 ###

1.在bin/catalina.sh中添加jvm参数

![20190910230717468.png][]

2.启动tomcat

3.查看gc日志文件

//JDK的版本信息
    Java HotSpot(TM) 64-Bit Server VM (25.171-b11) for bsd-amd64 JRE (1.8.0_171-b11), built on Mar 28 2018 12:50:57 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
    //内存信息
    Memory: 4k page, physical 8388608k(377872k free)
    
    /proc/meminfo:
    
    //命令行参数
    CommandLine flags: -XX:InitialHeapSize=134217728 -XX:MaxHeapSize=2147483648 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -
    //使用了压缩类空间ccs，普通对象也使用了32位的短指针，使用并行GC
    XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
    
    //日期T时间毫秒：
    //(Allocation Failure)发生GC的原因
    //PSYoungGen：表示youngGC
    //33280K->5088K(38400K)：young区GC前33280，GC后为5088，（38400k）表示young区总大小
    //33280K->7266K(125952K)：堆区GC前为33280，GC后为7266，（125952K）堆区总大小
    //0.0128686 secs：GC所用的时间
    2019-09-10T23:05:58.384-0800: 2.047: [GC (Allocation Failure) [PSYoungGen: 33280K->5088K(38400K)] 33280K->7266K(125952K), 0.0128686 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
    2019-09-10T23:05:59.358-0800: 3.020: [GC (Allocation Failure) [PSYoungGen: 38368K->5100K(38400K)] 40546K->13606K(125952K), 0.0193032 secs] [Times: user=0.03 sys=0.01, real=0.02 secs] 
    2019-09-10T23:05:59.732-0800: 3.395: [GC (Allocation Failure) [PSYoungGen: 38380K->5116K(38400K)] 46886K->17864K(125952K), 0.0107381 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
    2019-09-10T23:06:00.089-0800: 3.751: [GC (Allocation Failure) [PSYoungGen: 38396K->5100K(71680K)] 51144K->22159K(159232K), 0.0169793 secs] [Times: user=0.03 sys=0.01, real=0.02 secs] 
    2019-09-10T23:06:00.725-0800: 4.387: [GC (Allocation Failure) [PSYoungGen: 71660K->5116K(71680K)] 88719K->31977K(159232K), 0.0222310 secs] [Times: user=0.04 sys=0.01, real=0.02 secs] 
    2019-09-10T23:06:01.286-0800: 4.948: [GC (Allocation Failure) [PSYoungGen: 71676K->14827K(146432K)] 98537K->41738K(233984K), 0.0323715 secs] [Times: user=0.05 sys=0.01, real=0.03 secs] 
    2019-09-10T23:06:02.821-0800: 6.483: [GC (Allocation Failure) [PSYoungGen: 146411K->16378K(147968K)] 173322K->51289K(235520K), 0.0564683 secs] [Times: user=0.12 sys=0.02, real=0.05 secs] 
    2019-09-10T23:06:04.189-0800: 7.851: [GC (Allocation Failure) [PSYoungGen: 147962K->20291K(283648K)] 182873K->55521K(371200K), 0.0471863 secs] [Times: user=0.08 sys=0.01, real=0.05 secs] 
    
    //GC原因Metadata GC Threshold
    2019-09-10T23:06:06.942-0800: 10.605: [GC (Metadata GC Threshold) [PSYoungGen: 175681K->16051K(285696K)] 210911K->51505K(373248K), 0.0323976 secs] [Times: user=0.06 sys=0.01, real=0.03 secs] 
    
    //这里发生了fullGC
    2019-09-10T23:06:06.975-0800: 10.637: [Full GC (Metadata GC Threshold) [PSYoungGen: 16051K->0K(285696K)] [ParOldGen: 35453K->25685K(77312K)] 51505K->25685K(363008K), [Metaspace: 20872K->20872K(1069056K)], 0.0707623 secs] [Times: user=0.20 sys=0.00, real=0.07 secs] 
    2019-09-10T23:06:40.060-0800: 43.721: [GC (Allocation Failure) [PSYoungGen: 261120K->9374K(390656K)] 286805K->35076K(467968K), 0.0150271 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
    Heap
     PSYoungGen      total 390656K, used 58881K [0x0000000795580000, 0x00000007b0e80000, 0x00000007c0000000)
      eden space 380928K, 12% used [0x0000000795580000,0x00000007985d8cd0,0x00000007ac980000)
      from space 9728K, 96% used [0x00000007b0500000,0x00000007b0e27b18,0x00000007b0e80000)
      to   space 24064K, 0% used [0x00000007adf80000,0x00000007adf80000,0x00000007af700000)
     ParOldGen       total 77312K, used 25701K [0x0000000740000000, 0x0000000744b80000, 0x0000000795580000)
      object space 77312K, 33% used [0x0000000740000000,0x00000007419195d0,0x0000000744b80000)
     Metaspace       used 31177K, capacity 31566K, committed 31744K, reserved 1077248K
      class space    used 3646K, capacity 3805K, committed 3840K, reserved 1048576K

三、CMS日志

1.修改/bin/catalina.sh

![20190912203719570.png][]

2.重启tomcat，日志分析

Java HotSpot(TM) 64-Bit Server VM (25.171-b11) for bsd-amd64 JRE (1.8.0_171-b11), built on Mar 28 2018 12:50:57 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
    Memory: 4k page, physical 8388608k(286436k free)
    
    /proc/meminfo:
    
    CommandLine flags: -XX:CMSFullGCsBeforeCompaction=5 -XX:CMSInitiatingOccupancyFraction=92 -XX:InitialHeapSize=134217728 -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=348966912 
    
    //MaxTenuringThreshold：young区到old区年龄大小为6
    -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCMSCompactAtFullCollection -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers -XX:+UseCompressedOops 
    
    //old区为CMS，young区垃圾收集为ParNewGC。并发的
    -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 
    
    //ParNew: 34944K->4352K(39296K：young区使用的是ParNew
    2019-09-12T20:35:23.701-0800: 1.908: [GC (Allocation Failure) 2019-09-12T20:35:23.701-0800: 1.908: [ParNew: 34944K->4352K(39296K), 0.0190088 secs] 34944K->7212K(126720K), 0.0191691 secs] [Times: user=0.03 sys=0.01, real=0.02 secs] 
    2019-09-12T20:35:24.671-0800: 2.878: [GC (Allocation Failure) 2019-09-12T20:35:24.671-0800: 2.878: [ParNew: 39296K->4352K(39296K), 0.0300604 secs] 42156K->14738K(126720K), 0.0301814 secs] [Times: user=0.07 sys=0.01, real=0.03 secs] 
    2019-09-12T20:35:25.041-0800: 3.249: [GC (Allocation Failure) 2019-09-12T20:35:25.041-0800: 3.249: [ParNew: 39296K->4352K(39296K), 0.0132059 secs] 49682K->21715K(126720K), 0.0133530 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 
    2019-09-12T20:35:25.352-0800: 3.560: [GC (Allocation Failure) 2019-09-12T20:35:25.352-0800: 3.560: [ParNew: 39296K->4352K(39296K), 0.0077438 secs] 56659K->23800K(126720K), 0.0078526 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
    2019-09-12T20:35:25.631-0800: 3.839: [GC (Allocation Failure) 2019-09-12T20:35:25.631-0800: 3.839: [ParNew: 39296K->4352K(39296K), 0.0068865 secs] 58744K->25307K(126720K), 0.0070060 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
    2019-09-12T20:35:26.003-0800: 4.211: [GC (Allocation Failure) 2019-09-12T20:35:26.003-0800: 4.211: [ParNew: 39296K->4351K(39296K), 0.0065397 secs] 60251K->26491K(126720K), 0.0066588 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
    2019-09-12T20:35:26.306-0800: 4.513: [GC (Allocation Failure) 2019-09-12T20:35:26.306-0800: 4.513: [ParNew: 39295K->3983K(39296K), 0.0050595 secs] 61435K->26537K(126720K), 0.0051820 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
    2019-09-12T20:35:26.540-0800: 4.748: [GC (Allocation Failure) 2019-09-12T20:35:26.540-0800: 4.748: [ParNew: 38927K->4352K(39296K), 0.0069235 secs] 61481K->28064K(126720K), 0.0070573 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
    2019-09-12T20:35:26.852-0800: 5.060: [GC (Allocation Failure) 2019-09-12T20:35:26.852-0800: 5.060: [ParNew: 39296K->4352K(39296K), 0.0071100 secs] 63008K->29592K(126720K), 0.0072299 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
    2019-09-12T20:35:27.198-0800: 5.406: [GC (Allocation Failure) 2019-09-12T20:35:27.198-0800: 5.406: [ParNew: 39296K->4352K(39296K), 0.0065534 secs] 64536K->31252K(126720K), 0.0066711 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
    2019-09-12T20:35:27.521-0800: 5.729: [GC (Allocation Failure) 2019-09-12T20:35:27.521-0800: 5.729: [ParNew: 39296K->4352K(39296K), 0.0172508 secs] 66196K->32716K(126720K), 0.0173683 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
    2019-09-12T20:35:27.818-0800: 6.026: [GC (Allocation Failure) 2019-09-12T20:35:27.818-0800: 6.026: [ParNew: 39296K->4352K(39296K), 0.0070238 secs] 67660K->33790K(126720K), 0.0071432 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
    2019-09-12T20:35:28.045-0800: 6.253: [GC (Allocation Failure) 2019-09-12T20:35:28.045-0800: 6.253: [ParNew: 39296K->4352K(39296K), 0.0096104 secs] 68734K->35824K(126720K), 0.0097494 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 
    2019-09-12T20:35:28.440-0800: 6.648: [GC (Allocation Failure) 2019-09-12T20:35:28.440-0800: 6.648: [ParNew: 39296K->4352K(39296K), 0.0183789 secs] 70768K->37679K(126720K), 0.0185188 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
    2019-09-12T20:35:28.744-0800: 6.952: [GC (Allocation Failure) 2019-09-12T20:35:28.744-0800: 6.952: [ParNew: 39296K->4352K(39296K), 0.0064967 secs] 72623K->38790K(126720K), 0.0066385 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
    2019-09-12T20:35:29.040-0800: 7.248: [GC (Allocation Failure) 2019-09-12T20:35:29.040-0800: 7.248: [ParNew: 39296K->4352K(39296K), 0.0050860 secs] 73734K->39492K(126720K), 0.0051987 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
    2019-09-12T20:35:29.329-0800: 7.537: [GC (Allocation Failure) 2019-09-12T20:35:29.329-0800: 7.537: [ParNew: 39296K->3924K(39296K), 0.0148910 secs] 74436K->39288K(126720K), 0.0150390 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 
    2019-09-12T20:35:30.247-0800: 8.455: [GC (Allocation Failure) 2019-09-12T20:35:30.247-0800: 8.455: [ParNew: 38868K->3150K(39296K), 0.0150120 secs] 74232K->38732K(126720K), 0.0151588 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
    2019-09-12T20:35:31.240-0800: 9.448: [GC (Allocation Failure) 2019-09-12T20:35:31.240-0800: 9.448: [ParNew: 38094K->3753K(39296K), 0.0082905 secs] 73676K->40410K(126720K), 0.0084762 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
    2019-09-12T20:35:31.981-0800: 10.189: [GC (Allocation Failure) 2019-09-12T20:35:31.981-0800: 10.189: [ParNew: 38697K->2033K(39296K), 0.0046261 secs] 75354K->39511K(126720K), 0.0047576 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
    
    //(CMS Initial Mark):发生fullGC开始，CMS初始标记
    //37477K(87424K)] ：Old区大小为87424K，占用了37477K
    //39511K(126720K)：堆区大小为126720K，占用了39511K
    2019-09-12T20:35:31.986-0800: 10.194: [GC (CMS Initial Mark) [1 CMS-initial-mark: 37477K(87424K)] 39511K(126720K), 0.0019947 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
    2019-09-12T20:35:31.988-0800: 10.196: [CMS-concurrent-mark-start]
    2019-09-12T20:35:32.045-0800: 10.252: [CMS-concurrent-mark: 0.056/0.056 secs] [Times: user=0.17 sys=0.02, real=0.06 secs] 
    2019-09-12T20:35:32.045-0800: 10.252: [CMS-concurrent-preclean-start]
    2019-09-12T20:35:32.046-0800: 10.253: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    2019-09-12T20:35:32.046-0800: 10.254: [CMS-concurrent-abortable-preclean-start]
    2019-09-12T20:35:32.701-0800: 10.908: [GC (Allocation Failure) 2019-09-12T20:35:32.701-0800: 10.908: [ParNew: 36977K->3762K(39296K), 0.0096313 secs] 74455K->41240K(126720K), 0.0097515 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
    2019-09-12T20:35:33.101-0800: 11.309: [GC (Allocation Failure) 2019-09-12T20:35:33.101-0800: 11.309: [ParNew: 38706K->2210K(39296K), 0.0096260 secs] 76184K->41682K(126720K), 0.0097537 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
    2019-09-12T20:35:33.114-0800: 11.322: [CMS-concurrent-abortable-preclean: 0.245/1.069 secs] [Times: user=1.79 sys=0.21, real=1.07 secs] 
    2019-09-12T20:35:33.115-0800: 11.322: [GC (CMS Final Remark) [YG occupancy: 2212 K (39296 K)]2019-09-12T20:35:33.115-0800: 11.322: [Rescan (parallel) , 0.0027557 secs]2019-09-12T20:35:33.118-0800: 11.325: [weak refs processing, 0.0001143 secs]2019-09-12T20:35:33.118-0800: 11.325: [class unloading, 0.0063984 secs]2019-09-12T20:35:33.124-0800: 11.332: [scrub symbol table, 0.0077314 secs]2019-09-12T20:35:33.132-0800: 11.340: [scrub string table, 0.0008981 secs][1 CMS-remark: 39471K(87424K)] 41684K(126720K), 0.0190971 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
    2019-09-12T20:35:33.134-0800: 11.342: [CMS-concurrent-sweep-start]
    2019-09-12T20:35:33.154-0800: 11.361: [CMS-concurrent-sweep: 0.019/0.020 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    2019-09-12T20:35:33.154-0800: 11.362: [CMS-concurrent-reset-start]
    2019-09-12T20:35:33.159-0800: 11.366: [CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.02 sys=0.01, real=0.00 secs] 
    //fullGC结束
    
    2019-09-12T20:35:33.403-0800: 11.611: [GC (Allocation Failure) 2019-09-12T20:35:33.403-0800: 11.611: [ParNew: 37154K->1751K(39296K), 0.0024516 secs] 50818K->15414K(126720K), 0.0025835 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
    2019-09-12T20:35:33.901-0800: 12.109: [GC (Allocation Failure) 2019-09-12T20:35:33.901-0800: 12.109: [ParNew: 36695K->4351K(39296K), 0.0050220 secs] 50358K->18609K(126720K), 0.0051503 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
    2019-09-12T20:35:56.233-0800: 34.441: [GC (Allocation Failure) 2019-09-12T20:35:56.233-0800: 34.441: [ParNew: 39295K->3481K(39296K), 0.0086561 secs] 53553K->20382K(126720K), 0.0088483 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
    2019-09-12T20:36:04.857-0800: 43.064: [GC (Allocation Failure) 2019-09-12T20:36:04.859-0800: 43.067: [ParNew: 38425K->3689K(39296K), 0.0049315 secs] 55326K->20590K(126720K), 0.0073734 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

### 四、G1日志 ###

1.修改/bin/catalina.sh

![20190912210012437.png][]

2.启动tomcat，GC日志分析

Java HotSpot(TM) 64-Bit Server VM (25.171-b11) for bsd-amd64 JRE (1.8.0_171-b11), built on Mar 28 2018 12:50:57 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
    Memory: 4k page, physical 8388608k(300080k free)
    
    /proc/meminfo:
    
    CommandLine flags: -XX:InitialHeapSize=134217728 -XX:MaxHeapSize=2147483648 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops
    
    //使用G1GC
     -XX:+UseG1GC 
    
    //(G1 Evacuation Pause)分配失败，导致GC，young：youngGC
    2019-09-12T21:03:35.867-0800: 0.928: [GC pause (G1 Evacuation Pause) (young), 0.0073185 secs]
    
    //Parallel Time：并发线程花费时间，GC Workers: 4；停止应用程序，4个并发的GC线程
       [Parallel Time: 5.5 ms, GC Workers: 4]
    
            //开始时间927.8
          [GC Worker Start (ms): Min: 927.8, Avg: 927.8, Max: 927.9, Diff: 0.1]
         
         //Root Scanning；根节点扫描；因为有4个线程，所以耗时有最小时间，最大时间，平均时间
          [Ext Root Scanning (ms): Min: 0.3, Avg: 0.7, Max: 1.1, Diff: 0.9, Sum: 2.8]
          [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
             [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
          [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.7, Diff: 0.7, Sum: 1.0]
          [Object Copy (ms): Min: 4.1, Avg: 4.3, Max: 4.6, Diff: 0.6, Sum: 17.0]
          [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
             [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
          [GC Worker Total (ms): Min: 5.2, Avg: 5.3, Max: 5.4, Diff: 0.1, Sum: 21.2]
          [GC Worker End (ms): Min: 933.1, Avg: 933.1, Max: 933.2, Diff: 0.1]
       [Code Root Fixup: 0.0 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 0.1 ms]
       [Other: 1.7 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 1.4 ms]
          [Ref Enq: 0.0 ms]
          [Redirty Cards: 0.1 ms]
    
        //Humongous Register：大对象
          [Humongous Register: 0.0 ms]
          [Humongous Reclaim: 0.0 ms]
          [Free CSet: 0.1 ms]
    
    //Eden区从14M变成了0，全部被回收，下一次Eden区扩容到17M
    //Survivors区从0.0B->2048.0K
    //整个堆从14M变成了3587.0K，整个堆大小为128.0M)
       [Eden: 14.0M(14.0M)->0.0B(17.0M) Survivors: 0.0B->2048.0K Heap: 14.0M(128.0M)->3587.0K(128.0M)]
     [Times: user=0.02 sys=0.01, real=0.01 secs] 
    2019-09-12T21:03:36.602-0800: 1.663: [GC pause (G1 Evacuation Pause) (young), 0.0210049 secs]
       [Parallel Time: 18.4 ms, GC Workers: 4]
          [GC Worker Start (ms): Min: 1663.2, Avg: 1663.2, Max: 1663.2, Diff: 0.1]
          [Ext Root Scanning (ms): Min: 0.8, Avg: 1.1, Max: 1.4, Diff: 0.6, Sum: 4.4]
          [Update RS (ms): Min: 0.4, Avg: 0.4, Max: 0.6, Diff: 0.2, Sum: 1.7]
             [Processed Buffers: Min: 1, Avg: 2.0, Max: 3, Diff: 2, Sum: 8]
          [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.4, Max: 1.5, Diff: 1.5, Sum: 1.7]
          [Object Copy (ms): Min: 5.0, Avg: 6.3, Max: 6.9, Diff: 1.9, Sum: 25.0]
          [Termination (ms): Min: 0.0, Avg: 7.6, Max: 10.1, Diff: 10.1, Sum: 30.3]
             [Termination Attempts: Min: 1, Avg: 2.8, Max: 5, Diff: 4, Sum: 11]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
          [GC Worker Total (ms): Min: 8.3, Avg: 15.8, Max: 18.3, Diff: 10.0, Sum: 63.3]
          [GC Worker End (ms): Min: 1671.5, Avg: 1679.0, Max: 1681.5, Diff: 10.0]
       [Code Root Fixup: 0.0 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 0.1 ms]
       [Other: 2.4 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 2.1 ms]
          [Ref Enq: 0.0 ms]
          [Redirty Cards: 0.1 ms]
          [Humongous Register: 0.0 ms]
          [Humongous Reclaim: 0.0 ms]
          [Free CSet: 0.1 ms]
       [Eden: 17.0M(17.0M)->0.0B(73.0M) Survivors: 2048.0K->3072.0K Heap: 20.5M(128.0M)->9090.0K(128.0M)]
     [Times: user=0.04 sys=0.01, real=0.02 secs] 
    2019-09-12T21:03:37.582-0800: 2.643: [GC pause (G1 Evacuation Pause) (young), 0.0174061 secs]
       [Parallel Time: 11.2 ms, GC Workers: 4]
          [GC Worker Start (ms): Min: 2643.2, Avg: 2643.3, Max: 2643.3, Diff: 0.1]
          [Ext Root Scanning (ms): Min: 0.3, Avg: 0.7, Max: 1.1, Diff: 0.8, Sum: 2.7]
          [Update RS (ms): Min: 0.3, Avg: 0.5, Max: 0.9, Diff: 0.5, Sum: 2.1]
             [Processed Buffers: Min: 1, Avg: 2.8, Max: 5, Diff: 4, Sum: 11]
          [Scan RS (ms): Min: 0.1, Avg: 0.3, Max: 0.4, Diff: 0.3, Sum: 1.2]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 0.5]
          [Object Copy (ms): Min: 9.0, Avg: 9.4, Max: 9.7, Diff: 0.7, Sum: 37.4]
          [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
             [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
          [GC Worker Total (ms): Min: 11.0, Avg: 11.1, Max: 11.1, Diff: 0.1, Sum: 44.3]
          [GC Worker End (ms): Min: 2654.3, Avg: 2654.3, Max: 2654.3, Diff: 0.0]
       [Code Root Fixup: 0.0 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 0.1 ms]
       [Other: 6.1 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 5.8 ms]
          [Ref Enq: 0.0 ms]
          [Redirty Cards: 0.1 ms]
          [Humongous Register: 0.0 ms]
          [Humongous Reclaim: 0.0 ms]
          [Free CSet: 0.1 ms]
       [Eden: 58.0M(58.0M)->0.0B(68.0M) Survivors: 3072.0K->8192.0K Heap: 66.9M(128.0M)->19.5M(128.0M)]
     [Times: user=0.03 sys=0.01, real=0.02 secs] 
    2019-09-12T21:03:37.879-0800: 2.940: [GC pause (G1 Evacuation Pause) (young), 0.0259386 secs]
       [Parallel Time: 19.6 ms, GC Workers: 4]
          [GC Worker Start (ms): Min: 2940.0, Avg: 2940.0, Max: 2940.1, Diff: 0.1]
          [Ext Root Scanning (ms): Min: 0.3, Avg: 0.5, Max: 0.9, Diff: 0.6, Sum: 1.9]
          [Update RS (ms): Min: 0.4, Avg: 0.9, Max: 2.5, Diff: 2.1, Sum: 3.8]
             [Processed Buffers: Min: 1, Avg: 2.5, Max: 5, Diff: 4, Sum: 10]
          [Scan RS (ms): Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.6, Sum: 1.9]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 0.5]
          [Object Copy (ms): Min: 8.1, Avg: 8.9, Max: 9.6, Diff: 1.5, Sum: 35.5]
          [Termination (ms): Min: 0.0, Avg: 4.3, Max: 8.7, Diff: 8.7, Sum: 17.3]
             [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
          [GC Worker Total (ms): Min: 10.9, Avg: 15.2, Max: 19.6, Diff: 8.7, Sum: 61.0]
          [GC Worker End (ms): Min: 2951.0, Avg: 2955.3, Max: 2959.6, Diff: 8.6]
       [Code Root Fixup: 0.0 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 0.2 ms]
       [Other: 6.1 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 5.7 ms]
          [Ref Enq: 0.1 ms]
          [Redirty Cards: 0.1 ms]
          [Humongous Register: 0.0 ms]
          [Humongous Reclaim: 0.0 ms]
          [Free CSet: 0.1 ms]
       [Eden: 50.0M(48.0M)->0.0B(69.0M) Survivors: 8192.0K->7168.0K Heap: 69.5M(128.0M)->27.5M(128.0M)]
     [Times: user=0.04 sys=0.01, real=0.03 secs]

[20190910230717468.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/04/18/3bc4aa11757e475e862ce25392f834f7.png
[20190912203719570.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/04/18/4a68d96cb3054e79a156f8a185d9976d.png
[20190912210012437.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/04/18/89004ddc90bc4d85893acc0f4e2e3be6.png