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

最新推荐文章于 2025-03-29 10:30:00 发布

qq_35151346

最新推荐文章于 2025-03-29 10:30:00 发布

阅读量1.9k

点赞数

分类专栏： jvm 文章标签： jvm java G1 CMS

本文链接：https://blog.youkuaiyun.com/qq_35151346/article/details/100715949

版权

jvm 专栏收录该内容

13 篇文章

订阅专栏

一、日志相关参数

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]