java线程分析

站在巨人的肩膀上：

netstat -anp|grep **

我发现现在网上没有好好讲这个的，少数的几篇文章都是大谈自己的工具，却没把方法讲清楚。我决定以我以前碰到的case为例写一篇来分享。到目前为止，我认为分析Java代码问题的最有效的工具仍然是java thread dump。

原因：

- 任何操作系统平台下都可以使用。

- 在多数情况下，可以在生产环境中使用。

- 和操作系统提供的工具相比，java thread dump给出的信息是直白的，直接对应到应用代码。

- 它对被分析的系统干扰很小，因此能反应真实的问题。而其它很多profiling或Instrument工具本身对JVM运行有很大的干扰，经常不能暴露出真正的问题，而且这种工具不能用于生产系统。

我觉得在通常情况下分析Java虚拟机死锁比分析内存泄漏要容易的多。因为死锁发生时，JVM通常处于挂起状态(hang住了)，thread dump可以给出静态稳定的信息，查找死锁只需要查找有问题的线程。而内存泄漏的问题却很难界定，一个运行的JVM里有无数对象存在，只有写程序的人才知道哪些对象是垃圾，而哪些不是，而且对象的引用关系非常复杂，很难得到一份清晰的对象引用图。

Java虚拟机死锁发生时，从操作系统上观察，虚拟机的CPU占用率为零，很快会从top或prstat的输出中消失。这时你就可以收集thread dump了，Unix/Linux 下是kill -3 <JVM pid> ，在Windows下可以在JVM的console窗口上敲Ctrl-Break。根据不同的设置，thread dump会输出到当前控制台上或应用服务器的日志里。

"service-j2ee" prio=5 tid=0x024f1c28 nid=0x125 waiting for monitor entry

[62a3e000..62a3f690]

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

com.sun.enterprise.resource.IASNonSharedResourcePool.internalGetResource(IASNonS

haredResourcePool.java:625)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: - waiting to

lock <0x965d8110> (a com.sun.enterprise.resource.IASNonSharedResourcePool)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

com.sun.enterprise.resource.IASNonSharedResourcePool.getResource(IASNonSharedRes

ourcePool.java:520)

................

如何找到当前持有锁的线程是解决问题的关键。方法是搜索thread dump，查找"locked <0x965d8110>"， 找到持有锁的线程。

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: "Thread-20" daemon prio=5 tid=0x01394f18

nid=0x109 runnable [6716f000..6716fc28]

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

java.net.SocketInputStream.socketRead0(Native Method)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

java.net.SocketInputStream.read(SocketInputStream.java:129)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at oracle.net.ns.Packet.receive(Unknown

Source)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.net.ns.DataPacket.receive(Unknown Source)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.net.ns.NetInputStream.getNextPacket(Unknown Source)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.net.ns.NetInputStream.read(Unknown Source)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.net.ns.NetInputStream.read(Unknown Source)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.net.ns.NetInputStream.read(Unknown Source)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.jdbc.ttc7.MAREngine.unmarshalUB1(MAREngine.java:929)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.jdbc.ttc7.MAREngine.unmarshalSB1(MAREngine.java:893)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.jdbc.ttc7.Ocommoncall.receive(Ocommoncall.java:106)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.jdbc.ttc7.TTC7Protocol.logoff(TTC7Protocol.java:396)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: - locked <0x954f47a0> (a

oracle.jdbc.ttc7.TTC7Protocol)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.jdbc.driver.OracleConnection.close(OracleConnection.java:1518)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: - locked <0x954f4520> (a

oracle.jdbc.driver.OracleConnection)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

com.sun.enterprise.resource.JdbcUrlAllocator.destroyResource(JdbcUrlAllocator.java:122)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

com.sun.enterprise.resource.IASNonSharedResourcePool.destroyResource(IASNonSharedResourcePool.java:8

72)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

com.sun.enterprise.resource.IASNonSharedResourcePool.resizePool(IASNonSharedResourcePool.java:1086)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: - locked <0x965d8110> (a

com.sun.enterprise.resource.IASNonSharedResourcePool)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

com.sun.enterprise.resource.IASNonSharedResourcePool$Resizer.run(IASNonSharedResourcePool.java:1178)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

java.util.TimerThread.mainLoop(Timer.java:432)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

java.util.TimerThread.run(Timer.java:382)

在这个例子里，持有锁的线程在等待Oracle返回结果，却始终等不到响应，因此发生了死锁。

如果持有锁的线程还在等待给另一个对象上锁，那么还是按上面的办法顺藤摸瓜，直到找到死锁的根源为止。

另外，在thread dump里还会经常看到这样的线程，它们是等待一个条件而主动放弃锁的线程。例如：

"Thread-1" daemon prio=5 tid=0x014e97a8 nid=0x80 in Object.wait() [68c6f000..68c6fc28]

at java.lang.Object.wait(Native Method)

