用「逐步排除」的方法定位Java服務線上「系統性」故障

時間 2019-11-06

原文原文鏈接

1、摘要

因爲硬件問題、系統資源緊缺或者程序自己的BUG，Java服務在線上不可避免地會出現一些「系統性」故障，好比：服務性能明顯降低、部分（或全部）接口超時或卡死等。其中部分故障隱藏頗深，對運維和開發形成長期困擾。筆者根據本身的學習和實踐，總結出一套行之有效的「逐步排除」的方法，來快速定位Java服務線上「系統性」故障。

2、導言

Java語言是普遍使用的語言，它具備跨平臺的特性和易學易用的特色，不少服務端應用都採用Java語言開發。因爲軟件系統自己以及運行環境的複雜性，Java的應用不可避免地會出現一些故障。儘管故障的表象一般比較明顯（服務反應明顯變慢、輸出發生錯誤、發生崩潰等），但故障定位卻並不必定容易。爲何呢？有以下緣由：

1. 程序打印的日誌越詳細，越容易定位到BUG，可是可能有些時候程序中沒有打印相關內容到日誌，或者日誌級別沒有設置到相應級別

2. 程序可能只對很特殊的輸入條件發生故障，但輸入條件難以推斷和復現

3. 一般本身編寫的程序出現的問題會比較容易定位，但應用常常是由多人協做編寫，故障定位人員可能並不熟悉其餘人員編寫的程序

4. 應用一般會依賴不少第三方庫，第三方庫中隱藏着的BUG多是始料未及的

5. 多數的開發人員學習的都是「如何編寫業務功能」的技術資料，但對於「如何編寫高效、可靠的程序」、「如何定位程序故障」卻知之甚少。因此一旦應用出現故障，他們並無足夠的技術背景知識來幫助他們完成故障定位。

儘管有些故障會很難定位，但筆者根據學習和實踐總結出一套「逐步排除」的故障定位方法：經過操做系統和Java虛擬機提供的監控和診斷工具，獲取到系統資源和目標服務（出現故障的Java服務）內部的狀態，並依據服務程序的特色，識別出哪些現象是正常的，哪些現象是異常的。然後經過排除正常的現象，和跟蹤異常現象，就能夠達到故障定位的目標。

在正式介紹該方法以前，先申明一下這個方法使用的範圍。

3、本方法適用的範圍

本方法主要適用於Linux系統中Java服務線上「系統性」故障的定位，好比：服務性能明顯降低、部分（或全部）接口超時或卡死。其它操做系統或其它語言的服務，也能夠參考本文的思路。

不適用本方法的狀況：對於「功能性」故障，例如運算結果不對、邏輯分支走錯等，不建議使用本方法。對待這些狀況比較恰當的方法是在測試環境中重現，並使用Java虛擬機提供的「遠程調試」功能進行動態跟蹤調試。

前面說過，本方法基於「異常現象」的識別來定位故障。那系統中可能有哪些異常現象呢？

4、有哪些異常現象

咱們能夠將異常現象分紅兩類：系統資源的異常現象、「目標服務」內部的異常現象。目標服務，指的是出現故障的Java服務。

1. 系統資源的異常現象

一個程序因爲BUG或者配置不當，可能會佔用過多的系統資源，致使系統資源匱乏。這時，系統中其它程序就會出現計算緩慢、超時、操做失敗等「系統性」故障。常見的系統資源異常現象有：CPU佔用太高、物理內存富餘量極少、磁盤I/O佔用太高、發生換入換出過多、網絡連接數過多。能夠經過top、iostat、vmstat、netstat工具獲取到相應狀況。

2. 目標服務內部的異常現象

Java堆滿
Java堆是「Java虛擬機」從操做系統申請到的一大塊內存，用於存放Java程序運行中建立的對象。當Java堆滿或者較滿的狀況下，會觸發「Java虛擬機」的「垃圾收集」操做，將全部「不可達對象」（即程序邏輯不能引用到的對象）清理掉。有時，因爲程序邏輯或者Java堆參數設置的問題，會致使「可達對象」（即程序邏輯能夠引用到的對象）佔滿了Java堆。這時，Java虛擬機就會無休止地作「垃圾回收」操做，使得整個Java程序會進入卡死狀態。咱們可使用jstat工具查看Java堆的佔用率。
日誌中的異常
目標服務可能會在日誌中記錄一些異常信息，例如超時、操做失敗等信息，其中可能含有系統故障的關鍵信息。
疑難雜症
死鎖、死循環、數據結構異常（過大或者被破壞）、集中等待外部服務迴應等現象。這些異常現象一般採用jstack工具能夠獲取到很是有用的線索。

