JVM 性能调优监控工具

本篇主要学习记录下工作中常用的 JDK 自带的一些 JVM 性能调优监控工具,通过了解这些工具,可以在排查问题时给予我们非常大的帮助,将一些隐藏在底下的东西拿到明面上来做分析。

jps(Java Virtual Machine Process Status Tool)

jps 主要用来输出 JVM 中运行的进程状态信息。语法格式如下:

1
jps [options] [hostid]

如果不指定 hostid 就默认为当前主机或服务器,命令行参数选项说明如下:

-q 不输出类名、Jar名和传入main方法的参数

1
2
➜  ~ jps -q
42060

-m 输出传入 main 方法的参数(与默认 jps 指令返回的信息相同)

1
2
➜  ~ jps -m
42060 TestSofaBootApplication

-l 输出 main 类或 jar 的全限名

1
2
➜  ~ jps -l
42060 com.glmapper.bridge.boot.TestSofaBootApplication

-v 输出传入 JVM 的参数

1
2
➜  ~ jps -v
42060 TestSofaBootApplication -agentlib:jdwp=transport=dt_socket,address=127.0.0.1:51645,suspend=y,server=n -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:/Users/xxxx/Library/Caches/JetBrains/IntelliJIdea2020.1/captureAgent/debugger-agent.jar -Dfile.encoding=UTF-8

在排查问题时,我们通过都会通过 jps 来看下当前机器运行的进程有哪些,通过不同的参数来快速找到我们目标进程所在的 pid,以便于我们后续的一系列排查操作。

jstack(Java Stack Trace)

jstack 主要用来查看某个 Java 进程内的线程堆栈信息。如果 java 程序崩溃生成 core 文件,jstack 工具可以用来获得 core 文件的 java stacknative stack 的信息,从而可以轻松地知道 java 程序是如何崩溃和在程序何处发生问题。另外,jstack 工具还可以附属到正在运行的 java 程序中,看到当时运行的 java 程序的 java stacknative stack 的信息, 如果现在运行的 java 程序呈现 hung 的状态,jstack 是非常有用的。

下面是 jstack 语法格式:

1
2
3
jstack [option] pid
jstack [option] executable core
jstack [option] [server-id@]remote-hostname-or-ip

不管是什么指令,我们都要学会先通过 -h 去查一下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
➜  ~ jstack -h
Usage:
jstack [-l] <pid>
(连接到正在运行的进程)
jstack -F [-m] [-l] <pid>
(连接到挂起的进程)
jstack [-m] [-l] <executable> <core>
(连接到 core 文件)
jstack [-m] [-l] [server_id@]<remote server IP or hostname>
(连接到远程调试服务器)

Options:
-F to force a thread dump. Use when jstack <pid> does not respond (process is hung)
-m to print both java and native frames (mixed mode)
-l long listing. Prints additional information about locks
-h or -help to print this help message

Options 参数说明如下:

选项 作用
-F 当正常输出的请求不被响应时,强制输出线程堆栈
-m 如果调用到本地方法的话,可以显示 C/C++ 的堆栈
-l 除堆栈外,显示关于锁的附加信息,在发生死锁时可以用 jstack -l pid 来观察锁持有情况

下面我们重点来聊一聊,jstack 中信息到底要怎么看。

jstack 堆栈信息介绍

下面是 jstack 输出的一段 tacer 数据

1
2
3
4
5
"main" #1 prio=5 os_prio=31 tid=0x00007fb93b802000 nid=0x2703 waiting on condition [0x0000700005e5d000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at com.glmapper.bridge.boot.TestJstack.testWaitingOnConditionCondition(TestJstack.java:19)
at com.glmapper.bridge.boot.TestJstack.main(TestJstack.java:10)

通过这段数据我们大概能 get 到的点主要包括以下信息:

  • main 线程名
  • #1 堆栈序号,没有实际含义,可忽略
  • prio 线程优先级
  • os_prio 操作系统层次的优先级
  • tid 线程标识
  • nid 线程id

线程状态介绍

从上面 jstack 输出的信息可以看到线程状态相关的信息,比如

TIMED_WAITING

1
java.lang.Thread.State: TIMED_WAITING (sleeping)

RUNNABLE

1
java.lang.Thread.State: RUNNABLE

