【Java】JVM Thread Dump 文件分析

JAVA Thread Dump 文件分析

Thread Dump介绍

Thread Dump是非常有用的诊断Java应用问题的工具。每一个Java虚拟机都有及时生成所有线程在某一点状态的thread-dump的能力，虽然各个 Java虚拟机打印的thread dump略有不同，但是大多都提供了每个线程的所有信息，例如: 线程状态、线程 Id、本机 Id、线程名称、堆栈跟踪、优先级。

Thread Dump特点

  1. 能在各种操作系统下使用

  2. 能在各种Java应用服务器下使用

  3. 可以在生产环境下使用而不影响系统的性能

  4. 可以将问题直接定位到应用程序的代码行上(对于线上排查问题非常有用)

它能帮我们解决哪些线上问题?

Thread dump 能帮我们定位到 例如 CPU 峰值、应用程序中的无响应性、响应时间差、线程挂起、高内存消耗。

如何抓取Thread Dump

一般当服务器挂起,崩溃或者性能底下时,就需要抓取服务器的线程堆栈(Thread Dump)用于后续的分析. 在实际运行中，往往一次 dump的信息，还不足以确认问题。为了反映线程状态的动态变化，需要接连多次做threaddump，每次间隔10-20s，建议至少产生三次 dump信息，如果每次 dump都指向同一个问题，我们才确定问题的典型性。

获取thread dump

JDK自带命令行工具获取PID，再获取ThreadDump:
1. jps 或 ps –ef|grep java (获取PID)
2. jstack [-l ]<pid> | tee -a jstack.log  (获取ThreadDump)

实操演练

获取所有线程的thread dump 分两步.

  • 第一步 获取进程的PID

使用Jps 获取所有java进程的信息

【Java】JVM Thread Dump 文件分析

  • 第二步 选取对应的pid 例如上图红框中的数字串 使用Jstack获取所有线程栈信息

jstack  -l  9468 | tee -a jstack.log

【Java】JVM Thread Dump 文件分析

日志字段分析

我们把Thread dump文件分为2个部分来理解

拿我们的例子来说:

//头部信息  包含 当前时间  jvm信息
2021-01-14 17:00:51
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.171-b11 mixed mode):

//线程info信息块
"ajp-nio-8019-exec-7" #75 daemon prio=5 os_prio=0 tid=0x00007fa0cc37e800 nid=0x2af3 waiting on condition [0x00007fa02eceb000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for  <0x00000000f183aa30> (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.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:103)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:31)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)

线程info信息块各个参数的意义:

  • 线程名称：ajp-nio-8019-exec-7

  • 线程类型：daemon

  • 优先级: 默认是5

  • jvm线程id：tid=0x00007fa0cc37e800，jvm内部线程的唯一标识（通过java.lang.Thread.getId()获取，通常用自增方式实现。）

  • 对应系统线程id（NativeThread ID）：nid=0x2af3，和top命令查看的线程pid对应，不过一个是10进制，一个是16进制。（通过命令：top -H -p pid，可以查看该进程的所有线程信息）

  • 线程状态：java.lang.Thread.State: WAITING (parking)

  • 线程调用栈信息：用于代码的分析。堆栈信息应该从下向上解读，因为程序调用的顺序是从下向上的。

系统线程状态 (Native Thread Status)

系统线程有如下状态：

  • deadlock

死锁线程，一般指多个线程调用期间进入了相互资源占用，导致一直等待无法释放的情况。

  • runnable

一般指该线程正在执行状态中，该线程占用了资源，正在处理某个操作，如通过SQL语句查询数据库、对某个文件进行写入等。

  • blocked

线程正处于阻塞状态，指当前线程执行过程中，所需要的资源长时间等待却一直未能获取到，被容器的线程管理器标识为阻塞状态，可以理解为等待资源超时的线程。

  • waiting on condition

线程正处于等待资源或等待某个条件的发生，具体的原因需要结合下面堆栈信息进行分析。

（1）如果堆栈信息明确是应用代码，则证明该线程正在等待资源，一般是大量读取某种资源且该资源采用了资源锁的情况下，线程进入等待状态，等待资源的读取，或者正在等待其他线程的执行等。

（2）如果发现有大量的线程都正处于这种状态，并且堆栈信息中得知正等待网络读写，这是因为网络阻塞导致线程无法执行，很有可能是一个网络瓶颈的征兆：

网络非常繁忙，几乎消耗了所有的带宽，仍然有大量数据等待网络读写；
网络可能是空闲的，但由于路由或防火墙等原因，导致包无法正常到达；
所以一定要结合系统的一些性能观察工具进行综合分析，比如netstat统计单位时间的发送包的数量，看是否很明显超过了所在网络带宽的限制；观察CPU的利用率，看系统态的CPU时间是否明显大于用户态的CPU时间。这些都指向由于网络带宽所限导致的网络瓶颈。

