• -------------------------------------------------------------
  • ====================================
> 技能 > idea的一次jvm调优

idea的一次jvm调优

技能 dewbay 5年前 (2019-09-18) 2260次浏览 已收录 0个评论 扫描二维码
文章目录[隐藏]

1.准备工作:

这段时间一直在看 jvm 调优的内容,苦于没有环境让自己练手,周三下午测试人员说测试后台过于慢,之前一直以为是数据库压力太大的问题,后来连上测试环境,发现 xmn=150m,新生代只分配了 150m,而整个堆最大为 2g,然后和运维同事沟通了,建议设置成 1G,项目再打包,后台页面基本都秒开,虽然是个测试环境小小的调优,还是比较开心的哈.
测试环境毕竟是测试环境,因为开发没有权限,有东西想改还是要和运维沟通,这几天拿 idea 试试手,把 idea 调优下.先说下我的配置,E5 2660 ,8 核 16 线程,16G 内存,120G ssd,cpu 虽然线程数比较多,但是主频比较低,只有 2.2g,idea 在我电脑上启动大概需要 20s 左右.其实前几天就着手做这个事情,但是一直没有办法统计出 idea 具体的启动时间,周志明大佬在深入 jvm 一书中是用的 eclipse 调优,eclipse 插件似乎把启动时间写入到全局变量中了,idea 我找了半天没找到,今天下午突然发现,其实 idea 在启动的时候会把启动信息写入到日志中,我的位置是在 C:\Users\Administrator.IntelliJIdea2018.1\system\log\idea.log,这里面记录了 idea 启动都做了哪些事情
idea的一次jvm调优
image
然后我就以 app initialzation took 作为时间的标准,后面这个 13745ms 我不知道它咋算出来的,启动时间到这个点输出一个是 11667 这个时间才对,然后我就以 11667 作为 idea 的启动时间来判断.如果是用 linux 来截取这个时间的话 awk 命令就够了,做两次管道
grep 'App initialization took' idea.log | awk '{print $4}'|awk -F ']' '{print $1}'
我是 windows 上跑的这个,然后就开了个 pycharm,用 python 来处理这个时间,为了能够在 idea 启动的瞬间,就记录这些信息,我把 idea 配置在了环境变量里,然后用 python 启动,就是下面的 openIdeaAndTools 方法,这里顺便吐槽下 pycharm,我配完环境变量,idea 死活起不来,然后电脑重启下突然就好了,估计它的 terminal 缓存了系统的环境变量,不知道算不算 bug.
#!/usr/bin/env python
# -*- coding=utf-8 -*-
import fileinput
import os
import threading

import time


class MyThread(threading.Thread):
    def __init__(self, arg):
        super(MyThread, self).__init__()
        self.arg = arg

    def run(self):
        os.system(self.arg)


def getIdeaStartTime(logPath):
    # 获取 idea 的启动时间
    for line in fileinput.input(logPath):
        if 'App initialization took' in line:
            print(line.split('[')[-1].split(']')[0])


def openIdeaAndTools():
    # 这里调用命令是阻塞执行,所以开启线程异步执行
    t1 = MyThread('idea64.exe ')
    t1.start()
    # 防止 idea 未启动先执行了下面的代码
    time.sleep(0.1)
    try:
        # 调用 jps 命令
        pid = os.popen("jps")
        for l in pid:
            # 因为 idea 启动后,jps 输出的只有一个 vmid,后面没有类名,以此来判断该进程是 idea 的
            id = l.split(' ')[0]
            info = l.split(' ')[1]
            # 我这台机器上还跑了 pycharm,pycharm 后面同样没有类名,就把 pycharm 的 vmid 去掉
            if not info.strip() and int(id) != 1200:
                print("idea 的 Id 为" + id)
                # 调用 jstat
                t4 = MyThread('jstat -gcutil ' + id + ' 1000 3')
                t4.start()
                # 调用 jconsole
                t2 = MyThread('jconsole ' + id)
                # 调用 jvisualvm
                t3 = MyThread('jvisualvm')
                t3.start()
                t2.start()
    finally:
        pid.close()


if __name__ == "__main__":

    # getIdeaStartTime(logPath = "C:\\Users\\Administrator\\.IntelliJIdea2018.1\\system\\log\\idea.log")
    openIdeaAndTools()

