用“逐步排除”的方法定位Java服务线上“系统性”故障
說明:原文地址已經(jīng)不可訪問,其他地方有轉(zhuǎn)載,不過很多丟失圖片,所以,找到一處有圖的重新配好圖。
用“逐步排除”的方法定位Java服務(wù)線上“系統(tǒng)性”故障
Posted on?2014/08/25李斯寧(高級測試開發(fā)工程師)
一、摘要
由于硬件問題、系統(tǒng)資源緊缺或者程序本身的BUG,Java服務(wù)在線上不可避免地會出現(xiàn)一些“系統(tǒng)性”故障,比如:服務(wù)性能明顯下降、部分(或所有)接口超時或卡死等。其中部分故障隱藏頗深,對運維和開發(fā)造成長期困擾。筆者根據(jù)自己的學(xué)習(xí)和實踐,總結(jié)出一套行之有效的“逐步排除”的方法,來快速定位Java服務(wù)線上“系統(tǒng)性”故障。二、導(dǎo)言
Java語言是廣泛使用的語言,它具有跨平臺的特性和易學(xué)易用的特點,很多服務(wù)端應(yīng)用都采用Java語言開發(fā)。由于軟件系統(tǒng)本身以及運行環(huán)境的復(fù)雜性,Java的應(yīng)用不可避免地會出現(xiàn)一些故障。盡管故障的表象通常比較明顯(服務(wù)反應(yīng)明顯變慢、輸出發(fā)生錯誤、發(fā)生崩潰等),但故障定位卻并不一定容易。為什么呢?有如下原因: 1. 程序打印的日志越詳細(xì),越容易定位到BUG,但是可能有些時候程序中沒有打印相關(guān)內(nèi)容到日志,或者日志級別沒有設(shè)置到相應(yīng)級別 2. 程序可能只對很特殊的輸入條件發(fā)生故障,但輸入條件難以推斷和復(fù)現(xiàn) 3. 通常自己編寫的程序出現(xiàn)的問題會比較容易定位,但應(yīng)用經(jīng)常是由多人協(xié)作編寫,故障定位人員可能并不熟悉其他人員編寫的程序 4. 應(yīng)用通常會依賴很多第三方庫,第三方庫中隱藏著的BUG可能是始料未及的 5. 多數(shù)的開發(fā)人員學(xué)習(xí)的都是“如何編寫業(yè)務(wù)功能”的技術(shù)資料,但對于“如何編寫高效、可靠的程序”、“如何定位程序故障”卻知之甚少。所以一旦應(yīng)用出現(xiàn)故障,他們并沒有足夠的技術(shù)背景知識來幫助他們完成故障定位。 盡管有些故障會很難定位,但筆者根據(jù)學(xué)習(xí)和實踐總結(jié)出一套“逐步排除”的故障定位方法:通過操作系統(tǒng)和Java虛擬機提供的監(jiān)控和診斷工具,獲取到系統(tǒng)資源和目標(biāo)服務(wù)(出現(xiàn)故障的Java服務(wù))內(nèi)部的狀態(tài),并依據(jù)服務(wù)程序的特點,識別出哪些現(xiàn)象是正常的,哪些現(xiàn)象是異常的。而后通過排除正常的現(xiàn)象,和跟蹤異常現(xiàn)象,就可以達(dá)到故障定位的目標(biāo)。 在正式介紹該方法之前,先申明一下這個方法使用的范圍。三、本方法適用的范圍
本方法主要適用于Linux系統(tǒng)中Java服務(wù)線上“系統(tǒng)性”故障的定位,比如:服務(wù)性能明顯下降、部分(或所有)接口超時或卡死。其它操作系統(tǒng)或其它語言的服務(wù),也可以參考本文的思路。 不適用本方法的情況:對于“功能性”故障,例如運算結(jié)果不對、邏輯分支走錯等,不建議使用本方法。對待這些情況比較恰當(dāng)?shù)姆椒ㄊ窃跍y試環(huán)境中重現(xiàn),并使用Java虛擬機提供的“遠(yuǎn)程調(diào)試”功能進(jìn)行動態(tài)跟蹤調(diào)試。 前面說過,本方法基于“異常現(xiàn)象”的識別來定位故障。那系統(tǒng)中可能有哪些異常現(xiàn)象呢?四、有哪些異常現(xiàn)象
我們可以將異常現(xiàn)象分成兩類:系統(tǒng)資源的異常現(xiàn)象、“目標(biāo)服務(wù)”內(nèi)部的異常現(xiàn)象。目標(biāo)服務(wù),指的是出現(xiàn)故障的Java服務(wù)。 1. 系統(tǒng)資源的異常現(xiàn)象 一個程序由于BUG或者配置不當(dāng),可能會占用過多的系統(tǒng)資源,導(dǎo)致系統(tǒng)資源匱乏。這時,系統(tǒng)中其它程序就會出現(xiàn)計算緩慢、超時、操作失敗等“系統(tǒng)性”故障。常見的系統(tǒng)資源異常現(xiàn)象有:CPU占用過高、物理內(nèi)存富余量極少、磁盤I/O占用過高、發(fā)生換入換出過多、網(wǎng)絡(luò)鏈接數(shù)過多。可以通過top、iostat、vmstat、netstat工具獲取到相應(yīng)情況。 2. 目標(biāo)服務(wù)內(nèi)部的異常現(xiàn)象- Java堆滿
Java堆是“Java虛擬機”從操作系統(tǒng)申請到的一大塊內(nèi)存,用于存放Java程序運行中創(chuàng)建的對象。當(dāng)Java堆滿或者較滿的情況下,會觸發(fā)“Java虛擬機”的“垃圾收集”操作,將所有“不可達(dá)對象”(即程序邏輯不能引用到的對象)清理掉。有時,由于程序邏輯或者Java堆參數(shù)設(shè)置的問題,會導(dǎo)致“可達(dá)對象”(即程序邏輯可以引用到的對象)占滿了Java堆。這時,Java虛擬機就會無休止地做“垃圾回收”操作,使得整個Java程序會進(jìn)入卡死狀態(tài)。我們可以使用jstat工具查看Java堆的占用率。 - 日志中的異常
目標(biāo)服務(wù)可能會在日志中記錄一些異常信息,例如超時、操作失敗等信息,其中可能含有系統(tǒng)故障的關(guān)鍵信息。 - 疑難雜癥
死鎖、死循環(huán)、數(shù)據(jù)結(jié)構(gòu)異常(過大或者被破壞)、集中等待外部服務(wù)回應(yīng)等現(xiàn)象。這些異常現(xiàn)象通常采用jstack工具可以獲取到非常有用的線索。
五、故障定位的步驟
我們采用“從外到內(nèi),逐步排除”的方式來定位故障: 1. 先排除其它程序過度占用系統(tǒng)資源的問題 2. 然后排除“目標(biāo)服務(wù)”本身占用系統(tǒng)資源過度的問題 3. 最后觀察目標(biāo)服務(wù)內(nèi)部的情況,排除掉各種常見故障類型。 對于不能排除的方面,要根據(jù)該信息對應(yīng)的“危險程度”來判斷是應(yīng)該“進(jìn)一步深入”還是“暫時跳過”。例如“目標(biāo)服務(wù)Java堆占用100%”這是一條危險程度較高的信息,建議立即“進(jìn)一步深入”。而對于“在CPU核數(shù)為8的機器上,其它程序偶然占用CPU達(dá)200%”這種危險程度不是很高的信息,則建議“暫時跳過”。當(dāng)然,有些具體情況還需要故障排查人員根據(jù)自己的經(jīng)驗做出判斷。第一步:排除其它程序占用過量系統(tǒng)資源的情況
圖示:排除其它程序占用過量系統(tǒng)資源的情況 1.?運行【top】,檢查CPU idle情況,如果發(fā)現(xiàn)idle較多(例如多余50%),則排除其它進(jìn)程占用CPU過量的情況。
如果idle較少,則按shift+p,將進(jìn)程按照CPU占用率從高到低排序,逐一排查(見下面TIP)。 2.?運行【free -g】,檢查剩余物理內(nèi)存(“-/+ buffer/cache”行的“free”列)情況,如果發(fā)現(xiàn)剩余物理內(nèi)存較多(例如剩余2GB以上),則排除占用物理內(nèi)存過量的情況。
如果剩余物理內(nèi)存較少(例如剩余1GB以下),則運行【vmstat -n 1】檢查si/so(換入換出)情況,
第一行數(shù)值表示的是從系統(tǒng)啟動到運行命令時的均值,我們忽略掉。從第二行開始,每一行的si/so表示該秒內(nèi)si/so的block數(shù)。如果多行數(shù)值都為零,則可以排除物理內(nèi)存不足的問題。如果數(shù)值較大(例如大于1000 blocks/sec,block的大小一般是1KB)則說明存在較明顯的內(nèi)存不足問題。我們可以運行【top】輸入shift+m,將進(jìn)程按照物理內(nèi)存占用(“RES”列)從大到小進(jìn)行排序,然后對排前面的進(jìn)程逐一排查(見下面TIP)。 3.?如果目標(biāo)服務(wù)是磁盤I/O較重的程序,則用【iostat -d 1】,檢查磁盤I/O情況。若“目標(biāo)服務(wù)對應(yīng)的磁盤”讀寫量在預(yù)估之內(nèi)(預(yù)估要注意cache機制的影響),則排除其它進(jìn)程占用磁盤I/O過量的問題。
第一組數(shù)據(jù)是從該機器從開機以來的統(tǒng)計值。從第二組開始,都是每秒鐘的統(tǒng)計值。通過【df】命令,可以看到Device與目錄的關(guān)系。下圖設(shè)備“sdb”就對應(yīng)了目錄“/disk2”。
假如發(fā)現(xiàn)目標(biāo)服務(wù)所在磁盤讀寫量明顯超過推算值,則應(yīng)該找到大量讀寫磁盤的進(jìn)程(見下面TIP) 4.?運行【netstat -aonp | grep tcp| wc -l】查看各種狀態(tài)的TCP連接數(shù)量和。如果總數(shù)較小(例如小于500),則排除連接數(shù)占用過多問題。 假如發(fā)現(xiàn)連接數(shù)較多,可以用【netstat -natp|awk ‘{print $7}’|sort|uniq -c|sort -rn】按照PID統(tǒng)計TCP連接的數(shù)量,然后對連接數(shù)較多的進(jìn)程逐一排查(見下面TIP)。 TIP:如何“逐一排查”:假如定位到是某個外部程序占用過量系統(tǒng)資源,則依據(jù)進(jìn)程的功能和配置情況判斷是否合乎預(yù)期。假如符合預(yù)期,則考慮將服務(wù)遷移到其他機器、修改程序運行的磁盤、修改程序配置等方式解決。假如不符合預(yù)期,則可能是運行者對該程序不太了解或者是該程序發(fā)生了BUG。外部程序通常可能是Java程序也可能不是Java程序,如果是Java程序,可以把它當(dāng)作目標(biāo)服務(wù)一樣進(jìn)行排查;而非Java程序具體排查方法超出了本文范圍,列出三個工具供參考選用:
- 系統(tǒng)提供的調(diào)用棧的轉(zhuǎn)儲工具【pstack】,可以了解到程序中各個線程當(dāng)前正在干什么,從而了解到什么邏輯占用了CPU、什么邏輯占用了磁盤等
- 系統(tǒng)提供的調(diào)用跟蹤工具【strace】,可以偵測到程序中每個系統(tǒng)API調(diào)用的參數(shù)、返回值、調(diào)用時間等。從而確認(rèn)程序與系統(tǒng)API交互是否正常等。
- 系統(tǒng)提供的調(diào)試器【gdb】,可以設(shè)置條件斷點偵測某個系統(tǒng)函數(shù)調(diào)用的時候調(diào)用棧是什么樣的。從而了解到什么邏輯不斷在分配內(nèi)存、什么邏輯不斷在創(chuàng)建新連接等
第二步:排除目標(biāo)服務(wù)占用了過量系統(tǒng)資源的情況
圖示:排除目標(biāo)服務(wù)占用了過量系統(tǒng)資源的情況 1.?運行【top】,shift+p按照“CPU使用”從高到低的排序查看進(jìn)程,假如目標(biāo)服務(wù)占用的CPU較低(<100%,即小于一個核的計算量),或者符合經(jīng)驗預(yù)期,則排除目標(biāo)服務(wù)CPU占用過高的問題。 假如目標(biāo)服務(wù)占用的CPU較高(>100%,即大于一個核的計算量),則shift+h觀察線程級別的CPU使用分布。
- 如果CPU使用分散到多個線程,而且每個線程占用都不算高(例如都<30%),則排除CPU占用過高的問題
- 如果CPU使用集中到一個或幾個線程,而且很高(例如都>95%),則用【jstack pid > jstack.log】獲取目標(biāo)服務(wù)中線程調(diào)用棧的情況。top中看到的占用CPU較高的線程的PID轉(zhuǎn)換成16進(jìn)制(字母用小寫),然后在jstack.log中找到對應(yīng)線程,檢查其邏輯:
- 假如對應(yīng)線程是純計算型任務(wù)(例如GC、正則匹配、數(shù)值計算等),則排除CPU占用過高的問題。當(dāng)然如果這種線程占用CPU總量如果過多(例如占滿了所有核),則需要對線程數(shù)量做控制(限制線程數(shù) < CPU核數(shù))。
- 假如對應(yīng)線程不是純計算型任務(wù)(例如只是向其他服務(wù)請求一些數(shù)據(jù),然后簡單組合一下返回給用戶等),而該線程CPU占用過高(>95%),則可能發(fā)生了異常。例如:死循環(huán)、數(shù)據(jù)結(jié)構(gòu)過大等問題,確定具體原因的方法見下文“第三步:目標(biāo)進(jìn)程內(nèi)部觀察”。
第三步:目標(biāo)服務(wù)內(nèi)部觀察
圖示:目標(biāo)服務(wù)內(nèi)部觀察
1. Java堆占用情況 ? 用【jstat -gcutil pid】查看目標(biāo)服務(wù)的OLD區(qū)占用比例,假如占用比例低于85%則排除Java堆占用比例過高的問題。 假如占用比例較高(例如超過98%),則服務(wù)存在Java堆占滿的問題。這時候可以用jmap+mat進(jìn)行分析定位內(nèi)存中占用比例的情況(見下文TIP),從而較快地定位到Java堆滿的原因。 TIP:用jmap+mat進(jìn)行分析定位內(nèi)存中占用比例的情況 先通過【jmap -dump:file=dump.map pid】取得目標(biāo)服務(wù)的Java堆轉(zhuǎn)儲,然后找一臺空閑內(nèi)存較大的機器在VNC中運行mat工具。mat工具中打開dump.map后,可以方便地分析內(nèi)存中什么對象引用了大量的對象(從邏輯意義上來說,就是該對象占用了多大比例的內(nèi)存)。具體使用可以ca 2. 異常日志觀察 通過類似【tail -10000 stdout.log.2014-08-15 | grep -B2 -A10 -i exception】這樣的方式,可以查到日志中最近記錄的異常。 3. 疑難雜癥 用【jstack pid > jstack.log】獲取目標(biāo)服務(wù)中“鎖情況”和“各線程調(diào)用棧”信息,并分析
- 檢查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.如果發(fā)現(xiàn)deadlock則則根據(jù)jstack.log中的提示定位到對應(yīng)代碼邏輯。
- 用【POST?http://www.xinitek.com/ajax/summaryJStack?< jstack.log > jstack.log.summary】對jstack.log做合并處理,然后繼續(xù)分析故障所在。
| 情況 | 嫌疑點 | 猜測原因 |
| 線程數(shù)量過多 | 某種線程數(shù)量過多 | 運行環(huán)境中“限制線程數(shù)量”的機制失效 |
| 多個線程在等待一把鎖,但拿到鎖的線程在做某個操作 | 拿到這把鎖的線程在做網(wǎng)絡(luò)connect操作 | 被connect的服務(wù)異常 |
| ? | 拿到鎖的線程在做數(shù)據(jù)結(jié)構(gòu)遍歷操作 | 該數(shù)據(jù)結(jié)構(gòu)過大或被破壞 |
| 某個耗時的操作被反復(fù)調(diào)用 | 某個應(yīng)當(dāng)被緩存的對象多次被創(chuàng)建 | 對象池的配置錯誤 |
| 等待外部服務(wù)的響應(yīng) | 很多線程都在等待外部服務(wù)的響應(yīng) | 該外部服務(wù)故障 |
| ? | 很多線程都在等待FutureTask完成,而FutureTask在等待外部服務(wù)的響應(yīng) | 該外部服務(wù)故障 |
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.?多個線程在等待一把鎖,但拿到鎖的線程在做數(shù)據(jù)結(jié)構(gòu)遍歷操作
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.?某個應(yīng)當(dāng)被緩存的對象多次被創(chuàng)建(數(shù)據(jù)庫連接) 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. 很多線程都在等待外部服務(wù)的響應(yīng) 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)
5.?很多線程都在等待FutureTask完成,而FutureTask在等待外部服務(wù)的響應(yīng) 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)
圖示:故障定位步驟匯總 故障定位是一個較復(fù)雜和需要經(jīng)驗的過程,如果現(xiàn)在故障正在發(fā)生,對于分析經(jīng)驗不很多的開發(fā)或運維人員,有什么簡單的操作步驟記錄下需要的信息嗎?下面提供一個
六、給運維人員的簡單步驟
如果事發(fā)突然且不能留著現(xiàn)場太久,要求運維人員:? 1. top: 記錄cpu idle%。如果發(fā)現(xiàn)cpu占用過高,則c, shift+h, shift + p查看線程占用CPU情況,并記錄 2. free: 查看內(nèi)存情況,如果剩余量較小,則top中shift+m查看內(nèi)存占用情況,并記錄 3. 如果top中發(fā)現(xiàn)占用資源較多的進(jìn)程名稱(例如java這樣的通用名稱)不太能說明進(jìn)程身份,則要用ps xuf | grep java等方式記錄下具體進(jìn)程的身份? 4. 取jstack結(jié)果。假如取不到,嘗試加/F jstack命令:jstack PID > jstack.log 5. jstat查看OLD區(qū)占用率。如果占用率到達(dá)或接近100%,則jmap取結(jié)果。假如取不到,嘗試加/F? jstat命令:?jstat -gcutil PID S0 ?S1 ? ?E ? ? ?O?? ? P ? ? YGC ? ?YGCT ? ?FGC ?FGCT ? GCT 0.00 21.35 88.01?97.35?59.89 111461 1904.894 1458 291.369 2196.263 jmap命令:??jmap -dump:file=dump.map PID 6. 重啟服務(wù) 原文http://techblog.youdao.com/?p=961 這里也有圖片備份:https://www.jianshu.com/p/bfaf385520c5總結(jié)
以上是生活随笔為你收集整理的用“逐步排除”的方法定位Java服务线上“系统性”故障的全部內(nèi)容,希望文章能夠幫你解決所遇到的問題。
- 上一篇: Java常用命令及Java Dump
- 下一篇: 线上java问题排查