Thread Dump 分析综述

最近在做性能测试，需要对线程堆栈进行分析，在网上收集了一些资料，学习完后，将相关知识整理在一起，输出文章如下。

一、Thread Dump介绍

1.1什么是Thread Dump？

Thread Dump是非常有用的诊断Java应用问题的工具。每一个Java虚拟机都有及时生成所有线程在某一点状态的thread-dump的能力，虽然各个 Java虚拟机打印的thread dump略有不同，但是大多都提供了当前活动线程的快照，及JVM中所有Java线程的堆栈跟踪信息，堆栈信息一般包含完整的类名及所执行的方法，如果可能的话还有源代码的行数。

 

1.2 Thread Dump特点

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

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

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

4. 可以将问题直接定位到应用程序的代码行上

 

1.3 Thread Dump 能诊断的问题

1. 查找内存泄露，常见的是程序里load大量的数据到缓存；

2. 发现死锁线程；

 

1.4如何抓取Thread Dump

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

有很多方式可用于获取ThreadDump, 下面列出一部分获取方式：

JVM 自带的工具获取线程堆栈:

JDK自带命令行工具获取PID，再获取ThreadDump:

1. jps 或 ps –ef|grepjava (获取PID)

2. jstack [-l ]<pid> | tee -a jstack.log  (获取ThreadDump)

 

二、java线程的状态转换介绍(为后续分析做准备)

java线程状态见《Thread之一：线程生命周期及五种状态》

 

三、Thread Dump分析

通过前面1.4部分的方法，获取Thread Dump信息后，对其进行分析；

3.1 jstack Dump 日志文件中的线程状态

dump 文件里，值得关注的线程状态有：
  1. 死锁，Deadlock（重点关注） 
  2. 执行中，Runnable   
  3. 等待资源，Waiting on condition（重点关注） 
  4. 等待获取监视器，Waiting on monitor entry（重点关注）
  5. 暂停，Suspended
  6. 对象等待中，Object.wait() 或 TIMED_WAITING
  7. 阻塞，Blocked（重点关注）  
  8. 停止，Parked
1，线程状态为“waiting for monitor entry”：
意味着它 在等待进入一个临界区 ，所以它在”Entry Set“队列中等待。
此时线程状态一般都是 Blocked：
  • java.lang.Thread.State: BLOCKED (on object monitor)
2，线程状态为“waiting on condition”：
说明它在等待另一个条件的发生，来把自己唤醒，或者干脆它是调用了 sleep(N)。
此时线程状态大致为以下几种：
  • java.lang.Thread.State: WAITING (parking)：一直等那个条件发生；
  • java.lang.Thread.State: TIMED_WAITING (parking或sleeping)：定时的，那个条件不到来，也将定时唤醒自己。
3，如果大量线程在“waiting for monitor entry”：
可能是一个全局锁阻塞住了大量线程。
如果短时间内打印的 thread dump 文件反映，随着时间流逝，waiting for monitor entry 的线程越来越多，没有减少的趋势，可能意味着某些线程在临界区里呆的时间太长了，以至于越来越多新线程迟迟无法进入临界区。
 
4，如果大量线程在“waiting on condition”：
可能是它们又跑去获取第三方资源，尤其是第三方网络资源，迟迟获取不到Response，导致大量线程进入等待状态。
所以如果你发现有大量的线程都处在 Wait on condition，从线程堆栈看，正等待网络读写，这可能是一个网络瓶颈的征兆，因为网络阻塞导致线程无法执行。
 
线程状态为“in Object.wait()”：
说明它获得了监视器之后，又调用了 java.lang.Object.wait() 方法。
每个 Monitor在某个时刻，只能被一个线程拥有，该线程就是 “Active Thread”，而其它线程都是 “Waiting Thread”，分别在两个队列 “ Entry Set”和 “Wait Set”里面等候。在 “Entry Set”中等待的线程状态是 “Waiting for monitor entry”，而在 “Wait Set”中等待的线程状态是 “in Object.wait()”。
当线程获得了 Monitor，如果发现线程继续运行的条件没有满足，它则调用对象（一般就是被 synchronized 的对象）的 wait() 方法，放弃了 Monitor，进入 “Wait Set”队列。
此时线程状态大致为以下几种：
  • java.lang.Thread.State: TIMED_WAITING (on object monitor)；
  • java.lang.Thread.State: WAITING (on object monitor)；