2.未优化前:

首先说下 idea 的默认配置,在 help-edit custom vm options 可以看到,配置如下:
-Xms128m                        //最小堆 128
-Xmx750m                        //最大 750
-XX:ReservedCodeCacheSize=240m  //代码缓存
-XX:+UseConcMarkSweepGC         //使用 parnew+cms 垃圾回收
-XX:SoftRefLRUPolicyMSPerMB=50  //和 soft 引用有关
-ea
-Dsun.io.useCanonCaches=false
-Djava.net.preferIPv4Stack=true
-XX:+HeapDumpOnOutOfMemoryError //内存溢出 dump 出快照
-XX:-OmitStackTraceInFastThrow  //抛出堆栈异常
整个的设置还是比较少的,经过多次测试,idea 的启动时间大概在 18s 左右,jstat 信息如下(只截取了最后一次测试的前 18s)
idea 的 Id 为 4440
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00 100.00  63.01   1.64  94.90  83.95      1    0.011     0    0.000    0.011
  0.00 100.00  61.75  16.45  95.42  83.95      3    0.067     0    0.000    0.067
100.00   0.00  28.84  22.12  94.73  83.02      4    0.106     0    0.000    0.106
100.00   0.00  68.97  22.12  94.73  83.02      4    0.106     0    0.000    0.106
  0.00 100.00  30.26  31.35  96.83  93.83      5    0.117     1    0.005    0.122
100.00   0.00   0.00  35.89  97.20  94.96      6    0.131     2    0.027    0.158
 90.56   0.00  10.54  38.82  97.53  95.00      8    0.141     2    0.027    0.168
100.00   0.00  68.57  46.48  97.53  95.04     10    0.165     2    0.027    0.192
  0.00  97.85  22.65  51.15  97.05  92.71     11    0.175     2    0.027    0.202
  0.00 100.00  73.74  60.28  97.18  94.92     13    0.225     2    0.027    0.252
  0.00 100.00  91.61  60.28  97.18  94.92     13    0.225     2    0.027    0.252
100.00   0.00   4.12  64.82  97.41  93.94     14    0.235     2    0.027    0.262
100.00   0.00  12.22  64.82  97.41  93.94     14    0.235     2    0.027    0.262
100.00   0.00  71.19  64.82  97.41  93.94     14    0.235     2    0.027    0.262
  0.00 100.00  43.52  78.72  96.97  92.43     17    0.315     3    0.029    0.343
  0.00 100.00   6.02  74.14  95.99  91.92     19    0.341     5    0.053    0.395
100.00   0.00  35.30  67.15  95.24  90.23     20    0.370     6    0.092    0.462
100.00   0.00  35.64  78.42  94.32  87.14     22    0.419     7    0.094    0.512
这 18s 中可以看出 YGC(也就是 minor gc)发生了 22 次,共耗时 0.419s,而 FGC 总共发生了 7 次,总耗时 0.094s,ygc 平均每次时间为 0.019s,而 fgc 每次为 0.013.
idea的一次jvm调优
image
从这张图中我们可以看出整个堆的大小先是平稳,后随着使用堆大小的增加逐步变大,而使用堆频繁 gc,gc 日志如下(前 23s,比较长,就直接放服务器了):GC 日志:
在 0.942s 的时候第一次出现了 Allocation Failure,分配内存失败,这会导致新生代触发 gc,这主要的原因是因为初始堆的大小设置成了 128m.好了,有了解决思路,第一步要做的就是先禁掉插件,哈哈,人生就是需要皮一下,idea 的 log 反应出插件的加载似乎是占用了很长一段时间,为了达到优化的效果,先把插件禁掉,在来对 gc 进行调优.

3.开工:

3.1 禁插件

禁掉插件的效果非常明显,测试了三次,时间分别为 9296,10034,10363,而最后一次 jstat 的信息如下:
idea 的 Id 为 6512
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00 100.00  91.18   1.63  94.81  83.95      2    0.028     0    0.000    0.028
  0.00 100.00  49.32  16.38  95.35  83.95      3    0.068     0    0.000    0.068
  0.00 100.00  50.65  16.38  95.35  83.95      3    0.068     0    0.000    0.068
