对项目的一次JVM调优

初始状态，即不加任何JVM参数启动项目时的JVM状态如下

GC信息

image.png

堆信息

image.png

Metaspace信息

image.png

该图使用了JVisualVM中的VisualGC插件统计获得，下载地址ViusalGC For 8U40

从GC信息图中可以看出，

  • 启动过程中一共发生24次GC，总计消耗704.142ms
  • 最后一次GC发生的原因是Metaspace Threshold
  • 发生了20次新生代GC，总计消耗269.828ms
  • 发生了4次老年代GC，总计消耗434.296ms
  • 类加载19290个，类卸载4个，总计消耗27.908s
  • 截止启动完成，Eden区总内存大小为1.246GB，已使用128.720MB
  • 截止启动完成，S0总大小为39MB，S1总大小为39M，S0，S1已经使用0MB
  • 截止启动完成，Old区总大小为257MB，已使用63.362MB
  • 截止启动完成，Metaspace总大小为96MB，已使用90.905MB

从堆信息图中可以看出，

  • 堆的大小一直在动态的改变
  • 已使用的堆内存一直是低于堆的总内存的

从Metaspace信息图中可以看出，

  • Metaspace的大小也一直在改变
  • 并且已使用内存和总内存差距很小

启动环境

系统

Windows7，64bit，内存大小16G，CPU i5-6500 3.2GHz

JDK版本

8u92

Hotspot模式

Mixed Mode

进程启动参数

jar -Dspring.config.location=D:dev\workspace\application.yml -javaagent:D:dev\workspace\jar\skywalking-agent\skywalking-agent.jar=agent.service_name=* -Dskywalking.collector.backend_service=170.xxx.xxx.xxx:11800,170.xxx.xxx.xxx:11800

这里添加了一个skywalking

进程JVM参数

因为没有手动指定，这里为默认参数

使用jinfo [pid]命令查看JVM参数

VM Flags:
Non-default VM flags: 
-XX:-BytecodeVerificationLocal 
-XX:-BytecodeVerificationRemote
# 最大并行编译数
-XX:CICompilerCount=3
# 初始堆大小，256MB 
-XX:InitialHeapSize=268435456 
# 最大堆大小，4068MB
-XX:MaxHeapSize=4265607168 
# 新生代最大大小，1356MB
-XX:MaxNewSize=1421869056 
-XX:MinHeapDeltaBytes=524288 
# 新生代初始大小，85MB
-XX:NewSize=89128960
# 老年代初始大小，171MB 
-XX:OldSize=179306496 
-XX:+PrintGC 
-XX:+PrintGCTimeStamps 
-XX:TieredStopAtLevel=1
-XX:+UseCompressedClassPointers 
-XX:+UseCompressedOops 
-XX:+UseFastUnorderedTimeStamps 
-XX:-UseLargePagesIndividualAllocation 
# 使用Parallel Scanvenge垃圾回收器
-XX:+UseParallelGC

根据以上信息可以知道，当进程启动完毕时，堆的大小，包括新生代的大小，老年代的大小等都是在动态改变的，并且在启动过程中发生了3次老年代GC，而正常情况下，老年代GC最好是一天一次或者几天一次，这次优化的内容就是让进程在启动时不会触发老年代的GC

具体优化的项

  • 堆大小动态改变问题
  • GC次数尽可能减少，不要触发老年代GC

添加GC日志相关参数

如下

  • -XX:+PrintGCDetails
  • -XX:+PrintGCTimeStamps
  • -Xloggc:path/gc.log

重新启动进程后GC日志如下