瞭解異常現象分類以後，咱們來具體講講故障定位的步驟。

5、故障定位的步驟

咱們採用「從外到內，逐步排除」的方式來定位故障：

1. 先排除其它程序過分佔用系統資源的問題

2. 而後排除「目標服務」自己佔用系統資源過分的問題

3. 最後觀察目標服務內部的狀況，排除掉各類常見故障類型。

對於不能排除的方面，要根據該信息對應的「危險程度」來判斷是應該「進一步深刻」仍是「暫時跳過」。例如「目標服務Java堆佔用100%」這是一條危險程度較高的信息，建議當即「進一步深刻」。而對於「在CPU核數爲8的機器上，其它程序偶然佔用CPU達200%」這種危險程度不是很高的信息，則建議「暫時跳過」。固然，有些具體狀況還須要故障排查人員根據本身的經驗作出判斷。

第一步：排除其它程序佔用過量系統資源的狀況 java

圖示：排除其它程序佔用過量系統資源的狀況

1. 運行【top】，檢查CPU idle狀況，若是發現idle較多（例如多餘50%），則排除其它進程佔用CPU過量的狀況。

若是idle較少，則按shift+p，將進程按照CPU佔用率從高到低排序，逐一排查（見下面TIP）。

2. 運行【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」列）從大到小進行排序，而後對排前面的進程逐一排查（見下面TIP）。

3. 若是目標服務是磁盤I/O較重的程序，則用【iostat -d 1】，檢查磁盤I/O狀況。若「目標服務對應的磁盤」讀寫量在預估以內（預估要注意cache機制的影響），則排除其它進程佔用磁盤I/O過量的問題。

第一組數據是從該機器從開機以來的統計值。從第二組開始，都是每秒鐘的統計值。經過【df】命令，能夠看到Device與目錄的關係。下圖設備「sdb」就對應了目錄「/disk2」。

假如發現目標服務所在磁盤讀寫量明顯超過推算值，則應該找到大量讀寫磁盤的進程（見下面TIP）

4. 運行【netstat -aonp | grep tcp| wc -l】查看各類狀態的TCP鏈接數量和。若是總數較小（例如小於500），則排除鏈接數佔用過多問題。

假如發現鏈接數較多，能夠用【netstat -natp|awk ‘{print $7}’|sort|uniq -c|sort -rn】按照PID統計TCP鏈接的數量，而後對鏈接數較多的進程逐一排查（見下面TIP）。

TIP：如何「逐一排查」：假如定位到是某個外部程序佔用過量系統資源，則依據進程的功能和配置狀況判斷是否合乎預期。假如符合預期，則考慮將服務遷移到其餘機器、修改程序運行的磁盤、修改程序配置等方式解決。假如不符合預期，則多是運行者對該程序不太瞭解或者是該程序發生了BUG。外部程序一般多是Java程序也可能不是Java程序，若是是Java程序，能夠把它看成目標服務同樣進行排查；而非Java程序具體排查方法超出了本文範圍，列出三個工具供參考選用：

系統提供的調用棧的轉儲工具【pstack】，能夠了解到程序中各個線程當前正在幹什麼，從而瞭解到什麼邏輯佔用了CPU、什麼邏輯佔用了磁盤等
系統提供的調用跟蹤工具【strace】，能夠偵測到程序中每一個系統API調用的參數、返回值、調用時間等。從而確認程序與系統API交互是否正常等。
系統提供的調試器【gdb】，能夠設置條件斷點偵測某個系統函數調用的時候調用棧是什麼樣的。從而瞭解到什麼邏輯不斷在分配內存、什麼邏輯不斷在建立新鏈接等

TIP：如何「找到大量讀寫磁盤的進程」：

1. 若是Linux系統比較新（kernel v2.6.20以上）可使用iotop工具獲知每一個進程的io狀況，較快地定位到讀寫磁盤較多的進程。