还有一些 "GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fcee9004000 nid=0x1f07 runnable 信息,这种是 jvm 用来回收内存的,先不关注,这里主要看下 java.lang.Thread.State;

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
public enum State {
/**
* 当线程对象创建时存在的状态,此时线程不可能执行
*/
NEW,
/**
* 当调用thread.start()后,线程变成为 Runnable 状态。只要得到CPU,就可以执行;
*/
RUNNABLE,
/**
* 如果进入同步方法或同步代码块,没有获取到锁,则会进入该状态;
*/
BLOCKED,
/**
* 执行thread.join()或在锁对象调用obj.wait()等情况就会进该状态,表明线程正处于等待某个资源或条件发生来唤醒自己;
*/
WAITING,
/**
* 执行Thread.sleep(long)、thread.join(long)或obj.wait(long)等就会进该状态,与Waiting的区别在于Timed_Waiting的等待有时间限制;
*/
TIMED_WAITING,
/**
* 终止
*/
TERMINATED;
}

再回到上面堆栈信息,可以观察到,当状态是 TIMED_WAITING 时,堆栈中会出现 waiting on condition xxxx 信息,类似的还有:

  • waiting on monitor entry : 在等待获取锁,一般对应 BLOCKED
  • in Object.wait() : 获取锁后又执行obj.wait()放弃锁,一般对应 WAITING

下面就针对这些状态举一些简单的小例子。

线程状态举例及 jstack 分析

waiting on condition

1、执行代码

