1. 程式人生 > 實用技巧 >Java線上棧故障排查問題(COPY)

Java線上棧故障排查問題(COPY)

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 .故障定位步驟

  • 由外到內、由大到小、逐步排除
    • 排除其它程式過度佔用系統資源的問題

    • 排除服務本身佔用系統資源過度的問題

    • 觀察服務內部的情況,排除掉各種常見故障型別。

      • 對於不能排除的方面,要根據該資訊對應的“危險程度”來判斷是應該“進一步深入”還是“暫時跳過”。例如:

        • “服務Java堆佔用100%”,建議“進一步深入”。

        • “CPU核數為8的機器上,其它程式偶然佔用CPU達200%”,建議“暫時跳過”。

  • 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級別記憶體情況。

      • 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: 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)