JVM性能调优实战
环境准备
linux环境
测试环境需要1台Linux支持
IP | 开放端口 | 内存 | 说明 |
---|---|---|---|
192.168.xx.xx | 8080 | 4GB | 运行web项目 |
jdk安装
jdk使用的版本为jdk8,需要在Linux服务器中安装jdk8
以下全部操作均在
root
下执行
下载jdk8
在JDK下载页面下载JDK,如下:
解压jdk压缩包
1 | tar -zxvf jdk-8u251-linux-x64.tar.gz #解压jdk压缩包 |
生成软连接配置环境变量
1 | ln -s /usr/local/lib/jdk1.8.0_251/ /usr/local/jdk #使用/usr/local/jdk指向jdk的存放路径 |
文件末尾添加如下内容:
1 | export JAVA_HOME=/usr/local/jdk |
激活环境变量配置
1 | source /etc/profile #激活环境变量 |
验证jdk安装成功
1 | java -version #查看java版本 |
安装tomcat
1 | cd /use/local/tomcat |
对tomcat进行优化配置
修改server.xml
1 | vim server.xml |
禁用AJP服务
禁用AJP服务,一般是使用Nginx+tomcat的架构,所以用不着AJP协议,所以把AJP连接器禁用。
1 | <!-- <Connector port="8009" protocol="AJP/1.3" redirectPort="8443" />--> |
设置线程池
设置线程池,并且调整最大并发线程数
1 | <!--将注释打开--> |
使用NIO2
设置tomcat运行模式为nio2,tomcat的运行模式有3种:bio、nio、apr,其中nio2是nio的升级版,在
tomcat8中才支持的,建议采用nio2模式
1 | <Connector executor="tomcatThreadPool" port="8080" protocol="org.apache.coyote.http11.Http11Nio2Protocol" connectionTimeout="20000" redirectPort="8443" /> |
启动Tomcat测试
1 | cd /usr/local/test/apache-tomcat-8.5.34/bin |
打开浏览器进行测试访问
如果访问到首页 就完成了 tomcat优化
部署web项目
将需要测试的war包上传到linux服务器,然后在tomcat上面部署
1 | cd /usr/local/apache-tomcat-8.5.34/webapps |
压力测试
配置TomcatGC参数
配置默认GC 参数,为了效果故意将jvm内存调整小 -Xms64m -Xmx128m
并配置打印GC日志信息
这里使用jdk1.8的默认垃圾回收器
jdk1.8 默认垃圾收集器Parallel Scavenge(新生代)+Parallel Old(老年代)
编辑catalina.sh
tomcat启动执行的是tomcat/bin/startup.sh,startup.sh执行的是catalina.sh,所以要在catalina.sh中进行设置
在catalina.sh 的开头加入如下配置
1 | cd /usr/local/apache-tomcat-8.5.34/bin |
参数说明
- -XX:+PrintGC 输出GC日志
- -XX:+PrintGCDetails 输出GC的详细日志
- -XX:+PrintGCTimeStamps 输出GC的时间戳(以基准时间的形式)
- -XX:+PrintGCDateStamps 输出GC的时间戳(以日期的形式,如 2013-05-04T21:53:59.234+0800)
- -XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
- -Xloggc:../logs/gc.log 日志文件的输出路径
启动tomcat
1 | cd /usr/local/apache-tomcat-8.5.34/bin |
查看日志
查看catalina.out的日志检查修改JVM参数是否生效
1 | cd /usr/local/apache-tomcat-8.5.34/logs |
出现如下参数说明我们的修改已经生效
jmeter使用
jmeter 使用参考 jmeter 使用
进行压测
创建测试用例
配置线程组
配置线程组使用200的并发进行测试,每个线程执行100次,总数为20000次请求
查看tomcat日志
压测后查看tomcat是否有报错日志
出现GC overhead limit exceeded 错误
GC overhead limt exceed检查是Hotspot VM 1.6定义的一个策略,通过统计GC时间来预测是否要OOM了,提前抛出异常,防止OOM发生。Sun 官方对此的定义是:“并行/并发回收器在GC回收时间过长时会抛出OutOfMemroyError。过长的定义是,超过98%的时间用来做GC并且回收了不到2%的堆内存。用来避免内存过小造成应用不能正常工作。
因为我们故意将堆内存调小 所以基本上可以确认是堆内存过小导致垃圾回收频繁
解决办法
- 增加heap堆内存。
- 增加对内存后错误依旧,获取heap内存快照,使用Eclipse MAT工具,找出内存泄露发生的原因并进行修复。
- 优化代码以使用更少的内存或重用对象,而不是创建新的对象,从而减少垃圾收集器运行的次数。如果代码中创建了许多临时对象(例如在循环中),应该尝试重用它们。
- 升级JDK到1.8,最起码也是1.7,并使用G1GC垃圾回收算法。
- 除了使用命令-xms1g -xmx2g设置堆内存之外,尝试在启动脚本中加入配置:
查看压测结果
查看关键指标
平均响应时间:6418ms
吞吐量:24.7/sec (每秒的请求量)
错误率:1.78%
GC日志解析
GCeasy介绍
使用
上面我们介绍了各个垃圾收集器的GC日志,我们打开GCeasy的官网,上传我们的GC日志(我这里用的Parallel收集器),点击Analyze进行分析即可得到报告,得到的报告可以进行下载。由于报告内容比较多,我就捡几个主要的截个图简单说明一下,其他的可以自己看一下,而且可以自己试试不同的垃圾收集器的GC日志的分析报告有什么区别。
Problem detected
出现如下界面说明已经检测到了问题,这里面说是内存问题,但是详细信息需要收费
大概意思是:我们的机器学习算法已经识别出内存问题,查看问题和建议的解决方案需要成为我们的付费用户。
JVM memory size
这一部分分别使用了表格和图形界面来展示了JVM堆内存大小。如图所示:
左侧分别展示了年轻代的内存分配分配空间大小(Allocated)和年轻代内存分配空间大小的最大峰值(Peek),然后依次是老年代(Old Generation)、元数据区(Meta Space)、堆区和非堆区(Young + Old + Meta Space)总大小。值得注意的是,每一代的最大内存利用率都会超过分配的大小,但是图中的内存分配利用率已经超过了峰值内存了。
在jvm内存统计中可以看出,年轻代与老年代在高峰时,基本将可用空间都占满了,说明内存空间不足,需要调整内存大小。
Key Performance Indicators
这一部分是关键的性能指标,如图:
关键指标中,吞吐量为95.042%,gc平均停顿时间为165 ms,最大停顿时间为510 ms。
可以看出,在初始状态时,吞吐量并不高,最大停顿时间较长,平均停顿时间也比较长。
参数描述
- Throughput:表示的是吞吐量
- Latency:表示响应时间
- Avg Pause GC Time: 平均GC时间
- Max Pause GC TIme :最大GC时间
Interactive Graphs
这一部分是GC的各种状态的一个图表
Heap After GC
第一部分是Heap after GC,GC后堆的内存图,堆是用来存储对象的,从图中可以看出,随着GC的进行,垃圾回收器把对象都回收掉了,因此堆的大小逐渐增大。
在图表中可以看出,gc之后堆内存的使用基本是在100m左右,红色的三角是Full GC,我们看到有大量的Full GC,也证明了内存不足频繁的Full GC。
Heap before GC
第二部分是Heap before GC,这是GC前堆的使用率,可以看出随着程序的运行,堆使用率越来越高,堆被对象占用的内存越来越大。
在图表中可以看出,gc之前的堆内存的使用在高峰时,将占80m~100m之间。
GC Duration Time
第三部分是GC Duration Time,就是GC持续时间。从图中可以看到,发生Full GC的时间持续的比较端,而Young GC持续的时间比较长。图中横坐标表示GC发生的时间段,纵坐标表示的是GC持续时间。
在gc持续时间统计中,可以看出full gc的时间要远高于younggc的时间,在调优时应当尽量的减少full gc。
Reclaimed Bytes
第四部分表示的是GC回收掉的垃圾对象的内存大小。
从图中可以看出,Full GC仅仅回收不到1M的对象,而Young GC则回收的对象比较多,大部分发生在10m~30m左右。
回收最多的次是发生在full gc可以推断此次是内存即将耗尽,发生了fullgc,释放了大量的内存空间,这也是在前面年轻代对象有部分进入到老年代,在此次fullgc时被清理了。
后面Full GC很频繁并且基本没有什么回收,基本可以确定频繁GC 导致 stw 没有请求能够进来导致回收不了。
Young GC
第五部分表示的是Young Gen,年轻代的内存分配情况。对象都是朝生夕死,年轻代存放的就是刚刚产生的对象,每进行一次GC,都会GC掉很多垃圾对象,剩下的就是右GC Root关联的对象,这些对象会年龄会逐渐增加,达到了一定阈值就会晋升为老年代的对象。
可以看到before GC表示的图线随着时间的进行逐渐增大,也就是年轻代中对象越来越多,而GC事件发生后,年轻代中对象就会减少,也就是after GC图线表示的内存变化趋势。
从年轻代的gc情况来看,gc之前与gc之后差较大,说明垃圾对象在年轻代被清理的比较多,就是说临时性的对象居多。
Old Gen
第六部分是Old Gen,表示的是老年代的内存分配情况。细心的读者会发现,为啥一开始before GC的内存大小比after GC的内存分配要少呢?这里得先知道老年代存放的都是年龄大的对象,意思就是经过了多次GC都没有被GC掉的对象,就会晋升为老年代的对象。所以这就解释了为啥after GC内存要比before GC内存要大,因为每次GC过后,都会有年轻代的对象晋升为老年代对象。
从老年代的gc情况来看,gc之前与之后的差并不大,说明老年代的垃圾对象并不是很多。
Meta Space
第七部分是Meta Space,表示的是元数据区内存分配情况。
Meta Space空间充足,基本没有变化,占用空间40m左右。
A&P
第八部分表示的是堆内存分配和晋升情况。
从该图中看出,晋升到老年代的对象与可以分配对象相比,非常的少,也说明了上面我们看到的,对象主要集中在young区。
GC Statistics
GC 分析数据
左图:表示的是堆内存中Minor GC和Full GC回收垃圾对象的内存。
中图:总计GC时间,包括Minor GC和Full GC,时间单位为ms。
右图:GC平均时间,包括了Minor GC和Full GC。
接下来则分别表示的是总GC统计,MinorGC的统计,FullGC的统计,GC暂停程序的统计。
分析结果
在GC统计中,可以看出:
- Minor GC清理掉的垃圾对象合计15.28gb,说明产生的临时对象非常的多
- Minor GC的执行间隔为73ms,说明发生gc的行为是比较频繁的
- Full GC发生了846次,非常频繁
- Full GC的平均持续时间为171ms,时间较长
- GC的暂停次数为690次,暂停次数将影响到服务的响应时间
Object Stats
接下来是对象统计,Total Created Bytes表示的是创建的字节总数,Total promoted bytes表示的是晋升的字节总数,Avg creation rate表示的是平均创建字节率,Avg promotion rate表示平均的晋升率。
在对象的统计中,可以看出对象的平均生成率:81.15m/s,平均的晋升率:5.25mb/s。
Memory Leak
由于记录的程序没有内存泄漏,所以这里就没有内存泄漏的日志信息。此处可以诊断8种OOM中的5种(Java堆内存溢出,超出GC开销限制,请求数组大小超过JVM限制,Permgen空间,元空间)。
GC Causes
CG所花费的时间,也就是停顿线程的时间。
在GC原因统计中可以看出,大部分发生gc的原因都为分配失败,也就说内存不足导致;
需要说明的是虽然发生了4次Metadata GC,并不是Metaspace不足导致,前面我们看到Metaspace空间充足,而是该gc发生在最开始时间,说明初始的Metaspace不足,导致了Metaspace扩容,并发生了GC,可以适当调整Metaspace初始大小以减少Metadata GC次数。
GC 调优
调整内存
根据分析得出 主要是 内存不足导致的,并行临时对象居多,我们先进行内存调整,将内jvm堆内存调整为2G,并且使用默认的垃圾收集器
JVM 配置
1 | -Xms2048m -Xmx2048m -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:../logs/gc.log |
压测结果
查看关键指标变化
平均响应时间:6418ms -> 850ms
吞吐量:24.7/sec -> 217.5/sec(每秒的请求量)
错误率:1.78% -> 0.00%
我们发现直接增加内存 性能提升还是很可观的
分析GC日志
上传GC日志继续分析
JVM memory size
我们发现新生代和老年代基本上都有剩余空间,内存应该没有问题
Key Performance Indicators
GC 的 停顿时间以及最大停顿时间有所增加是因为 内存增加的缘故,吞吐量还是不高在82左右
GC Statistics
和原来相比 Minor GC以及Full GC 的次数都有大幅度降低,并且Full GC由原来的864 降低到2次,Full GC回收的数据也很少,说明大量的垃圾在新生代已经被回收了,总的停顿时间由2分钟降低到20秒,优化很不错。
增加年轻代大小
根据方才的优化发现老年代还是晋升了很多垃圾,并且老年代垃圾相对还是比较多,分析得出大部分都是临时对象,将年轻代增加到1G
JVM 配置
1 | -Xms2048m -Xmx2048m -XX:NewSize=1024m -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:../logs/gc.log |
压测结果
查看关键指标变化
平均响应时间:850ms -> 638ms
吞吐量: 217.5/sec -> 249.3/sec(每秒的请求量)
错误率:0.00%
我们发现增加年轻代后,响应时间和吞吐量有少许提升
分析GC日志
上传GC日志继续分析
JVM memory size
我们发现新生代垃圾比较多,老年代基本上很少了,说明大部分垃圾在年轻代已经被清理了
Key Performance Indicators
GC 的 停顿时间以及最大停顿时间降低很多,说明大部分在新生代被清理了,老年代没有过多的清理,吞吐量也有了大幅度提升,到了 95左右
GC Statistics
和原来相比Minor GC 的平均响应时间有所降低,停顿时间也有大幅度降低
使用G1 垃圾收集器
选择性能更优的垃圾收集器也是调优的手段之一,在jdk8中,使用率最高的当属G1收集器了,下面我们就尝试切换成G1收集器,来看下它的表现。
JVM 配置
这里XX:MaxGCPauseMillis 是期望GC停顿时间,我们上面压测最好的结果实在160ms左右,这里我们设置为150ms
1 | -XX:+UseG1GC -XX:MaxGCPauseMillis=150 -Xms2048m -Xmx2048m -XX:NewSize=1024m -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:../logs/gc.log |
压测结果
查看关键指标变化
平均响应时间:638ms -> 542ms
吞吐量: 249.3/sec -> 331.8/sec(每秒的请求量)
错误率:0.00%
我们发现使用G1垃圾收集器后,响应时间和吞吐量有了大幅度提升
分析GC日志
上传GC日志继续分析
JVM memory size
我们发现新生代垃圾比较多,老年代基本上很少了,说明大部分垃圾在年轻代已经被清理了
Key Performance Indicators
GC 的 停顿时间有所降低,最大停顿时间有所增加,G1在GC停顿时间上优化不多,但是在吞吐量上有所增加,提升到了97以上
Phases Statistics
G1 GC Time
我们G1 停顿时间很少平均停顿时间56.2ms 最大停顿时间5s,总结可以得出G1是一个更加优秀的垃圾收集器。