想要了解更多，加QQ群72132378

JDK本身提供了很多方便的JVM效能調優監控工具，除了整合式的VisualVM和jConsole外，還有jps、jstack、jmap、jhat、jstat等小巧的工具，本部落格希望能起拋磚引玉之用，讓大家能開始對JVM效能調優的常用工具有所瞭解。

    現實企業級Java開發中，有時候我們會碰到下面這些問題：

• OutOfMemoryError，記憶體不足

• 記憶體洩露

• 執行緒死鎖

• 鎖爭用（Lock Contention）

• Java程序消耗CPU過高

• ......

    這些問題在日常開發中可能被很多人忽視（比如有的人遇到上面的問題只是重啟伺服器或者調大記憶體，而不會深究問題根源），但能夠理解並解決這些問題是Java程式設計師進階的必備要求。本文將對一些常用的JVM效能調優監控工具進行介紹，希望能起拋磚引玉之用。本文參考了網上很多資料，難以一一列舉，在此對這些資料的作者表示感謝！關於JVM效能調優相關的資料，請參考文末。

A、 jps(Java Virtual Machine Process Status Tool)      

    jps主要用來輸出JVM中執行的程序狀態資訊。語法格式如下：

1	jps [options] [hostid]

    如果不指定hostid就預設為當前主機或伺服器。

    命令列引數選項說明如下：

1	-q 不輸出類名、Jar名和傳入main方法的引數

2	-m 輸出傳入main方法的引數

3	-l 輸出main類或Jar的全限名

4	-v 輸出傳入JVM的引數

   比如下面：

1	[email protected] :/# jps -m -l

2	2458 org.artifactory.standalone.main.Main /usr/local/artifactory-2.2.5/etc/jetty.xml

3	29920 com.sun.tools.hat.Main -port 9998 /tmp/dump.dat

4	3149 org.apache.catalina.startup.Bootstrap start

5	30972 sun.tools.jps.Jps -m -l

6	8247 org.apache.catalina.startup.Bootstrap start

7	25687 com.sun.tools.hat.Main -port 9999 dump.dat

8	21711 mrf-center.jar

B、 jstack

    jstack主要用來檢視某個Java程序內的執行緒堆疊資訊。語法格式如下：

1	jstack [option] pid

2	jstack [option] executable core

3	jstack [option] [server-id@]remote-hostname-or-ip

    命令列引數選項說明如下：

1	-l long listings，會打印出額外的鎖資訊，在發生死鎖時可以用jstack -l pid來觀察鎖持有情況

2	-m mixed mode，不僅會輸出Java堆疊資訊，還會輸出C/C++堆疊資訊（比如Native方法）

    jstack可以定位到執行緒堆疊，根據堆疊資訊我們可以定位到具體程式碼，所以它在JVM效能調優中使用得非常多。下面我們來一個例項找出某個Java程序中最耗費CPU的Java執行緒並定位堆疊資訊，用到的命令有ps、top、printf、jstack、grep。

    第一步先找出Java程序ID，我部署在伺服器上的Java應用名稱為mrf-center：

1	[email protected]:/# ps -ef | grep mrf-center | grep -v grep

2	root     21711     1  1 14:47 pts/3    00:02:10 java -jar mrf-center.jar

    得到程序ID為21711，第二步找出該程序內最耗費CPU的執行緒，可以使用ps -Lfp pid或者ps -mp pid -o THREAD, tid, time或者top -Hp pid，我這裡用第三個，輸出如下：

    TIME列就是各個Java執行緒耗費的CPU時間，CPU時間最長的是執行緒ID為21742的執行緒，用

1	printf "%x\n" 21742

    得到21742的十六進位制值為54ee，下面會用到。    

    OK，下一步終於輪到jstack上場了，它用來輸出程序21711的堆疊資訊，然後根據執行緒ID的十六進位制值grep，如下：

1	[email protected]:/# jstack 21711 | grep 54ee

