本文主要介绍了一次因内存泄露导致服务不可用生产事件的处理过程，同时也包括后续的应用跟踪及问题优化过程。本文亦包括在对事故原因进行复盘和分析，并调整 JVM 参数优化性能过程中涉及到的 JVM 性能优化相关知识。
生产事件
事件经过
- 2019.12.09 9:15 技术人员接运维人员反馈，APP 服务无法正常使用。
- 2019.12.09 9:20 开发人员介入，开始排查原因。
- 2019.12.09 9:25 登陆 Eureka 控制台，发现 4 个网关服务续约失败，处于 DOWN 状态，判断网关实例处理于不可用状态。
- 2019.12.09 9:30 登陆网关服务器，排查应用 GC 状态，发现应用 Full GC 频繁，初始判断应用发生了内存泄露。
- 2019.12.09 9:36 对于 4 台网关应用服务进行依次紧急重启，APP 服务能力恢复。
原因分析
- 根据事故发生时，Zuul 网关应用的 Full GC 频率及堆内存使用情况，分析事故原因为应用存在内存溢出或内存泄露。
- 根据此类事故存在前例，主要表现经过一段进运行后，应用可用内存不足，Full GC 频繁，判断事故原因可能为因存在资源未及时释放导致的内存泄露。
- 由于事故发生时，应用网关错误日志被错误删除，无法根据堆栈信息判断事故发生时应用的状态。
- 由于事故发生时，应用堆栈信息没有进行 dump,无法判断其时内存中对象的分布情况和运行线程的状态。
- 由于生产环境应用未打印 GC 日志，无法通过 GC 日志排查应用 Crash 原因。
临时解决方案
基于此类事件发生的原因分析，初步解决方案如下：
- 使用 crontab 定时对 zuul 服务间断一段时间进行重启，两次服务重启间隔周期为 6 天，其中 4 台服务依次重启时间间隔设定为 1 小时。
初步拟定的后续优化措施
- 修改应用启动时设置的 JVM 参数，增加-XX:+HeapDumpOnOutOfMemoryError，使用应用内存溢出时可以 dump 出堆栈快照。
- 增加 JVM 参数-XX:+PrintGCDetails，打印应用 GC 情况。
- 分析源代码，排查资源未及时关闭，或因异常情况未关闭的情况，如有修改其实现。
- 设置 JVM 参数-XX:+UseConcMarkSweepGC，老年代使用 CMS 垃圾收集器，保持生产环境与测试环境一致，保障应用的时延要求。
- 排查网关服务中以下 sentinel 及 prometheus 相关对象内存占用过高的原因,优化其实现，减少内存占用。
- com.alibaba.csp.sentinel.slots.statistic.base.LongAdder
- com.alibaba.csp.sentinel.node.metric.MetricNode
- io.prometheus.client.DoubleAdder
- 修改 logback-spring.xml，增加日志自动压缩，同时优化日志输出格式提升日志打印信息价值，归档好 error 日志。
生产环境堆栈使用情况跟踪
由于事件发生时，没有保存有价值的信息，后续对生产应用进行观察，以确认应用运行情况。多次跟踪发现如下问题。
- Java 应用宿主机 CPU、内存、磁盘没有存在明显性能瓶颈。
- 查看堆内存情况，没有明确设置 jvm 参数，导致堆大小、新生代初始大小、Survivor 区域大小、老年代初始大小、元数据区初始大小均存在明显偏小的情况。
- 通过三次堆内存使用情况比较，老年代已使用内存增加明显，新生代已使用内存没有明显增长，
推测是由于 Survivor 区域偏小导致 MinorGC 后 Survivor 区域溢出，对象没有到最大晋升年代即转移到了老年代。 - 查看 GC 情况，MinorGC 和 MajorGC 频率过快，反映出新生代和老年代内存区域设置不合理。
- 新生代和老年代使用 ParallelGC（throughput collector），对于网关应用推荐使用时延类型的垃圾收集器，如 Concurrent Mark Sweep (CMS) Collector。
系统资源使用情况
使用 vmstat 查看系统资源
通过 vmstat 命令显示内存、IO、CPU 资源未存在瓶颈。
$ vmstat
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
1 0 57728 549036 275392 4434100 0 0 0 7 0 0 5 0 95 0 0
使用 free 查看内存使用情况
$ free -h
total used free shared buff/cache available
Mem: 7.6G 2.6G 551M 397M 4.5G 4.3G
Swap: 8.0G 56M 7.9G
使用 top 查看系统资源
$ top
top - 14:01:51 up 442 days, 22:10, 1 user, load average: 0.17, 0.12, 0.12
Tasks: 105 total, 1 running, 104 sleeping, 0 stopped, 0 zombie
%Cpu(s): 4.2 us, 0.6 sy, 0.0 ni, 94.2 id, 0.1 wa, 0.0 hi, 0.1 si, 0.9 st
KiB Mem : 8010192 total, 492912 free, 2794956 used, 4722324 buff/cache
KiB Swap: 8388604 total, 8330876 free, 57728 used. 4451432 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
24467 loginus+ 20 0 10.244g 1.846g 14156 S 21.6 24.2 622:54.70 java
应用启动 30 小时后查看堆栈情况
使用 jps 查看 VMID
$ jps -l
24467 zuul-0.0.1.jar
使用 jinfo 查看 JVM 参数
jinfo 命令显示应用启动时未设置 JVM 参数，且 JVM 根据自适应策略分配的堆大小、初始新生代大小、Survivor 初始大小、老年代初始大小、元数据区大小存在偏小的现象。
$ jinfo 24467
Attaching to process ID 24467, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.91-b14
Java System Properties:
......
VM Flags:
Non-default VM flags: -XX:CICompilerCount=3 -XX:InitialHeapSize=130023424 -XX:MaxHeapSize=2051014656 -XX:MaxNewSize=683671552 -XX:MinHeapDeltaBytes=524288 -XX:NewSize=42991616 -XX:OldSize=87031808 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
Command line:
使用 jmap -heap 查看堆内存使用情况
应用 JAVA 堆的老年代及新生代 Survivor 区偏小及使用比率过高。
$ jmap -heap 24467
Attaching to process ID 24467, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.91-b14
using thread-local object allocation.
Parallel GC with 4 thread(s)
Heap Configuration:
MinHeapFreeRatio = 0
MaxHeapFreeRatio = 100
MaxHeapSize = 2051014656 (1956.0MB)
NewSize = 42991616 (41.0MB)
MaxNewSize = 683671552 (652.0MB)
OldSize = 87031808 (83.0MB)
NewRatio = 2
SurvivorRatio = 8
MetaspaceSize = 21807104 (20.796875MB)
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 17592186044415 MB
G1HeapRegionSize = 0 (0.0MB)
Heap Usage:
PS Young Generation
Eden Space:
capacity = 125304832 (119.5MB)
used = 50442968 (48.106163024902344MB)
free = 74861864 (71.39383697509766MB)
40.25620336811912% used
From Space:
capacity = 1572864 (1.5MB)
used = 1433680 (1.3672637939453125MB)
free = 139184 (0.1327362060546875MB)
91.15091959635417% used
To Space:
capacity = 1572864 (1.5MB)
used = 0 (0.0MB)
free = 1572864 (1.5MB)
0.0% used
PS Old Generation
capacity = 646447104 (616.5MB)
used = 557551408 (531.7224578857422MB)
free = 88895696 (84.77754211425781MB)
86.24857386630043% used
39044 interned Strings occupying 4838664 bytes.
使用 jstat -gc 查看 GC 情况
通过查看 YGC、FGC、FGCT 项数值， 可以知道 MinorGC 和 MajorGC 频率过高，而且 MajorGC 平均耗时过高。
$ jstat -gc 24467
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
1024.0 2560.0 1008.0 0.0 134656.0 132550.9 640512.0 548254.2 99200.0 94998.8 12672.0 11868.3 19204 414.569 70 74.953 489.522
$ jstat -gc 24467
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
2560.0 1536.0 0.0 1416.1 116224.0 71671.3 641024.0 585665.1 99200.0 94995.1 12672.0 11867.7 19563 423.094 72 77.614 500.708
$ jstat -gc 24467
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
1536.0 1536.0 0.0 1440.0 111104.0 74654.5 641024.0 586897.4 99200.0 94995.1 12672.0 11867.7 19565 423.134 72 77.614 500.748
应用启动 78 小时后再次查看堆栈情况
使用 jmap -heap 查看堆内存使用情况
老年代使用大小进一步扩大，扩大过程伴随着 MajorGC.
$ jmap -heap 24467
Attaching to process ID 24467, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.91-b14
using thread-local object allocation.
Parallel GC with 4 thread(s)
Heap Configuration:
MinHeapFreeRatio = 0
MaxHeapFreeRatio = 100
MaxHeapSize = 2051014656 (1956.0MB)
NewSize = 42991616 (41.0MB)
MaxNewSize = 683671552 (652.0MB)
OldSize = 87031808 (83.0MB)
NewRatio = 2
SurvivorRatio = 8
MetaspaceSize = 21807104 (20.796875MB)
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 17592186044415 MB
G1HeapRegionSize = 0 (0.0MB)
Heap Usage:
PS Young Generation
Eden Space:
capacity = 135790592 (129.5MB)
used = 9833384 (9.377845764160156MB)
free = 125957208 (120.12215423583984MB)
7.241579740664213% used
From Space:
capacity = 1572864 (1.5MB)
used = 1458208 (1.390655517578125MB)
free = 114656 (0.109344482421875MB)
92.71036783854167% used
To Space:
capacity = 2621440 (2.5MB)
used = 0 (0.0MB)
free = 2621440 (2.5MB)
0.0% used
PS Old Generation
capacity = 1035993088 (988.0MB)
used = 984042752 (938.456298828125MB)
free = 51950336 (49.543701171875MB)
94.98545534697621% used
39172 interned Strings occupying 4856640 bytes.
使用 jmap -histo 查看堆内对象分布
io.prometheus.client.DoubleAdder、com.alibaba.csp.sentinel.slots.statistic.base.LongAdder 等监控类组件对象内存占比偏高。
$ jmap -histo 24467|more
num #instances #bytes class name
----------------------------------------------
1: 4487593 333733824 [C
2: 4405980 105743520 java.lang.String
3: 2398449 76750368 java.util.concurrent.ConcurrentHashMap$Node
4: 2233667 71477344 io.prometheus.client.DoubleAdder
5: 2251973 67756960 [Ljava.lang.String;
6: 2234850 53636400 java.util.Arrays$ArrayList
7: 34130 48613136 [B
8: 2233645 35738320 io.prometheus.client.Counter$Child
9: 947460 30318720 com.alibaba.csp.sentinel.slots.statistic.base.LongAdder
10: 11550 28238768 [J
11: 6230 23170688 [Ljava.util.concurrent.ConcurrentHashMap$Node;
12: 133920 11106968 [Ljava.lang.Object;
13: 120132 8649504 com.alibaba.csp.sentinel.node.metric.MetricNode
14: 25853 7283504 [I
15: 15868 6601088 rx.internal.util.unsafe.SpscLinkedQueue
16: 157910 6316400 [Lcom.alibaba.csp.sentinel.slots.statistic.base.LongAdder;
17: 157910 5053120 com.alibaba.csp.sentinel.slots.statistic.base.WindowWrap
18: 25373 4465648 rx.internal.util.unsafe.SpscUnboundedArrayQueue
19: 125263 4008416 java.util.HashMap$Node
20: 157910 3789840 com.alibaba.csp.sentinel.slots.statistic.data.MetricBucket
使用 jstat -gc 查看 GC 情况
MinjorGC 及 MajorGC 发生频率进一步加快，且 MajorGC 平均耗时接近 2s.
$ jstat -gc 24467
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
1536.0 3072.0 1464.0 0.0 117760.0 95989.9 1011712.0 981977.8 99456.0 95277.6 12672.0 11872.4 64954 1403.554 390 736.403 2139.957
应用启动 96 小时后再次查看堆栈情况
使用 jmap -heap 查看堆内存使用情况
老年代使用大小进一步扩大，而 Survivor 区域偏小，MinjorGC 发生后幸存对象无法被 Survivor 区域容纳，导致对象过早晋升到老年代。
$ jmap -heap 24467
Attaching to process ID 24467, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.91-b14
using thread-local object allocation.
Parallel GC with 4 thread(s)
Heap Configuration:
MinHeapFreeRatio = 0
MaxHeapFreeRatio = 100
MaxHeapSize = 2051014656 (1956.0MB)
NewSize = 42991616 (41.0MB)
MaxNewSize = 683671552 (652.0MB)
OldSize = 87031808 (83.0MB)
NewRatio = 2
SurvivorRatio = 8
MetaspaceSize = 21807104 (20.796875MB)
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 17592186044415 MB
G1HeapRegionSize = 0 (0.0MB)
Heap Usage:
PS Young Generation
Eden Space:
capacity = 236453888 (225.5MB)
used = 128990192 (123.01463317871094MB)
free = 107463696 (102.48536682128906MB)
54.5519437599605% used
From Space:
capacity = 7340032 (7.0MB)
used = 6906832 (6.5868682861328125MB)
free = 433200 (0.4131317138671875MB)
94.09811837332589% used
To Space:
capacity = 9437184 (9.0MB)
used = 0 (0.0MB)
free = 9437184 (9.0MB)
0.0% used
PS Old Generation
capacity = 1181220864 (1126.5MB)
used = 1043733632 (995.3819580078125MB)
free = 137487232 (131.1180419921875MB)
88.36058215781735% used
39210 interned Strings occupying 4861472 bytes.
使用 jstat -gc 查看 GC 情况
MinjorGC频率接近4s/次，反映新生代设置过小。
$ jstat -gc 24467 1000 10000
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
2560.0 2048.0 0.0 1792.2 171520.0 55080.3 1151488.0 1041471.2 99712.0 95374.3 12672.0 11872.4 83101 1814.040 490 1052.659 2866.699
2560.0 2048.0 0.0 1792.2 171520.0 96507.4 1151488.0 1041471.2 99712.0 95374.3 12672.0 11872.4 83101 1814.040 490 1052.659 2866.699
2560.0 2048.0 0.0 1792.2 171520.0 135071.5 1151488.0 1041471.2 99712.0 95374.3 12672.0 11872.4 83101 1814.040 490 1052.659 2866.699
2048.0 3072.0 1744.0 0.0 189952.0 11847.6 1151488.0 1042303.4 99712.0 95374.3 12672.0 11872.4 83102 1814.061 490 1052.659 2866.720
2048.0 3072.0 1744.0 0.0 189952.0 72834.3 1151488.0 1042303.4 99712.0 95374.3 12672.0 11872.4 83102 1814.061 490 1052.659 2866.720
2048.0 3072.0 1744.0 0.0 189952.0 117876.7 1151488.0 1042303.4 99712.0 95374.3 12672.0 11872.4 83102 1814.061 490 1052.659 2866.720
2048.0 3072.0 1744.0 0.0 189952.0 161142.5 1151488.0 1042303.4 99712.0 95374.3 12672.0 11872.4 83102 1814.061 490 1052.659 2866.720
2560.0 2048.0 0.0 1648.0 184320.0 8315.4 1151488.0 1043039.6 99712.0 95374.3 12672.0 11872.4 83103 1814.084 490 1052.659 2866.743
使用 jmap -histo 查看堆内对象分布
com.alibaba.csp.sentinel.slots.statistic.base.LongAdder 及 com.alibaba.csp.sentinel.slots.statistic.base.LongAdder 在堆内存中的实例个数及字节大小进一步提升。
$ jmap -histo 24467 |more
num #instances #bytes class name
----------------------------------------------
1: 5241140 389131992 [C
2: 5141724 123401376 java.lang.String
3: 2804348 89739136 java.util.concurrent.ConcurrentHashMap$Node
4: 2639286 84457152 io.prometheus.client.DoubleAdder
5: 2661267 80234760 [Ljava.lang.String;
6: 2642167 63412008 java.util.Arrays$ArrayList
7: 46094 45134520 [B
8: 2639243 42227888 io.prometheus.client.Counter$Child
9: 1002114 32067648 com.alibaba.csp.sentinel.slots.statistic.base.LongAdder
10: 6169 24235056 [Ljava.util.concurrent.ConcurrentHashMap$Node;
11: 205744 14813568 com.alibaba.csp.sentinel.node.metric.MetricNode
12: 113644 10100632 [Ljava.lang.Object;
13: 3567 10079776 [J
14: 23926 7012560 [I
15: 167019 6680760 [Lcom.alibaba.csp.sentinel.slots.statistic.base.LongAdder;
16: 167019 5344608 com.alibaba.csp.sentinel.slots.statistic.base.WindowWrap
17: 167019 4008456 com.alibaba.csp.sentinel.slots.statistic.data.MetricBucket
18: 41051 3612488 java.lang.reflect.Method
19: 65758 3156384 org.aspectj.weaver.reflect.ShadowMatchImpl
20: 35361 2701056 [Ljava.util.HashMap$Node;
查看 JVM 调优可用的参数
java [options] classname [args]
java [options] -jar filename [args]
options
Command-line options separated by spaces. See Options.
classname
The name of the class to be launched.
filename
The name of the Java Archive (JAR) file to be called. Used only with the -jar option.
args
The arguments passed to the main() method separated by spaces.
Java Options
-d64
Runs the application in a 64-bit environment. If a 64-bit environment is not installed or is not supported, then an error will be reported.
By default, the application is run in a 32-bit environment unless a 64-bit system is used.
Currently only the Java HotSpot Server VM supports 64-bit operation, and the -server option is implicit with the use of -d64.
The -client option is ignored with the use of -d64. This is subject to change in a future release.
-jar filename
Executes a program encapsulated in a JAR file. The filename argument is the name of a JAR file with a manifest that contains a line in the form Main-Class:classname that defines the class with the public static void main(String[] args) method that serves as your application's starting point.
When you use the -jar option, the specified JAR file is the source of all user classes, and other class path settings are ignored.
For more information about JAR files, see the following resources:
jar(1)
The Java Archive (JAR) Files guide at http://docs.oracle.com/javase/8/docs/technotes/guides/jar/index.html
Lesson: Packaging Programs in JAR Files at
http://docs.oracle.com/javase/tutorial/deployment/jar/index.html
-server
Selects the Java HotSpot Server VM. The 64-bit version of the JDK supports only the Server VM, so in that case the option is implicit.
For default JVM selection, see Server-Class Machine Detection at
http://docs.oracle.com/javase/8/docs/technotes/guides/vm/server-class.html
-Xmnsize
Sets the initial and maximum size (in bytes) of the heap for the young generation (nursery).
Append the letter k or K to indicate kilobytes, m or M to indicate megabytes, g or G to indicate gigabytes.
The young generation region of the heap is used for new objects. GC is performed in this region more often than in other regions.
If the size for the young generation is too small, then a lot of minor garbage collections will be performed.
If the size is too large, then only full garbage collections will be performed, which can take a long time to complete.
Oracle recommends that you keep the size for the young generation between a half and a quarter of the overall heap size.
The following examples show how to set the initial and maximum size of young generation to 256 MB using various units:
-Xmn256m
-Xmn262144k
-Xmn268435456
Instead of the -Xmn option to set both the initial and maximum size of the heap for the young generation, you can use -XX:NewSize to set the initial size and -XX:MaxNewSize to set the maximum size.
如果-Xms 和-Xmx 并没有设定为同一值，使用-Xmn 选项时，Java 堆的大小变化不会影响新生代空间，即新生代空间的大小总保持恒定，而不是随着 Java 堆大小扩展或缩减做相应的调整。
因此，请注意，只有在-Xms 和-Xmx 设定为同一值时才使用-Xmn 选项。
-Xmssize
Sets the initial size (in bytes) of the heap.
This value must be a multiple of 1024 and greater than 1 MB. Append the letter k or K to indicate kilobytes, m or M to indicate megabytes, g or G to indicate gigabytes.
The following examples show how to set the size of allocated memory to 6 MB using various units:
-Xms6291456
-Xms6144k
-Xms6m
If you do not set this option, then the initial size will be set as the sum of the sizes allocated for the old generation and the young generation.
The initial size of the heap for the young generation can be set using the -Xmn option or the -XX:NewSize option.
关注吞吐量及延迟的 Java 应用程序应该将—Xms 和—Xmx 设定为同一值。
这是因为无论扩展还是缩减新生代空间或老年代空间都需要进行 Full GC,而 Full GC 会降低程序的吞吐量并导致更长的延迟。
-Xmxsize
Specifies the maximum size (in bytes) of the memory allocation pool in bytes.
This value must be a multiple of 1024 and greater than 2 MB. Append the letter k or K to indicate kilobytes, m or M to indicate megabytes, g or G to indicate gigabytes.
The default value is chosen at runtime based on system configuration.
For server deployments, -Xms and -Xmx are often set to the same value.
See the section "Ergonomics" in Java SE HotSpot Virtual Machine Garbage Collection Tuning Guide at http://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/index.html.
The following examples show how to set the maximum allowed size of allocated memory to 80 MB using various units:
-Xmx83886080
-Xmx81920k
-Xmx80m
The -Xmx option is equivalent to -XX:MaxHeapSize.
-XX:MetaspaceSize=size
Sets the size of the allocated class metadata space that will trigger a garbage collection the first time it is exceeded.
This threshold for a garbage collection is increased or decreased depending on the amount of metadata used. The default size depends on the platform.
-XX:MaxMetaspaceSize=size
Sets the maximum amount of native memory that can be allocated for class metadata.
By default, the size is not limited. The amount of metadata for an application depends on the application itself, other running applications, and the amount of memory available on the system.
The following example shows how to set the maximum class metadata size to 256 MB:
-XX:MaxMetaspaceSize=256m
-XX:SurvivorRatio=ratio
Sets the ratio between eden space size and survivor space size. By default, this option is set to 8. The following example shows how to set the eden/survivor space ratio to 4:
-XX:SurvivorRatio=4
-XX:+PrintGCDetails
Enables printing of detailed messages at every GC. By default, this option is disabled.
-XX:+PrintGCTimeStamps
Enables printing of time stamps at every GC. By default, this option is disabled.
-XX:+PrintGCDateStamps
Enables printing of a date stamp at every GC. By default, this option is disabled.
Format: yyyy-MM-dd T HH-mm-ss.SSS-TZ
-Xloggc:filename
Sets the file to which verbose GC events information should be redirected for logging. The information written to this file is similar to the output of -verbose:gc with the time elapsed since the first GC event preceding each logged event. The -Xloggc option overrides -verbose:gc if both are given with the same java command.
Example:
-Xloggc:garbage-collection.log
-XX:+HeapDumpOnOutOfMemoryError
Enables the dumping of the Java heap to a file in the current directory by using the heap profiler (HPROF) when a java.lang.OutOfMemoryError exception is thrown.
You can explicitly set the heap dump file path and name using the -XX:HeapDumpPath option.
By default, this option is disabled and the heap is not dumped when an OutOfMemoryError exception is thrown.
-XX:HeapDumpPath=path
Sets the path and file name for writing the heap dump provided by the heap profiler (HPROF) when the -XX:+HeapDumpOnOutOfMemoryError option is set. By default, the file is created in the current working directory, and it is named java_pidpid.hprof where pid is the identifier of the process that caused the error. The following example shows how to set the default file explicitly (%p represents the current process identificator):
-XX:HeapDumpPath=./java_pid%p.hprof
The following example shows how to set the heap dump file to /var/log/java/java_heapdump.hprof:
-XX:HeapDumpPath=/var/log/java/java_heapdump.hprof
-XX:+PrintGCApplicationConcurrentTime
Enables printing of how much time elapsed since the last pause (for example, a GC pause). By default, this option is disabled.
-XX:+PrintGCApplicationStoppedTime
Enables printing of how much time the pause (for example, a GC pause) lasted. By default, this option is disabled.
-XX:+PrintCommandLineFlags
Enables printing of ergonomically selected JVM flags that appeared on the command line. It can be useful to know the ergonomic values set by the JVM, such as the heap space size and the selected garbage collector.
By default, this option is disabled and flags are not printed.
-XX:+ScavengeBeforeFullGC
Enables GC of the young generation before each full GC. This option is enabled by default.
Oracle recommends that you do not disable it, because scavenging the young generation before a full GC can reduce the number of objects reachable from the old generation space into the young generation space.
To disable GC of the young generation before each full GC, specify -XX:-ScavengeBeforeFullGC.
-XX:MaxTenuringThreshold=threshold
Sets the maximum tenuring threshold for use in adaptive GC sizing. The largest value is 15.
The default value is 15 for the parallel (throughput) collector, and 6 for the CMS collector.
The following example shows how to set the maximum tenuring threshold to 10:
-XX:MaxTenuringThreshold=10
-XX:+PrintTenuringDistribution
Enables printing of tenuring age information. The following is an example of the output:
Desired survivor size 48286924 bytes, new threshold 10 (max 10)
- age 1: 28992024 bytes, 28992024 total
- age 2: 1366864 bytes, 30358888 total
- age 3: 1425912 bytes, 31784800 total
...
Age 1 objects are the youngest survivors (they were created after the previous scavenge, survived the latest scavenge, and moved from eden to survivor space). Age 2 objects have survived two scavenges (during the second scavenge they were copied from one survivor space to the next). And so on.
In the preceding example, 28 992 024 bytes survived one scavenge and were copied from eden to survivor space, 1 366 864 bytes are occupied by age 2 objects, etc. The third value in each row is the cumulative size of objects of age n or less.
By default, this option is disabled.
-XX:+UseConcMarkSweepGC
Enables the use of the CMS garbage collector for the old generation. Oracle recommends that you use the CMS garbage collector when application latency requirements cannot be met by the throughput (-XX:+UseParallelGC) garbage collector. The G1 garbage collector (-XX:+UseG1GC) is another alternative.
By default, this option is disabled and the collector is chosen automatically based on the configuration of the machine and type of the JVM. When this option is enabled, the -XX:+UseParNewGC option is automatically set and you should not disable it, because the following combination of options has been deprecated in JDK 8: -XX:+UseConcMarkSweepGC -XX:-UseParNewGC.
-XX:CMSInitiatingOccupancyFraction=percent
Sets the percentage of the old generation occupancy (0 to 100) at which to start a CMS collection cycle. The default value is set to -1. Any negative value (including the default) implies that -XX:CMSTriggerRatio is used to define the value of the initiating occupancy fraction.
The following example shows how to set the occupancy fraction to 20%:
-XX:CMSInitiatingOccupancyFraction=20
-XX:+UseCMSInitiatingOccupancyOnly
Enables the use of the occupancy value as the only criterion for initiating the CMS collector. By default, this option is disabled and other criteria may be used.
-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses
Enables invoking of concurrent GC by using the System.gc() request and unloading of classes during the concurrent GC cycle. This option is disabled by default and can be enabled only together with the -XX:+UseConcMarkSweepGC option.
-XX:+CMSClassUnloadingEnabled
Enables class unloading when using the concurrent mark-sweep (CMS) garbage collector. This option is enabled by default. To disable class unloading for the CMS garbage collector, specify -XX:-CMSClassUnloadingEnabled.
-XX:+ParallelRefProcEnabled
Enables parallel reference processing. By default, this option is disabled.
创建 Jmeter 测试计划
创建 http 测试计划，保存 jmx 文件，然后关闭 GUI
- 测试计划使用 10 个用户对 3 个高频交易进行 30 分钟压力测试。
- 创建完成的测试计划见 ZullTestPlan.zip。
- 如何创建测试参考 4. Building a Web Test Plan
从命令行启动 Jmeter 测试
jmeter -n -t "D:\java\jmeter\TestPlan\ZullTestPlan.jmx" -l "D:\java\jmeter\TestPlan\ZullTestPlan.csv" -e -o "D:\java\jmeter\TestPlan\ZullTestPlan"
Don't use GUI mode for load testing !, only for Test creation and Test debugging.
For load testing, use CLI Mode (was NON GUI):
jmeter -n -t [jmx file] -l [results file] -e -o [Path to web report folder]
& increase Java Heap to meet your test requirements:
Modify current env variable HEAP="-Xms1g -Xmx1g -XX:MaxMetaspaceSize=256m" in the jmeter batch file
Check : https://jmeter.apache.org/usermanual/best-practices.html
模拟生产 JVM 参数在 SIT 环境启动
启动命令
nohup java -server -XX:CICompilerCount=3 -XX:InitialHeapSize=130023424\
-XX:MaxHeapSize=2051014656 -XX:MaxNewSize=683671552\
-XX:MinHeapDeltaBytes=524288-XX:NewSize=42991616\
-XX:+UseCompressedClassPointers -XX:+UseCompressedOops\
-XX:+UseParallelGC\
-XX:+PrintTenuringDistribution -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/data/logs/xxx/gc/zuul-prod-garbage-collection.log\
-XX:+PrintCommandLineFlags\
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/xxx/dump/zuul-prod-java_heapdump.hprof\
-Dapollo.meta=http://182.241.36.3:8080\
-Dcom.sun.management.jmxremote.port=9999 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false\
-jar /home/loginuser/xxx-ms/app/zuul-0.0.1.jar --spring.profiles.active=fat --debug=true\
>/dev/null 2>&1 &
jinfo 查看进程参数
$ jinfo 1397
Attaching to process ID 1397, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.161-b12
Java System Properties:
......
VM Flags:
Non-default VM flags: -XX:CICompilerCount=3 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=null -XX:InitialHeapSize=130023424 -XX:+ManagementServer -XX:MaxHeapSize=2051014656 -XX:MaxNewSize=683671552 -XX:MinHeapDeltaBytes=524288 -XX:NewSize=42991616 -XX:OldSize=87031808 -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
Command line: -XX:CICompilerCount=3 -XX:InitialHeapSize=130023424 -XX:MaxHeapSize=2051014656 -XX:MaxNewSize=683671552 -XX:MinHeapDeltaBytes=524288 -XX:NewSize=42991616 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC -XX:+PrintTenuringDistribution -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/data/logs/xxx/gc/zuul-prod-garbage-collection.log -XX:+PrintCommandLineFlags -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/xxx/dump/zuul-prod-java_heapdump.hprof -Dapollo.meta=http://10.29.36.3:8080 -Dcom.sun.management.jmxremote.port=9999 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false
jmap -heap 查看堆内存使用情况
生产环境没有设置 jvm 参数，根据 jvm 自动适应策略设定的堆内存大小偏小。
$ jmap -heap 1397
Attaching to process ID 1397, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.161-b12
using thread-local object allocation.
Parallel GC with 4 thread(s)
Heap Configuration:
MinHeapFreeRatio = 0
MaxHeapFreeRatio = 100
MaxHeapSize = 2051014656 (1956.0MB)
NewSize = 42991616 (41.0MB)
MaxNewSize = 683671552 (652.0MB)
OldSize = 87031808 (83.0MB)
NewRatio = 2
SurvivorRatio = 8
MetaspaceSize = 21807104 (20.796875MB)
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 17592186044415 MB
G1HeapRegionSize = 0 (0.0MB)
Heap Usage:
PS Young Generation
Eden Space:
capacity = 135790592 (129.5MB)
used = 122045104 (116.39128112792969MB)
free = 13745488 (13.108718872070312MB)
89.87743716442446% used
From Space:
capacity = 1572864 (1.5MB)
used = 1441792 (1.375MB)
free = 131072 (0.125MB)
91.66666666666667% used
To Space:
capacity = 1572864 (1.5MB)
used = 0 (0.0MB)
free = 1572864 (1.5MB)
0.0% used
PS Old Generation
capacity = 145752064 (139.0MB)
used = 134571672 (128.3375473022461MB)
free = 11180392 (10.662452697753906MB)
92.32917072104036% used
43358 interned Strings occupying 5226120 bytes.
jstat -gc 查看 GC 情况
$ jstat -gc 1397 1000 10000
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
1536.0 1536.0 0.0 1464.5 53760.0 22707.0 134144.0 120973.0 98520.0 94384.1 12760.0 11998.9 419 5.110 6 1.122 6.231
查看打印的 GC 日志
整个压力测试过程中存在 6 次 Full GC。
日志见 zuul-prod-garbage-collection.log
查看 Jmeter 压力测试报告
根据模拟测试结果调整 JVM 参数
启动命令
调整内容主要为：
- 将堆大小及初始堆小设置为相同值。
- 将堆大小设置为活跃数据大小的 3-4 倍（稳定态时老年代使用大小即为活跃数据大小，生产环境老年代使用大小为 995M 左右）。
- 将元数据区初始大小调大，防止扩容带来的 MajorGC。
- 将新生代大小设置为活跃数据大小的 1.2-2 倍。
- 将 Survior 区占比调大，观察是否仍存在提前晋升老年代的情况。
- 将老年代垃圾收集器改为 CMS,以减少 GC 停顿，减少应用时延。
nohup java -server -Xmn1024m -Xms4096m -Xmx4096m -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m\
-XX:MaxTenuringThreshold=15 -XX:SurvivorRatio=6\
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC\
-XX:CMSInitiatingOccupancyFraction=65 -XX:+UseCMSInitiatingOccupancyOnly -XX:+CMSClassUnloadingEnabled\
-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses\
-XX:+PrintTenuringDistribution -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/data/logs/xxx/gc/zuul-sit-garbage-collection.log\
-XX:+PrintCommandLineFlags\
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/xxx/dump/zuul-sit-java_heapdump.hprof\
-Dapollo.meta=http://182.241.36.3:8080\
-Dcom.sun.management.jmxremote.port=9999 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false\
-jar /home/loginuser/xxx-ms/app/zuul-0.0.1.jar --spring.profiles.active=fat --debug=true\
>/dev/null 2>&1 &
使用 Jmeter 运行压力测试
应用吞吐量 QPS 在 30 左右，比调整前有降低。
C:\Users\wuby>jmeter -n -t "D:\java\jmeter\TestPlan\ZullTestPlan.jmx" -l "D:\java\jmeter\TestPlan\ZullTestPlan-sit.csv" -e -o "D:\java\jmeter\TestPlan\ZullTestPlanSIT"
Creating summariser <summary>
Created the tree successfully using D:\java\jmeter\TestPlan\Zull Test Plan.jmx
Starting standalone test @ Fri Dec 13 11:12:11 CST 2019 (1576206731036)
Waiting for possible Shutdown/StopTestNow/HeapDump/ThreadDump message on port 4445
Warning: Nashorn engine is planned to be removed from a future JDK release
summary + 563 in 00:00:19 = 30.3/s Avg: 298 Min: 73 Max: 1268 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary + 968 in 00:00:30 = 32.2/s Avg: 310 Min: 66 Max: 1172 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 1531 in 00:00:49 = 31.5/s Avg: 306 Min: 66 Max: 1268 Err: 0 (0.00%)
summary + 989 in 00:00:30 = 32.8/s Avg: 302 Min: 67 Max: 1172 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 2520 in 00:01:19 = 32.0/s Avg: 304 Min: 66 Max: 1268 Err: 0 (0.00%)
summary + 849 in 00:00:30 = 28.5/s Avg: 351 Min: 67 Max: 1113 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 3369 in 00:01:49 = 31.0/s Avg: 316 Min: 66 Max: 1268 Err: 0 (0.00%)
summary + 845 in 00:00:30 = 28.2/s Avg: 357 Min: 66 Max: 960 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 4214 in 00:02:19 = 30.4/s Avg: 324 Min: 66 Max: 1268 Err: 0 (0.00%)
summary + 799 in 00:00:30 = 26.6/s Avg: 374 Min: 68 Max: 1143 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 5013 in 00:02:49 = 29.7/s Avg: 332 Min: 66 Max: 1268 Err: 0 (0.00%)
summary + 1044 in 00:00:30 = 34.9/s Avg: 286 Min: 67 Max: 877 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 6057 in 00:03:19 = 30.5/s Avg: 324 Min: 66 Max: 1268 Err: 0 (0.00%)
summary + 832 in 00:00:30 = 27.7/s Avg: 359 Min: 68 Max: 1136 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 6889 in 00:03:49 = 30.1/s Avg: 328 Min: 66 Max: 1268 Err: 0 (0.00%)
summary + 875 in 00:00:30 = 29.2/s Avg: 343 Min: 72 Max: 1106 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 7764 in 00:04:19 = 30.0/s Avg: 330 Min: 66 Max: 1268 Err: 0 (0.00%)
summary + 937 in 00:00:30 = 31.2/s Avg: 320 Min: 67 Max: 972 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 8701 in 00:04:49 = 30.2/s Avg: 329 Min: 66 Max: 1268 Err: 0 (0.00%)
summary + 826 in 00:00:30 = 27.5/s Avg: 363 Min: 65 Max: 1259 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 9527 in 00:05:19 = 29.9/s Avg: 332 Min: 65 Max: 1268 Err: 0 (0.00%)
summary + 857 in 00:00:30 = 28.6/s Avg: 347 Min: 70 Max: 1215 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 10384 in 00:05:49 = 29.8/s Avg: 333 Min: 65 Max: 1268 Err: 0 (0.00%)
summary + 966 in 00:00:30 = 31.9/s Avg: 311 Min: 65 Max: 1216 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 11350 in 00:06:19 = 30.0/s Avg: 331 Min: 65 Max: 1268 Err: 0 (0.00%)
summary + 803 in 00:00:30 = 27.0/s Avg: 374 Min: 72 Max: 1252 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 12153 in 00:06:49 = 29.7/s Avg: 334 Min: 65 Max: 1268 Err: 0 (0.00%)
summary + 907 in 00:00:30 = 30.2/s Avg: 330 Min: 70 Max: 1346 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 13060 in 00:07:19 = 29.8/s Avg: 334 Min: 65 Max: 1346 Err: 0 (0.00%)
summary + 926 in 00:00:30 = 30.9/s Avg: 321 Min: 66 Max: 1120 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 13986 in 00:07:49 = 29.8/s Avg: 333 Min: 65 Max: 1346 Err: 0 (0.00%)
summary + 860 in 00:00:30 = 28.4/s Avg: 352 Min: 74 Max: 1082 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 14846 in 00:08:19 = 29.8/s Avg: 334 Min: 65 Max: 1346 Err: 0 (0.00%)
summary + 857 in 00:00:30 = 28.9/s Avg: 348 Min: 67 Max: 1338 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 15703 in 00:08:49 = 29.7/s Avg: 335 Min: 65 Max: 1346 Err: 0 (0.00%)
summary + 807 in 00:00:30 = 26.9/s Avg: 370 Min: 67 Max: 1515 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 16510 in 00:09:19 = 29.6/s Avg: 337 Min: 65 Max: 1515 Err: 0 (0.00%)
summary + 1017 in 00:00:30 = 33.9/s Avg: 296 Min: 71 Max: 1011 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 17527 in 00:09:49 = 29.8/s Avg: 334 Min: 65 Max: 1515 Err: 0 (0.00%)
summary + 998 in 00:00:30 = 33.3/s Avg: 300 Min: 66 Max: 1062 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 18525 in 00:10:19 = 29.9/s Avg: 332 Min: 65 Max: 1515 Err: 0 (0.00%)
summary + 880 in 00:00:30 = 29.3/s Avg: 339 Min: 75 Max: 1148 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 19405 in 00:10:49 = 29.9/s Avg: 333 Min: 65 Max: 1515 Err: 0 (0.00%)
summary + 1121 in 00:00:30 = 37.4/s Avg: 268 Min: 68 Max: 963 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 20526 in 00:11:19 = 30.2/s Avg: 329 Min: 65 Max: 1515 Err: 0 (0.00%)
summary + 967 in 00:00:30 = 32.2/s Avg: 301 Min: 66 Max: 1158 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 21493 in 00:11:49 = 30.3/s Avg: 328 Min: 65 Max: 1515 Err: 0 (0.00%)
summary + 738 in 00:00:30 = 24.5/s Avg: 417 Min: 74 Max: 21002 Err: 2 (0.27%) Active: 10 Started: 10 Finished: 0
summary = 22231 in 00:12:19 = 30.1/s Avg: 331 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 875 in 00:00:30 = 29.3/s Avg: 340 Min: 69 Max: 1361 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 23106 in 00:12:49 = 30.1/s Avg: 331 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 986 in 00:00:30 = 32.4/s Avg: 305 Min: 72 Max: 942 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 24092 in 00:13:19 = 30.2/s Avg: 330 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 958 in 00:00:30 = 32.4/s Avg: 313 Min: 65 Max: 1168 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 25050 in 00:13:49 = 30.2/s Avg: 329 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 904 in 00:00:30 = 30.1/s Avg: 330 Min: 70 Max: 863 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 25954 in 00:14:19 = 30.2/s Avg: 329 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 967 in 00:00:30 = 32.2/s Avg: 311 Min: 72 Max: 1106 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 26921 in 00:14:49 = 30.3/s Avg: 329 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 875 in 00:00:30 = 29.1/s Avg: 339 Min: 68 Max: 903 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 27796 in 00:15:19 = 30.3/s Avg: 329 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 761 in 00:00:30 = 25.4/s Avg: 396 Min: 65 Max: 1426 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 28557 in 00:15:49 = 30.1/s Avg: 331 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 905 in 00:00:30 = 29.8/s Avg: 332 Min: 65 Max: 1105 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 29462 in 00:16:19 = 30.1/s Avg: 331 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 958 in 00:00:30 = 32.3/s Avg: 311 Min: 69 Max: 989 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 30420 in 00:16:49 = 30.2/s Avg: 330 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 1213 in 00:00:30 = 40.1/s Avg: 248 Min: 66 Max: 831 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 31633 in 00:17:19 = 30.5/s Avg: 327 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 1172 in 00:00:30 = 39.3/s Avg: 253 Min: 66 Max: 1171 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 32805 in 00:17:49 = 30.7/s Avg: 324 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 782 in 00:00:30 = 26.1/s Avg: 383 Min: 67 Max: 1188 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 33587 in 00:18:19 = 30.6/s Avg: 326 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 955 in 00:00:30 = 31.8/s Avg: 312 Min: 68 Max: 886 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 34542 in 00:18:49 = 30.6/s Avg: 325 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 968 in 00:00:30 = 32.3/s Avg: 312 Min: 71 Max: 1024 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 35510 in 00:19:19 = 30.6/s Avg: 325 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 880 in 00:00:30 = 29.3/s Avg: 341 Min: 65 Max: 1223 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 36390 in 00:19:49 = 30.6/s Avg: 326 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 903 in 00:00:30 = 30.1/s Avg: 331 Min: 66 Max: 1191 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 37293 in 00:20:19 = 30.6/s Avg: 326 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 962 in 00:00:30 = 32.0/s Avg: 310 Min: 68 Max: 1293 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 38255 in 00:20:49 = 30.6/s Avg: 325 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 1036 in 00:00:30 = 34.6/s Avg: 289 Min: 66 Max: 1166 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 39291 in 00:21:19 = 30.7/s Avg: 324 Min: 65 Max: 21002 Err: 2 (0.01%)
summary + 860 in 00:00:30 = 28.6/s Avg: 350 Min: 70 Max: 1078 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 40151 in 00:21:49 = 30.7/s Avg: 325 Min: 65 Max: 21002 Err: 2 (0.00%)
summary + 938 in 00:00:30 = 31.1/s Avg: 320 Min: 67 Max: 1045 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 41089 in 00:22:19 = 30.7/s Avg: 325 Min: 65 Max: 21002 Err: 2 (0.00%)
summary + 930 in 00:00:30 = 31.2/s Avg: 320 Min: 70 Max: 1022 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 42019 in 00:22:49 = 30.7/s Avg: 325 Min: 65 Max: 21002 Err: 2 (0.00%)
summary + 876 in 00:00:30 = 29.1/s Avg: 343 Min: 74 Max: 1197 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 42895 in 00:23:19 = 30.7/s Avg: 325 Min: 65 Max: 21002 Err: 2 (0.00%)
summary + 965 in 00:00:30 = 32.3/s Avg: 309 Min: 65 Max: 1079 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 43860 in 00:23:49 = 30.7/s Avg: 325 Min: 65 Max: 21002 Err: 2 (0.00%)
summary + 971 in 00:00:30 = 32.4/s Avg: 309 Min: 68 Max: 1132 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 44831 in 00:24:19 = 30.7/s Avg: 324 Min: 65 Max: 21002 Err: 2 (0.00%)
summary + 1046 in 00:00:30 = 34.5/s Avg: 288 Min: 67 Max: 979 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 45877 in 00:24:49 = 30.8/s Avg: 323 Min: 65 Max: 21002 Err: 2 (0.00%)
summary + 1003 in 00:00:30 = 33.7/s Avg: 298 Min: 67 Max: 992 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 46880 in 00:25:19 = 30.9/s Avg: 323 Min: 65 Max: 21002 Err: 2 (0.00%)
summary + 928 in 00:00:30 = 30.9/s Avg: 318 Min: 67 Max: 1076 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 47808 in 00:25:49 = 30.9/s Avg: 323 Min: 65 Max: 21002 Err: 2 (0.00%)
summary + 740 in 00:00:30 = 24.7/s Avg: 411 Min: 70 Max: 1152 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 48548 in 00:26:19 = 30.8/s Avg: 324 Min: 65 Max: 21002 Err: 2 (0.00%)
summary + 789 in 00:00:30 = 26.3/s Avg: 375 Min: 64 Max: 1391 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 49337 in 00:26:49 = 30.7/s Avg: 325 Min: 64 Max: 21002 Err: 2 (0.00%)
summary + 1069 in 00:00:30 = 35.3/s Avg: 281 Min: 68 Max: 1202 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 50406 in 00:27:19 = 30.8/s Avg: 324 Min: 64 Max: 21002 Err: 2 (0.00%)
summary + 990 in 00:00:30 = 33.3/s Avg: 304 Min: 67 Max: 970 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 51396 in 00:27:49 = 30.8/s Avg: 324 Min: 64 Max: 21002 Err: 2 (0.00%)
summary + 878 in 00:00:30 = 29.3/s Avg: 341 Min: 76 Max: 922 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 52274 in 00:28:19 = 30.8/s Avg: 324 Min: 64 Max: 21002 Err: 2 (0.00%)
summary + 898 in 00:00:30 = 29.9/s Avg: 332 Min: 64 Max: 1133 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 53172 in 00:28:49 = 30.8/s Avg: 324 Min: 64 Max: 21002 Err: 2 (0.00%)
summary + 924 in 00:00:30 = 30.6/s Avg: 325 Min: 67 Max: 1200 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 54096 in 00:29:19 = 30.8/s Avg: 324 Min: 64 Max: 21002 Err: 2 (0.00%)
summary + 935 in 00:00:30 = 31.3/s Avg: 319 Min: 69 Max: 1066 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 55031 in 00:29:49 = 30.8/s Avg: 324 Min: 64 Max: 21002 Err: 2 (0.00%)
summary + 440 in 00:00:13 = 33.9/s Avg: 300 Min: 76 Max: 888 Err: 0 (0.00%) Active: 0 Started: 10 Finished: 10
summary = 55471 in 00:30:02 = 30.8/s Avg: 324 Min: 64 Max: 21002 Err: 2 (0.00%)
Tidying up ... @ Fri Dec 13 11:42:13 CST 2019 (1576208533013)
... end of run
使用 jinfo 查看 jvm 参数
$ jinfo 4441
Attaching to process ID 4441, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.161-b12
Java System Properties:
......
VM Flags:
Non-default VM flags: -XX:CICompilerCount=3 -XX:+CMSClassUnloadingEnabled -XX:CMSInitiatingOccupancyFraction=65 -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=null -XX:InitialHeapSize=4294967296 -XX:+ManagementServer -XX:MaxHeapSize=4294967296 -XX:MaxMetaspaceSize=536870912 -XX:MaxNewSize=1073741824 -XX:MaxTenuringThreshold=15 -XX:MetaspaceSize=536870912 -XX:MinHeapDeltaBytes=196608 -XX:NewSize=1073741824 -XX:OldPLABSize=16 -XX:OldSize=3221225472 -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:SurvivorRatio=6 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC
Command line: -Xmn1024m -Xms4096m -Xmx4096m -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -XX:MaxTenuringThreshold=15 -XX:SurvivorRatio=6 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:CMSInitiatingOccupancyFraction=65 -XX:+UseCMSInitiatingOccupancyOnly -XX:+CMSClassUnloadingEnabled -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses -XX:+PrintTenuringDistribution -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/data/logs/xxx/gc/zuul-sit-garbage-collection.log -XX:+PrintCommandLineFlags -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/xxx/dump/zuul-sit-java_heapdump.hprof -Dapollo.meta=http://10.29.36.3:8080 -Dcom.sun.management.jmxremote.port=9999 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false
使用 jmap -heap 查看堆内存情况
新生代内存及老年代内存分布合理，Survivor 空间较大应该不存在溢出可能
$jmap -heap 4441
Attaching to process ID 4441, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.161-b12
using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC
Heap Configuration:
MinHeapFreeRatio = 40
MaxHeapFreeRatio = 70
MaxHeapSize = 4294967296 (4096.0MB)
NewSize = 1073741824 (1024.0MB)
MaxNewSize = 1073741824 (1024.0MB)
OldSize = 3221225472 (3072.0MB)
NewRatio = 2
SurvivorRatio = 6
MetaspaceSize = 536870912 (512.0MB)
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 536870912 (512.0MB)
G1HeapRegionSize = 0 (0.0MB)
Heap Usage:
New Generation (Eden + 1 Survivor Space):
capacity = 939524096 (896.0MB)
used = 453480288 (432.4725036621094MB)
free = 486043808 (463.5274963378906MB)
48.267020498003276% used
Eden Space:
capacity = 805306368 (768.0MB)
used = 443029624 (422.50597381591797MB)
free = 362276744 (345.49402618408203MB)
55.013798673947655% used
From Space:
capacity = 134217728 (128.0MB)
used = 10450664 (9.966529846191406MB)
free = 123767064 (118.0334701538086MB)
7.786351442337036% used
To Space:
capacity = 134217728 (128.0MB)
used = 0 (0.0MB)
free = 134217728 (128.0MB)
0.0% used
concurrent mark-sweep generation:
capacity = 3221225472 (3072.0MB)
used = 82530968 (78.7076644897461MB)
free = 3138694504 (2993.292335510254MB)
2.5620984534422555% used
46204 interned Strings occupying 5696544 bytes.
使用 jstat 查看 GC 情况
没有老年代 GC,新生代 GC 频率在 18S/次，一次 YGC 耗时在 0.031s
$ jstat -gc 4441 1000 10000
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
131072.0 131072.0 11046.0 0.0 786432.0 322479.5 3145728.0 79671.0 99200.0 94661.4 12928.0 12080.7 44 2.022 0 0.000 2.022
131072.0 131072.0 11046.0 0.0 786432.0 375862.8 3145728.0 79671.0 99200.0 94661.4 12928.0 12080.7 44 2.022 0 0.000 2.022
131072.0 131072.0 11046.0 0.0 786432.0 428974.7 3145728.0 79671.0 99200.0 94661.4 12928.0 12080.7 44 2.022 0 0.000 2.022
131072.0 131072.0 11046.0 0.0 786432.0 469273.7 3145728.0 79671.0 99200.0 94661.4 12928.0 12080.7 44 2.022 0 0.000 2.022
131072.0 131072.0 11046.0 0.0 786432.0 508063.9 3145728.0 79671.0 99200.0 94661.4 12928.0 12080.7 44 2.022 0 0.000 2.022
131072.0 131072.0 11046.0 0.0 786432.0 540068.0 3145728.0 79671.0 99200.0 94661.4 12928.0 12080.7 44 2.022 0 0.000 2.022
131072.0 131072.0 11046.0 0.0 786432.0 591452.8 3145728.0 79671.0 99200.0 94661.4 12928.0 12080.7 44 2.022 0 0.000 2.022
131072.0 131072.0 11046.0 0.0 786432.0 623320.3 3145728.0 79671.0 99200.0 94661.4 12928.0 12080.7 44 2.022 0 0.000 2.022
131072.0 131072.0 11046.0 0.0 786432.0 648622.4 3145728.0 79671.0 99200.0 94661.4 12928.0 12080.7 44 2.022 0 0.000 2.022
131072.0 131072.0 11046.0 0.0 786432.0 691081.9 3145728.0 79671.0 99200.0 94661.4 12928.0 12080.7 44 2.022 0 0.000 2.022
131072.0 131072.0 11046.0 0.0 786432.0 722491.2 3145728.0 79671.0 99200.0 94661.4 12928.0 12080.7 44 2.022 0 0.000 2.022
131072.0 131072.0 11046.0 0.0 786432.0 752811.6 3145728.0 79671.0 99200.0 94661.4 12928.0 12080.7 44 2.022 0 0.000 2.022
131072.0 131072.0 11046.0 0.0 786432.0 785398.5 3145728.0 79671.0 99200.0 94661.4 12928.0 12080.7 45 2.022 0 0.000 2.022
131072.0 131072.0 0.0 10823.3 786432.0 53869.6 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 102255.4 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 143168.4 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 194015.1 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 230944.1 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 296609.0 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 346729.9 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 396746.0 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 439339.5 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 496687.3 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 537191.4 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 589712.9 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 627099.3 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 654386.6 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 709031.9 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 738114.6 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 0.0 10823.3 786432.0 764832.3 3145728.0 79723.3 99200.0 94676.5 12928.0 12080.7 45 2.053 0 0.000 2.053
131072.0 131072.0 7679.0 0.0 786432.0 39947.3 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 76661.1 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 128073.0 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 172306.4 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 225913.6 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 275137.2 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 303857.2 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 343776.0 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 377306.2 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 421184.0 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 485130.2 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 521003.2 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 562271.8 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 603153.8 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 635340.1 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
131072.0 131072.0 7679.0 0.0 786432.0 678719.9 3145728.0 79802.1 99200.0 94682.8 12928.0 12081.2 46 2.079 0 0.000 2.079
使用 jmap -histo 查看堆内对象分布
没有见明显异常的占用空间较大的对象，但由于只测试了 3 个高频 API 接口，而生产上 Sentinel dashboard 显示存在 120 个 API 接口，存在在接口增长后出现大量 sentinel 及 prometheus 相关对象的可能。
$ jmap -histo 4441|more
num #instances #bytes class name
----------------------------------------------
1: 712570 98963552 [C
2: 32894 33451296 [I
3: 78363 12556848 [B
4: 475895 11421480 java.lang.String
5: 218021 9260728 [Ljava.lang.Object;
6: 66549 5856312 java.lang.reflect.Method
7: 163063 5218016 java.util.concurrent.ConcurrentHashMap$Node
8: 122845 4913800 java.util.LinkedHashMap$Entry
9: 2774 4144416 [J
10: 39461 4065944 [Ljava.util.HashMap$Node;
11: 110501 3536032 java.util.HashMap$Node
12: 65153 3127344 org.aspectj.weaver.reflect.ShadowMatchImpl
13: 44576 2852864 java.net.URL
14: 86969 2783008 org.springframework.boot.loader.jar.StringSequence
15: 56959 2278360 java.util.TreeMap$Entry
16: 19772 2179904 java.lang.Class
17: 88234 2117616 java.lang.StringBuffer
稳定态 GC 日志查询
新生代 GC 频率在 20s/次，新生代平均耗时在 0.035s 左右，没有提前对象晋升的情况。没有 Full GC.
2019-12-13T11:13:06.866+0800: 714.481: [GC (Allocation Failure) 2019-12-13T11:13:06.866+0800: 714.482: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 5486000 bytes, 5486000 total
- age 2: 1587128 bytes, 7073128 total
- age 3: 3359208 bytes, 10432336 total
- age 4: 8707984 bytes, 19140320 total
- age 5: 1385232 bytes, 20525552 total
- age 6: 4915184 bytes, 25440736 total
- age 7: 1561152 bytes, 27001888 total
- age 8: 1527272 bytes, 28529160 total
- age 9: 1552744 bytes, 30081904 total
- age 10: 1547520 bytes, 31629424 total
- age 11: 3776456 bytes, 35405880 total
- age 12: 5870512 bytes, 41276392 total
- age 13: 3000728 bytes, 44277120 total
- age 14: 2236808 bytes, 46513928 total
- age 15: 2933688 bytes, 49447616 total
: 871157K->61526K(917504K), 0.0671772 secs] 905293K->98536K(4063232K), 0.0684356 secs] [Times: user=0.24 sys=0.00, real=0.07 secs]
2019-12-13T11:13:22.691+0800: 730.306: [GC (Allocation Failure) 2019-12-13T11:13:22.691+0800: 730.307: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 6776192 bytes, 6776192 total
- age 2: 1419936 bytes, 8196128 total
- age 3: 1222760 bytes, 9418888 total
- age 4: 3029048 bytes, 12447936 total
- age 5: 8543912 bytes, 20991848 total
- age 6: 1385232 bytes, 22377080 total
- age 7: 4903920 bytes, 27281000 total
- age 8: 1561152 bytes, 28842152 total
- age 9: 1527128 bytes, 30369280 total
- age 10: 1552744 bytes, 31922024 total
- age 11: 1547488 bytes, 33469512 total
- age 12: 3776576 bytes, 37246088 total
- age 13: 5870648 bytes, 43116736 total
- age 14: 3000728 bytes, 46117464 total
- age 15: 2236808 bytes, 48354272 total
: 847958K->65736K(917504K), 0.0607406 secs] 884968K->105669K(4063232K), 0.0620571 secs] [Times: user=0.21 sys=0.00, real=0.07 secs]
2019-12-13T11:13:40.535+0800: 748.151: [GC (Allocation Failure) 2019-12-13T11:13:40.535+0800: 748.151: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 7097328 bytes, 7097328 total
- age 2: 963208 bytes, 8060536 total
- age 3: 1004200 bytes, 9064736 total
- age 4: 883848 bytes, 9948584 total
- age 5: 2890328 bytes, 12838912 total
- age 6: 8414960 bytes, 21253872 total
- age 7: 1385232 bytes, 22639104 total
- age 8: 4903280 bytes, 27542384 total
- age 9: 1561152 bytes, 29103536 total
- age 10: 1527128 bytes, 30630664 total
- age 11: 1552744 bytes, 32183408 total
- age 12: 1547488 bytes, 33730896 total
- age 13: 3776352 bytes, 37507248 total
- age 14: 5870512 bytes, 43377760 total
- age 15: 3000768 bytes, 46378528 total
: 852168K->69419K(917504K), 0.0557614 secs] 892101K->111566K(4063232K), 0.0571392 secs] [Times: user=0.20 sys=0.01, real=0.06 secs]
2019-12-13T11:13:59.841+0800: 767.456: [GC (Allocation Failure) 2019-12-13T11:13:59.841+0800: 767.457: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 2951152 bytes, 2951152 total
- age 2: 1177136 bytes, 4128288 total
- age 3: 587888 bytes, 4716176 total
- age 4: 595712 bytes, 5311888 total
- age 5: 804592 bytes, 6116480 total
- age 6: 2890328 bytes, 9006808 total
- age 7: 8384616 bytes, 17391424 total
- age 8: 1384912 bytes, 18776336 total
- age 9: 4903280 bytes, 23679616 total
- age 10: 1561152 bytes, 25240768 total
- age 11: 1527128 bytes, 26767896 total
- age 12: 1552744 bytes, 28320640 total
- age 13: 1547488 bytes, 29868128 total
- age 14: 3776624 bytes, 33644752 total
- age 15: 5870752 bytes, 39515504 total
: 855066K->45561K(917504K), 0.0510823 secs] 897212K->90677K(4063232K), 0.0523193 secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
2019-12-13T11:14:18.356+0800: 785.972: [GC (Allocation Failure) 2019-12-13T11:14:18.357+0800: 785.972: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 6872256 bytes, 6872256 total
- age 2: 993064 bytes, 7865320 total
- age 3: 799696 bytes, 8665016 total
- age 4: 219576 bytes, 8884592 total
- age 5: 449840 bytes, 9334432 total
- age 6: 788048 bytes, 10122480 total
- age 7: 2890328 bytes, 13012808 total
- age 8: 8317872 bytes, 21330680 total
- age 9: 1384912 bytes, 22715592 total
- age 10: 4903352 bytes, 27618944 total
- age 11: 1561152 bytes, 29180096 total
- age 12: 1527128 bytes, 30707224 total
- age 13: 1552744 bytes, 32259968 total
- age 14: 1547520 bytes, 33807488 total
- age 15: 3776608 bytes, 37584096 total
: 831993K->50312K(917504K), 0.0610168 secs] 877109K->101240K(4063232K), 0.0624417 secs] [Times: user=0.20 sys=0.01, real=0.06 secs]
2019-12-13T11:14:37.887+0800: 805.503: [GC (Allocation Failure) 2019-12-13T11:14:37.888+0800: 805.503: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 2913888 bytes, 2913888 total
- age 2: 1111488 bytes, 4025376 total
- age 3: 609168 bytes, 4634544 total
- age 4: 251728 bytes, 4886272 total
- age 5: 203024 bytes, 5089296 total
- age 6: 431088 bytes, 5520384 total
- age 7: 782944 bytes, 6303328 total
- age 8: 2890264 bytes, 9193592 total
- age 9: 8277960 bytes, 17471552 total
- age 10: 1384912 bytes, 18856464 total
- age 11: 4901656 bytes, 23758120 total
- age 12: 1561152 bytes, 25319272 total
- age 13: 1527128 bytes, 26846400 total
- age 14: 1552744 bytes, 28399144 total
- age 15: 1547488 bytes, 29946632 total
: 836744K->37619K(917504K), 0.0435036 secs] 887672K->92332K(4063232K), 0.0447698 secs] [Times: user=0.15 sys=0.00, real=0.05 secs]
2019-12-13T11:14:57.963+0800: 825.579: [GC (Allocation Failure) 2019-12-13T11:14:57.964+0800: 825.580: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 4736896 bytes, 4736896 total
- age 2: 991176 bytes, 5728072 total
- age 3: 714768 bytes, 6442840 total
- age 4: 124696 bytes, 6567536 total
- age 5: 206344 bytes, 6773880 total
- age 6: 199344 bytes, 6973224 total
- age 7: 426432 bytes, 7399656 total
- age 8: 782992 bytes, 8182648 total
- age 9: 2890568 bytes, 11073216 total
- age 10: 8265712 bytes, 19338928 total
- age 11: 1384912 bytes, 20723840 total
- age 12: 4901120 bytes, 25624960 total
- age 13: 1561152 bytes, 27186112 total
- age 14: 1527128 bytes, 28713240 total
- age 15: 1552744 bytes, 30265984 total
: 824051K->46796K(917504K), 0.0399734 secs] 878764K->103070K(4063232K), 0.0411551 secs] [Times: user=0.14 sys=0.00, real=0.04 secs]
2019-12-13T11:15:12.776+0800: 840.392: [GC (Allocation Failure) 2019-12-13T11:15:12.777+0800: 840.392: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 5174432 bytes, 5174432 total
- age 2: 1129208 bytes, 6303640 total
- age 3: 613408 bytes, 6917048 total
- age 4: 298624 bytes, 7215672 total
- age 5: 91488 bytes, 7307160 total
- age 6: 185408 bytes, 7492568 total
- age 7: 193920 bytes, 7686488 total
- age 8: 426432 bytes, 8112920 total
- age 9: 782992 bytes, 8895912 total
- age 10: 2890152 bytes, 11786064 total
- age 11: 8265232 bytes, 20051296 total
- age 12: 1384912 bytes, 21436208 total
- age 13: 4901192 bytes, 26337400 total
- age 14: 1561152 bytes, 27898552 total
- age 15: 1527128 bytes, 29425680 total
: 833228K->44813K(917504K), 0.0461198 secs] 889502K->102658K(4063232K), 0.0473808 secs] [Times: user=0.14 sys=0.00, real=0.05 secs]
2019-12-13T11:15:29.245+0800: 856.861: [GC (Allocation Failure) 2019-12-13T11:15:29.245+0800: 856.861: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 4589320 bytes, 4589320 total
- age 2: 973864 bytes, 5563184 total
- age 3: 744888 bytes, 6308072 total
- age 4: 231896 bytes, 6539968 total
- age 5: 152912 bytes, 6692880 total
- age 6: 87696 bytes, 6780576 total
- age 7: 96160 bytes, 6876736 total
- age 8: 193824 bytes, 7070560 total
- age 9: 425328 bytes, 7495888 total
- age 10: 783320 bytes, 8279208 total
- age 11: 2890480 bytes, 11169688 total
- age 12: 8265048 bytes, 19434736 total
- age 13: 1367240 bytes, 20801976 total
- age 14: 4901120 bytes, 25703096 total
- age 15: 1561152 bytes, 27264248 total
: 831245K->43358K(917504K), 0.0379752 secs] 889090K->102746K(4063232K), 0.0391689 secs] [Times: user=0.13 sys=0.00, real=0.04 secs]
......
2019-12-13T11:39:20.483+0800: 2288.099: [GC (Allocation Failure) 2019-12-13T11:39:20.484+0800: 2288.099: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 3055976 bytes, 3055976 total
- age 2: 991144 bytes, 4047120 total
- age 3: 666200 bytes, 4713320 total
- age 4: 181224 bytes, 4894544 total
- age 5: 131400 bytes, 5025944 total
- age 6: 228904 bytes, 5254848 total
- age 7: 98248 bytes, 5353096 total
- age 8: 111368 bytes, 5464464 total
- age 9: 88792 bytes, 5553256 total
- age 10: 70136 bytes, 5623392 total
- age 11: 104584 bytes, 5727976 total
- age 12: 57880 bytes, 5785856 total
- age 13: 38944 bytes, 5824800 total
- age 14: 41760 bytes, 5866560 total
- age 15: 48768 bytes, 5915328 total
: 793803K->7868K(917504K), 0.0225761 secs] 878546K->92651K(4063232K), 0.0237404 secs] [Times: user=0.09 sys=0.00, real=0.02 secs]
2019-12-13T11:39:35.246+0800: 2302.862: [GC (Allocation Failure) 2019-12-13T11:39:35.247+0800: 2302.863: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 5120600 bytes, 5120600 total
- age 2: 1018128 bytes, 6138728 total
- age 3: 627160 bytes, 6765888 total
- age 4: 238320 bytes, 7004208 total
- age 5: 130184 bytes, 7134392 total
- age 6: 126552 bytes, 7260944 total
- age 7: 189960 bytes, 7450904 total
- age 8: 97696 bytes, 7548600 total
- age 9: 111368 bytes, 7659968 total
- age 10: 88792 bytes, 7748760 total
- age 11: 70136 bytes, 7818896 total
- age 12: 72424 bytes, 7891320 total
- age 13: 38368 bytes, 7929688 total
- age 14: 38944 bytes, 7968632 total
- age 15: 41760 bytes, 8010392 total
: 794300K->9618K(917504K), 0.0265646 secs] 879083K->94450K(4063232K), 0.0277991 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]
2019-12-13T11:39:52.832+0800: 2320.448: [GC (Allocation Failure) 2019-12-13T11:39:52.833+0800: 2320.448: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 2976656 bytes, 2976656 total
- age 2: 1032016 bytes, 4008672 total
- age 3: 587984 bytes, 4596656 total
- age 4: 312384 bytes, 4909040 total
- age 5: 109008 bytes, 5018048 total
- age 6: 111144 bytes, 5129192 total
- age 7: 111152 bytes, 5240344 total
- age 8: 161736 bytes, 5402080 total
- age 9: 81176 bytes, 5483256 total
- age 10: 94848 bytes, 5578104 total
- age 11: 88792 bytes, 5666896 total
- age 12: 54296 bytes, 5721192 total
- age 13: 47344 bytes, 5768536 total
- age 14: 38368 bytes, 5806904 total
- age 15: 38944 bytes, 5845848 total
: 796050K->9007K(917504K), 0.0241335 secs] 880882K->93882K(4063232K), 0.0253620 secs] [Times: user=0.09 sys=0.00, real=0.02 secs]
2019-12-13T11:40:11.585+0800: 2339.201: [GC (Allocation Failure) 2019-12-13T11:40:11.585+0800: 2339.201: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 3016528 bytes, 3016528 total
- age 2: 913112 bytes, 3929640 total
- age 3: 609216 bytes, 4538856 total
- age 4: 232600 bytes, 4771456 total
- age 5: 148648 bytes, 4920104 total
- age 6: 90760 bytes, 5010864 total
- age 7: 93472 bytes, 5104336 total
- age 8: 111152 bytes, 5215488 total
- age 9: 144664 bytes, 5360152 total
- age 10: 80624 bytes, 5440776 total
- age 11: 94296 bytes, 5535072 total
- age 12: 64456 bytes, 5599528 total
- age 13: 29528 bytes, 5629056 total
- age 14: 47344 bytes, 5676400 total
- age 15: 38368 bytes, 5714768 total
: 795439K->8944K(917504K), 0.0245796 secs] 880314K->93858K(4063232K), 0.0257438 secs] [Times: user=0.09 sys=0.00, real=0.02 secs]
2019-12-13T11:40:29.059+0800: 2356.675: [GC (Allocation Failure) 2019-12-13T11:40:29.060+0800: 2356.676: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 2914000 bytes, 2914000 total
- age 2: 1047120 bytes, 3961120 total
- age 3: 513096 bytes, 4474216 total
- age 4: 206784 bytes, 4681000 total
- age 5: 162432 bytes, 4843432 total
- age 6: 146320 bytes, 4989752 total
- age 7: 90040 bytes, 5079792 total
- age 8: 92824 bytes, 5172616 total
- age 9: 111104 bytes, 5283720 total
- age 10: 127592 bytes, 5411312 total
- age 11: 80624 bytes, 5491936 total
- age 12: 67872 bytes, 5559808 total
- age 13: 49048 bytes, 5608856 total
- age 14: 29528 bytes, 5638384 total
- age 15: 47344 bytes, 5685728 total
: 795376K->9665K(917504K), 0.0256483 secs] 880290K->94618K(4063232K), 0.0268120 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]
2019-12-13T11:40:48.644+0800: 2376.260: [GC (Allocation Failure) 2019-12-13T11:40:48.645+0800: 2376.261: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 3069848 bytes, 3069848 total
- age 2: 966712 bytes, 4036560 total
- age 3: 641456 bytes, 4678016 total
- age 4: 138256 bytes, 4816272 total
- age 5: 104088 bytes, 4920360 total
- age 6: 141784 bytes, 5062144 total
- age 7: 134688 bytes, 5196832 total
- age 8: 89776 bytes, 5286608 total
- age 9: 92824 bytes, 5379432 total
- age 10: 94584 bytes, 5474016 total
- age 11: 110520 bytes, 5584536 total
- age 12: 45992 bytes, 5630528 total
- age 13: 53472 bytes, 5684000 total
- age 14: 38984 bytes, 5722984 total
- age 15: 29528 bytes, 5752512 total
: 796097K->6914K(917504K), 0.0275711 secs] 881050K->91915K(4063232K), 0.0288077 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]
2019-12-13T11:41:05.861+0800: 2393.476: [GC (Allocation Failure) 2019-12-13T11:41:05.862+0800: 2393.477: [ParNew
Desired survivor size 67108864 bytes, new threshold 15 (max 15)
- age 1: 4679048 bytes, 4679048 total
- age 2: 1108432 bytes, 5787480 total
- age 3: 589816 bytes, 6377296 total
- age 4: 118736 bytes, 6496032 total
- age 5: 137656 bytes, 6633688 total
- age 6: 81472 bytes, 6715160 total
- age 7: 93584 bytes, 6808744 total
- age 8: 118168 bytes, 6926912 total
- age 9: 89776 bytes, 7016688 total
- age 10: 92824 bytes, 7109512 total
- age 11: 94032 bytes, 7203544 total
- age 12: 78288 bytes, 7281832 total
- age 13: 41096 bytes, 7322928 total
- age 14: 53472 bytes, 7376400 total
- age 15: 38984 bytes, 7415384 total
: 793346K->9101K(917504K), 0.0279328 secs] 878347K->94132K(4063232K), 0.0293894 secs] [Times: user=0.09 sys=0.01, real=0.03 secs]
查看 Jmeter 压力测试报告
查看 Jmeter 压力测试报告，应用吞吐量存在下降。
再次调整新生代内存参数，优化吞吐量目标
启动命令
主要调整项目如下：
- 增大新生代大小，同时增大堆大小，保持老年代大小不变。
- 减小 Survivor 区大小占比，以提高 Eden+From Survivor 区大小。
- 降低初始元数据区大小，128M 的空间足够，应该不会产生扩容。
nohup java -server -Xmn1536m -Xms4608m -Xmx4608m -XX:MetaspaceSize=128m -XX:MaxMetaspaceSize=512m\
-XX:MaxTenuringThreshold=15 -XX:SurvivorRatio=8\
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC\
-XX:CMSInitiatingOccupancyFraction=65 -XX:+UseCMSInitiatingOccupancyOnly -XX:+CMSClassUnloadingEnabled\
-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses\
-XX:+PrintTenuringDistribution -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/data/logs/xxx/gc/zuul-sit-garbage-collection.log\
-XX:+PrintCommandLineFlags\
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/xxx/dump/zuul-sit-java_heapdump.hprof\
-Dapollo.meta=http://10.29.36.3:8080\
-Dcom.sun.management.jmxremote.port=9999 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false\
-jar /home/loginuser/xxx-ms/app/zuul-0.0.1.jar --spring.profiles.active=fat --debug=true\
>/dev/null 2>&1 &
启动 Jmeter 压力测试
吞吐量目标达到
C:\Users\wuby>jmeter -n -t "D:\java\jmeter\TestPlan\ZullTestPlan.jmx" -l "D:\java\jmeter\TestPlan\ZullTestPlan-sit2.csv" -e -o "D:\java\jmeter\TestPlan\ZullTestPlanSIT2"
Creating summariser <summary>
Created the tree successfully using D:\java\jmeter\TestPlan\Zull Test Plan.jmx
Starting standalone test @ Fri Dec 13 12:16:42 CST 2019 (1576210602279)
Waiting for possible Shutdown/StopTestNow/HeapDump/ThreadDump message on port 4445
Warning: Nashorn engine is planned to be removed from a future JDK release
summary + 1006 in 00:00:17 = 57.9/s Avg: 154 Min: 65 Max: 1007 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary + 2063 in 00:00:30 = 68.8/s Avg: 145 Min: 64 Max: 513 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 3069 in 00:00:47 = 64.8/s Avg: 148 Min: 64 Max: 1007 Err: 0 (0.00%)
summary + 2077 in 00:00:30 = 69.0/s Avg: 144 Min: 64 Max: 508 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 5146 in 00:01:17 = 66.4/s Avg: 146 Min: 64 Max: 1007 Err: 0 (0.00%)
summary + 2087 in 00:00:30 = 69.7/s Avg: 143 Min: 63 Max: 536 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 7233 in 00:01:47 = 67.4/s Avg: 145 Min: 63 Max: 1007 Err: 0 (0.00%)
summary + 1877 in 00:00:30 = 62.5/s Avg: 159 Min: 62 Max: 3692 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 9110 in 00:02:17 = 66.3/s Avg: 148 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2100 in 00:00:30 = 70.1/s Avg: 142 Min: 64 Max: 536 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 11210 in 00:02:47 = 67.0/s Avg: 147 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2098 in 00:00:30 = 70.0/s Avg: 142 Min: 64 Max: 537 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 13308 in 00:03:17 = 67.4/s Avg: 146 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2107 in 00:00:30 = 70.3/s Avg: 142 Min: 63 Max: 530 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 15415 in 00:03:47 = 67.8/s Avg: 146 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2099 in 00:00:30 = 70.0/s Avg: 142 Min: 63 Max: 514 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 17514 in 00:04:17 = 68.1/s Avg: 145 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2120 in 00:00:30 = 70.7/s Avg: 141 Min: 64 Max: 564 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 19634 in 00:04:47 = 68.3/s Avg: 145 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2099 in 00:00:30 = 69.9/s Avg: 143 Min: 63 Max: 543 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 21733 in 00:05:17 = 68.5/s Avg: 145 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2107 in 00:00:30 = 70.2/s Avg: 142 Min: 63 Max: 514 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 23840 in 00:05:47 = 68.6/s Avg: 144 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2104 in 00:00:30 = 70.2/s Avg: 142 Min: 63 Max: 505 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 25944 in 00:06:17 = 68.8/s Avg: 144 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2091 in 00:00:30 = 69.6/s Avg: 143 Min: 64 Max: 502 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 28035 in 00:06:47 = 68.8/s Avg: 144 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2094 in 00:00:30 = 69.8/s Avg: 143 Min: 63 Max: 499 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 30129 in 00:07:17 = 68.9/s Avg: 144 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2099 in 00:00:30 = 69.8/s Avg: 142 Min: 63 Max: 593 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 32228 in 00:07:47 = 68.9/s Avg: 144 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2099 in 00:00:30 = 70.1/s Avg: 142 Min: 62 Max: 522 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 34327 in 00:08:17 = 69.0/s Avg: 144 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2092 in 00:00:30 = 69.8/s Avg: 143 Min: 62 Max: 633 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 36419 in 00:08:47 = 69.1/s Avg: 144 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2099 in 00:00:30 = 70.0/s Avg: 142 Min: 63 Max: 577 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 38518 in 00:09:17 = 69.1/s Avg: 144 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2089 in 00:00:30 = 69.7/s Avg: 143 Min: 62 Max: 557 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 40607 in 00:09:47 = 69.1/s Avg: 144 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2110 in 00:00:30 = 70.3/s Avg: 142 Min: 63 Max: 523 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 42717 in 00:10:17 = 69.2/s Avg: 143 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2094 in 00:00:30 = 69.8/s Avg: 143 Min: 62 Max: 515 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 44811 in 00:10:47 = 69.2/s Avg: 143 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2102 in 00:00:30 = 70.1/s Avg: 142 Min: 64 Max: 505 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 46913 in 00:11:17 = 69.3/s Avg: 143 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2094 in 00:00:30 = 69.8/s Avg: 142 Min: 63 Max: 538 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 49007 in 00:11:47 = 69.3/s Avg: 143 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2104 in 00:00:30 = 70.0/s Avg: 142 Min: 63 Max: 516 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 51111 in 00:12:17 = 69.3/s Avg: 143 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2094 in 00:00:30 = 69.8/s Avg: 143 Min: 63 Max: 550 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 53205 in 00:12:47 = 69.3/s Avg: 143 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2092 in 00:00:30 = 69.8/s Avg: 143 Min: 63 Max: 536 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 55297 in 00:13:17 = 69.3/s Avg: 143 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2086 in 00:00:30 = 69.5/s Avg: 143 Min: 64 Max: 546 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 57383 in 00:13:47 = 69.4/s Avg: 143 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 2100 in 00:00:30 = 70.0/s Avg: 142 Min: 64 Max: 527 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
summary = 59483 in 00:14:17 = 69.4/s Avg: 143 Min: 62 Max: 3692 Err: 0 (0.00%)
summary + 517 in 00:00:10 = 50.7/s Avg: 141 Min: 65 Max: 570 Err: 0 (0.00%) Active: 0 Started: 10 Finished: 10
summary = 60000 in 00:14:28 = 69.2/s Avg: 143 Min: 62 Max: 3692 Err: 0 (0.00%)
Tidying up ... @ Fri Dec 13 12:31:10 CST 2019 (1576211470241)
... end of run
查看 GC 日志
查看 GC 日志，MinorGC 频率在 15s/次，平均延迟在 0.035s 左右，没有 MajorGC。
GC 日志见 zuul-sit-garbage-collection.log
2019-12-13T12:23:04.089+0800: 537.679: [GC (Allocation Failure) 2019-12-13T12:23:04.090+0800: 537.680: [ParNew
Desired survivor size 80510976 bytes, new threshold 15 (max 15)
- age 1: 4189088 bytes, 4189088 total
- age 2: 765008 bytes, 4954096 total
- age 3: 301432 bytes, 5255528 total
- age 4: 151264 bytes, 5406792 total
- age 5: 159600 bytes, 5566392 total
- age 6: 76304 bytes, 5642696 total
- age 7: 75424 bytes, 5718120 total
- age 8: 74048 bytes, 5792168 total
- age 9: 74576 bytes, 5866744 total
- age 10: 74368 bytes, 5941112 total
- age 11: 80912 bytes, 6022024 total
- age 12: 75008 bytes, 6097032 total
- age 13: 75208 bytes, 6172240 total
- age 14: 74784 bytes, 6247024 total
- age 15: 29808 bytes, 6276832 total
: 1267079K->8947K(1415616K), 0.0343768 secs] 1345925K->87854K(4561344K), 0.0360069 secs] [Times: user=0.11 sys=0.00, real=0.04 secs]
2019-12-13T12:23:18.447+0800: 552.037: [GC (Allocation Failure) 2019-12-13T12:23:18.448+0800: 552.037: [ParNew
Desired survivor size 80510976 bytes, new threshold 15 (max 15)
- age 1: 4296184 bytes, 4296184 total
- age 2: 771112 bytes, 5067296 total
- age 3: 265416 bytes, 5332712 total
- age 4: 232256 bytes, 5564968 total
- age 5: 77720 bytes, 5642688 total
- age 6: 75144 bytes, 5717832 total
- age 7: 76280 bytes, 5794112 total
- age 8: 75424 bytes, 5869536 total
- age 9: 73984 bytes, 5943520 total
- age 10: 74576 bytes, 6018096 total
- age 11: 74368 bytes, 6092464 total
- age 12: 80912 bytes, 6173376 total
- age 13: 75008 bytes, 6248384 total
- age 14: 74200 bytes, 6322584 total
- age 15: 29856 bytes, 6352440 total
: 1267315K->10192K(1415616K), 0.0275319 secs] 1346222K->89102K(4561344K), 0.0288281 secs] [Times: user=0.10 sys=0.00, real=0.03 secs]
2019-12-13T12:23:32.671+0800: 566.261: [GC (Allocation Failure) 2019-12-13T12:23:32.672+0800: 566.262: [ParNew
Desired survivor size 80510976 bytes, new threshold 15 (max 15)
- age 1: 4311672 bytes, 4311672 total
- age 2: 754336 bytes, 5066008 total
- age 3: 271880 bytes, 5337888 total
- age 4: 196952 bytes, 5534840 total
- age 5: 143232 bytes, 5678072 total
- age 6: 77720 bytes, 5755792 total
- age 7: 74592 bytes, 5830384 total
- age 8: 76280 bytes, 5906664 total
- age 9: 75424 bytes, 5982088 total
- age 10: 73984 bytes, 6056072 total
- age 11: 74576 bytes, 6130648 total
- age 12: 74368 bytes, 6205016 total
- age 13: 80912 bytes, 6285928 total
- age 14: 75008 bytes, 6360936 total
- age 15: 28768 bytes, 6389704 total
: 1268560K->8387K(1415616K), 0.0277973 secs] 1347470K->87301K(4561344K), 0.0291240 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]
2019-12-13T12:23:47.010+0800: 580.600: [GC (Allocation Failure) 2019-12-13T12:23:47.011+0800: 580.600: [ParNew
Desired survivor size 80510976 bytes, new threshold 15 (max 15)
- age 1: 4451320 bytes, 4451320 total
- age 2: 757984 bytes, 5209304 total
- age 3: 265392 bytes, 5474696 total
- age 4: 181336 bytes, 5656032 total
- age 5: 90920 bytes, 5746952 total
- age 6: 74744 bytes, 5821696 total
- age 7: 77688 bytes, 5899384 total
- age 8: 74592 bytes, 5973976 total
- age 9: 76248 bytes, 6050224 total
- age 10: 75424 bytes, 6125648 total
- age 11: 73984 bytes, 6199632 total
- age 12: 74576 bytes, 6274208 total
- age 13: 74368 bytes, 6348576 total
- age 14: 80912 bytes, 6429488 total
- age 15: 28784 bytes, 6458272 total
: 1266755K->9434K(1415616K), 0.0289570 secs] 1345669K->88349K(4561344K), 0.0303265 secs] [Times: user=0.10 sys=0.00, real=0.03 secs]
......
查看 Jmeter 压力测试报告
查看 Jmeter 压力测试报告，应用吞吐量达标
拟定生产 JVM 参数
nohup java -server -Xmn1536m -Xms4608m -Xmx4608m -XX:MetaspaceSize=128m -XX:MaxMetaspaceSize=512m\
-XX:MaxTenuringThreshold=15 -XX:SurvivorRatio=8\
-XX:+UseConcMarkSweepGC\
-XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+CMSClassUnloadingEnabled\
-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses\
-XX:+PrintTenuringDistribution -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/data/logs/xxx/gc/zuul-garbage-collection.log\
-XX:+PrintCommandLineFlags\
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/xxx/dump/zuul-java_heapdump.hprof\
-Dcom.sun.management.jmxremote.port=9999 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false\
-jar /home/loginuser/xxx-ms/app/zuul-0.0.1.jar --spring.profiles.active=prod\
>/dev/null 2>&1 &
JVM 性能调优工作流程
在开始调优工作之前我们对应用程序的性能需求应该有一个清晰的了解，这些性能需求源于应用程序干系人定义的优先级。性能需求（也称为系统需求）主要关注应用程序运行的特定方面，譬如吞吐量、响应时间、内存清耗、启动时间、可用性、可管理性等。
JVM 调优工程流程图如下。
- 在整个 JVM 性能调优过程中需要全盘考虑各方面的影响，了解应用程序干系人更关注哪些性能指标，选择其中最重要的系统需求作为调优目标。
- 明确调优目标之后，下一步就是选择部署模式。需要选择的是将应用程序部署到多个 JVM 上运行，还是在单个 JVM 上运行。可用性、可管理性以及内存使用都是选择 JVM 部署模式时需要考虑的因素。
- 接下来是选择 JVM 的运行时环境，主要是客户端虚拟机（更短启动时间和较小内存使用）和服务端虚拟机（更高的吞吐量）的抉择。系统需求在吞吐量、响应性、启动及初始化时间方面的要求主导了 JVM 运行时环境的选择。
- 接下来是流程中垃圾收集器调优的环节，通过优化垃圾收集，帮助应用程序达到内存使用、停顿时间/延迟、吞吐量的要求。调优一般是从调节垃圾收集器，满足程序的内存使用需求开始，之后是时间延迟的要求，最后是吞吐量的要求。
- JVM 调优是一个根据性能测试结果不断优化配置的多次迭代过程。在达到应用程序的系统需求指标之前，每个步骤都可能经历多次迭代。此外，为了达到某一个方面的指标，有可能需要对之前的性能参数进行调整，进而需要重做之前的调优步骤。假设发生这样的场景，经过几个迭代的垃圾收集器调节后，程序在延迟上的表现仍不能令人满意。这种情况下，改变 JVM 的部署模式就变得非常重要，否则就只能修改应用程序或者重新定义应用程序的系统需求。
JVM 垃圾收集器调优基本原则
JVM 垃圾收集器调优有三个需要理解的基本原则：
- 每次 MinorGC 都尽可能地收集垃圾对象。我们把这称为“MinorGC 回收原则”。遵守这一原则可以减少应用程序发生 FullGC 的频率。FullGC 的持续时间总是最长的，是应用程序无法达到其延迟或吞吐量要求的罪魁祸首。
- 处理吞吐量和延迟问题时，垃圾收集器能使用的内存越大，即 Java 堆空间越大，垃圾收集的效果越好，应用程序运行也越流畅。我们称之为“GC 内存最大化原则”。
- 在吞吐量、延迟、内存占用三个性能属性中任意选择两个进行 JVM 垃圾收集器调优。我们称之为“GC 调优的 3 选 2 原则”。
确定内存占用
确定内存占用调优将为我们定义运行应用程序需要的 Java 堆的大小提供有力依据。其主要步骤如下：
1．确定初始堆大小，模拟生产环境负荷，使应用程序不再发生 OutOfMemoryError,运行于稳定态。
2．计算活跃数据大小。
3. 初始堆空间大小配置。
堆大小调优着眼点
无论是通过命令行选项显示指定 Java 堆大小还是采用 HotSpot VM 自动选择的 Java 堆大小，目的都是希望将应用程序调整到最典型的工作场景，即它的稳定阶段。你需要产生足够的负荷，同时驱动应用程序处理这些根据生产环境模拟的负荷。
尝试将应用程序推进到稳定态运行，如果存在哪个 Java 内存区域发生 OutOfMemoryError,即增大其容量，直到应用程序处于稳定态，不再发生 OutOfMemoryError,下一步就开始统计应用程序中的活跃数据大小了。
计算活跃数据大小
活跃数据大小是应用程序运行于稳定态时，长期存活的对象在 Java 堆中占用的空间大小。换句话说，活跃数据大小是应用程序运行于稳定态，FullGC 之后 Java 堆老年代和元数据区占用的空间大小。
Java 应用的活跃数据大小可以通过 GC 日志收集。活跃数据大小包括下面的内容：
- 应用程序运行于稳定态时，老年代占用的 Java 堆大小；
- 应用程序运行于稳定态时，元数据区占用的 Java 堆大小。
为了更好地度量应用程序的活跃数据大小，最好在多次 FullGC 之后再次查看 Java 堆的占用情况。另外，需要确保 Full GC 发生时，应用程序处于稳定态运行。
初始堆大小配置
- 通用法则之一，将 Java 堆的初始值-Xms 和最大值-Xmx 设置为老年代活跃数据大小的 3-4 倍。
- 通用法则之二，元数据区的初始值-XX:MetaspaceSize 和最大值-XX:MaxMetaspaceSize 应该是元数据区的活跃数据大小的 1.2-1.5 倍。
- 补充法则，新生代空间大小-Xmn 应该是老年代空间活跃数据大小的 1-1.5 倍。
- 如果 Java 堆的初始值及最大值为活跃数据大小的 3-4 倍，新生代为活跃数据的 1-1.5 倍时，老年代应该设置为活跃数据大小的 2-3 倍。
调优延迟/响应性
调优延迟/响应性的目标是达到程序的延迟性需求，包括多个活动的迭代：优化 Java 堆大小的配置、评估 GC 的的持续时间及频率、是否可能切换到不同的垃圾收集器以及发生垃圾收集器切换之后进行一步的内存调优。
评估调优结果是否达到后选择
- 应用程序的延迟性达到要求 接着进行吞吐量调优
- 应用程序的延迟性未达到要求 此时需要回顾应用程序的延迟性要求，或者修改应用程序以改善延迟性。为改善应用程序的延迟性，可能采取的活动包括：
- 堆分析，修改应用程序，减少对象分配及对象保持
- 改变 JVM 部署模式，减少单个 JVM 的负荷。
评估垃圾收集器对延迟性影响的过程活动
- 测量 MinorGC 的持续时间
- 统计 MinorGC 的次数
- 测量 Full GC 的最差（最长）持续时间
- 统计最差情况下，Full GC 的频率。
测量 GC 的持续时间及频率对优化 Java 堆大小至关重要。MinorGC 的持续时间及频率决定了优化后的新生代的大小。最差情况下的 Full GC 持续时间和频率决定了老年代的大小以及垃圾收集器的切换：是否需要从 Throughput 收集器转向 CMS 收集器。如果 Throughput 收集器的 Full GC 的最差垃圾收集持续时间和频率不能满足应用程序的延迟性要求，那么就要考虑切换到 CMS 收集器。一旦发生切换，同时也需要对 CMS 进行调优。
评估调优目标的输入（延迟性系统需求）
- 应用程序可接受的平均停滞时间 平均停滞时间将与测量出的 MinorGC 持续时间进行比较。
- 可接受的 MinorGC(会导致延迟)频率 MinorGC 频率将与可容忍的值进行比较。对应用干系人而言，GC 持续的时间比 GC 发生的频率更重要。
- 应用干系人可接受的应用程序的最大停顿时间 最大停顿时间将与最差情况下 Full GC 的持续时间进行比较。
- 应用干系人可接受的最大停顿发生的频率 最大停顿发生的频率基本上就是 Full GC 的频率。同样，对于大多数应用干系人而言，相对于 GC 的频率，他更关心 GC 持续的平均停顿时间及最大停顿时间。
优化新生代的大小
根据垃圾收集的统计数据，MinorGC 的持续时间和频率可以确定新生代空间的大小。
- 比较观察到的 MinorGC 平均持续时间及应用的平均延迟要求。如果观测的平均 GC 持续时间大于应用程序的延迟性要求，可以适当减少新生代空间的大小，之后再运行测试。收集 GC 统计数据之后再次评估数据。
- 如果观察到的 MinorGC 频率大于应用程序的延迟性要求（发生得太频繁），增大新生代空间，之后再运行测试。收集 GC 统计数据之后再次评估数据。
- 真正达到应用程序的平均延迟要求之前可能要经历多次迭代。调整新生代空间大小时，尽量保持老年代空间的大小恒定。
调整新生代空间，需要注意三个准则。
- 老年代空间大小不应小于活跃数据大小的 1.5 倍。
- 新生代空间至少应用为 Java 堆的 10%，通过-Xms 和-Xmx 可以设定该值。
- 增大 Java 堆大小时，需要注意不要超过 JVM 可用的物理内存数。
优化老年代的大小
优化老年代的大小的目标是评估 Full GC 引入的最差停滞时间以及 Full GC 的频率。
- 如果预期或观察到 Full GC 频率已经远远不能达到应用程序的最差 Full GC 频率要求，就应增大老年代空间的大小， 这样可以降低 Full GC 的频率。增大老年代空间的大小时注意保持新生代空间大小恒定。
- 如果由于 Full GC 持续时间过长，无法达到应用程序的最差延迟性要求，可以改用并行垃圾收集器。使用 Throughput 收集器时，增加老年代空间通常无法显著降低 Full GC 的时间。GMS 收集器能在应用程序运行的同时以最大的并行度对老年代空间进行垃圾回收。
调整 Survivor 空间的容量
晋升阀值决定对象在新生代 Survivor 空间中保留的时间。HotSpot VM 在每次 Minor GC 时都会计算晋升阀值以决定什么时候对一个对象进行提升。晋升阀值计算的依据是 Minor GC 之后新生代要容纳的可达对象需要的空间大小以及目标 Survivor 空间占用的空间大小。
可以使用命令行选项-XX:MaxTenuringThreshold=指定最大晋升阀值，内部计算出的晋升阀值小于或等于最大晋升阀值。如果 VM 认为它无法维持 Survivor 空间的占用，它会使用一个低于最大值的晋升阀值来保证目标 Survivor 空间的占用。比晋升阀值年龄大的对象都会被提升到老年代。换句话说，当存活下来的对象占用空间超过目标 Suvivor 空间容量时就会发生溢出。溢出导致对象被迅速提升到老年代，造成老年代的增长也快于预期，而导致 Full GC 频繁，降低应用程序的吞吐量。
调整 Survivor 空间容量有一个重要的原则：调整 Survivor 空间容量时，如果新生代空间大小不变，增大 Survivor 空间会减少 Eden 空间；而减少 Eden 空间会增加 MinorGC 的频率。因此， 为了同时满足应用程序的 MinorGC 频率要求，就要增加当前新生代空间的大小；即增大 Survivor 空间大小时，Eden 空间的大小应该保持不变。
通常情况下，即使在 Survivor 空间之间多次复制对象也对匆匆将对象晋升到老年代要好。
应用程序吞吐量调优
吞吐量调优的主要输入是应用程序的吞吐量要求。应用的吞吐量通常是在应用层面而不是在 JVM 层面进行度量。因此，应用程序必定要有一些吞吐量的性能指标报告，或者根据应用程序进行操作能衍生出某种吞吐量指标。之后再将观察的吞吐量与应用程序的吞吐量要求进行比较。当观察的应用程序吞吐量满足或超过预期的吞吐量要求时，整个调优过程圆满结束。如果你需要进一步调优应用程序的吞吐量，那还需要进行额外的 JVM 调优工作。
一个指导原则是，CMS 包括 MinorGC 所带来的开销应该小于 10%，你可能将这个值减少到 1%-3%。通常情况下，如果当前观察到的 CMS 收集器开销在 3% 或更少，通过调优吞吐量性能的提升空间就极其有限了。
参考资料
- Java Platform, Standard Edition Tools Reference: java
- Java Platform, Standard Edition HotSpot Virtual Machine Garbage Collection Tuning Guide
- Jmeter: 16. Best Practices
- Jmeter: User's Manual
- Jmeter: 4. Building a Web Test Plan
- Jmeter: 14. Generating Report Dashboard
- The jstat Command
- HotSpot Virtual Machine Garbage Collection Tuning Guide
- Java 性能优化权威指南
- vmstat(8) - Linux man page
- free(1) - Linux man page
- top(1) - Linux man page
欢迎来到这里！
我们正在构建一个小众社区，大家在这里相互信任，以平等 • 自由 • 奔放的价值观进行分享交流。最终，希望大家能够找到与自己志同道合的伙伴，共同成长。
注册 关于