（3）还有一种常见的情况是该线程在 sleep，等待 sleep 的时间到了，将被唤醒。

  • waiting for monitor entry 或 in Object.wait()

Moniter 是Java中用以实现线程之间的互斥与协作的主要手段，它可以看成是对象或者class的锁，每个对象都有，也仅有一个 Monitor。
【Java】JVM Thread Dump 文件分析

从上图可以看出，每个Monitor在某个时刻只能被一个线程拥有，该线程就是 "Active Thread"，而其他线程都是 "Waiting Thread"，分别在两个队列 "Entry Set"和"Wait Set"里面等待。其中在 "Entry Set" 中等待的线程状态是 waiting for monitor entry，在 "Wait Set" 中等待的线程状态是 in Object.wait()。

（1）"Entry Set"里面的线程。
我们称被 synchronized 保护起来的代码段为临界区，对应的代码如下：

synchronized(obj) {
}

当一个线程申请进入临界区时，它就进入了 "Entry Set" 队列中，这时候有两种可能性：

  • 该Monitor不被其他线程拥有，"Entry Set"里面也没有其他等待的线程。本线程即成为相应类或者对象的Monitor的Owner，执行临界区里面的代码；此时在Thread Dump中显示线程处于 "Runnable" 状态。

  • 该Monitor被其他线程拥有，本线程在 "Entry Set" 队列中等待。此时在Thread Dump中显示线程处于 "waiting for monity entry" 状态。

临界区的设置是为了保证其内部的代码执行的原子性和完整性，但因为临界区在任何时间只允许线程串行通过，这和我们使用多线程的初衷是相反的。如果在多线程程序中大量使用synchronized，或者不适当的使用它，会造成大量线程在临界区的入口等待，造成系统的性能大幅下降。如果在Thread Dump中发现这个情况，应该审视源码并对其进行改进。

（2）"Wait Set"里面的线程
当线程获得了Monitor，进入了临界区之后，如果发现线程继续运行的条件没有满足，它则调用对象（通常是被synchronized的对象）的wait()方法，放弃Monitor，进入 "Wait Set"队列。只有当别的线程在该对象上调用了 notify()或者notifyAll()方法，"Wait Set"队列中的线程才得到机会去竞争，但是只有一个线程获得对象的Monitor，恢复到运行态。"Wait Set"中的线程在Thread Dump中显示的状态为 in Object.wait()。

通常来说，当CPU很忙的时候关注 Runnable 状态的线程，反之则关注 waiting for monitor entry 状态的线程。

JVM线程状态

根据dump日志分析

下面我们根据实际的代码 来分析dump日志,可以更加透明的了解线程为什么是这个状态

例子1:

等待释放锁

package jstack;
public class BlockedState
{
private static Object object = new Object();
public static void main(String[] args)
{
Runnable task = new Runnable() {
@Override
public void run()
{
synchronized (object)
{
long begin = System.currentTimeMillis();
long end = System.currentTimeMillis();
// 让线程运行5分钟,会一直持有object的监视器
while ((end - begin) <= 5 * 60 * 1000)
{
}
}
}
};
new Thread(task, "t1").start();
new Thread(task, "t2").start();
}
}

先获取object的线程会执行5分钟，这5分钟内会一直持有object的监视器，另一个线程无法执行处在BLOCKED状态

"t2" prio=6 tid=0x27d7a800 nid=0x1350 waiting for monitor entry [0x2833f000]
java.lang.Thread.State: BLOCKED (on object monitor)
at jstack.BlockedState$1.run(BlockedState.java:17)
- waiting to lock <0x1cfcdc00> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:662)
"t1" prio=6 tid=0x27d79400 nid=0x1338 runnable [0x282ef000]
java.lang.Thread.State: RUNNABLE
at jstack.BlockedState$1.run(BlockedState.java:22)
- locked <0x1cfcdc00> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:662)

通过thread dump可以看到：t2线程在BLOCKED (on object monitor)。waiting for monitor entry 等待进入synchronized保护的区域 ，但obj对应的 Monitor 被其他线程所拥有，所以 JVM线程的状态是 java.lang.Thread.State: BLOCKED (on object monitor)，说明线程等待资源。

例子2:

死锁

public class DeadLock {
public static void main(String[] args) {
final Object resource1 = "resource1";
final Object resource2 = "resource2";
Thread t1 = new Thread(){
public void run(){
synchronized(resource1){
System.out.println("Thread1:locked resource1");
try{
Thread.sleep(50);
}catch(Exception ex){
}
synchronized(resource2){
System.out.println("Thread1:locked resource2");
}
}
}
};
Thread t2 = new Thread(){
public void run(){
synchronized(resource2){
System.out.println("Thread2:locked resource2");
try{
Thread.sleep(50);
}catch(Exception ex){
}
synchronized(resource1){
System.out.println("Thread2:locked resource1");
}
}
}
};
t1.start();
t2.start();
}
}

