In case of 40G JVM core dump…

好久不收拾,这里都长草了。先广告一下,弄了一个shawnma.com的域名(其实去年就申请了,然后就给忘了,浪费了50元啊!),以后shawnma.xomud.com就不搞了,xomud.com我也不打算续了,有人想要么,可以转让,哈。

这是一个很久以前写了一半的东西(从URL来看,去年11月),坚持写完:

—- 跟时髦的分割线 —

最近公司的产品出了一个奇怪的问题,有一个weblogic跑的应用,跑着跑着,就core dump,产生一个40G的core文件。一开始觉得很奇怪,为什么有这么大的一个core,一般就想,嗯,java内存泄露了。但是这个应用的-Xmx一共才4G,加上PermGen,加上JVM的东西,顶多也就5、6G的core啊。再说这个系统总共内存只有32G,40G的core一定是因为某些native library或者其他的什么地方泄露了内存。

Solaris有一些很好的工具,是Linux所没有的,一旦到了Linux平台我就很怀念他们。比如pstack,比如dtrace。尤其是dtrace,加上一些网上的dtrace script,用来troubleshooting真的是很无敌,跟Windows底下的Sysinternals suite一样。不知道是不是Linux也有类似的工具?

pstack可以用来检查一个core文件产生时系统所有线程的状态。(Java也有一个,jstack,有时候不太好用)不过由于我们是内存泄露,当然要用pmap(java有jmap,不过只能查看java heap)。一个正常的java经常的内存image应该是这样:

$ pmap 3536 |more
3536:   /opt/middleware/jdk1.6.0_21/bin/amd64/java -Dweblogic.Name=imdmapi -se
0000000000400000         52K r-x--  /opt/middleware/jdk1.6.0_21/bin/amd64/java
000000000041C000          4K rw---  /opt/middleware/jdk1.6.0_21/bin/amd64/java
000000000041D000     158048K rw---    [ heap ]
FFFFFD7ECBCD0000        152K rw--R    [ anon ]
FFFFFD7ECC2D6000        152K rw--R    [ stack tid=2729 ]
......
FFFFFD7EEA6F1000          8K rw---  /opt/middleware/jdk1.6.0_21/jre/lib/amd64/libnet.so
FFFFFD7EEA6F5000          8K r--s-  dev:32,0 ino:477791
FFFFFD7EEA6F8000         16K r--s-  dev:32,0 ino:8281559
FFFFFD7EEA7FB000         16K rw--R    [ stack tid=8 ]
FFFFFD7EEA800000    1048576K rw---    [ anon ]
FFFFFD7F2A800000    3145728K rw---    [ anon ]
FFFFFD7FEA800000     131072K rw---    [ anon ]
FFFFFD7FF2800000      88064K rw---    [ anon ]
....
FFFFFD7FFF3FD000          8K rwx--  /lib/amd64/ld.so.1
FFFFFD7FFFDFC000         16K rw---    [ stack ]

其中最上面低地址段的是真正的进程的Heap。底下那段红色的anonymous的内存段才是真正的java heap——它其实在内存高端,相当于跟栈在抢内存。这段内存不是用malloc()这样的东西来申请的,而是通过mmap()把一个文件映射到内存里来申请的。我们指定一个4G的max heap,那么JVM就mmap一个4G的文件。这个文件,当然就是/dev/zero。这个行为也是可以观察的,用truss(Linux: strace)指定跟踪mmap何open这两个系统调用就能发现了JVM先open了/dev/zero,然后把这个文件映射进内存。这样还有一个好处是内存相当于已经都memset成0了!至于为什么使用mmap,据说是为了产生一块连续的内存作为heap,不过我不明白为什么pmap显示它还是分成几段。

再来看看我们的core文件的map:

