JVM线上故障排查(一)

前言

大部分的开发都没有接触到线上故障排查的经历, 本篇通过对生产事故的复盘做下记录分析。
公司是做IM机器人的。 某次, 售后反馈, 大量客户的机器人出现延迟对话的情况, 此时, 看业务日志发现业务未出现问题, 而数据入口处MQ无日志埋点, 无法判断是哪个环节出现了延迟。

现象

  1. load average偏高
  2. top查看gc进程占用了大量的cpu
  3. 内存free空间还比较多
  4. gc日志显示大量的 Full GC

理论

要排查问题, 首先需要了解各个指标的具体含义

  • load average 表示的是CPU的负载. 一般业界能够被接受的值是, load average <= CPU核数 *0.7。

  • Full GC 会导致 STW :top一the一World,简称STW,指的是Gc事件发生过程中,会产生应用程序的停顿。停顿产生时整个应用程序线程都会被暂停,没有任何响应,有点像卡死的感觉,这个停顿称为STW

  • 线程池 队列是一种消息堆积策略, 比如下边的线程池, 最大线程100, 队列长度10000, 在高并发下, queue可能被堆积满。假设每个任务的执行耗时为200ms, 则该场景下任务需要 10000/100*200ms=20000ms=20s 能够执行完。则 TPS=10000/20=500。所以, 理论上单点最大并发500。

1
new ThreadPoolExecutor(50, 100, 30L, TimeUnit.SECONDS, new ArrayBlockingQueue(10000), new AbortPolicy())
  • gc日志 所示, MinorGC 已无法回收内存, 只能触发 Full GC。 出现这种情况说明: 1. 内存还在使用中, 无法释放(可能内存分配太小, 正常内存溢出; 可能有IO、三方调用等耗时操作, 任务执行效率低, 导致内存长时间占用); 2. 内存泄露
1
2
3
4
5
[644572.936s][info][gc] GC(288066) To-space exhausted
[644572.936s][info][gc] GC(288066) Pause Young (Concurrent Start) (G1 Evacuation Pause) 497M->497M(512M) 59.255ms
[644572.936s][info][gc] GC(288068) Concurrent Cycle
[644573.994s][info][gc] GC(288067) Pause Full (G1 Evacuation Pause) 497M->369M(512M) 1058.025ms
[644573.995s][info][gc] GC(288068) Concurrent Cycle 1058.250ms

分析

通过上边的现象分析

  1. 任务延时, 说明阻塞率比较高, 可能是业务阻塞(业务日志可以排查耗时), 也可能是得到的cpu执行单元降低
  2. load average高, 说明无法再扩大线程池最大线程数
  3. GC Thread占用大量cpu, 需要排查gc日志, 查看gc日志可知, Full GC频繁, 说明需要分析内存(看哪些对象占用内存高)。同时 Full GC会阻塞业务线程(有效内存得不到释放), 且会造成线程池中Queue进一步堆积, 加剧内存的消耗, 降低线程执行效率。内存分析过程下边再详细阐述。到这里基本可以确认, 线上的512M内存需要扩容了。

内存分析模拟

导出线程快照: jstack -l pid > xxx.log
导出内存快照: jmap -dump:live,format=b,file=/data/xxxx.hprof pid

1
live表示只dump活跃对象,format=b表示二进制格式,file表示保存文件的路径,pid表示进程号。

详细的JVM在线指令可以参考 https://idcent.cn/#/note/JVM调优指令

  1. 查看我们应用的pid
1
ps -ef | grep xxx
  1. 利用top命令找到CPU占用高的进程pid
1
top

显示pid: 381179

1
381179 root      20   0 6222740 996436   9272 S   0.7  12.5 133:34.36 java
  1. 利用top找到该pid 381179下所有的线程数据
1
top -Hp 381179

可以看到占用cpu资源最高的为385444

1
385444 root      20   0 6222740 996436   9272 S   0.3  12.5  22:06.56 dubbo-future-ti
  1. 占用率最高的线程 ID 为385444,将其转换为 16 进制形式 (因为 java native 线程以 16 进制形式输出)
1
printf '%x\n' 385444

得到线程ID: 5e1a4

  1. 利用 jstack 打印出 java 线程调用栈信息
1
2
3
4
5
6
# 1. 在线查询
jstack 381179 | grep '5e1a4' -A 50 --color

# 2. 导出线程快照查询
jstack -l 381179 > ./381179.stack
cat 381179.stack | grep '5e1a4' -C 50

模拟故障

  1. 堆内存溢出
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
package com.example.demo;

import java.util.ArrayList;
import java.util.List;

/**
* 堆溢出: java对象在堆中分配内存
*
* VM options: -Xms20m -Xmx20m -XX:+HeapDumpOnOutOfMemoryError
*
* 执行结果:
*
* 分配次数:1
* 分配次数:2
* 分配次数:3
* java.lang.OutOfMemoryError: Java heap space
* Dumping heap to java_pid17426.hprof ...
* Heap dump file created [17431809 bytes in 0.026 secs]
* Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
* at HeapOOm.main(HeapOOm.java:15)
*/
public class HeapOOm {

public static void main(String[] args) throws InterruptedException {
List<byte[]> list = new ArrayList<>();
int i=0;
while(true){
list.add(new byte[5*1024*1024]);
System.out.println("分配次数:"+(++i));
}
}
}
  1. 栈内存溢出
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
package com.example.demo;