我们的这段代码是让两个线程互相等待对象释放锁,造成死锁的情况,在这种情况下,获取Thread dump文件 我们会发现jvm已经提示我们死锁了 如下:

"Thread-1" #20 prio=5 os_prio=31 tid=0x00007fb76c0e1800 nid=0x9d03 waiting for monitor entry [0x0000700004dbf000]
java.lang.Thread.State: BLOCKED (on object monitor)
at DeadLock$2.run(DeadLock.java:35)
- waiting to lock <0x000000076af61870> (a java.lang.String)
- locked <0x000000076af618b0> (a java.lang.String)
"Thread-0" #19 prio=5 os_prio=31 tid=0x00007fb76c002800 nid=0x9e03 waiting for monitor entry [0x0000700004cbc000]
java.lang.Thread.State: BLOCKED (on object monitor)
at DeadLock$1.run(DeadLock.java:19)
- waiting to lock <0x000000076af618b0> (a java.lang.String)
- locked <0x000000076af61870> (a java.lang.String)

Found one Java-level deadlock:
=============================
"Thread-1":
waiting to lock monitor 0x00007fb769825b58 (object 0x000000076af61870, a java.lang.String),
which is held by "Thread-0"
"Thread-0":
waiting to lock monitor 0x00007fb769823168 (object 0x000000076af618b0, a java.lang.String),
which is held by "Thread-1"
Java stack information for the threads listed above:
===================================================
"Thread-1":
at DeadLock$2.run(DeadLock.java:35)
- waiting to lock <0x000000076af61870> (a java.lang.String)
- locked <0x000000076af618b0> (a java.lang.String)
"Thread-0":
at DeadLock$1.run(DeadLock.java:19)
- waiting to lock <0x000000076af618b0> (a java.lang.String)
- locked <0x000000076af61870> (a java.lang.String)
Found 1 deadlock.

例子3

调用wait()，sleep()对应的线程状态

    public static void main(String[] args) {
Thread thread = new Thread("线程1") {
//重写run方法
public void run() {
synchronized (this) {
System.out.println(Thread.currentThread().getName());
try {
wait();
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
};
thread.start();
try {
TimeUnit.SECONDS.sleep(3);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (thread) {
System.out.println(Thread.currentThread().getName());
try {
TimeUnit.SECONDS.sleep(60);
} catch (InterruptedException e) {
e.printStackTrace();
}
thread.notify();
}
}

上面代码会先执行线程1 run()方法，然后调用wait()方法阻塞block住。等到主线程调用thread.notify()方法之后才会继续往下执行。我们在程序跑起来之后大概10秒时候导出thread dump日志文件信息，此时：

"线程1" #12 prio=5 os_prio=0 tid=0x00007f420024d800 nid=0x1ca5 in Object.wait() [0x00007f41e71ee000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1)
at java.lang.Object.wait(Object.java:502)
at com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1.run(ObjectWaitingMock.java:15)
- locked <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1)
Locked ownable synchronizers:
- None
....(其他信息这里我们省略掉)
"main" #1 prio=5 os_prio=0 tid=0x00007f420000d800 nid=0x1c84 waiting on condition [0x00007f4209891000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at java.lang.Thread.sleep(Thread.java:340)
at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
at com.jvm.study.threaddump.deadlock.ObjectWaitingMock.main(ObjectWaitingMock.java:31)
- locked <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1)
Locked ownable synchronizers:
- None

  • [线程1]线程：wait()方法阻塞住了，状态对应in Object.wait()，状态详细信息对应java.lang.Thread.State: WAITING (on object monitor)。

  • [main]线程：TimeUnit.SECONDS.sleep(60)阻塞住了，状态对应waiting on condition，状态详细信息对应java.lang.Thread.State: TIMED_WAITING (sleeping)。

根据案例症状分析解决方案

  • 1 CPU占用率不高，但响应很慢

在整个请求的过程中多次执行Thread Dump然后进行对比，取得 BLOCKED状态的线程列表，通常是因为线程停在了I/O、数据库连接或网络连接的地方。

  • 2 CPU飙高，load高，响应很慢

一个请求过程中多次dump；对比多次dump文件的runnable线程，如果执行的方法有比较大变化，说明比较正常。如果在执行同一个方法，就有一些问题了；先找到占用CPU的进程，然后再定位到对应的线程，最后分析出对应的堆栈信息。
在同一时间多次使用上述的方法，然后进行对比分析，从代码中找到问题所在的原因.

  • 3 请求无法响应

多次dump，检查是否有 Found one Java-level deadlock提示,死锁经常表现为程序的停顿，或者不再响应用户的请求。从操作系统上观察，对应进程的CPU占用率为零，很快会从top或prstat的输出中消失。

以上是 【Java】JVM Thread Dump 文件分析 的全部内容， 来源链接： utcz.com/a/99266.html

回到顶部