JDK自带工具堆栈分析实践

96
行径行
2017.11.19 10:46 字数 1938

  • tags:JVM
  • categories:笔记
  • date: 2017-02-28 13:15:29

JDK其实自带的有挺多工具可以进行对程序的相关运行JVM堆栈监控与查询。这次把自己使用JDK自带工具对程序堆栈分析过程列出来,以备自己复习和思考。我一直认为万物基于基础。把底层构造设计好,掌握好了。任凭风摧雨打,都能屹立不倒,JDK也是一样,其实官方自己设计集成了不少有用的东西。很多东西不是没有用武之地,是我们还没有遇到问题,也就没有机会使用它。所以,在有空闲时间或者想更深入了解某一领域的知识,自己可以不断拓宽自己的思维领域,脱离舒适安全区,不断学习与实践。

JVM.jpg

当我们使用IDE或者其他基于cmd/linux中java命令来运行程序时候,系统本地都会创建相关JVM运行对应的进程资源。而在JVM管理的内部,又是有很多java线程在运行与处理。最主要的一个线程,那当就是我们经常看到的main(String[] args)方法入口对应的线程啦。所以,开始对以正常运行的本地javaJVM进程进行实践玩玩,look,look。(哎,当然,自己也是一个菜鸟级别的码农,手握着这本人人都能修炼入门的Java心经,想要练成绝顶神功还有很长的路要走啊.....( ̄ε  ̄))

该次实践背景是:在当前运行的java应用中,有一个线程,进行了大量的IO操作。我的目的就是:通过jdk自带工具,把该线程找出来,定位为指定的应用中的代码块。例子参考了《JVM实践..》。
来来,看看运行的代码:

public class HoldIOMain{
 public static class HoldIOTask implements Runnable{
   @Override
   public void run(){
    while(true){
     try{
    FileOutputStream fos = new FileOutputStream(new File("temp"));
    for(int i=0;i<10000;i++){
     fos.write(i);
     fos.close();
     FileInputStream fis = new FileInputStream(new File("temp"));
     while(fis.read()!=-1); //a log of read operations.
    }
   }catch(Exception e){
   }
 }
}
}
 public static class LazyTask implements Runnable{
  public void run(){
   try{
        while(true){
          Thread.sleep(1000);
    }
   }catch(Exception e){}
  }

}
 public static void main(String[] args){    //四线程操作
  new Thread(new HoldIOTask()).start(); 
  new Thread(new LazyTask()).start();
  new Thread(new LazyTask()).start();
  new Thread(new LazyTask()).start();
}
}

查看当前JVM中运行进程

Jdk安装目录中bin路径下的jps命令。它的定义是:(百度百科中的,汗...)
jps位于jdk的bin目录下,其作用是显示当前系统的java进程情况,及其id号。jps相当于Solaris进程工具ps。不象"pgrep java"或"ps -ef grep java",jps并不使用应用程序名来查找JVM实例。因此,它查找所有的Java应用程序,包括即使没有使用java执行体的那种(例如,定制的启动 器)。另外,jps仅查找当前用户的Java进程,而不是当前系统中的所有进程。
具体实际操作如下:(前提是本地系统中JVM已经启动啦,其实只要涉及到java*.exe运行了就会查到信息)

[root@hadoop201 Desktop]# jps  (查看当前用户java相关所有进程号)
3204 Jps
3177 HoldIOMain

可以看到,当前用户系统中正在运行的java进程号id为3177。只要拿到进程号,后面的命令都可以基于进程号对进程处理中的各种资源都可以查询。进程是计算机进行资源调度的最小单位嘛。可以查看,系统态和用户态之间如何切换的,资源是如何处理的等等,进程这个真是各个很重要的概念。(不行,要去补补操作系统才行。。┑( ̄▽  ̄)┍)

根据进程号查看进程信息

在第一步中,我们通过jps可以找到名字为HoldIOMain的进程号为3177,之后,我们可以通过pidstat -p 3177 -d -t 1 3(linux) 命令查看在当前系统中,该进程的一些基本情况。关于pidstat命令具体使用,可以参考这片文章:这里
好了,看我如何进行操作的:

[root@hadoop201 Desktop]# pidstat -p 3177 -d -t 1 3  (通过pidstat 命令查看所有线程IO读写情况)
Linux 2.6.32-504.el6.x86_64 (hadoop201) 01/11/2017 _x86_64_(1 CPU)
04:42:44 PM      TGID       TID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
04:42:45 PM      3177         -      0.00  36792.00  18396.00  java
04:42:45 PM         -      3177      0.00      0.00      0.00  |__java
04:42:45 PM         -      3178      0.00      0.00      0.00  |__java
04:42:45 PM         -      3179      0.00      0.00      0.00  |__java
04:42:45 PM         -      3180      0.00      0.00      0.00  |__java
04:42:45 PM         -      3181      0.00      0.00      0.00  |__java
04:42:45 PM         -      3182      0.00      0.00      0.00  |__java
04:42:45 PM         -      3183      0.00      0.00      0.00  |__java
04:42:45 PM         -      3184      0.00      0.00      0.00  |__java
04:42:45 PM         -      3185      0.00      0.00      0.00  |__java
04:42:45 PM         -      3186      0.00      0.00      0.00  |__java

