一、前言

Java 語言是當前網際網路應用最為廣泛的語言，作為一名 Java 程式猿，當業務相對比較穩定之後平常工作除了 coding 之外，大部分時間（70%~80%）是會用來排查突發或者週期性的線上問題。

由於業務應用 bug(本身或引入第三方庫)、環境原因、硬體問題等原因，Java 線上服務出現故障 / 問題幾乎不可避免。例如，常見的現象包括部分請求超時、使用者明顯感受到系統發生卡頓等等。

儘快線上問題從系統表象來看非常明顯，但排查深究其發生的原因還是比較困難的，因此對開發測試或者是運維的同學產生了許多的困擾。

排查定位線上問題是具有一定技巧或者說是經驗規律的，排查者如果對業務系統瞭解得越深入，那麼相對來說定位也會容易一些。

不管怎麼說，掌握 Java 服務線上問題排查思路並能夠熟練排查問題常用工具 / 命令 / 平臺是每一個 Java 程式猿進階必須掌握的實戰技能。

筆者依據自己的 工作經驗總結出一套基本的線上問題排查流程，同學們可以根據自己的實際工作情況進行歸納總結。

二、Java 服務常見線上問題

所有 Java 服務的線上問題從系統表象來看歸結起來總共有四方面：CPU、記憶體、磁碟、網路。例如 CPU 使用率峰值突然飈高、記憶體溢位 (洩露)、磁碟滿了、網路流量異常、FullGC 等等問題。

基於這些現象我們可以將線上問題分成兩大類: 系統異常、業務服務異常。

1. 系統異常

常見的系統異常現象包括:  CPU 佔用率過高、CPU 上下文切換頻率次數較高、磁碟滿了、磁碟 I/O 過於頻繁、網路流量異常 (連線數過多)、系統可用記憶體長期處於較低值 (導致 oom killer) 等等。

這些問題可以通過 top(cpu)、free(記憶體)、df(磁碟)、dstat(網路流量)、pstack、vmstat、strace(底層系統呼叫) 等工具獲取系統異常現象資料。

此外，如果對系統以及應用進行排查後，均未發現異常現象的更笨原因，那麼也有可能是外部基礎設施如 IAAS 平臺本身引發的問題。

例如運營商網路或者雲服務提供商偶爾可能也會發生一些故障問題，你的引用只有某個區域如廣東使用者訪問系統時發生服務不可用現象，那麼極有可能是這些原因導致的。

今天我司部署在阿里雲華東地域的業務系統中午時分突然不能為廣東地區使用者提供正常服務，對系統進行各種排查均為發現任何問題。

最後，通過查詢阿里雲公告得知原因是 “ 廣東地區電信線路訪問華東地區網際網路資源（包含阿里雲華東 1 地域）出現網路丟包或者延遲增大的異常情況 “。

https://help.aliyun.com/noticelist/articleid/20724342.html?spm=5176.789004748.n2.6.LeTsMp

2. 業務服務異常

常見的業務服務異常現象包括: PV 量過高、服務呼叫耗時異常、執行緒死鎖、多執行緒併發問題、頻繁進行 Full GC、異常安全攻擊掃描等。

三、問題定位

我們一般會採用排除法，從外部排查到內部排查的方式來定位線上服務問題。

• 首先我們要排除其他程序 (除主程序之外) 可能引起的故障問題；

• 然後排除業務應用可能引起的故障問題；

• 可以考慮是否為運營商或者雲服務提供商所引起的故障。

1. 定位流程

1.1 系統異常排查流程

1.2 業務應用排查流程

2. Linux 常用的效能分析工具

Linux 常用的效能分析工具使用包括 : top(cpu)、free(記憶體)、df(磁碟)、dstat(網路流量)、pstack、vmstat、strace(底層系統呼叫) 等。

2.1 CPU

CPU 是系統重要的監控指標，能夠分析系統的整體執行狀況。監控指標一般包括執行佇列、CPU 使用率和上下文切換等。

top 命令是 Linux 下常用的 CPU 效能分析工具 , 能夠實時顯示系統中各個程序的資源佔用狀況 , 常用於服務端效能分析。

top 命令顯示了各個程序 CPU 使用情況 , 一般 CPU 使用率從高到低排序展示輸出。其中 Load Average 顯示最近 1 分鐘、5 分鐘和 15 分鐘的系統平均負載，上圖各值為 2.46，1.96，1.99。

我們一般會關注 CPU 使用率最高的程序，正常情況下就是我們的應用主程序。第七行以下：各程序的狀態監控。

