课堂笔记：JVM（四）JVM调优实战

四、GC调优实战

JVM调优主要就是调整下面两个指标

停顿时间：垃圾收集器做垃圾回收中断应用执行的时间。-XX:MaxGCPauseMillis

吞吐量：垃圾收集的时间和总时间的占比：1/(1+n),吞吐量为1-1/(1+n)。-XX:GCTimeRatio=n

GC调优步骤

1.打印GC日志（后面是日志文件的输出路径）

-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:D:/gc.log

Tomcat可以直接加载JAVA_OPTS变量里

2.分析日志得到关键性指标

3.分析GC原因，调优JVM参数

GC日志分析

Java HotSpot(TM) 64-Bit Server VM (25.201-b09) for windows-amd64 JRE (1.8.0_201-b09), built on Dec 15 2018 18:36:39 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 12479204k(4570228k free), swap 16280292k(3304900k free)
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=199667264 -XX:+ManagementServer -XX:MaxHeapSize=3194676224 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation 
-XX:+UseParallelGC 
2020-05-30T21:25:30.363+0800: 3.599: [GC (Allocation Failure) [PSYoungGen: 49152K->6822K(57344K)] 49152K->6902K(188416K), 0.0271238 secs] [Times: user=0.00 sys=0.01, real=0.03 secs] 

2020-05-30T21:25:32.047+0800: 5.276: [Full GC (Metadata GC Threshold) [PSYoungGen: 6573K->0K(57344K)] [ParOldGen: 173K->6458K(68096K)] 6746K->6458K(125440K), [Metaspace: 20663K->20662K(1067008K)], 0.0573999 secs] [Times: user=0.13 sys=0.00, real=0.06 secs] 

020-05-30T21:25:35.962+0800: 9.190: [Full GC (Metadata GC Threshold) [PSYoungGen: 11260K->0K(148992K)] [ParOldGen: 9799K->18425K(108032K)] 21059K->18425K(257024K), [Metaspace: 33895K->33895K(1079296K)], 0.0784414 secs] [Times: user=0.22 sys=0.00, real=0.08 secs] 

• Memory: 4k ：内存大小。JVM为设置参数指定堆大小的情况下，JVM会根据计算机的物理内存动态分配，最小：物理内存1/64，最大：物理内存1/4.在真实的环境中，应该设置好，使得内存最大化。

首先看轻GC：

• “[GC (Allocation Failure) [PSYoungGen: 49152K->6822K(57344K)] ”：证明发生了一次GC，原因是分配失败。发生了一次轻GC，在GC过程中，新生代从49152k变成6822k，总的新生代大小为57344k。
• “49152K->6902K(188416K)”：整个堆内存的使用情况，该次GC后，内存从最开始的49152k到6902k，整个堆内存的大小为188416k。这里发现在一个轻GC之后，新生代中占用的内存小于整个堆空间中内存的占用，原因是该次GC之后又对象被分配到了老年代。也有可能是老年代本来就存在一些对象。

其次看FullGC：

• “Full GC (Metadata GC Threshold)”：说明发生了Full GC。
• “[PSYoungGen: 11260K->0K(148992K)] ”：新生代总共148992k，GC后占用内存从11260k~0k。
• “[ParOldGen: 9799K->18425K(108032K)] 21059K->18425K(257024K)”：老年代从9799k到18425k，说明Full GC之后新生代中的大量对象分配到 了老年代。
• “ 21059K->18425K(257024K)”：表示整个对内存空间的占用情况，整个堆空间大小为257024k，GC之后从21059k到18425k。
• “ [Metaspace: 33895K->33895K(1079296K)], 0.0784414 secs]”：元空间GC情况，可以发现此时没有变化。如果发生了变化的话，比如从20M到2M，那么这个元空间的内存就会变小。如果没有变化的话，那么这个元空间的内存就会增大。

GC在线分析网站：

https://gceasy.io/

