記一次解決tomcat自動關閉的bug

alunbar發表於2019-08-14
Tomcat

最近一個執行了4年的javaee web專案，經常接到客戶反饋系統無法開啟。登入伺服器檢視服務，發現是tomcat自動關閉了。基本是3到4天發生一次。

運維人員開始以為是其他服務殺死了tomcat服務，沒放在心上，解決方法就是直接重啟tomcat。

最終捅了簍子，運維人員被客戶投訴，扣了一個月的績效。

解決這個bug兜兜轉轉來到了我這裡。既然接到任務，那就開幹，沒有解決不了的bug。

系統的執行環境如下：
tomcat6.0
32位jdk7.0
window server2003 32位，32G記憶體。

檢視日誌，如果tomcat閃崩，都會在tomcat的bin目錄下生成以"hs_err"開頭的日誌檔案。開啟最新的日誌檔案，首先看到的是下面一段話：

# There is insufficient memory for the Java Runtime Environment to continue.
# Native memory allocation (malloc) failed to allocate 32756 bytes for ChunkPool::allocate
# Possible reasons:
#   The system is out of physical RAM or swap space
#   In 32 bit mode, the process size limit was hit
# Possible solutions:
#   Reduce memory load on the system
#   Increase physical memory or swap space
#   Check if swap backing store is full
#   Use 64 bit Java on a 64 bit OS
#   Decrease Java heap size (-Xmx/-Xms)
#   Decrease number of Java threads
#   Decrease Java thread stack sizes (-Xss)
#   Set larger code cache with -XX:ReservedCodeCacheSize=
# This output file may be truncated or incomplete.
#
#  Out of Memory Error (allocation.cpp:211), pid=7864, tid=6556
#
# JRE version: Java(TM) SE Runtime Environment (7.0_79-b15) (build 1.7.0_79-b15)
# Java VM: Java HotSpot(TM) Server VM (24.79-b02 mixed mode windows-x86 )
# Failed to write core dump.

大概意思就是記憶體不夠了，無法分配32756位元組的空間。同時給出幾個解決方法：
1、減少系統記憶體負載；
2、增加實體記憶體或者交換空間；
3、在64位作業系統上使用64位jdk；
4、減少java heap大小；
5、減少java執行緒數量；
6、減少java執行緒堆疊大小。

通過上面的內容可以得出，jvm無法分配32756 bytes的記憶體空間。

從接到任務開始，我一直以為是jvm配置出錯，導致記憶體不夠用，只需調整下新生代、老年代的配置即可。

繼續往下看日誌檔案，找到"GC Heap History (10 events):"這一行，這個記錄jvm最後10次垃圾回收時堆的變化情況。

