注: 该文章的原文是由 Tae Jin Gu 编写,原文地址为 How to Analyze Java Thread Dumpsjava
当有障碍,或者是一个基于 JAVA 的 WEB 应用运行的比预期慢的时候,咱们须要使用 thread dumps
。若是对于你来讲, thread dumps
是很是复杂的,这篇文章或许能对你有所帮助。在这里我将解释在 JAVA 中什么是 threads
,他们的类型,怎么被建立的,怎样管理它们,你怎样从正在运行的应用中 dump threads
,最后你能够怎样分析它以及肯定瓶颈或者是阻塞线程。本文来自于 JAVA 应用程序长期调试经验的结果。linux
一个 web 服务器使用几十到几百个线程来处理大量并发用户,若是一个或多个线程使用相同的资源,线程之间的竞争就不可避免了,而且有时候可能会发生死锁。web
Thread contention 是一个线程等待锁的一个状态,这个锁被另一个线程持有,等待被释放,不一样的线程频繁访问 WEB 应用的共享资源。例如,记录一条日志,线程尝试记录日志以前必须先获取锁来访问共享资源。apache
死锁是线程竞争的一个特殊状态,一个或是多个线程在等待其余线程完成它们的任务为了完成它们本身的任务。编程
线程竞争会引发各类不一样的问题,为了分析这些这些问题,你须要使用 dump threads,dump threads
能给你提供每一个线程的精确状态信息。服务器
一个线程能够与其余线程在同一时间内被处理。为了确保一致性,当多个线程试图使用共享资源的时候,经过使用 hread synchronization
在同一时间内,应该只有一个线程能访问共享资源多线程
JAVA 中的线程同步可使用监视器,每一个 JAVA 对象都有一个单独的监视器,这个监视器仅仅只能被一个线程拥有,对于拥有一个由不一样的线程所拥有的监视器的线程,确实须要在队列中等待,以便其余线程释放它的监视器。并发
为了分析一个 thread dump
文件,你须要知道线程状态。线程状况在 java.lang.Thread.State
中阐明了。oracle
图1:线程状态app
WAITING
不一样是经过方法参数指定了最大等待时间,WAITING
能够经过时间或者是外部的变化解除)JAVA 的线程类型分为如下两种:
Daemon threads 将中止工做当没有其余任何非 Daemon threads
时。即便你不建立任何线程,JAVA 应用也将默认建立几个线程。他们大部分是 daemon threads
。主要用于任务处理好比内存回收或者是 JMX
。
一个运行 static void main(String[] args)
方法的线程被做为非 daemon threads
线程建立,而且当该线程中止工做的时候,全部任何其余 daemon threads
也将中止工做。(这个运行在 main 方法中的线程被称为 VM thread in HotSpot VM)
咱们将介绍三种最经常使用的方法,记住,有很是多的其余方法能够获取thread dump
,一个 thread dump
仅仅只能在测量的时候显示线程状态。所以为了看得线程状态的变化,建议每隔5秒提取5到10次的记录。
在 JDK1.6 或者是更高的版本中,经过使用 jstack, 在 MS Windows 平台上可能能够获取到 Thread Dump
。
经过使用 jps
检查当前正在运行的JAVA进程的 PID。
[user@linux ~]$ jps -v 25780 RemoteTestRunner -Dfile.encoding=UTF-8 25590 sub.rmi.registry.RegistryImpl 2999 -Dapplication.home=/home1/user/java/jdk.1.6.0_24 -Xms8m 26300 sun.tools.jps.Jps -mlvV -Dapplication.home=/home1/user/java/jdk.1.6.0_24 -Xms8m
使用明确的 PID 做为 jstack
的参数来获取 thread dumps
。
[user@linux ~]$ jstack -f 5824
经过使用一个程序 jVisualVM
来生成 Thread Dump
。
如上图在左侧的任务表示当前正在运行的进程列表,点击你想要信息的那个线程,而后选择 thread tab
页来检查实时的线程信息。点击右边的 Thread Dump
按钮来获取 thread dump
文件。
经过使用 ps -ef
命令来获取当前正在运行的 JAVA 应用程序的进程 ID。
[user@linux ~]$ ps - ef | grep java user 2477 1 0 Dec23 ? 00:10:45 ... user 25780 25361 0 15:02 pts/3 00:00:02 ./jstatd -J -Djava.security.policy=jstatd.all.policy -p 2999 user 26335 25361 0 15:49 pts/3 00:00:00 grep java
使用精确的 pid 做为 kill –SIGQUIT(3)
的参数来获取 thread dump
。
"pool-1-thread-13" prio=6 tid=0x000000000729a000 nid=0x2fb4 runnable [0x0000000007f0f000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264) at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306) at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158) - locked <0x0000000780b7e688> (a java.io.InputStreamReader) at java.io.InputStreamReader.read(InputStreamReader.java:167) at java.io.BufferedReader.fill(BufferedReader.java:136) at java.io.BufferedReader.readLine(BufferedReader.java:299) - locked <0x0000000780b7e688> (a java.io.InputStreamReader) at java.io.BufferedReader.readLine(BufferedReader.java:362)
Java.lang.Thread
类生成一个线程的时候,该线程将被命名为 Thread-(Number)
。可是当使用 java.util.concurrent.ThreadFactory
类的时候,它将被命名为 pool-(number)-thread-(number)
。这个应用程序的总体性能降低是由于一个线程占用了锁阻止了其余线程得到锁,在下面的示例中,BLOCKED_TEST pool-1-thread-1
线程占用了 <0x0000000780a000b0>
锁,然而 BLOCKED_TEST pool-1-thread-2
和 BLOCKED_TEST pool-1-thread-3 threads
正在等待获取锁。
"BLOCKED_TEST pool-1-thread-1" prio=6 tid=0x0000000006904800 nid=0x28f4 runnable [0x000000000785f000] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:282) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123) - locked <0x0000000780a31778> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:432) - locked <0x0000000780a04118> (a java.io.PrintStream) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:85) - locked <0x0000000780a040c0> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:168) at java.io.PrintStream.newLine(PrintStream.java:496) - locked <0x0000000780a04118> (a java.io.PrintStream) at java.io.PrintStream.println(PrintStream.java:687) - locked <0x0000000780a04118> (a java.io.PrintStream) at com.nbp.theplatform.threaddump.ThreadBlockedState.monitorLock(ThreadBlockedState.java:44) - locked <0x0000000780a000b0> (a com.nbp.theplatform.threaddump.ThreadBlockedState) at com.nbp.theplatform.threaddump.ThreadBlockedState$1.run(ThreadBlockedState.java:7) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) Locked ownable synchronizers: - <0x0000000780a31758> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) "BLOCKED_TEST pool-1-thread-2" prio=6 tid=0x0000000007673800 nid=0x260c waiting for monitor entry [0x0000000008abf000] java.lang.Thread.State: BLOCKED (on object monitor) at com.nbp.theplatform.threaddump.ThreadBlockedState.monitorLock(ThreadBlockedState.java:43) - waiting to lock <0x0000000780a000b0> (a com.nbp.theplatform.threaddump.ThreadBlockedState) at com.nbp.theplatform.threaddump.ThreadBlockedState\$2.run(ThreadBlockedState.java:26) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor\$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) Locked ownable synchronizers: - <0x0000000780b0c6a0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) "BLOCKED_TEST pool-1-thread-3" prio=6 tid=0x00000000074f5800 nid=0x1994 waiting for monitor entry [0x0000000008bbf000] java.lang.Thread.State: BLOCKED (on object monitor) at com.nbp.theplatform.threaddump.ThreadBlockedState.monitorLock(ThreadBlockedState.java:42) - waiting to lock <0x0000000780a000b0> (a com.nbp.theplatform.threaddump.ThreadBlockedState) at com.nbp.theplatform.threaddump.ThreadBlockedState\$3.run(ThreadBlockedState.java:34) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) Locked ownable synchronizers: - <0x0000000780b0e1b8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
这是当线程 A 须要获取线程 B 的锁来继续它的任务,然而线程 B 也须要获取线程 A 的锁来继续它的任务的时候发生的。在 thread dump
中,你能看到 DEADLOCK_TEST-1
线程持有 0x00000007d58f5e48
锁,而且尝试获取 0x00000007d58f5e60
锁。你也能看到 DEADLOCK_TEST-2
线程持有 0x00000007d58f5e60
,而且尝试获取 0x00000007d58f5e78
,同时 DEADLOCK_TEST-3
线程持有 0x00000007d58f5e78
,而且在尝试获取 0x00000007d58f5e48
锁,如你所见,每一个线程都在等待获取另一个线程的锁,这状态将不会被改变直到一个线程丢弃了它的锁。
"DEADLOCK_TEST-1" daemon prio=6 tid=0x000000000690f800 nid=0x1820 waiting for monitor entry [0x000000000805f000] java.lang.Thread.State: BLOCKED (on object monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.goMonitorDeadlock(ThreadDeadLockState.java:197) - waiting to lock <0x00000007d58f5e60> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.monitorOurLock(ThreadDeadLockState.java:182) - locked <0x00000007d58f5e48> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.run(ThreadDeadLockState.java:135) Locked ownable synchronizers: - None "DEADLOCK_TEST-2" daemon prio=6 tid=0x0000000006858800 nid=0x17b8 waiting for monitor entry [0x000000000815f000] java.lang.Thread.State: BLOCKED (on object monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.goMonitorDeadlock(ThreadDeadLockState.java:197) - waiting to lock <0x00000007d58f5e78> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.monitorOurLock(ThreadDeadLockState.java:182) - locked <0x00000007d58f5e60> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.run(ThreadDeadLockState.java:135) Locked ownable synchronizers: - None "DEADLOCK_TEST-3" daemon prio=6 tid=0x0000000006859000 nid=0x25dc waiting for monitor entry [0x000000000825f000] java.lang.Thread.State: BLOCKED (on object monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.goMonitorDeadlock(ThreadDeadLockState.java:197) - waiting to lock <0x00000007d58f5e48> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.monitorOurLock(ThreadDeadLockState.java:182) - locked <0x00000007d58f5e78> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.run(ThreadDeadLockState.java:135) Locked ownable synchronizers: - None
该线程是正常的,由于它的状态为 RUNNABLE,尽管如此,当你按照时间顺序排列 Thread Dump
,你会发现 socketReadThread
线程正在无限等待读取 socket。
"socketReadThread" prio=6 tid=0x0000000006a0d800 nid=0x1b40 runnable [0x00000000089ef000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264) at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306) at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158) - locked <0x00000007d78a2230> (a java.io.InputStreamReader) at sun.nio.cs.StreamDecoder.read0(StreamDecoder.java:107) - locked <0x00000007d78a2230> (a java.io.InputStreamReader) at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:93) at java.io.InputStreamReader.read(InputStreamReader.java:151) at com.nbp.theplatform.threaddump.ThreadSocketReadState$1.run(ThreadSocketReadState.java:27) at java.lang.Thread.run(Thread.java:662)
线程保持在 Waiting
状态,在 Thread Dump
中,IoWaitThread
线程保持等待状态来从 LinkedBlockingQueue
接收消息。若是 LinkedBlockingQueue
一直没有消息,该线程的状态将不会改变。
"IoWaitThread" prio=6 tid=0x0000000007334800 nid=0x2b3c waiting on condition [0x000000000893f000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000007d5c45850> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987) at java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:440) at java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:629) at com.nbp.theplatform.threaddump.ThreadIoWaitState$IoWaitHandler2.run(ThreadIoWaitState.java:89) at java.lang.Thread.run(Thread.java:662)
没必要要的线程会堆积起来,当线程的资源不能被正常的组织的话,若是这个发送了,建议监控线程组织过程或检查线程终止的条件。
[user@linux ~]$ ps -mo pid.lwp.stime.time.cpu -C java PID LWP STIME TIME %CPU 10029 - Dec07 00:02:02 99.5 - 10039 Dec07 00:00:00 0.1 - 10040 Dec07 00:00:00 95.5
从这个应用中,发现使用 CPU 最高的线程。
获取使用 CPU 最多的轻量级进程(LWP),把它的惟一标示码 (10039) 转换成十六进制 (0x2737)。
Thread Dump
,检查进程的动做。经过 PID 10029 来提取应用程序的 Thread Dump
,而后经过一个 nid 0x2737 来找到这个线程。
"NioProcessor-2" prio=10 tid=0x0a8d2800 nid=0x2737 runnable [0x49aa5000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method) at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210) at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69) - locked <0x74c52678> (a sun.nio.ch.Util$1) - locked <0x74c52668> (a java.util.Collections$UnmodifiableSet) - locked <0x74c501b0> (a sun.nio.ch.EPollSelectorImpl) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80) at external.org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:65) at external.org.apache.mina.common.AbstractPollingIoProcessor$Worker.run(AbstractPollingIoProcessor.java:708) at external.org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662)
每一个小时的几个时间提取 Thread Dump
,而后检查线程的状态来肯定问题。
屡次得到 thread dumps
后,找出 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)
在屡次获取 thread dumps
后,取得 BLOCKED
状态的线程列表。
若是线程是 BLOCKED
的,提取线程尝试获取的相关联的锁。
经过 thread dumps
,你能肯定线程状态中止在 BLOCKED
,由于锁 <0xe0375410>
不能被获取到,这个问题能够经过分析当前夯住的线程的 stack trace
来解决。
使用 DBMS
的时候,为何以上的范例常常出现再应用程序中,这有两个缘由。第一个缘由是配置不当。尽管事实是该线程仍然在工做,它们不能展现它们最好的性能,由于 DBCP
的配置文件没有配置正确。若是你屡次提取 thread dumps
而且对比它们,你将常常看到被阻塞的线程以前处于不一样的状态。
第二个缘由是不正常的链接。当与 DBMS
的链接保持在不正常的状态,线程将等待直到超时。在这个例子中,经过屡次提取 thread dumps
并对比它们,你会发现与 DBMS 相关的线程仍然在阻塞状态。经过适当改变一些值,好比超时时间,你能够缩短问题发生的时间。
当使用 java.lang.Thread
对象建立线程的时候,线程被命名为 Thread-(Number) 。当使用 java.util.concurrent.DefaultThreadFactory
对象建立线程的时候,线程被命名为 named pool-(Number)-thread-(Number)。当为应用程序分析成百上千的线程的时候,若是线程依然用它们默认的名字,分析它们将变得很是困难,由于这是很是难以辨别这些线程来分析的。
所以,你被建议开发一个命名线程的规则当一个新线程被建立的时候。
当你使用 java.lang.Thread
建立线程,你能够经过建立参数给该线程定义个约定俗成的名字。
public Thread(Runnable target, String name); public Thread(ThreadGroup group, String name); public Thread(ThreadGroup group, Runnable target, String name); public Thread(ThreadGroup group, Runnable target, String name, long stackSize);
当你使用 java.util.concurrent.ThreadFactory
建立线程的时候,你能够经过生成你本身的线程工厂来命名它,若是你不须要特别的功能性,你可使用 MyThreadFactory
做为如下描述:
import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.ThreadFactory; import java.util.concurrent.atomic.AtomicInteger; public class MyThreadFactory implements ThreadFactory { private static final ConcurrentHashMap<String, AtomicInteger> POOL_NUMBER = new ConcurrentHashMap<String, AtomicInteger>(); private final ThreadGroup group; private final AtomicInteger threadNumber = new AtomicInteger(1); private final String namePrefix; public MyThreadFactory(String threadPoolName) { if (threadPoolName == null) { throw new NullPointerException("threadPoolName"); } POOL_NUMBER.putIfAbsent(threadPoolName, new AtomicInteger()); SecurityManager securityManager = System.getSecurityManager(); group = (securityManager != null) ? securityManager.getThreadGroup() : Thread.currentThread().getThreadGroup(); AtomicInteger poolCount = POOL_NUMBER.get(threadPoolName); if (poolCount == null) { namePrefix = threadPoolName + " pool-00-thread-"; } else { namePrefix = threadPoolName + " pool-" + poolCount.getAndIncrement() + "-thread-"; } } public Thread newThread(Runnable runnable) { Thread thread = new Thread(group, runnable, namePrefix + threadNumber.getAndIncrement(), 0); if (thread.isDaemon()) { thread.setDaemon(false); } if (thread.getPriority() != Thread.NORM_PRIORITY) { thread.setPriority(Thread.NORM_PRIORITY); } return thread; } }
你可使用 MBean 来获取 ThreadInfo
对象。你也能够获取更加多经过 thread dumps 不能获取的信息。经过使用 ThreadInfo
。
ThreadMXBean mxBean = ManagementFactory.getThreadMXBean(); long[] threadIds = mxBean.getAllThreadIds(); ThreadInfo[] threadInfos = mxBean.getThreadInfo(threadIds); for (ThreadInfo threadInfo : threadInfos) { System.out.println( threadInfo.getThreadName()); System.out.println( threadInfo.getBlockedCount()); System.out.println( threadInfo.getBlockedTime()); System.out.println( threadInfo.getWaitedCount()); System.out.println( threadInfo.getWaitedTime()); }
你可使用方法 ThreadInfo
来提取阻塞线程或者是等待线程花费的时间。并利用这一点,你也能够获得那些处于非活动状态的时间异常长的线程列表。
在本文中,我关注的是为开发人员提供了大量的多线程编程经验,本素材多是常识。对于经验较少的开发人员来讲,我以为我直接跳过 thread dumps
,不提供足够的关于 thread activities
的背景知识。这是因为个人知识缺少,因此我不能很清晰的简洁明了的解释 thread activities
。我衷心的但愿本文能给不少开发人员提供帮助。