美文网首页Android 小技巧及工具
一次针对idea启动的JVM调优过程记录

一次针对idea启动的JVM调优过程记录

作者: 帅气滴糟老头 | 来源:发表于2019-03-04 16:00 被阅读0次

    前言

    本文通过VisualVM工具和gc日志的分析,有针对性的通过配置idea的启动参数来达到加快idea启动速度的目的。
    如果你对VisualVM工具和gc日志不了解,可以先阅读我的另外两篇文章:
    Visual GC 插件使用
    理解CMS GC日志

    调优前idea的运行状态

    本次idea的版本为:2018.2.3
    jdk版本为1.8
    下面是idea的默认初始启动参数

    -Xms128m
    -Xmx750m
    -XX:ReservedCodeCacheSize=240m
    -XX:+UseConcMarkSweepGC
    -XX:SoftRefLRUPolicyMSPerMB=50
    -ea
    -Dsun.io.useCanonCaches=false
    -Djava.net.preferIPv4Stack=true
    -XX:+HeapDumpOnOutOfMemoryError
    -XX:-OmitStackTraceInFastThrow
    

    为了能看到idea运行时的gc日志,添加如下参数输出gc日志

    -verbose:gc
    -XX:+PrintGCDetails
    -Xloggc:D:/gc.log
    

    接下来打开VisualVM工具,准备监控idea。
    最后启动idea,idea的启动总耗时无法从监控工具中直接获得,因为VsualVM不知道idea运行到什么阶段才算是启动完成,只能粗略认为如果在的数据相对稳定时就算启动完成,下面是idea从启动到运行数据稳定时的VisualVM监控截图

    通过上图可以看出idea的启动耗时情况如下:

    • JIT编译耗时:3m 5.690s
    • 加载类48051个,耗时:1m 29.960s
    • 垃圾收集总耗时2.048s,其中:
      • MInor GC触发了131次,耗时1.451s
      • Full GC触发了14次,耗时597.601ms

    很遗憾,由于我这台机器的硬件性能原因(超级慢的机械硬盘),JIT编译和类加载占用了绝大多数的耗时(将近4分钟),这成为我这台机器上idea启动缓慢的主要原因,而由于垃圾回收造成的耗时只有2秒,似乎除了升级硬件没有其他办法了,通过优化启动参数起到的效果微乎其微,到这里已经可以宣布本次调优到此结束,我去买块固态硬盘换上就行。
    但是如果这样草草结束那这篇文章将毫无意义,本次教程仍然可以作为idea的启动优化范本,本着这个目标,我将厚着脸皮继续接下来的分析和微不足道的“调优”。

    编译时间

    上面的启动数据中编译时间耗时最长,什么是编译时间呢?
    编译时间是指虚拟机的JIT编译器(Just In Time Compiler)编译热点代码(Hot Spot Code)的耗时。我们知道Java语言为了实现跨平台的特性,Java代码编译出来后形成的Class文件中存储的是字节码(ByteCode),虚拟机通过解释方式执行字节码命令,比起C/C++编译成本地二进制码来说,速度要慢不少。为了解决程序解释执行的速度问题,JDK1.2以后,虚拟机内置了两个运行时编译器,如果一段Java方法被调用次数达到一定程度,就会被判定为热代码交给JIT编译器及时编译为本地代码,提高运行速度。甚至有可能在运行期动态编译比C/C++的编译期静态编译出来的代码更优秀,因为运行期可以书记很多编译期无法知道的信息,甚至可以采用一些很激进的优化手段,在优化条件不成立的时候再逆优化回来。所以Java程序只要代码没有问题(主要是泄露问题,如内存泄露、链接泄露),随着代码被编译的越来越彻底,运行速度应当是越运行越快的。Java的运行期编译最大的缺点就是它进行编译需要消程序正常的运行时间,这也就是说说的“编译时间”。--------摘录自《深入理解Java虚拟机》。
    十分遗憾,这部分的时间主要受限于机器的性能,所以不在本次调优范围之内。

    类加载时间优化

    类加载其实也没有太大的优化空间,由于idea使用者很多,我们可以认为它编译的代码是可靠的,不需要在加载的时候再进行字节码验证,因此可以通过-Xverify:none禁止掉字节码验证过程。

    优化垃圾回收发生频率

    编译时间和类加载时间粗略的处理完了,更多的是无能无能为力,目前还剩下GC时间没有调整,而GC时间正是本次调优中最终要的一块,并不是说它是耗时最长的一块,相反的,相比于编译时间和类加载时间,GC的时间显得微不足道,可是别忘了,这段耗时数据只是idea启动到启动完成的耗时情况,编译和类加载的在影响力被放大了,在绝大多数的应用中,不可能出现持续不断的类被加载或卸载。在程序运行一段时间后,热点方法被不断编译,新的热点方法数量也总会下降,倒是垃圾收集是会随着程序运行而不断进行着的,所以它对性能的影响要更为重要。

    先来看看下面打印的gc日志信息

    OpenJDK 64-Bit Server VM (25.152-b8) for windows-amd64 JRE (1.8.0_152-release-1248-b8), built on Jun 29 2018 12:50:12 by "builduser" with MS VC++ 10.0 (VS2010)
    Memory: 4k page, physical 8283072k(5066236k free), swap 12739520k(8195240k free)
    CommandLine flags: -XX:ErrorFile=C:\Users\along\java_error_in_idea_%p.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=C:\Users\along\java_error_in_idea.hprof -XX:InitialHeapSize=134217728 -XX:MaxHeapSize=786432000 -XX:MaxNewSize=262144000 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:-OmitStackTraceInFastThrow -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:ReservedCodeCacheSize=251658240 -XX:SoftRefLRUPolicyMSPerMB=50 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
    0.775: [GC (Allocation Failure) 0.776: [ParNew: 34944K->4352K(39296K), 0.0135813 secs] 34944K->6354K(126720K), 0.0139347 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
    0.971: [GC (Allocation Failure) 0.971: [ParNew: 39296K->4352K(39296K), 0.0146668 secs] 41298K->11591K(126720K), 0.0147703 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    1.203: [GC (Allocation Failure) 1.203: [ParNew: 39296K->4352K(39296K), 0.0160772 secs] 46535K->18675K(126720K), 0.0161621 secs] [Times: user=0.01 sys=0.03, real=0.01 secs] 
    2.492: [GC (Allocation Failure) 2.492: [ParNew: 39296K->4352K(39296K), 0.0131525 secs] 53619K->23456K(126720K), 0.0132417 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    4.428: [GC (Allocation Failure) 4.428: [ParNew: 39296K->4352K(39296K), 0.0217882 secs] 58400K->32031K(126720K), 0.0219023 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    4.450: [GC (CMS Initial Mark) [1 CMS-initial-mark: 27679K(87424K)] 32032K(126720K), 0.0015071 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    4.452: [CMS-concurrent-mark-start]
    4.496: [CMS-concurrent-mark: 0.043/0.045 secs] [Times: user=0.11 sys=0.02, real=0.05 secs] 
    4.496: [CMS-concurrent-preclean-start]
    4.497: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    4.497: [GC (CMS Final Remark) [YG occupancy: 5356 K (39296 K)]4.497: [Rescan (parallel) , 0.0014807 secs]4.499: [weak refs processing, 0.0000504 secs]4.499: [class unloading, 0.0040176 secs]4.503: [scrub symbol table, 0.0043625 secs]4.507: [scrub string table, 0.0006099 secs][1 CMS-remark: 27679K(87424K)] 33036K(126720K), 0.0112286 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
    4.509: [CMS-concurrent-sweep-start]
    4.523: [CMS-concurrent-sweep: 0.011/0.014 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
    4.523: [CMS-concurrent-reset-start]
    4.524: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    5.691: [GC (Allocation Failure) 5.691: [ParNew: 39296K->4352K(39296K), 0.0147091 secs] 64045K->33966K(126720K), 0.0148173 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    6.077: [GC (Allocation Failure) 6.077: [ParNew: 39296K->3129K(39296K), 0.0094558 secs] 68910K->35478K(126720K), 0.0095706 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    6.335: [GC (Allocation Failure) 6.335: [ParNew: 38073K->4131K(39296K), 0.0061449 secs] 70422K->36480K(126720K), 0.0062500 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    6.684: [GC (Allocation Failure) 6.684: [ParNew: 39075K->4352K(39296K), 0.0072328 secs] 71424K->38186K(126720K), 0.0073373 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    6.904: [GC (Allocation Failure) 6.904: [ParNew: 39296K->4352K(39296K), 0.0152431 secs] 73130K->42748K(126720K), 0.0153401 secs] [Times: user=0.03 sys=0.03, real=0.02 secs] 
    6.982: [GC (Allocation Failure) 6.983: [ParNew: 39296K->4051K(39296K), 0.0118092 secs] 77692K->46829K(126720K), 0.0119116 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
    8.171: [GC (Allocation Failure) 8.171: [ParNew: 38995K->4352K(39296K), 0.0069665 secs] 81773K->48520K(126720K), 0.0070546 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    8.807: [GC (Allocation Failure) 8.807: [ParNew: 39296K->4352K(39296K), 0.0112211 secs] 83464K->53207K(126720K), 0.0113210 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
    9.876: [GC (Allocation Failure) 9.876: [ParNew: 39296K->4352K(39296K), 0.0115803 secs] 88151K->55456K(126720K), 0.0116764 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
    10.154: [GC (Allocation Failure) 10.154: [ParNew: 39296K->4352K(39296K), 0.0142880 secs] 90400K->61654K(126720K), 0.0143769 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    10.294: [GC (Allocation Failure) 10.294: [ParNew: 39296K->4352K(39296K), 0.0091483 secs] 96598K->66090K(126720K), 0.0092357 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    10.586: [GC (Allocation Failure) 10.586: [ParNew: 39296K->4352K(39296K), 0.0139048 secs] 101034K->72139K(126720K), 0.0139959 secs] [Times: user=0.00 sys=0.02, real=0.02 secs] 
    12.137: [GC (Allocation Failure) 12.137: [ParNew: 39296K->4352K(39296K), 0.0101046 secs] 107083K->75926K(126720K), 0.0101926 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    12.504: [GC (Allocation Failure) 12.504: [ParNew: 39296K->4352K(39296K), 0.0078685 secs] 110870K->78133K(126720K), 0.0079574 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    12.926: [GC (Allocation Failure) 12.926: [ParNew: 39296K->4352K(39296K), 0.0140482 secs] 113077K->84325K(126720K), 0.0141424 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
    12.940: [GC (CMS Initial Mark) [1 CMS-initial-mark: 79973K(87424K)] 85010K(126720K), 0.0012677 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    12.942: [CMS-concurrent-mark-start]
    12.993: [CMS-concurrent-mark: 0.050/0.051 secs] [Times: user=0.11 sys=0.02, real=0.05 secs] 
    12.993: [CMS-concurrent-preclean-start]
    12.994: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    12.994: [CMS-concurrent-abortable-preclean-start]
    13.615: [GC (Allocation Failure) 13.615: [ParNew: 39296K->4352K(39296K), 0.0104557 secs] 119269K->89274K(127296K), 0.0105497 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    14.003: [CMS-concurrent-abortable-preclean: 0.512/1.009 secs] [Times: user=2.25 sys=0.19, real=1.02 secs] 
    14.003: [GC (CMS Final Remark) [YG occupancy: 22287 K (39296 K)]14.003: [Rescan (parallel) , 0.0031256 secs]14.006: [weak refs processing, 0.0000911 secs]14.006: [class unloading, 0.0077341 secs]14.014: [scrub symbol table, 0.0096173 secs]14.024: [scrub string table, 0.0006469 secs][1 CMS-remark: 84922K(88000K)] 107209K(127296K), 0.0218205 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
    14.025: [CMS-concurrent-sweep-start]
    14.060: [CMS-concurrent-sweep: 0.033/0.035 secs] [Times: user=0.05 sys=0.02, real=0.03 secs] 
    14.060: [CMS-concurrent-reset-start]
    14.061: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    14.425: [GC (Allocation Failure) 14.425: [ParNew: 39296K->4352K(39296K), 0.0141685 secs] 92679K->68359K(129040K), 0.0142836 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
    14.440: [GC (CMS Initial Mark) [1 CMS-initial-mark: 64007K(89744K)] 69049K(129040K), 0.0011983 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    14.441: [CMS-concurrent-mark-start]
    14.511: [CMS-concurrent-mark: 0.069/0.070 secs] [Times: user=0.16 sys=0.00, real=0.06 secs] 
    14.511: [CMS-concurrent-preclean-start]
    14.513: [CMS-concurrent-preclean: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    14.513: [CMS-concurrent-abortable-preclean-start]
    14.877: [CMS-concurrent-abortable-preclean: 0.102/0.364 secs] [Times: user=0.92 sys=0.06, real=0.37 secs] 
    14.877: [GC (CMS Final Remark) [YG occupancy: 21837 K (39296 K)]14.877: [Rescan (parallel) , 0.0053605 secs]14.883: [weak refs processing, 0.0006198 secs]14.884: [class unloading, 0.0071049 secs]14.891: [scrub symbol table, 0.0114251 secs]14.902: [scrub string table, 0.0006942 secs][1 CMS-remark: 64007K(89744K)] 85844K(129040K), 0.0257053 secs] [Times: user=0.05 sys=0.00, real=0.03 secs] 
    14.905: [CMS-concurrent-sweep-start]
    14.946: [CMS-concurrent-sweep: 0.041/0.041 secs] [Times: user=0.13 sys=0.00, real=0.03 secs] 
    14.946: [CMS-concurrent-reset-start]
    14.947: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    15.246: [GC (Allocation Failure) 15.246: [ParNew: 39296K->4352K(39296K), 0.0111934 secs] 99535K->70324K(139696K), 0.0112986 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    16.024: [GC (Allocation Failure) 16.024: [ParNew: 39296K->4352K(39296K), 0.0171974 secs] 105268K->76570K(139696K), 0.0173153 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    16.492: [GC (Allocation Failure) 16.492: [ParNew: 39296K->4352K(39296K), 0.0105329 secs] 111514K->80446K(139696K), 0.0106566 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
    17.447: [GC (Allocation Failure) 17.447: [ParNew: 39296K->4352K(39296K), 0.0110877 secs] 115390K->83628K(139696K), 0.0111993 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    18.293: [GC (Allocation Failure) 18.293: [ParNew: 39296K->4351K(39296K), 0.0120751 secs] 118572K->87072K(139696K), 0.0121918 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    19.408: [GC (Allocation Failure) 19.408: [ParNew: 39295K->4352K(39296K), 0.0208940 secs] 122016K->92520K(139696K), 0.0210306 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    19.430: [GC (CMS Initial Mark) [1 CMS-initial-mark: 88168K(100400K)] 92520K(139696K), 0.0032161 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
    19.433: [CMS-concurrent-mark-start]
    19.551: [CMS-concurrent-mark: 0.117/0.118 secs] [Times: user=0.34 sys=0.01, real=0.11 secs] 
    19.551: [CMS-concurrent-preclean-start]
    19.553: [CMS-concurrent-preclean: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    19.553: [GC (CMS Final Remark) [YG occupancy: 4946 K (39296 K)]19.553: [Rescan (parallel) , 0.0038428 secs]19.557: [weak refs processing, 0.0000778 secs]19.557: [class unloading, 0.0161316 secs]19.573: [scrub symbol table, 0.0277477 secs]19.601: [scrub string table, 0.0020632 secs][1 CMS-remark: 88168K(100400K)] 93115K(139696K), 0.0505128 secs] [Times: user=0.19 sys=0.00, real=0.06 secs] 
    19.604: [CMS-concurrent-sweep-start]
    19.645: [CMS-concurrent-sweep: 0.041/0.041 secs] [Times: user=0.09 sys=0.00, real=0.03 secs] 
    19.645: [CMS-concurrent-reset-start]
    19.646: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    20.850: [GC (Allocation Failure) 20.850: [ParNew: 39296K->4352K(39296K), 0.0158607 secs] 117751K->88834K(170056K), 0.0159895 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] 
    22.220: [GC (Allocation Failure) 22.220: [ParNew: 39296K->4352K(39296K), 0.0148033 secs] 123778K->94619K(170056K), 0.0149265 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    23.564: [GC (Allocation Failure) 23.564: [ParNew: 39296K->4352K(39296K), 0.0135509 secs] 129563K->98248K(170056K), 0.0136790 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    24.771: [GC (Allocation Failure) 24.771: [ParNew: 39296K->4352K(39296K), 0.0145119 secs] 133192K->104816K(170056K), 0.0146111 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
    25.258: [GC (Allocation Failure) 25.258: [ParNew: 39296K->3583K(39296K), 0.0103148 secs] 139760K->106926K(170056K), 0.0104209 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
    25.716: [GC (Allocation Failure) 25.716: [ParNew: 38527K->2491K(39296K), 0.0036823 secs] 141870K->105834K(170056K), 0.0037803 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
    26.059: [GC (Allocation Failure) 26.059: [ParNew: 37435K->4352K(39296K), 0.0074091 secs] 140778K->108280K(170056K), 0.0075127 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
    26.360: [GC (Allocation Failure) 26.360: [ParNew: 39296K->4352K(39296K), 0.0128741 secs] 143224K->112671K(170056K), 0.0129771 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    26.722: [GC (Allocation Failure) 26.722: [ParNew: 39296K->3318K(39296K), 0.0074259 secs] 147615K->113598K(170056K), 0.0075388 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
    28.661: [GC (Allocation Failure) 28.661: [ParNew: 38262K->4352K(39296K), 0.0080974 secs] 148542K->115946K(170056K), 0.0081910 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    31.633: [GC (Allocation Failure) 31.633: [ParNew: 39296K->4019K(39296K), 0.0113950 secs] 150890K->117543K(170056K), 0.0114967 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    33.646: [GC (CMS Initial Mark) [1 CMS-initial-mark: 113524K(130760K)] 145964K(170056K), 0.0111026 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
    33.658: [CMS-concurrent-mark-start]
    33.838: [CMS-concurrent-mark: 0.180/0.180 secs] [Times: user=0.58 sys=0.16, real=0.18 secs] 
    33.838: [CMS-concurrent-preclean-start]
    33.847: [CMS-concurrent-preclean: 0.008/0.008 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    33.847: [CMS-concurrent-abortable-preclean-start]
    34.676: [GC (Allocation Failure) 34.676: [ParNew: 38963K->4154K(39296K), 0.0121330 secs] 152487K->120008K(170056K), 0.0122409 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
    35.252: [CMS-concurrent-abortable-preclean: 0.898/1.406 secs] [Times: user=3.74 sys=0.92, real=1.42 secs] 
    35.253: [GC (CMS Final Remark) [YG occupancy: 27111 K (39296 K)]35.253: [Rescan (parallel) , 0.0081521 secs]35.261: [weak refs processing, 0.0003194 secs]35.261: [class unloading, 0.0281588 secs]35.289: [scrub symbol table, 0.0442413 secs]35.334: [scrub string table, 0.0024159 secs][1 CMS-remark: 115854K(130760K)] 142965K(170056K), 0.0841369 secs] [Times: user=0.08 sys=0.00, real=0.08 secs] 
    35.379: [CMS-concurrent-sweep-start]
    35.437: [CMS-concurrent-sweep: 0.058/0.058 secs] [Times: user=0.16 sys=0.03, real=0.05 secs] 
    35.441: [GC (Allocation Failure) 35.441: [ParNew: 39098K->3113K(39296K), 0.0103459 secs] 136710K->103650K(170056K), 0.0104781 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    35.524: [CMS-concurrent-reset-start]
    35.524: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    35.680: [GC (Allocation Failure) 35.680: [ParNew: 38057K->2674K(39296K), 0.0053558 secs] 138594K->103210K(206860K), 0.0054837 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    35.970: [GC (Allocation Failure) 35.970: [ParNew: 37618K->1756K(39296K), 0.0034152 secs] 138154K->102293K(206860K), 0.0035290 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
    36.083: [GC (Allocation Failure) 36.083: [ParNew: 36682K->2230K(39296K), 0.0035850 secs] 137219K->102767K(206860K), 0.0037060 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    36.962: [GC (Allocation Failure) 36.962: [ParNew: 37174K->4093K(39296K), 0.0063455 secs] 137711K->104630K(206860K), 0.0064587 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    39.037: [GC (Allocation Failure) 39.037: [ParNew: 39037K->4352K(39296K), 0.0163667 secs] 139574K->108000K(206860K), 0.0164784 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
    43.569: [GC (Allocation Failure) 43.569: [ParNew: 39296K->4352K(39296K), 0.0156834 secs] 142944K->112273K(206860K), 0.0157718 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    44.831: [GC (Allocation Failure) 44.831: [ParNew: 39296K->4352K(39296K), 0.0160218 secs] 147217K->119293K(206860K), 0.0161332 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
    46.812: [GC (Allocation Failure) 46.812: [ParNew: 39296K->4352K(39296K), 0.0171458 secs] 154237K->124437K(206860K), 0.0172581 secs] [Times: user=0.06 sys=0.02, real=0.03 secs] 
    49.491: [GC (Allocation Failure) 49.491: [ParNew: 39296K->4352K(39296K), 0.0194665 secs] 159381K->128295K(206860K), 0.0195841 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    52.579: [GC (Allocation Failure) 52.579: [ParNew: 39295K->4352K(39296K), 0.0192815 secs] 163239K->132280K(206860K), 0.0194056 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    58.755: [GC (Allocation Failure) 58.755: [ParNew: 39296K->3571K(39296K), 0.0165521 secs] 167224K->134656K(206860K), 0.0166886 secs] [Times: user=0.06 sys=0.02, real=0.03 secs] 
    60.319: [GC (Allocation Failure) 60.319: [ParNew: 38515K->4352K(39296K), 0.0098126 secs] 169600K->135674K(206860K), 0.0099612 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    61.388: [GC (Allocation Failure) 61.388: [ParNew: 39296K->4352K(39296K), 0.0212038 secs] 170618K->143183K(206860K), 0.0213571 secs] [Times: user=0.08 sys=0.00, real=0.02 secs] 
    63.553: [GC (Allocation Failure) 63.553: [ParNew: 39296K->4352K(39296K), 0.0350091 secs] 178127K->152043K(206860K), 0.0351456 secs] [Times: user=0.11 sys=0.02, real=0.03 secs] 
    63.667: [GC (CMS Initial Mark) [1 CMS-initial-mark: 147691K(167564K)] 152163K(206860K), 0.0057144 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
    63.673: [CMS-concurrent-mark-start]
    63.928: [CMS-concurrent-mark: 0.252/0.255 secs] [Times: user=0.56 sys=0.02, real=0.25 secs] 
    63.929: [CMS-concurrent-preclean-start]
    63.933: [CMS-concurrent-preclean: 0.005/0.005 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    63.933: [CMS-concurrent-abortable-preclean-start]
    64.839: [GC (Allocation Failure) 64.839: [ParNew: 39296K->4352K(39296K), 0.0217313 secs] 186987K->157822K(206860K), 0.0218687 secs] [Times: user=0.08 sys=0.02, real=0.03 secs] 
    65.584: [CMS-concurrent-abortable-preclean: 0.984/1.651 secs] [Times: user=3.31 sys=0.64, real=1.65 secs] 
    65.725: [GC (CMS Final Remark) [YG occupancy: 25021 K (39296 K)]65.725: [Rescan (parallel) , 0.0096415 secs]65.735: [weak refs processing, 0.0030954 secs]65.738: [class unloading, 0.0679151 secs]65.806: [scrub symbol table, 0.0667871 secs]65.873: [scrub string table, 0.0042969 secs][1 CMS-remark: 153470K(167564K)] 178491K(206860K), 0.1813899 secs] [Times: user=0.22 sys=0.02, real=0.19 secs] 
    65.907: [CMS-concurrent-sweep-start]
    66.086: [CMS-concurrent-sweep: 0.145/0.179 secs] [Times: user=0.31 sys=0.13, real=0.17 secs] 
    66.087: [CMS-concurrent-reset-start]
    66.087: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    67.049: [GC (Allocation Failure) 67.049: [ParNew: 39296K->3877K(39296K), 0.0166127 secs] 162824K->132129K(245180K), 0.0167465 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
    69.559: [GC (Allocation Failure) 69.559: [ParNew: 38821K->3837K(39296K), 0.0074212 secs] 167073K->132088K(245180K), 0.0075559 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    70.179: [GC (Allocation Failure) 70.179: [ParNew: 38781K->3084K(39296K), 0.0124219 secs] 167032K->134074K(245180K), 0.0125777 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    70.414: [GC (Allocation Failure) 70.414: [ParNew: 38009K->2594K(39296K), 0.0049789 secs] 168999K->133584K(245180K), 0.0051167 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
    70.452: [GC (Allocation Failure) 70.453: [ParNew: 37538K->1186K(39296K), 0.0047285 secs] 168528K->132725K(245180K), 0.0048623 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    71.353: [GC (Allocation Failure) 71.353: [ParNew: 36130K->1639K(39296K), 0.0044468 secs] 167669K->133178K(245180K), 0.0045898 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    72.621: [GC (Allocation Failure) 72.621: [ParNew: 36583K->1841K(39296K), 0.0044832 secs] 168122K->133380K(245180K), 0.0046209 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    73.568: [GC (Allocation Failure) 73.569: [ParNew: 36785K->3018K(39296K), 0.0049447 secs] 168324K->134557K(245180K), 0.0050719 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    75.024: [GC (Allocation Failure) 75.024: [ParNew: 37962K->3000K(39296K), 0.0064347 secs] 169501K->134859K(245180K), 0.0065663 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    75.717: [GC (Allocation Failure) 75.717: [ParNew: 37944K->2907K(39296K), 0.0056746 secs] 169803K->134765K(245180K), 0.0058276 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
    76.380: [GC (Allocation Failure) 76.380: [ParNew: 37851K->3720K(39296K), 0.0069908 secs] 169709K->135892K(245180K), 0.0071392 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    77.971: [GC (Allocation Failure) 77.971: [ParNew: 38643K->4352K(39296K), 0.0074766 secs] 170815K->137026K(245180K), 0.0076240 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    78.099: [GC (Allocation Failure) 78.099: [ParNew: 39296K->3003K(39296K), 0.0088121 secs] 171970K->136982K(245180K), 0.0089570 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    79.792: [GC (Allocation Failure) 79.792: [ParNew: 37947K->4352K(39296K), 0.0083633 secs] 171926K->138692K(245180K), 0.0085048 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    81.511: [GC (Allocation Failure) 81.511: [ParNew: 39296K->4352K(39296K), 0.0144021 secs] 173636K->143187K(245180K), 0.0145389 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    82.718: [GC (Allocation Failure) 82.718: [ParNew: 39296K->3639K(39296K), 0.0114718 secs] 178131K->145810K(245180K), 0.0116320 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
    83.427: [GC (Allocation Failure) 83.427: [ParNew: 38583K->2171K(39296K), 0.0174478 secs] 180754K->146275K(245180K), 0.0175961 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
    83.997: [GC (Allocation Failure) 83.997: [ParNew: 37115K->4065K(39296K), 0.0084177 secs] 181219K->148169K(245180K), 0.0085797 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    84.369: [GC (Allocation Failure) 84.369: [ParNew: 39004K->4352K(39296K), 0.0126906 secs] 183108K->149816K(245180K), 0.0128324 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    84.775: [GC (Allocation Failure) 84.775: [ParNew: 39296K->4352K(39296K), 0.0111427 secs] 184760K->151364K(245180K), 0.0113054 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
    85.262: [GC (Allocation Failure) 85.262: [ParNew: 39296K->4352K(39296K), 0.0104396 secs] 186308K->152834K(245180K), 0.0105845 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
    85.483: [GC (Allocation Failure) 85.483: [ParNew: 39296K->3256K(39296K), 0.0098272 secs] 187778K->153630K(245180K), 0.0099762 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    85.664: [GC (Allocation Failure) 85.664: [ParNew: 38200K->3305K(39296K), 0.0086681 secs] 188574K->154982K(245180K), 0.0088034 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
    85.878: [GC (Allocation Failure) 85.878: [ParNew: 38249K->3077K(39296K), 0.0066568 secs] 189926K->154754K(245180K), 0.0068201 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    86.055: [GC (Allocation Failure) 86.055: [ParNew: 38021K->3488K(39296K), 0.0088006 secs] 189698K->156270K(245180K), 0.0089508 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
    86.404: [GC (Allocation Failure) 86.404: [ParNew: 38432K->3825K(39296K), 0.0065495 secs] 191214K->156606K(245180K), 0.0066845 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    86.659: [GC (Allocation Failure) 86.659: [ParNew: 38769K->4352K(39296K), 0.0096163 secs] 191550K->157937K(245180K), 0.0097553 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    87.515: [GC (Allocation Failure) 87.515: [ParNew: 39296K->4352K(39296K), 0.0130228 secs] 192881K->159538K(245180K), 0.0131736 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
    87.762: [GC (Allocation Failure) 87.762: [ParNew: 39296K->4352K(39296K), 0.0132700 secs] 194482K->161009K(245180K), 0.0134131 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
    87.992: [GC (Allocation Failure) 87.993: [ParNew: 39296K->4311K(39296K), 0.0140168 secs] 195953K->162838K(245180K), 0.0141751 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
    88.789: [GC (Allocation Failure) 88.789: [ParNew: 39214K->4352K(39296K), 0.0130915 secs] 197741K->164842K(245180K), 0.0132280 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    90.444: [GC (Allocation Failure) 90.444: [ParNew: 39296K->4352K(39296K), 0.0272877 secs] 199786K->173862K(245180K), 0.0274215 secs] [Times: user=0.06 sys=0.05, real=0.03 secs] 
    91.288: [GC (Allocation Failure) 91.288: [ParNew: 39296K->4352K(39296K), 0.0123840 secs] 208806K->178353K(245180K), 0.0125301 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    92.009: [GC (Allocation Failure) 92.009: [ParNew: 39296K->4116K(39296K), 0.0103236 secs] 213297K->178117K(245180K), 0.0104623 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    93.387: [GC (Allocation Failure) 93.387: [ParNew: 39060K->4352K(39296K), 0.0125852 secs] 213061K->180214K(245180K), 0.0127326 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    94.080: [GC (Allocation Failure) 94.080: [ParNew: 39296K->4352K(39296K), 0.0179525 secs] 215158K->184651K(245180K), 0.0180903 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
    94.372: [GC (Allocation Failure) 94.372: [ParNew: 39296K->3417K(39296K), 0.0124076 secs] 219595K->186581K(245180K), 0.0125541 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    94.706: [GC (Allocation Failure) 94.706: [ParNew: 38361K->3645K(39296K), 0.0065380 secs] 221525K->186809K(245180K), 0.0066838 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    94.933: [GC (Allocation Failure) 94.933: [ParNew: 38589K->4352K(39296K), 0.0108594 secs] 221753K->190001K(245180K), 0.0110202 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    95.466: [GC (Allocation Failure) 95.466: [ParNew: 39296K->4352K(39296K), 0.0155525 secs] 224945K->195120K(245180K), 0.0156909 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
    95.501: [GC (CMS Initial Mark) [1 CMS-initial-mark: 190768K(205884K)] 195948K(245180K), 0.0070082 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    95.510: [CMS-concurrent-mark-start]
    95.810: [GC (Allocation Failure) 95.810: [ParNew: 39296K->4029K(39296K), 0.0180107 secs] 230064K->198844K(245180K), 0.0181491 secs] [Times: user=0.03 sys=0.03, real=0.02 secs] 
    95.860: [CMS-concurrent-mark: 0.319/0.349 secs] [Times: user=1.03 sys=0.09, real=0.36 secs] 
    95.860: [CMS-concurrent-preclean-start]
    95.867: [CMS-concurrent-preclean: 0.008/0.008 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    95.868: [CMS-concurrent-abortable-preclean-start]
    96.222: [GC (Allocation Failure) 96.222: [ParNew: 38973K->3663K(39296K), 0.0063856 secs] 233788K->198477K(245180K), 0.0065234 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    96.365: [GC (Allocation Failure) 96.408: [ParNew: 38607K->1558K(39296K), 0.0086877 secs] 233421K->199117K(245180K), 0.0512458 secs] [Times: user=0.08 sys=0.02, real=0.05 secs] 
    96.427: [CMS-concurrent-abortable-preclean: 0.196/0.559 secs] [Times: user=1.77 sys=0.08, real=0.56 secs] 
    96.435: [GC (CMS Final Remark) [YG occupancy: 2335 K (39296 K)]96.435: [Rescan (parallel) , 0.0046999 secs]96.440: [weak refs processing, 0.0009738 secs]96.441: [class unloading, 0.0807112 secs]96.521: [scrub symbol table, 0.0752882 secs]96.597: [scrub string table, 0.0048940 secs][1 CMS-remark: 197559K(205884K)] 199894K(245180K), 0.1922167 secs] [Times: user=0.38 sys=0.00, real=0.19 secs] 
    96.627: [CMS-concurrent-sweep-start]
    96.779: [CMS-concurrent-sweep: 0.148/0.152 secs] [Times: user=0.58 sys=0.03, real=0.15 secs] 
    96.780: [CMS-concurrent-reset-start]
    96.780: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    97.650: [GC (Allocation Failure) 97.650: [ParNew: 36502K->4352K(39296K), 0.0098521 secs] 181641K->149893K(281196K), 0.0099936 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
    98.767: [GC (Allocation Failure) 98.767: [ParNew: 39296K->4352K(39296K), 0.0233734 secs] 184837K->157191K(281196K), 0.0235074 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
    99.559: [GC (Allocation Failure) 99.559: [ParNew: 39296K->4352K(39296K), 0.0275950 secs] 192135K->166749K(281196K), 0.0277604 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    101.190: [GC (Allocation Failure) 101.190: [ParNew: 39296K->3247K(39296K), 0.0177208 secs] 201693K->169997K(281196K), 0.0178745 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    102.401: [GC (Allocation Failure) 102.401: [ParNew: 27762K->2743K(39296K), 0.0065361 secs] 194512K->169493K(281196K), 0.0066773 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    102.848: [GC (Allocation Failure) 102.848: [ParNew: 37687K->4352K(39296K), 0.0147408 secs] 204437K->173493K(281196K), 0.0148764 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
    103.407: [GC (Allocation Failure) 103.407: [ParNew: 39296K->3764K(39296K), 0.0079773 secs] 208437K->174384K(281196K), 0.0081011 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    103.718: [GC (Allocation Failure) 103.718: [ParNew: 38708K->2328K(39296K), 0.0057011 secs] 209328K->172948K(281196K), 0.0058308 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
    103.869: [GC (Allocation Failure) 103.869: [ParNew: 37272K->2576K(39296K), 0.0047015 secs] 207892K->173196K(281196K), 0.0048408 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    104.019: [GC (Allocation Failure) 104.019: [ParNew: 37520K->3299K(39296K), 0.0047839 secs] 208140K->173919K(281196K), 0.0049173 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
    104.266: [GC (Allocation Failure) 104.266: [ParNew: 38243K->3027K(39296K), 0.0059474 secs] 208863K->174969K(281196K), 0.0060970 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
    104.453: [GC (Allocation Failure) 104.453: [ParNew: 37971K->1043K(39296K), 0.0040487 secs] 209913K->172985K(281196K), 0.0041945 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    104.619: [GC (Allocation Failure) 104.619: [ParNew: 35987K->1415K(39296K), 0.0041532 secs] 207929K->173356K(281196K), 0.0042910 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    104.837: [GC (Allocation Failure) 104.837: [ParNew: 36359K->984K(39296K), 0.0044415 secs] 208300K->173308K(281196K), 0.0045926 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    104.982: [GC (Allocation Failure) 104.982: [ParNew: 35928K->1226K(39296K), 0.0045926 secs] 208252K->173585K(281196K), 0.0047326 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    105.235: [GC (Allocation Failure) 105.235: [ParNew: 36170K->1214K(39296K), 0.0083639 secs] 208529K->173574K(281196K), 0.0085206 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    105.423: [GC (Allocation Failure) 105.423: [ParNew: 36158K->1574K(39296K), 0.0041199 secs] 208518K->173950K(281196K), 0.0042763 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
    105.614: [GC (Allocation Failure) 105.614: [ParNew: 36518K->1325K(39296K), 0.0057608 secs] 208894K->173718K(281196K), 0.0059048 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
    105.906: [GC (Allocation Failure) 105.907: [ParNew: 36269K->2049K(39296K), 0.0045301 secs] 208662K->174521K(281196K), 0.0046816 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
    106.055: [GC (Allocation Failure) 106.055: [ParNew: 36993K->1580K(39296K), 0.0048747 secs] 209465K->174382K(281196K), 0.0050321 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    110.282: [GC (Allocation Failure) 110.282: [ParNew: 36524K->1932K(39296K), 0.0059831 secs] 209326K->174819K(281196K), 0.0061418 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    113.730: [GC (Allocation Failure) 113.730: [ParNew: 36876K->2446K(39296K), 0.0053845 secs] 209763K->175421K(281196K), 0.0055512 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    119.258: [GC (Allocation Failure) 119.258: [ParNew: 37343K->2464K(39296K), 0.0083832 secs] 210319K->175481K(281196K), 0.0085042 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    119.450: [GC (Allocation Failure) 119.450: [ParNew: 37406K->3177K(39296K), 0.0050507 secs] 210424K->176202K(281196K), 0.0051677 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    132.225: [GC (Allocation Failure) 132.225: [ParNew: 38121K->2291K(39296K), 0.0186346 secs] 211146K->176229K(281196K), 0.0187870 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
    134.054: [GC (Allocation Failure) 134.054: [ParNew: 37215K->2195K(39296K), 0.0056068 secs] 211154K->176134K(281196K), 0.0057440 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    135.648: [GC (Allocation Failure) 135.648: [ParNew: 37139K->2180K(39296K), 0.0056249 secs] 211078K->176119K(281196K), 0.0057340 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    139.642: [GC (Allocation Failure) 139.642: [ParNew: 37124K->4351K(39296K), 0.0108911 secs] 211063K->178789K(281196K), 0.0110292 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    142.545: [GC (Allocation Failure) 142.545: [ParNew: 39295K->3882K(39296K), 0.0149548 secs] 213733K->181616K(281196K), 0.0150984 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
    145.692: [GC (Allocation Failure) 145.692: [ParNew: 38826K->2691K(39296K), 0.0119078 secs] 216560K->182714K(281196K), 0.0120453 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    145.742: [GC (Allocation Failure) 145.742: [ParNew: 37612K->1629K(39296K), 0.0054784 secs] 217634K->181652K(281196K), 0.0056037 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    170.689: [GC (Allocation Failure) 170.689: [ParNew: 36573K->1771K(39296K), 0.0091290 secs] 216596K->181794K(281196K), 0.0093619 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
    

    可以看到大部分为Minor GC,是由于年轻代空间不足而导致内存分配失败(Allocation Failure)而发起的,解决方案就是扩大新生代容量,以减少Minor GC发生的次数。

    下面来看下堆空间的变化曲线图

    可以看到堆的初始容量约为223M,在开始的一段时间内保持稳定,当内存占用过高时启动垃圾回收,当内存占用达到189M时,再次出发垃圾回收,同时虚拟机为了减少过于频繁的垃圾回收,对堆空间进行了扩容,之后堆空间稳定在267M。
    idea的初始堆空间分配如下:

    -Xms128m
    -Xmx750m
    

    可见初始堆空间设置的过小,我们将初始值跟最大值一样大,防止因为堆扩容引发的消耗。
    综上我们第一次优化后的启动参数如下

    -Xms750m
    -Xmx750m
    -Xmn200m
    -Xverify:none
    -XX:ReservedCodeCacheSize=240m
    -XX:+UseConcMarkSweepGC
    -XX:SoftRefLRUPolicyMSPerMB=50
    -ea
    -Dsun.io.useCanonCaches=false
    -Djava.net.preferIPv4Stack=true
    -XX:+HeapDumpOnOutOfMemoryError
    -XX:-OmitStackTraceInFastThrow
    

    重启idea,下面是VisualVM监控结果

    我们可以看到
    编译时间由原来的3m 5.690s变为了2m 28.233s,减少了30多秒,这个提升还算明显。
    类加载用时却由原来的1m 29.960s增加到了4m 6.368s,可能是由于-Xverify:none参数起到了相反的效果。
    重点观察GC,由于增大了新生代的空间Minor GC次数明显降低,由131次降为26次,Full GC次数由14次降为8次,提升并不明显。
    可以看到老年区的容量为550M,最终使用量稳定在175.694M,可见老年代的空间是完全足够的,可为什么还会发生8次Full GC呢?原因就是Matespace导致的,下面是Matespace空间变化图:

    Matespace是元空间,在JDK1.8代替永久代成为方法区的实现,元空间并不占用堆空间的内存,而是使用系统内存。上图中可看到Matespace的初始值非常小,在程序启动过程中由于空间不足发生了多次的扩容,最终容量稳定在220M,而Matespace空间不足同样会引发Full GC。我们通过如下参数给Matespace设置一个足够大的初始容量

    -XX:MetaspaceSize=248m
    

    为了进一步减少Minor的次数,再次增大新生代的初始空间
    而由于不确定类加载时间边长是否是-Xverify:none参数造成的,姑且先不处理。
    第二次优化后的启动参数如下

    -Xms750m
    -Xmx750m
    -Xmn400m
    -XX:MetaspaceSize=248m
    -Xverify:none
    -XX:ReservedCodeCacheSize=240m
    -XX:+UseConcMarkSweepGC
    -XX:SoftRefLRUPolicyMSPerMB=50
    -ea
    -Dsun.io.useCanonCaches=false
    -Djava.net.preferIPv4Stack=true
    -XX:+HeapDumpOnOutOfMemoryError
    -XX:-OmitStackTraceInFastThrow
    

    重启idea,VisualVM监控结果如下

    提升很明显,Minor GC再次减少为13,但是仍然有两次Full GC,应该是老年代空间稍微小了(只有250M),索性将堆空间增大到1G,同时将新生代空间也增大到500M,第三次优化后的启动参数如下

    -Xms1024m
    -Xmx1024m
    -Xmn500m
    -XX:MetaspaceSize=248m
    -Xverify:none
    -XX:ReservedCodeCacheSize=240m
    -XX:+UseConcMarkSweepGC
    -XX:SoftRefLRUPolicyMSPerMB=50
    -ea
    -Dsun.io.useCanonCaches=false
    -Djava.net.preferIPv4Stack=true
    -XX:+HeapDumpOnOutOfMemoryError
    -XX:-OmitStackTraceInFastThrow
    

    重启idea,VisualVM监控结果如下

    可以看到Full GC没有了,而且Minor GC数量也控制的可比较小。

    综上,最终的优化配置参数为

    -Xms1024m
    -Xmx1024m
    -Xmn500m
    -XX:MetaspaceSize=248m
    -Xverify:none
    -XX:ReservedCodeCacheSize=240m
    -XX:+UseConcMarkSweepGC
    -XX:SoftRefLRUPolicyMSPerMB=50
    -Xverify:none
    -ea
    -Dsun.io.useCanonCaches=false
    -Dsun.awt.keepWorkingSetOnMinimize=true
    -Djava.net.preferIPv4Stack=true
    -XX:+HeapDumpOnOutOfMemoryError
    -XX:-OmitStackTraceInFastThrow
    -Dfile.encoding=UTF-8
    

    下面是用到的各参数作用备注:

    -verbose:gc             #在虚拟机发生内存回收时在输出设备显示信息,格式如下:[Full GC 268K->168K(1984K), 0.0187390 secs]该参数用来监视虚拟机内存回收的情况。
    -XX:+PrintGCDetails     #发生垃圾收集时打印内存回收日志
    -XX:+PrintGCTimeStamps  #输出GC的时间戳(以基准时间的形式,如49.459,默认就是这个输出形式,可以不写)
    -XX:+PrintGCDateStamps   #输出GC的时间戳(以以日期的形式,如2019-03-01T12:57:54.486+0800)
    -XX:+PrintGCApplicationStoppedTime  #打印垃圾回收期间程序暂停的时间,这个日志量非常庞大,如果没有特殊需求,不要加上这个配置
    -XX:+PrintHeapAtGC   #在进行GC的前后打印出堆的信息
    -Xloggc:D:/gc.log       #gc日志输出路径
    
    -Xms1024m               #初始堆内存
    -Xmx1024m               #最大堆内存
    -Xmn500m                #新生代容量
    -XX:MetaspaceSize=248m  #元空间初始容量
    -XX:MaxMetaspaceSize=512m   #元空间最大容量
    -XX:PermSize=248m       #JVM初始分配的非堆内存
    -XX:MaxPermSize=512m    #JVM最大允许分配的非堆内存,按需分配
    -XX:ReservedCodeCacheSize=512m      #代码编译缓存容量,默认为240m
    -Xverify:none           #关闭Java字节码验证,从而加快了类装入的速度
    -Xnoclassgc             #关闭虚拟机对class的垃圾回收功能
    -XX:+UseParNewGC        #使用ParNew收集器进行新生代垃圾回收
    -XX:+UseConcMarkSweepGC #使用CMS+Serial Old收集器进行老年代垃圾回收
    -XX:SoftRefLRUPolicyMSPerMB=50      #扫描软引用时间 JetBrain官方推荐设置
    -ea                     #设置虚拟机是否启动断言机制,缺省时虚拟机关闭断言机制,用-ea可打开断言机制
    -server                 #使用server模式运行,默认是client
    -Dsun.io.useCanonCaches=false
    -Dsun.awt.keepWorkingSetOnMinimize=true     #系统属性,在应用程序最小化后阻止 JVM 对其进行修剪。
    -Djava.net.preferIPv4Stack=true
    -XX:+HeapDumpOnOutOfMemoryError             #该配置会把快照保存在用户目录或者tomcat目录下,也可以通过 -XX:HeapDumpPath=/tmp/heapdump.hprof 来显示指定路径
                                                #此外,OnOutOfMemoryError参数允许用户指定当出现oom时,指定某个脚本来完成一些动作。
                                                #-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/heapdump.hprof -XX:OnOutOfMemoryError="sh ~/test.sh"
    -XX:-OmitStackTraceInFastThrow
    -Dfile.encoding=UTF-8   #设置字符编码为UTF-8
    -XX:+DisableExplicitGC 禁止 RMI 调用 System.gc()。
    

    相关文章

      网友评论

        本文标题:一次针对idea启动的JVM调优过程记录

        本文链接:https://www.haomeiwen.com/subject/aosbuqtx.html