一般都是RMI相关线程（RMI RenewClean、 GC Daemon、RMI Reaper），GC线程（Finalizer），引用对象垃圾回收线程（Reference Handler）等系统线程处于这种状态。

3.2 Dump文件中的线程状态含义及注意事项

含义如下所示：

  • Deadlock：死锁线程，一般指多个线程调用间，进入相互资源占用，导致一直等待无法释放的情况。
  • Runnable：一般指该线程正在执行状态中，该线程占用了资源，正在处理某个请求，有可能正在传递SQL到数据库执行，有可能在对某个文件操作，有可能进行数据类型等转换。
  • Waiting on condition：等待资源，或等待某个条件的发生。具体原因需结合 stacktrace来分析。
    • 如果堆栈信息明确是应用代码，则证明该线程正在等待资源。一般是大量读取某资源，且该资源采用了资源锁的情况下，线程进入等待状态，等待资源的读取。
    • 又或者，正在等待其他线程的执行等。
    • 如果发现有大量的线程都在处在 Wait on condition，从线程 stack看，正等待网络读写，这可能是一个网络瓶颈的征兆。因为网络阻塞导致线程无法执行。
      • 一种情况是网络非常忙，几乎消耗了所有的带宽，仍然有大量数据等待网络读写；
      • 另一种情况也可能是网络空闲，但由于路由等问题，导致包无法正常的到达。
    • 另外一种出现 Wait on condition的常见情况是该线程在 sleep，等待 sleep的时间到了时候，将被唤醒。
  • Blocked：线程阻塞，是指当前线程执行过程中，所需要的资源长时间等待却一直未能获取到，被容器的线程管理器标识为阻塞状态，可以理解为等待资源超时的线程。
  • Waiting for monitor entry 和 in Object.wait()：Monitor是 Java中用以实现线程之间的互斥与协作的主要手段，它可以看成是对象或者 Class的锁。每一个对象都有，也仅有一个 monitor。从下图1中可以看出，每个 Monitor在某个时刻，只能被一个线程拥有，该线程就是 “Active Thread”，而其它线程都是 “Waiting Thread”，分别在两个队列 “ Entry Set”和 “Wait Set”里面等候。在 “Entry Set”中等待的线程状态是 “Waiting for monitor entry”，而在 “Wait Set”中等待的线程状态是 “in Object.wait()”。

http://images.cnblogs.com/cnblogs_com/zhengyun_ustc/255879/o_clipboard%20-%20%E5%89%AF%E6%9C%AC039.png

从上图可以看出，每个Monitor在某个时刻只能被一个线程拥有，该线程就是 "Active Thread"，而其他线程都是 "Waiting Thread"，分别在两个队列 "Entry Set"和"Waint 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 状态的线程。

 

3.3 首先介绍一下Thread Dump信息的各个部分

头部信息：

时间，jvm信息

2011-11-02 19:05:06  

Full thread dump Java HotSpot(TM) Server VM (16.3-b01 mixed mode): 

Thread Dump日志的线程信息：

以下面的日志为例：

"resin-22129" daemon prio=10 tid=0x00007fbe5c34e000 nid=0x4cb1 waiting on condition [0x00007fbe4ff7c000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:315)
    at com.caucho.env.thread2.ResinThread2.park(ResinThread2.java:196)
    at com.caucho.env.thread2.ResinThread2.runTasks(ResinThread2.java:147)
    at com.caucho.env.thread2.ResinThread2.run(ResinThread2.java:118)


"Timer-20" daemon prio=10 tid=0x00007fe3a4bfb800 nid=0x1a31 in Object.wait() [0x00007fe3a077a000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000006f0620ff0> (a java.util.TaskQueue)
    at java.util.TimerThread.mainLoop(Timer.java:552)
    - locked <0x00000006f0620ff0> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:505)

以上依次是：

  • "resin-22129" 线程名称：如果使用 java.lang.Thread 类生成一个线程的时候，线程名称为 Thread-(数字) 的形式，这里是resin生成的线程；
  • daemon 线程类型：线程分为守护线程 (daemon) 和非守护线程 (non-daemon) 两种，通常都是守护线程；
  • prio=10 线程优先级：默认为5，数字越大优先级越高；
  • tid=0x00007fbe5c34e000 JVM线程的id：JVM内部线程的唯一标识，通过 java.lang.Thread.getId()获取，通常用自增的方式实现；
  • nid=0x4cb1 系统线程id：对应的系统线程id（Native Thread ID)，可以通过 top 命令进行查看，现场id是十六进制的形式；
  • waiting on condition 系统线程状态：这里是系统的线程状态，具体的含义见下面 系统线程状态部分；
  • [0x00007fbe4ff7c000] 起始栈地址：线程堆栈调用的其实内存地址；
  • java.lang.Thread.State: WAITING (parking) JVM线程状态：这里标明了线程在代码级别的状态，详细的内容见下面的 JVM线程运行状态 部分。
  • 线程调用栈信息：下面就是当前线程调用的详细栈信息，用于代码的分析。堆栈信息应该从下向上解读，因为程序调用的顺序是从下向上的。

