JVM經常使用指標查詢

一.what‘s going on in Java Application

　　當系統卡頓，應用莫名被殺掉，咱們應該怎麼排查？在我已知的系統掛掉的狀況，只經歷過兩種：1.內存申請不了（OOM）；2.CPU佔用太高

　　使用top命令便可以觀察linux的進程信息，以及CPU佔用信息，拿到了進程號就能夠進一步瞭解進程信息。

netstat -apn | grep 35011

　　便可觀察java應用所監聽的端口。

　　若是機子上配置了Java環境，則使用jps命令便可看到Java進程號。

　　一般我最經常使用是

jps -ml

　　可顯示給主函數傳入的參數，並顯示主類的完整包名。

　　能夠查詢啓動Java進程時候jvm的參數，使用

jps -v

　　能夠看到一些收集器的配置（以上是使用CMS），Java堆的內存配置，等等。注意裏面有一個參數，HeapDumpOnOutofMemmoryError，這個參數說明JVM在檢測到內存溢出的時候會輸出一個內存快照，並輸出到後面這個dumpPath中。

　　內存溢出有兩種狀況，一種是到達JVM設置的最大內存，而這個時候並無到達Linux系統內存瓶頸，這個時候應該是不會把Java殺掉（猜想）；另外一種是形成了Linux系統內存申請問題，則Linux會殺掉這個異常進程（Linux Kernel OOM(Out of memory killer)）。

　　若是想從linux層面查看進程，則進入文件夾;Linux的進程是以文件形式記錄的，也就是fd的概念。

/proc/{pid}/status

　　

linux日誌文件說明 (抄過來的)
/var/log/message 系統啓動後的信息和錯誤日誌，是Red Hat Linux中最經常使用的日誌之一
/var/log/secure 安全相關的日誌信息
/var/log/maillog 郵件相關的日誌信息
/var/log/cron 定時任務相關的日誌信息
/var/log/spooler UUCP和news設備相關的日誌信息
/var/log/boot.log 守護進程啓動和中止相關的日誌消息
/var/log/wtmp 該日誌文件永久記錄每一個用戶登陸、註銷及系統的啓動、停機的事件

　　有一次查詢OOM掛掉的應用信息，在阿里雲監控裏內存下來的那個時間點，去查message，看到了Linux的OOM kill的日誌。

二.Memmory or CPU

　　在市面上看到的Java應用，不管是處理什麼業務的，最多見的就是對這兩種資源的支配。計算密集型，考慮空間換時間；文檔型、內存型的，考慮優化業務方法或者考慮多臺機器。根據以上的方法，咱們能夠對Java進程的一些指標進行監控，而咱們若是須要進一步知道卡頓的緣由，則咱們可使用jdk自帶的工具進行查詢。

　　內存這個主題能夠分爲不少場景：堆內存不足（業務需求增加、代碼中申請內存不合理致使頻繁Full GC、一次申請內存超過JVM設置、內存溢出）、常量池內存不足、Linux內存不足、爆棧 等等。可是大多數狀況下，咱們都是能夠預料到的（大多數都是代碼的問題）。若是你有一個業務，會加載大量的文檔，那你確定一開始就知道須要準備可伸縮型架構了（只要加機器就能解決線上問題的架構，也就是便於橫向擴展）。因此，在內存這個主題上，咱們只須要關注一些不是當即發生、在系統運行中逐漸拖垮系統的問題排查，好比，內存溢出。

　　在Java中，內存溢出指的是使用過的而且將來再也不使用的內存沒有被GC正常回收的狀況。舉個例子，你在系統中使用了全局的Map記錄一些業務以及數據對應的關係，而key值是業務產生時候的標誌（每次業務都會不同），value值是每次業務的對應數據；若是在業務完成以後沒有remove，則在系統運行的過程當中，這個Map是會不斷增大的，最終這些無用的內存會致使OOM。（固然，一個正常的程序員是不會這麼寫的）

　　咱們在內存溢出的時候可能作得更加隱祕，因此須要使用jdk的工具幫助咱們發現這些問題。

jmap -histo {pid} | head

　　這個是正常的內存快照，若是是不正常的，則排在前幾的有可能就是你寫的那個數據結構。再經過一些手段定位出是代碼中的哪行。這樣咱們排查內存溢出就會簡單一些了。