- waiting on <0x95b07178> (a java.util.LinkedList)

at com.iplanet.ias.util.collection.BlockingQueue.remove(BlockingQueue.java:258)

- locked <0x95b07178> (a java.util.LinkedList)

at com.iplanet.ias.util.threadpool.FastThreadPool$ThreadPoolThread.run(FastThreadPool.java:241)

at java.lang.Thread.run(Thread.java:534)

有时也会需要分析这类线程，尤其是线程等待的条件。

其实，Java thread dump并不只用于分析死锁，其它Java应用运行时古怪的行为都可以用thread dump来分析。

最后，在Java SE 5里，增加了jstack的工具，也可以获取thread dump。在Java SE 6里， 通过jconsole的图形化工具也可以方便地查找涉及object monitors 和java.util.concurrent.locks死锁。

二：线程分析 
2.1. JVM 线程 
在线程中，有一些 JVM内部的后台线程，来执行譬如垃圾回收，或者低内存的检测等等任务，这些线程往往在 JVM初始化的时候就存在，如下所示：

     我们更多的是要观察用户级别的线程，如下所示：

我们能看到：
    * 线程的状态： waiting on condition
    * 线程的调用栈
    * 线程的当前锁住的资源： <0xef63d600> 


2.2. 线程的状态分析 
       正如我们刚看到的那样，线程的状态是一个重要的指标，它会显示在线程 Stacktrace的头一行结尾的地方。那么线程常见的有哪些状态呢？线程在什么样的情况下会进入这种状态呢？我们能从中发现什么线索？< /span>
1.1 Runnable 
该状态表示线程具备所有运行条件，在运行队列中准备操作系统的调度，或者正在运行。

1.2 Wait on condition 
       该状态出现在线程等待某个条件的发生。具体是什么原因，可以结合 stacktrace来分析。最常见的情况是线程在等待网络的读写，比如当网络数据没有准备好读时，线程处于这种等待状态，而一旦有数据准备好读之后，线程会重新激活，读取并处理数据。在 Java引入 NewIO之前，对于每个网络连接，都有一个对应的线程来处理网络的读写操作，即使没有可读写的数据，线程仍然阻塞在读写操作上，这样有可能造成资源浪费，而且给操作系统的线程调度也带来压力。在 NewIO里采用了新的机制，编写的服务器程序的性能和可扩展性都得到提高。
        如果发现有大量的线程都在处在 Wait on condition，从线程 stack看， 正等待网络读写，这可能是一个网络瓶颈的征兆。因为网络阻塞导致线程无法执行。一种情况是网络非常忙，几 乎消耗了所有的带宽，仍然有大量数据等待网络读 写；另一种情况也可能是网络空闲，但由于路由等问题，导致包无法正常的到达。所以要结合系统的一些性能观察工具来综合分析，比如 netstat统计单位时间的发送包的数目，如果很明显超过了所在网络带宽的限制 ; 观察 cpu的利用率，如果系统态的 CPU时间，相对于用户态的 CPU时间比例较高；如果程序运行在 Solaris 10平台上，可以用 dtrace工具看系统调用的情况，如果观察到 read/write的系统调用的次数或者运行时间遥遥领先；这些都指向由于网络带宽所限导致的网络瓶颈。另外一种出现 Wait on condition的常见情况是该线程在 sleep，等待 sleep的时间到了时候，将被唤醒。

1.3 Waiting for monitor entry 和 in Object.wait() 
         在多线程的 JAVA程序中，实现线程之间的同步，就要说说 Monitor。 Monitor是 Java中用以实现线程之间的互斥与协作的主要手段，它可以看成是对象或者 Class的锁。每一个对象都有，也仅有一个 monitor。每个 Monitor在某个时刻，只能被一个线程拥有，该线程就是 “Active Thread”，而其它线程都是 “Waiting Thread”，分别在两个队列 “ Entry Set”和 “Wait Set”里面等候。在 “Entry Set”中等待的线程状态是 “Waiting for monitor entry”，而在 “Wait Set”中等待的线程状态是 “in Object.wait()”。
        先看 “Entry Set”里面的线程。我们称被 synchronized保护起来的代码段为临界区。当一个线程申请进入临界区时，它就进入了 “Entry Set”队列。对应的 code就像：
synchronized(obj) {
.........

}

这时有两种可能性：
     该 monitor不被其它线程拥有， Entry Set里面也没有其它等待线程。本线程即成为相应类或者对象的 Monitor的 Owner，执行临界区的代码
     该 monitor被其它线程拥有，本线程在 Entry Set队列中等待。 

