Java Thread Dumps分析

Java Thread Dumps分析

原文地址：http://java.sys-con.com/node/1611555

作者：Shankar Itchapurapu（yakoo5译于2014.05.01）

一、       概述：

软件运维是一项极其枯燥乏味而又非常具有挑战性的工作，就像软件功能被期望的很美好那样。想象下半夜被手机的不停的震动吵醒一样，感觉很不爽吧？

任何软件系统，不管它被构建和质量测试的多么好都可能会出现运行时的性能问题。问题可能是由系统内部产生，也可能是由于外部环境所致。软件系统是建立在一定假设和一些先入为主的观念基础上。然而，当这些系统开始真正运行时，这些假设可能失效从而导致系统故障。

对于企业级J2EE系统，它们通常拥有非常大的用户数量基础，而且会涉及很多异构系统间的互操作，其中一个最常见的运行时问题就是系统性能下降或者系统“挂起”。碰到这种情况，通常的故障排除做法就是分析Java线程转储，以便找出那些导致系统系能下降或系统挂起的线程。本文讨论了Javastack traces、Java线程的解剖结构以及如何阅读常见的线程转储。

二、       Exceptions and Stack Traces

我相信大家在学习和开发阶段或多或少都会遇到过异常（exceptions）。Java通过Exception来告知一个运行时错误。Exceptions包含两部分：异常消息（Message）和堆栈跟踪信息（Stack traces）。异常消息可以告诉你出什么错了，而堆栈跟踪信息可以提供能够了解所有与本次运行时错误有关的自上而下的类方法调用流程信息。

下面是一个ArrayIndexOutOfBoundsException（数组越界）的堆栈跟踪信息的例子：

Exception in thread "main"java.lang.ArrayIndexOutOfBoundsException: 4

at Test.run(Test.java:13)

at Test.<init>(Test.java:5)

at Test.main(Test.java:20)

在上面的异常信息中，第一行“Exception in thread"main" java.lang.ArrayIndexOutOfBoundsException: 4”说明JVM在尝试访问数组索引号为4的值时抛出了异常，抛出异常的Java线程是“main”线程。

下面我们来大体过下stack trace信息。异常处理第一条：先看下第一行（包含异常消息的行）来了解是什么异常，然后再接着往下看来了解调用流程。在上面的例子中，调用从Test.java的第20行（main()方法）开始，然后开始调用Test类的构造器。构造器（Constructors）在stack traces里面以<init>方式显示，然后接着执行Test类的run()方法，在执行第13行时发现并抛出了异常。

从上面的stack trace，我们可以看出Test.java尝试读取的内容位置超出了数组的大小边界。

三、       Java线程转储(Thread Dump)

Java Thread dump可以被认为是在某一时刻JVM中所有线程的一个快照。线程转储可能包含一个或多个线程。在多线程环境中，比如像J2EE应用服务器中，会有很多线程和线程组。每一个线程都有它们自己的调用栈来执行各自负责的任务。Thread Dump提供所有这些JVM线程的站跟踪信息，以及关于某一特定线程的详细信息。

四、       Java虚拟机进程和Java线程(Java VM Process and Java Threads)

Java虚拟机或JVM是一个操作系统级的进程，Java线程是它的子进程或者轻量级进程（Solaris的说法）。

五、       生成Java线程转储(Generating Java Thread Dumps)

可以通过向JVM进程发送SIGQUIT信号来生成线程转储，有几种不同的方式可以发送这个信号给JVM进程：

在Unix中，可以使用“kill -3<pid>”命令，pid是JVM的进程ID；

在Windows中，可以在运行JVM所在的窗口按CTRL+BREAK组合键。

六、       Java线程的3种状态(Thread State)

每一个Java线程在它们的生命周期中都可能会处于下面3个状态中的任意一种状态。

Runnable

线程正在运行或者它已经拿到了它的CPU时间片而准备去运行。在JRockit虚拟机的线程转储中，这个状态标记为ACTIVE。

Waiting on Monitor

线程处于sleeping或者在一定时间内在一个对象上面等待，亦或者等待被另外一个线程唤醒（notifiy）。通常在调用Thread对象的sleep()方法或者某个对象的wait()方法时将会使线程会处于这个状态。

例如，在WebLogic服务器中，一些空闲的execute线程在等待一个socket读取线程去通知它们处理时，就会处于Waiting on Monitor状态。它们的stack trace跟下面这段类似：

