记一次解决tomcat自动关闭的bug

最近一个运行了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、一定要仔细阅读日志文件,一步一步排除掉潜在的解决方案。综合系统的运行环境,找出合理的解决方案。

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 202,406评论 5 475
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 84,976评论 2 379
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 149,302评论 0 335
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,366评论 1 273
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,372评论 5 363
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,457评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,872评论 3 395
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,521评论 0 256
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,717评论 1 295
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,523评论 2 319
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,590评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,299评论 4 318
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,859评论 3 306
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,883评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,127评论 1 259
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 42,760评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,290评论 2 342

推荐阅读更多精彩内容