在第一种情况下，线程将处于 “Runnable”的状态，而第二种情况下，线程 DUMP会显示处于 “waiting for monitor entry”。如下所示：

        临界区的设置，是为了保证其内部的代码执行的原子性和完整性。但是因为临界区在任何时间只允许线程串行通过，这 和我们多线程的程序的初衷是相反的。 如果在多线程的程序中，大量使用 synchronized，或者不适当的使用了它，会造成大量线程在临界区的入口等待，造成系统的性能大幅下降。如果在线程 DUMP中发现了这个情况，应该审查源码，改进程序。
        现在我们再来看现在线程为什么会进入 “Wait Set”。当线程获得了 Monitor，进入了临界区之后，如果发现线程继续运行的条件没有满足，它则调用对象（一般就是被 synchronized 的对象）的 wait() 方法，放弃了 Monitor，进入 “Wait Set”队列。只有当别的线程在该对象上调用了 notify() 或者 notifyAll() ， “ Wait Set”队列中线程才得到机会去竞争，但是只有一个线程获得对象的 Monitor，恢复到运行态。在 “Wait Set”中的线程， DUMP中表现为： in Object.wait()，类似于：

仔细观察上面的 DUMP信息，你会发现它有以下两行：
- locked <0xef63beb8> (a java.util.ArrayList)
- waiting on <0xef63beb8> (a java.util.ArrayList) 
这里需要解释一下，为什么先 lock了这个对象，然后又 waiting on同一个对象呢？让我们看看这个线程对应的代码：

线程的执行中，先用 synchronized 获得了这个对象的 Monitor（对应于 locked <0xef63beb8> ）。当执行到 obj.wait(), 线程即放弃了 Monitor的所有权，进入 “wait set”队列（对应于 waiting on <0xef63beb8> ）。
         往往在你的程序中，会出现多个类似的线程，他们都有相似的 DUMP信息。这也可能是正常的。比如，在程序中，有多个服务线程，设计成从一个队列里面读取请求数据。这个队列就是 lock以及 waiting on的对象。当队列为空的时候，这些线程都会在这个队列上等待，直到队列有了数据，这些线程被 Notify，当然只有一个线程获得了 lock，继续执行，而其它线程继续等待。

3. JDK 5.0 的 lock 
        上面我们提到如果 synchronized和 monitor机制运用不当，可能会造成多线程程序的性能问题。在 JDK 5.0中，引入了 Lock机制，从而使开发者能更灵活的开发高性能的并发多线程程序，可以替代以往 JDK中的 synchronized和 Monitor的 机制。但是，要注意的是，因为 Lock类只是一个普通类， JVM无从得知 Lock对象的占用情况，所以在线程 DUMP中，也不会包含关于 Lock的信息， 关于死锁等问题，就不如用 synchronized的编程方式容易识别。

4.案例分析 
1.     死锁
在多线程程序的编写中，如果不适当的运用同步机制，则有可能造成程序的死锁，经常表现为程序的停顿，或者不再响应用户的请求。比如在下面这个示例中，是个较为典型的死锁情况：

在 JAVA 5中加强了对死锁的检测。线程 Dump中可以直接报告出 Java级别的死锁，如下所示：

2.     热锁
        热锁，也往往是导致系统性能瓶颈的主要因素。其表现特征为，由于多个线程对临界区，或者锁的竞争，可能出现：
    * 频繁的线程的上下文切换：从操作系统对线程的调度来看，当 线程在等待资源而阻塞的时候，操作系统会将之切换出来，放到等待的队列，当线程获得资源之后，调度算法会将这个线程切换进去，放到执行队列中。
    * 大量的系统调用：因为线程的上下文切换，以及热锁的竞争，或 者临界区的频繁的进出，都可能导致大量的系统调用。
    * 大部分 CPU开销用在 “系统态 ”：线程上下文切换，和系统调用，都会导致 CPU在 “系统态 ”运行，换而言之，虽然系统很忙碌，但是 CPU用在 “用户态 ”的比例较小，应用程序得不到充分的 CPU资源。 
    * 随着 CPU数目的增多，系统的性能反而下降。因为 CPU数目多，同 时运行的线程就越多，可能就会造成更频繁的线程上下文切换和系统态的 CPU开销，从而导致更糟糕的性能。 
上面的描述，都是一个 scalability（可扩展性）很差的系统的表现。从整体的性能指标看，由于线程热锁的存在，程序的响应时间会变长，吞吐量会降低。< /span>
         那么，怎么去了解 “热锁 ”出现在什么地方呢？一个重要的方法还是结合操作系统的各种工具观察系统资源使用状况，以及收集 Java线程的 DUMP信息，看线程都阻塞在什么方法上，了解原因，才能找到对应的解决方法。
        我们曾经遇到过这样的例子，程序运行时，出现了以上指出的各种现象，通过观察操作系统的资源使用统计信息，以及线程 DUMP信息，确定了程序中热锁的存在，并发现大多数的线程状态都是 Waiting for monitor entry或者 Wait on monitor，且是阻塞在压缩和解压缩的方法上。后来采用第三方的压缩包 javalib替代 JDK自带的压缩包后，系统的性能提高了几倍。