100.00   0.00  29.37  21.33  94.72  85.34      4    0.089     0    0.000    0.089
100.00   0.00  49.98  21.33  94.72  85.34      4    0.089     0    0.000    0.089
100.00   0.00  90.62  21.33  94.72  85.34      4    0.089     1    0.009    0.099
  0.00 100.00  45.10  32.07  97.56  94.05      5    0.112     1    0.009    0.121
100.00   0.00  79.42  36.54  97.22  95.07      6    0.128     2    0.035    0.163
 90.65   0.00  92.93  39.97  97.63  95.09      9    0.169     2    0.035    0.204
100.00   0.00  62.49  47.90  97.69  95.15     10    0.195     2    0.035    0.230
10s 内发生了 10 次 ygc,2 次 fgc,其实说实话,这样的性能完全很好了,但是本着这是一篇调优的文章,有点参数还是要改改,看看效果,首先调整的就是整个堆的大小.

3.2 调整堆的大小

启动的时候频繁出现了 allocation failure,这是因为堆的初始大小过小,导致新生代的内存过小,所以,先设置了以下参数:
-Xms2048m
-Xmx2048m
-Xmn1600m
堆的大小不在动态调整,而是固定在了 2g,而新生代则直接分配了 1600m,这一次,启动时间为 7s,jstat 信息如下,前 12s:
S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00   0.00  16.00   0.00  17.24  19.25      0    0.000     0    0.000    0.000
  0.00   0.00  24.00   0.00  17.24  19.25      0    0.000     0    0.000    0.000
  0.00   0.00  32.00   0.00  17.24  19.25      0    0.000     0    0.000    0.000
  0.00   0.00  36.00   0.00  17.24  19.25      0    0.000     1    0.101    0.101
  0.00   0.00  46.00   0.00  17.24  19.25      0    0.000     1    0.101    0.101
  0.00   0.00  54.00   0.00  17.24  19.25      0    0.000     1    0.101    0.101
  0.00   0.00  66.00   0.00  17.24  19.25      0    0.000     1    0.101    0.101
  0.00   0.00  70.00   0.00  17.24  19.25      0    0.000     1    0.101    0.101
  0.00   0.00  78.00   0.00  17.24  19.25      0    0.000     2    0.101    0.101
  0.00   0.00  90.00   0.00  17.24  19.25      0    0.000     2    0.258    0.258
  0.00   0.00  96.00   0.00  17.24  19.25      0    0.000     2    0.258    0.258
  0.00  41.29  20.32   0.00  96.90  94.00      1    0.054     3    0.267    0.321
