某java服務異常退出原因排查

背景

周日的時候，測試環境的一臺java服務進程（以下簡稱A服務）異常退出。該情況在上周日就已經出現過一次，但是那次沒有在意，只是以為是有人登陸了這臺服務器將服務給停了。可是這次又出現了，說明這是一個問題，而不是偶然現象。咨詢了運維小伙伴后，通過查閱/var/log/messages日志，可以看到是因為操作系統內存耗盡，觸發了OOM killer，殺死了A服務。并且我們同時也看到了上周日也是因為觸發了OOM killer，導致進程被OS殺死：

......
Aug 5 21:11:25 iZ233ufr4soZ kernel: Out of memory: Kill process 18923 (java) score 558 or sacrifice child
Aug 5 21:11:25 iZ233ufr4soZ kernel: Killed process 18923, UID 0, (java) total-vm:1638524kB, anon-rss:597908kB, file-rss:100kB

從日志中我們可以看到，A服務占用了操作系統大量的內存導致無法給其他應用程序分配內存。當時第一直覺是A服務發生了內存泄漏（后來證明第一直覺是錯的）。關于內存泄露的文章網上有一大堆，簡而言之就是 JVM里創建了大量的無法被垃圾回收但是不再被使用的對象 。在這里首先需要聲明兩點：

1. 內存泄露和內存溢出是兩個不同的概念。內存泄露關心的是無用對象，內存泄漏最終會導致內存溢出。除了內存泄露，在瞬時讀取大量數據至內存中也是會導致內存溢出的，比如數據庫返回大量的對象，或者讀取了一張很大的圖片在內存中。
2. 垃圾收集算法普遍有兩種，一種是引用計數（PHP），另一種是根搜索或者可達性分析。java采用的就是這種，具體算法網上文章一大堆，這里就不再贅述了。簡而言之就是如果能夠從根開始往下找到這個對象，那么這個對象就還有用，就不該回收。該方法可以有效解決循環引用。

經典的、常見的內存泄漏的原因有以下幾個方面：

1. 靜態的集合類：由于這些變量的生命周期與應用程序保持一致，所以會導致這些類中的對象就算被手動置為null，也無法被釋放。
2. 單例：同1，單例類的生命周期與應用程序也保持一致，如果單例類中也保持了某些對象，那么這些對象也是無法被回收的。
3. 各種連接、IO：這些操作都是十分消耗資源的，如果忘記了關閉，比如忘記關閉數據庫連接，那么也是會發生內存泄漏的情況。
4. threadlocal：由于threadlocal變量的生命周期與線程保持一致，當與線程池結合使用時，由于線程使用完畢后不會銷毀，所以threadlocal變量可能也會出現泄漏的情況。
5. 其他：比如監聽器，外部模塊調用等。。

Heap Dump

大體上所有的內存泄露的原因都可以通過研究Heap Dump文件（堆轉儲）來解決。JVM可以通過jmap命令dump出當前的heap快照，通常后綴名為.hprof。JVM支持在OOM時，dump出當前的heap，便于開發人員分析為何出現了OOM。

看了一下我們當前的啟動腳本，發現沒有添加導出HeapDump文件的參數。所以在 所有的啟動語句中加上了 -XX:+HeapDumpOnOutOfMemoryError ，當JVM發生OOM時，可以自動地導出HeapDump文件。但是發現該參數沒有起作用，經過仔細研究之后發現， 操作系統層級的OOM killer是不會觸發HeapDumpOnOutOfMemoryError ，因為OOM killer直接殺死JVM進程，不會給你JVM任何機會，比如導出Heap，或者執行一些其他hook命令。但是當時并沒有意識到這一點，只是接著往下走，也因此走了很多彎路。

定位內存泄露的核心思路是 通過兩份及以上的快照比對，查看是否有某些對象一直在增多，如果有的話，那么很可能發生了內存泄漏 。為了研究hprof文件，我們需要借助MAT（Eclipse Memory Analyzer Tool）。該工具的用法十分簡單，照著網上的教程學一下就會。導入之后我們可以看到：

MAT覺得可能是數據庫連接發生了泄漏。然后點擊Overview > Dominator Tree，并且按照class進行group by之后我們可以看到確實數據庫連接占用了很多內存：

