本篇主要学习记录下工作中常用的
JDK
自带的一些
JVM
性能调优监控工具,通过了解这些工具,可以在排查问题时给予我们非常大的帮助,将一些隐藏在底下的东西拿到明面上来做分析。
jps(Java Virtual Machine Process Status Tool)
jps
主要用来输出
JVM
中运行的进程状态信息。语法格式如下:
jps [options] [hostid] 复制代码
如果不指定
hostid
就默认为当前主机或服务器,命令行参数选项说明如下:
-q 不输出类名、Jar名和传入main方法的参数
➜ ~ jps -q 42060 复制代码
-m 输出传入 main 方法的参数(与默认 jps 指令返回的信息相同)
➜ ~ jps -m 42060 TestSofaBootApplication 复制代码
-l 输出 main 类或 jar 的全限名
➜ ~ jps -l 42060 com.glmapper.bridge.boot.TestSofaBootApplication 复制代码
-v 输出传入 JVM 的参数
➜ ~ 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 stack
和
native stack
的信息,从而可以轻松地知道
java
程序是如何崩溃和在程序何处发生问题。另外,
jstack
工具还可以附属到正在运行的
java
程序中,看到当时运行的
java
程序的
java stack
和
native stack
的信息, 如果现在运行的
java
程序呈现
hung
的状态,
jstack
是非常有用的。
下面是
jstack
语法格式:
jstack [option] pid jstack [option] executable core jstack [option] [server-id@]remote-hostname-or-ip 复制代码
不管是什么指令,我们都要学会先通过 -h 去查一下
➜ ~ 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
数据
"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
java.lang.Thread.State: TIMED_WAITING (sleeping) 复制代码
RUNNABLE
java.lang.Thread.State: RUNNABLE 复制代码
还有一些
"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fcee9004000 nid=0x1f07 runnable
信息,这种是 jvm 用来回收内存的,先不关注,这里主要看下
java.lang.Thread.State
;
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、执行代码
/** * 产生 waiting on condition */ private static void testWaitingOnConditionCondition(){ while (true){ try { Thread.sleep(60000); } catch (InterruptedException e) { e.printStackTrace(); } } } 复制代码
2、执行结果
"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、执行代码
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、执行结果
"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、执行代码
/** * 产生 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、执行结果
"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、执行代码
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、执行结果
"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 状态。
小结
一般情况我们在做问题排查时,如果系统非常慢,我们需要特别关注
Blocked
,
Waiting on condition
这些状态。如果系统的 cpu 负载比较高的话,则可以死循环等思路去摸查,此时要关注下
Runable
状态;那如果堆栈中有
Deadlock
,那就是产生了死锁。
jstat(JVM统计监测工具)
jstat
是 JVM 统计监测工具,其语法格式如下:
jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]] 复制代码
vmid
是
Java
虚拟机
ID
,在
Linux/Unix
系统上一般就是进程
ID
。
interval
是采样时间间隔;
count
是采样数目。比如下面输出的是
GC
信息,采样时间间隔为 1000ms,采样数为 3:
➜ ~ 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
使用。其使用语法如下:
jmap [option] <pid> jmap [option] <executable <core> jmap [option] [server_id@]<remote server IP or hostname> 复制代码
Options
参数说明如下:
选项 | 作用 |
---|---|
打印与
相同的信息 |
|
-heap |
打印
堆摘要 |
-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
jmap -heap
通过指定
pid
,可以将当前进程的
heap
信息打印在
console
上,包括使用的
GC
算法、堆配置参数和各代中堆内存使用情况,如下:
$ 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 上,包括类加载器名称、对象是否存活、对象地址、父类加载器、已加载的类大小等信息,如下:
$ 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 可以查看堆内存中的对象数目、大小统计直方图,如下:
# 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 到文件一般使用如下指令:
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 服务
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 负载高等等;目前社区也有很多好用的工具,例如 Arthas,perfma 等。
作者:glmapper