JAVA进阶5 性能分析工具——JStack

一、功能说明

1. 作用

生成java虚拟机当前时刻的线程快照，即每个线程的堆栈信息，可以用来定位线程出现长时间停顿的原因。

2. 语法

jstack命令的语法格式： jstack <pid>
可以用jps查看java进程id。

在实际运行中，往往一次 dump的信息，还不足以确认问题。建议产生三次 dump信息，如果每次 dump都指向同一个问题，我们才确定问题的典型性。

一段jstack 运行结果示例：

"pool-1-thread-1" prio=10 tid=0x00007f3bf012d000 nid=0x7168 waiting on condition [0x00007f3c34164000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x0000000085c23468> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:745)

"commons-pool-EvictionTimer" daemon prio=10 tid=0x00007f3bf0112800 nid=0x7167 in Object.wait() [0x00007f3c188cc000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000085c24778> (a java.util.TaskQueue)
	at java.util.TimerThread.mainLoop(Timer.java:552)
	- locked <0x0000000085c24778> (a java.util.TaskQueue)
	at java.util.TimerThread.run(Timer.java:505)

"nioEventLoopGroup-3-8" prio=10 tid=0x00007f3c00016000 nid=0x7140 runnable [0x00007f3c346c2000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
	- locked <0x0000000085e6d7e0> (a io.netty.channel.nio.SelectedSelectionKeySet)
	- locked <0x0000000085e6d7d0> (a java.util.Collections$UnmodifiableSet)
	- locked <0x0000000085e6d800> (a sun.nio.ch.EPollSelectorImpl)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
	at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:622)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:310)
	at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
	at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
	at java.lang.Thread.run(Thread.java:745)

"nioEventLoopGroup-3-7" prio=10 tid=0x00007f3c00014000 nid=0x713f runnable [0x00007f3c347c3000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
	- locked <0x0000000085ca0f70> (a io.netty.channel.nio.SelectedSelectionKeySet)
	- locked <0x0000000085cc2f60> (a java.util.Collections$UnmodifiableSet)
	- locked <0x0000000085ca0e68> (a sun.nio.ch.EPollSelectorImpl)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
	at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:622)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:310)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48

3. 一般程序分析过程

(1) 获取进程pid

通过jps, ps -ef | grep java 等命令 获取目标进程pid。本文示例pid = 3367

(2) 进程pid转16进制

可使用命令： printf "%x\n" 目标进程pid。

printf "%x\n" 3367
1

(3) 使用jstack命令打印快照

# jstack 进程id | grep -20 16进制值
jstack 3363 | grep -20 d27
1
2

分析红字上下文查找进程可能的问题即可。

二、线程状态分析

1. deadlock

死锁

2. locked

线程阻塞，指当前线程执行过程中，所需要的资源长时间等待却一直未能获取到，被容器的线程管理标识为阻塞状态，可以理解为等待资源超时的线程。

3. Runnable

在运行队列中准备操作系统的调度，或者正在运行。

4. TIMED_WAITING

线程在等待唤醒，但设置了时限

5. Wait on condition

该状态出现在线程等待某个条件的发生。具体是什么原因，可以结合 stacktrace来分析。
最常见的情况是线程在等待网络的读写。
如果发现有大量的线程都在处在 Wait on condition，从线程 stack看， 正等待网络读写，这可能是一个网络瓶颈的征兆。因为网络阻塞导致线程无法执行。一种情况是网络非常忙，几 乎消耗了所有的带宽，仍然有大量数据等待网络读 写；另一种情况也可能是网络空闲，但由于路由等问题，导致包无法正常的到达。所以要结合系统的一些性能观察工具来综合分析，比如 netstat统计单位时间的发送包的数目，如果很明显超过了所在网络带宽的限制 ; 观察 cpu的利用率，如果系统态的 CPU时间，相对于用户态的 CPU时间比例较高；如果程序运行在 Solaris 10平台上，可以用 dtrace工具看系统调用的情况，如果观察到 read/write的系统调用的次数或者运行时间遥遥领先；这些都指向由于网络带宽所限导致的网络瓶颈。另外一种出现 Wait on condition的常见情况是该线程在 sleep，等待 sleep的时间到了时候，将被唤醒。

6. 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) {
.........

}
1
2
3
4

这时有两种可能性：
该 monitor不被其它线程拥有， Entry Set里面也没有其它等待线程。本线程即成为相应类或者对象的 Monitor的 Owner，执行临界区的代码
该 monitor被其它线程拥有，本线程在 Entry Set队列中等待。
在第一种情况下，线程将处于 “Runnable”的状态，而第二种情况下，线程 DUMP会显示处于 “waiting for monitor entry”。如下所示：

"Thread-0" prio=10 tid=0x08222eb0 nid=0x9 waiting for monitor entry [0xf927b000..0xf927bdb8]  
  
at testthread.WaitThread.run(WaitThread.java:39)  
  
- waiting to lock <0xef63bf08> (a java.lang.Object)  
  
- locked <0xef63beb8> (a java.util.ArrayList)  
  
at java.lang.Thread.run(Thread.java:595)  
1
2
3
4
5
6
7
8
9

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

"Thread-1" prio=10 tid=0x08223250 nid=0xa in Object.wait() [0xef47a000..0xef47aa38]  
  
        at java.lang.Object.wait(Native Method)  
  
        - waiting on <0xef63beb8> (a java.util.ArrayList)  
  
        at java.lang.Object.wait(Object.java:474)  
  
        at testthread.MyWaitThread.run(MyWaitThread.java:40)  
  
        - locked <0xef63beb8> (a java.util.ArrayList)  
  
        at java.lang.Thread.run(Thread.java:595)  
1
2
3
4
5
6
7
8
9
10
11
12
13

仔细观察上面的 DUMP信息，你会发现它有以下两行：

• locked <0xef63beb8> (a java.util.ArrayList)
• waiting on <0xef63beb8> (a java.util.ArrayList)
  这里需要解释一下，为什么先 lock了这个对象，然后又 waiting on同一个对象呢？让我们看看这个线程对应的代码：

synchronized(obj) {  
       .........  
       obj.wait();  
       .........  
}   
1
2
3
4
5

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

三、JDK 5.0 的 lock

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

死锁示例

Found one Java-level deadlock:  
=============================  
"Thread-1":  
waiting to lock monitor 0x0003f334 (object 0x22c19f18, a java.lang.Object),  
which is held by "Thread-0"  
"Thread-0":  
waiting to lock monitor 0x0003f314 (object 0x22c19f20, a java.lang.Object),  
which is held by "Thread-1"   
1
2
3
4
5
6
7
8

JStack 分析工具

IBM Thread and Monitor Dump Analyzer for Java