/**
* 栈空间不足溢出
*
* 执行结果:
*
* 递归次数:18117
* Exception in thread "main" java.lang.StackOverflowError
* at StackOverflowErrorDemo.sofMethod(StackOverflowErrorDemo.java:13)
*/
public class StackOverflowErrorDemo {

int depth = 0;

public void sofMethod(){
depth ++ ;
sofMethod();
}

public static void main(String[] args) {
StackOverflowErrorDemo test = null;
try {
test = new StackOverflowErrorDemo();
test.sofMethod();
} finally {
System.out.println("递归次数:"+test.depth);
}
}
}
  1. 永久代-方法区溢出
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
package com.example.demo;

import org.springframework.cglib.proxy.Enhancer;
import org.springframework.cglib.proxy.MethodInterceptor;
import org.springframework.cglib.proxy.MethodProxy;

import java.lang.reflect.Method;

/**
* java7 方法区溢出
* -XX:PermSize=10m -XX:MaxPermSize=10m
*/
public class MethodAreaOOMTest {

public static void main(String[] args) {
int i=0;
try {
while(true){
Enhancer enhancer = new Enhancer();
enhancer.setSuperclass(OOMObject.class);
enhancer.setUseCache(false);
enhancer.setCallback(new MethodInterceptor() {
@Override
public Object intercept(Object obj, Method method, Object[] args, MethodProxy proxy) throws Throwable {
return proxy.invokeSuper(obj, args);
}
});
enhancer.create();
i++;
}
} finally{
System.out.println("运行次数:"+i);
}
}

static class OOMObject{

}
}
  1. 元空间溢出
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
package com.example.demo;

import sun.misc.Unsafe;

import java.lang.reflect.Field;

/**
* -Xms20m -Xmx20m -XX:MaxDirectMemorySize=10m
*/
public class DirectMemoryOOMTest {

public static void main(String[] args) {
int i=0;
try {
Field field = Unsafe.class.getDeclaredFields()[0];
field.setAccessible(true);
Unsafe unsafe = (Unsafe) field.get(null);
while(true){
unsafe.allocateMemory(1024*1024);
i++;
}
} catch (Exception e) {
e.printStackTrace();
}finally {
System.out.println("分配次数:"+i);
}
}
}
  1. Young GC 模拟
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
package com.example.demo;

import java.util.ArrayList;
import java.util.List;

/**
* @author cuishiying
*/
public class TestYGC {
/**
* 设置参数 -Xms10m -Xmx20m -Xmn5m -XX:+PrintGCDetails
* -Xms10m 初始化堆内存大小
* -Xmx20m 堆最大内存
* -Xmn5m 年轻代的大小
* -XX:+PrintGCDetails 打印gc明细日志
**/
public static void main(String[] args) {
List<Object> list = new ArrayList<>();

for (int i = 0; i < 4; i++) {
byte[] b = new byte[1024 * 1024];
list.add(b);
}
}
}
  1. Full GC 模拟
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
package com.example.demo;

import java.util.ArrayList;
import java.util.List;

/**
* @author cuishiying
*/
public class TestFullGC {
/**
* 设置参数 -Xms10m -Xmx20m -Xmn5m -XX:+PrintGCDetails
* -Xms10m 初始化堆内存大小
* -Xmx20m 堆最大内存
* -Xmn5m 年轻代的大小
* -XX:+PrintGCDetails 打印gc明细日志
* 新生代占堆内存的1/3
* 老年代占堆内存的2/3
**/
public static void main(String[] args) {
List<Object> list = new ArrayList<>();

for (int i = 0; i < 8; i++) {
byte[] b = new byte[1024 * 1024];
list.add(b);
}
}
}

哪些对象触发了Full GC, 可以通过如下查看

1
jmap -histo:live pid | head -10

参考 http://static.kancloud.cn/alex_wsc/javajvm/1844985

  1. 死锁模拟
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
package com.javaedge.concurrency.example.deadLock;


public class DeadLockDemo {
private static Object resource1 = new Object();//资源 1
private static Object resource2 = new Object();//资源 2

public static void main(String[] args) {
new Thread(() -> {
synchronized (resource1) {
System.out.println(Thread.currentThread() + "get resource1");
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
e.printStackTrace();
}
System.out.println(Thread.currentThread() + "waiting get resource2");
synchronized (resource2) {
System.out.println(Thread.currentThread() + "get resource2");
}
}
}, "线程 1").start();

new Thread(() -> {
synchronized (resource2) {
System.out.println(Thread.currentThread() + "get resource2");
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
e.printStackTrace();
}
System.out.println(Thread.currentThread() + "waiting get resource1");
synchronized (resource1) {
System.out.println(Thread.currentThread() + "get resource1");
}
}
}, "线程 2").start();
}
}

最后

简单总结下: CPU看线程, 内存看GC

本文到此结束,感谢阅读。如果您觉得不错,请关注公众号【当我遇上你】,您的支持是我写作的最大动力。