性能文章>JVM故障分析及性能优化系列之五:常见的Thread Dump日志案例分析>

JVM故障分析及性能优化系列之五:常见的Thread Dump日志案例分析原创

https://a.perfma.net/img/2959233
7月前
203601

我们在上篇文章中详细描述了Thread Dump中Native Thread和JVM Thread线程的各种状态及描述,今天总结分析的一些原则,并详细列举一些案例进行说明。

症状及解决方案

下面列出几种常见的症状即对应的解决方案:

CPU占用率很高,响应很慢

按照《Java内存泄漏分析系列之一:使用jstack定位线程堆栈信息》中所说的方法,先找到占用CPU的进程,然后再定位到对应的线程,最后分析出对应的堆栈信息。
在同一时间多次使用上述的方法,然后进行对比分析,从代码中找到问题所在的原因。如果线程指向的是"VM Thread"或者无法从代码中直接找到原因,就需要进行内存分析,具体的见下一篇文章。

CPU占用率不高,但响应很慢

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

关注点概况

在Thread Dump文件中,线程的状态分成两种:Native Thread Status和JVM Thread Status,具体的含义可以参考上一篇文章。在分析日志的时候需要重点关注如下几种线程状态:

系统线程状态为 deadlock

线程处于死锁状态,将占用系统大量资源。

系统线程状态为 waiting for monitor entry 或 in Object.wait()

如上一篇文章中所说,系统线程处于这种状态说明它在等待进入一个临界区,此时JVM线程的状态通常都是 java.lang.Thread.State: BLOCKED。

如果大量线程处于这种状态的话,可能是一个全局锁阻塞了大量线程。如果短期内多次打印Thread Dump信息,发现 waiting for monitor entry 状态的线程越来越多,没有减少的趋势,可能意味着某些线程在临界区里呆得时间太长了,以至于越来越多新线程迟迟无法进入。

系统线程状态为 waiting on condition

系统线程处于此种状态说明它在等待另一个条件的发生来唤醒自己,或者自己调用了sleep()方法。此时JVM线程的状态通常是java.lang.Thread.State: WAITING (parking)(等待唤醒条件)或java.lang.Thread.State: TIMED_WAITING (parking或sleeping)(等待定时唤醒条件)。

如果大量线程处于此种状态,说明这些线程又去获取第三方资源了,比如第三方的网络资源或读取数据库的操作,长时间无法获得响应,导致大量线程进入等待状态。因此,这说明系统处于一个网络瓶颈或读取数据库操作时间太长。

系统线程状态为 blocked

线程处于阻塞状态,需要根据实际情况进行判断。

案例分析

下面通过几个案例进行分解来获得解决问题的方法。

waiting for monitor entry 和 java.lang.Thread.State: BLOCKED

  • "DB-Processor-13" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f000]
  • java.lang.Thread.State: BLOCKED (on object monitor)
  • at beans.ConnectionPool.getConnection(ConnectionPool.java:102)
  • - waiting to lock <0xe0375410> (a beans.ConnectionPool)
  • at beans.cus.ServiceCnt.getTodayCount(ServiceCnt.java:111)
  • at beans.cus.ServiceCnt.insertCount(ServiceCnt.java:43)
  •  
  • "DB-Processor-14" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f020]
  • java.lang.Thread.State: BLOCKED (on object monitor)
  • at beans.ConnectionPool.getConnection(ConnectionPool.java:102)
  • - waiting to lock <0xe0375410> (a beans.ConnectionPool)
  • at beans.cus.ServiceCnt.getTodayCount(ServiceCnt.java:111)
  • at beans.cus.ServiceCnt.insertCount(ServiceCnt.java:43)
  •  
  • "DB-Processor-3" daemon prio=5 tid=0x00928248 nid=0x8b waiting for monitor entry [0x000000000825d080]
  • java.lang.Thread.State: RUNNABLE
  • at oracle.jdbc.driver.OracleConnection.isClosed(OracleConnection.java:570)
  • - waiting to lock <0xe03ba2e0> (a oracle.jdbc.driver.OracleConnection)
  • at beans.ConnectionPool.getConnection(ConnectionPool.java:112)
  • - locked <0xe0386580> (a java.util.Vector)
  • - locked <0xe0375410> (a beans.ConnectionPool)
  • at beans.cus.Cue_1700c.GetNationList(Cue_1700c.java:66)
  • at org.apache.jsp.cue_1700c_jsp._jspService(cue_1700c_jsp.java:120)
  •  

上面系统线程的状态是 waiting for monitor entry,说明此线程通过 synchronized(obj) { } 申请进入临界区,但obj对应的 Monitor 被其他线程所拥有,所以 JVM线程的状态是 java.lang.Thread.State: BLOCKED (on object monitor),说明线程等待资源超时。

下面的 waiting to lock <0xe0375410> 说明线程在等待给 0xe0375410 这个地址上锁(trying to obtain 0xe0375410 lock),如果在日志中发现有大量的线程都在等待给 0xe0375410 上锁的话,这个时候需要在日志中查找那个线程获取了这个锁 locked <0xe0375410>,如上面的例子中是 “DB-Processor-14” 这个线程,这样就可以顺藤摸瓜了。上面的例子是因为获取数据库操作等待的时间太长所致的,这个时候就需要修改数据库连接的配置信息。

如果两个线程相互都被对方的线程锁锁住,这样就造成了 死锁 现象,如下面的例子所示:
threaddeadlock1.png

waiting on condition 和 java.lang.Thread.State: 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)
  •  

JVM线程的状态是 java.lang.Thread.State: TIMED_WAITING (parking),说明线程处于定时等待的状态,parking指线程处于挂起中。

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

in Object.wait() 和 java.lang.Thread.State: 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)
  •  

本例中JVM线程的状态是 java.lang.Thread.State: TIMED_WAITING (on object monitor),说明线程调用了 java.lang.Object.wait(long timeout) 方法而进入了等待状态。

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

另外需要注意的是,是先 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 (;;) {
  • lock.wait(timeout);
  • r = reallyPoll();
  • // ……
  • }
  • }
  •  

线程在执行的过程中,先用 synchronized 获得了这个对象的 Monitor(对应 locked <0x00000000aa672478>),当执行到 lock.wait(timeout); 的时候,线程就放弃了Monitor的所有权,进入 “Wait Set” 队列(对应 waiting on <0x00000000aa672478>)。

前面几篇文章详细说明了如何分析Thread Dump文件,除此之外还可以通过分析JVM堆内存信息来进一步找到问题的原因。

原文链接:https://www.javatang.com/archives/2017/10/26/08572060.html

 

系列阅读

JVM故障分析及性能优化系列之一:使用jstack定位线程堆栈信息

JVM故障分析及性能优化系列之二:jstack生成的Thread Dump日志结构解析

JVM故障分析及性能优化系列之三:jstat命令的使用及VM Thread分析

JVM故障分析及性能优化系列之四:jstack生成的Thread Dump日志线程状态

JVM故障分析及性能优化系列之六:JVM Heap Dump(堆转储文件)的生成和MAT的使用

JVM故障分析及性能优化系列之七:使用MAT的Histogram和Dominator Tree定位溢出源

分类:
标签:
请先登录,再评论

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

为你推荐

不起眼,但是足以让你有收获的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有多熟悉,看到这篇文章,应该还是会有点小惊讶的,不过我觉得这个案例我分享出来,是想表达不管多么奇怪的现象请一定要追究下去,会让你慢慢变得强大起来,
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得