idea分析java内存溢出,idea的一次jvm调优

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启动都做了哪些事情

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.

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个

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介绍