JDK自帶工具堆棧分析實(shí)踐


  • tags:JVM
  • categories:筆記
  • date: 2017-02-28 13:15:29

JDK其實(shí)自帶的有挺多工具可以進(jìn)行對(duì)程序的相關(guān)運(yùn)行JVM堆棧監(jiān)控與查詢。這次把自己使用JDK自帶工具對(duì)程序堆棧分析過(guò)程列出來(lái),以備自己復(fù)習(xí)和思考。我一直認(rèn)為萬(wàn)物基于基礎(chǔ)。把底層構(gòu)造設(shè)計(jì)好,掌握好了。任憑風(fēng)摧雨打,都能屹立不倒,JDK也是一樣,其實(shí)官方自己設(shè)計(jì)集成了不少有用的東西。很多東西不是沒(méi)有用武之地,是我們還沒(méi)有遇到問(wèn)題,也就沒(méi)有機(jī)會(huì)使用它。所以,在有空閑時(shí)間或者想更深入了解某一領(lǐng)域的知識(shí),自己可以不斷拓寬自己的思維領(lǐng)域,脫離舒適安全區(qū),不斷學(xué)習(xí)與實(shí)踐。

JVM.jpg

當(dāng)我們使用IDE或者其他基于cmd/linux中java命令來(lái)運(yùn)行程序時(shí)候,系統(tǒng)本地都會(huì)創(chuàng)建相關(guān)JVM運(yùn)行對(duì)應(yīng)的進(jìn)程資源。而在JVM管理的內(nèi)部,又是有很多java線程在運(yùn)行與處理。最主要的一個(gè)線程,那當(dāng)就是我們經(jīng)常看到的main(String[] args)方法入口對(duì)應(yīng)的線程啦。所以,開(kāi)始對(duì)以正常運(yùn)行的本地javaJVM進(jìn)程進(jìn)行實(shí)踐玩玩,look,look。(哎,當(dāng)然,自己也是一個(gè)菜鳥(niǎo)級(jí)別的碼農(nóng),手握著這本人人都能修煉入門(mén)的Java心經(jīng),想要練成絕頂神功還有很長(zhǎng)的路要走啊.....( ̄ε  ̄))

該次實(shí)踐背景是:在當(dāng)前運(yùn)行的java應(yīng)用中,有一個(gè)線程,進(jìn)行了大量的IO操作。我的目的就是:通過(guò)jdk自帶工具,把該線程找出來(lái),定位為指定的應(yīng)用中的代碼塊。例子參考了《JVM實(shí)踐..》。
來(lái)來(lái),看看運(yùn)行的代碼:

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();
}
}

查看當(dāng)前JVM中運(yùn)行進(jìn)程

Jdk安裝目錄中bin路徑下的jps命令。它的定義是:(百度百科中的,汗...)
jps位于jdk的bin目錄下,其作用是顯示當(dāng)前系統(tǒng)的java進(jìn)程情況,及其id號(hào)。jps相當(dāng)于Solaris進(jìn)程工具ps。不象"pgrep java"或"ps -ef grep java",jps并不使用應(yīng)用程序名來(lái)查找JVM實(shí)例。因此,它查找所有的Java應(yīng)用程序,包括即使沒(méi)有使用java執(zhí)行體的那種(例如,定制的啟動(dòng) 器)。另外,jps僅查找當(dāng)前用戶的Java進(jìn)程,而不是當(dāng)前系統(tǒng)中的所有進(jìn)程。
具體實(shí)際操作如下:(前提是本地系統(tǒng)中JVM已經(jīng)啟動(dòng)啦,其實(shí)只要涉及到j(luò)ava*.exe運(yùn)行了就會(huì)查到信息)

[root@hadoop201 Desktop]# jps  (查看當(dāng)前用戶java相關(guān)所有進(jìn)程號(hào))
3204 Jps
3177 HoldIOMain

可以看到,當(dāng)前用戶系統(tǒng)中正在運(yùn)行的java進(jìn)程號(hào)id為3177。只要拿到進(jìn)程號(hào),后面的命令都可以基于進(jìn)程號(hào)對(duì)進(jìn)程處理中的各種資源都可以查詢。進(jìn)程是計(jì)算機(jī)進(jìn)行資源調(diào)度的最小單位嘛??梢圆榭矗到y(tǒng)態(tài)和用戶態(tài)之間如何切換的,資源是如何處理的等等,進(jìn)程這個(gè)真是各個(gè)很重要的概念。(不行,要去補(bǔ)補(bǔ)操作系統(tǒng)才行。。┑( ̄▽  ̄)┍)

根據(jù)進(jìn)程號(hào)查看進(jìn)程信息

在第一步中,我們通過(guò)jps可以找到名字為HoldIOMain的進(jìn)程號(hào)為3177,之后,我們可以通過(guò)pidstat -p 3177 -d -t 1 3(linux) 命令查看在當(dāng)前系統(tǒng)中,該進(jìn)程的一些基本情況。關(guān)于pidstat命令具體使用,可以參考這片文章:這里
好了,看我如何進(jìn)行操作的:

[root@hadoop201 Desktop]# pidstat -p 3177 -d -t 1 3  (通過(guò)pidstat 命令查看所有線程IO讀寫(xiě)情況)
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   //看這里,進(jìn)行了大量的磁盤(pán)讀寫(xiě)操作

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  //可以進(jìn)行磁盤(pán)大量讀寫(xiě)的進(jìn)行id號(hào)。注意是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
....

