ThreadDump堆栈分析 | HeapDump性能社区

最近在进行一些系统问题追踪分析，顺便翻了翻以前的笔记和书籍，突然发现了以前写的 ThreadDump分析笔记（一）解读堆栈
)，阿哈哈哈，好吧，这次顺便补个二。线程堆栈是我们排查问题常用的一种数据，具有很高的价值。但是线程堆栈打印出来是贼拉多的，上一次已经把基础概念说了，今儿就来叨叨下应该怎么看这玩意。

线程堆栈可以干嘛

线程堆栈主要是反映了当前系统线程正在干什么，堆栈可以从几个角度来分析

局部堆栈信息（就是每个线程的详细栈信息)

记录了每一个线程调用的层次关系，当前线程正在执行哪个函数，当前的线程状态是什么，当前线程持有哪些锁，在等待哪些锁。

堆栈的统计信息（每个线程栈都会有一个统计数据）

可以看出锁的竞争状态，是不是有很多锁竞争，是不是有死锁,大部分线程处于什么状态，线程总数等。

多次堆栈对比信息

多次堆栈的好处就是可以形成对比，通过对比统计，你就才会发现问题所在。

例如每次打印堆栈这个线程一直处于同样的上下文中（比如一直在执行某一段代码），那就要考虑是否合理或者有瓶颈了。

例如某一个线程在多次堆栈中都在等待一个锁，那就要看看这个锁为什么不释放。

线程栈在问题分析上原理都是类似的，我们搞几个常见的问题，这几个问题基本就涵盖了生产环境经常发生的现象

死循环分析（多次堆栈对比信息）

代码出了BUG导致死循环，会明显拉高CPU，这时候就可以通过上面所讲的多次对比的方法进行可疑线程寻找,具体步骤如下：

使用jstack pid > pid.dump 导出第一次线程栈文件
等几十秒在重读导出第二个dump 文件
对比两个文件，排除掉WAITING和SLEEPING 状态的数据，因为这两种状态是不消耗CPU的
找出这一段时间内一直活跃的线程，如果相同的线程处于相同的上下文，那这个就要作为重点排查对象。结合代码来查看线程所执行的上下文是否属于应该长期运行的代码。

如果对比完后没有发现可以线程，那就需要考虑下CPU过高是否是因为内存设置不合理，比如是否没有设置元空间大小而导致频繁full gc，是否新生代太小导致大批量对象晋升导致的频繁GC，从而导致CPU过高。

CPU消耗分析

死循环会导致CPU 过高，这是一种BUG。但在大多数情况下，有很多CPU密集型的逻辑计算也会拉高CPU。这些问题分析起来可能会微微不太方便，因为单纯通过线程栈这一种信息是不够了，我们需要借助linux的一些小命令。

都知道我们的应用是以进程的方式运行在linux中，每个进程内又包含了很多的线程,在java 中我们使用的是。在linux中，我们可以使用top 命令查看cpu 占比。而需要知道的是linux中的本地线程(LWPID)是和java 线程一一对应的，在top显示的是10进制的线程ID，而在线程栈中的nid用16禁制来表示。（其中涉及的知识点内核线程KLT、轻量级进程LWP、用户线程UT可以看一下）

具体分析步骤如下：

top -Hp pid 来获取当前该进程内所有线程的统计数据，PID就是线程ID（LWPID），这个ID对应这java thread dump 内的nid（native thread id），nid 是16进制的，所有如图PID=221 就等于 nid=0xdd，可以使用printf “%x\n” 221 来转换ID

在java 线程栈中搜索nid=0xdd

如果找到的对应的线程PID正在执行java代码，那说明该java代码导致cpu过高，如：

    "Thread-444" prio=1 tid=0xa4853568 nid=0xdd runnable [0xafcf7000..0xafcf8680] 
        //当前正在执行的代码是纯Java代码
         at org.apache.commons.collections.ReferenceMap.getEntry(Unknown Source) 
        at org.apache.commons.collections.ReferenceMap.get(Unknown Source)

如果找到找到的PID 正在执行行Native code ，那说明导致CPU过高问题代码在JNI调用中，如：

    "Thread-609" prio=5 tid=0x01583d88 nid=0xdd runnable [7a680000..7a6819c0] 
        //CheckLicense是Native方法，说明导致CPU过高的问题代码在本地代码中。
         at meetingmgr.conferencemgr.Operation.CheckLicense(Native method) 
        at meetingmgr.MeetingAdapter.prolongMeeting(MeetingAdapter.java:171)

这种定位方式基本可以一次命中问题所在，不管什么原因导致的CPU 过高都可以排查出来，这种方式消耗小，生产环境非常是适合使用。

资源不足分析

系统资源不足犹如一条高速公路中间一截变成了羊肠小道，所有就算其他地方在宽也没有用，这就是木桶效应。比如dubbo 链路中某一服务提供者数据库连接不够了，那就会产生资源竞争，请求该资源的线程都会被阻塞或者挂起，系统设计差一点的就有可能造成系统雪崩。所以说系统资源不足和系统瓶颈是同一类问题。