1.Parallel Scavenge收集器(默认)

分析parallel-gc.log

第一次调优，设置Metaspace大小：增大元空间大小-XX:MetaspaceSize=64M -XX:MaxMetaspaceSize=64M

第二次调优，增大年轻代动态扩容增量（默认是20%），可以减少YGC：-XX:YoungGenerationSizeIncrement=30

比较下几次调优效果：

吞吐量	最大停顿	平均停顿	YGC	FGC
97.169%	420 ms	60.0 ms	12	2
98.775%	60.0 ms	28.0 ms	10	0

2.配置CMS收集器

-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -Xloggc:D:/gc-cms.log

分析gc-cms.log

Java HotSpot(TM) 64-Bit Server VM (25.201-b09) for windows-amd64 JRE (1.8.0_201-b09), built on Dec 15 2018 18:36:39 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 12479204k(4608124k free), swap 16280292k(3258208k free)
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=199667264 -XX:+ManagementServer -XX:MaxHeapSize=3194676224 -XX:MaxNewSize=348966912 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
2020-05-30T22:18:23.094+0800: 3.039: [GC (Allocation Failure) 2020-05-30T22:18:23.094+0800: 3.040: [ParNew: 52480K->6528K(59008K), 0.0106917 secs] 52480K->6972K(190080K), 0.0109860 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2020-05-30T22:18:23.772+0800: 3.717: [GC (Allocation Failure) 2020-05-30T22:18:23.772+0800: 3.717: [ParNew: 59008K->6527K(59008K), 0.0167618 secs] 59452K->10858K(190080K), 0.0168590 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] 
2020-05-30T22:18:24.376+0800: 4.322: [GC (Allocation Failure) 2020-05-30T22:18:24.376+0800: 4.322: [ParNew: 59007K->5067K(59008K), 0.0068271 secs] 63338K->10698K(190080K), 0.0069350 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2020-05-30T22:18:24.383+0800: 4.329: [GC (CMS Initial Mark) [1 CMS-initial-mark: 5630K(131072K)] 11167K(190080K), 0.0008400 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2020-05-30T22:18:24.384+0800: 4.330: [CMS-concurrent-mark-start]
2020-05-30T22:18:24.427+0800: 4.372: [CMS-concurrent-mark: 0.043/0.043 secs] [Times: user=0.09 sys=0.01, real=0.04 secs] 
2020-05-30T22:18:24.427+0800: 4.373: [CMS-concurrent-preclean-start]
2020-05-30T22:18:24.428+0800: 4.374: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2020-05-30T22:18:24.428+0800: 4.374: [CMS-concurrent-abortable-preclean-start]
2020-05-30T22:18:24.745+0800: 4.691: [CMS-concurrent-abortable-preclean: 0.097/0.317 secs] [Times: user=0.64 sys=0.06, real=0.32 secs] 
2020-05-30T22:18:24.745+0800: 4.691: [GC (CMS Final Remark) [YG occupancy: 36275 K (59008 K)]2020-05-30T22:18:24.745+0800: 4.691: [Rescan (parallel) , 0.0054229 secs]2020-05-30T22:18:24.750+0800: 4.696: [weak refs processing, 0.0000740 secs]2020-05-30T22:18:24.750+0800: 4.696: [class unloading, 0.0027947 secs]2020-05-30T22:18:24.753+0800: 4.699: [scrub symbol table, 0.0052821 secs]2020-05-30T22:18:24.759+0800: 4.705: [scrub string table, 0.0004237 secs][1 CMS-remark: 5630K(131072K)] 41905K(190080K), 0.0146353 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
2020-05-30T22:18:24.760+0800: 4.706: [CMS-concurrent-sweep-start]
2020-05-30T22:18:24.764+0800: 4.710: [CMS-concurrent-sweep: 0.003/0.003 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2020-05-30T22:18:24.764+0800: 4.710: [CMS-concurrent-reset-start]
2020-05-30T22:18:24.766+0800: 4.712: [CMS-concurrent-reset: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

为四个步骤：

• 初始标记（CMS initial mark）： 暂停所有的其他线程，并记录下直接与root相连的对象，速度很快

• 并发标记（CMS concurrent mark）： 同时开启GC和用户线程，用一个闭包结构去记录可达对象。但在这个阶段结束，这个闭包结构并不能保证包含当前所有的可达对象。因为用户线程可能会不断的更新引用域，所以GC线程无法保证可达性分析的实时性。所以这个算法里会跟踪记录这些发生引用更新的地方。

• 重新标记（CMS remark）： 重新标记阶段就是为了修正并发标记期间因为用户程序继续运行而导致标记产生变动的那一部分对象的标记记录，这个阶段的停顿时间一般会比初始标记阶段的时间稍长，远远比并发标记阶段时间短

• 并发清除（CMS concurrent sweep）： 开启用户线程，同时GC线程开始对为标记的区域做清扫。

  ---

• [GC (CMS Initial Mark) [1 CMS-initial-mark: 5630K(131072K)] 11167K(190080K), 0.0008400 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]：初始标记

• [CMS-concurrent-mark: 0.043/0.043 secs:开始进行并发标记。

• [GC (CMS Final Remark) ：重新标记。

• [CMS-concurrent-sweep: 0.003/0.003 secs]：并发清除。

3.配置G1收集器

-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+UseG1GC -Xloggc:D:/gc-g1s.log

分析gc-g1.log

2020-05-30T22:47:38.295+0800: 3.161: [GC pause (G1 Evacuation Pause) (young), 0.0055069 secs]
   [Parallel Time: 3.9 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 3161.0, Avg: 3161.1, Max: 3161.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.9, Avg: 1.0, Max: 1.2, Diff: 0.3, Sum: 4.2]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 0.6]
      [Object Copy (ms): Min: 2.4, Avg: 2.7, Max: 2.8, Diff: 0.4, Sum: 10.6]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 3.8, Avg: 3.9, Max: 3.9, Diff: 0.1, Sum: 15.5]
      [GC Worker End (ms): Min: 3164.9, Avg: 3164.9, Max: 3164.9, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 1.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.8 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 14.0M(14.0M)->0.0B(17.0M) Survivors: 0.0B->2048.0K Heap: 14.0M(192.0M)->2950.5K(192.0M)]

每两个时间戳之间的是一行。在最后一行有一个对G1收集器的总结，可以看到Eden去和Survivors回收情况。

在G1收集器中，Young GC是对新生代的Region进行回收，Mixed GC是对新生代和部分收益高的老年代的Region进行回收。

-XX:InitiatingHeapOccupancyPercen:老年代占用空间超过整堆比IHOP阈值(默认45%),超过则执行混合收集，在IHOP值超过45%的时候会判断进行Mixed GC。如多低于，则不会进行Mixed GC.

在G1收集器中很好发生Full GC。当发生内存溢出的时候一定会发生Full GC。

2020-05-31T09:36:34.583+0800: 2.291: [Full GC (Allocation Failure)  9273K->9087K(10M), 0.0614836 secs]
   [Eden: 0.0B(1024.0K)->0.0B(1024.0K) Survivors: 0.0B->0.0B Heap: 9273.5K(10.0M)->9087.2K(10.0M)], [Metaspace: 4266K->4266K(1056768K)]
 [Times: user=0.06 sys=0.00, real=0.06 secs] 
2020-05-31T09:36:34.645+0800: 2.353: [GC concurrent-mark-abort]
Heap
 garbage-first heap   total 10240K, used 9087K [0x00000000ff600000, 0x00000000ff700050, 0x0000000100000000)
  region size 1024K, 1 young (1024K), 0 survivors (0K)
 Metaspace       used 4328K, capacity 4604K, committed 4864K, reserved 1056768K
  class space    used 475K, capacity 492K, committed 512K, reserved 1048576K

young GC:[GC pause (G1 Evacuation Pause)(young)

initial-mark:[GC pause (Metadata GC Threshold)(young)(initial-mark) (参数：InitiatingHeapOccupancyPercent)

mixed GC:[GC pause (G1 Evacuation Pause)(Mixed) (参数：G1HeapWastePercent)

full GC:[Full GC (Allocation Failure)(无可用region)

（G1内部，前面提到的混合GC是非常重要的释放内存机制，它避免了G1出现Region没有可用的情况，否则就会触发 FullGC事件。CMS、Parallel、Serial GC都需要通过Full GC去压缩老年代并在这个过程中扫描整个老年代。G1的Full GC算法和Serial GC收集器完全一致。当一个Full GC发生时，整个Java堆执行一个完整的压缩，这样确保了最大的空余内存可用。G1的Full GC是一个单线程，它可能引起一个长时间的停顿时间，G1的设计目标是减少Full GC，满足应用性能目标。）

查看发生MixedGC的阈值：jinfo -flag InitiatingHeapOccupancyPercent 进程ID

调优：

第一次调优，设置Metaspace大小：增大元空间大小-XX:MetaspaceSize=64M -XX:MaxMetaspaceSize=64M

第二次调优，添加吞吐量和停顿时间参数：-XX:GCTimeRatio=99 -XX:MaxGCPauseMillis=10

GC常用参数

堆栈设置

-Xss:每个线程的栈大小

-Xms:初始堆大小，默认物理内存的1/64

-Xmx:最大堆大小，默认物理内存的1/4

-Xmn:新生代大小

-XX:NewSize:设置新生代初始大小

-XX:NewRatio:默认2表示新生代占年老代的1/2，占整个堆内存的1/3。

-XX:SurvivorRatio:默认8表示一个survivor区占用1/8的Eden内存，即1/10的新生代内存。

-XX:MetaspaceSize:设置元空间大小

-XX:MaxMetaspaceSize:设置元空间最大允许大小，默认不受限制，JVM Metaspace会进行动态扩展。

垃圾回收统计信息

-XX:+PrintGC

-XX:+PrintGCDetails

-XX:+PrintGCTimeStamps

-Xloggc:filename

收集器设置

-XX:+UseSerialGC:设置串行收集器

-XX:+UseParallelGC:设置并行收集器

-XX:+UseParallelOldGC:老年代使用并行回收收集器

-XX:+UseParNewGC:在新生代使用并行收集器

-XX:+UseParalledlOldGC:设置并行老年代收集器

-XX:+UseConcMarkSweepGC:设置CMS并发收集器

-XX:+UseG1GC:设置G1收集器

-XX:ParallelGCThreads:设置用于垃圾回收的线程数

并行收集器设置

-XX:ParallelGCThreads:设置并行收集器收集时使用的CPU数。并行收集线程数。

-XX:MaxGCPauseMillis:设置并行收集最大暂停时间

-XX:GCTimeRatio:设置垃圾回收时间占程序运行时间的百分比。公式为1/(1+n)

CMS收集器设置

-XX:+UseConcMarkSweepGC:设置CMS并发收集器

-XX:+CMSIncrementalMode:设置为增量模式。适用于单CPU情况。

-XX:ParallelGCThreads:设置并发收集器新生代收集方式为并行收集时，使用的CPU数。并行收集线程数。

-XX:CMSFullGCsBeforeCompaction:设定进行多少次CMS垃圾回收后，进行一次内存压缩

-XX:+CMSClassUnloadingEnabled:允许对类元数据进行回收

-XX:UseCMSInitiatingOccupancyOnly:表示只在到达阀值的时候，才进行CMS回收

-XX:+CMSIncrementalMode:设置为增量模式。适用于单CPU情况

-XX:ParallelCMSThreads:设定CMS的线程数量

-XX:CMSInitiatingOccupancyFraction:设置CMS收集器在老年代空间被使用多少后触发

-XX:+UseCMSCompactAtFullCollection:设置CMS收集器在完成垃圾收集后是否要进行一次内存碎片的整理

G1收集器设置

-XX:+UseG1GC:使用G1收集器

-XX:ParallelGCThreads:指定GC工作的线程数量

-XX:G1HeapRegionSize:指定分区大小(1MB~32MB，且必须是2的幂)，默认将整堆划分为2048个分区

-XX:GCTimeRatio:吞吐量大小，0-100的整数(默认9)，值为n则系统将花费不超过1/(1+n)的时间用于垃圾收集

-XX:MaxGCPauseMillis:目标暂停时间(默认200ms)

-XX:G1NewSizePercent:新生代内存初始空间(默认整堆5%)

-XX:G1MaxNewSizePercent:新生代内存最大空间

-XX:TargetSurvivorRatio:Survivor填充容量(默认50%)

-XX:MaxTenuringThreshold:最大任期阈值(默认15)

-XX:InitiatingHeapOccupancyPercen:老年代占用空间超过整堆比IHOP阈值(默认45%),超过则执行混合收集

-XX:G1HeapWastePercent:堆废物百分比(默认5%)

-XX:G1MixedGCCountTarget:参数混合周期的最大总次数(默认8)

---

使用gceasy 工具分析GC日志

在实际的项目中一般不会直接分许GC日志，因为看起来不是很方便。如果实在是服务器不允许的情况下才会使用。

登录网址：

[httpss://gceasy.io]:

随后我们可以将导出的GC日志添加到网站中，然后选择分析，就会得到结果：

• 从这里的Throughput：95.757%可以看出吞吐量。
• Avg Pause GC Time：平均停顿为27.0ms
• Max Pause GC Time：最大停顿：80.0ms

这里可以看到Parallel Scavenge收集器的GC次数等详细信息。还可以看到总的GC时间是270ms.

1、Parallel Scavenge收集器（默认）

（1）、分析GC日志

这里我们可以对调优结果进行记录。

调优	吞吐量(%)	最大停顿(ms)	平均停顿(ms)	YGC	FGC
调优前	95.757	80	27	8	2
调大元空间后	97.867	40	27.5	8	0
增大年轻代扩容增量后	97.208	50	35.7	7	0

然后我们结合输出的GC日志查看Full GC产生的原因：

2020-05-31T10:55:20.400+0800: 5.029: [Full GC (Metadata GC Threshold) [PSYoungGen: 6386K->0K(106496K)] [ParOldGen: 237K->6368K(66048K)] 6623K->6368K(172544K), [Metaspace: 20528K->20528K(1067008K)], 0.0815557 secs] [Times: user=0.11 sys=0.00, real=0.08 secs] 

发现是元空间无法分配造成的，元空间已经达到了最大阈值“20528”。

现在的调优思路是增大元空间。

（2）、调优

第一次调优，设置Metaspace大小，增大元空间大小：

-XX:MetaspaceSize=64M -XX:MaxMetaspaceSize=64M

发现调大之后，记录在上面表中，没有产生FULL GC了，而且各项指标都有优化。

第二次调优，增大年轻代动态扩容增量（默认是20%），可以减少YGC：

-XX:YoungGenerationSizeIncrement=30

发现虽然YGC次数减少了一次，但是吞吐量，GC停顿等升高了，所以此次优化可以不进行。当项目到达一个最高优化就不需要再优化了。

如果用该工具调优后，页面没有给出调优建议，就说明已经调优的可以了。

2、G1收集器分析

-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:MetaspaceSize=64M -XX:+UseG1GC -Xloggc:D:/gc-g1-now.log

可以看到G1收集器可以回收的内存是很大的。

看到此时的优化程度已经很高了，不需要再优化了。

G1收集器如果发生了FULL GC 就会给出建议：