海阔天空

导航

一个new失败问题的查找过程

   在测试部发现一个问题,整个系统跑一阵后就有daemon程序崩溃,虽不是必现,但是一天还是可以出现好几次,导致性能测试无法继续下去,看core的信息是new失败了,具体堆栈如下:

  (gdb) bt
  #0  0x2acd25c1 in kill () from /lib/libc.so.6
  #1  0x2adfc58d in pthread_kill () from /lib/libpthread.so.0
  #2  0x2adfc90b in raise () from /lib/libpthread.so.0
  #3  0x2acd2364 in raise () from /lib/libc.so.6
  #4  0x2acd389b in abort () from /lib/libc.so.6
  #5  0x2ac57b57 in __cxa_call_unexpected () from /usr/lib/libstdc++.so.5
  #6  0x2ac57ba4 in std::terminate() () from /usr/lib/libstdc++.so.5
  #7  0x2ac57d16 in __cxa_throw () from /usr/lib/libstdc++.so.5
  #8  0x2ac57f02 in operator new(unsigned) () from /usr/lib/libstdc++.so.5
  #9  0x2ac57fef in operator new[](unsigned) () from /usr/lib/libstdc++.so.5
  #10 0x2abbfe43 in NSlab::alloc_buf(unsigned*) (pSize=0x7ffff300) at Nslab.cpp:199

  尽管new失败的情况是会有发生,但是在我们的整个系统里面都是不处理这种情况的,我们大部分的内存都是定好的,什么样的平台型号能够支持多少并发连接,这些都是预算好的,是不会有new失败的情况出现的。

  一开始怀疑该程序有内存泄漏,可是看整个core文件只有100多M,应该没有发生内存泄漏的可能。另外一次发生可能还是偶然,在继续跑的过程中发现其他程序也会崩溃,也是因为new失败了,不可能其他的程序都有可能内存泄漏,很多都是比较稳定的程序了,这个可能性不大。

  第二步开始怀疑系统是否真的没有内存了?捕获系统的SIGABRT信号,在信号处理函数里面把系统的状态全部打印了,包括:ps、top、free、/proc/meminfo,/proc/slabinfo等。然而崩溃的时候还是只看到该进程只占用了100多M的内存,而此时系统free的内存有2G之多,其余的信息也可证明系统内存绝对充足。看来不是系统内存引起的原因,如果是的话,问题也就不用再继续查找了,在有内存的时候也失败这个就一定查下去了。

  第三步开始怀疑系统,new是标准库提供的,而此时我们的内核版本从2.4.32迁移到2.4.35.4,是否有什么东西不匹配造成的?download了一个stdc++库,new的实现其实调用的就是C库里面的malloc,在GNU上下了一个匹配版本的C库,在malloc里面打印了一些日志,想用DEBUG版本的c库开查找下问题,C库的编译过程确实挺复杂麻烦,编完后就准备放到系统上,为了不直接覆盖之前的libc库,我使用了mv把之前的libc改了个名字,谁知libc一修改后,所有的命令都无法使用,都是找不到libc库,唯一可用的命令好像只剩下一个cd了,连dd居然也倚赖libc库。无奈只好挂从盘,好不容易把libc拷贝过去了,好了,大松一口气,重启,然而换了libc后的系统就是无法启动。折腾了一天,人被折腾到晕了,就是没办法让它起来。

  第四步,既然换libc暂时行不通,那就换方向。malloc的实现是调用了操作系统的brk来实现的,难道这里面有什么猫腻?看了一下sys_brk的代码,里面会返回失败的点还真多,反正修改内核代码和换内核已经是轻车熟路,于是在每个返回点都打印了日志,换内核。终于有收获了,发现是在sys_brk里面调用do_brk()的时候失败了,再详细跟踪下去,发现do_brk()里面如下语句导致的返回ENOMEM了:

     /* Check against address space limits *after* clearing old maps... */

      if ((mm->total_vm << PAGE_SHIFT) + len  > current->rlim[RLIMIT_AS].rlim_cur) 
