JVM成神路之线上故障排查、性能监控工具分析及各线上问题排错实战
在开发过程中,如果遇到JVM问题时,通常都有各种各样的本地可视化工具支持查看。但开发环境中编写出的程序迟早会被部署在生产环境的服务器上,而线上环境偶尔也容易遇到一些突发状况,比如JVM在线上环境往往会出现以下几个问题:
①JVM内存泄漏。
②JVM内存溢出。
③业务线程死锁。
④应用程序异常宕机。
⑤线程阻塞/响应速度变慢。
⑥CPU利用率飙升或100%。
当程序在线上环境发生故障时,就不比开发环境那样,可以通过可视化工具监控、调试,线上环境往往会“恶劣”很多,那当遇到这类问题时又该如何处理呢?首先在碰到这类故障问题时,得具备良好的排查思路,再建立在理论知识的基础上,通过经验+数据的支持依次分析后加以解决。
# Java程序监控及性能调优工具
碰到问题时,首先要做的就是定位问题。而一般定位问题是都会基于数据来进行,比如:程序运行日志、异常堆栈信息、GC日志记录、线程快照文件、堆内存快照文件等。同时,数据的收集又离不开监控工具的辅助,所以当JVM在线上运行过程中出现问题后,自然避免不了使用一些JDK自带以及第三方提供的工具,如:jps、jstat、jstack、jmap、jhat、hprof、jinfo、arthas
等,接下来挑一些常用的工具介绍一下。
# 进程监控工具 - jps
jps
工具的主要作用是用来查看机器上运行的Java进程,类似于Linux系统的ps -aux|grep java
命令。jps
工具也支持查看其他机器的Java进程,命令格式如下:
jps [ options ] [ hostid ]` 查看指令的用法:`jps -help
1
2
其中[options]
主要有-q、-m、-l、-v、-V
几个选项:
jps -q
:查看机器所有运行的Java进程,但只显示进程号(lvmid
)。jps -m
:~,只显示传递给main
方法的参数。jps -l
:~,只显示运行程序主类的包名,或者运行程序jar
包的完整路径。jps -v
:~,单独显示JVM启动时,显式指定的参数。jps -V
:~,显示主类名或者jar包名。
其中[hostid]
是用来连接其他机器查看Java进程的远程ID。
JPS
工具实际使用方式:jps [pid]
。
# 配置信息查看工具 - jinfo
jps
工具主要用于实时查看JVM的运行参数,也可以在运行时动态的调整一些参数。命令格式如下:
jinfo [ option1 ] [ option2 ]` 查看指令的用法:`jinfo -help / jinfo -h
1
2
其中[option1]
可选项如下:
<no option>
:第一个参数不写,默认输出JVM的全部参数和系统属性。-flag <name>
:输出与指定名称<name>
对应的所有参数,以及参数值。-flag [+|-]<name>
:开启或者关闭与指定名称<name>
对应的参数。-flag <name>=<value>
:设置与指定名称<name>
对应参数的值。-flags
:输出JVM全部的参数。-sysprops
:输出JVM全部的系统属性。
其中[option2]
可选项如下:
<pid>
:对应的JVM进程ID(必需参数),指定一个jinfo
要操作的Java进程。executable <core
:输出打印堆栈跟踪的核心文件。[server-id@]<remote server IP or hostname>
1:远程操作的地址。
server-id
:远程debug
服务的进程ID;remote server IP/hostname
:远程debug
服务的主机名 或 IP地址;
Jinfo
工具实际使用方式:jinfo -flags [pid]
。
PS:对于每个不同选项的效果就不再演示了,感兴趣的小伙伴可以自行在本地开个Java进程,然后使用上述的选项进行调试观察。
# 信息统计监控工具 - jstat
jstat
工全称为“Java Virtual Machine statistics monitoring tool
”,该工具可以利用JVM内建的指令对Java程序的资源以及性能进行实时的命令行的监控,监控范围包含:堆空间的各数据区、垃圾回收状况以及类的加载与卸载状态。
命令格式:
jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]
其中每个参数的释义如下:
[option]
:监控参数选项。-t
:在输出结果中加上Timestamp
列,显示系统运行的时间。-h
:可以在周期性数据输出的时候,指定间隔多少行数据后输出一次表头。vmid
:Virtual Machine ID
虚拟ID,也就是指定一个要监控的Java进程ID。interval
:每次执行的间隔时间,默认单位为ms
。count
:用于指定输出多少条数据,默认情况下会一直输出。
执行命令jstat -option
后,可以看到存在很多选项,如下:
-class
:输出类加载ClassLoad
相关的信息。-compiler
:显示与JIT即时编译相关的信息。-gc
:显示与GC相关的信息。-gccapacity
:显示每个分代空间的容量以及使用情况。-gcmetacapacity
:输出元数据空间相关的信息。-gcnew
:显示新生代空间相关的信息。-gcnewcapacity
:显示新生代空间的容量大小以及使用情况。-gcold
:输出年老代空间的信息。-gcoldcapacity
:输出年老代空间的容量大小以及使用情况。-gcutil
:显示垃圾回收信息。-gccause
:和-gcutil
功能相同,但是会额外输出最后一次或本次GC的诱因。-printcompilation
:输出JIT即时编译的方法信息。
所以jstat
的实际使用方式如下:
jstat -gc -t -h30 9895 1s 300
-gc:监控GC的状态 -t:显示系统运行的时间 -h30:间隔30行数据,输出一次表头 9895:Java进程ID 1s:时间间隔 300:本次输出的数据行数
# 堆内存统计分析工具 - jmap
jmap
是一个多功能的工具,主要是用于查看堆空间的使用情况,通常会配合jhat
工具一起使用,它可以用于生成Java堆的Dump
文件。但除此之外,也可以查看finalize
队列、元数据空间的详细信息,Java堆中对象统计信息,如每个分区的使用率、当前装配的GC收集器等。
命令格式:>
jmap [ option1 ] [ option2 ]
其中[option1]
可选项有:
[no option]
:查看进程的内存映像信息,与Solaris pmap
类似。-heap
:显示Java堆空间的详细信息。-histo[:live]
:显示Java堆中对象的统计信息。-clstats
:显示类加载相关的信息。-finalizerinfo
:显示F-Queue
队列中等待Finalizer
线程执行finalizer
方法的对象。-dump:<dump-options>
:生成堆转储快照。-F
:当正常情况下-dump
和-histo
执行失效时,前面加-F
可以强制执行。-help
:显示帮助信息。-J<flag>
:指定传递给运行jmap
的JVM参数。
其中[option2]
与jinfo
工具的相差无几,可选项如下:
<pid>
:对应的JVM进程ID(必需参数),指定一个jinfo
要操作的Java进程。executable <core
:输出打印堆栈跟踪的核心文件。[server-id@]<remote server IP or hostname>
1:远程操作的地址。
server-id
:远程debug
服务的进程ID;remote server IP/hostname
:远程debug
服务的主机名 或 IP地址;
jmap
工具实际使用方式:jmap -clstats [pid]
或jmap -dump:live,format=b,file=Dump.phrof [pid]
等。 堆快照导出命令解析:live
:导出堆中存活对象快照;format
:指定输出格式;file
:指定输出的文件名及其格式(.dat、.phrof
等格式)。
当然,具体的每个选项的效果也不再演示,大家感兴趣可以自行调试后观测。
不过值得一提的是:大部分JDK提供的工具与JVM通信方式都是通过的
Attach
机制实现的,该机制可以针对目标JVM进程进行一些操作,比如获取内存Dump
、线程Dump
、类信息统计、动态加载Agent
、动态设置JVM参数、打印JVM参数、获取系统属性等。有兴趣可以去深入研究一下,具体源码位置位于:com.sun.tools.attach
包,里面存在一系列Attach
机制相关的代码。
在最后对于histo
选项做个简单调试,histo
选项主要作用是打印堆空间中对象的统计信息,包括对象实例数、内存空间占用大小等。因为在histo:live
前会进行FullGC
,所以带上live
只会统计存活对象。因此,不加live
的堆大小要大于加live
堆的大小(因为带live
会强制触发一次FullGC
),如下:
上图中,class name
是对象的类型,但有些是缩写,对象的缩写类型与真实类型对比如下:
缩写类型 | B | C | D | F | I | J | Z | [ | L+类型 |
---|---|---|---|---|---|---|---|---|---|
真实类型 | byte | char | double | float | int | long | boolean | 数组 | 其他对象 |
# 堆栈跟踪工具 - jstack
jstack
工具主要用于捕捉JVM当前时刻的线程快照,线程快照是JVM中每条线程正在执行的方法堆栈集合。在线上情况时,生成线程快照文件可以用于定位线程出现长时间停顿的原因,如线程死锁、死循环、请求外部资源无响应等等原因导致的线程停顿。
当线程出现停顿时,可以通过jstack
工具生成线程快照,从快照信息中能查看到Java程序内部每条线程的调用堆栈情况,从调用堆栈信息中就可以清晰明了的看出:发生停顿的线程目前在干什么,在等待什么资源等。
同时,当Java程序崩溃时,如果配置好了参数,生成了core
文件,咱们也可以通过jstack
工具从core
文件中提取Java虚拟机栈相关的信息,从而进一步定位程序崩溃的原因。
jstack`工具命令格式:`jstack [-F] [option1] [option2]
1
其中[option1]
可选项为:
-l
:除开显示堆栈信息外,额外输出关于锁相关的附加信息(用于排查死锁问题)。-m
:如果线程调用到本地方法栈中的本地方法,也显示C/C++
的堆栈信息。
其中[option2]
可选项如下:
<pid>
:对应的JVM进程ID(必需参数),指定一个jinfo
要操作的Java进程。executable <core
:输出打印堆栈跟踪的核心文件。[server-id@]<remote server IP or hostname>
1:远程操作的地址。
server-id
:远程debug
服务的进程ID;remote server IP/hostname
:远程debug
服务的主机名 或 IP地址;
jstack
工具实际使用方式:jstack -l [pid]
。
同时,jstack
工具的-F
参数与jmap
的作用相同,当正常执行失效时,加上-F
可以强制执行jstack
指令。
最后,jstack
工具导出的Dump
日志值得留意的状态:
状态 | 释义 |
---|---|
Deadlock | 线程出现死锁 |
Runnable | 线程正在执行中 |
Waiting on condition | 线程等待资源 |
Waiting on monitor entry | 线程等待获取监视器锁 |
Suspended | 线程暂停 |
Object.wait()、TIMED_WAITING | 线程挂起 |
Blocked | 线程阻塞 |
Parked | 线程停止 |
# JVM排查工具小结
上述分析的工具都是JDK自带的工具,可以在不同维度对JVM运行时的状况进行监控,也能够帮助我们在线上环境时快速去定位排除问题。但除开JDK官方提供的一些工具之外,也有非常多第三方工具用起来非常顺手,如arthas、jprofilter、perfino、Yourkit、Perf4j、JProbe、MAT、Jconsole、visualVm
等,这些工具往往都比前面分析提到的那些JDK工具更实用且功能更加强大。
# JVM线上故障问题排查实战
# CPU 利用率高/飙升
CPU使用率是衡量系统繁忙程度的重要指标。但是**「CPU使用率的安全阈值是相对的,取决于你的系统的IO密集型还是计算密集型」**。一般计算密集型应用CPU使用率偏高load偏低,IO密集型相反。
常见原因:
- 频繁 gc
- 死循环、线程阻塞、io wait 等等
在一个最简单的SpringBoot Web 项目中增加CpuReaper
这个类:
/**
* 模拟 cpu 飙升场景
* @author Richard_yyf
*/
@Component
public class CpuReaper {
@PostConstruct
public void cpuReaper() {
int num = 0;
long start = System.currentTimeMillis() / 1000;
while (true) {
num = num + 1;
if (num == Integer.MAX_VALUE) {
System.out.println("reset");
num = 0;
}
if ((System.currentTimeMillis() / 1000) - start > 1000) {
return;
}
}
}
}
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
# 定位出问题的线程
top
定位CPU 最高的进程执行
top
命令,查看所有进程占系统CPU的排序,定位是哪个进程搞的鬼。在本例中就是咱们的java进程。PID那一列就是进程号。(对指示符含义不清楚的见【附录】)top -Hp pid
定位使用 CPU 最高的线程printf '0x%x' tid
线程 id 转化 16 进制
> printf '0x%x' 12817
> 0x3211
2
4.jstack pid | grep tid
找到线程堆栈
jstack 12816 | grep 0x3211 -A 30
找出有问题的代码之后,观察到线程栈之后。我们**「就要根据具体问题来具体分析」**。
# JVM内存溢出(OOM)
OOM 全称 “Out Of Memory”,表示内存耗尽。当 JVM 因为没有足够的内存来为对象分配空间,并且垃圾回收器也已经没有空间可回收时,就会抛出这个错误。
内存溢出(OOM)在线上排查中是一个比较常见的问题,同时在Java内存空间中,也会有多块区域会发生OOM问题,如堆空间、元空间、栈空间等。通常情况下,线上环境产生内存溢出的原因大致上有三类:
- ①为JVM分配的内存太小,不足以支撑程序正常执行时的数据增长。
- ②编写的Java程序内部存在问题、有Bug,导致GC回收速率跟不上分配速率。
- ③自己的代码或引入的第三方依赖存在内存溢出问题,导致可用内存不足。
模拟案例如下:
// JVM启动参数:-Xms64M -Xmx64M -XX:+HeapDumpOnOutOfMemoryError
// -XX:HeapDumpPath=/usr/local/java/java_code/java_log/Heap_OOM.hprof
public class OOM {
// 测试内存溢出的对象类
public static class OomObject{}
public static void main(String[] args){
List<OomObject> OOMlist = new ArrayList<>();
// 死循环:反复往集合中添加对象实例
for(;;){
OOMlist.add(new OomObject());
}
}
}
2
3
4
5
6
7
8
9
10
11
12
13
14
java -Xms64M -Xmx64M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/usr/local/java/java_code/java_log/Heap_OOM.hprof OOM &
过一会输出一句OOM异常信息:
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
at java.util.Arrays.copyOf(Arrays.java:3210)
at java.util.Arrays.copyOf(Arrays.java:3181)
at java.util.ArrayList.grow(ArrayList.java:261)
at java.util.ArrayList.ensureExplicitCapacity(ArrayList.java:235)
at java.util.ArrayList.ensureCapacityInternal(ArrayList.java:227)
at java.util.ArrayList.add(ArrayList.java:458)
at OOM.main(OOM.java:13)
2
3
4
5
6
7
8
在OOM时候,会自动导出dump文件,接下来我们只需要把这个Dump
文件直接往Eclipse MAT(Memory Analyzer Tool)
工具里面一丢,然后它就能自动帮你把OOM的原因分析出来,然后根据它分析的结果改善对应的代码即可。
# 线上内存溢出问题小结
Java程序在线上出现问题需要排查时,内存溢出问题绝对是“常客”,但通常情况下,OOM大多是因为代码问题导致的,在程序中容易引发OOM的情况:
- 一次性从外部将体积过于庞大的数据载入内存,如DB读表、读本地报表文件等。
- 程序中使用容器(
Map/List/Set
等)后未及时清理,内存紧张而GC无法回收。 - 程序逻辑中存在死循环或大量循环,或单个循环中产生大量重复的对象实例。
- 程序中引入的第三方依赖中存在BUG问题,因此导致内存出现故障问题。
- 程序中存在内存溢出问题,一直在蚕食可用内存,GC无法回收导致内存溢出。
- 第三方依赖加载大量类库,元空间无法载入所有类元数据,因而诱发OOM。
# JVM内存泄漏
内存泄漏的定义:不会再被使用的对象,其占用的内存却不能被回收,这就是内存泄漏。
内存泄漏的本质是:长生命周期的对象持有短生命周期对象的引用
线上的Java程序中,出现内存泄漏主要分为两种情况:
- 堆内泄漏:由于代码不合理导致内存出现泄漏,如垃圾对象与静态对象保持着引用、未正确的关闭外部连接等。
- 堆外泄漏:申请
buffer
流后未释放内存、直接内存中的数据未手动清理等。
内存溢出的模拟案例:
// JVM启动参数:-Xms64M -Xmx64M -XX:+HeapDumpOnOutOfMemoryError
// -XX:HeapDumpPath=/usr/local/java/java_code/java_log/Heap_MemoryLeak.hprof
// 如果不做限制,想要观测到内存泄漏导致OOM问题需要很长时间。
public class MemoryLeak {
// 长生命周期对象,静态类型的root节点
static List<Object> ROOT = new ArrayList<>();
public static void main(String[] args) {
// 不断创建新的对象,使用后不手动将其从容器中移除
for (int i = 0;i <= 999999999;i++) {
Object obj = new Object();
ROOT.add(obj);
obj = i;
}
}
}
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
运行后会出现:
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
at java.util.Arrays.copyOf(Arrays.java:3210)
at java.util.Arrays.copyOf(Arrays.java:3181)
at java.util.ArrayList.grow(ArrayList.java:261)
at java.util.ArrayList.ensureExplicitCapacity(ArrayList.java:235)
at java.util.ArrayList.ensureCapacityInternal(ArrayList.java:227)
at java.util.ArrayList.add(ArrayList.java:458)
at MemoryLeak.main(MemoryLeak.java:14)
2
3
4
5
6
7
8
在Java程序中,理论上那些创建出来的Object
对象在使用完成后,内存不足时,GC线程会将其回收,不过由于这些创建出来的对象在最后与静态的成员ROOT
建立起了引用关系,而静态成员在JVM中又被作为GcRoots
节点来对待的。
因此,所有创建出来的Object
对象在使用完成后,因为与ROOT
成员存在引用关系,所以都是可以通过根可达的对象,最终导致GC机制无法回收这些“无效”对象。
该案例中,从程序的执行结果来看,表象是内存溢出,但实则却是内存泄漏。
在开发编码过程中,应当刻意留意:当自己创建出的对象需要与静态对象建立连接,但使用一次之后明确清楚该对象不会再被使用,应当手动清空该对象与静态节点的引用,也就是手动置空或移除。如上述案例中,最后应该要ROOT.remove(obj)
才可。
常见的内存泄漏例子:
- 外部临时连接对象使用后未合理关闭,如DB连接、Socket连接、文件IO流等。
- 程序内新创建的对象与长生命周期对象建立引用使用完成后,未及时清理或断开连接,导致新对象一直存在着引用关系,GC无法回收。如:与静态对象、单例对象关联上了。
- 申请堆外的直接内存使用完成后,未手动释放或清理内存,从而导致内存泄漏,如:通过魔法类Unsafe申请本地内存、或使用Buffer缓冲区后未清理等。
# 业务线程死锁
死锁是指两个或两个以上的线程(或进程)在运行过程中,因为资源竞争而造成相互等待的现象,若无外力作用则不会解除等待状态,它们之间的执行都将无法继续下去。
死锁产生的有4个必要条件 (1) 互斥条件:一个资源每次只能被一个进程使用。 (2) 请求与保持条件:一个进程因请求资源而阻塞时,对已获得的资源保持不放。 (3) 不剥夺条件:进程已获得的资源,在末使用完之前,不能强行剥夺。 (4) 循环等待条件:若干进程之间形成一种头尾相接的循环等待资源关系。
# 实战JVM死锁问题排查
按照死锁产生原则,可写出一个产生死锁的程序:
public class DeadLock {
//创建两个对象,用两个线程分别先后独占
private Boolean flag1 = true;
private Boolean flag2 = false;
public static void main(String[] args) {
DeadLock deadLock = new DeadLock();
new Thread(new Runnable() {
@Override
public void run() {
System.out.println("线程1开始,作用是当flag1 = true 时,将flag2也改为 true");
synchronized (deadLock.flag1){
if(deadLock.flag1){
try{
//睡眠1s ,模拟业务执行耗时,并保证两个线程进入死锁状态
Thread.sleep(1000);
}catch (InterruptedException e){
e.printStackTrace();
}
System.out.println("flag1 = true,准备锁住flag2...");
synchronized (deadLock.flag2){
deadLock.flag2 = true;
}
}
}
}
}).start();
new Thread(new Runnable() {
@Override
public void run() {
System.out.println("线程2开始,作用是当flag2 = false 时,将flag1也改为 false");
synchronized (deadLock.flag2){
if(!deadLock.flag2){
try{
//睡眠1s ,模拟业务执行耗时,并保证两个线程进入死锁状态
Thread.sleep(1000);
}catch (InterruptedException e){
e.printStackTrace();
}
System.out.println("flag2 = false,准备锁住flag1...");
synchronized (deadLock.flag1){
deadLock.flag1 = false;
}
}
}
}
}).start();
}
}
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
40
41
42
43
44
45
46
47
48
49
50
51
52
53
以上代码,可以用一个死锁的图解释。线程1独占对象1,想要访问对象2,而对象2此时已经独占对象2,在等待对象1的资源释放,此时线程1因无法获取到对象2而无法向下执行,因此没法释放对象1,线程2同理,造成了死锁状态,两个线程都阻塞在等待资源处。
# 死锁问题JVM工具排查
查找程序运行端口
> jps -l 18714 sun.tools.jps.Jps 18703 jvm.DeadLock 123
1
2
3
4jstack打印堆栈信息,发现死锁存在的位置,进行排查
> jstack -l 18703
1
# jconsole方式排查
mac下:输入jconsol命令通过可视化界面连接
选择线程,监测死锁。会将死锁的线程信息都展示出来
# jvisualvm方式
用命令行召唤出jconsole,选择对应进程即可直观看到死锁的存在