"ExecuteThread: '2' for queue:'weblogic.admin.RMI'" daemon prio=5 tid=0x1752F040 nid=0x180c inObject.wait() [1887f000..1887fd8c]

at java.lang.Object.wait(Native Method) waiting on<04134D98> (a weblogic.kernel.ExecuteThread)

at java.lang.Object.wait(Object.java:426)

atweblogic.kernel.ExecuteThread.waitForRequest(ExecuteThread.java:126)

locked <04134D98> (a weblogic.kernel.ExecuteThread)

atweblogic.kernel.ExecuteThread.run(ExecuteThread.java:145)

一些其他版本的JVM也把这个状态叫做CW状态(Condition Waiting)，Object.wait()（如上所述）。JRockit虚拟机把这个状态标记为WAITING。

Waiting forMonitor Entry

表示线程正在等待一个对象的锁（一些其它的线程可能持有这个锁），当两个及以上的线程尝试执行同步代码时会出现这种情况。一定要注意，锁总是针对于对象而不是某些个别的方法。

下面是一个处于Waiting for Monitor Entry状态的线程stack trace示例：

"ExecuteThread: '24' for queue:'DisplayExecuteQueue'" daemon prio=5 tid=0x5541b0 nid=0x3b waiting formonitor entry [49b7f000..49b7fc24]

atweblogic.cluster.replication.ReplicationManager.createSecondary(ReplicationManager.java:908)
- waiting to lock <6c4b9130> (a java.lang.Object)
at weblogic.cluster.replication.ReplicationManager.updateSecondary(ReplicationManager.java:715)
at weblogic.servlet.internal.session.ReplicatedSessionData.syncSession(ReplicatedSessonData.java:459)
- locked <6c408700> (a weblogic.servlet.internal.session.ReplicatedSessionData)
at weblogic.servlet.internal.session.ReplicatedSessionContext.sync(ReplicatedSessionContext.java:134)
- locked <6c408700>(aweblogic.servlet.internal.session.ReplicatedSessionData)
at weblogic.servlet.internal.ServletRequestImpl.syncSession(ServletRequestImpl.java:2418)
at weblogic.servlet.internal.WebAppServletContext.invokeServlet(WebAppServletContext.java:3137)
at weblogic.servlet.internal.ServletRequestImpl.execute(ServletRequestImpl.java:2544)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:153)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:134)

从上面的stack trace中，你可以看到这个线程持有一个对象锁（地址为6c408700），同时又在等待锁另一个对象（地址为6c4b9130）。

一些其它的JVM可能并不会在stack trace中提供包含有锁相关信息的对象的Id，同样的状态也可以被叫做“MW”状态。JRockit虚拟机把这个状态标记为LOCKED。

七、       Java线程解剖(Anatomy of a Java Thread)

要想能够读懂或者分析Java线程转储，就必须要搞清楚线程转储的各个组成部分。下面我们通过一个thread stack样例进行举例，然后看看它的各个部分的内容。

"ExecuteThread: '1' " daemonprio=5 tid=0x628330 nid=0xf runnable [0xe4881000..0xe48819e0]

at com.vantive.vanjavi.VanJavi.VanCreateForm(Native Method)

at com.vantive.vanjavi.VanMain.open(VanMain.java:53)

at jsp_servlet._so.__newServiceOrder.printSOSection(__newServiceOrder.java:3547)

at jsp_servlet._so.__newServiceOrder._jspService (__newServiceOrder.java:5652)

at weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:265)

at weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:200)

at weblogic.servlet.internal.WebAppServletContext.invokeServlet(WebAppServletContext.java:2495)

at weblogic.servlet.internal.ServletRequestImpl.execute(ServletRequestImpl.java:2204)

at weblogic.kernel.ExecuteThread.execute (ExecuteThread.java:139)

at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:120)

在上面的线程转储中，我们最感兴趣的是第一行，至于其它的部分无外乎就是一些常见的stack trace内容。下面我来看看第一行都提供了什么信息：

Execute Thread : 1说明线程名称是"ExecuteThread: '1' "；

daemon表示这个线程是一个daemon线程；

prio=5线程的优先级 (默认是5)；

tid Java 线程Id (在运行的JVM实例中的线程唯一标识符)；

nid线程的本地Id（Native Identifier），在Solaris系统中指的是LWP id， 操作系统级的进程Id；

runnable线程状态(如上所述)；

[x..y]指这个线程在java heap里面执行的地址范围；

