0.前言

JVM自帶了一堆可排查JVM運行狀況的工具。But，每個工具的使用姿勢、使用后果均不同。作為開發人員，需要清楚每個工具的執行結果，不然會出現隨手執行一個命令、引發嚴重線上故障的場景。
這里簡要說明幾個使用命令
- jmap
  - jmap -dump
    - 例如， jmap -dump:format=b,file=heap.hprof 7
    - 該命令姿勢會令JVM將整個heap信息dump到一個文件中。如果heap比較大，會導致這個過程比較耗時。而且，為了保證dump的信息是准確、可靠的，JVM會處在STW狀態，致使服務不可用。
      - 可以通過-d64來解決，jmap -J-d64 -dump:format=b,file=dump.bin PID。
    - 通常dump下來的內存文件有幾個G大小，如果dump文件比較小，說明jmap姿勢不對，需要多執行幾次jmap -dump才能得到正常結果。
      - 可以用gcore將整個內存 dump下來，然后使用jmap將core dump轉為heap dump。
      - 方法，執行gcore PID得到C版本的core文件，再執行jmap -dump:format=b,file=heap.hprof /bin/java core.PID 即可。
  - jmap -permstat
    - 該命令會令JVM去統計perm區的狀況，整個過程比較的耗時，令JVM處於STW狀態，致使服務不可用。
  - jmap -histo:live
    - 該命令會令JVM執行GC操作，然后在進行統計信息。
- jstat
  - 利用JVM內建的指令對Java應用程序的資源和性能進行實時的命令行的監控，包括了對Heap size和垃圾回收狀況的監控。詳細查看堆內各個部分的使用量，以及加載類的數量。使用時，需加上查看進程的進程id、所選參數。
  - 使用姿勢，每秒輸出一次進程7的JVM資源使用情況，共輸出100次
    - jstat -gcutil 7 1000 100
在OOM場景，通常需要結合各種日志來排查(tomcat日志、gc日志等)。
- 如果沒有任何JVM參數設置，gc日志默認打印在stdout.log文件里，里面可能會打其他的日志，而且GC日志也不會輸出時間，所以在JVM啟動參數里最好加以下命令，規范下GC日志輸出到/home/admin/logs/gc.log，並且打印GC時間。
  - -XX:+HeapDumpOnOutOfMemoryError
  - -XX:HeapDumpPath=/home/admin/logs
  - -Xloggc:/home/admin/logs/gc.log
  - -XX:+PrintGCDetails
  - -XX:+PrintGCDateStamps

1.簡述

線上服務運營過程中，會存在各種原因(如，硬件問題、系統資源問題、程序bug等)引起的線上故障。具體現象有，服務性能下降、部分(或全部)接口超時、部分(或全部)接口卡死等。為保證服務可用性，一線開發人員需要能快速的排查、定位、解決這些問題。
雖然上述的故障現象看起來比較明顯，由於軟件系統本身以及運營環境的復雜性，導致故障定位非常困難，大概有以下原因：

程序打印的日志越詳細，越容易定位到BUG，但是可能有些時候程序中沒有打印相關內容到日志，或者日志級別沒有設置到相應級別
程序可能只對很特殊的輸入條件發生故障，但輸入條件難以推斷和復現
通常自己編寫的程序出現的問題會比較容易定位，但應用經常是由多人協作編寫，故障定位人員可能並不熟悉其他人員編寫的程序
應用通常會依賴很多第三方庫，第三方庫中隱藏着的BUG可能是始料未及的
多數的開發人員學習的都是“如何編寫業務功能”的技術資料，但對於“如何編寫高效、可靠的程序”、“如何定位程序故障”卻知之甚少。所以一旦應用出現故障，他們並沒有足夠的技術背景知識來幫助他們完成故障定位

因此，需要有一種普適的思路來指導Java棧線上問題的排查。大概有以下的排查思路：

2.適用范圍

這里只介紹部署在Linux系統上的Java服務線上故障排查、定位，如：服務性能明顯下降、部分（或所有）接口超時或卡死等。
對邏輯分支不對、計算結果不對等場景，需要利用JVM提供的遠程調試功能來進行動態跟蹤調試。