GC Heap History (10 events):
Event: 572312.299 GC heap before
{Heap before GC invocations=5046 (full 357):
 PSYoungGen      total 201472K, used 200685K [0x573c0000, 0x63bc0000, 0x63bc0000)
  eden space 198144K, 100% used [0x573c0000,0x63540000,0x63540000)
  from space 3328K, 76% used [0x63540000,0x637bb528,0x63880000)
  to   space 3328K, 0% used [0x63880000,0x63880000,0x63bc0000)
 ParOldGen       total 843776K, used 422602K [0x23bc0000, 0x573c0000, 0x573c0000)
  object space 843776K, 50% used [0x23bc0000,0x3d872b18,0x573c0000)
 PSPermGen       total 262144K, used 51848K [0x03bc0000, 0x13bc0000, 0x23bc0000)
  object space 262144K, 19% used [0x03bc0000,0x06e62138,0x13bc0000)
Event: 572312.305 GC heap after
Heap after GC invocations=5046 (full 357):
 PSYoungGen      total 201472K, used 1103K [0x573c0000, 0x63bc0000, 0x63bc0000)
  eden space 198144K, 0% used [0x573c0000,0x573c0000,0x63540000)
  from space 3328K, 33% used [0x63880000,0x63993c90,0x63bc0000)
  to   space 3328K, 0% used [0x63540000,0x63540000,0x63880000)
 ParOldGen       total 843776K, used 423618K [0x23bc0000, 0x573c0000, 0x573c0000)
  object space 843776K, 50% used [0x23bc0000,0x3d970b18,0x573c0000)
 PSPermGen       total 262144K, used 51848K [0x03bc0000, 0x13bc0000, 0x23bc0000)
  object space 262144K, 19% used [0x03bc0000,0x06e62138,0x13bc0000)
}
Event: 572351.132 GC heap before
{Heap before GC invocations=5047 (full 357):
 PSYoungGen      total 201472K, used 199247K [0x573c0000, 0x63bc0000, 0x63bc0000)
  eden space 198144K, 100% used [0x573c0000,0x63540000,0x63540000)
  from space 3328K, 33% used [0x63880000,0x63993c90,0x63bc0000)
  to   space 3328K, 0% used [0x63540000,0x63540000,0x63880000)
 ParOldGen       total 843776K, used 423618K [0x23bc0000, 0x573c0000, 0x573c0000)
  object space 843776K, 50% used [0x23bc0000,0x3d970b18,0x573c0000)
 PSPermGen       total 262144K, used 51848K [0x03bc0000, 0x13bc0000, 0x23bc0000)
  object space 262144K, 19% used [0x03bc0000,0x06e62138,0x13bc0000)
Event: 572351.137 GC heap after
Heap after GC invocations=5047 (full 357):
 PSYoungGen      total 201472K, used 1615K [0x573c0000, 0x63bc0000, 0x63bc0000)
  eden space 198144K, 0% used [0x573c0000,0x573c0000,0x63540000)
  from space 3328K, 48% used [0x63540000,0x636d3ec8,0x63880000)
  to   space 3328K, 0% used [0x63880000,0x63880000,0x63bc0000)
 ParOldGen       total 843776K, used 423674K [0x23bc0000, 0x573c0000, 0x573c0000)
  object space 843776K, 50% used [0x23bc0000,0x3d97eb18,0x573c0000)
 PSPermGen       total 262144K, used 51848K [0x03bc0000, 0x13bc0000, 0x23bc0000)
  object space 262144K, 19% used [0x03bc0000,0x06e62138,0x13bc0000)
}
Event: 572398.649 GC heap before
{Heap before GC invocations=5048 (full 357):
 PSYoungGen      total 201472K, used 199759K [0x573c0000, 0x63bc0000, 0x63bc0000)
  eden space 198144K, 100% used [0x573c0000,0x63540000,0x63540000)
  from space 3328K, 48% used [0x63540000,0x636d3ec8,0x63880000)
  to   space 3328K, 0% used [0x63880000,0x63880000,0x63bc0000)
 ParOldGen       total 843776K, used 423674K [0x23bc0000, 0x573c0000, 0x573c0000)
  object space 843776K, 50% used [0x23bc0000,0x3d97eb18,0x573c0000)
 PSPermGen       total 262144K, used 51848K [0x03bc0000, 0x13bc0000, 0x23bc0000)
  object space 262144K, 19% used [0x03bc0000,0x06e62138,0x13bc0000)
Event: 572398.655 GC heap after
Heap after GC invocations=5048 (full 357):
 PSYoungGen      total 201472K, used 1998K [0x573c0000, 0x63bc0000, 0x63bc0000)
  eden space 198144K, 0% used [0x573c0000,0x573c0000,0x63540000)
  from space 3328K, 60% used [0x63880000,0x63a73830,0x63bc0000)
  to   space 3328K, 0% used [0x63540000,0x63540000,0x63880000)
 ParOldGen       total 843776K, used 423703K [0x23bc0000, 0x573c0000, 0x573c0000)
  object space 843776K, 50% used [0x23bc0000,0x3d985cc0,0x573c0000)
 PSPermGen       total 262144K, used 51848K [0x03bc0000, 0x13bc0000, 0x23bc0000)
  object space 262144K, 19% used [0x03bc0000,0x06e62138,0x13bc0000)
}
Event: 576881.689 GC heap before
{Heap before GC invocations=5049 (full 357):
 PSYoungGen      total 201472K, used 200142K [0x573c0000, 0x63bc0000, 0x63bc0000)
  eden space 198144K, 100% used [0x573c0000,0x63540000,0x63540000)
  from space 3328K, 60% used [0x63880000,0x63a73830,0x63bc0000)
  to   space 3328K, 0% used [0x63540000,0x63540000,0x63880000)
 ParOldGen       total 843776K, used 423703K [0x23bc0000, 0x573c0000, 0x573c0000)
  object space 843776K, 50% used [0x23bc0000,0x3d985cc0,0x573c0000)
 PSPermGen       total 262144K, used 51850K [0x03bc0000, 0x13bc0000, 0x23bc0000)
  object space 262144K, 19% used [0x03bc0000,0x06e62850,0x13bc0000)
Event: 576881.696 GC heap after
Heap after GC invocations=5049 (full 357):
 PSYoungGen      total 201472K, used 3155K [0x573c0000, 0x63bc0000, 0x63bc0000)
  eden space 198144K, 0% used [0x573c0000,0x573c0000,0x63540000)
  from space 3328K, 94% used [0x63540000,0x63854cb0,0x63880000)
  to   space 3328K, 0% used [0x63880000,0x63880000,0x63bc0000)
 ParOldGen       total 843776K, used 423703K [0x23bc0000, 0x573c0000, 0x573c0000)
  object space 843776K, 50% used [0x23bc0000,0x3d985cc0,0x573c0000)
 PSPermGen       total 262144K, used 51850K [0x03bc0000, 0x13bc0000, 0x23bc0000)
  object space 262144K, 19% used [0x03bc0000,0x06e62850,0x13bc0000)
}
Event: 580535.452 GC heap before
{Heap before GC invocations=5050 (full 357):
 PSYoungGen      total 201472K, used 201299K [0x573c0000, 0x63bc0000, 0x63bc0000)
  eden space 198144K, 100% used [0x573c0000,0x63540000,0x63540000)
  from space 3328K, 94% used [0x63540000,0x63854cb0,0x63880000)
  to   space 3328K, 0% used [0x63880000,0x63880000,0x63bc0000)
 ParOldGen       total 843776K, used 423703K [0x23bc0000, 0x573c0000, 0x573c0000)
  object space 843776K, 50% used [0x23bc0000,0x3d985cc0,0x573c0000)
 PSPermGen       total 262144K, used 51856K [0x03bc0000, 0x13bc0000, 0x23bc0000)
  object space 262144K, 19% used [0x03bc0000,0x06e64228,0x13bc0000)
Event: 580535.459 GC heap after
Heap after GC invocations=5050 (full 357):
 PSYoungGen      total 200960K, used 1858K [0x573c0000, 0x63bc0000, 0x63bc0000)
  eden space 197632K, 0% used [0x573c0000,0x573c0000,0x634c0000)
  from space 3328K, 55% used [0x63880000,0x63a50be0,0x63bc0000)
  to   space 3584K, 0% used [0x634c0000,0x634c0000,0x63840000)
 ParOldGen       total 843776K, used 423703K [0x23bc0000, 0x573c0000, 0x573c0000)
  object space 843776K, 50% used [0x23bc0000,0x3d985cc0,0x573c0000)
 PSPermGen       total 262144K, used 51856K [0x03bc0000, 0x13bc0000, 0x23bc0000)
  object space 262144K, 19% used [0x03bc0000,0x06e64228,0x13bc0000)
}