我的天，一共有180個。但是我馬上冷靜下來，確實是有180個，因為目前測試環境一共有6個庫，A服務在啟動的時候會默認每個庫建立30個連接，一共180個。為了證實我的想法，點擊右鍵，查看對象的所有GC路徑：

查看結果后，確實如此。由此可見數據庫連接是十分消耗資源的，在測試環境上，我們默認啟動的連接數應該要縮小，否則會占用大量的內存。

那么是否發生了泄露呢，這時需要用到MAT的baseline比較功能，該功能是用來比較兩個快照之間是否有對象數量和大小的變化。如果發生了內存泄漏，那么會存在一個對象的數量一直增多的情況。但是經過比較之后我發現，數據庫連接只是占用了大量的內存，并沒有出現異常增多的情況，并且其他對象類型也是一樣，程序跑得十分穩定而又正常。

JProfiler

到了這一步，我開始懷疑其實A服務沒有內存泄露的代碼。那么如果沒有內存泄露的話，為什么會占用這么高的內存呢？其實這個問題仔細想想，答案很簡單，但是當時方向還是錯了，我覺得還是有哪些地方可能出現了內存泄漏，所以上了profile工具。java世界中的profile工具首推JProfiler，網上可以下載破解版（付費的實在是太貴了）。通過JProfiler，我們可以實時監測JVM的一舉一動。該工具十分好用，并且界面做的十分好看，推薦大家使用。PS：其實JProfiler包含了MAT的所有功能，只是MAT更加簡潔，而且還免費。

通過JProfiler可以看到，我們的內存波動十分正常，并沒有出現內存占用越來越多的情況，否則藍色的曲線應該是呈上升趨勢。下圖中，藍色的線表示當前占用的內存，綠色的線表示當前heap的大小：

最后

由此可見，A服務其實沒有存在內存泄漏。回過頭來看，其實我們的OOM發生在操作系統層，和我們平時遇到的JVM的OOM是不一樣的。這里需要介紹一下OOM killer：操作系統在給應用程序分配內存時，采用的是over-commit策略，即無論應用需要多少內存，操作系統都會允許，即使超過了目前剩余的容量，操作系統依然允許。這是因為操作系統覺得大部分的應用程序并不會用滿他自己聲明的內存。但是還是可能會出現大家都用滿了自己聲明的內存的情況，這個時候操作系統如果不釋放內存出來，很可能連自己都無法運行了，所以這個時候操作系統就會叫OOM killer過來，給所有的進程打分，選出得分最高者，直接kill掉。一般都是內存占用最高的進程被kill掉。

那么A服務為什么會占用這么多內存呢？當我們排除了“內存泄露”這個原因，那么只可能是A服務確實占用了這么多內存。通過 java -XX:+PrintFlagsFinal -version | grep -iE 'HeapSize|PermSize|ThreadStackSize' ，我們可以看到A服務的測試機上的默認JVM配置：

uintx AdaptivePermSizeWeight = 20 {product}
intx CompilerThreadStackSize = 0 {pd product}
uintx ErgoHeapSizeLimit = 0 {product}
uintx HeapSizePerGCThread = 87241520 {product}
uintx InitialHeapSize := 16297600 {product}
uintx LargePageHeapSizeThreshold = 134217728 {product}
uintx MaxHeapSize := 522190848 {product}
uintx MaxPermSize = 174063616 {pd product}
uintx PermSize = 21757952 {pd product}
intx ThreadStackSize = 1024 {pd product}
intx VMThreadStackSize = 1024 {pd product}

我們可以看到，在這臺內存僅有1G的服務器上，MaxHeapSize竟然達到了500兆。由于A服務的不斷運行，遲早有一天會吃滿整個HeapSize，由于JVM不會自動歸還HeapSize，就算你實際使用的heap大小只有一點點，操作系統還是認為你占用了這么多的HeapSize。所以這就解釋了為什么我們需要一周的時間才會發生這個場景，那是因為由初始的HeapSize達到MaxHeapSize需要長時間的運行以積累足夠的對象觸發JVM的Heap擴展策略。也解釋了在每次進程消失的時間點，我們實際上沒有做什么消耗資源的操作，但進程還是退出了，那是因為操作系統只認你占領的內存空間，并不會管你實際使用了多少空間。