在上面,我們通過(guò)linux的pidstat命令查看到了,對(duì)系統(tǒng)磁盤(pán)進(jìn)行大量讀寫(xiě)的進(jìn)程的進(jìn)程號(hào)為3187。下面,我們就可以通過(guò)jdk的jstack命令繼續(xù)操作。

jstack分析執(zhí)行線程

在上一步,我們查到了,有問(wèn)題的對(duì)磁盤(pán)進(jìn)行大量讀寫(xiě)的進(jìn)程號(hào)為3187,十六進(jìn)制為:C73.然后我們可以通過(guò)jdk自帶的jstack命令對(duì)線程進(jìn)行分析。
jstack也是位于jdk%JAVA_HOME%/bin或者($JAVA_HOME/bin)。對(duì)它的定義是:
jstack用于生成java虛擬機(jī)當(dāng)前時(shí)刻的線程快照。線程快照是當(dāng)前java虛擬機(jī)內(nèi)每一條線程正在執(zhí)行的方法堆棧的集合,生成線程快照的主要目的是定位線程出現(xiàn)長(zhǎng)時(shí)間停頓的原因,如線程間死鎖、死循環(huán)、請(qǐng)求外部資源導(dǎo)致的長(zhǎng)時(shí)間等待等。 線程出現(xiàn)停頓的時(shí)候通過(guò)jstack來(lái)查看各個(gè)線程的調(diào)用堆棧,就可以知道沒(méi)有響應(yīng)的線程到底在后臺(tái)做什么事情,或者等待什么資源。 百度詳情點(diǎn)擊jstack

然后我進(jìn)行過(guò)了以下操作:

[root@hadoop201 Desktop]#jstack 3187  (可知有問(wèn)題線程號(hào)為nid=3187 轉(zhuǎn)化為16進(jìn)制為: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.

注意注意:當(dāng)我們查看3187線程快照內(nèi)容的時(shí)候,我們可以看到一共有四個(gè)線程,也就是"Thread-0" ~ "Thread-4"。我們之前也知道進(jìn)行大量讀寫(xiě)操作線程id號(hào)為3187,對(duì)應(yīng)成十六進(jìn)制就是C73,這時(shí)候,我們可以看到,那四條線程中,確實(shí)有一條線程的nid=c73。("Thread-0" prio=10 tid=0x00007f7bc00a0800 nid=0xc73),詳情可以看看上面的信息。

我們可以定位這條thread-0線程,發(fā)現(xiàn)該線程確實(shí)是在流打開(kāi)的狀態(tài)下,不斷的進(jìn)行讀寫(xiě)操作。我們還找到了該線程的名字,具體的類(lèi):HoldIOMain$HoldIOTask.run(HoldIOMain.java:10),TM的就可以下定論了,在HoldIOMain類(lèi)中的內(nèi)部HoldIOTask線程的第十行有問(wèn)題啊。ㄟ(▔▽▔ㄟ) (╯▔▽▔)╯.....

jmap轉(zhuǎn)儲(chǔ)線程堆信息

在上面我們進(jìn)行了棧的分析,下面來(lái)看看跟應(yīng)用內(nèi)存對(duì)象密不可分的堆部分信息。
jmap也是與jstack位于相同目錄中。jmap的百度定義為Jmap命令用于生成堆轉(zhuǎn)儲(chǔ)快照,有時(shí)候也成為heapdump或者dump文件。 Jmap不僅僅可以獲取dump文件,還可以查詢finalize執(zhí)行隊(duì)列,Java堆和永久代的詳細(xì)信息,如空間使用率、當(dāng)時(shí)用的是那種收集器等。,詳情這里:jmap
簡(jiǎn)單使用命令:jmap -dump:format=b,file=location pid (PID為主線程的id)
可以轉(zhuǎn)儲(chǔ)出當(dāng)前線程中所有類(lèi)對(duì)象信息到以.hprof結(jié)尾的文件中。該文件可以使用jhat,也可以使用Visual VM等工具打開(kāi)。

我進(jìn)行操作:

[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.

打開(kāi)瀏覽器查看如下圖:


jmap_heap.png

好了,這個(gè)小實(shí)踐就算分析完了,至于里面還有很多東西,需要自己不斷實(shí)踐,加深理解了。未來(lái)路還很長(zhǎng)啊...


至于還有一些其他的信息補(bǔ)充:
JDK1.7后,有jcmd多功能工具命令,導(dǎo)出堆棧信息,查看java進(jìn)程,導(dǎo)出線程信息,執(zhí)行GC。有需要可以自己去看看jcmd的應(yīng)用吧。

(PS:這篇是在上班時(shí)間寫(xiě)的,好像偷懶了啊哈哈....)

?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請(qǐng)聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成,瀏覽時(shí)請(qǐng)結(jié)合常識(shí)與多方信息審慎甄別。
平臺(tái)聲明:文章內(nèi)容(如有圖片或視頻亦包括在內(nèi))由作者上傳并發(fā)布,文章內(nèi)容僅代表作者本人觀點(diǎn),簡(jiǎn)書(shū)系信息發(fā)布平臺(tái),僅提供信息存儲(chǔ)服務(wù)。

相關(guān)閱讀更多精彩內(nèi)容

友情鏈接更多精彩內(nèi)容