看了上面的內容，並沒有發現tomcat閃崩是由於老年代，持久代，新生代空間不足引起的。有好幾次因為eden區空間使用到100%引起的full gc，但是垃圾回收過後eden區的空間都恢復到正常的水平。

日誌中還記錄了tomcat閃崩時heap堆的使用情況：

Heap
 PSYoungGen      total 200960K, used 95671K [0x573c0000, 0x63bc0000, 0x63bc0000)
  eden space 197632K, 47% used [0x573c0000,0x5cf5d230,0x634c0000)
  from space 3328K, 55% used [0x63880000,0x63a50be0,0x63bc0000)
  to   space 3584K, 0% used [0x634c0000,0x634c0000,0x63840000)
 ParOldGen       total 843776K, used 423703K [0x23bc0000, 0x573c0000, 0x573c0000)
  object space 843776K, 50% used [0x23bc0000,0x3d985cc0,0x573c0000)
 PSPermGen       total 262144K, used 51856K [0x03bc0000, 0x13bc0000, 0x23bc0000)
  object space 262144K, 19% used [0x03bc0000,0x06e64228,0x13bc0000)

一切都那麼正常，同時又那麼詭異。

翻看了之前發生日誌，內容都是大同小異。

重新翻看了幾遍日誌，這次把重點放在日誌中建議的解決方案上：