2	"PollIntervalRetrySchedulerThread" prio=10 tid=0x00007f950043e000 nid=0x54ee in Object.wait() [0x00007f94c6eda000]

    可以看到CPU消耗在PollIntervalRetrySchedulerThread這個類的Object.wait()，我找了下我的程式碼，定位到下面的程式碼：

01	// Idle wait

02	getLog().info("Thread [" + getName() + "] is idle waiting...");

03	schedulerThreadState = PollTaskSchedulerThreadState.IdleWaiting;

04	long now = System.currentTimeMillis();

05	long waitTime = now + getIdleWaitTime();

06	long timeUntilContinue = waitTime - now;

07	synchronized(sigLock) {

08

try {

09	if(!halted.get()) {

10	sigLock.wait(timeUntilContinue);

11

}

12

}

13	catch (InterruptedException ignore) {

14

}

15

}

    它是輪詢任務的空閒等待程式碼，上面的sigLock.wait(timeUntilContinue)就對應了前面的Object.wait()。

C、 jmap（Memory Map）和jhat（Java Heap Analysis Tool）

    jmap用來檢視堆記憶體使用狀況，一般結合jhat使用。

    jmap語法格式如下：

1	jmap [option] pid

2	jmap [option] executable core

3	jmap [option] [server-id@]remote-hostname-or-ip

    如果執行在64位JVM上，可能需要指定-J-d64命令選項引數。

1	jmap -permstat pid

    列印程序的類載入器和類載入器載入的持久代物件資訊，輸出：類載入器名稱、物件是否存活（不可靠）、物件地址、父類載入器、已載入的類大小等資訊，如下圖：

   使用jmap -heap pid檢視程序堆記憶體使用情況，包括使用的GC演算法、堆配置引數和各代中堆記憶體使用情況。比如下面的例子：

01	[email protected]:/# jmap -heap 21711

02	Attaching to process ID 21711, please wait...

03	Debugger attached successfully.

04	Server compiler detected.

05	JVM version is 20.10-b01

06

07	using thread-local object allocation.

08	Parallel GC with 4 thread(s)

09

10	Heap Configuration:

11	MinHeapFreeRatio = 40

12	MaxHeapFreeRatio = 70

13	MaxHeapSize      = 2067791872 (1972.0MB)

14	NewSize          = 1310720 (1.25MB)

15	MaxNewSize       = 17592186044415 MB

16	OldSize          = 5439488 (5.1875MB)

17	NewRatio         = 2

18	SurvivorRatio    = 8

19	PermSize         = 21757952 (20.75MB)

20	MaxPermSize      = 85983232 (82.0MB)

21

22	Heap Usage:

23	PS Young Generation

24	Eden Space:

25	capacity = 6422528 (6.125MB)

26	used     = 5445552 (5.1932830810546875MB)

27	free     = 976976 (0.9317169189453125MB)

28	84.78829520089286% used

29	From Space:

30	capacity = 131072 (0.125MB)

31	used     = 98304 (0.09375MB)

32	free     = 32768 (0.03125MB)

33	75.0% used

34

To Space:

35	capacity = 131072 (0.125MB)

36	used     = 0 (0.0MB)

37	free     = 131072 (0.125MB)

38

0.0% used

39	PS Old Generation

40	capacity = 35258368 (33.625MB)

41	used     = 4119544 (3.9287033081054688MB)

42	free     = 31138824 (29.69629669189453MB)

43	11.683876009235595% used

44	PS Perm Generation

45	capacity = 52428800 (50.0MB)

46	used     = 26075168 (24.867218017578125MB)

47	free     = 26353632 (25.132781982421875MB)

48	49.73443603515625% used

49

....

    使用jmap -histo[:live] pid檢視堆記憶體中的物件數目、大小統計直方圖，如果帶上live則只統計活物件，如下：

01	[email protected]:/# jmap -histo:live 21711 | more

02

03	num     #instances         #bytes  class name

04	----------------------------------------------

05	1:         38445        5597736  <constMethodKlass>

06	2:         38445        5237288  <methodKlass>

