诊断 Java 应用的过程中, 我们经常要去看线程的相关信息. 比如当前 JVM 有多少线程, 从启动到现在已经创建过多少线程, 线程的 CPU 使用率, 线程是不是发生了死锁, CPU 使用率过高是哪些代码导致的. 这要求我们对 Java 的线程必须有一定的了解, 才能比较有针对性的分析这些问题. 下面我们就从分析 Thread dump 开始介绍 Thread 相关的信息.
如何查看当前Java应用线程的信息
最快速的方式就是获得当前应用的 Thread dump, 然后使用文本的方式查看. 比如:
$ jps
49048 Jps
3499 Pycharm
$ jcmd 3499 Thread.print > /tmp/thread.txt
$ cat /tmp/thread.txt
复制代码上面的例子中, 我们先是使用 jps 查看当前的用户的 Java 进程, 然后我们使用 jcmd <pid> Thread.print 命令来输出 Thread dump. 默认情况下, 这个命令会打印到当前控制台, 我们重定向到一个本地文件. 然后使用 cat 命令来查看具体的线程内容(如果你是桌面模式, 可以使用任何文本编辑器查看).
我们把整个 Thread dump 的信息, 分成3部分来分别讲解:
- 头部 JVM 及线程 Summary 部分
- 常规线程具体信息部分
- 尾部特殊线程及其它部分
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
}
复制代码第一行是当前进程的进程号(pid), 第二行是产生 Thread dump的系统时间, 第三行主要是JDK的信息, 然后是所有线程的线程ID(tid)的列表,以及线程的数量(113). 上面SMR是 Safe Memory Reclamation 的缩写. 这部分信息通常情况下价值不大, 大部分有用的信息都在线程具体内容部分.
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)
复制代码第一行是当前线程的元数据信息, 包含很多有用的信息, 我们逐一来解释一下:
"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)).in Object.wait(): 表示当前线程最后运行在Obect类的wait()方法里面.[0x000070000a4d5000]: 最后的栈指针(SP)地址, 一般诊断中用不到这个信息.
第二行告诉我们当前线程的状态: 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对象.
尾部特殊线程及其它
在整个 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
复制代码死锁信息
如果在做 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)
... 省略 ...
复制代码我们会在后续的文章中单独介绍死锁, 所以关于死锁的诊断, 发生的可能情况, 这里就不介绍了.
如何获得 Thread dump
上面详细介绍了 Thread dump 里面的一些信息, 那么有哪些方式可以获得线程这些信息呢?
jcmd
jcmd 是 JDK 自带的命令, 通过 jcmd <pid> Thread.print 就可以得到
jstack
jstack 也是 JDK 自带的命令, 通过 jstack -l -e <pid> 也可以获得
其它方式查看线程的信息
jconsole
jconsole 是 JDK 自带的一个桌面工具, 它和 jcmd/jstack 一样, 也在 JDK 的 bin 目录下, 连接上对应的JVM 之后, 它就可以查看线程的相关信息, 还可以检测死锁.
编程方式获取线程信息
通过使用 ThreadMXBean 接口, 能比较容易的在代码中获得Java 线程的相关信息, 大家可以尝试使用如下代码:
public static void main(String[] args) {
ThreadInfo[] threadInfos = ManagementFactory.getThreadMXBean()
.dumpAllThreads(true, true);
Arrays.stream(threadInfos).forEach(System.out::println);
}
复制代码监控 JVM Thread 的一些指标
监控 Java 应用线程的相关指标对于我们观察应用的健康状况很重要, 那么有哪些跟线程相关的指标呢?
- 当前活跃的线程数目以及从启动到现在的所有创建的线程数目;
- 按照线程的状态(blocked, running, waiting, timed_waiting)来分类的活跃线程数目;
- 按照线程是不是 daemon 线程的来分类;
- 死锁线程的数目;
2221
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
