好久不收拾，这里都长草了。先广告一下，弄了一个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
嗯，想要在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
就会看到这个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，每次都是。所以如果早点看这个文件，也许可以少绕点弯子。