PID : 程序 id
USER : 程序所有者
PR : 程序優先順序
NI : nice 值。負值表示高優先順序，正值表示低優先順序
VIRT : 程序使用的虛擬記憶體總量，單位 kb。VIRT=SWAP+RES
RES : 程序使用的、未被換出的實體記憶體大小，單位 kb。RES=CODE+DATA
SHR : 共享記憶體大小，單位 kb
S : 程序狀態。D= 不可中斷的睡眠狀態 R= 執行 S= 睡眠 T= 跟蹤 / 停止 Z= 殭屍程序
%CPU : 上次更新到現在的 CPU 時間佔用百分比
%MEM : 程序使用的實體記憶體百分比
TIME+ : 程序使用的 CPU 時間總計，單位 1/100 秒
COMMAND : 程序名稱

2.2 記憶體

記憶體是排查線上問題的重要參考依據，記憶體問題很多時候是引起 CPU 使用率較高的見解因素。

系統記憶體：free 是顯示的當前記憶體的使用 ,-m 的意思是 M 位元組來顯示內容。

free -m

部分引數說明：

  total 記憶體總數: 3790M
  used 已經使用的記憶體數: 1880M
  free 空閒的記憶體數: 118M
  shared 當前已經廢棄不用 , 總是 0
  buffers Buffer 快取記憶體數: 1792M

2.3 磁碟

df -h

du -m /path

2.4 網路

dstat 命令可以集成了 vmstat、iostat、netstat 等等工具能完成的任務。

   dstat -c  cpu 情況    -d 磁碟讀寫        -n 網路狀況        -l 顯示系統負載        -m 顯示形同記憶體狀況        -p 顯示系統程序資訊        -r 顯示系統 IO 情況

2.5 其它

vmstat：

vmstat 2 10 -t

vmstat 是 Virtual Meomory Statistics（虛擬記憶體統計）的縮寫 , 是實時系統監控工具。該命令通過使用 knlist 子程式和 /dev/kmen 偽裝置驅動器訪問這些資料，輸出資訊直接列印在螢幕。

使用 vmstat 2 10  -t 命令，檢視 io 的情況 (第一個引數是取樣的時間間隔數單位是秒，第二個引數是取樣的次數)。