四、案例分析：

4.1、使用方案

cpu飙高，load高，响应很慢

方案：
* 一个请求过程中多次dump

* 对比多次dump文件的runnable线程，如果执行的方法有比较大变化，说明比较正常。如果在执行同一个方法，就有一些问题了。

查找占用cpu最多的线程信息

方案：
* 使用命令： top -H -p pid（pid为被测系统的进程号），找到导致cpu高的线程id。

见《找出Java进程中大量消耗CPU》

上述Top命令找到的线程id，对应着dump thread信息中线程的nid，只不过一个是十进制，一个是十六进制。

* 在thread dump中，根据top命令查找的线程id，查找对应的线程堆栈信息。

cpu使用率不高但是响应很慢

方案：
* 进行dump，查看是否有很多thread struck在了i/o、数据库等地方，定位瓶颈原因。

请求无法响应

方案：
* 多次dump，对比是否所有的runnable线程都一直在执行相同的方法，如果是的，恭喜你，锁住了！

4.2 案例分析：

4.2.1.死锁：

死锁经常表现为程序的停顿，或者不再响应用户的请求。从操作系统上观察，对应进程的CPU占用率为零，很快会从top或prstat的输出中消失。

    在thread dump中，会看到类似于这样的信息：

waiting for monitor entry

（图 1）

deadlock

 

说明：

（图1）中有一个“Waiting formonitor entry”，可以看出，两个线程各持有一个锁，又在等待另一个锁，很明显这两个线程互相持有对方正在等待的锁。所以造成了死锁现象；

（图2）中对死锁的现象做了说明，可以看到，是“DeadLockTest.java”的39行造成的死锁现象。这样就能到相应的代码下去查看，定位问题。

4.2.2.热锁

热锁，也往往是导致系统性能瓶颈的主要因素。其表现特征为：由于多个线程对临界区，或者锁的竞争，可能出现：
    * 频繁的线程的上下文切换：从操作系统对线程的调度来看，当线程在等待资源而阻塞的时候，操作系统会将之切换出来，放到等待的队列，当线程获得资源之后，调度算法会将这个线程切换进去，放到执行队列中。
    * 大量的系统调用：因为线程的上下文切换，以及热锁的竞争，或者临界区的频繁的进出，都可能导致大量的系统调用。
    * 大部分CPU开销用在“系统态 ”：线程上下文切换，和系统调用，都会导致 CPU在 “系统态 ”运行，换而言之，虽然系统很忙碌，但是 CPU用在 “用户态 ”的比例较小，应用程序得不到充分的 CPU资源。 
    * 随着 CPU数目的增多，系统的性能反而下降。因为CPU数目多，同时运行的线程就越多，可能就会造成更频繁的线程上下文切换和系统态的CPU开销，从而导致更糟糕的性能。 
    上面的描述，都是一个 scalability（可扩展性）很差的系统的表现。从整体的性能指标看，由于线程热锁的存在，程序的响应时间会变长，吞吐量会降低。
    那么，怎么去了解 “热锁 ”出现在什么地方呢？一个重要的方法还是结合操作系统的各种工具观察系统资源使用状况，以及收集Java线程的DUMP信息，看线程都阻塞在什么方法上，了解原因，才能找到对应的解决方法。
    我们曾经遇到过这样的例子，程序运行时，出现了以上指出的各种现象，通过观察操作系统的资源使用统计信息，以及线程 DUMP信息，确定了程序中热锁的存在，并发现大多数的线程状态都是 Waitingfor monitor entry或者 Wait on monitor，且是阻塞在压缩和解压缩的方法上。后来采用第三方的压缩包 javalib替代 JDK自带的压缩包后，系统的性能提高了几倍。

 

五、示例

转载

综合示范一：Waiting to lock 和 Blocked
实例如下：
"RMI TCP Connection(267865)-172.16.5.25" daemon prio=10 tid=0x00007fd508371000 nid=0x55ae waiting for monitor entry [0x00007fd4f8684000]
   java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:201)