3.適用的異常現象

系統資源異常現象
- 一個程序由於BUG或者配置不當，可能會占用過多的系統資源，導致系統資源匱乏。這時，系統中其它程序就會出現計算緩慢、超時、操作失敗等“系統性”故障。
- 常見的系統資源異常現象有：
  - CPU占用過高
  - 物理內存富余量極少
  - 磁盤I/O占用過高
  - 發生換入換出過多
  - 網絡鏈接數過多
- 可以通過top、iostat、vmstat、netstat工具獲取到相應情況。
服務內部異常現象
- Java堆滿 - 使用jstat工具查看Java堆的占用率
  - Java堆是“Java虛擬機”從操作系統申請到的一大塊內存，用於存放Java程序運行中創建的對象。
  - 當Java堆滿或者較滿的情況下，會觸發“Java虛擬機”的“垃圾收集”操作，將所有“不可達對象”（即程序邏輯不能引用到的對象）清理掉。
  - 有時，由於程序邏輯或者Java堆參數設置的問題，會導致“可達對象”（即程序邏輯可以引用到的對象）占滿了Java堆。
  - 這時，Java虛擬機就會無休止地做“垃圾回收”操作，使得整個Java程序會進入卡死狀態。
- 日志出現異常信息
  - 日志中會記錄一些異常信息，例如超時、操作失敗等信息，其中可能含有系統故障的關鍵信息。
- 死鎖、死循環、數據結構異常（過大或者被破壞）、集中等待外部服務回應等現象
  - 可采用jstack工具可以獲取可能有用的線索

4 .故障定位步驟

由外到內、由大到小、逐步排除
- 排除其它程序過度占用系統資源的問題
- 排除服務本身占用系統資源過度的問題
- 觀察服務內部的情況，排除掉各種常見故障類型。
  - 對於不能排除的方面，要根據該信息對應的“危險程度”來判斷是應該“進一步深入”還是“暫時跳過”。例如：
A. 排除其它程序占用過量系統資源的情況
- 運行【top】，檢查CPU idle情況，如果發現idle較多（例如多余50%），則排除其它進程占用CPU過量的情況。
  - 如果idle較少，則按shift+p，將進程按照CPU占用率從高到低排序，逐一排查。
- 運行【free -g】，檢查剩余物理內存（“-/+ buffer/cache”行的“free”列）情況，如果發現剩余物理內存較多（例如剩余2GB以上），則排除占用物理內存過量的情況。排除服務占用了過量系統資源的情況。
  - 如果剩余物理內存較少（例如剩余1GB以下），則運行【vmstat -n 1】檢查si/so（換入換出）情況
    - 第一行數值表示的是從系統啟動到運行命令時的均值，可以暫時忽略。
    - 從第二行開始，每一行的si/so表示該秒內si/so的block數。如果多行數值都為零，則可以排除物理內存不足的問題。
    - 如果數值較大（例如大於1000 blocks/sec，block的大小一般是1KB）則說明存在較明顯的內存不足問題。
    - 可以運行【top】輸入shift+m，將進程按照物理內存占用（“RES”列）從大到小進行排序，然后對排前面的進程逐一排查。
- 如果目標服務是磁盤I/O較重的程序，則用【iostat -d 1】，檢查磁盤I/O情況。若“目標服務對應的磁盤”讀寫量在預估之內（預估要注意cache機制的影響），則排除其它進程占用磁盤I/O過量的問題。
  - 第一組數據是從該機器從開機以來的統計值。從第二組開始，都是每秒鍾的統計值。通過【df】命令，可以看到Device與目錄的關系。下圖設備“sdb”就對應了目錄“/disk2”。
  - 假如發現目標服務所在磁盤讀寫量明顯超過推算值，則應該找到大量讀寫磁盤的進程。
