12 3 / 3 页下一页

转一篇 [复制链接]

zylthinking

大富大贵

论坛徽章:: 11

电梯直达

1楼 [收藏(0)] [报告]

发表于 2011-08-31 16:26 |只看该作者 |倒序浏览

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