- waiting to lock <0x00000000acf4d0c0> (a org.apache.log4j.Logger)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.log(Category.java:853)
at org.apache.commons.logging.impl.Log4JLogger.warn(Log4JLogger.java:234)
at com.tuan.core.common.lang.cache.remote.SpyMemcachedClient.get(SpyMemcachedClient.java:110)
……
1）线程状态是 Blocked，阻塞状态。说明线程等待资源超时！
2）“ waiting to lock <0x00000000acf4d0c0>”指，线程在等待给这个 0x00000000acf4d0c0 地址上锁（英文可描述为：trying to obtain  0x00000000acf4d0c0 lock）。
3）在 dump 日志里查找字符串 0x00000000acf4d0c0，发现有大量线程都在等待给这个地址上锁。如果能在日志里找到谁获得了这个锁（如locked < 0x00000000acf4d0c0 >），就可以顺藤摸瓜了。
4）“waiting for monitor entry”说明此线程通过 synchronized(obj) {……} 申请进入了临界区，从而进入了下图1中的“Entry Set”队列，但该 obj 对应的 monitor 被其他线程拥有，所以本线程在 Entry Set 队列中等待。
5）第一行里，"RMI TCP Connection(267865)-172.16.5.25"是 Thread Name 。tid指Java Thread id。nid指native线程的id。prio是线程优先级。[0x00007fd4f8684000]是线程栈起始地址。
 

 

综合示范二：Waiting on condition 和 TIMED_WAITING
实例如下：
"RMI TCP Connection(idle)" daemon prio=10 tid=0x00007fd50834e800 nid=0x56b2 waiting on condition [0x00007fd4f1a59000]
   java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for  <0x00000000acd84de8> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:662)
1）“TIMED_WAITING (parking)”中的 timed_waiting 指等待状态，但这里指定了时间，到达指定的时间后自动退出等待状态；parking指线程处于挂起中。

2）“waiting on condition”需要与堆栈中的“parking to wait for  <0x00000000acd84de8> (a java.util.concurrent.SynchronousQueue$TransferStack)”结合来看。首先，本线程肯定是在等待某个条件的发生，来把自己唤醒。其次，SynchronousQueue 并不是一个队列，只是线程之间移交信息的机制，当我们把一个元素放入到 SynchronousQueue 中时必须有另一个线程正在等待接受移交的任务，因此这就是本线程在等待的条件。
3）别的就看不出来了。
 

综合示范三：in Obejct.wait() 和 TIMED_WAITING

实例如下：
"RMI RenewClean-[172.16.5.19:28475]" daemon prio=10 tid=0x0000000041428800 nid=0xb09 in Object.wait() [0x00007f34f4bd0000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000aa672478> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
- locked <0x00000000aa672478> (a java.lang.ref.ReferenceQueue$Lock)
at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run(DGCClient.java:516)
at java.lang.Thread.run(Thread.java:662)
1）“TIMED_WAITING (on object monitor)”，对于本例而言，是因为本线程调用了 java.lang.Object.wait(long timeout) 而进入等待状态。

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

3）RMI RenewClean 是 DGCClient 的一部分。DGC 指的是 Distributed GC，即分布式垃圾回收。

4）请注意，是先 locked <0x00000000aa672478>，后 waiting on <0x00000000aa672478>，之所以先锁再等同一个对象，请看下面它的代码实现：
static private class  Lock { };
private Lock lock = new Lock();
public Reference<? extends T> remove(long timeout)
{
    synchronized (lock) {
        Reference<? extends T> r = reallyPoll();
        if (r != null) return r;
        for (;;) {
            .wait(timeout);
            r = reallyPoll();
            ……
       }
}
即，线程的执行中，先用 synchronized 获得了这个对象的 Monitor（对应于  locked <0x00000000aa672478> ）；当执行到 lock.wait(timeout);，线程就放弃了 Monitor 的所有权，进入“Wait Set”队列（对应于  waiting on <0x00000000aa672478> ）。
5）从堆栈信息看，是正在清理 remote references to remote objects ，引用的租约到了，分布式垃圾回收在逐一清理呢。

 

posted on 2012-11-05 13:32  duanxz  阅读(691)  评论(0)  编辑  收藏  举报

Powered by: 博客园 Copyright © 2024 duanxz
Powered by .NET 9.0 on Kubernetes