當一個系統在發生 OOM 的時候，行為可能會讓你感到非常困惑。因為 JVM 是運行在操作系統之上的，操作系統的一些限制，會嚴重影響 JVM 的行為。**故障排查是一個綜合性的技術問題，在日常工作中要增加自己的知識廣度。多總結、多思考、多記錄，這才是正確的晉級方式**。 現在的互聯網服務，一般都做了負載均衡。如果一個實例發生了問題，不要著急去重啟。萬能的重啟會暫時緩解問題，但如果不保留現場，可能就錯失了解決問題的根本，擔心的事情還會到來。 所以，當實例發生問題的時候，第一步是隔離，第二步才是問題排查。什么叫隔離呢？就是把你的這臺機器從請求列表里摘除，比如把 nginx 相關的權重設成零。在微服務中，也有相應的隔離機制，這里默認你已經有了（面試也默認你已經有隔離功能了）。 本課時的內容將涉及非常多的 Linux 命令，對 JVM 故障排查的幫助非常大，你可以逐個擊破。 ### 1. GC 引起 CPU 飆升 我們有個線上應用，單節點在運行一段時間后，CPU 的使用會飆升，一旦飆升，一般懷疑某個業務邏輯的計算量太大，或者是觸發了死循環（比如著名的 HashMap 高并發引起的死循環），但排查到最后其實是 GC 的問題。 在 Linux 上，分析哪個線程引起的 CPU 問題，通常有一個固定的步驟。我們下面來分解這個過程，這是面試頻率極高的一個問題。  （1）使用 top 命令，查找到使用 CPU 最多的某個進程，記錄它的 pid。使用 Shift + P 快捷鍵可以按 CPU 的使用率進行排序。 ``` top ``` （2）再次使用 top 命令，加 -H 參數，查看某個進程中使用 CPU 最多的某個線程，記錄線程的 ID。 ``` top?-Hp?$pid ``` （3）使用 printf 函數，將十進制的 tid 轉化成十六進制。 ``` printf?%x?$tid ``` （4）使用 jstack 命令，查看 Java 進程的線程棧。 ``` jstack?$pid?>$pid.log ``` （5）使用 less 命令查看生成的文件，并查找剛才轉化的十六進制 tid，找到發生問題的線程上下文。 ``` less?$pid.log ``` 我們在 jstack 日志中找到了 CPU 使用最多的幾個線程。  可以看到問題發生的根源，是我們的堆已經滿了，但是又沒有發生 OOM，于是 GC 進程就一直在那里回收，回收的效果又非常一般，造成 CPU 升高應用假死。 接下來的具體問題排查，就需要把內存 dump 一份下來，使用 MAT 等工具分析具體原因了（將在第 12 課時講解）。 ### 2. 現場保留 可以看到這個過程是繁雜而冗長的，需要記憶很多內容。現場保留可以使用自動化方式將必要的信息保存下來，那一般在線上系統會保留哪些信息呢？下面我進行一下總結。 #### 2.1. 瞬時態和歷史態 為了協助我們的分析，這里創造了兩個名詞：瞬時態和歷史態。瞬時態是指當時發生的、快照類型的元素；歷史態是指按照頻率抓取的，有固定監控項的資源變動圖。 有很多信息，比如 CPU、系統內存等，瞬時態的價值就不如歷史態來的直觀一些。因為瞬時狀態無法體現一個趨勢性問題（比如斜率、求導等），而這些信息的獲取一般依靠監控系統的協作。 但對于 lsof、heap 等，這種沒有時間序列概念的混雜信息，體積都比較大，無法進入監控系統產生有用價值，就只能通過瞬時態進行分析。在這種情況下，瞬時態的價值反而更大一些。我們常見的堆快照，就屬于瞬時狀態。 問題不是憑空產生的，在分析時，一般要收集系統的整體變更集合，比如代碼變更、網絡變更，甚至數據量的變化。  接下來對每一項資源的獲取方式進行介紹。 #### 2.2. 保留信息 * （1）系統當前網絡連接 ``` ss?-antp?>?$DUMP_DIR/ss.dump?2>&1 ``` 其中，ss 命令將系統的所有網絡連接輸出到 ss.dump 文件中。使用 ss 命令而不是 netstat 的原因，是因為 netstat 在網絡連接非常多的情況下，執行非常緩慢。 后續的處理，可通過查看各種網絡連接狀態的梳理，來排查 TIME_WAIT 或者 CLOSE_WAIT，或者其他連接過高的問題，非常有用。 線上有個系統更新之后，監控到 CLOSE_WAIT 的狀態突增，最后整個 JVM 都無法響應。CLOSE_WAIT 狀態的產生一般都是代碼問題，使用 jstack 最終定位到是因為 HttpClient 的不當使用而引起的，多個連接不完全主動關閉。 * （2）網絡狀態統計 ``` netstat?-s?>?$DUMP_DIR/netstat-s.dump?2>&1 ``` 此命令將網絡統計狀態輸出到 netstat-s.dump 文件中。它能夠按照各個協議進行統計輸出，對把握當時整個網絡狀態，有非常大的作用。 ``` sar?-n?DEV?1?2?>?$DUMP_DIR/sar-traffic.dump?2>&1 ``` 上面這個命令，會使用 sar 輸出當前的網絡流量。在一些速度非常高的模塊上，比如 Redis、Kafka，就經常發生跑滿網卡的情況。如果你的 Java 程序和它們在一起運行，資源則會被擠占，表現形式就是網絡通信非常緩慢。 * （3）進程資源 ``` lsof?-p?$PID?>?$DUMP_DIR/lsof-$PID.dump ``` 這是個非常強大的命令，通過查看進程，能看到打開了哪些文件，這是一個神器，可以以進程的維度來查看整個資源的使用情況，包括每條網絡連接、每個打開的文件句柄。同時，也可以很容易的看到連接到了哪些服務器、使用了哪些資源。這個命令在資源非常多的情況下，輸出稍慢，請耐心等待。 * （4）CPU 資源 ``` mpstat?>?$DUMP_DIR/mpstat.dump?2>&1 vmstat?1?3?>?$DUMP_DIR/vmstat.dump?2>&1 sar?-p?ALL??>?$DUMP_DIR/sar-cpu.dump??2>&1 uptime?>?$DUMP_DIR/uptime.dump?2>&1 ``` 主要用于輸出當前系統的 CPU 和負載，便于事后排查。這幾個命令的功能，有不少重合，使用者要注意甄別。 * （5）I/O 資源 ``` iostat?-x?>?$DUMP_DIR/iostat.dump?2>&1 ``` 一般，以計算為主的服務節點，I/O 資源會比較正常，但有時也會發生問題，比如日志輸出過多，或者磁盤問題等。此命令可以輸出每塊磁盤的基本性能信息，用來排查 I/O 問題。在第 8 課時介紹的 GC 日志分磁盤問題，就可以使用這個命令去發現。 * （6）內存問題 ``` free?-h?>?$DUMP_DIR/free.dump?2>&1 ``` free 命令能夠大體展現操作系統的內存概況，這是故障排查中一個非常重要的點，比如 SWAP 影響了 GC，SLAB 區擠占了 JVM 的內存。 * （7）其他全局 ``` ps?-ef?>?$DUMP_DIR/ps.dump?2>&1 dmesg?>?$DUMP_DIR/dmesg.dump?2>&1 sysctl?-a?>?$DUMP_DIR/sysctl.dump?2>&1 ``` dmesg 是許多靜悄悄死掉的服務留下的最后一點線索。當然，ps 作為執行頻率最高的一個命令，它當時的輸出信息，也必然有一些可以參考的價值。 另外，由于內核的配置參數，會對系統和 JVM 產生影響，所以我們也輸出了一份。 * （8）進程快照，最后的遺言（jinfo） ``` ${JDK_BIN}jinfo?$PID?>?$DUMP_DIR/jinfo.dump?2>&1 ``` 此命令將輸出 Java 的基本進程信息，包括環境變量和參數配置，可以查看是否因為一些錯誤的配置造成了 JVM 問題。 * （9）dump 堆信息 ``` ${JDK_BIN}jstat?-gcutil?$PID?>?$DUMP_DIR/jstat-gcutil.dump?2>&1 ${JDK_BIN}jstat?-gccapacity?$PID?>?$DUMP_DIR/jstat-gccapacity.dump?2>&1 ``` jstat 將輸出當前的 gc 信息。一般，基本能大體看出一個端倪，如果不能，可將借助 jmap 來進行分析。 * （10）堆信息 ``` ${JDK_BIN}jmap?$PID?>?$DUMP_DIR/jmap.dump?2>&1 ${JDK_BIN}jmap?-heap?$PID?>?$DUMP_DIR/jmap-heap.dump?2>&1 ${JDK_BIN}jmap?-histo?$PID?>?$DUMP_DIR/jmap-histo.dump?2>&1 ${JDK_BIN}jmap?-dump:format=b,file=$DUMP_DIR/heap.bin?$PID?>?/dev/null??2>&1 ``` jmap 將會得到當前 Java 進程的 dump 信息。如上所示，其實最有用的就是第 4 個命令，但是前面三個能夠讓你初步對系統概況進行大體判斷。 因為，第 4 個命令產生的文件，一般都非常的大。而且，需要下載下來，導入 MAT 這樣的工具進行深入分析，才能獲取結果。這是分析內存泄漏一個必經的過程。 * （11）JVM 執行棧 ``` ${JDK_BIN}jstack?$PID?>?$DUMP_DIR/jstack.dump?2>&1 ``` jstack 將會獲取當時的執行棧。一般會多次取值，我們這里取一次即可。這些信息非常有用，能夠還原 Java 進程中的線程情況。 ``` top?-Hp?$PID?-b?-n?1?-c?>??$DUMP_DIR/top-$PID.dump?2>&1 ``` 為了能夠得到更加精細的信息，我們使用 top 命令，來獲取進程中所有線程的 CPU 信息，這樣，就可以看到資源到底耗費在什么地方了。 * （12）高級替補 ``` kill?-3?$PID ``` 有時候，jstack 并不能夠運行，有很多原因，比如 Java 進程幾乎不響應了等之類的情況。我們會嘗試向進程發送 kill -3 信號，這個信號將會打印 jstack 的 trace 信息到日志文件中，是 jstack 的一個替補方案。 ``` gcore?-o?$DUMP_DIR/core?$PID ``` 對于 jmap 無法執行的問題，也有替補，那就是 GDB 組件中的 gcore，將會生成一個 core 文件。我們可以使用如下的命令去生成 dump： ``` ${JDK_BIN}jhsdb?jmap?--exe?${JDK}java??--core?$DUMP_DIR/core?--binaryheap ``` #### 3. 內存泄漏的現象 稍微提一下 jmap 命令，它在 9 版本里被干掉了，取而代之的是 jhsdb，你可以像下面的命令一樣使用。 ``` jhsdb?jmap??--heap?--pid??37340 jhsdb?jmap??--pid??37288 jhsdb?jmap??--histo?--pid??37340 jhsdb?jmap??--binaryheap?--pid??37340 ``` heap 參數能夠幫我們看到大體的內存布局，以及每一個年代中的內存使用情況。這和我們前面介紹的內存布局，以及在 VisualVM 中看到的 沒有什么不同。但由于它是命令行，所以使用更加廣泛。  histo 能夠大概的看到系統中每一種類型占用的空間大小，用于初步判斷問題。比如某個對象 instances 數量很小，但占用的空間很大，這就說明存在大對象。但它也只能看大概的問題，要找到具體原因，還是要 dump 出當前 live 的對象。  一般內存溢出，表現形式就是 Old 區的占用持續上升，即使經過了多輪 GC 也沒有明顯改善。我們在前面提到了 GC Roots，內存泄漏的根本就是，有些對象并沒有切斷和 GC Roots 的關系，可通過一些工具，能夠看到它們的聯系。 #### 4. 一個卡頓實例 有一個關于服務的某個實例，經常發生服務卡頓。由于服務的并發量是比較高的，所以表現也非常明顯。這個服務和我們第 8 課時的高并發服務類似，每多停頓 1 秒鐘，幾萬用戶的請求就會感到延遲。 我們統計、類比了此服務其他實例的 CPU、內存、網絡、I/O 資源，區別并不是很大，所以一度懷疑是機器硬件的問題。 接下來我們對比了節點的 GC 日志，發現無論是 Minor GC，還是 Major GC，這個節點所花費的時間，都比其他實例長得多。 通過仔細觀察，我們發現在 GC 發生的時候，vmstat 的 si、so 飆升的非常嚴重，這和其他實例有著明顯的不同。 使用 free 命令再次確認，發現 SWAP 分區，使用的比例非常高，引起的具體原因是什么呢？ 更詳細的操作系統內存分布，從 /proc/meminfo 文件中可以看到具體的邏輯內存塊大小，有多達 40 項的內存信息，這些信息都可以通過遍歷 /proc 目錄的一些文件獲取。我們注意到 slabtop 命令顯示的有一些異常，dentry（目錄高速緩沖）占用非常高。 問題最終定位到是由于某個運維工程師執行了一句命令： ``` find?/?|?grep?"x" ``` 他是想找一個叫做 x 的文件，看看在哪臺服務器上，結果，這些老服務器由于文件太多，掃描后這些文件信息都緩存到了 slab 區上。而服務器開了 swap，操作系統發現物理內存占滿后，并沒有立即釋放 cache，導致每次 GC 都要和硬盤打一次交道。 解決方式就是關閉 SWAP 分區。 swap 是很多性能場景的萬惡之源，建議禁用。當你的應用真正高并發了，SWAP 絕對能讓你體驗到它魔鬼性的一面：進程倒是死不了了，但 GC 時間長的卻讓人無法忍受。 #### 5. 內存泄漏  我們再來聊一下內存溢出和內存泄漏的區別。 內存溢出是一個結果，而內存泄漏是一個原因。內存溢出的原因有內存空間不足、配置錯誤等因素。 不再被使用的對象、沒有被回收、沒有及時切斷與 GC Roots 的聯系，這就是內存泄漏。內存泄漏是一些錯誤的編程方式，或者過多的無用對象創建引起的。 舉個例子，有團隊使用了 HashMap 做緩存，但是并沒有設置超時時間或者 LRU 策略，造成了放入 Map 對象的數據越來越多，而產生了內存泄漏。 再來看一個經常發生的內存泄漏的例子，也是由于 HashMap 產生的。代碼如下，由于沒有重寫 Key 類的 hashCode 和 equals 方法，造成了放入 HashMap 的所有對象都無法被取出來，它們和外界失聯了。所以下面的代碼結果是 null。 ``` //leak?example import?java.util.HashMap; import?java.util.Map; public?class?HashMapLeakDemo?{ ????public?static?class?Key?{ ????????String?title; ????????public?Key(String?title)?{ ????????????this.title?=?title; ????????} ????} ????public?static?void?main(String[]?args)?{ ????????Map<Key,?Integer>?map?=?new?HashMap<>(); ????????map.put(new?Key("1"),?1); ????????map.put(new?Key("2"),?2); ????????map.put(new?Key("3"),?2); ????????Integer?integer?=?map.get(new?Key("2")); ????????System.out.println(integer); ????} } ``` 即使提供了 equals 方法和 hashCode 方法，也要非常小心，盡量避免使用自定義的對象作為 Key。倉庫中 dog 目錄有一個實際的、有問題的例子，你可以嘗試排查一下。 再看一個例子，關于文件處理器的應用，在讀取或者寫入一些文件之后，由于發生了一些異常，close 方法又沒有放在 finally 塊里面，造成了文件句柄的泄漏。由于文件處理十分頻繁，產生了嚴重的內存泄漏問題。 另外，對 Java API 的一些不當使用，也會造成內存泄漏。很多同學喜歡使用 String 的 intern 方法，但如果字符串本身是一個非常長的字符串，而且創建之后不再被使用，則會造成內存泄漏。 ``` import?java.util.UUID; public?class?InternDemo?{ ????static?String?getLongStr()?{ ????????StringBuilder?sb?=?new?StringBuilder(); ????????for?(int?i?=?0;?i?<?100000;?i++)?{ ????????????sb.append(UUID.randomUUID().toString()); ????????} ????????return?sb.toString(); ????} ????public?static?void?main(String[]?args)?{ ????????while?(true)?{ ????????????getLongStr().intern(); ????????} ????} } ``` #### 6. 小結 本課時介紹了很多 Linux 命令，用于定位分析問題，所有的命令都是可以實際操作的，能夠讓你詳細地把握整個 JVM 乃至操作系統的運行狀況。其中，jinfo、jstat、jstack、jhsdb（jmap）等是經常被使用的一些工具，尤其是 jmap，在分析處理內存泄漏問題的時候，是必須的。 同時還介紹了保留現場的工具和輔助分析的方法論，遇到問題不要慌，記得隔離保存現場。 接下來我們看了一個實際的例子，由于 SWAP 的啟用造成的服務卡頓。SWAP 會引起很多問題，在高并發服務中一般是關掉它。從這個例子中也可以看到，影響 GC，甚至是整個 JVM 行為的因素，可能不僅限于 JVM 內部，故障排查也是一個綜合性的技能。 最后，我們詳細看了下內存泄漏的概念和幾個實際的例子，從例子中能明顯的看到內存泄漏的結果，但是反向去找這些問題代碼就不是那么容易了。在后面的課時內容中，我們將使用 MAT 工具具體分析這個捉蟲的過程。