2. 經過【ls -l /proc/*/fd | grep 該設備映射裝載到的文件系統路徑】查看到哪一個進程打開了該設備的文件，並根據進程身份、打開的文件名、文件大小等屬性判斷是否作了大量讀寫。

3. 可使用pstack取得進程的線程調用棧，或者strace跟蹤磁盤讀寫API來幫助確認某個進程是否在作磁盤作大量讀寫

第二步：排除目標服務佔用了過量系統資源的狀況

圖示：排除目標服務佔用了過量系統資源的狀況

1. 運行【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%），則可能發生了異常。例如：死循環、數據結構過大等問題，肯定具體緣由的方法見下文「第三步：目標進程內部觀察」。

2. 運行【top】，shift+m按照「物理內存使用(RES)」從高到低排序進程，評估目標服務佔的內存量是否在預期以內。若是在預期以內，則排除目標服務Native內存佔用太高的問題。

提示：因爲Java進程中有Java級別的內存佔用，也有Native級別的內存佔用，因此Java進程的「物理內存使用(RES)」比「-Xmx參數指定的Java堆大小」大一些是正常的（例如1.5~2倍左右）。

假如「物理內存使用(RES)」超出預期較多（例如2倍以上），而且肯定JNI邏輯不該該佔用這麼多內存，則多是NIO或JNI代碼出現了BUG。因爲本文主要討論的是Java級別的問題，因此對這種狀況不作過多討論。讀者能夠參考上文「TIP：如何逐一排查」進行native級別的調試。

第三步：目標服務內部觀察

圖示：目標服務內部觀察

1. Java堆佔用狀況

用【jstat -gcutil pid】查看目標服務的OLD區佔用比例，假如佔用比例低於85%則排除Java堆佔用比例太高的問題。

假如佔用比例較高（例如超過98%），則服務存在Java堆佔滿的問題。這時候能夠用jmap+mat進行分析定位內存中佔用比例的狀況（見下文TIP），從而較快地定位到Java堆滿的緣由。

TIP：用jmap+mat進行分析定位內存中佔用比例的狀況

先經過【jmap -dump:file=dump.map pid】取得目標服務的Java堆轉儲，而後找一臺空閒內存較大的機器在VNC中運行mat工具。mat工具中打開dump.map後，能夠方便地分析內存中什麼對象引用了大量的對象（從邏輯意義上來講，就是該對象佔用了多大比例的內存）。具體使用能夠ca

2. 異常日誌觀察

經過相似【tail -10000 stdout.log.2014-08-15 | grep -B2 -A10 -i exception】這樣的方式，能夠查到日誌中最近記錄的異常。

3. 疑難雜症

用【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中的提示定位到對應代碼邏輯。

用【POST http://www.xinitek.com/ajax/summaryJStack < jstack.log > jstack.log.summary】對jstack.log作合併處理，而後繼續分析故障所在。

經過jstack.log.summary中的狀況，咱們能夠較迅速地定位到一些嫌疑點，並能夠猜想其故障引發的緣由（後文有jstack.log.summary狀況舉例供參考）

狀況	嫌疑點	猜想緣由
線程數量過多	某種線程數量過多	運行環境中「限制線程數量」的機制失效
多個線程在等待一把鎖，但拿到鎖的線程在作某個操做	拿到這把鎖的線程在作網絡connect操做	被connect的服務異常
	拿到鎖的線程在作數據結構遍歷操做	該數據結構過大或被破壞
某個耗時的操做被反覆調用	某個應當被緩存的對象屢次被建立	對象池的配置錯誤
等待外部服務的響應	不少線程都在等待外部服務的響應	該外部服務故障
	不少線程都在等待FutureTask完成，而FutureTask在等待外部服務的響應	該外部服務故障

猜想了緣由後，能夠經過日誌檢查、監控檢查、用測試程序嘗試復現等方式確認猜想是否正確。若是須要更細緻的證據來確認，能夠經過BTrace、strace、jmap+MAT等工具進行分析，最終確認問題所在。

下面簡單介紹下這幾個工具：

BTrace：用於監測Java級別的方法調用狀況。能夠對運行中的Java虛擬機插入調試代碼，從而確認方法每次調用的參數、返回值、花費時間等。第三方免費工具。

strace：用於監視系統調用狀況。能夠獲得每次系統調用的參數、返回值、耗費時間等。Linux自帶工具。

jmap+MAT：用於查看Java級別內存狀況。jmap是JDK自帶工具，能夠將Java程序的Java堆轉儲到數據文件中；MAT是eclipse.org上提供的一個工具，能夠檢查jmap轉儲數據文件中的數據。結合這兩個工具，咱們能夠很是容易地看到Java程序內存中全部對象及其屬性。

TIP：jstack.log.summary狀況舉例

1. 某種線程數量過多

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)

2. 多個線程在等待一把鎖，但拿到鎖的線程在作數據結構遍歷操做

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)

3. 某個應當被緩存的對象屢次被建立（數據庫鏈接）

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 …

4. 不少線程都在等待外部服務的響應

100 threads at

「Thread-0″ prio=6 tid=0x189cdc00 nid=0×2904 runnable [0x18d5f000]
java.lang.Thread.State: RUNNABLE
at java.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) ios

5. 不少線程都在等待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: RUNNABLE
at 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) ajax