作者: 羽飞
2017-01-30 09:43:47
背景介绍
core的出现
这是一次在并行环境(是上线之前，新系统与旧系统并行运行，用来检测新系统正确性的环境)出现的严重BUG。
出现问题的模块在MDB，就是内存数据库，一个存放系统重要数据并且支持主备模式的模块。但是当时出现问题的场景是这样的：
备机MDB由于收到了错乱的复制数据,导致自动停止。维护人员看到备机宕机,在启动它的时候，主MDB core了。
系统运行环境
PowerLinux
Linux 3.10.0-327.el7.ppc64le
Red Hat Enterprise Linux 7.6.1-80.el7
GCC 4.8.5 20150623 (Red Hat 4.8.5-4)
问题定位
core信息
当看到core文件的时候我们都傻眼了，core文件只有20G大小，但是MDB存放的是大量数据，core的这个MDB平时运行时虚拟内存占用大概是500G。
就是说core不完整。用gdb查看core文件出现下面的信息：
[billmdb]$ gdb -c core.46943
GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-80.el7
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "ppc64le-redhat-linux-gnu".
For bug reporting instructions, please see:
.
BFD: Warning: /app/billmdb/config/run/abm_mdb1_2373/core.46943 is truncated: expected core file size >= 46961328128, found: 25857536000.
[New LWP 46963]
[New LWP 46946]
[New LWP 46949]
[New LWP 46950]
这里有个重要信息：
BFD: Warning: /app/billmdb/config/run/abm_mdb1_2373/core.46943 is truncated: expected core file size >= 46961328128, found: 25857536000.
core文件被截断了，不知道为什么。查看系统参数配置、内存、磁盘空间和系统日志，都没有发现问题。于是找了一个测试环境，启动一个MDB，使用kill -s 11 pid，发现也不能core完整，而且系统配置和环境均没有发现问题。被逼无奈，只能求助系统管理员。
经过一番交涉与测试，系统管理员也没有说出所以然，最后请求红帽的系统工程师。红帽工程师当时不是随时等待我们的传唤，我们等了三天左右，约在周日(红帽真爽，周末双薪，我们的服务费交了两倍)。
收集数据
红帽的工程师不来，我们当然也不能闲着，因为即使他们解决了core不完整的问题，也不等于我们的问题就找到了。
出现问题最重要的是收集现场数据。但是最重要的第一手资料core，已经丢失了。我们就查看程序运行日志和系统日志，还有系统性能历史数据采集，包括CPU、内存、网络和磁盘。
1.程序日志
因为是线上环境，所以程序的日志对于core来说，并没有太大的价值。我们分析了一下，当时大致的场景，就是在备机启动的时候，而主在给备机发送数据，至于发送什么，无法得知。
2.系统日志
我们使用dmsg能从系统日志中找到core当时时间点的一条日志，但是再也没有其它的异常信息：
1079 [12月15 16:06] odframe[56409]: unhandled signal 11 at 00003ff9e33c17f8 nip 00003fffa4e1805c lr 00003fffa4e18040 code 30001
很遗憾，我只能从这条信息看到我们的程序core了，是段错误，但是core在哪里，无法得知。
3.系统性能历史数据
非常抱歉，没有截图。不过可以肯定的是，CPU平稳，内存没有明显波动而且空闲内存还有几百G，IO正常空间很充足，而且没有故障，网络数据没有异常。
4.系统改动
希望现场人员特别是维护人员都对系统做了什么改动。但是很遗憾的是，大家都说什么都没动，因为是线上环境，都不敢动。
重现
实在没有办法，所有的信息都显示，这是个奇葩的core，轻轻地来轻轻地走，不留下一丝痕迹。
我们只能使用比较笨但是一般都很有效的方法，就是重现。
我们联系现场管理人员要了一个测试环境，把core的MDB的所有配置信息和core当时的数据都复制过来，启动主备。发现有时候会core，有时候不core。但是core信息还是不完整，不过还算有收获，总是能够重现的。
core信息没办法看，我就直接用gdb来运行主MDB，这样当程序出现异常的时候，gdb就会捕获到，跟core一样直观。不过很快就证明我的做法不行，不是想法有问题，是gdb也hold不住这个异常。当程序异常终止时，gdb可以使用info thread看到线程信息，都是在running状态。可是无法使用where查看线程的栈信息。改用先把程序起起来，再用gdb attach的方法，依然如此。
gdb attach进程，进程出现异常后的的信息：
Reading symbols from /app/billmdb/lib/libestatD.so...done.
Loaded symbols for /app/billmdb/lib/libestatD.so
0x00003fffa92f8058 in poll () from /lib64/power8/libc.so.6
Missing separate debuginfos, use: debuginfo-install glibc-2.17-105.el7.ppc64le libaio-0.3.109-13.el7.ppc64le libgcc-4.8.5-4.el7.ppc64le libstdc++-4.8.5-4.el7.ppc64le
(gdb) c
Continuing.
[New Thread 0x3ffd6b137880 (LWP 44564)]
[New Thread 0x3ffd6ad37880 (LWP 44571)]
thread_get_info_callback: cannot get thread info: generic error
(gdb) c
Continuing.
Cannot execute this command while the selected thread is running.
(gdb) info th
Id Target Id Frame
2221 Thread 0x3ffd6ad37880 (LWP 44571) "odframe" (running)
2220 Thread 0x3ffd6b137880 (LWP 44564) "odframe" (running)
2219 Thread 0x3fffa0bb7880 (LWP 30879) "odframe" (running)
2218 Thread 0x3fff9ff57880 (LWP 30880) "odframe" (running)
* 2217 Thread 0x3fff9fb57880 (LWP 30881) "odframe" (running)
2216 Thread 0x3fff9eca7880 (LWP 30882) "odframe" (running)
2215 Thread 0x3fff9e4a7880 (LWP 30883) "odframe" (running)
尝试定位
虽然gdb都无法跟踪到core的位置，但是既然重现了，总会有办法的。
tcmalloc
我们请教了高手，不过高手远在万里之外，只能给几个建议。高手给的第一个建议就是去掉tcmalloc。理由是tcmalloc在我们当前使用的系统上没有经过全面的测试，官方发布的数据中也没有说支持PowerLinux 8系统。于是我们去掉tcmalloc，跑了十几次，发现真的不core了。当时真的欢喜异常，认为找到了问题所在，只需要在白天再来看看为什么tcmalloc不行，因为当时实在太困了，而且既然找到了”问题”，那就先回去休息吧。
于是乎，在呼呼大睡之后第二天过来，用头一天晚上的方法，程序加上tcmalloc，去掉tcmalloc，跑了几次。OMG，我们要疯了，竟然不管用了。有没有tcmalloc都有可能会core。世界观都被颠覆了。我们依然没有找到问题所在。
valgrind
valgrind是一个非常强大的工具，能够定位出大部分内存泄露和越界的问题。只是因为它跑的特别慢，可能有几十倍，导致像这种有超时机制的程序无法正常执行，只能给有超时时间的地方，延迟几十倍。
不过最后证明我们想多了，valgrind压根跑不起来这个程序，理由是线程数太多。
==19639== Warning: set address range perms: large range [0xaaf860000, 0xaee1c0000) (defined)
==19639== Warning: set address range perms: large range [0xb1dd00000, 0xb9dd00000) (defined)
==19639== Warning: set address range perms: large range [0xb1dd00000, 0xb9dd00000) (noaccess)
==19639== Warning: set address range perms: large range [0xb1dd00000, 0xb61c10000) (defined)
==19639== Warning: set address range perms: large range [0xb1dd00000, 0xbe1c00000) (noaccess)
vg_alloc_ThreadState: no free slots available
Increase VG_N_THREADS, rebuild and try again.
valgrind: the 'impossible' happened:
VG_N_THREADS is too low
host stacktrace:
==19639==at 0x3807E984: ??? (in /usr/lib64/valgrind/memcheck-ppc64le-linux)
==19639==by 0x3807EB2F: ??? (in /usr/lib64/valgrind/memcheck-ppc64le-linux)
==19639==by 0x3807EDCB: ??? (in /usr/lib64/valgrind/memcheck-ppc64le-linux)
==19639==by 0x3807EE1B: ??? (in /usr/lib64/valgrind/memcheck-ppc64le-linux)
==19639==by 0x380E466B: ??? (in /usr/lib64/valgrind/memcheck-ppc64le-linux)
==19639==by 0x3813DAEF: ??? (in /usr/lib64/valgrind/memcheck-ppc64le-linux)
==19639==by 0x380E88CB: ??? (in /usr/lib64/valgrind/memcheck-ppc64le-linux)
==19639==by 0x380E40C7: ??? (in /usr/lib64/valgrind/memcheck-ppc64le-linux)
==19639==by 0x380E5D9B: ??? (in /usr/lib64/valgrind/memcheck-ppc64le-linux)
==19639==by 0x380FDDCF: ??? (in /usr/lib64/valgrind/memcheck-ppc64le-linux)
==19639==by 0x380FE47B: ??? (in /usr/lib64/valgrind/memcheck-ppc64le-linux)
==19639==by 0x3813D167: ??? (in /usr/lib64/valgrind/memcheck-ppc64le-linux)
sched status:
running_tid=4
Thread 1: status = VgTs_WaitSys
==19639==at 0x7B98058: ??? (in /usr/lib64/power8/libc-2.17.so)
==19639==by 0x764F73B: CSocketBase::select(timeval const&, int) (socketinner.cpp
于是下载valgrind的源码，修改线程参数，终于跑起来了。
可是等了快一个小时，在加载数据文件的时候，它说内存不够了，无法一次性分配超过几百G的内存。这又是valgrind的限制。换了几个版本的valgrind，发现都是这样，也没有找到修改这个限制的地方。因为急着解决问题，也没有对valgrind深入查看。
core
终于等来了红帽的工程师。我们一边配合他重现core不完整的场景，一边继续测试。
红帽工程师通过几个小时的努力，终于定位到是因为‘/var’目录空间不足引起的。因为这个程序的core，会通过内核来触发的，并不是普通的内存越界，所以要占用/var空间，然后将core文件复制到用户指定的目录。而/var空间一般分配的很小，而我们的core文件却需要500G以上空间，当然就不可能core全了。
红帽工程师把var调整到500G以上，足以容纳整个core。令人震惊的是，ls -lh显示core文件有40+T!我和我的小伙伴们真的惊呆了，整个磁盘一共只有1T而已，core文件有40+T。不过还好，幸亏我们知道ls查看到的并不是真是的物理空间大小，使用du -sh查看，确实是500G。只是，这是什么导致的？进程虚拟空间竟然有40T？不可能的。
到底是什么把进程空间搞这么大？在程序core的过程中，使用pmap dump出进程空间：
63677: odframe -m -i abm_mdb1_2373_3910_1.xml
0000000010000000 64K r-x-- odframe.1.7.7.607293
0000000010010000 64K r---- odframe.1.7.7.607293
0000000010020000 64K rw--- odframe.1.7.7.607293
0000010035880000 11328K rw--- [ anon ]
0000010036390000 49303296K rw--- [ anon ]
0000100000000000 192K r-x-- ld-2.17.so
0000100000030000 64K r---- ld-2.17.so
0000100000040000 64K rw--- ld-2.17.so
0000100000050000 128K r-x-- [ anon ]
0000100000070000 384K r-x-- libtcmalloc.so.4.1.2
00001000000d0000 64K r---- libtcmalloc.so.4.1.2
00001000000e0000 64K rw--- libtcmalloc.so.4.1.2
00001000000f0000 128K rw--- [ anon ]
0000100000110000 128K r-x-- libailog_interfaceD.so.1.7.7.611175
0000100000130000 64K r---- libailog_interfaceD.so.1.7.7.611175
0000100000140000 64K rw--- libailog_interfaceD.so.1.7.7.611175
// 省略链接库的空间
000010000dd60000 64K rw--- [ anon ]
000010000dd70000 64K ----- [ anon ]
0000100011970000 64K ----- [ anon ]
0000100011980000 4032K rw--- [ anon ] // 线程的栈空间
0000100011d70000 64K ----- [ anon ] // 线程栈保护区
0000100011d80000 4032K rw--- [ anon ]
// 中间省略一些线程的栈
00001001e6d80000 4032K rw--- [ anon ]
00001001e7170000 64K ----- [ anon ]
00001001e7180000 4032K rw--- [ anon ] // 线程栈空间
000010022c430000 51529470336K rw--- [ stack ] // 线程栈保护区
total 51586769600K
最后一个线程的保护区，足足有40多个T，肯定是被破坏了。
一目了然，线程栈的保护区都被破坏了。
进程读写内存，都不可能超出进程的空间，那么线程栈保护区这么大，谁做的？
strace
能够操作进程空间的系统调用只有brk(sbrk)和mmap(munmap)，那就抓取系统调用，分析一下brk和mmap吧。
使用strace跟踪进程系统调用，分析brk跟mmap。日志中没有找到brk系统调用(不是从程序执行就跟踪)。但是mmap有几次，抛去为动态链接库申请空间，还有申请的线程栈空间，也没有多少次了。把这些数据捞出来，是读取binlog文件的(类似于MySQL的binlog)。但是mmap也没有发现什么异常。把munmap捞出来，发现有一次munmap调用传入的参数大小与mmap不符。这样就一目了然了，肯定是读取binlog的代码有问题。我们只需要对一下binlog相关的mmap使用的代码，很快就定位到了位置。
总结
本次BUG是由于一次对大文件mmap读取的修正改出来的错误，因为改的匆忙，没有对代码做全面检测，而且测试不充分，所以导致了这个问题。庆幸的是上线前的一次BUG。
对于munmap参数错误导致进程空间被破坏，个人认为这从kernel应该能够cover住这种错误，而且kernel已经检测到了这种错误，引起core dump。
总结一下本次检查问题的操作过程：
收集进程信息：core信息，进程日志，系统日志，系统历史统计信息(CPU,内存，磁盘，网络等);
尝试重现;
确定当前使用的一些第三方软件对程序没有影响;
使用gdb跟踪进程执行;
使用valgrind检查内存越界;
使用pmap检查进程空间;
使用strace跟踪系统调用。