我的Java程序在做什么呢？

经常被客户问到这样的问题，我想知道我的Java应用到底在干什么？通常我会反问一句：你为什么想知道呢？得到的回答是，这个Java应用太耗用CPU的资源了，想知道它都耗在哪儿了！

我的这些客户其实都有一定的经验，他们知道怎样通过操作系统的工具和命令来查看某个应用对CPU的资源消耗。例如在Solaris中的prstat命令，就可以得到下面的输出

PID      USERNAME  SIZE     RSS     STATE  PRI   NICE      TIME    CPU    PROCESS/NLWP
 22227  root               706M  568M      cpu19    0        0          17:34:33  82%    appservDAS/89
  24348 root               570M  439M      sleep     59       0          0:00:05    0.7%    Xorg/15
   9053  root               215M  134M      sleep     1         0          5:55:37    0.5%    java/10
 18879  root               500M  386M      sleep    59       0           0:32:01    0.0%    Oracle/58
 24482  root               3384K 2936K     cpu0    49      0           0:00:00    0.0%    prstat/1
........
Total: 72 processes, 1483 lwps, load averages: 3.39, 3.40, 3.31

从上面的输出很容易判断哪个应用占用了多少CPU的资源。例如上面的例子JavaEE应用服务器“appservDAS”占用了82%的CPU资源。appservDAS的进程其实就是Java应用。那么要进一步判断这个进程为什么消耗了这么多的CPU呢？这不是件容易的事。我的客户先是获得了Java进程的一个快照，也叫ThreadDump。这很简单，只需要kill -3 22227就可以给这个Java进程一个信号，要求它打印出所有当前的线程调用栈。结果如下：

Full thread dump Java HotSpot(TM) Server VM (1.5.0_09-b03 mixed mode):

"RMI ConnectionExpiration-[10.1.4.206:43996,com.sun.appserv.management.client.AdminRMISSLClientSocketFactory@807653]" daemon prio=10 tid=0x028cb120 nid=0x24f6 waiting on condition [0xc30ff000..0xc30ffbf0]
 at java.lang.Thread.sleep(Native Method)
 at sun.rmi.transport.tcp.TCPChannel$Reaper.run(TCPChannel.java:446)
 at java.lang.Thread.run(Thread.java:595)

"RMI TCP Connection(4205)-10.1.4.206" daemon prio=10 tid=0x0110eb30 nid=0x24f4 runnable [0xc31ff000..0xc31ffaf0]
 at java.net.SocketInputStream.socketRead0(Native Method)
 at java.net.SocketInputStream.read(SocketInputStream.java:129)
 at com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:293)
 at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:331)
 at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:723)
 - locked <0xf7362488> (a java.lang.Object)
 at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:680)
 at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)
 - locked <0xf7362498> (a com.sun.net.ssl.internal.ssl.AppInputStream)
 at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
 at java.io.BufferedInputStream.read(BufferedInputStream.java:235)
 - locked <0xf325e540> (a java.io.BufferedInputStream)
 at java.io.FilterInputStream.read(FilterInputStream.java:66)
 at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:448)
 at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:707)
 at java.lang.Thread.run(Thread.java:595)

"service-j2ee" daemon prio=10 tid=0x01c080d8 nid=0x811 runnable [0x00000000..0xc60ff7e0]

"service-j2ee" daemon prio=10 tid=0x01d78e60 nid=0x812 runnable [0x00000000..0xc541f7e0]

"service-j2ee" daemon prio=10 tid=0x010c98a0 nid=0x813 runnable [0x00000000..0xc53cf7e0]

"service-j2ee" daemon prio=10 tid=0x01d7b110 nid=0x814 runnable [0x00000000..0xc516f7e0]

.......

原谅我不把所有的长长的输出都写在这，总之很长，想想，有89个线程呢！从这里能看出什么来吗？能看出哪个线程花费了多少CPU吗？看不出来，因为快照是个静态的数据，只能知道当前每个线程在做什么，但是哪个线程花的CPU多就不得而知了。

通常要知道你的应用哪些部分花费的CPU资源多，需要profiling的工具（例如NetBeans的Profiler），但是这些工具使用和部署起来还是比较麻烦的，而且不适用于生产系统。下面提供一个简单的方法来快速的判断：

1 使用prstat的时候加上-L的参数，你就能获得每个操作系统的线程所消耗的资源。例如：

PID      USERNAME  SIZE     RSS     STATE  PRI   NICE      TIME    CPU    PROCESS/LWPID
 22227  root               706M  568M      cpu19    0        0          17:34:33  23%    appservDAS/89
22227  root               706M  568M      cpu19    0        0          17:34:33  12%    appservDAS/54
22227  root               706M  568M      cpu19    0        0          17:34:33  10%    appservDAS/31
22227  root               706M  568M      cpu19    0        0          17:34:33  10%    appservDAS/12
  24348 root               570M  439M      sleep     59       0          0:00:05    0.7%    Xorg/15
   9053  root               215M  134M      sleep     1         0          5:55:37    0.5%    java/10
 18879  root               500M  386M      sleep    59       0           0:32:01    0.0%    Oracle/58
 24482  root               3384K 2936K     cpu0    49      0           0:00:00    0.0%    prstat/1
........
Total: 72 processes, 1483 lwps, load averages: 3.39, 3.40, 3.31

这时候你能获得比刚才更详细的信息：哪个线程花费了多少CPU。但是这个线程号如何与Java Thread Dump文件中对应起来呢。很简单，在Java Thread Dump文件中，每个线程都有tid=...nid=...的属性，其中nid就是native thread id，也就是只的是LWPID号，只不过nid中用16进制来表示。例如上面的例子中，从prstat中，获得appservDAS的第89个线程消耗了很大的CPU，89的16进制是0x59，找到下面的线程：

"service-j2ee" daemon prio=10 tid=0x016158e8 nid=0x59 runnable [0xc789e000..0xc789f7e0]
 at com.sun.enterprise.web.connector.httpservice.HttpServiceConnector.jniRead(Native Method)
 at com.sun.enterprise.web.connector.httpservice.HttpServiceConnector.read(HttpServiceConnector.java:283)
 at com.sun.enterprise.web.connector.httpservice.HttpServiceRequestStream.read(HttpServiceRequestStream.java:55)
 at org.apache.jsp.mod_005fdms.commons.iWebServer_jsp$iWebSignature.ReadPackage(iWebServer_jsp.java:400)
 at org.apache.jsp.mod_005fdms.commons.iWebServer_jsp$iWebSignature.ExecuteRun(iWebServer_jsp.java:459)
 at org.apache.jsp.mod_005fdms.commons.iWebServer_jsp._jspService(iWebServer_jsp.java:672)
 at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:105)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:860)
....

就可以快速判断这个Java应用的资源消耗大概在什么地方了！