概述

有挺長一段時間沒寫技術文章了，正好這兩天美團kafka團隊有位小夥伴加了我微信，然後諮詢了一個JVM crash的問題，大家對crash的問題都比較無奈，因為沒有現場，資訊量不多，碰到這類問題我們應該怎麼去分析，我想趁這次機會和大家分享一下我針對這種問題的分析過程。

不過我覺得這個分析過程可能會有點繞，因為crash檔案太大，不能讓大家看到crash檔案的全貌而對讓大家理解起來沒那麼有體感，因此您可以先跳到文章最後看一下結論，再回過頭來看整個分析過程或許會更有幫助。

問題初探

首先我要了crash檔案，第一眼當然是看開頭

從這個提示初步來看我們基本猜到是實體記憶體不夠導致的crash，在請求196608bytes

記憶體的時候crash了，於是馬上跑到crash檔案的最後

發現其實實體記憶體是足夠的，還有1G多，怎麼會分配192KB的記憶體都分配不了呢？因此不太可能是實體記憶體不夠導致的。

另外我們注意下這是發生在JDK7上的，JDK8上的提示會有一些不一樣，JDK8上只會在32位的機器上才會有和上面完全一樣的提示內容。

找出問題現場

那接下來我們要找一下發生問題的地方究竟在哪裡？我的第一感覺是看是什麼執行緒上發生的crash，然後再看其棧到底是什麼？於是在crash日誌裡找到了如下內容：

從上面我們看到crash的執行緒是VMThread(JVM裡唯一的一個執行緒，主要用來處理JVM的一些事件，比如GC)，它正在做Full GC，從棧上我們可以看到正在做擴容，不過ConcurrentMarkSweepGeneration

的資料結構在CMS GC下Perm和Old都是用的它，那究竟是哪個呢，我們先看下棧上提到的GenCollectedHeap::do_collection這個方法，找到其呼叫compute_new_size方法的地方

我們暫時無法確認到底呼叫的是上面那個compute_new_size，還是下面那個，如果是下面那個，那就可以確認是Perm擴容所致，如果是上面那個，那就是old擴容所致。

為了進一步確認，我們此時應該看下JVM引數

從上面的JVM引數可以看到我們設定了Xmx和Xms相等，並且還設定了Xmn，那Old的Size是固定的，這樣一來基本可以排除是Old擴容所致，並且我們發現沒有設定PermSize

和MaxPermSize，這樣肯定是存在擴容操作的，因為它們預設不相等，因此可以斷定是Perm擴容的時候發生了crash

至此我們可以確定當時的場景是：發生了一次Full GC，在Full GC完之後根據當時的實際情況會對各個記憶體分代重新設定分代大小進行擴容，在對Perm擴容的時候發生了crash，Perm擴容其實就是做了一次mmap的操作：

從上面的程式碼，我們進入到warn_fail_commit_memory這個方法

理論上我們其實是會在標準輸出裡列印上面的內容，不過從業務方那得知，他們將標準輸出重定向到了/dev/null，因此上面那行日誌就看不到了，如果能看到上面的日誌，那至少我們知道mmap發生的具體errno是什麼，從而斷定mmap到底是為什麼失敗了。於是叫業務方將標準輸出重定向到一個固定的檔案裡看具體的異常。

到現在好像基本上斷了思路，只能等待引數修改之後看看其效果。

結合GC日誌再探問題

我忙完一些事情後又想起這個案例，於是繼續看這個crash日誌，看到了crash的那個點，是發生了Full GC，而這個Full GC是GenCollectFull，這個就比較特殊了，因為它發生的場景主要是三種：

• JVMTI的強制GC
• System GC
• GC Locker

 

第一個基本可以排除，因為一般情況下都不會有這種agent來做這個，那下面兩種情況怎麼確定呢？如果有GC日誌就好了，於是找業務方要了GC日誌，比較可惜的是這個系統跑在JDK7上，GCCause並沒有預設開啟，因此我們從GC日誌上看不到GC的原因，如果是JDK8，那在GC日誌裡是能看到System.gc的關鍵字來表明是System.gc觸發的，GC Locker也同樣可以看到相關的關鍵字。不過因為JDK引數裡沒有顯示開啟GCCause(-XX:+PrintGCCause)，於是最後那條GC日誌我們只能看到如下內容：

這條GC日誌還沒有打完，因為此時發生了crash，從這個GC日誌看，老生代使用率其實很低的(5891510K/20971520K=28%)，是不是超過了CMS的閾值？於是我們看上面的JVM引數裡果然看到了CMSInitiatingOccupancyFraction設定為30，那就是老生代使用率達到30%會觸發一次background CMS GC，不過目前還沒達到CMS GC發生的條件，而且從整個GC日誌來看，CMS GC的次數並不多，因此基本可以排除記憶體碎片的問題，因為這次要申請的記憶體其實還是很小的，那這麼一說是不是可能是GC Locker導致的呢，看起來也不應該，這個要結合上一條GC日誌來看，上一條GC日誌是

和下一條Full GC相差了蠻久（2069977.519-2069794.281=183.238s），這期間新生代和老生代使用率都不高，可以結合crash日誌裡的下面內容斷定

在Full GC之前，eden使用率也只有55%，因此不太可能在這個期間存在跨GC的情況，因此GC Locker基本沒可能。

