性能文章>ThreadDump堆栈分析>

ThreadDump堆栈分析原创

2年前
500000

最近在进行一些系统问题追踪分析,顺便翻了翻以前的笔记和书籍,突然发现了以前写的 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

image.png

  • 在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)
  1. 看到有40多个线程再等待锁0xbef17078,首先找到已经占有这把锁的线程,即"Thread-196"

  2. 看到"Thread-196"占有了锁0xbef17078,但又在等待锁<0xbc7b4110>,那么此时需要再找出 占有<0xbc7b4110>这个锁的线程,即"Thread-609"

  3. 那么占有锁<0xbc7b4110>的线程是问题的根源,下一步就要查到底为什么这个线程长时 间占有这个锁。可能的原因是持有这把锁的线程正在执行的代码性能比较低,导致锁占用时间过长。

线程堆栈不能分析什么

线程堆栈定位问题,只能定位在当前线程上留下痕迹的问题,如死锁、挂起等因为锁导致的系统性能问题。但对于不留痕迹的问题,就无能为力了。比如:

  • 线程泄漏,为何没有被合理的回收
  • 线程并发导致的BUG,这种问题在线程堆栈中没有任何痕迹,所以这种问题线程堆 栈无法提供任何帮助。
  • 数据库锁表的问题,问题往往是由于某个事务没有提交/回 滚,但这些信息无法在堆栈中表现出来,所以堆栈分析这类问题毫无帮助。
请先登录,再评论

暂无回复,快来写下第一个回复吧~

为你推荐

不起眼,但是足以让你有收获的JVM内存分析案例
分析 这个问题说白了,就是说有些int[]对象不知道是哪里来的,于是我拿他的例子跑了跑,好像还真有这么回事。点该 dump 文件详情,查看相关的 int[] 数组,点该对象的“被引用对象”,发现所
从一起GC血案谈到反射原理
前言 首先回答一下提问者的问题。这主要是由于存在大量反射而产生的临时类加载器和 ASM 临时生成的类,这些类会被保留在 Metaspace,一旦 Metaspace 即将满的时候,就会触发 Fu
关于内存溢出,咱再聊点有意思的?
概述 上篇文章讲了JVM在GC上的一个设计缺陷,揪出一个导致GC慢慢变长的JVM设计缺陷,可能有不少人还是没怎么看明白的,今天准备讲的大家应该都很容易看明白 本文其实很犹豫写不写,因为感觉没有
协助美团kafka团队定位到的一个JVM Crash问题
概述 有挺长一段时间没写技术文章了,正好这两天美团kafka团队有位小伙伴加了我微信,然后咨询了一个JVM crash的问题,大家对crash的问题都比较无奈,因为没有现场,信息量不多,碰到这类问题我
又发现一个导致JVM物理内存消耗大的Bug(已提交Patch)
概述 最近我们公司在帮一个客户查一个JVM的问题(JDK1.8.0_191-b12),发现一个系统老是被OS Kill掉,是内存泄露导致的。在查的过程中,阴差阳错地发现了JVM另外的一个Bug。这个B
JVM实战:优化我的IDEA GC
IDEA是个好东西,可以说是地球上最好的Java开发工具,但是偶尔也会卡顿,仔细想想IDEA也是Java开发的,会不会和GC有关,于是就有了接下来对IDEA的GC进行调优 IDEA默认JVM参数: -
不起眼,但是足以让你收获的JVM内存案例
今天的这个案例我觉得应该会让你涨姿势吧,不管你对JVM有多熟悉,看到这篇文章,应该还是会有点小惊讶的,不过我觉得这个案例我分享出来,是想表达不管多么奇怪的现象请一定要追究下去,会让你慢慢变得强大起来,
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得