按照JVM默認的策略，MaxHeapSize默認是四分之一的內存空間，InitialHeapSize是64分之一的內存空間大小，這臺機器之所以有500M的大小，會不會跟內存降過級有關（2G->1G），這就不得而知了。

所以現在要復現問題也很簡單。開啟A服務，并且啟動壓力測試，讓他瞬間吃滿MaxHeapSize，然后再隨便開啟一個也占用較多資源的應用（比如Mysql），這個時候就會發現A服務又被殺死了，并且/var/log/messages中打出了相應的日志。

具體地解決方案：

1. 測試環境默認創建的線程數以及連接數需要往小設，因為測試環境不會有這么多的并發。
2. 手動配置JVM的最大堆（-Xmx）和初始堆（-Xms）的大小，具體大小值需要根據實際情況而定，設置地太大容易被OOM killer殺掉，設置地太小容易發生十分頻繁的GC操作。在測試環境中，可以盡量往小配置，避免其他應用影響。
3. 加上 -XX:+HeapDumpOnOutOfMemoryError ，便于在JVM發生OOM時，可以還原“事故現場”。

PS：由于一個java應用是單進程程序，所以當OOM killer選擇了java的時候，整個java世界就會瞬間崩塌，JVM無法做任何響應就退出了，無法做任何gracefully shutdown，也不會有任何日志文件寫出。如果從這個方面來看的話，PHP的多進程思路是優于java應用的。

總結

查看日志

當某一java應用程序意外退出時，先查看日志信息，具體的日志有以下幾個：

1. /var/log/messages*：查看系統內核日志，判斷是否被OOM killer殺死。如果是的話，那么說明系統內存資源緊張。此時可以通過日志查看當時列出來的所有占用內存較多的進程，kill掉一些無關的進程節省內存空間。并且通過調小 -Xmx 參數，或者將自己納入OOM killer的白名單，避免因為排名過高被意外殺死。
2. ./java_pid.hprof：查看heap dump信息。如果JVM啟動時配置了 -XX:+HeapDumpOnOutOfMemoryError ，并且沒有指定其他路徑，那么可以在當前目錄下找到hprof文件。利用MAT等其他工具進行分析，查看是哪些對象占用了較多的內存導致JVM無法繼續分配內存。
3. ./hs_err_pid.log：查看JVM崩潰信息。比如應用程序當無法再申請到服務器資源，或者JNI調用錯誤的時候，就會出現JVM崩潰錯誤，那么默認在當前目錄下可以找到hs_err_pid.log文件。
4. /var/log/xxx/xxx.log：查看應用自身日志。某些情況可能是系統自身調用了System.exit函數，此時需要查看自身日志。

定位問題

通過查看日志之后，確定是由于內存溢出導致的，那么需要判斷是否是因為內存泄露導致的。我們可以先分析JVM退出時dump出來的堆轉儲文件，若存在著大量數量異常多的無用對象，那么肯定是發生了內存泄露。

定位內存泄露的思路十分簡單，就是通過Jmap或者其他工具按照一定的時間間隔dump出heap，然后通過MAT或其他工具來進行比較分析。若發現有某個對象，隨著時間增長在不停地變多，而該對象理應被GC回收，那么就是該對象發生了內存泄漏。此時我們可以查看該對象的GC root，找到引用該對象的根位置，從而定位問題。

若覺得MAT不是很好用，還可以使用更加高級的JProfiler工具。

其他

綜上所述，其實整個問題是一個參數配置的問題。參數配置的問題始終是一個難題。每一個參數的配置，最后組合在一起會形成質變的效果。深入了解每個模塊可配置的參數的含義，多做壓力測試，可以方便我們提前找到問題。

參考資料

1. jprofiler如何進行遠程監控
2. jvm相關參數
3. 診斷java的內存泄露
4. MAT使用入門
5. OOM killer
6. Find out your jvm heap size
7. 深入研究JVM
8. OOM未導出hprof文件

 

來自：http://www.kissyu.org/2016/08/09/某java服務異常退出原因排查/