#   Reduce memory load on the system
#   Increase physical memory or swap space
#   Check if swap backing store is full
#   Use 64 bit Java on a 64 bit OS
#   Decrease Java heap size (-Xmx/-Xms)
#   Decrease number of Java threads
#   Decrease Java thread stack sizes (-Xss)

其中下面幾個解決方案不採用：

  • Reduce memory load on the system。 系統記憶體夠用，32G的記憶體，還剩20G沒用，無需減少記憶體。
  • Increase physical memory or swap space。 系統記憶體夠用，32G的記憶體，還剩20G沒用，無需增加實體記憶體。
  • Use 64 bit Java on a 64 bit OS。 32位作業系統，無法使用64位jdk。

只剩下下面的三個解決方案了：

  • Decrease Java heap size (-Xmx/-Xms)。 heap堆設定過大，就會影響剩餘記憶體。
  • Decrease number of Java threads
  • Decrease Java thread stack sizes (-Xss)

而減少java執行緒的數量，需要修改程式碼，這個也不實際。

最後只剩下

  • Decrease Java heap size (-Xmx/-Xms)
  • Decrease Java thread stack sizes (-Xss)

這兩個解決方案了，就從這裡入手，曙光就在前方。

先看 Decrease Java thread stack sizes (-Xss) 解決方案

java執行緒執行也是需要記憶體空間的，-Xss引數指定每個執行緒堆疊的大小，為jvm啟動的每個執行緒分配的記憶體大小。在jdk1.4版本中是256K，JDK1.5及以上版本是1M。

tomcat jvm的引數設定如下：

JAVA_OPTS=%JAVA_OPTS% -server -Xms1024m -Xmx1024m -Xmn200M -XX:PermSize=256M -XX:MaxPermSize=512m -XX:SurvivorRatio=1 -Xss256k

已經通過-Xss設定每個java執行緒堆疊的大小為256K。

在java語言裡， 當你建立一個執行緒的時候，虛擬機器會在JVM記憶體建立一個Thread物件同時建立一個作業系統執行緒，而這個系統執行緒的記憶體用的不是JVMMemory，而是系統中剩下的記憶體(MaxProcessMemory - JVMMemory - ReservedOsMemory)。

當需要建立執行緒，而作業系統剩餘記憶體不夠分配給一個java執行緒時，就會報Out of Memory Error的錯誤。

由於已經設定通過-Xss設定java執行緒棧的大小為256K，因此也決定不採用這個解決方案。

現在只剩 下Decrease Java heap size (-Xmx/-Xms) 這個解決方案了。通過減少堆的大小，而留出足夠的記憶體空間給java執行緒堆疊使用。

32位的window作業系統給每個程式分配的記憶體空間是2G，減去堆的最大容量和PermSize的最大容量，剩下的容量就留給java執行緒棧使用。

經過分析程式碼和之前錯誤的日誌，發現一般在350個執行緒這樣就出現Out of Memory Error的錯誤。
在出現錯誤時，heap空間才用了不到40%。因此決定將java heap的從1G減少到768M。

修改的jvm引數如下：

JAVA_OPTS=%JAVA_OPTS% -server -Xms768m -Xmx768m -Xmn200M -XX:PermSize=256M -XX:MaxPermSize=512m -XX:SurvivorRatio=1 -Xss256k

到目前為止，系統已經穩定執行1個月，各個引數指標都在正常範圍內。heap使用率最高才70%。

總結：
1、經過這次解決bug，加深了對java虛擬機器的瞭解，特別是執行緒棧，記憶體堆，持久代，新生代等概念。
2、一定要仔細閱讀日誌檔案，一步一步排除掉潛在的解決方案。綜合系統的執行環境，找出合理的解決方案。

相關文章