如果系统资源不足，就会有大量的线程等待资源，打印线程栈就会发现这个特征，那就说明该资源就是系统瓶颈。此时打印线程栈，会发现大量线程停在同一个方法调用上。

例如：堆栈大量的http-1-Processor线程都停止在org.apache.commons.pool.impl .GenericObjectPool.borrowObject上面，说明大量的线程正在等待该资源。这就说明了该系统资源是瓶颈。

 http-8082-Processor84" daemon prio=10 tid=0x0887c000 nid=0x5663 in Object.wait() 
       java.lang.Thread.State: WAITING (on object monitor)
       at java.lang.Object.wait(Object.java:485) 
       at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(Unknown Source)
       - locked <0x75132118> (a org.apache.commons.dbcp.AbandonedObjectPool)
       at org.apache.commons.dbcp.AbandonedObjectPool.borrowObject()
       - locked <0x75132118> (a org.apache.commons.dbcp.AbandonedObjectPool) 
       at org.apache.commons.dbcp.PoolingDataSource.getConnection()
       at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:312)  
      at dbAccess.FailSafeConnectionPool.getConnection(FailSafeConnectionPool.java:162) 
      at servlets.ControllerServlet.doGet(ObisControllerServlet.java:93)

导致资源不足的原因结合堆栈信息判断有可能如下几个方面：

连接池配置不够导致的
系统当前并发突然增大导致资源耗尽
资源占用太久不释放导致耗尽，SQL语句不恰当没有命中索引，或者没有索引导致的数据库访问太慢
资源用完后，在某种异常情况下，没有关闭或者回池，导致可用资源泄漏或者减少，从而导致资源竞争

资源不足在系统的表现上来看就是性能问题，往往系统会越来越慢，最后导致不能正常响应。

锁链分析

先说一点，死锁的两个线程或多个线程是不消耗CPU的。只有死循环，并且循环内代码都是CPU密集型操作，才有可能造成CPU100%的使用率，像socket或者数据库等IO操作是不怎么消耗CPU的。

锁链不是死锁，有的时候打印出的堆栈，很多线程在等待不同的锁，有的锁竞争可能是由于另一个锁对象竞争导致，这时候要找到根源到底在哪。如下堆栈信息，等待锁0xbef17078的线程有40多个，等待0xbc7b4110有10多个。

"Thread-1021" prio=5 tid=0x0164eac0 nid=0x41e waiting for monitor entry[...] 
at meetingmgr.timer.OnMeetingExec.monitorExOverNotify(OnMeetingExec.java:262)
- waiting to lock <0xbef17078> (a [B) //等待锁0xbef17078  
at meetingmgr.timer.OnMeetingExec.execute(OnMeetingExec.java:189)  
at util.threadpool.RunnableWrapper.run(RunnableWrapper.java:131)  
at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(...)  
at java.lang.Thread.run(Thread.java:534)  

"Thread-196" prio=5 tid=0x01054830 nid=0xe1 waiting for monitor entry[...]  
at meetingmgr.conferencemgr.Operation.prolongResource(Operation.java:474)  
- waiting to lock <0xbc7b4110> (a [B) //等待锁0xbc7b4110  
at meetingmgr.MeetingAdapter.prolongMeeting(MeetingAdapter.java:171)  
at meetingmgr.FacadeForCallBean.applyProlongMeeting(FacadeFroCallBean.java:190) 
at meetingmgr.timer.OnMeetingExec.monitorExOverNotify(OnMeetingExec.java:278) 
- locked <0xbef17078> (a [B) //占有锁0xbef17078  
at meetingmgr.timer.OnMeetingExec.execute(OnMeetingExec.java:189) 
at util.threadpool.RunnableWrapper.run(RunnableWrapper.java:131)  
at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(...)  
at java.lang.Thread.run(Thread.java:534)  


"Thread-609" prio=5 tid=0x01583d88 nid=0x280 runnable [7a680000..7a6819c0] 
at java.net.SocketInputStream.socketRead0(Native method)  
at oracle.jdbc.ttc7.Oall7.recieve(Oall7.java:369) 
at net.sf.hiberante.impl.QueryImpl.list(QueryImpl.java:39) | 
at meetingmgr.conferencemgr.Operation.prolongResource(Operation.java:481) 
- locked <0xbc7b4110> (a [B) //占有锁0xbc7b4110  
at meetingmgr.MeetingAdapter.prolongMeeting(MeetingAdapter.java:171) 
at meetingmgr.timer.OnMeetingExec.execute(OnMeetingExec.java:189) 
at util.threadpool.RunnableWrapper.run(RunnableWrapper.java:131) 
at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(...)
at java.lang.Thread.run(Thread.java:534)

看到有40多个线程再等待锁0xbef17078,首先找到已经占有这把锁的线程，即"Thread-196"
看到"Thread-196"占有了锁0xbef17078,但又在等待锁<0xbc7b4110>,那么此时需要再找出占有<0xbc7b4110>这个锁的线程，即"Thread-609"
那么占有锁<0xbc7b4110>的线程是问题的根源，下一步就要查到底为什么这个线程长时间占有这个锁。可能的原因是持有这把锁的线程正在执行的代码性能比较低，导致锁占用时间过长。