一直到 12s 的时候,新生代才出现首次 gc,gc 日志异常的少,前面一直是 cms 在做初始标记-并发标记等工作,是在处理老年代内存,前 7s 只出现了一次老年代的回收,这也说明了大内存对程序的运行帮助那是相当大.
4.246: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(458752K)] 471859K(1933312K), 0.1010486 secs] [Times: user=0.16 sys=0.00, real=0.10 secs] 
4.347: [CMS-concurrent-mark-start]
4.347: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
4.347: [CMS-concurrent-preclean-start]
4.349: [CMS-concurrent-preclean: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
4.349: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 9.362: [CMS-concurrent-abortable-preclean: 0.256/5.013 secs] [Times: user=13.81 sys=2.18, real=5.01 secs] 
9.362: [GC (CMS Final Remark) [YG occupancy: 1022364 K (1474560 K)]9.362: [Rescan (parallel) , 0.1397593 secs]9.502: [weak refs processing, 0.0000532 secs]9.502: [class unloading, 0.0081261 secs]9.510: [scrub symbol table, 0.0068646 secs]9.517: [scrub string table, 0.0007781 secs][1 CMS-remark: 0K(458752K)] 1022364K(1933312K), 0.1575112 secs] [Times: user=1.06 sys=0.00, real=0.16 secs] 
9.520: [CMS-concurrent-sweep-start]
9.520: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
9.520: [CMS-concurrent-reset-start]
9.523: [CMS-concurrent-reset: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
12.028: [GC (Allocation Failure) 12.028: [ParNew: 1310720K->67643K(1474560K), 0.0544422 secs] 1310720K->67643K(1933312K), 0.0545925 secs] [Times: user=0.51 sys=0.06, real=0.06 secs] 
12.083: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(458752K)] 106973K(1933312K), 0.0083509 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
12.091: [CMS-concurrent-mark-start]
12.091: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
12.091: [CMS-concurrent-preclean-start]
12.094: [CMS-concurrent-preclean: 0.003/0.003 secs] [Times: user=0.16 sys=0.01, real=0.00 secs] 
12.095: [CMS-concurrent-abortable-preclean-start]
16.748: [CMS-concurrent-abortable-preclean: 4.303/4.653 secs] [Times: user=32.20 sys=1.31, real=4.65 secs] 
16.748: [GC (CMS Final Remark) [YG occupancy: 737368 K (1474560 K)]16.748: [Rescan (parallel) , 0.0331714 secs]16.782: [weak refs processing, 0.0000574 secs]16.782: [class unloading, 0.0177730 secs]16.800: [scrub symbol table, 0.0229479 secs]16.823: [scrub string table, 0.0011784 secs][1 CMS-remark: 0K(458752K)] 737368K(1933312K), 0.0792557 secs] [Times: user=0.48 sys=0.00, real=0.08 secs] 
16.828: [CMS-concurrent-sweep-start]
16.828: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
16.828: [CMS-concurrent-reset-start]
16.829: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
21.380: [GC (Allocation Failure) 21.380: [ParNew: 1378363K->124879K(1474560K), 0.0719474 secs] 1378363K->124879K(1933312K), 0.0721093 secs] [Times: user=0.53 sys=0.08, real=0.07 secs] 
23.844: [GC (Allocation Failure) 23.845: [ParNew: 1435599K->78246K(1474560K), 0.2064758 secs] 1435599K->139746K(1933312K), 0.2066017 secs] [Times: user=1.06 sys=0.03, real=0.21 secs]

3.2 新生代调优

为了能够说明某些问题,我把参数又调回了初始参数,因为如果用上面的参数继续跑,基本没法调了,用原始参数对新生代进行调优,在此首先需要介绍下 parnew 收集器.

3.2.1 parnew 介绍

parnew 是作为新生代的垃圾回收器,当然也就采用了复制的算法,首先进行可达性分析,stop the world,然后再进行垃圾回收,将 eden 和 s0 的数据复制到 s1 当中去,它和 serial 的区别就在于 parnew 是多线的,然后关于 parnew 的文档,很可惜的是我在 oracle 官网上没有找到,全是介绍 g1,cms 和 parallel scavenge 的,但是官网给出的常见问题列表中有个问题比较有意思,地址, What is the Parallel Young Generation collector (-XX:+UseParNewGC)?官网的回复是 parNew 和 parallel 表现出来的东西很像,但是在内部实现上不一样,也就是说关于运行的机制大都差不多,毕竟都是并行的,但是在代码实现上差很多,还有一个不同点就是 parnew 是能和 cms 搭配使用的,而 parallel 不行.

3.2.2 调优参数

然后我就用了初始的 vm 参数中又加了几个参数,(jvm 的参数值介绍,官网地址)
第一个参数是-Xmn400m,分配给新生代 400m 的内存,另外固定住堆的大小为 750M,防止因堆的大小不够用而频繁 gc.
第二个是-XX:ParallelGCThreads,这个参数用于调整线程数,在我机器上默认是 13 个
idea的一次jvm调优
image
第三个是-XX:+ScavengeBeforeFullGC,minor gc 优先于 fgc,这样的好处就是往往会存在着新生代的对象持有老年代的引用(所以老年代的 gc,通常会伴随着 fgc),这样在 fgc 之前先清理掉一部分年轻代对象,会减少可达性分析的成本(在本次实验中,似乎没有展示出优势,fgc 次数比较少).
-Xms750m
-Xmx750m
-Xmn400m
-XX:ParallelGCThreads=20
-XX:+ScavengeBeforeFullGC

3.2.3 调优结果

这一次启动时间 9s,然后看下前 9s 的 jstat 信息:
S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00   0.00  28.00   0.00  17.24  19.25      0    0.000     0    0.000    0.000
  0.00   0.00  50.00   0.00  17.24  19.25      0    0.000     0    0.000    0.000
  0.00   0.00  52.00   0.00  17.24  19.25      0    0.000     0    0.000    0.000
  0.00   0.00  60.00   0.00  17.24  19.25      0    0.000     0    0.000    0.000
  0.00   0.00  64.00   0.00  17.24  19.25      0    0.000     0    0.000    0.000
  0.00   0.00  68.00   0.00  17.24  19.25      0    0.000     0    0.000    0.000
  0.00   0.00  76.00   0.00  17.24  19.25      0    0.000     0    0.000    0.000
  0.00   0.00  84.00   0.00  17.24  19.25      0    0.000     1    0.089    0.089
  0.00  66.86   5.20   0.00  96.69  92.35      1    0.025     1    0.089    0.115
  0.00  66.86  33.40   0.00  96.69  92.35      1    0.025     1    0.089    0.115
由上面结果可得知,9s 中共发生 1 次 ygc,这我觉得益于-Xms750m,-Xmx750m,-Xmn400m,将新生代的内存大小固定在了 400m,而减少了频繁的 gc.

3.2.4parnew gc 日志解读

然后这里顺便解读下 gc 的日志,关于 parnew 的:
9.399: [GC (Allocation Failure) 9.399: [ParNew: 327680K->27386K(368640K), 0.0253901 secs] 327680K->27386K(727040K), 0.0255930 secs] [Times: user=0.06 sys=0.06, real=0.03 secs]
9.399 代表项目启动时间,Allocation Failure 代表 gc 的原因,因为内存分配失败,ParNew 代表使用的 ParNew 算法,327680K->27386K(368640K)代表,新生代回收前->新生代回收后(整个新生代大小),327680K->27386K(727040K)代表,整个堆回收前->整个堆回收后(整个堆的大小),0.0255930s 代表此次垃圾回收的时间,[Times: user=0.06 sys=0.06, real=0.03 secs] 代表用户线程执行的时间,系统线程执行的时间,总共耗时,因为用户线程和系统线程并行执行,所以总耗时往往比 user+sys 时间要小.

3.3 老年代调优

3.3.1 cms 介绍

老年代主要用的是 cms 垃圾回收器,使用的是标记-清除算法,正如之前所说的,major gc 时因为存在老年代持有新生代的引用,所以会扫描整个堆而发生 fgc,另外,因为标记-清除算法会产生碎片,当老年代的内存足够分配一个对象,却因内存不连续时,这时往往也会发生 fgc,下面就简单介绍下 cms文章原文地址,CMS 官方介绍
cms 整个工作过程总共分为这几个步骤:
1.初始标记,这一阶段主要是通过 gc root 进行可达性分析,找到直接关联的对象,这是需要 stw.
2.并发标记,由第一阶段标记出的 gc 信息出发,追踪整个堆的对象信息,将所有活着的对象进行标记,因为是并发执行,所以没有太多的开销
3.并发预清理,此阶段主要是为了减少重标记的时间,标记新生代晋升的对象,新分配到老年代的对象以及在并发阶段被修改的对象,重新标记需要全量扫描整个堆大小(存在年轻代关联老年代的引用,所以需要扫描整个堆),但是如果在并发预清理之后,重标记之前做一次 minor gc(也就是类似于之前 ScavengeBeforeFullGC)的功能,则能降低重标记的时间.所以它有个子阶段.
    3.1 可中断的并发预清理,这一阶段主要的工作就是能够在 remark 阶段之前产生一次 minor gc,由两个参数控制 CMSScheduleRemarkEdenSizeThreshold,CMSScheduleRemarkEdenPenetration,默认值分别是 2M,50%,第一个代表当预清理完成之后,eden 区域大于这个值时,开启可中断的预清理,直到 eden 空间使用率达到 50%则中断,并发预清理期间执行时长 由 CMSMaxAbortablePrecleanTime = 5s 这个参数控制,意为并发预清理执行时长如果有 5s 了,那无论有无 minor gc,有无达到 50%,都停止并发预清理,进入重标记阶段,如果没有发生 minor gc,则可由 CMSScavengeBeforeRemark 参数,使并发预清理后,remark 之前强制执行一次 minor gc(这会造成重标记时间减短,但 minor gc 是需要 stw.所以使用还是要权衡)
4.重标记:会扫描新生代和老年代,日志中提现为 Rescan(多线程),这个因为前面做了很多工作,所以停顿时间较少
5.并发清理:并发清理无效对象
6.重置:cms 清除内部状态.为下次回收准备
整个流程大致如此,这其中有几个点需要说明下:
cms 是如何识别老年代对象引用的?这里需要介绍下 card table,card table 其实就是一个数组,每个位置存储的是一个 byte,cms 将老年代空间分为 512bytes 的快,card table 每个元素对应一个块,并发标记时.如果某个对象的引用发生了变化,就标记该对象所在的快为 dirty card,并发预清理会重新扫描该块.将该对象引用的对象标记为可达,如图所示:
初始状态:
idea的一次jvm调优
image
随后老年代引用发生变化,对应的块变为 dirty card:
idea的一次jvm调优
image
紧接着并发预清理,重新扫描修改后的引用,将其设置为可达:
idea的一次jvm调优
image
对于老年代持有新生代的引用,minor gc 是如何识别的?当有老年代引用新生代,对应的 card table 被标识为相应的中(就是 card table 里面 byte 的 8 位,约定好每一位的含义,以此来区分)所以 minor gc 通过扫描 card table 就可以识别老年代引用新生代.
何为浮动垃圾?当并发预清理之时,用户线程还在跑着,此时产生的垃圾只能下次回收,这一部分垃圾叫浮动垃圾.CMSInitiatingOccupancyFraction=n 这个参数控制着老年代使用的比例达到 n 时,才开始垃圾回收,设置过低会造成老年代频繁的垃圾回收,设置过高会导致无法分配内存空间,会出现 Concurrent Mode Failure,从而导致 cms 使用备份 serial old 算法清除老年代,从而产生更长的 stw.
何为动态检查机制?UseCMSInitiatingOccupancyOnly,cms 根据历史,预测老年代需要多久填满以及进行一次回收,老年代使用完之前,cms 会根据预测进行 gc.
cms 如何碎片整理?UseCMSCompactAtFullCollection 这个参数,就是进行 fgc 时,进行碎片整理,但是会造成 stw 时间变长,CMSFullGCsBeforeCompaction 这个参数就是用于设置多少次不压缩的 fgc,紧接着来一次碎片整理.
以上算是对 cms 的一个总结,cms 主要是为了解决两个问题,一个是减少 stw 时间,另一个是减少空间碎片,所以性能性对于其他的一些老年代垃圾回收还是比较优秀的.

3.3.2 cms 调优

不知道大家注意到没有,第一次 jstat 信息老年代的使用空间几乎没有怎么使用,但是依旧是发生了 fgc,用 jstat -gccause 可以看到 gc 原因,如下:
idea的一次jvm调优
image
我们可以看到出现了 Meradata GC threshold,jdk1.8 取消了永久代,而是用堆外内存 meta space 来存放这些信息,而 meta 回收的及其繁琐,尤其是类信息,需要判断整个堆当中是否还有再用的该类的实例,所以这一阶段触发了 fgc,而 idea 默认的 MetaspaceSize 大小为 21M,所以此次对于老年代的调优,先是调大 MetaspaceSize=128 大小.

3.3.3 调优结果

这一次的效果非常明显,一直到 35s 才第一次出现 fgc,这一次 idea 的启动时间还是 11s,但是从 gc 信息中,我还是比较满意的,这 11s 当中只出现了一次 ygc,没有出现 fgc.
idea的一次jvm调优
image

3.3.4 cms 日志解读

这边主要是以如何分析 cms 日志为主,截取了一段gc 日志:
4.407: [GC (CMS Initial Mark) [1 CMS-initial-mark: 19337K(87424K)] 50969K(126720K), 0.0049123 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
4.407s 时初始标记开始,19337k(87424K)->老年代已使用(老年代大小) 50969K(126720K)->整个堆已使用(整个堆大小),0.0049123s 共耗时多久,这一阶段是需要 stw 的.
4.412: [CMS-concurrent-mark-start]
4.425: [CMS-concurrent-mark: 0.012/0.012 secs] [Times: user=0.11 sys=0.01, real=0.01 secs]
这一阶段是并发标记阶段,4.412并发标记开始的标志,4.425开始标记,0.012/0.012因为是并发执行,表示 gc 线程时间/用户线程时间
4.425: [CMS-concurrent-preclean-start]
4.428: [CMS-concurrent-preclean: 0.003/0.004 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4.428: [CMS-concurrent-abortable-preclean-start]**
4.658: [GC (Allocation Failure) 4.659: [ParNew: 39296K->4352K(39296K), 0.0110973 secs] 58633K->31757K(126720K), 0.0112153 secs] [Times: user=0.22 sys=0.00, real=0.01 secs] 
5.741: [CMS-concurrent-abortable-preclean: 0.925/1.312 secs] [Times: user=4.96 sys=0.20, real=1.31 secs] 
这是并发预清理阶段,其中含有可中断的并发预清理,用以让年轻代发生 minor gc,里面的信息和上面的类似,不在赘述.
5.741: [GC (CMS Final Remark) [YG occupancy: 23403 K (39296 K)]5.741: [Rescan (parallel) , 0.0075331 secs]5.749: [weak refs processing, 0.0000928 secs]5.749: [class unloading, 0.0064751 secs]5.755: [scrub symbol table, 0.0063506 secs]5.762: [scrub string table, 0.0010179 secs][1 CMS-remark: 27405K(87424K)] 50808K(126720K), 0.0224856 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
这是重标记阶段,是需要 stw 的,扫描整个堆 YG occupancy: 23403 K (39296 K)表示年轻代当前使用的(年轻代总容量),rescan 是其子阶段,开始重新扫描,耗时0.0075331,weak refs processing,第二个子阶段,处理弱引用,class unloading,第三个子阶段,卸载未使用的类,scrub symbol table,第四份子阶段,处理符号表,最后一个子阶段 scrub string table,处理 string 池?(后面两个没太明白,找了下也没找到啥有用信息),CMS-remark: 27405K(87424K),在这个阶段之后老年代占有的内存大小和老年代的容量；
5.764: [CMS-concurrent-sweep-start]
5.787: [CMS-concurrent-sweep: 0.023/0.023 secs] [Times: user=0.09 sys=0.02, real=0.02 secs]
并发清理阶段
5.787: [CMS-concurrent-reset-start]
5.793: [CMS-concurrent-reset: 0.006/0.006 secs] [Times: user=0.08 sys=0.02, real=0.01 secs]
重置一些信息,以便下次垃圾回收.

4.最终的配置信息

-Xms750m
-Xmx750m
-Xmn400m
-XX:MetaspaceSize=128m
-XX:ParallelGCThreads=20
-XX:+ScavengeBeforeFullGC
-XX:ReservedCodeCacheSize=512m
-XX:+UseConcMarkSweepGC
-XX:SoftRefLRUPolicyMSPerMB=50
-XX:+PrintGCDetails
-Xloggc:d:\idea_gc.log
-XX:+PrintGCTimeStamps
-ea
-Dsun.io.useCanonCaches=false
-Djava.net.preferIPv4Stack=true
-XX:+HeapDumpOnOutOfMemoryError
-XX:-OmitStackTraceInFastThrow

5.总结

如果线上出现长时间停顿的事情,确定是因为 gc 的原因.首先要确定是 gc 的某个具体原因,比如新生代或者老年代过小,导致频繁 gc,再比如,就像本次 idea 调优一样,因为 meta 空间过小,导致发生 fgc,另外还有一个容易忽略的事情,就是 java nio 使用了直接内存,这部分内存不受垃圾回收控制,例如下载文件等操作出现长时间卡顿,应该考虑是不是直接内存分配过低的问题.一旦能够具体到某个原因,在去处理这些事情,效果就会很明确,当然 jvm 自带的分析工具是排查问题的主要手段,这些工具一定能够熟练.
露水湾 , 版权所有丨如未注明 , 均为原创丨本网站采用BY-NC-SA协议进行授权
转载请注明原文链接：idea的一次jvm调优
喜欢 (0)赏
[]
分享 (0)
关于作者：
作者主页
发表我的评论
取消评论

表情 贴图 加粗 删除线 居中 斜体 签到

Hi，您需要填写昵称和邮箱！

  • 昵称 (必填)
  • 邮箱 (必填)
  • 网址