04:42:45 PM         -      3187      0.00  36792.00  18396.00  |__java   //看这里,进行了大量的磁盘读写操作

04:42:45 PM         -      3188      0.00      0.00      0.00  |__java
04:42:45 PM         -      3189      0.00      0.00      0.00  |__java
04:42:45 PM         -      3190      0.00      0.00      0.00  |__java

04:42:45 PM      TGID       TID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
04:42:46 PM      3177         -      0.00  37464.00  18732.00  java
04:42:46 PM         -      3177      0.00      0.00      0.00  |__java
04:42:46 PM         -      3178      0.00      0.00      0.00  |__java
04:42:46 PM         -      3179      0.00      0.00      0.00  |__java
04:42:46 PM         -      3180      0.00      0.00      0.00  |__java
04:42:46 PM         -      3181      0.00      0.00      0.00  |__java
04:42:46 PM         -      3182      0.00      0.00      0.00  |__java
04:42:46 PM         -      3183      0.00      0.00      0.00  |__java
04:42:46 PM         -      3184      0.00      0.00      0.00  |__java
04:42:46 PM         -      3185      0.00      0.00      0.00  |__java
04:42:46 PM         -      3186      0.00      0.00      0.00  |__java
04:42:46 PM         -      3187      0.00  37464.00  18732.00  |__java  //可以进行磁盘大量读写的进行id号。注意是3187
04:42:46 PM         -      3188      0.00      0.00      0.00  |__java
04:42:46 PM         -      3189      0.00      0.00      0.00  |__java
04:42:46 PM         -      3190      0.00      0.00      0.00  |__java

04:42:46 PM      TGID       TID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
04:42:47 PM      3177         -      0.00  37800.00  18900.00  java
04:42:47 PM         -      3177      0.00      0.00      0.00  |__java
04:42:47 PM         -      3178      0.00      0.00      0.00  |__java
04:42:47 PM         -      3179      0.00      0.00      0.00  |__java
04:42:47 PM         -      3180      0.00      0.00      0.00  |__java
04:42:47 PM         -      3181      0.00      0.00      0.00  |__java
04:42:47 PM         -      3182      0.00      0.00      0.00  |__java
04:42:47 PM         -      3183      0.00      0.00      0.00  |__java
04:42:47 PM         -      3184      0.00      0.00      0.00  |__java
04:42:47 PM         -      3185      0.00      0.00      0.00  |__java
04:42:47 PM         -      3186      0.00      0.00      0.00  |__java
04:42:47 PM         -      3187      0.00  37800.00  18900.00  |__java
04:42:47 PM         -      3188      0.00      0.00      0.00  |__java
04:42:47 PM         -      3189      0.00      0.00      0.00  |__java
04:42:47 PM         -      3190      0.00      0.00      0.00  |__java
....

在上面,我们通过linux的pidstat命令查看到了,对系统磁盘进行大量读写的进程的进程号为3187。下面,我们就可以通过jdk的jstack命令继续操作。

jstack分析执行线程

在上一步,我们查到了,有问题的对磁盘进行大量读写的进程号为3187,十六进制为:C73.然后我们可以通过jdk自带的jstack命令对线程进行分析。
jstack也是位于jdk%JAVA_HOME%/bin或者($JAVA_HOME/bin)。对它的定义是:
jstack用于生成java虚拟机当前时刻的线程快照。线程快照是当前java虚拟机内每一条线程正在执行的方法堆栈的集合,生成线程快照的主要目的是定位线程出现长时间停顿的原因,如线程间死锁、死循环、请求外部资源导致的长时间等待等。 线程出现停顿的时候通过jstack来查看各个线程的调用堆栈,就可以知道没有响应的线程到底在后台做什么事情,或者等待什么资源。 百度详情点击jstack

然后我进行过了以下操作:

[root@hadoop201 Desktop]#jstack 3187  (可知有问题线程号为nid=3187 转化为16进制为:C73)