07	3:          3500        3749504  <constantPoolKlass>

08	4:         60858        3242600  <symbolKlass>

09	5:          3500        2715264  <instanceKlassKlass>

10	6:          2796        2131424  <constantPoolCacheKlass>

11	7:          5543        1317400  [I

12	8:         13714        1010768  [C

13	9:          4752        1003344  [B

14	10:          1225         639656  <methodDataKlass>

15	11:         14194         454208  java.lang.String

16	12:          3809         396136  java.lang.Class

17	13:          4979         311952  [S

18	14:          5598         287064  [[I

19	15:          3028         266464  java.lang.reflect.Method

20	16:           280         163520  <objArrayKlassKlass>

21	17:          4355         139360  java.util.HashMap$Entry

22	18:          1869         138568  [Ljava.util.HashMap$Entry;

23	19:          2443          97720  java.util.LinkedHashMap$Entry

24	20:          2072          82880  java.lang.ref.SoftReference

25	21:          1807          71528  [Ljava.lang.Object;

26	22:          2206          70592  java.lang.ref.WeakReference

27	23:           934          52304  java.util.LinkedHashMap

28	24:           871          48776  java.beans.MethodDescriptor

29	25:          1442          46144  java.util.concurrent.ConcurrentHashMap$HashEntry

30	26:           804          38592  java.util.HashMap

31	27:           948          37920  java.util.concurrent.ConcurrentHashMap$Segment

32	28:          1621          35696  [Ljava.lang.Class;

33	29:          1313          34880  [Ljava.lang.String;

34	30:          1396          33504  java.util.LinkedList$Entry

35	31:           462          33264  java.lang.reflect.Field

36	32:          1024          32768  java.util.Hashtable$Entry

37	33:           948          31440  [Ljava.util.concurrent.ConcurrentHashMap$HashEntry;

    class name是物件型別，說明如下：

1

B  byte

2

C  char

3

D  double

4

F  float

5

I  int

6

J  long

7	Z  boolean

8	[  陣列，如[I表示int[]

9	[L+類名 其他物件

    還有一個很常用的情況是：用jmap把程序記憶體使用情況dump到檔案中，再用jhat分析檢視。jmap進行dump命令格式如下：

1	jmap -dump:format=b,file=dumpFileName

    我一樣地對上面程序ID為21711進行Dump：

1	[email protected]:/# jmap -dump:format=b,file=/tmp/dump.dat 21711

2	Dumping heap to /tmp/dump.dat ...

3	Heap dump file created

   dump出來的檔案可以用MAT、VisualVM等工具檢視，這裡用jhat檢視：

01	[email protected]:/# jhat -port 9998 /tmp/dump.dat

02	Reading from /tmp/dump.dat...

03	Dump file created Tue Jan 28 17:46:14 CST 2014

04	Snapshot read, resolving...

05	Resolving 132207 objects...

06	Chasing references, expect 26 dots..........................

07	Eliminating duplicate references..........................

08	Snapshot resolved.

09	Started HTTP server on port 9998

10	Server is ready.

     然後就可以在瀏覽器中輸入主機地址:9998查看了：

    上面紅線框出來的部分大家可以自己去摸索下，最後一項支援OQL（物件查詢語言）。

D、jstat（JVM統計監測工具）

    語法格式如下：

1	jstat [ generalOption | outputOptions vmid [interval[s|ms] [count]] ]

    vmid是虛擬機器ID，在Linux/Unix系統上一般就是程序ID。interval是取樣時間間隔。count是取樣數目。比如下面輸出的是GC資訊，取樣時間間隔為250ms，取樣數為4：

1	[email protected]:/# jstat -gc 21711 250 4

2	S0C    S1C    S0U    S1U      EC       EU        OC         OU       PC     PU    YGC     YGCT    FGC    FGCT     GCT

3	192.0  192.0   64.0   0.0    6144.0   1854.9   32000.0     4111.6   55296.0 25472.7    702    0.431   3      0.218    0.649

4	192.0  192.0   64.0   0.0    6144.0   1972.2   32000.0     4111.6   55296.0 25472.7    702    0.431   3      0.218    0.649

5	192.0  192.0   64.0   0.0    6144.0   1972.2   32000.0     4111.6   55296.0 25472.7    702    0.431   3      0.218    0.649

6	192.0  192.0   64.0   0.0    6144.0   2109.7   32000.0     4111.6   55296.0 25472.7    702    0.431   3      0.218    0.649

    要明白上面各列的意義，先看JVM堆記憶體佈局：

    可以看出：

1	堆記憶體 = 年輕代 + 年老代 + 永久代

2	年輕代 = Eden區 + 兩個Survivor區（From和To）

    現在來解釋各列含義：

1	S0C、S1C、S0U、S1U：Survivor 0/1區容量（Capacity）和使用量（Used）

2	EC、EU：Eden區容量和使用量

3	OC、OU：年老代容量和使用量

4	PC、PU：永久代容量和使用量

5	YGC、YGT：年輕代GC次數和GC耗時

6	FGC、FGCT：Full GC次數和Full GC耗時

7

GCT：GC總耗時

其他JVM效能調優參考資料：

《Java虛擬機器規範》

《Java Performance》

《Effective Java》

對應引數解釋：

使用 TDA 工具，看到大量 Java Thread State 的第一反應是： 1，執行緒狀態為“waiting for monitor entry”： 意味著它 在等待進入一個臨界區 ，所以它在”Entry Set“佇列中等待。 此時執行緒狀態一般都是 Blocked：

• java.lang.Thread.State: BLOCKED (on object monitor)

2，執行緒狀態為“waiting on condition”： 說明它在等待另一個條件的發生，來把自己喚醒，或者乾脆它是呼叫了 sleep(N)。 此時執行緒狀態大致為以下幾種：

• java.lang.Thread.State: WAITING (parking)：一直等那個條件發生；
• java.lang.Thread.State: TIMED_WAITING (parking或sleeping)：定時的，那個條件不到來，也將定時喚醒自己。

3，如果大量執行緒在“waiting for monitor entry”： 可能是一個全域性鎖阻塞住了大量執行緒。 如果短時間內列印的 thread dump 檔案反映，隨著時間流逝，waiting for monitor entry 的執行緒越來越多，沒有減少的趨勢，可能意味著某些執行緒在臨界區裡呆的時間太長了，以至於越來越多新執行緒遲遲無法進入臨界區。 4，如果大量執行緒在“waiting on condition”： 可能是它們又跑去獲取第三方資源，尤其是第三方網路資源，遲遲獲取不到Response，導致大量執行緒進入等待狀態。 所以如果你發現有大量的執行緒都處在 Wait on condition，從執行緒堆疊看，正等待網路讀寫，這可能是一個網路瓶頸的徵兆，因為網路阻塞導致執行緒無法執行。 執行緒狀態為“in Object.wait()”： 說明它獲得了監視器之後，又呼叫了 java.lang.Object.wait() 方法。 每個 Monitor在某個時刻，只能被一個執行緒擁有，該執行緒就是 “Active Thread”，而其它執行緒都是 “Waiting Thread”，分別在兩個佇列 “ Entry Set”和 “Wait Set”裡面等候。在 “Entry Set”中等待的執行緒狀態是 “Waiting for monitor entry”，而在 “Wait Set”中等待的執行緒狀態是 “in Object.wait()”。 當執行緒獲得了 Monitor，如果發現執行緒繼續執行的條件沒有滿足，它則呼叫物件（一般就是被 synchronized 的物件）的 wait() 方法，放棄了 Monitor，進入 “Wait Set”佇列。 此時執行緒狀態大致為以下幾種：

• java.lang.Thread.State: TIMED_WAITING (on object monitor)；
• java.lang.Thread.State: WAITING (on object monitor)；

一般都是RMI相關執行緒（RMI RenewClean、 GC Daemon、RMI Reaper），GC執行緒（Finalizer），引用物件垃圾回收執行緒（Reference Handler）等系統執行緒處於這種狀態。 圖1 A Java Monitor 示範一： 下面這個執行緒在等待這個鎖 0x00000000fe7e3b50，等待進入臨界區： "RMI TCP Connection(64896)-172.16.52.118" daemon prio=10 tid=0x00000000405a6000 nid=0x68fe waiting for monitor entry [0x00007f2be65a3000]    java.lang.Thread.State: BLOCKED (on object monitor) at com.xyz.goods.service.impl.GoodsServiceImpl.findChanellGoodsCountWithCache(GoodsServiceImpl.java:1734) - waiting to lock <0x00000000fe7e3b50> (a java.lang.String)
那麼誰持有這個鎖呢？ 是另一個先呼叫了 findChanellGoodsCountWithCache 函式的執行緒： "RMI TCP Connection(64878)-172.16.52.117" daemon prio=10 tid=0x0000000040822000 nid=0x6841 runnable [0x00007f2be76b3000]    java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at java.io.BufferedInputStream.fill(BufferedInputStream.java:218) at java.io.BufferedInputStream.read1(BufferedInputStream.java:258) at java.io.BufferedInputStream.read(BufferedInputStream.java:317) - locked <0x00000000af4ed638> (a java.io.BufferedInputStream) at org.bson.io.Bits.readFully(Bits.java:35) at org.bson.io.Bits.readFully(Bits.java:28) at com.mongodb.Response.<init>(Response.java:35) at com.mongodb.DBPort.go(DBPort.java:110) - locked <0x00000000af442d48> (a com.mongodb.DBPort) at com.mongodb.DBPort.go(DBPort.java:75) - locked <0x00000000af442d48> (a com.mongodb.DBPort) at com.mongodb.DBPort.call(DBPort.java:65) at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:202) at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:296) at com.mongodb.DB.command(DB.java:152) at com.mongodb.DBCollection.getCount(DBCollection.java:760) at com.mongodb.DBCollection.getCount(DBCollection.java:731) at com.mongodb.DBCollection.count(DBCollection.java:697) at com.xyz.goods.manager.MongodbManager.count(MongodbManager.java:202) at com.xyz.goods.service.impl.GoodsServiceImpl.findChanellGoodsCount(GoodsServiceImpl.java:1787) at com.xyz.goods.service.impl.GoodsServiceImpl.findChanellGoodsCountWithCache(GoodsServiceImpl.java:1739) - locked <0x00000000fe7e3b50> (a java.lang.String) 示範二： 等待另一個條件發生來將自己喚醒： "RMI TCP Connection(idle)" daemon prio=10 tid=0x00007fd50834e800 nid=0x56b2 waiting on condition [0x00007fd4f1a59000]    java.lang.Thread.State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for  <0x00000000acd84de8> (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) 1）“TIMED_WAITING (parking)”中的 timed_waiting 指等待狀態，但這裡指定了時間，到達指定的時間後自動退出等待狀態；parking指執行緒處於掛起中。 2）“waiting on condition”需要與堆疊中的“parking to wait for  <0x00000000acd84de8> (a java.util.concurrent.SynchronousQueue$TransferStack)” 結合來看。首先，本執行緒肯定是在等待某個條件的發生，來把自己喚醒。其次，SynchronousQueue 並不是一個佇列，只是執行緒之間移交資訊的機制，當我們把一個元素放入到 SynchronousQueue 中時必須有另一個執行緒正在等待接受移交的任務，因此這就是本執行緒在等待的條件。 示範三： "RMI RenewClean-[172.16.50.182:4888]" daemon prio=10 tid=0x0000000040d2c800 nid=0x97e in Object.wait() [0x00007f9ccafd0000]    java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x0000000799b032d8> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118) - locked <0x0000000799b032d8> (a java.lang.ref.ReferenceQueue$Lock) at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run(DGCClient.java:516) at java.lang.Thread.run(Thread.java:662)