剩下的线程转储内容说明了调用流程，在这个例子中，线程（ExecuteThread 1）是一个正在执行本地vanCreateForm()方法的操作系统的后台daemon线程。

八、       如何使用线程转储(Putting Thread Dumps to Use)

在这个部分，我会给大家介绍一些java线程转储非常有用的案例。

(一)   高CPU占用率(High CPU consumption)

诊断分析(Diagnosis)

应用程序似乎消耗了几乎100%CPU占用率，同时系统吞吐量有显著下降，在高负载CPU的情况下，系统性能开始变的很低。

线程转储(Thread Dump)

线程转储中所有线程大都表现出一个或多个线程在所有的线程转储时都在执行相同的操作。

解决方案(Solution)

1. 选择一个特定的调用流程（例如：一个web的表单提交调用流程），在调用完成前采取5~7次线程转储操作；

2. 在线程转储中查找处于“runnable”状态的线程。如果每个这样的线程看起来都在继续执行（每一个线程转储中的方法调用都不同），说明这个线程一直在处理中，应该不是罪魁祸首。如果在整个线程转储中，线程都在执行相同的方法（相同的行号），那么几乎可以非常确定这个线程就是罪魁祸首。然后找到这段代码，做一个代码级别的分析，你几乎就可以确定找到了问题所在。

(二)   CPU占用率很低，但是响应时间却很糟糕(Low CPU consumption and Poor Response time)

诊断分析(Diagnosis)

通常在I/O非常密集型的系统中，每当系统负载过高时，都会发生这样的情况。CPU占用率低是因为只有少数的线程在使用合理的CPU时间片。

线程转储(Thread Dump)

一些或者所有处于runnable状态的线程似乎都在执行I/O相关的操作，比如：一个文件读/写或者数据库相关的操作。

解决方案(Solution)

简要了解应用程序的I/O操作后，我们可以使用缓存（如果可以的话）来减少与数据库的交互。

(三)   应用程序/服务器挂起

诊断分析(Diagnosis)

某个用程序或者JVM托管应用程序的服务器将会挂起（变得无法响应服务请求）。

线程转储(Thread Dump)

1. 在所有线程转储期间，发现所有处于runnable状态的线程都在执行相同的操作。服务器无法创建更多的线程，因为所有的runnable线程“永远”都无法完成它们的任务；

2. 这可能是由于许多线程都在等待一个monitor entry。如果一个“runnable”的线程持有某个对象上的锁，并且从不返回这个锁，而同时其它线程又都在等待同一个锁时，就会发生这种情况。

解决方案(Solution)

1. 检查死锁。JVM通常是可以检测到一些简单的死锁（比如：线程A正在等待线程B，反之亦然）。然而，你需要了解在某个特定时刻锁的相关情况，以确定是否有涉及任何复杂的死锁场景；

2. 重审代码中的同步方法或同步块，尽可能减少同步区域的大小；

3. 其中一个问题可能是在访问一个远程资源或组件时超时时间过长。可以实现一个具有合理超时限制的远程对象客户端，以便在远程系统未在规定时间内响应时抛出一个合适的异常；

4. 如果所有的线程都在等待一个资源（比如：EJB/DB连接），可以考虑增加这些资源池的大小。

九、       工具(Tools)

线程转储分析，在商业领域和开源领域都有一些可用的工具。Samurai（中文译为：日本武士）就是其中之一，Samurai是一个轻量级的开源工具，它既可以通过命令提示行启动，也可以以JavaWeb Start应用程序方式运行。关于Samurai的更多信息和文档，可以访问：http://yusuke.homeip.net/samurai/en/index.html

十、       结论(Conclusion)

在生产环境中维护企业级J2EE应用程序是一项非常艰巨的任务。随着业务的不断变化，J2EE应用环境的变化，都可能会导致生产环境的应用程序运行不稳定，其中一个主要因素就是高负载。虽然，大部分系统都被设计为可扩展的，但是环境的限制仍然可能会导致这些系统变得无法响应。

Java线程转储是一个用来识别、诊断、检测和解决典型的生产系统问题的很好机制。虽然应用程序分析和其它的一些机制确实存在，分析Java线程转储可以让我们对一些常见的生产系统级问题有一个清晰、早期的认识，并且为我们节省了时间，帮助我们为生产应用程序提供更好的用户体验。

译文下载地址：http://download.csdn.net/detail/yakoo5/7280879