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 之后, 它就可以查看线程的相关信息, 还可以检测死锁.
    • 缺点：必须有桌面图形端支持

![[_attachments/Pasted image 20231207103808.png]]

jconsole

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

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

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 行附近的源代码:

![[_attachments/Pasted image 20231207102812.png]]

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

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

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

![[_attachments/Pasted image 20231207102841.png]]

进入这个方法也需要获得当前对象的锁, 但是上层栈帧已经获得了这个锁, 所以这次可以直接进入这个方法. 然后在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

本栏目推荐文章
• 深入探索JVM：理解Java程序在虚拟机中的存储和管理
• 用jacoco统计JAVA项目测试代码覆盖率
• Java实现在线编辑预览office文档
• Java小细节之缩进中if 和else的对应关系
• 【JVM】记录一次线上服务频繁FGC的排查过程
• 春眠不觉晓，Java数据类型知多少？基础牢不牢看完本文就有数了
• idea 中java代码修改后运行代码不生效
• Java日期时间处理详解
• java项目(jar包)配置为开机自启 jar包bat脚本启动和配置为开机自启
• Java中锁的解决方案

Thread Dump Java JVMthread dump java jvm heap dump java jvm dump线程tda-thread analyzer java jvm java-jvm 线程thread java thread java java平台jvm java jdk jre jvm java jvm jre jdk