一、摘要
于硬件問題、系統資源緊缺或者程序本身的BUG,Java服務在線上不可避免地會出現一些“系統性”故障,比如:服務性能明顯下降、部分(或所有)接口超
時或卡死等。其中部分故障隱藏頗深,對運維和開發造成長期困擾。筆者根據自己的學習和實踐,總結出一套行之有效的“逐步排除”的方法,來快速定位Java
服務線上“系統性”故障。
二、導言
語言是廣泛使用的語言,它具有跨平臺的特性和易學易用的特點,很多服務端應用都采用Java語言開發。由于軟件系統本身以及運行環境的復雜性,Java的
應用不可避免地會出現一些故障。盡管故障的表象通常比較明顯(服務反應明顯變慢、輸出發生錯誤、發生崩潰等),但故障定位卻并不一定容易。為什么呢?有如
下原因:
三、本方法適用的范圍
四、有哪些異?,F象
個程序由于BUG或者配置不當,可能會占用過多的系統資源,導致系統資源匱乏。這時,系統中其它程序就會出現計算緩慢、超時、操作失敗等“系統性”故障。
常見的系統資源異?,F象有:CPU占用過高、物理內存富余量極少、磁盤I/O占用過高、發生換入換出過多、網絡鏈接數過多。可以通過top、iostat、vmstat、netstat工具獲取到相應情況。
-
Java堆滿
Java堆是“Java虛擬機”從操作系統申請到的一大塊內存,用于存放Java程序運行中創建的對象。當Java堆滿或者較滿的情況下,會觸發
“Java虛擬機”的“垃圾收集”操作,將所有“不可達對象”(即程序邏輯不能引用到的對象)清理掉。有時,由于程序邏輯或者Java堆參數設置的問題,
會導致“可達對象”(即程序邏輯可以引用到的對象)占滿了Java堆。這時,Java虛擬機就會無休止地做“垃圾回收”操作,使得整個Java程序會進入
卡死狀態。我們可以使用jstat工具查看Java堆的占用率。 -
日志中的異常
目標服務可能會在日志中記錄一些異常信息,例如超時、操作失敗等信息,其中可能含有系統故障的關鍵信息。 -
疑難雜癥
死鎖、死循環、數據結構異常(過大或者被破壞)、集中等待外部服務回應等現象。這些異?,F象通常采用jstack工具可以獲取到非常有用的線索。
五、故障定位的步驟
于不能排除的方面,要根據該信息對應的“危險程度”來判斷是應該“進一步深入”還是“暫時跳過”。例如“目標服務Java堆占用100%”這是一條危險程
度較高的信息,建議立即“進一步深入”。而對于“在CPU核數為8的機器上,其它程序偶然占用CPU達200%”這種危險程度不是很高的信息,則建議“暫
時跳過”。當然,有些具體情況還需要故障排查人員根據自己的經驗做出判斷。
第一步:排除其它程序占用過量系統資源的情況
一行數值表示的是從系統啟動到運行命令時的均值,我們忽略掉。從第二行開始,每一行的si/so表示該秒內si/so的block數。如果多行數值都為
零,則可以排除物理內存不足的問題。如果數值較大(例如大于1000
blocks/sec,block的大小一般是1KB)則說明存在較明顯的內存不足問題。我們可以運行【top】輸入shift+m,將進程按照物理內存
占用(“RES”列)從大到小進行排序,然后對排前面的進程逐一排查(見下面TIP)。
假如定位到是某個外部程序占用過量系統資源,則依據進程的功能和配置情況判斷是否合乎預期。假如符合預期,則考慮將服務遷移到其他機器、修改程序運行的磁
盤、修改程序配置等方式解決。假如不符合預期,則可能是運行者對該程序不太了解或者是該程序發生了BUG。外部程序通??赡苁荍ava程序也可能不是
Java程序,如果是Java程序,可以把它當作目標服務一樣進行排查;而非Java程序具體排查方法超出了本文范圍,列出三個工具供參考選用:
- 系統提供的調用棧的轉儲工具【pstack】,可以了解到程序中各個線程當前正在干什么,從而了解到什么邏輯占用了CPU、什么邏輯占用了磁盤等
- 系統提供的調用跟蹤工具【strace】,可以偵測到程序中每個系統API調用的參數、返回值、調用時間等。從而確認程序與系統API交互是否正常等。
- 系統提供的調試器【gdb】,可以設置條件斷點偵測某個系統函數調用的時候調用棧是什么樣的。從而了解到什么邏輯不斷在分配內存、什么邏輯不斷在創建新連接等
第二步:排除目標服務占用了過量系統資源的情況
- 如果CPU使用分散到多個線程,而且每個線程占用都不算高(例如都<30%),則排除CPU占用過高的問題
-
如果CPU使用集中到一個或幾個線程,而且很高(例如都>95%),則用【jstack pid >
jstack.log】獲取目標服務中線程調用棧的情況。top中看到的占用CPU較高的線程的PID轉換成16進制(字母用小寫),然后在
jstack.log中找到對應線程,檢查其邏輯:- 假如對應線程是純計算型任務(例如GC、正則匹配、數值計算等),則排除CPU占用過高的問題。當然如果這種線程占用CPU總量如果過多(例如占滿了所有核),則需要對線程數量做控制(限制線程數 < CPU核數)。
- 假如對應線程不是純計算型任務(例如只是向其他服務請求一些數據,然后簡單組合一下返回給用戶等),而該線程CPU占用過高(>95%),則可能發生了異常。例如:死循環、數據結構過大等問題,確定具體原因的方法見下文“第三步:目標進程內部觀察”。
第三步:目標服務內部觀察
通過【jmap -dump:file=dump.map
pid】取得目標服務的Java堆轉儲,然后找一臺空閑內存較大的機器在VNC中運行mat工具。mat工具中打開dump.map后,可以方便地分析內
存中什么對象引用了大量的對象(從邏輯意義上來說,就是該對象占用了多大比例的內存)。具體使用可以ca
- 檢查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.
- 用【POST http://www.xinitek.com/ajax/summaryJStack < jstack.log > jstack.log.summary】對jstack.log做合并處理,然后繼續分析故障所在。
情況 | 嫌疑點 | 猜測原因 |
線程數量過多 | 某種線程數量過多 |
運行環境中“限制線程數量”的機制失效
|
多個線程在等待一把鎖,但拿到鎖的線程在做某個操作
|
拿到這把鎖的線程在做網絡connect操作
|
被connect的服務異常 |
|
拿到鎖的線程在做數據結構遍歷操作
|
該數據結構過大或被破壞
|
某個耗時的操作被反復調用
|
某個應當被緩存的對象多次被創建
|
對象池的配置錯誤 |
等待外部服務的響應
|
很多線程都在等待外部服務的響應
|
該外部服務故障
|
|
很多線程都在等待FutureTask完成,而FutureTask在等待外部服務的響應
|
該外部服務故障
|
用于查看Java級別內存情況。jmap是JDK自帶工具,可以將Java程序的Java堆轉儲到數據文件中;MAT是eclipse.org上提供的一
個工具,可以檢查jmap轉儲數據文件中的數據。結合這兩個工具,我們可以非常容易地看到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: RUNNABLEat 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)
daemon prio=10 tid=0x000000004dc43800 nid=0x65f5 waiting for monitor
entry [0x00000000507ff000]
“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)
“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)
六、給運維人員的簡單步驟
七、參考資料
- BTrace官網
- MAT官網
- 使用jmap和MAT觀察Java程序內存數據
- 使用Eclipse遠程調試Java應用程序
- Linux下輸入【man strace/top/iostat/vmstat/netstat/jstack】
文章鏈接:http://techblog.youdao.com/?p=961
原創文章,作者:追馬,如若轉載,請注明出處:http://www.www58058.com/570