- .運行【netstat -aonp | grep tcp| wc -l】查看各種狀態的TCP連接數量和。如果總數較小（例如小於500），則排除連接數占用過多問題。
  - 假如發現連接數較多，可以用【netstat -natp|awk ‘{print $7}’|sort|uniq -c|sort -rn】按照PID統計TCP連接的數量，然后對連接數較多的進程逐一排查。
    - 如何“逐一排查”
      - 假如定位到是某個外部程序占用過量系統資源，則依據進程的功能和配置情況判斷是否合乎預期。
      - 假如符合預期，則考慮將服務遷移到其他機器、修改程序運行的磁盤、修改程序配置等方式解決。
      - 假如不符合預期，則可能是運行者對該程序不太了解或者是該程序發生了BUG。
      - 外部程序通常可能是Java程序也可能不是Java程序，如果是Java程序，可以把它當作目標服務一樣進行排查；而非Java程序不做詳細說明，可參考選用下面幾個工具：
        
        系統提供的調用棧的轉儲工具【pstack】，可以了解到程序中各個線程當前正在干什么，從而了解到什么邏輯占用了CPU、什么邏輯占用了磁盤等。
        
        系統提供的調用跟蹤工具【strace】，可以偵測到程序中每個系統API調用的參數、返回值、調用時間等。從而確認程序與系統API交互是否正常等。
        
        系統提供的調試器【gdb】，可以設置條件斷點偵測某個系統函數調用的時候調用棧是什么樣的。從而了解到什么邏輯不斷在分配內存、什么邏輯不斷在創建新連接等。
    - 如何“找到大量讀寫磁盤的進程”
      - 如果Linux系統比較新（kernel v2.6.20以上）可以使用iotop工具獲知每個進程的io情況，較快地定位到讀寫磁盤較多的進程。
      - 通過【ls -l /proc/*/fd | grep 該設備映射裝載到的文件系統路徑】查看到哪個進程打開了該設備的文件，並根據進程身份、打開的文件名、文件大小等屬性判斷是否做了大量讀寫。
      - 可以使用pstack取得進程的線程調用棧，或者strace跟蹤磁盤讀寫API來幫助確認某個進程是否在做磁盤做大量讀寫。
B. 排除目標服務占用了過量系統資源的情況
- 運行【top】，shift+p按照“CPU使用”從高到低的排序查看進程，假如目標服務占用的CPU較低（<100%，即小於一個核的計算量），或者符合經驗預期，則排除目標服務CPU占用過高的問題。
  - 假如目標服務占用的CPU較高（>100%，即大於一個核的計算量），則shift+h觀察線程級別的CPU使用分布。
  - 如果CPU使用分散到多個線程，而且每個線程占用都不算高（例如都<30%），則排除CPU占用過高的問題。
  - 如果CPU使用集中到一個或幾個線程，而且很高（例如都>95%），則用【jstack pid > jstack.log】獲取目標服務中線程調用棧的情況。top中看到的占用CPU較高的線程的PID轉換成16進制（字母用小寫），然后在jstack.log中找到對應線程，檢查其邏輯：假如對應線程是純計算型任務（例如GC、正則匹配、數值計算等），則排除CPU占用過高的問題。當然如果這種線程占用CPU總量如果過多（例如占滿了所有核），則需要對線程數量做控制（限制線程數 < CPU核數）。
  - 假如對應線程不是純計算型任務（例如只是向其他服務請求一些數據，然后簡單組合一下返回給用戶等），而該線程CPU占用過高（>95%），則可能發生了異常。
    - 例如：死循環、數據結構過大等問題，確定具體原因的方法見參考“第三步：目標進程內部觀察”。
- 運行【top】，shift+m按照“物理內存使用(RES)”從高到低排序進程，評估目標服務占的內存量是否在預期之內。如果在預期之內，則排除目標服務Native內存占用過高的問題。
  - 由於Java進程中有Java級別的內存占用，也有Native級別的內存占用，所以Java進程的“物理內存使用(RES)”比“-Xmx參數指定的Java堆大小”大一些是正常的（例如1.5~2倍左右）。
  - 假如“物理內存使用(RES)”超出預期較多（例如2倍以上），並且確定JNI邏輯不應該占用這么多內存，則可能是NIO或JNI代碼出現了BUG，暫時對這種情況不做過多討論。
C. 服務內部觀察
- Java堆占用情況 - 用【jstat -gcutil pid】查看目標服務的OLD區占用比例，假如占用比例低於85%則排除Java堆占用比例過高的問題。
  - 假如占用比例較高（例如超過98%），則服務存在Java堆占滿的問題。這時候可以用jmap+mat進行分析定位內存中占用比例的情況，從而較快地定位到Java堆滿的原因。
  - 用jmap+mat進行分析定位內存中占用比例的情況
    - 先通過【jmap -dump:file=dump.map pid】取得目標服務的Java堆轉儲，然后找一台空閑內存較大的機器在VNC中運行mat工具。
    - mat工具中打開dump.map后，可以方便地分析內存中什么對象引用了大量的對象（從邏輯意義上來說，就是該對象占用了多大比例的內存）。
- 異常日志觀察，如：
  - tail -1000 stdout.log.2020-02-02 | grep -i exception
- 疑難雜症
  - 用【jstack pid > jstack.log】獲取目標服務中“鎖情況”和“各線程調用棧”信息，並分析檢查jstack.log中是否有deadlock報出，如果沒有則排除deadlock情況。
    - *Found one Java-level deadlock:*
      
      *=============================*
      
      *“Thread-0″:*
      
      * waiting to lock monitor 0x1884337c (object 0x046ac698, a java.lang.Object),*
      
      * which is held by “main”*
      
      *“main”:*
      
      * waiting to lock monitor 0x188426e4 (object 0x046ac6a0, a java.lang.Object),*
      
      * which is held by “Thread-0″*
      
      * *
      *Java stack information for the threads listed above:*
      *===================================================*
      *“Thread-0″:*
      * at LockProblem$T2.run(LockProblem.java:14)*
      * - waiting to lock <0x046ac698> (a java.lang.Object)*
      * - locked <0x046ac6a0> (a java.lang.Object)*
      *“main”:*
      * at LockProblem.main(LockProblem.java:25)*
      * - waiting to lock <0x046ac6a0> (a java.lang.Object)*
      * - locked <0x046ac698> (a java.lang.Object)*
      * *
      *Found 1 deadlock.*
  - 如果發現deadlock則根據jstack.log中的提示定位到對應代碼邏輯。通過分析堆棧情況，可以定位到可以信息，並猜測故障的原因，通過日志檢查、監控檢查、用測試程序嘗試復現等方式確認猜測是否正確。
  - 如果需要更細致的證據來確認，可以通過BTrace、strace、jmap+MAT等工具進行分析，最終確認問題所在。
排查工具
- BTrace - 用於監測Java級別的方法調用情況。
  - 可以對運行中的Java虛擬機插入調試代碼，從而確認方法每次調用的參數、返回值、花費時間等。第三方免費工具。
- strace - 用於監視系統調用情況。
  - 可以得到每次系統調用的參數、返回值、耗費時間等。Linux自帶工具。
- jmap+MAT - 用於查看Java級別內存情況。
場景舉例
- 某種線程數量過多
  - *1000 threads at*
    *“Timer-0″ prio=6 tid=0x189e3800 nid=0x34e0 in Object.wait() [0x18c2f000]*
    * java.lang.Thread.State: TIMED_WAITING (on object monitor)*
    * at java.lang.Object.wait(Native Method)*
    * at java.util.TimerThread.mainLoop(Timer.java:552)*
    * - locked [***] (a java.util.TaskQueue)*
    * at java.util.TimerThread.run(Timer.java:505)*
- 多個線程在等待一把鎖，但拿到鎖的線程在做數據結構遍歷操作
  - *38 threads at*
    *“Thread-44″ prio=6 tid=0×18981800 nid=0x3a08 waiting for monitor entry [0x1a85f000]*
    * java.lang.Thread.State: BLOCKED (on object monitor)*
    * at SlowAction$Users.run(SlowAction.java:15)*
    * - waiting to lock [***] (a java.lang.Object)*
    
    * *
    *1 threads at*
    *“Thread-3″ prio=6 tid=0x1894f400 nid=0×3954 runnable [0x18d1f000]*
    * java.lang.Thread.State: RUNNABLE*
    * at java.util.LinkedList.indexOf(LinkedList.java:603)*
    * at java.util.LinkedList.contains(LinkedList.java:315)*
    * at SlowAction$Users.run(SlowAction.java:18)*
    * - locked [***] (a java.lang.Object)*
- ```
某個應當被緩存的對象多次被創建（數據庫連接）
```
  - 99 threads at
    “resin-tcp-connection-*:3231-321″ daemon prio=10 tid=0x000000004dc43800 nid=0x65f5 waiting for monitor entry [0x00000000507ff000]
    java.lang.Thread.State: BLOCKED (on object monitor)
    at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:290)
    - waiting to lock <0x00000000b26ee8a8> (a org.apache.commons.dbcp.PoolableConnectionFactory)
    at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:771)
    at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:95)
    * *
    1 threads
    at “resin-tcp-connection-*:3231-149″ daemon prio=10 tid=0x000000004d67e800 nid=0x66d7 runnable [0x000000005180f000]
    java.lang.Thread.State: RUNNABLE
    …
    at org.apache.commons.dbcp.DriverManagerConnectionFactory.createConnection(DriverManagerConnectionFactory.java:46)
    at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:290)
    - locked <0x00000000b26ee8a8> (a org.apache.commons.dbcp.PoolableConnectionFactory)
    at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:771)
    at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:95)
    at …
- 很多線程都在等待外部服務的響應
  - ```
  100 threads at
  “Thread-0″ prio=6 tid=0x189cdc00 nid=0×2904 runnable [0x18d5f000]
  java.lang.Thread.State: RUNNABLE
  atjava.net.SocketInputStream.socketRead0(Native Method)
  at java.net.SocketInputStream.read(SocketInputStream.java:150)
  at java.net.SocketInputStream.read(SocketInputStream.java:121)…
  at RequestingService$RPCThread.run(RequestingService.java:24)
```
- ```
很多線程都在等待FutureTask完成，而FutureTask在等待外部服務的響應
```
  - ```
  100 threads at
  “Thread-0″ prio=6 tid=0×18861000 nid=0x38b0 waiting on condition [0x1951f000]
     java.lang.Thread.State: WAITING (parking)
   at sun.misc.Unsafe.park(Native Method)
   - parking to wait for [***] (a java.util.concurrent.FutureTask$Sync)
   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
   at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
   at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:994)
   at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1303)
   at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:248)
   at java.util.concurrent.FutureTask.get(FutureTask.java:111)
   at IndirectWait$MyThread.run(IndirectWait.java:51)
   
  100 threads at
  “pool-1-thread-1″ prio=6 tid=0x188fc000 nid=0×2834 runnable [0x1d71f000]
  java.lang.Thread.State: RUNNABLEat java.net.SocketInputStream.socketRead0(Native Method)
  at java.net.SocketInputStream.read(SocketInputStream.java:150)
  at java.net.SocketInputStream.read(SocketInputStream.java:121)…
  at IndirectWait.request(IndirectWait.java:23)
  at IndirectWait$MyThread$1.call(IndirectWait.java:46)
  at IndirectWait$MyThread$1.call(IndirectWait.java:1)
  at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
  at java.util.concurrent.FutureTask.run(FutureTask.java:166)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
  at java.lang.Thread.run(Thread.java:722)
```

免責聲明！

本站轉載的文章為個人學習借鑒使用，本站對版權不負任何法律責任。如果侵犯了您的隱私權益，請聯系本站郵箱yoyou2525@163.com刪除。

猜您在找 Java程序線上故障排查生產環境JAVA進程高CPU占用故障排查 java cpu過高問題排查問題線上故障排查(2) - Java應用故障之堆溢出OOM問題及排查方案 JVM 出現 fullGC 很頻繁，怎么去線上排查問題 Java生產環境下問題排查 JAVA 線上故障排查全套路 JAVA 線上問題排查方法 java線上服務問題排查如何打日志才能方便排查問題？