JVM实战调优

项目介绍

本项目是spring cloud zuul项目，程序内容就是做请求的签名加解密，然后对响应做加密。

项目问题

在测试环境，启动时-Xms1024m -Xmx1024m时偶发oom。调至2048才能稳定使用。生产环境(竟然没有指定堆内存大小，让运维看了下大致用了2G)。

jstat -gc介绍

S0C、S1C、S0U、S1U：Survivor 0/1区容量（Capacity）和使用量（Used）
EC、EU：Eden区容量和使用量
OC、OU：年老代容量和使用量
PC、PU：永久代容量和使用量
YGC、YGT：年轻代GC次数和GC耗时
FGC、FGCT：Full GC次数和Full GC耗时
GCT：GC总耗时

调优过程

因为本人认为该项目用不到1G甚至2G的内存，因此尽量将堆内存改小来优化，因此通过对比三种内存配置来观察。

1.调整测试环境堆内存为-Xms1024m -Xmx1024m(大小一致是为了防止抖动)。3小时内YGC次数很少(32次)，FGC出现大量(679次)。

image.png

2.调整为2G，3小时内YGC次数还是很少(20次)，FGC暴增(35852)。

image.png

3.调整为512M，YGC次数变多，FGC次数变少。

image.png

4.因为512M内存配置从GC次数来看为最优，因此以下步骤都从512M开始调优。

5.增加-XX:+PrintGCDetails -XX:+PrintGCTimeStamps,为了查看具体的GC过程。重新启动程序，对接口集中调用。
[GC (Allocation Failure) 131584K->3160K(502784K), 0.0114047 secs]
[GC (Allocation Failure) 134744K->3963K(502784K), 0.0074061 secs]
[GC (Allocation Failure) 135547K->3456K(502784K), 0.0042079 secs]
[GC (Allocation Failure) 135040K->4204K(502784K), 0.0053519 secs]
[GC (Allocation Failure) 135788K->6210K(502784K), 0.0121042 secs]
[GC (GCLocker Initiated GC) 137794K->6512K(516096K), 0.0172766 secs]
2020-08-06 16:19:17.178 HV000001: Hibernate Validator 5.3.6.Final
[GC (Allocation Failure) 166774K->7288K(517120K), 0.0223911 secs]
[GC (Allocation Failure) 167544K->7059K(517632K), 0.0067879 secs]
[GC (Metadata GC Threshold) 20293K->6828K(513024K), 0.0063631 secs]
[Full GC (Metadata GC Threshold) 6828K->6252K(513024K), 0.0851168 secs]
[GC (Allocation Failure) 167532K->7967K(517120K), 0.0055101 secs]

. ____ _ __ _ _
/\ / ' __ _ () __ __ _ \ \ \
( ( )__ | '_ | '| | ' / ` | \ \ \
\/ )| |)| | | | | || (| | ) ) ) )
' |____| .|| ||| |_, | / / / /
=========||==============|/=////

---

很明显能看到spring boot图案还没出来，就进行多次GC以及FGC。[Full GC (Metadata GC Threshold)，元数据区不够用，元数据和机器内存有关，jvm1.8版本的默认值是20M，于是增加启动配置-XX:MetaspaceSize=64M,重新启动。

6.第二次启动日志，启动时的元数据引起的FGC消失，但还是有大量的YGC。(调优策略起效)
2.586: [GC (Allocation Failure) [PSYoungGen: 131584K->3333K(153088K)] 131584K->3341K(502784K), 0.0292512 secs] [Times: user=0.05 sys=0.04, real=0.02 secs]
3.576: [GC (Allocation Failure) [PSYoungGen: 134917K->3955K(153088K)] 134925K->3971K(502784K), 0.0300654 secs] [Times: user=0.05 sys=0.07, real=0.03 secs]
4.344: [GC (Allocation Failure) [PSYoungGen: 135539K->3424K(153088K)] 135555K->3440K(502784K), 0.0095274 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
4.635: [GC (Allocation Failure) [PSYoungGen: 135008K->4202K(153088K)] 135024K->4290K(502784K), 0.0137263 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]
4.876: [GC (Allocation Failure) [PSYoungGen: 135786K->6173K(153088K)] 135874K->6269K(502784K), 0.0124761 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
5.168: [GC (Allocation Failure) [PSYoungGen: 137757K->6118K(166400K)] 137853K->6510K(516096K), 0.0123913 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

---

image.png

7分钟内发生了84次YGC,26次 FGC。还是很严重的FGC。

7.jmap -histo 19681 | -head 20(查看前20最多的对象)

image.png

此情况不明显看不出来。

8.jmap -dump:live,format=b,file=xxx.txt PID(导出堆信息，生产上尽量别使用，影响程序)

9.将堆文件导入mat

image.png

10.有4个problem,点开详情查看如下

image.png
image.png

11.三个都是httpOutPutBuffer特别大,怀疑是由于对网关的大量请求导致大量的buffer占用内存，但因为请求还未响应，导致大量FGC，并且FGC作用不大。最后定位到springboot配置中server.max-http-header-size = 81920000（78M）设置过大。该参数默认值是4KB。请求也不会有上传文件等，第一次测试调整直接用默认值。

12.重启，观察日志如下:
0.709: [GC (Allocation Failure) [PSYoungGen: 131584K->3144K(153088K)] 131584K->3152K(502784K), 0.0104742 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]
1.175: [GC (Allocation Failure) [PSYoungGen: 134728K->3955K(153088K)] 134736K->3971K(502784K), 0.0088299 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]
1.433: [GC (Allocation Failure) [PSYoungGen: 135539K->3392K(153088K)] 135555K->3480K(502784K), 0.0056318 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
1.664: [GC (Allocation Failure) [PSYoungGen: 134976K->4253K(153088K)] 135064K->4349K(502784K), 0.0059212 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
1.879: [GC (Allocation Failure) [PSYoungGen: 135837K->6717K(153088K)] 135933K->6821K(502784K), 0.0127180 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2.066: [GC (Allocation Failure) [PSYoungGen: 138301K->5849K(166912K)] 138405K->5961K(516608K), 0.0148195 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
2020-08-07 15:59:14.183 HV000001: Hibernate Validator 5.3.6.Final
2.297: [GC (Allocation Failure) [PSYoungGen: 166105K->4437K(167424K)] 166217K->6984K(517120K), 0.0338361 secs] [Times: user=0.12 sys=0.03, real=0.03 secs]
2.519: [GC (Allocation Failure) [PSYoungGen: 164693K->3456K(167936K)] 167240K->6760K(517632K), 0.0054449 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
2.902: [GC (Allocation Failure) [PSYoungGen: 164736K->3046K(167936K)] 168040K->7680K(517632K), 0.0109321 secs] [Times: user=0.04 sys=0.01, real=0.01 secs]
2020-08-07 15:51:13.557 HV000001: Hibernate Validator 5.3.6.Final

---

启动时还是存在很多YGC。怀疑是内置tomcat启动或者框架本身导致的原因。有待考证。

13.8分钟后，jstat -gc pid 1000

image.png

8分钟内没有发生一次FGC，效果显著。