core 'core.2' of 12264: /opt/middleware/jdk1.6.0_21/bin/amd64/java -Dserver.name=iip -Xrs -Xms
0000000000400000         52K r-x--  /opt/middleware/jdk1.6.0_21/bin/amd64/java
000000000041C000          4K rw---  /opt/middleware/jdk1.6.0_21/bin/amd64/java
000000000041D000    2227600K rw---
0000000088381000    2097152K rw---
0000000108381000    4194304K rw---
0000000208381000    8388608K rw---
0000000408381000   16777216K rw---    [ heap ]
FFFFFD7EDE76C000         88K rw---    [ stack tid=166 ]
FFFFFD7EDE86D000         88K rw---    [ stack tid=165 ]
……
FFFFFD7EF2800000       2048K rw---
FFFFFD7EF2A00000       2048K rw---
FFFFFD7EF2C00000       2048K rw---
FFFFFD7EF2E00000       2048K rw---
FFFFFD7EFAA00000    2797568K rw---
FFFFFD7FA5600000    1398784K rw---
FFFFFD7FFAC01000          4K r----
FFFFFD7FFAC03000          8K r----

hmm,进程的heap很大(16+8+4+2+2=32G),加上JVM的heap,差不多就39G了。JVM的heap还是4G,所以这绝不是java代码泄露,而是native的代码泄露了。另外,这些内存片似乎很有规律,2,2,4,8,16,32是不是有某些特殊的事情发生呢?先用truss看看是不是:

truss -t brk -p <pid>

嗯,想要在heap上(非JVM heap)申请内存一定要用brk函数,malloc/calloc只是libc的函数。brk我总觉得是bark,实际上是break的意思。anyway..brk的结果也显示,申请的内存恰好是2,4,8这样指数递增的。

开始有点怀疑是weblogic的某些lib有问题,因为weblogic为了性能使用了一些native的库。想过用valgrind,或者dmalloc之类的东西来分析native内存泄露,不过那似乎太麻烦了。好在我们有dtrace!比如下面的这个代码就可以在调用brk()这个函数的时候,打印出调用的stack出来:

#!/usr/sbin/dtrace -s
syscall::brk:entry
/pid == $1/
{
    stack();
    printf("====>allocating to: %x\n", arg0);
}

它的意思很简单,当调到syscall的brk这个函数的入口(entry)的时候,而且满足pid=<脚本参数>的情况下,打印stack,并且打印出arg0,也就是调brk的第一个函数。结果如下:

0  52693                        brk:entry
              libc.so.1`_brk_unlocked+0xa
              libc.so.1`sbrk+0x20
              libc.so.1`_morecore+0x12b
              libc.so.1`_malloc_unlocked+0x10d
              libc.so.1`malloc+0x2d
              libjvm.so`__1cCosGmalloc6FL_pv_+0x1e
              libjvm.so`__1cFChunk2n6FLL_pv_+0x49
              libjvm.so`__1cFArenaEgrow6ML_pv_+0x3a
              libjvm.so`__1cINodeHashEgrow6M_v_+0x87
              libjvm.so`__1cINodeHashQhash_find_insert6MpnENode__2_+0x140
              libjvm.so`__1cMPhaseIterGVNNtransform_old6MpnENode__2_+0x731
              libjvm.so`__1cMPhaseIterGVNIoptimize6M_v_+0xff
              libjvm.so`__1cHCompileIOptimize6M_v_+0x801
....

每次的结果都是类似的,这里显然没有java的什么事,也不是weblogic的代码,而是JVM本身的代码。如果你看到里面有hash的字样,你应该联想到,2,4,8,16这样的事情应该是hash表每次rehash的时候把自己的bucket扩大一倍造成的。那么,这个hash表最后一共有十几个G bucket,显然是死循环造成的。仔细再看这个线程,是java的compiler thread,它似乎在优化什么东西。那么我们通过pstack来看看它。通过pstack很容易能看到目前进程里每个线程的状态,然后我们可以只看这个compiler thread:

pstack <pid>/<thread id>

就会看到这个compiler thread总是在运行,而且总是有这个NodeHash的字样在里面,显然死死循环了。

根据“你不会是第一个”的互联网原则,搜索了一下,发现有人报了这么一个JVM bug。直到我们用的JDK 6 u21里面还有这个bug,而且这已经是当时最新的JDK了!还好,过了1个月甲骨文公司出了6u23,fix了这个bug。还去看了一下,fix的办法就是如果这个optimizer搞了很多次,就return,不optimize了!

另外,JVM死掉的时候一般会有一个hs_xxx.log的文件,后来仔细看了一下,它其实已经记录了,当前的thread就是compiler thread,每次都是。所以如果早点看这个文件,也许可以少绕点弯子。

《In case of 40G JVM core dump…》有3个想法

发表评论

电子邮件地址不会被公开。 必填项已用*标注