- tags:JVM
- categories:笔记
- date: 2017-02-28 13:15:29
JDK其实自带的有挺多工具可以进行对程序的相关运行JVM堆栈监控与查询。这次把自己使用JDK自带工具对程序堆栈分析过程列出来，以备自己复习和思考。我一直认为万物基于基础。把底层构造设计好，掌握好了。任凭风摧雨打，都能屹立不倒，JDK也是一样，其实官方自己设计集成了不少有用的东西。很多东西不是没有用武之地，是我们还没有遇到问题，也就没有机会使用它。所以，在有空闲时间或者想更深入了解某一领域的知识，自己可以不断拓宽自己的思维领域，脱离舒适安全区,不断学习与实践。
当我们使用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.
打开浏览器查看如下图:
好了，这个小实践就算分析完了，至于里面还有很多东西，需要自己不断实践，加深理解了。未来路还很长啊...
至于还有一些其他的信息补充：
JDK1.7后，有jcmd多功能工具命令，导出堆栈信息，查看java进程，导出线程信息，执行GC。有需要可以自己去看看jcmd的应用吧。
（PS:这篇是在上班时间写的，好像偷懒了啊哈哈....）
