[JVM] Java Thread Dump 分析 [转载]

0 序

缘起

近期项目上我负责的微服务出现了难以排查的问题，目前怀疑是线程方面的情况，故需深入了解thread dump文件内容的各项含义。

本文主要转载了网友的观点，详见：参考文献

诊断 Java 应用的过程中, 我们经常要去看线程的相关信息.

比如：
当前 JVM 有多少线程
从启动到现在已经创建过多少线程,
线程的 CPU 使用率
线程是不是发生了死锁
CPU 使用率过高是哪些代码导致的.

这要求我们对 Java 的线程必须有一定的了解, 才能比较有针对性的分析这些问题.
下面我们就从分析 Thread dump 开始介绍 Thread 相关的信息.

1 如何查看当前Java应用线程的信息?Thread Dump 文件

最快速的方式就是获得当前应用的 Thread dump, 然后使用文本的方式查看. 比如:

$ jps
49048 Jps
3499 Pycharm

$ jcmd 3499 Thread.print > /tmp/thread.tdump
$ cat /tmp/thread.tdump

上面的例子中, 我们先是使用 jps 查看当前的用户的 Java 进程, 然后我们使用 jcmd <pid> Thread.print 命令来输出 Thread dump.
默认情况下, 这个命令会打印到当前控制台, 我们重定向到一个本地文件. 然后使用 cat 命令来查看具体的线程内容(如果你是桌面模式, 可以使用任何文本编辑器查看).
获取 thread dump 文件的方法（方法很多，仅简单小结一二）
- jcmd
  - jcmd 是 JDK 自带的命令, 通过 jcmd <pid> Thread.print 就可以得到
- jstack
  - jstack 也是 JDK 自带的命令, 通过 jstack -l -e <pid> 也可以获得
- jconsole
  - jconsole 是 JDK 自带的一个桌面工具, 它和 jcmd/jstack 一样, 也在 JDK 的 bin 目录下, 连接上对应的JVM 之后, 它就可以查看线程的相关信息, 还可以检测死锁.
  - 缺点：必须有桌面图形端支持

jconsole

我们把整个 Thread dump 的信息, 分成3部分来分别讲解:

头部 JVM 及线程 Summary 部分
常规线程具体信息部分
尾部特殊线程及其它部分

2 Thread dump 头部 JVM 及线程ID列表

在最开始部分, 我们看到类似下面的信息:

3499:
2023-04-01 08:41:33
Full thread dump OpenJDK 64-Bit Server VM (17.0.5+1-b653.25 mixed mode):
 
Threads class SMR info:
_java_thread_list=0x000060000b029f00, length=113, elements={
0x00007fc18981e800, 0x00007fc18a01ee00, 0x00007fc18a01cc00, 0x00007fc18a8bea00,
				... ...
0x00007fc1878f0200, 0x00007fc1410d6600, 0x00007fc18a489600, 0x00007fc131aefa00,
0x00007fc131ad4a00
}

第1行：当前进程的进程号(pid)
第2行：产生 Thread dump的系统时间
第3行：主要是JDK的信息
后续行：所有线程的线程ID(tid)的列表、及线程的数量(113)
- 上面SMR是 Safe Memory Reclamation 的缩写.
- 【这部分内容，可能因不同版本、厂商的JVM虚拟机而不同，也可能不存在这部分内容】
  - 不影响分析（只不过是统计信息罢了）

这部分信息通常情况下价值不大, 大部分有用的信息都在线程具体内容部分.

3 Thread dump 常规线程具体信息

接下来就是每个线程的具体元数据部分和线程栈部分. 我们拿其中一个例子来说明:

"pool-4-thread-1" #191 prio=5 os_prio=31 cpu=4012.76ms elapsed=313903.17s allocated=1229K defined_classes=23 tid=0x00007fc1898a8000 nid=0x23757 in Object.wait()  [0x000070000a4d5000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@17.0.5/Native Method)
	- waiting on <no object reference available>
	at java.io.PipedInputStream.read(java.base@17.0.5/PipedInputStream.java:326)
	- eliminated <0x0000000782139b00> (a java.io.PipedInputStream)
	at java.io.PipedInputStream.read(java.base@17.0.5/PipedInputStream.java:377)
	- locked <0x0000000782139b00> (a java.io.PipedInputStream)
	at com.jetbrains.python.console.transport.TCumulativeTransport.read(TCumulativeTransport.kt:46)
	at com.jetbrains.python.console.transport.server.TNettyServerTransport$TNettyTransport.readAll(TNettyServerTransport.kt:243)
	at org.apache.thrift.protocol.TBinaryProtocol.readAll(TBinaryProtocol.java:455)
	at org.apache.thrift.protocol.TBinaryProtocol.readI32(TBinaryProtocol.java:354)
	at org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:243)
	at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:27)
	at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:313)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.5/ThreadPoolExecutor.java:1136)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.5/ThreadPoolExecutor.java:635)
	at java.lang.Thread.run(java.base@17.0.5/Thread.java:833)
 
   Locked ownable synchronizers:
	- <0x0000000782139ef8> (a java.util.concurrent.ThreadPoolExecutor$Worker)

