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

  • 2019 年 10 月 3 日
  • 筆記

最近一個運行了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、一定要仔細閱讀日誌文件，一步一步排除掉潛在的解決方案。綜合系統的運行環境，找出合理的解決方案。

VirMach 便宜 VPS

QNews

QNews