JVM Thread Dump 文件分析

作者: 若丨寒 | 来源:发表于2021-01-15 14:34 被阅读0次

JAVA Thread Dump 文件分析

Thread Dump介绍

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

Thread Dump特点

能在各种操作系统下使用
能在各种Java应用服务器下使用
可以在生产环境下使用而不影响系统的性能
可以将问题直接定位到应用程序的代码行上(对于线上排查问题非常有用)

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

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进程的信息

image

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

jstack  -l  9468 | tee -a jstack.log

image

日志字段分析

我们把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。

image

从上图可以看出，每个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线程状态

NEW：

每一个线程，在堆内存中都有一个对应的Thread对象。 Thread t = new Thread();当刚刚在堆内存中创建Thread对象，还没有调用t.start()方法之前，线程就处在NEW状态。在这个状态上，线程与普通的java对象没有什么区别，就仅仅是一个堆内存中的对象。

RUNNABLE：

该状态表示线程具备所有运行条件，在运行队列中准备操作系统的调度，或者正在运行。这个状态的线程比较正常，但如果线程长时间停留在在这个状态就不正常了，这说明线程运行的时间很长（存在性能问题），或者是线程一直得不得执行的机会（存在线程饥饿的问题）。

BLOCKED：

线程正在等待获取java对象的监视器(也叫内置锁)，即线程正在等待进入由synchronized保护的方法或者代码块。 synchronized用来保证原子性，任意时刻最多只能由一个线程进入该临界区域，其他线程只能排队等待。

WAITING：

处在该线程的状态，正在等待某个事件的发生，只有特定的条件满足，才能获得执行机会。而产生这个特定的事件，通常都是另一个线程。也就是说，如果不发生特定的事件，那么处在该状态的线程一直等待，不能获取执行的机会。比如：

A线程调用了obj对象的obj.wait()方法，如果没有线程调用obj.notify或obj.notifyAll，那么A线程就没有办法恢复运行；如果A线程调用了LockSupport.park()，没有别的线程调用LockSupport.unpark(A)，那么A没有办法恢复运行。

TIMED_WAITING：

J.U.C中很多与线程相关类，都提供了限时版本和不限时版本的API。TIMED_WAITING意味着线程调用了限时版本的API，正在等待时间流逝。当等待时间过去后，线程一样可以恢复运行。如果线程进入了WAITING状态，一定要特定的事件发生才能恢复运行；而处在TIMED_WAITING的线程，如果特定的事件发生或者是时间流逝完毕，都会恢复运行。

TERMINATED：

线程执行完毕，执行完run方法正常返回，或者抛出了运行时异常而结束，线程都会停留在这个状态。这个时候线程只剩下Thread对象了，没有什么用了。

根据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的输出中消失。

来源：https://www.tuicool.com/articles/NfI7nm2

JVM Thread Dump 文件分析

JAVA Thread Dump 文件分析

Thread Dump介绍

Thread Dump特点

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

如何抓取Thread Dump

实操演练

日志字段分析

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

系统线程状态 (Native Thread Status)

JVM线程状态

根据dump日志分析

例子1:

例子2:

例子3

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

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读

Java架构技术栈