一般般帅
上一篇:性能监控与调优实战
线上问题排查经验总结
2775 2021-03-22 2021-05-23
前言：本文以几个精心模拟的例子，来说明线上问题排查的思路。
一、OOM
1、问题代码
/**
* -Xmx1024m -Xms1024m
* @author HK
* @date 2021-03-22 21:28
*/
@RequiredArgsConstructor
@RestController
@RequestMapping("/temp")
public class TempTestController {
private final List<Object> list = new ArrayList<>();
@GetMapping("/tempGetStr")
public String test(int times) {
return "hello, I am OK";
}
@GetMapping("/tempTest")
public String tempTest(int times) {
for (int j = 0; j < times; j++) {
String uuid = IdUtil.fastUUID();
// 0 1 2
int i = RandomUtil.randomInt(3);
if (i == 0) {
list.add(uuid);
} else if (i == 1) {
Map<String, Object> map = new HashMap<>(8);
map.put(uuid, uuid);
list.add(map);
} else if (i == 2) {
list.add(new Object());
}
}
return "success run " + times + " times";
}
}
2、搞蹦服务器
1、循环500万次
### 测试不断new对象，并保持与GC Root的联系 curl http://127.0.0.1:9090/temp/tempTest?times=5000000
### 运行5百万次
GET http://127.0.0.1:9090/temp/tempTest?times=5000000
### 测试 curl http://127.0.0.1:9090/temp/tempGetStr
### 测试服务器是否运行正常
GET http://127.0.0.1:9090/temp/tempGetStr
### 查看应用内存状态，有如下发现，注意对应关系，有两个 - -
[root@izwz93pwxi9qhdp46ajo0qz ~]# jstat -gc 20018
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT CGC CGCT GCT
73728.0 78848.0 0.0 25536.0 187392.0 43362.9 699392.0 637858.2 84736.0 80335.1 11264.0 10516.7 45 1.478 4 1.930 - - 3.407
# S0C：年轻代中第一个survivor（幸存区）的容量 （字节）
# S1C：年轻代中第二个survivor（幸存区）的容量 (字节)
# S0U ：年轻代中第一个survivor（幸存区）目前已使用空间 (字节)
# S1U ：年轻代中第二个survivor（幸存区）目前已使用空间 (字节)
# EC ：年轻代中Eden（伊甸园）的容量 (字节)
# EU ：年轻代中Eden（伊甸园）目前已使用空间 (字节)
# OC ：Old代的容量 (字节)
# OU ：Old代目前已使用空间 (字节)
# MC：metaspace(元空间)的容量 (字节)
# MU：metaspace(元空间)目前已使用空间 (字节)
# CCSC：当前压缩类空间大小
# CCSU：当前压缩类空间已用大小
# YGC ：从应用程序启动到采样时年轻代中gc次数
# YGCT ：从应用程序启动到采样时年轻代中gc所用时间(s)
# FGC ：从应用程序启动到采样时old代(全gc)gc次数
# FGCT ：从应用程序启动到采样时old代(全gc)gc所用时间(s)
# GCT：从应用程序启动到采样时gc用的总时间(s)
# 由上面信息，我们大概可以知道
# 老年代大小为 699392 / 1024 = 683M，几乎已被填满，且可知默认老年代:新生代 = 350:700 = 1:2
此时服务器仍表现正常状态，虽然老年代内存不足，但访问测试链接仍可快速响应。
2、循环1000万次
curl http://127.0.0.1:9090/temp/tempTest?times=10000000（可分两次500万，也可一次1000万），服务器直接崩溃（也可能表现为假死），对外测试请求具体表现为无响应或响应缓慢。
# 对比前面的500万，我们可以知道除了Eden表现也为内存不足外，GC的 GCT=gc总时间急剧增加、YGC\YGCT=基本不变\基本不变、FGC\FGCT=稳定增加\稳定增加、
[root@izwz93pwxi9qhdp46ajo0qz ~]# jstat -gc 20018
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT CGC CGCT GCT
73728.0 78848.0 0.0 25536.0 187392.0 43362.9 699392.0 637858.2 84736.0 80335.1 11264.0 10516.7 45 1.478 4 1.930 - - 3.407
[root@izwz93pwxi9qhdp46ajo0qz ~]# jstat -gc 20018
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT CGC CGCT GCT
73728.0 78848.0 0.0 25536.0 187392.0 43362.9 699392.0 637858.2 84736.0 80335.1 11264.0 10516.7 45 1.478 4 1.930 - - 3.407
[root@izwz93pwxi9qhdp46ajo0qz ~]# jstat -gc 20018
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT CGC CGCT GCT
66048.0 70144.0 0.0 0.0 205312.0 205312.0 699392.0 698894.8 84736.0 79759.5 11264.0 10430.1 47 1.609 91 112.514 - - 114.122
[root@izwz93pwxi9qhdp46ajo0qz ~]# jstat -gc 20018
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT CGC CGCT GCT
66048.0 70144.0 0.0 0.0 205312.0 205312.0 699392.0 698896.1 84736.0 79759.5 11264.0 10430.1 47 1.609 144 185.206 - - 186.814
[root@izwz93pwxi9qhdp46ajo0qz ~]# jstat -gc 20018
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT CGC CGCT GCT
66048.0 70144.0 0.0 0.0 205312.0 205312.0 699392.0 698896.1 84736.0 79759.5 11264.0 10430.1 47 1.609 146 187.927 - - 189.535
[root@izwz93pwxi9qhdp46ajo0qz ~]# jstat -gc 20018
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT CGC CGCT GCT
66048.0 70144.0 0.0 0.0 205312.0 205311.9 699392.0 698896.1 84736.0 79759.5 11264.0 10430.1 47 1.609 148 190.631 - - 192.239
[root@izwz93pwxi9qhdp46ajo0qz ~]# jstat -gc 20018
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT CGC CGCT GCT
66048.0 70144.0 0.0 0.0 205312.0 205312.0 699392.0 698898.6 84736.0 79759.5 11264.0 10430.1 47 1.609 176 229.182 - - 230.790
[root@izwz93pwxi9qhdp46ajo0qz ~]# jstat -gc 20018
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT CGC CGCT GCT
66048.0 70144.0 0.0 0.0 205312.0 205312.0 699392.0 698922.2 84736.0 79759.5 11264.0 10430.1 47 1.609 274 366.171 - - 367.780
[root@izwz93pwxi9qhdp46ajo0qz ~]# jstat -gc 20018
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT CGC CGCT GCT
66048.0 70144.0 0.0 0.0 205312.0 205312.0 699392.0 698949.6 84736.0 79760.0 11264.0 10430.1 47 1.609 382 516.247 - - 517.855
[root@izwz93pwxi9qhdp46ajo0qz ~]# jstat -gc 20018
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT CGC CGCT GCT
66048.0 70144.0 0.0 0.0 205312.0 205312.0 699392.0 699048.7 84736.0 79760.7 11264.0 10430.6 47 1.609 724 1003.560 - - 1005.169
为什么要列举这些呢？是因为我们无法从错误日志、或直观的线程堆栈信息、或明显的代码位置查看到任何有关于类TempTestController的任何信息！
3、排除步骤
个人经验，不一定对，请假设现在是纯线上环境，只知道服务器响应缓慢，日志看不出什么问题。
1、free、top、df
[root@izwz93pwxi9qhdp46ajo0qz ~]# free -hl
total used free shared buff/cache available
Mem: 1.8G 1.4G 68M 436K 344M 269M
Low: 1.8G 1.7G 68M
High: 0B 0B 0B
Swap: 0B 0B 0B
### 其中 total：物理内存的总大小 used：被使用的大小 free：可用内存空闲内存大小 shared：被多个进程共享的内存
### buffer/cached:磁盘缓存的大小 available：还可以被进程使用的物理内存大小
### 可以看到这是一台小内存服务器，但总内存还是够的，约有 68 + 269 / (1.8 * 1024) = 337 / 1850 = 18% 内存可用，处于正常范围
### 这里根据实际的情况，会有不同的表现，服务器可能偶尔表现为无响应-即崩溃，或偶尔表现为相应缓慢
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
10302 hk-pc 20 0 6790896 1.2g 24480 S 680.5 3.9 160:22.44 java
29034 hk-pc 20 0 2399844 129484 86860 S 7.6 0.4 0:17.78 deepin-system-m
10855 hk-pc 20 0 1998044 103740 84920 S 6.3 0.3 0:15.92 deepin-terminal
2416 root 20 0 4663684 152996 87888 S 4.6 0.5 1:21.91 Xorg
8850 hk-pc 20 0 8474608 1.6g 67732 S 4.3 5.0 6:13.29 java
31148 root 20 0 447344 314168 52092 S 3.3 1.0 0:11.77 kube-apiserver
1444 root 20 0 391284 13008 10204 S 2.0 0.0 1:09.89 udisksd
### cpu飙升，cpu全部耗在fgc，此时服务器对外表现为无响应
[root@izwz93pwxi9qhdp46ajo0qz ~]# df -hl
文件系统 容量 已用 可用 已用% 挂载点
/dev/vda1 40G 5.9G 32G 16% /
devtmpfs 909M 0 909M 0% /dev
tmpfs 919M 0 919M 0% /dev/shm
tmpfs 919M 432K 919M 1% /run
tmpfs 919M 0 919M 0% /sys/fs/cgroup
tmpfs 184M 0 184M 0% /run/user/0
### 服务器硬盘容量也是足够的
# du是查看当前目录的占用空间大小
2、jps、jinfo、jstat
### 找到具体的pid
[root@izwz93pwxi9qhdp46ajo0qz ~]# jps -l
4644 sun.tools.jps.Jps
20151 /xiaokui/product/k-mp-robot-v2.0.jar
7947 org.apache.catalina.startup.Bootstrap
5853 /xiaokui/product/eladmin-system-v2.0.jar
### 查看应用的配置信息，包含 -Xmx -Xms -Xss参数等
[root@izwz93pwxi9qhdp46ajo0qz ~]# jinfo 20018 | tee jinfo-20018.log
VM Flags:
-XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:CICompilerCount=4 -XX:InitialHeapSize=1073741824 -XX:+ManagementServer -XX:MaxHeapSize=1073741824 -XX:MaxNewSize=357564416 -XX:MinHeapDeltaBytes=524288 -XX:NewSize=357564416 -XX:OldSize=716177408 -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
VM Arguments:
jvm_args: -Dvisualvm.id=35945095365241 -Xmx1024m -Xms1024m -XX:TieredStopAtLevel=1 -Xverify:none -Dspring.output.ansi.enabled=always -Dcom.sun.management.jmxremote -Dspring.jmx.enabled=true -Dspring.liveBeansView.mbeanDomain -Dspring.application.admin.enabled=true -javaagent:/usr/dev/idea/lib/idea_rt.jar=39091:/usr/dev/idea/bin -Dfile.encoding=UTF-8
### 得知一个应用的大概信息后，我们需要具体的一个信息，比如当前Java堆的情况、Eden、Surivor、老年代
### tee xx.txt 新建文件
### tee -a xx.txt 追加写入
[root@izwz93pwxi9qhdp46ajo0qz ~]# jstat -gc 20018 | tee -a jstat.log
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT CGC CGCT GCT
74752.0 70144.0 0.0 0.0 204288.0 203615.3 699392.0 699391.5 85888.0 80646.3 11392.0 10538.0 46 1.671 315 442.864 - - 444.535
# S0C：年轻代中第一个survivor（幸存区）的容量 （字节）
# S1C：年轻代中第二个survivor（幸存区）的容量 (字节)
# S0U ：年轻代中第一个survivor（幸存区）目前已使用空间 (字节)
# S1U ：年轻代中第二个survivor（幸存区）目前已使用空间 (字节)
# EC ：年轻代中Eden（伊甸园）的容量 (字节)
# EU ：年轻代中Eden（伊甸园）目前已使用空间 (字节)
# OC ：Old代的容量 (字节)
# OU ：Old代目前已使用空间 (字节)
# MC：metaspace(元空间)的容量 (字节)
# MU：metaspace(元空间)目前已使用空间 (字节)
# CCSC：当前压缩类空间大小
# CCSU：当前压缩类空间已用大小
# YGC ：从应用程序启动到采样时年轻代中gc次数
# YGCT ：从应用程序启动到采样时年轻代中gc所用时间(s)
# FGC ：从应用程序启动到采样时old代(全gc)gc次数
# FGCT ：从应用程序启动到采样时old代(全gc)gc所用时间(s)
# GCT：从应用程序启动到采样时gc用的总时间(s)
# 由上面信息，我们大概可以知道
# 两个Survivor容量，大小为 74752 / 1024 = 73M，容量充足
# Eden大小为 204288 / 1024 = 200M，几乎已被填满，且可知新生代总大小为 350M，Eden:Survivor:Survivor=200:75:75=40:15:15=8:3:3，由此可见这里有个最低内存限制，并不会严格的遵循默认比例设置
# 老年代大小为 699392 / 1024 = 683M，几乎已被填满，且可知默认老年代:新生代 = 350:700 = 1:2
# 相信的gc信息，可以参考之前的gc次数、时间分析
3、分析
到此为止，我们已经完成这次线上事故的分析，具体如下
- 服务器总内存空间、硬盘空间正常，因此可将事故范围缩小至单个应用
- 前期服务器CPU一定会发生飙升，可以通过jps、jinfo、jstat可以知道具体原因（这里是老年代fgc次数过多，耗时过长）
- gc前期cpu飙升-此时仍有一定堆空间，对外表现为相应缓慢
- gc中期-gc顶峰，对外表现为无响应，但此时gc仍在快速多频次进行
- gc后期-gc尽最大努力内存仍不够，gc逐渐降到最低，但由于之前高强度gc导致部分关键对象无空间存放，功能缺失，此时系统呈假死状态，无任何响应
- 此时我们若能够从日志输出、jstack输出、jinfo输出 中找到相关线索，比如发现某个怀疑类、明显Java堆空间不足、新生代老年代比例不合适等等，再针对性解决问题，此步可解决绝大多数问题
注：https://github.com/oldratlee/useful-scripts有个脚本show-busy-java-threads可查看Java使用cpu最高的topN线程，原理是top的线程模式结合jstack，可以根据此工具定位到是业务线程还是gc线程。
为了加大难度，我们假设从日志输出、jstack输出中均无法找到关键信息，或者说我们需要再进一步确认一下。继续分析
4、堆分析
1、jmap
[root@izwz93pwxi9qhdp46ajo0qz ~]# jmap -h
Usage:
jmap -clstats <pid>
to connect to running process and print class loader statistics
jmap -finalizerinfo <pid>
to connect to running process and print information on objects awaiting finalization
jmap -histo[:live] <pid>
to connect to running process and print histogram of java object heap
if the "live" suboption is specified, only count live objects
jmap -dump:<dump-options> <pid>
to connect to running process and dump java heap
jmap -? -h --help
to print this help message
dump-options:
live dump only live objects; if not specified,
all objects in the heap are dumped.
format=b binary format
file=<file> dump heap to <file>
Example: jmap -dump:live,format=b,file=heap.bin <pid>
[root@izwz93pwxi9qhdp46ajo0qz ~]# jmap -dump:farmat=b,file=pid58574.dump 58574
由此可得到一个1.3G的dump文件。接下来使用dump分析工具，如下所示
2、jprofiler
3、visualvm
5、问题总结
1、常见调优参数
| 参数 | 说明 | 补充说明 |
|---|---|---|
| -Xms1024m | 设置最小堆内存为1024m | 当-Xmx和-Xms值相同时，可以避免对内存动态扩展带来的损耗，因此一般设置为相同 |
| -Xmx1024m | 设置最大堆内存为1024m | |
| -Xss254k | 设置每个线程的堆栈大小 | 在相同的物理内存下，减少这个值能生成更多的线程 |
| -Xmn200m | 设置堆新生代的大小 | 老年底、非堆自动计算 |
| -XX:NewRatio= | 设置年轻代与年老代的比值 | 设置为4，则年轻代和年老代所占比值为1：4，年轻代占整个堆的1/5。默认为2 |
| -XX:SurvivorRatio=8 | 设置年轻代中Eden区与一个Survivor区的比值 | 设置为8，则Eden : From Survivor : To SUrvivor = 8 :1 :1 |
| -XX:+UseParallelGC | 设置并行收集器 | +为开启 -为关闭 =为复制 |
| -XX:-UseParallelGC | 关闭并行收集器 | |
| -XX:+HeapDumpOnOutOfMemoryError | 默认关闭 | 当发生内存溢出异常时是否生成堆转储快照 |
| -XX:+PrintGCDetails | 默认关闭 | 打印GC详细信息 |
| -verbose:gc | 开启GC日志 | |
| -Xloggc:d:/home/gc.log | GC日志存放的位置 | |
| java -XX:+PrintFlagsFinal -version | 可查看虚拟机所有参数值 |
总访问次数: 322次, 一般般帅 创建于 2021-03-22, 最后更新于 2021-05-23
欢迎关注微信公众号，第一时间掌握最新动态！