[ctk@172 ~]$ jmap -heap 35011
Attaching to process ID 35011, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.181-b13

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 1073741824 (1024.0MB)
   NewSize                  = 87228416 (83.1875MB)
   MaxNewSize               = 87228416 (83.1875MB)
   OldSize                  = 986513408 (940.8125MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 78512128 (74.875MB)
   used     = 39575536 (37.74217224121094MB)
   free     = 38936592 (37.13282775878906MB)
   50.40690783467237% used
Eden Space:
   capacity = 69795840 (66.5625MB)
   used     = 39518256 (37.68754577636719MB)
   free     = 30277584 (28.874954223632812MB)
   56.6197870818662% used
From Space:
   capacity = 8716288 (8.3125MB)
   used     = 57280 (0.05462646484375MB)
   free     = 8659008 (8.25787353515625MB)
   0.6571604793233082% used
To Space:
   capacity = 8716288 (8.3125MB)
   used     = 0 (0.0MB)
   free     = 8716288 (8.3125MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 986513408 (940.8125MB)
   used     = 115758360 (110.3957748413086MB)
   free     = 870755048 (830.4167251586914MB)
   11.734088869068874% used

25248 interned Strings occupying 3380280 bytes.

　　使用-heap查看堆信息，這樣就能總體看看內存的狀況。

　　另外一種狀況，是收集器選型不合理致使的gc卡頓，這樣須要去觀察gc的狀態，用到了jdk的另外一種工具：jstat

[ctk@172 ~]$ jstat -gc 35011
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
8512.0 8512.0  55.9   0.0   68160.0  32072.9   963392.0   113045.3  79036.0 72618.0 12220.0 10128.0     44    2.041   6      0.129    2.170

　　帶c的意思是capacity（容量）的意思，帶u的是used（已使用）的意思。s0，s1這些都是書上的概念，年輕代，老年代等等。M是method，方法區的意思。通常看的是YGC，YGCT，就是young gc次數，young gc time；FGC，FGCT，full gc次數，full gc time等參數。若是full gc的時間過長，young gc次數過於頻繁，則考慮去優化代碼。

[ctk@172 ~]$ jstat -gcutil 35011 100
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.66   0.00  62.44  11.73  91.88  82.88     44    2.041     6    0.129    2.170
  0.66   0.00  62.44  11.73  91.88  82.88     44    2.041     6    0.129    2.170
  0.66   0.00  62.44  11.73  91.88  82.88     44    2.041     6    0.129    2.170
  0.66   0.00  62.44  11.73  91.88  82.88     44    2.041     6    0.129    2.170

　　後邊帶個100指100ms輸出一次。

　　至今還沒碰到gc來不及而內存爆炸的狀況，若是出現大致都是代碼寫得很差。

　　另外一個topic，就是CPU佔用太高的問題。CPU佔用太高的狀況很容易聯想就是死循環，線程一直Runnable並且不退出。不少狀況下都是BUG，沒有什麼業務會讓Java進程使用那麼高的佔用率。我遇到過三次，狀況都不同，都歸於BUG。

　　第一個，是在一個2c的系統裏面，使用了全局jdk1.7的Map，而且是HashMap。在resize和put的過程當中，鏈表成了環，因此在系統開的Thread中，卡在ContainsKey這個方法中，致使CPU佔用太高掛掉，這個問題很隱蔽，而且是概率型發生的（誰也不能保證成環，也不能保證你計算到那個環上）。咱們最初是使用top命令觀察一段時間，發現CPU莫名的高，可是內存佔用卻不高，並且不是業務旺季。這個時候要採用jdk提供的另外一種工具：jstack

[ctk@172 ~]$ jstack 35011 | grep RUNNABLE -A 5
   java.lang.Thread.State: RUNNABLE

"elasticsearch[BeEZ6i3][trigger_engine_scheduler][T#1]" #50 daemon prio=5 os_prio=0 tid=0x00007faaf869f000 nid=0x88f9 waiting on condition [0x00007faaba846000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000c881d468> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
--
   java.lang.Thread.State: RUNNABLE

"elasticsearch[keepAlive/6.7.2]" #10 prio=5 os_prio=0 tid=0x00007faaf9fa8000 nid=0x88f8 waiting on condition [0x00007faabad47000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000c571a008> (a java.util.concurrent.CountDownLatch$Sync)
--
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000c9ce5940> (a sun.nio.ch.Util$3)
--
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000c9ce5d90> (a sun.nio.ch.Util$3)
--
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000c9c57a08> (a sun.nio.ch.Util$3)
--
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000c9c58398> (a sun.nio.ch.Util$3)
--
   java.lang.Thread.State: RUNNABLE
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:233)
    at org.elasticsearch.xpack.ml.process.logging.CppLogMessageHandler.tailStream(CppLogMessageHandler.java:105)
    at org.elasticsearch.xpack.ml.process.NativeController.lambda$tailLogsInThread$0(NativeController.java:70)
    at org.elasticsearch.xpack.ml.process.NativeController$$Lambda$1840/1525943877.run(Unknown Source)
--
   java.lang.Thread.State: RUNNABLE
    at java.lang.UNIXProcess.waitForProcessExit(Native Method)
    at java.lang.UNIXProcess.lambda$initStreams$3(UNIXProcess.java:289)
    at java.lang.UNIXProcess$$Lambda$135/1183231938.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
--
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread1" #7 daemon prio=9 os_prio=0 tid=0x00007faaf80fa000 nid=0x88ce waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #6 daemon prio=9 os_prio=0 tid=0x00007faaf80f8000 nid=0x88cd waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #5 daemon prio=9 os_prio=0 tid=0x00007faaf80f5800 nid=0x88cc runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Surrogate Locker Thread (Concurrent GC)" #4 daemon prio=9 os_prio=0 tid=0x00007faaf80f4800 nid=0x88cb waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007faaf80c1800 nid=0x88ca in Object.wait() [0x00007faad3ffe000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000c5888f08> (a java.lang.ref.ReferenceQueue$Lock)

　　咱們先是定位RUNNABLE的線程，發現有好幾個線程都是卡在containsKey這個方法。這個方法就是去hash一個key，並遍歷鏈表看看這個key是否存在。這裏有一個循環，若是循環不結束，則線程是一直RUNNABLE的，並且即便客戶端DISCONNECT，也不能保證這個Thread中止。咱們是web服務，斷開鏈接，可是後臺線程依然是沒有結束。

　

　　而後回憶起併發編程那本書裏提到的，併發下詭異的HashMap，遂猜想成環。由於使用的是static HashMap，因此建議修改成ConcurrentHashMap，觀察一段時間以後，問題修復。

　　第二個是在進行阿里雲vpc服務遷移的時候，發佈生產的時候，莫名其妙服務不打錯誤日誌，而應用起不來，屢試不爽。而且在啓動的好久以後，報了Socket TimeOut之類的錯誤。而後啓動的時候使用jstack查狀態，發現主線程main卡在數據庫鏈接上，一直是RUNNABLE的狀況，最終在啓動好久以後報出TIMEOUT之類的錯誤。（沒有現場日誌了）因此推測是服務器與數據庫的連接配置（安全組，權限，用戶）是否正常，最終是安全組的配置問題。

　　第三個問題很是詭異，消息中心採用ActiveMQ，業務方使用ActiveMQ Client進行使用。而消息中心閃斷以後，理應觸發重連機制，可是在拋出一個異常JMS 什麼Support Exception以後，CPU變得異常的高。而在拋出這個異常的時候，拋出了一個NoClassDef異常，這個異常大機率是jar衝突。這個問題沒有詳細排查，猜想是ActiveMQ在處理這個異常的時候，若是找不到有可能仍然不斷髮起重連，一直新建重連線程致使的。因爲是老系統，因此沒有詳細查了，根本緣由仍是依賴太過混亂。

　    dump內存。

jmap -dump:format=b,file=dump.hprof {pid}

 　　使用MAT進行內存分析。

　　 新鮮案例，幽靈通常的內存泄露。因爲內存中的ArrayList佔據老年代大量內存，觸發的fullgc不能把它gc掉致使頻繁的fullgc，進而CPU 100%，接口變慢。

　　

 

 

 

 

 

 

 

 

 　　還沒找到緣由。

MemoryAnalyzer.exe-vmargs -Xmx4g

　　 打開MAT時候指定最大內存。

 

 

 

三.In Conclusion

　　若是除去以上兩種，系統響應慢還有一個，就是Linux IO問題。這個不常遇到，可是一箇中間件的熟人在作RocketMQ搭建的時候，我體驗到了這種差異。（首先IO同步異步會有TPS的差異，cache和零拷貝又有區別）我並不精通，因此再也不總結。

　　平常的業務系統，若是不是業務正常引發的，最主要排查的是內存溢出以及不正常的Runnable引發的CPU太高。搞定這兩個，就能夠了。