"Thread-3" prio=10 tid=0x00007f7bc00a6800 nid=0xc76 waiting on condition [0x00007f7baa16d000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at HoldIOMain$LazyTask.run(HoldIOMain.java:26)
    at java.lang.Thread.run(Thread.java:662)

"Thread-2" prio=10 tid=0x00007f7bc00a4800 nid=0xc75 waiting on condition [0x00007f7bbc15c000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at HoldIOMain$LazyTask.run(HoldIOMain.java:26)
    at java.lang.Thread.run(Thread.java:662)

"Thread-1" prio=10 tid=0x00007f7bc00a2800 nid=0xc74 waiting on condition [0x00007f7bbc25d000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at HoldIOMain$LazyTask.run(HoldIOMain.java:26)
    at java.lang.Thread.run(Thread.java:662)

"Thread-0" prio=10 tid=0x00007f7bc00a0800 nid=0xc73 runnable [0x00007f7bbc35e000]
   java.lang.Thread.State: RUNNABLE
    at java.io.FileOutputStream.open(Native Method)
    at java.io.FileOutputStream.<init>(FileOutputStream.java:194)
    at java.io.FileOutputStream.<init>(FileOutputStream.java:145)
    at HoldIOMain$HoldIOTask.run(HoldIOMain.java:10)
    at java.lang.Thread.run(Thread.java:662)

"Low Memory Detector" daemon prio=10 tid=0x00007f7bc0087000 nid=0xc71 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=10 tid=0x00007f7bc0084800 nid=0xc70 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=10 tid=0x00007f7bc0082800 nid=0xc6f waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x00007f7bc0080800 nid=0xc6e waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x00007f7bc0064000 nid=0xc6d in Object.wait() [0x00007f7bbc964000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000f0a00580> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
    - locked <0x00000000f0a00580> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:171)

"Reference Handler" daemon prio=10 tid=0x00007f7bc0062000 nid=0xc6c in Object.wait() [0x00007f7bbca65000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000f0a00310> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:485)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
    - locked <0x00000000f0a00310> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x00007f7bc005b800 nid=0xc6b runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007f7bc0092000 nid=0xc72 waiting on condition 

JNI global references: 988

Heap
 def new generation   total 4800K, used 4800K [0x00000000eb800000, 0x00000000ebd30000, 0x00000000f0a00000)
  eden space 4288K, 100% used [0x00000000eb800000, 0x00000000ebc30000, 0x00000000ebc30000)
  from space 512K, 100% used [0x00000000ebc30000, 0x00000000ebcb0000, 0x00000000ebcb0000)
  to   space 512K,   0% used [0x00000000ebcb0000, 0x00000000ebcb0000, 0x00000000ebd30000)
 tenured generation   total 10496K, used 6239K [0x00000000f0a00000, 0x00000000f1440000, 0x00000000fae00000)
   the space 10496K,  59% used [0x00000000f0a00000, 0x00000000f1017c38, 0x00000000f1017e00, 0x00000000f1440000)
 compacting perm gen  total 21248K, used 2646K [0x00000000fae00000, 0x00000000fc2c0000, 0x0000000100000000)
   the space 21248K,  12% used [0x00000000fae00000, 0x00000000fb095860, 0x00000000fb095a00, 0x00000000fc2c0000)
No shared spaces configured.

注意注意:当我们查看3187线程快照内容的时候,我们可以看到一共有四个线程,也就是"Thread-0" ~ "Thread-4"。我们之前也知道进行大量读写操作线程id号为3187,对应成十六进制就是C73,这时候,我们可以看到,那四条线程中,确实有一条线程的nid=c73。("Thread-0" prio=10 tid=0x00007f7bc00a0800 nid=0xc73),详情可以看看上面的信息。

我们可以定位这条thread-0线程,发现该线程确实是在流打开的状态下,不断的进行读写操作。我们还找到了该线程的名字,具体的类:HoldIOMain$HoldIOTask.run(HoldIOMain.java:10),TM的就可以下定论了,在HoldIOMain类中的内部HoldIOTask线程的第十行有问题啊。ㄟ(▔▽▔ㄟ) (╯▔▽▔)╯.....

jmap转储线程堆信息

在上面我们进行了栈的分析,下面来看看跟应用内存对象密不可分的堆部分信息。
jmap也是与jstack位于相同目录中。jmap的百度定义为Jmap命令用于生成堆转储快照,有时候也成为heapdump或者dump文件。 Jmap不仅仅可以获取dump文件,还可以查询finalize执行队列,Java堆和永久代的详细信息,如空间使用率、当时用的是那种收集器等。,详情这里:jmap
简单使用命令:jmap -dump:format=b,file=location pid (PID为主线程的id)
可以转储出当前线程中所有类对象信息到以.hprof结尾的文件中。该文件可以使用jhat,也可以使用Visual VM等工具打开。

我进行操作:

[root@hadoop201 tmp]# jhat heap.hprof 
Reading from heap.hprof...
Dump file created Wed Jan 11 16:44:13 CST 2017
Snapshot read, resolving...
Resolving 583585 objects...
Chasing references, expect 116 dots....................................................................................................................
Eliminating duplicate references....................................................................................................................
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.

打开浏览器查看如下图:


jmap_heap.png

好了,这个小实践就算分析完了,至于里面还有很多东西,需要自己不断实践,加深理解了。未来路还很长啊...


至于还有一些其他的信息补充:
JDK1.7后,有jcmd多功能工具命令,导出堆栈信息,查看java进程,导出线程信息,执行GC。有需要可以自己去看看jcmd的应用吧。

(PS:这篇是在上班时间写的,好像偷懒了啊哈哈....)

JVM
Web note ad 1