Java HotSpot(TM) 64-Bit Server VM (25.92-b14) for windows-amd64 JRE (1.8.0_92-b14), built on Mar 31 2016 21:03:04 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16658592k(7982136k free), swap 33315340k(23762504k free)
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=266537472 -XX:+ManagementServer -XX:MaxHeapSize=4264599552 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
1.746: [GC (Allocation Failure) [PSYoungGen: 65536K->3781K(76288K)] 65536K->3781K(251392K), 0.0263583 secs] [Times: user=0.06 sys=0.00, real=0.03 secs] 
2.416: [GC (Allocation Failure) [PSYoungGen: 69317K->4401K(70144K)] 69317K->4401K(245248K), 0.0028175 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
3.551: [GC (Allocation Failure) [PSYoungGen: 69937K->5916K(71680K)] 69937K->5916K(246784K), 0.0046200 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
4.233: [GC (Allocation Failure) [PSYoungGen: 71452K->6514K(72192K)] 71452K->6530K(247296K), 0.0054890 secs] [Times: user=0.05 sys=0.02, real=0.00 secs] 
4.365: [GC (Allocation Failure) [PSYoungGen: 72036K->10095K(127488K)] 72052K->10119K(302592K), 0.0091533 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
4.614: [GC (Allocation Failure) [PSYoungGen: 126831K->10730K(138752K)] 126855K->13165K(313856K), 0.0098991 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
4.891: [GC (Allocation Failure) [PSYoungGen: 138730K->12348K(141824K)] 141165K->17277K(316928K), 0.0089637 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
5.117: [GC (Metadata GC Threshold) [PSYoungGen: 115954K->8216K(270336K)] 120883K->16417K(445440K), 0.0098273 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
5.127: [Full GC (Metadata GC Threshold) [PSYoungGen: 8216K->0K(270336K)] [ParOldGen: 8201K->13571K(96256K)] 16417K->13571K(366592K), [Metaspace: 20791K->20791K(1067008K)], 0.0424281 secs] [Times: user=0.08 sys=0.00, real=0.04 secs] 
5.829: [GC (Allocation Failure) [PSYoungGen: 256000K->6607K(270848K)] 269571K->20186K(367104K), 0.0056147 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
6.681: [GC (Allocation Failure) [PSYoungGen: 262607K->6482K(373248K)] 276186K->20070K(469504K), 0.0052574 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
7.509: [GC (Metadata GC Threshold) [PSYoungGen: 322398K->12671K(379904K)] 335985K->28252K(476160K), 0.0090304 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
7.518: [Full GC (Metadata GC Threshold) [PSYoungGen: 12671K->0K(379904K)] [ParOldGen: 15581K->24972K(139776K)] 28252K->24972K(519680K), [Metaspace: 34630K->34629K(1079296K)], 0.0378021 secs] [Times: user=0.14 sys=0.00, real=0.04 secs] 
9.737: [GC (Allocation Failure) [PSYoungGen: 366080K->12442K(499200K)] 391052K->37422K(638976K), 0.0083751 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
13.380: [GC (Allocation Failure) [PSYoungGen: 498842K->15849K(529920K)] 523822K->49693K(669696K), 0.0165356 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
15.015: [GC (Allocation Failure) [PSYoungGen: 529897K->16199K(652800K)] 563741K->59222K(792576K), 0.0162510 secs] [Times: user=0.00 sys=0.02, real=0.02 secs] 
17.292: [GC (Metadata GC Threshold) [PSYoungGen: 613203K->19529K(653824K)] 656226K->67180K(793600K), 0.0162558 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
17.308: [Full GC (Metadata GC Threshold) [PSYoungGen: 19529K->0K(653824K)] [ParOldGen: 47650K->48004K(204800K)] 67180K->48004K(858624K), [Metaspace: 57161K->57161K(1099776K)], 0.1291465 secs] [Times: user=0.36 sys=0.00, real=0.13 secs]
19.901: [GC (Allocation Failure) [PSYoungGen: 631296K->24549K(820736K)] 679300K->78123K(1025536K), 0.0181882 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
24.279: [GC (Allocation Failure) [PSYoungGen: 820709K->25280K(826368K)] 874283K->86207K(1031168K), 0.0233381 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
28.335: [GC (Allocation Failure) [PSYoungGen: 821440K->32739K(952320K)] 882367K->96902K(1157120K), 0.0257861 secs] [Times: user=0.06 sys=0.00, real=0.03 secs] 
36.811: [GC (Metadata GC Threshold) [PSYoungGen: 865510K->23365K(958464K)] 929673K->110742K(1163264K), 0.0343379 secs] [Times: user=0.06 sys=0.02, real=0.04 secs] 
36.845: [Full GC (Metadata GC Threshold) [PSYoungGen: 23365K->0K(958464K)] [ParOldGen: 87377K->78724K(299008K)] 110742K->78724K(1257472K), [Metaspace: 93225K->93225K(1134592K)], 0.1750465 secs] [Times: user=0.50 sys=0.00, real=0.17 secs]
Heap
 PSYoungGen      total 958464K, used 246307K [0x000000076b400000, 0x00000007b0380000, 0x00000007c0000000)
  eden space 919552K, 26% used [0x000000076b400000,0x000000077a488d50,0x00000007a3600000)
  from space 38912K, 0% used [0x00000007a3600000,0x00000007a3600000,0x00000007a5c00000)
  to   space 38912K, 0% used [0x00000007add80000,0x00000007add80000,0x00000007b0380000)
 ParOldGen       total 299008K, used 78724K [0x00000006c1c00000, 0x00000006d4000000, 0x000000076b400000)
  object space 299008K, 26% used [0x00000006c1c00000,0x00000006c68e1110,0x00000006d4000000)
 Metaspace       used 94605K, capacity 99668K, committed 99968K, reserved 1134592K
  class space    used 13003K, capacity 13887K, committed 13952K, reserved 1048576K

来看几条GC日志，首先是新生代GC

1.746: [GC (Allocation Failure) [PSYoungGen: 65536K->3781K(76288K)] 65536K->3781K(251392K), 0.0263583 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
  • 1.746：进程启动的时间，从启动开始计时，单位(秒)
  • GC (Allocation Failure)：表示发生GC了，原因是Allocation Failure，就是分配内存失败，也就是内存不足
  • PSYoungGen：新生代
  • 65536K->3781K(76288K)：回收前新生代使用内存为65536KB，回收后为3781KB，新生代总大小为76288KB
  • 65536K->3781K(251392K)：整个堆内存在回收前使用内存为65536KB，回收后为3781KB，堆内存大小为251392KB
  • 0.0263583 secs：本次GC消耗时间为0.0263583 秒
  • Times: user=0.06 sys=0.00, real=0.03 secs：GC导致暂停时间，用户态花费时间(user)为0.06秒，内核态花费时间(sys)为0秒，花费总时间(real)为0.03秒，这里real < user + sys的原因是，本次GC使用了多线程，它统计了所有CPU上的时间

接着是Full GC

5.127: [Full GC (Metadata GC Threshold) [PSYoungGen: 8216K->0K(270336K)] [ParOldGen: 8201K->13571K(96256K)] 16417K->13571K(366592K), [Metaspace: 20791K->20791K(1067008K)], 0.0424281 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]
  • Full GC(Metadata GC Threshold)：表示发生了Full GC，原因是Metadata GC Threshold,Metaspace内存不足导致的Full GC
  • PSYoungGen: 8216K->0K(270336K)：新生代回收前内存占用8216KB，回收后占用0KB，总内存270336KB
  • ParOldGen: 8201K->13571K(96256K)：老年代回收前内存占用8201KB，回收后占用13571KB，总内存96256KB
  • 16417K->13571K(366592K)：整个堆内存回收前占用16417KB，回收后占用13571KB，堆总大小为366592KB
  • Metaspace: 20791K->20791K(1067008K)：元空间回收前20791KB，回收后20791KB，总内存大小为1067008KB
  • 0.0424281 secs：本次Full GC消耗0.0424281 秒
  • Times: user=0.08 sys=0.00, real=0.04 secs：GC花费时间，用户态0.08秒，内核态0秒，总花费0.04秒

关于PSYoungGen和ParOldGen，这个名字会根据使用的垃圾回收器不同而改变，这里新生代使用的垃圾回收器是Parallel Scanvenge，老年代使用的垃圾回收器是Parallel Old

通过GC日志可以很清楚的看到，每次发生GC，堆的大小都在被调整，因此我们第一个要优化的点就是固定下堆的大小，不允许堆动态扩展

添加JVM参数

-Xms2048m -Xmx2048m

为什么设置为2048m，通过GC信息图可以看到，最终进程启动完毕后，总的堆大小被扩展到了1.5G左右

再次启动，然后观察VisualGC

image.png

发现GC次数没有显著的减少

继续尝试，这次我们固定下新生代的大小，并且固定Eden:Survivor的比例为8

-Xmn=1229m -XX:SurvivorRatio=8

再次启动后观察VisualGC

image.png

GC日志

Java HotSpot(TM) 64-Bit Server VM (25.92-b14) for windows-amd64 JRE (1.8.0_92-b14), built on Mar 31 2016 21:03:04 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16658592k(9547936k free), swap 33315340k(25271864k free)
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=2147483648 -XX:+ManagementServer -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=1288699904 -XX:NewSize=1288699904 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
5.193: [GC (GCLocker Initiated GC) [PSYoungGen: 826270K->25756K(1133056K)] 826270K->25772K(1971712K), 0.0228188 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
5.237: [GC (Metadata GC Threshold) [PSYoungGen: 73924K->11877K(1133056K)] 73940K->11901K(1971712K), 0.0079811 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
5.245: [Full GC (Metadata GC Threshold) [PSYoungGen: 11877K->0K(1133056K)] [ParOldGen: 24K->11711K(838656K)] 11901K->11711K(1971712K), [Metaspace: 21071K->21071K(1067008K)], 0.0401128 secs] [Times: user=0.13 sys=0.00, real=0.04 secs] 
7.583: [GC (Metadata GC Threshold) [PSYoungGen: 900988K->23807K(1133056K)] 912700K->35591K(1971712K), 0.0117518 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
7.595: [Full GC (Metadata GC Threshold) [PSYoungGen: 23807K->0K(1133056K)] [ParOldGen: 11783K->33588K(838656K)] 35591K->33588K(1971712K), [Metaspace: 35020K->35019K(1081344K)], 0.0361481 secs] [Times: user=0.08 sys=0.00, real=0.04 secs] 
13.819: [GC (Allocation Failure) [PSYoungGen: 1007616K->36913K(1133056K)] 1041204K->70509K(1971712K), 0.0216178 secs] [Times: user=0.05 sys=0.02, real=0.02 secs]
17.156: [GC (Allocation Failure) [PSYoungGen: 1044529K->43073K(1133056K)] 1078125K->76677K(1971712K), 0.0289869 secs] [Times: user=0.06 sys=0.00, real=0.03 secs] 
17.508: [GC (Metadata GC Threshold) [PSYoungGen: 127853K->23063K(1209856K)] 161457K->56675K(2048512K), 0.0187055 secs] [Times: user=0.03 sys=0.02, real=0.02 secs] 
17.527: [Full GC (Metadata GC Threshold) [PSYoungGen: 23063K->0K(1209856K)] [ParOldGen: 33612K->36437K(838656K)] 56675K->36437K(2048512K), [Metaspace: 57921K->57921K(1101824K)], 0.1243212 secs] [Times: user=0.36 sys=0.00, real=0.12 secs] 
23.128: [GC (Allocation Failure) [PSYoungGen: 1158656K->46861K(1205760K)] 1195093K->83306K(2044416K), 0.0279780 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
28.419: [GC (Allocation Failure) [PSYoungGen: 1205517K->47012K(1191424K)] 1241962K->83466K(2030080K), 0.0370902 secs] [Times: user=0.09 sys=0.00, real=0.04 secs] 
Heap
 PSYoungGen      total 1191424K, used 1005019K [0x00000000b3300000, 0x0000000100000000, 0x0000000100000000)
  eden space 1138688K, 84% used [0x00000000b3300000,0x00000000eda8db60,0x00000000f8b00000)
  from space 52736K, 89% used [0x00000000fcc80000,0x00000000ffa69200,0x0000000100000000)
  to   space 59904K, 0% used [0x00000000f8b00000,0x00000000f8b00000,0x00000000fc580000)
 ParOldGen       total 838656K, used 36453K [0x0000000080000000, 0x00000000b3300000, 0x00000000b3300000)
  object space 838656K, 4% used [0x0000000080000000,0x0000000082399618,0x00000000b3300000)
 Metaspace       used 94395K, capacity 99677K, committed 99792K, reserved 1134592K
  class space    used 13073K, capacity 14009K, committed 14076K, reserved 1048576K

可以看到，Full GC还是有3次，而且都是由Metaspace内存不足而导致的

接下来，我们对Metaspace做一个调整，Metaspace是JDK8之后新增的一个区域，用于代替之前永久代，存放类的元信息，比如类加载器的信息，类的方法、属性等信息，这个内存与堆内存不共享，使用的是直接内存，理论上来说物理内存有多大，它就能有多大，但是它还是由JVM进行管理，如果当前Metaspace的内存不足以存放更多的类信息，就会触发Full GC

所以我们调大Metaspace的内存大小，并且固定下来，通过之前的GC信息，我们可以看到，最终Metaspace使用的内存大小为90MB+，所以其实我们给他分配128MB即可，但是为了保险起见，并且机器内存充足的情况下，一般会给Metaspace分配256MB，这个视情况而定，这里我们分配256MB

-XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m

然后重启进程，观察VisualGC和GC日志
image.png

Java HotSpot(TM) 64-Bit Server VM (25.92-b14) for windows-amd64 JRE (1.8.0_92-b14), built on Mar 31 2016 21:03:04 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16658592k(10189640k free), swap 33315340k(26605448k free)
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=2147483648 -XX:+ManagementServer -XX:MaxHeapSize=2147483648 -XX:MaxMetaspaceSize=268435456 -XX:MaxNewSize=1288699904 -XX:MetaspaceSize=268435456 -XX:NewSize=1288699904 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
5.614: [GC (Allocation Failure) [PSYoungGen: 1007616K->31006K(1133056K)] 1007616K->31030K(1971712K), 0.0201528 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] 
8.870: [GC (Allocation Failure) [PSYoungGen: 1038622K->41117K(1133056K)] 1038646K->41221K(1971712K), 0.0281705 secs] [Times: user=0.01 sys=0.00, real=0.03 secs] 
14.656: [GC (Allocation Failure) [PSYoungGen: 1048733K->53249K(1133056K)] 1048837K->53369K(1971712K), 0.0313939 secs] [Times: user=0.06 sys=0.00, real=0.03 secs] 
18.528: [GC (Allocation Failure) [PSYoungGen: 1060865K->60868K(1133056K)] 1060985K->61004K(1971712K), 0.0331794 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
23.619: [GC (Allocation Failure) [PSYoungGen: 1068484K->77294K(1133056K)] 1068620K->77454K(1971712K), 0.0450021 secs] [Times: user=0.14 sys=0.00, real=0.05 secs] 
29.523: [GC (Allocation Failure) [PSYoungGen: 1084910K->72927K(1160192K)] 1085070K->73111K(1998848K), 0.0481649 secs] [Times: user=0.11 sys=0.03, real=0.05 secs]

可以看到，Full GC完全没有了，只剩下6次Minor GC

至此，优化的目标基本都达到了，还有6次MinorGC，我观察了一下，主要是由Skywalking agent引起的

如果要放到生产上，我们可以视情况配置下，如

  • 修改垃圾回收器，指定为ParNew+CMS组合，一般B/S应用都推荐使用这个组合，参数为-XX:+UseParNewGC(指定新生代垃圾回收器为ParNew)，-XX:+UseConcMarkSweepGC(指定老年代垃圾回收器为CMS)
  • 如果指定了CMS，那么我们需要额外配置一些参数来配合CMS，如CMS回收阈值，是否启用内存整理等
    • -XX:+UseCMSInitiatingOccupancyOnly：设置仅当老年代内存使用率达到阈值后才触发FullGC
    • -XX:CMSInitiatingOccupancyFraction=92：设置老年代内存占用达到92%时触发Full GC
    • 上面两个参数必须要配合使用，否则不生效
    • -XX:+CMSParallelInitialMarkEnabled：设置在初始标记阶段时使用多线程
    • -XX:+CMSScanvengeBeforeRemark：设置在重新标记节点前执行MinorGC，减少重新标记的时间
    • -XX:+UseCMSCompactAtFullCollection：设置CMS在进行FullGC时进行内存整理
    • -XX:CMSFullGCsBeforeCompaction：设置CMS执行几次后再对内存进行整理，默认为0次
  • 还有一些其他的参数，如-XX:+HeapDumpOnOutOfMemoryError，用于在JVM发生OOM时自动dump内存快照，-XX:HeadDumpPath，指定内存快照的存放路径
  • -xx:+DisableExplicitGC：禁止代码中显式触发GC，如System.gc()