第1行是当前线程的元数据信息, 包含很多有用的信息, 我们逐一来解释一下:

"pool-4-thread-1": 是当前线程的名字
#192: 表示这是应用启动后创建的第192个线程, 我们可以看到这个数字在我们的 Thread dump 从上到下是顺序增加的, 如果你发现中间某个数字没有, 说明那个线程已经死亡了.
prio=5: 这是线程的优先级. Java 线程优先级是1~10, 默认是5.
os_prio=31: 这是当前线程在操作系统层面的优先级, 这里是31.
cpu=4012.76ms: 表示当前线程从开始运行到生成Thread dump 时共使用了4012.76ms CPU 时间.
elapsed=313903.17s: 表示当前线程已经存活了313903.17s秒.
allocated=1229K: 表示当前线程共分配了1229K的内存.
defined_classes=23: 表示当前线程共新定义了23个新类.
tid=0x00007fc1898a8000: 当前线程的ID, 和第一部分的线程ID对应.
nid=0x23757: 当前线程在操作系统层面的ID(在Linux里,线程是一个轻量级的进程(LWP， Light Weight Process)).
in Object.wait(): 表示当前线程最后运行在 Obect 类的 wait() 方法里面.

[0x000070000a4d5000]: 最后的栈指针(SP)地址, 一般诊断中用不到这个信息.

第2行是告诉在我们当前线程的状态: TIMED_WAITING, 并且是等着对象的 monitor 上.
接着是线程的栈信息, 以 at 开头的行告诉我们当前栈帧执行的类和方法, 括号里面的内容告诉我们这个类的源文件名及当前在执行的行号, 如果前面有 /, 斜线前面表示代码属于的模块及版本.

另外有些行是以 - 开头的, 比如下面的每一行的栈帧都跟着一行以 - 开头的一行:

	at java.lang.Object.wait(java.base@17.0.5/Native Method)
	- waiting on <no object reference available>
	at java.io.PipedInputStream.read(java.base@17.0.5/PipedInputStream.java:326)
	- eliminated <0x0000000782139b00> (a java.io.PipedInputStream)
	at java.io.PipedInputStream.read(java.base@17.0.5/PipedInputStream.java:377)
	- locked <0x0000000782139b00> (a java.io.PipedInputStream)

首先, 我们最下面2行看起, 第5行表示在执行 PipedInputStream 的 377 行的 read()方法的时候, 当前线程获得了一把锁, 这把锁是属于一个 java.io.PipedInputStream 对象的. 下面是截取的 JDK 这个版本的 PipedInputStream 类的377 行附近的源代码:

可以看到, 这个方法是一个 synchronized 方法, 要执行到377行, 必须先获得当前对象的锁.

然后我们看第3, 4 行, 它表示在执行PipedInputStream 的326 行的 read() 方法的时候, 当前线程临时释放(eliminated) 了上层栈帧(第5行)获得的那把锁, 根据锁的ID可以看出锁是同一把.

然后我们看326行附近的源代码:

进入这个方法也需要获得当前对象的锁, 但是上层栈帧已经获得了这个锁, 所以这次可以直接进入这个方法. 然后在326行, 当前线程调用当前对象的 wait() 方法, 并且给了1000ms 的参数, 意思是:

当前线程要临时放弃拥有这个锁, 并且加入这个锁的wait队列.
在这个wait队列里, 如果没被 notify(), notifyAll() 提前唤醒进入等待队列, 那么至多等待1000ms, 就可以进入这个锁的block队列
- (关于 syncronized 锁, wait(), notify(), notifyAll() 方法以及 block队列和 wait 队列, 请查询相关信息),
然后就可以竞争再次获得这个锁.
进入 wait() 方法之后, 就进入了非Java写的 native code, 拿不到对象的地址, 所以这里虽然显示等着, 但是没有对象的引用可以给我们看.
最后, 每个线程尾部, 都有一段是关于Locked ownable synchronizers的部分. 有的线程拥有这种一个或多个同步器, 有的没有(none), 如果有就显示在这里.

   Locked ownable synchronizers:
	- <0x0000000782139ef8> (a java.util.concurrent.ThreadPoolExecutor$Worker)

