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

一、日志相關參數

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參數

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

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

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]