概述

有挺長一段時間沒寫技術文章了，正好這兩天美團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。

總結

以上是生活随笔為你收集整理的假笨说-协助美团kafka团队定位到的一个JVM Crash问题的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。