那最有可能的就是System GC了，那什麼情況會導致System GC的發生呢？

稍微總結下以前主要碰到的幾種會觸發System GC的情況：

• 程式碼裡顯示呼叫
• RMI裡定時呼叫
• 堆外記憶體不夠導致的呼叫

 

這幾種可能基本都可以排除

• 系統是kafka，是scala寫的，我特地下載了scala的原始碼下來，基本沒有這種顯示呼叫System GC的邏輯；
• RMI也不可能，因為我們從執行緒列表裡看不到GC Deamon執行緒，因此不存在這種check的呼叫；
• 堆外記憶體(主要是說DirectByteBuffer這種)也不太可能，因為我們從JVM引數來看，第一沒有顯示設定最大值MaxDirectMemorySize，第二Xmx設定有24G，那預設的堆外記憶體最大值基本也有差不多這麼大(Xmx除去一個survivor的大小)，後面再結合看了下top命令看到的資料的值，實體記憶體總共都才使用了7G左右，所以堆外記憶體滿了而導致的System GC也基本可以排除。

 

所以我再次翻了下JDK的程式碼，尋找可能丟擲System GC的情況，結果發現了sun.nio.ch.FileChannelImpl的map方法裡有類似的邏輯

會不會是這裡發生的呢？

確定問題現場

為了確定是否有類似的邏輯呼叫，於是我在kafka的原始碼裡搜尋了map的邏輯呼叫，果然看到大量的地方呼叫

似乎柳暗花明了，找業務方確認，還真得知有大量的索引檔案對映，並且都是大於1G的，於是我們是否可以設想這麼一個場景：kafka對映一個大檔案，結果失敗了，然後丟擲了一個OOM的異常，在catch到這個OOM的異常之後，主動觸發了一次System.gc，從而這就是當時crash發生的整個現場。

我們從crash日誌裡找到了類似的日誌

這個時間點和Full GC的時間點基本一致，差不多可以認為是上面這個事件發生的時候接著做了一次Full GC，那基本可以篤定jni.cpp:743應該是一個OOM的異常處理，於是我找到這個JDK版本的這行程式碼的位置，驗證確實如此

因此基本也確定業務系統是直到這個地方發生了crash，要驗證這個只能是有那個時候的執行緒，比如有crash時候的heapdump或者coredump，然後找到引發Full GC的那個執行緒，看它的呼叫棧是不是正好在做這塊的操作。

確定根本原因

問題發生的點確認了，那接下來我們要尋找根本原因，我們看下sun.nio.ch.FileChannelImpl.map0的native方法實現Java_sun_nio_ch_FileChannelImpl_map0，因為這是觸發crash的地方，然後看到下面的邏輯

因為確實是丟擲了一個OOM的異常，因此我們這裡完全可以確定mmap返回的errno是ENOMEM，所以我們在前面提出的，想把標準輸出打印出來以確認具體的mmap異常，從這個地方也基本可以確認mmap就是因為返回了ENOMEM這個錯誤碼，我們先看下mmap的手冊裡關於ENOMEM的介紹

因為我們確認了實體記憶體是足夠的，因此我們只能懷疑是否達到了mappings的最大個數，我們再結合下kernel裡的mmap的實現（mmap.c:do_mmap）

當mmap的vma個數達到了最大值的時候確實也會返回ENOMEM，於是我們要業務方確認下/proc/sys/vm/max_map_count的值，結果發現是65530，也就是說我們mmap的vma最多隻能是65530個，我們再結合下crash日誌裡虛擬地址對映的個數，正好達到了這個上限了，具體可以看看Dynamic libraries下面的條數有多少基本就是mmap的vma的個數。

至此我們完全確認了整個問題。

問題解決

從上面分析解決問題的方法有兩個

• 增大系統限制/proc/sys/vm/max_map_count
• kafka的索引檔案是否不需要一直有？是否可以限制一下

問題總結

上面的過程是我思考的一個過程，可能過程有些繞，不過我這裡可以來個簡單的概述，描述下整個問題發生的過程：

kafka做了很多索引檔案的記憶體對映，每個索引檔案佔用的記憶體還很大，這些索引檔案並且一直佔著沒有釋放，於是隨著索引檔案數的增多，而慢慢達到了實體記憶體的一個上限，比如對映到某個索引檔案的時候，實體記憶體還剩1G，但是我們要對映一個超過1G的檔案，因此會對映失敗，對映失敗接著就做了一次System GC，而在System GC過程中因為PermSize和MaxPermSize不一樣，從而導致了在Full GC完之後Perm進行擴容，在擴容的時候因為又呼叫了一次mmap，而在mmap的時候check是否達到了vma的最大上限，也就是/proc/sys/vm/max_map_count裡的65530，如果超過了，就直接crash了。

這只是我從此次crash檔案裡能想像到的一個現場，當然其實可能會有更多的場景，只要是能觸發mmap動作的地方都有可能是導致crash的案發現場，比如後面又給了我一個crash檔案，是在建立執行緒棧的時候因為mmap而導致的crash，完全和OOM沒有關係，所以根本原因還是因為kafka做了太多的索引檔案對映，導致mmap的vma非常多，超過了系統的限制，從而導致了crash。