在 Java 里面凡是使用 java.util.concurrent.locks.AbstractOwnableSynchronizer 或其子类实现同步功能的同步器, 并且被某个线程获得这个同步器锁的, 这个同步器就会显示在这段 Locked ownable synchronizers 里面. Java 里面的2个实现类分别是: ReentrantLock 和 ReentrantReadWriteLock

在 Java 里面, 一个锁(lock)可以是一个内置的(built-in) monitor, 也可以是一个 ownable synchronizer, 也可以是一个与同步器关联的 java.util.concurrent.locks.Condition对象.

4 尾部特殊线程及其它

在整个 Thread dump 的最下面, 我们可以看到一些信息非常简单的线程, 比如下面这种:

"VM Thread" os_prio=31 cpu=10486.47ms elapsed=314111.17s tid=0x00007fc188405460 nid=0x7c03 runnable  
 
"GC Thread#0" os_prio=31 cpu=71683.40ms elapsed=314111.18s tid=0x00007fc188507c80 nid=0x4203 runnable  
 
"GC Thread#1" os_prio=31 cpu=71692.01ms elapsed=314110.89s tid=0x00007fc18800dd80 nid=0xe403 runnable  
 
"G1 Conc#0" os_prio=31 cpu=295753.03ms elapsed=314111.18s tid=0x00007fc188508ba0 nid=0x4403 runnable  
 
"G1 Conc#1" os_prio=31 cpu=295775.82ms elapsed=314110.87s tid=0x00007fc136f0aa20 nid=0x1050b runnable  
 
"VM Periodic Task Thread" os_prio=31 cpu=49667.04ms elapsed=314111.09s tid=0x00007fc188529b50 nid=0x6c03 waiting on condition

这种线程基本都是 JVM 本身的一些线程, 不去处理我们写的业务逻辑, 主要用来维护 JVM 系统本身. 它的元数据跟我们上面介绍的线程元数据一样, 信息更少, 由于很多都是 native 代码编写, 也没有Java 的栈帧信息.

最后, Java Native Interface(JNI)相关的一些信息. 比如:

JNI global refs: 2777, weak refs: 6388

Y 延伸与补充

Y.1 死锁信息

如果在做 Thread dump 的时候, 有死锁的存在, Thread dump 里面最后面会标明线程死锁的相关信息, 比如:

Found one Java-level deadlock:
=============================
"Thread-0":
  waiting to lock monitor 0x0000600003a000d0 (object 0x000000061f613348, a java.io.PrintStream),
  which is held by "Thread-1"
 
"Thread-1":
  waiting to lock monitor 0x0000600003a185b0 (object 0x000000061f54ddd8, a ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy),
  which is held by "Thread-0"
 
Java stack information for the threads listed above:
===================================================
"Thread-0":
	at java.io.PrintStream.write(java.base@17.0.2/PrintStream.java:696)
	- waiting to lock <0x000000061f613348> (a java.io.PrintStream)
	at java.io.PrintStream.print(java.base@17.0.2/PrintStream.java:877)
	   ... 省略 ...
"Thread-1":
	at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:234)
	- waiting to lock <0x000000061f54ddd8> (a ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy)
        ... 省略 ...

我们会在后续的文章中单独介绍死锁, 所以关于死锁的诊断, 发生的可能情况, 这里就不介绍了.

Y.2 编程方式获取线程信息

通过使用 ThreadMXBean 接口, 能比较容易的在代码中获得Java 线程的相关信息, 大家可以尝试使用如下代码:

public static void main(String[] args) {
    ThreadInfo[] threadInfos = ManagementFactory.getThreadMXBean()
        .dumpAllThreads(true, true);
    Arrays.stream(threadInfos).forEach(System.out::println);
}

Y.3 监控 JVM Thread 的一些指标

thread dump 文件里，值得关注的线程状态有：

死锁， Deadlock（重点关注）

执行中，Runnable

等待资源， Waiting on condition（重点关注）

等待获取监视器， Waiting on monitor entry（重点关注）

暂停，Suspended

对象等待中，Object.wait() 或 TIMED_WAITING

阻塞， Blocked（重点关注）

停止，Parked

监控 Java 应用线程的相关指标对于我们观察应用的健康状况很重要, 那么有哪些跟线程相关的指标呢?

当前活跃的线程数目、从启动到现在的所有创建的线程数目;

按照线程的状态(blocked, running, waiting, timed_waiting)来分类的活跃线程数目;

按照线程是不是 daemon 线程的来分类;

死锁线程的数目;

X 参考文献

Java Thread Dump 分析 - CSDN

posted @ 2023-12-07 10:42 千千寰宇阅读(424) 评论(0) 编辑收藏举报

刷新页面返回顶部

千千寰宇

大数据与Java软件开发从业者，数智化转型实践者。