return -ENOMEM;

  这条语句表示该进程分配的内存已经超过了能够分配的最大内存了,current->rlim[RLIMIT_AS].rlim_cur的值打印出来是134217728,也就是128MB,此时再回头看看之前的core文件大小,果然不大不小,正好是134217728字节。这个值是可以通过setrlimit,取参数RLIMIT_AS来设置的,再看程序代码,只有设置过RLIMIT_CORE的一些属性,没有设置过RLIMIT_AS的属性。那又是谁设置的?到了这里测试过可以再次serlimit把RLIMIT_AS属性设置为4G即可,但是如果问题的根源没有找到,无法知道是否会有潜在问题。

  第五步,开始找是谁设置了RLIMIT_AS属性?把整个系统的代码搜索了一遍RLIMIT_AS和setrlimit,都没有发现。难道是程序运行中被修改?为了验证,在程序启动点和SIGABRT信号处理函数里面都通过getrlimit取RLIMIT_AS的属性并打印,手工运行了一下,发现在启动的时候打印的值是4294967296,即4G,但是如果程序崩溃了,打印的值就是128MB,无语。为了验证是否有人在中途修改了此值,于是在sys_brk里面任何分配内存,就把current的进程名和该进程的RLIMIT_AS值打印,想知道什么时候RLIMIT_AS的值会被修改。几次实验下来,却又发现与推论不符合的地方,这个值一直没有被修改,只是程序启动的时候有时候是4G,而有时候却就是128M,碰到128M的时候一跑压力就会new失败了,再次陷入无语。

  第六阶段,在看着上面所做的工作程序打印出来的日志,陷入无聊。同时也在不停的重复着new失败的现象,因为我们发现修改一些系统参数后,new失败的可能性提高到了50%以上。在无聊的盯着这些日志看了好久之后,猛然灵光一闪,发现如果是从web操作页面上点击“启用”来启动程序的,RLIMIT_AS的值就是128M,然而如果是自己在shell控制台里面敲命令启用程序的,RLIMIT_AS的值就是4G,无异于发现新大陆,莫非是CGI自己设置了RLIMIT_AS为128M,然后调用execl启用的程序也是128M,该属性是从父进程继承的。验证一下,果然,CGI启用程序一定会因new失败而崩溃,并且CGI里面RLIMIT_AS属性值也是128M的。但是CGI代码自己也没有设置128M的限制,莫非又是boa(我们用的HTTP服务器是boa)的代码里面限制的?刚好我们的boa是从其他部门拿过来的,只有可执行文件,没有源码,所以也能够解释之前所有源码搜索都搜索不到代码的原因。问题就要水落石出了,等到拿到boa的源码时,可惜一看,里面也没有设置这个值,不过重启boa发现boa打印的RLIMIT_AS值确实是128M。见鬼了。

  第七阶段,无聊时,突然联想到,直接在shell里面直接启用boa是否也是4G?测试了一下,果然,直接敲入boa启动,RLIMIT_AS的值是4G,而之前我们重启boa都是通过他的脚本/etc/init.d/boa restart来启用的,立即查看该脚本,在利用daemon启用boa之前,赫然发现了里面有这么一句“ulimit -m 131072”,去掉,一切恢复正常。

  至此水落石出,从时间上来看,比起之前的跨N个模块追查了3周才查到的一个BUG相比,此问题只查了3天的样子,然而追查过程却跌宕起伏,之前也不是由我来查这个问题,是项目组内的其他人,在查到有系统还有内存又new失败的时候,他们就放弃不查了,肯定的说不是代码问题,没方法继续查找下去的时候丢给了我。

  查BUG的经验还是细心和开阔思路,细心当然就是关注到一些别人留意不到的地方,通常一个小的发现立即就可以解决问题,我看到有人在找了半天还没有定位到问题的原因,而有些人对现场瞄一瞄,看看一些信息,立即就找到了思路,当然思路开阔的能力建立在你的知识系统之上的。同时注意在查BUG的时候,也要积累自己的知识。

posted on 2010-01-16 13:26  fll  阅读(4090)  评论(1编辑  收藏  举报