r 表示執行佇列 (就是說多少個程序真的分配到 CPU),b 表示阻塞的程序。    
swpd 虛擬記憶體已使用的大小，如果大於 0，表示你的機器實體記憶體不足了，如果不是程式記憶體洩露的原因，那麼你該升級記憶體了或者把耗記憶體的任務遷移到其他機器。
free   空閒的實體記憶體的大小，我的機器記憶體總共 8G，剩餘 3415M。
buff   Linux/Unix 系統是用來儲存，目錄裡面有什麼內容，許可權等的快取，我本機大概佔用 300 多 M
cache 檔案快取
si 列表示由磁碟調入記憶體，也就是記憶體進入記憶體交換區的數量；
so 列表示由記憶體調入磁碟，也就是記憶體交換區進入記憶體的數量
一般情況下，si、so 的值都為 0，如果 si、so 的值長期不為 0，則表示系統記憶體不足，需要考慮是否增加系統記憶體。    
bi 從塊裝置讀入資料的總量（讀磁碟）（每秒 kb）
bo 塊裝置寫入資料的總量（寫磁碟）（每秒 kb）
隨機磁碟讀寫的時候，這兩個值越大 ((超出 1024k)，能看到 cpu 在 IO 等待的值也會越大 這裡設定的 bi+bo 參考值為 1000，如果超過 1000，而且 wa 值比較大，則表示系統磁碟 IO 效能瓶頸。
in 每秒 CPU 的中斷次數，包括時間中斷
cs(上下文切換 Context Switch)

strace：strace 常用來跟蹤程序執行時的系統呼叫和所接收的訊號。

strace -cp tid strace -T -p tid    -T 顯示每一呼叫所耗的時間 .    -p pid  跟蹤指定的程序 pid.    -v 輸出所有的系統呼叫 . 一些呼叫關於環境變數 , 狀態 , 輸入輸出等呼叫由於使用頻繁 , 預設不輸出 .    -V 輸出 strace 的版本資訊 .

3. JVM 定位問題工具

在 JDK 安裝目錄的 bin 目錄下預設提供了很多有價值的命令列工具。每個小工具體積基本都比較小，因為這些工具只是 jdk\lib\tools.jar 的簡單封裝。

其中，定位排查問題時最為常用命令包括:jps（程序）、jmap（記憶體）、jstack（執行緒）、jinfo(引數) 等。

• jps: 查詢當前機器所有 JAVA 程序資訊；

• jmap: 輸出某個 java 程序記憶體情況 (如:產生那些物件及數量等)；

• jstack: 列印某個 Java 執行緒的執行緒棧資訊；

• jinfo: 用於檢視 jvm 的配置引數。

3.1 jps 命令

jps 用於輸出當前使用者啟動的所有程序 ID，當線上發現故障或者問題時，能夠利用 jps 快速定位對應的 Java 程序 ID。

jps -l -m -m -l -l 引數用於輸出主啟動類的完整路徑

當然，我們也可以使用 Linux 提供的查詢程序狀態命令，例如：

ps -ef | grep tomcat

我們也能快速獲取 tomcat 服務的程序 id。

3.2 jmap 命令

jmap -heap pid   輸出當前程序 JVM 堆新生代、老年代、持久代等請情況，GC 使用的演算法等資訊 jmap -histo:live {pid} | head -n 10  輸出當前程序記憶體中所有物件包含的大小 jmap -dump:format=b,file=/usr/local/logs/gc/dump.hprof {pid} 以二進位制輸出檔當前記憶體的堆情況，然後可以匯入 MAT 等工具進行

jmap(Java Memory Map) 可以輸出所有記憶體中物件的工具 , 甚至可以將 VM 中的 heap, 以二進位制輸出成文字。

jmap -heap pid：

jmap -heap pid   輸出當前程序 JVM 堆新生代、老年代、持久代等請情況，GC 使用的演算法等資訊

jmap 可以檢視 JVM 程序的記憶體分配與使用情況，使用 的 GC 演算法等資訊。

jmap -histo:live {pid} | head -n 10：

jmap -histo:live {pid} | head -n 10  輸出當前程序記憶體中所有物件包含的大小

輸出當前程序記憶體中所有物件例項數 (instances) 和大小 (bytes), 如果某個業務物件例項數和大小存在異常情況，可能存在記憶體洩露或者業務設計方面存在不合理之處。

jmap -dump：

jmap -dump:format=b,file=/usr/local/logs/gc/dump.hprof {pid}

-dump:formate=b,file= 以二進位制輸出當前記憶體的堆情況至相應的檔案，然後可以結合 MAT 等記憶體分析工具深入分析當前記憶體情況。

一般我們要求給 JVM 新增引數 -XX:+Heap Dump On Out Of Memory Error OOM 確保應用發生 OOM 時 JVM 能夠儲存並 dump 出當前的記憶體映象。

當然，如果你決定手動 dump 記憶體時，dump 操作佔據一定 CPU 時間片、記憶體資源、磁碟資源等，因此會帶來一定的負面影響。

此外，dump 的檔案可能比較大 , 一般我們可以考慮使用 zip 命令對檔案進行壓縮處理，這樣在下載檔案時能減少頻寬的開銷。

下載 dump 檔案完成之後，由於 dump 檔案較大可將 dump 檔案備份至制定位置或者直接刪除，以釋放磁碟在這塊的空間佔用。

3.3 jstack 命令

printf ‘%x\n’ tid   –>  10 進位制至 16 進位制執行緒 ID(navtive 執行緒) %d 10 進位制 jstack pid | grep tid -C 30 –color ps -mp 8278 -o THREAD,tid,time | head -n 40

某 Java 程序 CPU 佔用率高，我們想要定位到其中 CPU 佔用率最高的執行緒。

(1) 利用 top 命令可以查出佔 CPU 最高的執行緒 pid

top -Hp {pid}

(2) 佔用率最高的執行緒 ID 為 6900，將其轉換為 16 進位制形式 (因為 java native 執行緒以 16 進位制形式輸出)

printf ‘%x\n’ 6900

(3) 利用 jstack 打印出 java 執行緒呼叫棧資訊

jstack 6418 | grep ‘0x1af4’ -A 50 –color

3.4 jinfo 命令

檢視某個 JVM 引數值 jinfo -flag ReservedCodeCacheSize 28461 jinfo -flag MaxPermSize 28461

3.5 jstat 命令

jstat -gc pid jstat -gcutil `pgrep -u admin java`

4. 記憶體分析工具 MAT

4.1 什麼是 MAT?

MAT(Memory Analyzer Tool)，一個基於 Eclipse 的記憶體分析工具，是一個快速、功能豐富的 JAVA heap 分析工具，它可以幫助我們查詢記憶體洩漏和減少記憶體消耗。

使用記憶體分析工具從眾多的物件中進行分析，快速的計算出在記憶體中物件的佔用大小，看看是誰阻止了垃圾收集器的回收工作，並可以通過報表直觀的檢視到可能造成這種結果的物件。

右側的餅圖顯示當前快照中最大的物件。單擊工具欄上的柱狀圖，可以檢視當前堆的類資訊，包括類的物件數量、淺堆 (Shallow heap)、深堆 (Retained Heap).

淺堆表示一個物件結構所佔用記憶體的大小。深堆表示一個物件被回收後，可以真實釋放的記憶體大小。

1）支配樹 (The Dominator Tree)

列出了堆中最大的物件，第二層級的節點表示當被第一層級的節點所引用到的物件，當第一層級物件被回收時，這些物件也將被回收。

這個工具可以幫助我們定位物件間的引用情況，垃圾回收時候的引用依賴關係

2）Path to GC Roots

被 JVM 持有的物件，如當前執行的執行緒物件，被 systemclass loader 載入的物件被稱為 GC Roots， 從一個物件到 GC Roots 的引用鏈被稱為 Path to GC Roots。

通過分析 Path to GC Roots 可以找出 JAVA 的記憶體洩露問題，當程式不在訪問該物件時仍存在到該物件的引用路徑。

四、日誌分析

1. GC 日誌分析

1.1 GC 日誌詳細分析

Java 虛擬機器 GC 日誌是用於定位問題重要的日誌資訊，頻繁的 GC 將導致應用吞吐量下降、響應時間增加，甚至導致服務不可用。

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/usr/local/gc/gc.log -XX:+UseConcMarkSweepGC

我們可以在 java 應用的啟動引數中增加 -XX:+PrintGCDetails 可以輸出 GC 的詳細日誌，例外還可以增加其他的輔助引數，如-Xloggc 制定 GC 日誌檔案地址。如果你的應用還沒有開啟該引數 , 下次重啟時請加入該引數。

上圖為線上某應用在平穩執行狀態下的 GC 日誌截圖。

2017-12-29T18:25:22.753+0800: 73143.256: [GC2017-12-29T18:25:22.753+0800: 73143.257: [ParNew: 559782K->1000K(629120K), 0.0135760 secs] 825452K->266673K(2027264K), 0.0140300 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
[2017-12-29T18:25:22.753+0800: 73143.256] ： 自JVM啟動73143.256秒時發生本次GC. [ParNew: 559782K->1000K(629120K), 0.0135760 secs] : 對新生代進行的GC，使用ParNew收集器，559782K是新生代回收前的大小,1000K是新生代回收後大小,629120K是當前新生代分配的記憶體總大小, 0.0135760 secs表示本次新生代回收耗時 0.0135760秒 [825452K->266673K(2027264K), 0.0140300 secs]:825452K是回收堆記憶體大小,266673K是回收堆之後記憶體大小，2027264K是當前堆記憶體總大小,0.0140300 secs表示本次回收共耗時0.0140300秒 [Times: user=0.02 sys=0.00, real=0.02 secs] : 使用者態耗時0.02秒,系統態耗時0.00,實際耗時0.02秒

無論是 minor GC 或者是 Full GC, 我們主要關注 GC 回收實時耗時 , 如 real=0.02secs, 即 stop the world 時間，如果該時間過長，則嚴重影響應用效能。

1.2 CMS GC 日誌分析

Concurrent Mark Sweep(CMS) 是老年代垃圾收集器 , 從名字 (Mark Sweep) 可以看出，CMS 收集器就是 “標記-清除” 演算法實現的，分為六個步驟：

• 初始標記 (STW initial mark)；

• 併發標記 (Concurrent marking)；

• 併發預清理 (Concurrent precleaning)；

• 重新標記 (STW remark)；

• 併發清理 (Concurrent sweeping)；

• 併發重置 (Concurrent reset)。

其中初始標記 (STW initial mark) 和 重新標記 (STW remark) 需要”Stop the World”。

初始標記 ：在這個階段，需要虛擬機器停頓正在執行的任務，官方的叫法 STW(Stop The Word)。這個過程從垃圾回收的 “ 根物件 “ 開始，只掃描到能夠和 “ 根物件 “ 直接關聯的物件，並作標記。

所以這個過程雖然暫停了整個 JVM，但是很快就完成了。

併發標記 ：這個階段緊隨初始標記階段，在初始標記的基礎上繼續向下追溯標記。併發標記階段，應用程式的執行緒和併發標記的執行緒併發執行，所以使用者不會感受到停頓。

併發預清理 ：併發預清理階段仍然是併發的。在這個階段，虛擬機器查詢在執行併發標記階段新進入老年代的物件 (可能會有一些物件從新生代晉升到老年代， 或者有一些物件被分配到老年代)。

通過重新掃描，減少下一個階段 “ 重新標記 “ 的工作，因為下一個階段會 Stop The World。

重新標記 ：這個階段會暫停虛擬機器，收集器執行緒掃描在 CMS 堆中剩餘的物件。掃描從 “ 跟物件 “ 開始向下追溯，並處理物件關聯。

併發清理 ：清理垃圾物件，這個階段收集器執行緒和應用程式執行緒併發執行。

併發重置 ：這個階段，重置 CMS 收集器的資料結構，等待下一次垃圾回收。

cms 使得在整個收集的過程中只是很短的暫停應用的執行 , 可通過在 JVM 引數中設定 -XX:UseConcMarkSweepGC 來使用此收集器 , 不過此收集器僅用於 old 和 Perm(永生) 的物件收集。

CMS 減少了 stop the world 的次數，不可避免地讓整體 GC 的時間拉長了。

Full GC 的次數說的是 stop the world 的次數，所以一次 CMS 至少會讓 Full GC 的次數 +2，因為 CMS Initial mark 和 remark 都會 stop the world，記做 2 次。而 CMS 可能失敗再引發一次 Full GC。

上圖為線上某應用在進行 CMS GC 狀態下的 GC 日誌截圖。

如果你已掌握 CMS 的垃圾收集過程，那麼上面的 GC 日誌你應該很容易就能看的懂，這裡我就不詳細展開解釋說明了。

此外 CMS 進行垃圾回收時也有可能會發生失敗的情況。

異常情況有：

1）伴隨 prommotion failed, 然後 Full GC：

[prommotion failed：存活區記憶體不足，物件進入老年代，而此時老年代也仍然沒有記憶體容納物件，將導致一次 Full GC]

2）伴隨 concurrent mode failed，然後 Full GC：

[concurrent mode failed：CMS 回收速度慢，CMS 完成前，老年代已被佔滿，將導致一次 Full GC]

3）頻繁 CMS GC：

[記憶體吃緊，老年代長時間處於較滿的狀態]

2. 業務日誌

業務日誌除了關注系統異常與業務異常之外，還要關注服務執行耗時情況，耗時過長的服務呼叫如果沒有熔斷等機制，很容易導致應用效能下降或服務不可用，服務不可用很容易導致雪崩。

上面是某一介面的呼叫情況，雖然大部分呼叫沒有發生異常，但是執行耗時相對比較長。

grep ‘[0-9]{3,}ms’ *.log

找出呼叫耗時大於 3 位數的 dao 方法，把 3 改成 4 就是大於 4 位數

網際網路應用目前幾乎採用分散式架構，但不限於服務框架、訊息中介軟體、分散式快取、分散式儲存等等。

那麼這些應用日誌如何聚合起來進行分析呢 ?

首先，你需要一套分散式鏈路呼叫跟蹤系統，通過在系統執行緒上線文間透傳 traceId 和 rpcId，將所有日誌進行聚合，例如淘寶的鷹眼，spring cloud zipkin 等等。

五、案列分析

CPU 使用率高問題定位

按照定位流程首先排除了系統層面的問題。

利用 top -Hp 6814 輸出程序 ID 為 6814 的所有執行緒 CPU 使用率情況，發現某個執行緒使用率比較高，有些異常。

printf ‘%x\n’ 2304     #輸出執行緒 ID 的 16 進位制 jstack pid | grep ‘0x900’ -C 30 –color

輸出的日誌表明該執行緒一直處於與 mysql I/O 狀態：

利用 jmap -dump:format=b,file=/usr/local/logs/gc/dump.hprof {pid} 以二進位制輸出檔當前記憶體的堆情況，然後可以匯入 MAT 等工具進行分析。

如下圖所示，點選 MAT 的支配樹可以發現存在某個超大物件陣列，例項物件數目多大 30 多萬個。

經過分析發現數組中每一個物件都是核心業務物件，我們的業務系統有一個定時任務執行緒會訪問資料庫某張業務表的所有記錄。

然後載入至記憶體然後進行處理因此記憶體吃緊，導致 CPU 突然飆升。發現該問題後，已對該方案進行重新設計。