1
2
3
4
5
6
7
8
9
10
11
12
/**
* 产生 waiting on condition
*/
private static void testWaitingOnConditionCondition(){
while (true){
try {
Thread.sleep(60000);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}

2、执行结果

1
2
3
4
5
"main" #1 prio=5 os_prio=31 tid=0x00007fb93b802000 nid=0x2703 waiting on condition [0x0000700005e5d000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at com.glmapper.bridge.boot.TestJstack.testWaitingOnConditionCondition(TestJstack.java:19)
at com.glmapper.bridge.boot.TestJstack.main(TestJstack.java:10)

3、结果分析

这里就比较明显的是 main 线程中正在 sleep 方法。不过这里 TIMED_WAITING 后面的括号里还特殊表明了 sleeping,在一些场景下,常见的还有 parking,下面继续看例子。

waiting on condition (parking)

1、执行代码

1
2
3
4
5
6
7
8
9
10
11
12
private static void testWaitingOnConditionConditionWithParking(){
// 提供一个阻塞对了
BlockingQueue<String> blockingQueue = new ArrayBlockingQueue<String>(1);
// 先加一个
blockingQueue.add("test-parking");
try {
//继续加,这里肯定加不进去,所以会阻塞
blockingQueue.put("test-parking-xxx");
} catch (InterruptedException e) {
e.printStackTrace();
}
}

2、执行结果

1
2
3
4
5
6
7
8
9
"main" #1 prio=5 os_prio=31 tid=0x00007fd6d5008800 nid=0x2803 waiting on condition [0x000070000ffc1000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000076af3a938> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.ArrayBlockingQueue.put(ArrayBlockingQueue.java:353)
at com.glmapper.bridge.boot.TestJstack.testWaitingOnConditionConditionWithParking(TestJstack.java:113)
at com.glmapper.bridge.boot.TestJstack.main(TestJstack.java:13)

3、结果分析

main 线程进入了 waiting on conditon 状态,等待某一个资源,可以看到是在 a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObjec 进行了等待,阻塞住了。

waiting on monitor entry

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
/**
* 产生 waiting on monitor entry
*/
private static void testWaitingOnMonitorEntry(){
final Object obj = new Object();
final Thread thread = new Thread(){
@Override
public void run() {
// 锁 obj 对象
synchronized (obj){
System.out.println(Thread.currentThread().getName());
try {
Thread.sleep(60000);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
};
final Thread thread1 = new Thread(){
@Override
public void run() {
// 锁 obj 对象
synchronized (obj){
System.out.println(Thread.currentThread().getName());
try {
Thread.sleep(60000);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
};
thread.setName("test-thread");
thread.start();
thread1.setName("test-thread1");
thread1.start();
}

2、执行结果

1
2
3
4
5
6
7
8
9
10
"test-thread1" #14 prio=5 os_prio=31 tid=0x00007f9563880800 nid=0x5c03 waiting for monitor entry [0x000070000b029000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.glmapper.bridge.boot.TestJstack$2.run(TestJstack.java:50)
- waiting to lock <0x000000076af261d0> (a java.lang.Object)

"test-thread" #13 prio=5 os_prio=31 tid=0x00007f956387f800 nid=0x5a03 waiting on condition [0x000070000af26000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at com.glmapper.bridge.boot.TestJstack$1.run(TestJstack.java:38)
- locked <0x000000076af261d0> (a java.lang.Object)

3、结果分析

test-thread 获取到 obj 对象上的锁,因此正在执行 sleep 操作,状态为 TIMED_WAINTING, 而 test-thread1 由于未获取到 obj 对象上的锁,因此处于BLOCKED 状态。

test-thread1 正在 “waiting to lock <0x000000076af261d0>”,试图在地址为 0x000000076af261d0 所在的对象获取锁,而该锁却被 test-thread 线程占有 [locked <0x000000076af261d0>]。test-thread 线程正在 “waiting on condition”,说明正在等待某个条件触发,由 jstack 来看,此线程正在sleep。

object.wait()

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
private static void testObjectWait() {
final Thread thread = new Thread() {
@Override
public void run() {
synchronized (this) {
System.out.println(Thread.currentThread().getName());
try {
wait();
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
};
thread.start();
thread.setName("test-object-wait");
try {
Thread.sleep(5000);
} catch (InterruptedException e) {
e.printStackTrace();
}

synchronized (thread) {
System.out.println(Thread.currentThread().getName());
try {
Thread.sleep(30000);
} catch (InterruptedException e) {
e.printStackTrace();
}
thread.notify();
}
}

2、执行结果

1
2
3
4
5
6
7
8
9
10
11
12
13
14
"test-object-wait" #13 prio=5 os_prio=31 tid=0x00007fd43a809000 nid=0xa803 in Object.wait() [0x0000700010926000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x000000076af26140> (a com.glmapper.bridge.boot.TestJstack$3)
at java.lang.Object.wait(Object.java:502)
at com.glmapper.bridge.boot.TestJstack$3.run(TestJstack.java:73)
- locked <0x000000076af26140> (a com.glmapper.bridge.boot.TestJstack$3)

"main" #1 prio=5 os_prio=31 tid=0x00007fd43b001800 nid=0x2603 waiting on condition [0x000070000f2e4000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at com.glmapper.bridge.boot.TestJstack.testObjectWait(TestJstack.java:93)
- locked <0x000000076af26140> (a com.glmapper.bridge.boot.TestJstack$3)
at com.glmapper.bridge.boot.TestJstack.main(TestJstack.java:10)

3、结果分析

由于调用了 object.wait() 方法的时候放弃了锁,所以 test-object-wait 这个线程就出现了 Object.wait() 状态,线程的状态就是 waiting;等待 notify 来进行唤醒。由于 mian 线程在获得 test-object-wait 的线程锁后,调用了 Thread.sleep 方法,所以此时进入了 wating on condition 等待某一个资源,进入到 time_waiting 状态。

小结

一般情况我们在做问题排查时,如果系统非常慢,我们需要特别关注 BlockedWaiting on condition 这些状态。如果系统的 cpu 负载比较高的话,则可以死循环等思路去摸查,此时要关注下 Runable 状态;那如果堆栈中有 Deadlock,那就是产生了死锁。

jstat(JVM统计监测工具)

jstat 是 JVM 统计监测工具,其语法格式如下:

1
jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]

vmidJava 虚拟机 ID,在 Linux/Unix 系统上一般就是进程 IDinterval 是采样时间间隔; count 是采样数目。比如下面输出的是 GC 信息,采样时间间隔为 1000ms,采样数为 3:

1
2
3
4
5
➜  ~ jstat -gc 58950 1000 3
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
10752.0 10752.0 0.0 0.0 65536.0 6554.0 175104.0 0.0 4480.0 785.7 384.0 75.9 0 0.000 0 0.000 0.000
10752.0 10752.0 0.0 0.0 65536.0 6554.0 175104.0 0.0 4480.0 785.7 384.0 75.9 0 0.000 0 0.000 0.000
10752.0 10752.0 0.0 0.0 65536.0 6554.0 175104.0 0.0 4480.0 785.7 384.0 75.9 0 0.000 0 0.000 0.000

输出信息的列释义:

  • S0C、S1C、S0U、S1U:Survivor 0/1区容量(Capacity)和使用量(Used)
  • EC、EU:Eden区容量和使用量
  • OC、OU:年老代容量和使用量
  • PC、PU:永久代容量和使用量
  • YGC、YGT:年轻代 GC 次数和 GC 耗时
  • FGC、FGCT:Full GC 次数和 Full GC耗时
  • GCT:GC 总耗时

jmap(Memory Map)

jmap 用来查看堆内存使用状况,一般结合 jhat 使用。其使用语法如下:

1
2
3
jmap [option] <pid>
jmap [option] <executable <core>
jmap [option] [server_id@]<remote server IP or hostname>

Options 参数说明如下:

选项 作用
打印与 Solaris pmap 相同的信息
-heap 打印 java 堆摘要
-histo[:live] 打印 java 对象堆的直方图;如果指定了“live”子选项,则只计算live对象
-clstats 打印 classloader 统计信息
-finalizerinfo 打印 等待终结 对象的信息
–dump: : 以 hprof 二进制格式dump java heap
-F 使用 -dump: or -histo 强制执行
-J 直接传递给运行时系统

dump-options 又包括以下几个选项:

  • live : 只 dump 活动对象;如果未指定,堆中的所有对象将被dump。
  • format=b : 二进制格式
  • file= : dump 到指定文件

jmap -heap

通过指定 pid,可以将当前进程的 heap 信息打印在 console 上,包括使用的 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
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
$ jmap -heap 3493
Attaching to process ID 3493, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.172-b245

using parallel threads in the new generation.(eden 区使用的是并发线程)
using thread-local object allocation.(使用线程本地对象分配)
Concurrent Mark-Sweep GC (使用 CMS 垃圾收集器)
# 堆配置信息
Heap Configuration:
MinHeapFreeRatio = 40
MaxHeapFreeRatio = 70
MaxHeapSize = 2147483648 (2048.0MB)
NewSize = 805306368 (768.0MB)
MaxNewSize = 805306368 (768.0MB)
OldSize = 1342177280 (1280.0MB)
NewRatio = 2
SurvivorRatio = 8
MetaspaceSize = 21807104 (20.796875MB)
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 17592186044415 MB
G1HeapRegionSize = 0 (0.0MB)

# 堆使用情况
Heap Usage:
New Generation (Eden + 1 Survivor Space):
capacity = 724828160 (691.25MB)
used = 35156456 (33.527809143066406MB)
free = 689671704 (657.7221908569336MB)
4.850315970063856% used
Eden Space:
capacity = 644349952 (614.5MB)
used = 19878008 (18.95714569091797MB)
free = 624471944 (595.542854309082MB)
3.084970820328392% used
From Space:
capacity = 80478208 (76.75MB)
used = 15278448 (14.570663452148438MB)
free = 65199760 (62.17933654785156MB)
18.984577787815553% used
To Space:
capacity = 80478208 (76.75MB)
used = 0 (0.0MB)
free = 80478208 (76.75MB)
0.0% used
concurrent mark-sweep generation:
capacity = 1342177280 (1280.0MB)
used = 166885296 (159.1542205810547MB)
free = 1175291984 (1120.8457794189453MB)
12.433923482894897% used

55843 interned Strings occupying 6689024 bytes.

jmap -clstats

通过指定 pid ,可以将当前进程的 classloader 统计信息打印在 console 上,包括类加载器名称、对象是否存活、对象地址、父类加载器、已加载的类大小等信息,如下:

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
$ jmap -clstats  3493
Attaching to process ID 3493, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.172-b245
finding class loader instances ..done.
computing per loader stat ..done.
please wait.. computing liveness.......................liveness analysis may be inaccurate ...
class_loader classes bytes parent_loader alive? type

<bootstrap> 3211 5818395 null live <internal>
0x00000000b150ed50 1 1491 0x00000000b0020830 dead sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b8715670 1 900 0x00000000b0020830 dead sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000cb417140 1 1503 0x00000000b0020830 dead sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b98b4388 1 1491 null dead sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b5a419a0 1 900 0x00000000b0020830 dead sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b358df50 1 1493 0x00000000b0020830 dead sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b7b277b8 1 1503 0x00000000b0020830 dead sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000c2527c58 1 1505 0x00000000b0020830 dead sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b98b4580 1 1491 0x00000000b0026260 dead sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b9b307b8 1 1493 0x00000000b0020830 dead sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000e236b038 1 900 0x00000000b0020830 dead sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b0108400 1 1493 0x00000000b0020830 dead sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b010bc00 3 7946 0x00000000b0022f60 live org/jacoco/compass/agent/rt/internal/fastjson/util/ASMClassLoader@0x00000001000eb830
0x00000000b358e148 1 1493 0x00000000b0020830 dead sun/reflect/DelegatingClassLoader@0x000000010000a040

jmap -histo

使用 jmap -histo pid 可以查看堆内存中的对象数目、大小统计直方图,如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
# jmap -histo:live 1493  带上 live 则只统计存活对象
$ jmap -histo 1493
num #instances #bytes class name
----------------------------------------------
1: 1314509 144436976 [C
2: 1572864 37748736 org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapper
3: 77458 32776608 [B
4: 1061561 25477464 java.lang.String
5: 731623 23411936 java.util.HashMap$Node
6: 32930 22826616 [I
7: 150340 15546784 [Ljava.util.HashMap$Node;
8: 144895 14968208 [Ljava.lang.Object;
9: 377379 12076128 java.util.concurrent.ConcurrentHashMap$Node
10: 230943 11085264 java.util.HashMap
11: 81124 3893952 java.nio.HeapByteBuffer
12: 3396 3869944 [Ljava.util.concurrent.ConcurrentHashMap$Node;
13: 78418 3764064 java.nio.HeapCharBuffer
14: 75784 3031360 java.util.TreeMap$Entry
15: 72865 2914600 java.util.LinkedHashMap$Entry
16: 166213 2659408 java.util.HashSet
17: 18355 2643120 com.mysql.jdbc.Field
18: 18394 2044336 java.lang.Class
19: 19966 1757008 java.lang.reflect.Method

PS: 上图中的 [C [B 指的是 class 的对象类型,下面是常见类型的参考

  • B byte
  • C char
  • D double
  • F float
  • I int
  • J long
  • Z boolean
  • [ 数组,如 [I 表示 int[]
  • [L+类名 其他对象,如 [Ljava.lang.Object

jmap -dump

绝大多数情况下,我们不会直接在 console 来打印分析,更常规的做法是 dump 到指定的文件,然后通过一些可视化工具来辅助分析;那执行 dump 到文件一般使用如下指令:

1
2
3
4
5
jmap -dump:format=b,file=dumpFileName pid   # 语法

$ jmap -dump:format=b,file=test-dump.bin 85716 # 举例
Dumping heap to /Users/guolei.sgl/test-dump.bin ...
Heap dump file created

对于 dump 下来的文件,可以通过 jprofile 等图形化工具来分析,如下

也可以通过 jhat 查看,操作方式如下:

1、起 http 服务

1
2
3
4
5
6
7
8
9
10
jhat -port 9300 test-dump.bin
Reading from test-dump.bin...
Dump file created Wed Oct 28 17:54:24 CST 2020
Snapshot read, resolving...
Resolving 1151952 objects...
Chasing references, expect 230 dots......................................................................................................................................................................................................................................
Eliminating duplicate references......................................................................................................................................................................................................................................
Snapshot resolved.
Started HTTP server on port 9300
Server is ready.

2、dump 类概要信息

访问 localhost:9300 查看 dump 概要信息

3、class 详情

点击某个类查看详细信息

小结

本文介绍了一些 JDK 自带的一些性能调优监控工具,通过对这些工具的掌握,可以使的我们在实际的开发或者运维中能够快速的去定位和解决一些问题,常见的有 OOM、内存泄漏、线程死锁、CPU 负载高等等;目前社区也有很多好用的工具,例如 Arthasperfma 等。

作者

卫恒

发布于

2020-10-26

更新于

2022-04-23

许可协议

评论