使用jdk的jps、jstack工具检测代码问题，提高程序性能

标签：util   entry   执行   argument   could   mil   tar   cte   top   

今天给大家分享怎样利用jdk的jps和jstack工具结合定位代码的问题，提高程序的稳定性、健壮性和性能。

在jdk的bin，目录下面有很多的工具如图：

jps、jstack工具介绍:

jps:

是JDK1.5提供的一个显示当前所有java进程pid的命令，简单实用，非常适合在linux/unix平台上简单察看当前java进程的一些简单情况。

命令格式：jps [options ] [ hostid ]

[options]选项 ：

-q：仅输出VM标识符，不包括classname,jar name,arguments in main method 

-m：输出main method的参数 

-l：输出完全的包名，应用主类名，jar的完全路径名 

-v：输出jvm参数 

-V：输出通过flag文件传递到JVM中的参数(.hotspotrc文件或-XX:Flags=所指定的文件 

-Joption：传递参数到vm,例如:-J-Xms1024m

用-l作示例:

在图中，第一例是进程号，第二例是进程名（运行的程序），比如activemq（/home/activeMq/apache-activemq-5.5.1/bin/run.jar）、dubbo

服务（com.alibaba.dubbo.container.Main）、tomcat(org.apache.catalina.startup.Bootstrap)等等。

jstack:

jstack是java虚拟机自带的一种堆栈跟踪工具。jstack用于生成java虚拟机当前时刻的线程快照。线程快照是当前java虚拟机内每一条线程正

在执行的方法堆栈的集合，生成线程快照的主要目的是定位线程出现长时间停顿的原因，如线程间死锁、死循环、请求外部资源导致的长时

间等待等。

 线程出现停顿的时候通过jstack来查看各个线程的调用堆栈，就可以知道没有响应的线程到底在后台做什么事情，或者等待什么资源。

命令格式:jstack [ option ] pid

[options]选项 ：

-F :当’jstack [-l] pid’没有响应的时候强制打印栈信息;

-l :长列表. 打印关于锁的附加信息,例如属于java.util.concurrent的ownable synchronizers列表.

-m: 打印java和native c/c++框架的所有栈信息. -h | -help打印帮助信息

pid :需要被打印配置信息的java进程id,可以用jps工具查询

用-l作示例：

命令：

运行结果：

从图中我们可以查看各个线程的调用堆栈，就可以知道没有响应的线程到底在后台做什么事情，或者等待什么资源。

jps、jstack查找代码问题

原理：

通过jps命令查找到对应程序的进程，记录进程号，通过jstack命令把该进程号所在的程序的线程堆栈信息输出到文件，然后对文件里面的信息进行

分析，找到原因并解决问题。

注：这种方式尽量在并发的时候进行使用这样更容易找出代码问题。

步骤：

1).进入到jdk的bin目录，如图：

2).使用jps工具查看tomcat的进程（如果是linux环境建议使用ps命令）；

因为只安装了一个tomcat，使用jps -m命令（如果安装了多个tomcat ，请使用jps -v命令，该命令运行的结果中可以看到各个tomcat的路径）

3).执行jstack命令，并把输出结果输出到日志文件；

命令：

[root@s4 bin]# jstack 28501 >log1.log

打开文件log1.log文件看里面内容：

[root@s4 bin]# tail -200f log1.log
        - locked <0x00000007058fc4b0> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:484)
        at java.lang.Thread.run(Thread.java:662)

"http-8090-11" daemon prio=10 tid=0x00002aaab4047000 nid=0x7181 in Object.wait() [0x000000004238b000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000007056433f0> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
        at java.lang.Object.wait(Object.java:485)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:458)
        - locked <0x00000007056433f0> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:484)
        at java.lang.Thread.run(Thread.java:662)

"http-8090-10" daemon prio=10 tid=0x00002aaab46ec000 nid=0x7180 in Object.wait() [0x000000004228a000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x0000000705643610> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
        at java.lang.Object.wait(Object.java:485)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:458)
        - locked <0x0000000705643610> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:484)
        at java.lang.Thread.run(Thread.java:662)

"http-8090-9" daemon prio=10 tid=0x00002aaab4525800 nid=0x717f in Object.wait() [0x000000004078a000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x0000000705643898> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
        at java.lang.Object.wait(Object.java:485)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:458)
        - locked <0x0000000705643898> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:484)
        at java.lang.Thread.run(Thread.java:662)

4).日志文件进行分析

由于上面的tomcat没有进行压力测试，所以看到的都是tomcat的线程没有自己程序代码的线程。因此使用前段时间的进过

压力测试后导出的日志进行分析。部分日志内容如下：

"DubboClientHandler-192.168.6.162:2099-thread-2" daemon prio=10 tid=0x00002aaac069a000 nid=0x14c1 waiting on condition [0x000000004867f000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x0000000782c4d8e0> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:662)

"DubboClientHandler-192.168.6.162:2099-thread-2" daemon prio=10 tid=0x000000005be86000 nid=0x14c0 waiting on condition [0x000000004863e000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x0000000782c61ac0> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:662)


"http-portal%2F192.168.6.162-8097-184" daemon prio=10 tid=0x00002aaab0ecc800 nid=0x2d7a waiting for monitor entry [0x0000000045fa9000]  
  java.lang.Thread.State: BLOCKED (on object monitor)  
    at org.apache.log4j.Category.callAppenders(Category.java:204)  
    - waiting to lock <0x00000007800020a0> (a org.apache.log4j.spi.RootLogger)  
    at org.apache.log4j.Category.forcedLog(Category.java:391)  
    at org.apache.log4j.Category.log(Category.java:856)  
    at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:304)  

从最后的日志中我们可以看出这个日志线程处于BLOCKED状态，进入org.apache.log4j.Category类的callAppenders方法，

代码如下：

/**
     Call the appenders in the hierrachy starting at
     <code>this</code>.  If no appenders could be found, emit a
     warning.

     <p>This method calls all the appenders inherited from the
     hierarchy circumventing any evaluation of whether to log or not
     to log the particular log request.

     @param event the event to log.  
*/
  public void callAppenders(LoggingEvent event) {
    int writes = 0;

    for(Category c = this; c != null; c=c.parent) {
      // Protected against simultaneous call to addAppender, removeAppender,...
      synchronized(c) {
	if(c.aai != null) {
	  writes += c.aai.appendLoopOnAppenders(event);
	}
	if(!c.additive) {
	  break;
	}
      }
    }

    if(writes == 0) {
      repository.emitNoAppenderWarning(this);
    }
  }

从上面可以看出在该方法中有synchronized同步锁，同步锁会导致线程竞争，那么在大并发情况下将会出现性能问题，同时

会引起线程BLOCKED问题。

可以使用Apache log 解决这个问题，代码如下：

private static final Log log = LogFactory.getLog("xxx");  

通过测试,org.apache.log4j.Category.callAppenders线程BLOCKED问题没有了。

上面只是一个非常简单的示例，现实开发过程中可以根据线程的状态能够找出很多问题。大家不妨尝试一下。

---------------------------------------------------------------------------版权声明------------------------------------------------------------------------------------------

版权声明：本文为博主原创文章，未经博主允许不得转载。博客地址:http://blog.csdn.net/mr_smile2014

使用jdk的jps、jstack工具检测代码问题，提高程序性能

标签：util   entry   执行   argument   could   mil   tar   cte   top   

原文地址：http://blog.csdn.net/mr_smile2014/article/details/52669066