【线上故障】通过系统日志分析和定位
source link: https://os.51cto.com/article/700655.html
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
你好，我是雨乐!
在之前的文章中，我们有讲到如何定位内存泄漏和GDB调试-从入门实践到原理。今天，借助本文，来分享另外一种更为棘手的线上问题解决方案-如何在没有coredump文件的情况下，定位程序崩溃原因。
一个优秀的程序员，编码能力和解决问题的能力必不可少。编码能力体现的是逻辑思维能力，而解决问题的能力不仅仅依靠自己经验的积累，更需要一定的敏锐嗅觉和使用其他方式解决问题的能力。管他黑猫白猫，抓住老鼠就是好猫。
在日常的项目开发中，根据Bug产生的时机和环境，我们可以将Bug细分为以下几种：
- 线下缺陷：此阶段发生在上线前。主要在测试阶段，由开发人员在自测过程中或者有测试人员发现
- 线上问题：此阶段发生在上线后，也就是在正式环境或者生产环境。主要是不符合产品的需求逻辑，可能会影响用户体验
- 线上故障：这个阶段是最严重的，对公司的收益、用户体验都会造成影响，主要为服务不可用等
在本文的示例中，我们针对的第三个阶段，即线上故障进行定位和分析的一种方式，希望借助本文，能够对你的故障定位能力有一定的帮助。
早上到了公司，正在愉快地摸鱼，突然企业微信来了条报警，某个核心服务重新启动了。
于是，快速打开iterm，通过跳板机登录线上服务器，第一时间，查看有没有coredump文件生成:
ll /www/coredump/
total 0竟然没有coredump文件，当时心情是这样的：
当时第一反应是有人手动重启了，于是在组内群里问了下，没人动线上，看来问题比较麻烦。
既然没有coredump文件产生，且没有人手动重启服务，只能分析下系统日志，看看能得到什么线索。
通过在系统日志中，查找进程名来获取进程发生错误时候的日志信息。
grep xxx /var/log/messages
kernel: xxx[11120]: segfault at 7f855009e49f ip 0000003ab9a75f62 sp 00007fcccd7f74c0 error 4 in libc-2.12.so[3ab9a00000+18b000]在上面的信息中：
- xxx 为进程名，后面括号中的11120代表当时的线程id7f855009e49f为出错时候的地址
- 0000003ab9a75f62为发生错误时指令的地址
- 00007fcccd7f74c0 为堆栈指针
- 3ab9a00000为libc在此程序中映射的内存基址
- segfault at和error 4这两条信息可以得出是内存读出错
其中，内核对error的定义如下：
/*
* Page fault error code bits:
*
* bit 0 == 0: no page found 1: protection fault
* bit 1 == 0: read access 1: write access
* bit 2 == 0: kernel-mode access 1: user-mode access
* bit 3 == 1: use of reserved bit detected
* bit 4 == 1: fault was an instruction fetch
* bit 5 == 1: protection keys block access
*/
enum x86_pf_error_code {
X86_PF_PROT = 1 << 0,
X86_PF_WRITE = 1 << 1,
X86_PF_USER = 1 << 2,
X86_PF_RSVD = 1 << 3,
X86_PF_INSTR = 1 << 4,
X86_PF_PK = 1 << 5,
};
#endif /* _ASM_X86_TRAPS_H */
error 4代表用户态程序内存访问越界。
好了，通过上述内核日志，我们基本可以得出如下结论：
名为xxx的进程中，线程id为11120发生了用户态程序内存访问越界，且最终core在了libc-2.12.so中。原因基本确定，现在我们开始定位问题。
使用ldd命令，查看可执行程序的依赖：
ldd xxx
linux-vdso.so.1 => (0x00007ffedb331000)
librt.so.1 => /lib64/librt.so.1 (0x0000003aba200000)
libdl.so.2 => /lib64/libdl.so.2 (0x0000003ab9600000)
libstdc++.so.6 => /usr/lib64/libstdc++.so.6 (0x0000003abce00000)
libm.so.6 => /lib64/libm.so.6 (0x0000003aba600000)
libc.so.6 => /lib64/libc.so.6 (0x0000003ab9a00000)
/lib64/ld-linux-x86-64.so.2 (0x0000562e90634000)
libpthread.so.0 => /lib64/libpthread.so.0 (0x0000003ab9e00000)
libgcc_s.so.1 => /lib64/libgcc_s.so.1 (0x0000003abc200000)在上一节中，我们得到了程序发生错误时指令的地址(0000003ab9a75f62)以及libc-2.12.so在进程中的基址(3ab9a00000)，下面我通过objdump命令来进行分析。
通过下述命令，得到libc-2.12.so汇编结果(因为内容较多，我们将其重定向输出到一个临时文件)
objdump -tT /lib64/libc-2.12.so > ~/info查找汇编语句
Libc-2.21.so是个基础库，其内容多达58m，很难直接从中获取有用信息。
ll info
-rw-r--r-- 1 root root 58369282 Jan 28 10:14 info为了快速定位错误点，我们抓取跟错误点地址3ab9a75f62相关的命令(为了获取上下文，所以grep了部分)
objdump -tT /lib64/libc-2.12.so | grep 3ab9a75输出如下：
0000003ab9a75100 l F .text 0000000000000176 enlarge_userbuf
0000003ab9a756b0 l F .text 000000000000011b ptmalloc_lock_all
0000003ab9a757d0 l F .text 00000000000000b6 ptmalloc_unlock_all
0000003ab9a75890 l F .text 00000000000000c1 ptmalloc_unlock_all2
0000003ab9a75960 l F .text 0000000000000003 __failing_morecore
0000003ab9a75a20 l F .text 00000000000000da sYSTRIm
0000003ab9a75b00 l F .text 000000000000029d mem2chunk_check
0000003ab9a75da0 l F .text 00000000000000e0 malloc_printerr
0000003ab9a75e80 l F .text 0000000000000541 malloc_consolidate
0000003ab9a75280 l F .text 0000000000000187 _IO_str_seekoff_internal
0000003ab9a75970 l F .text 000000000000006b __malloc_check_init
0000003ab9a75410 l F .text 00000000000001aa _IO_str_overflow_internal
0000003ab9a759e0 l F .text 0000000000000031 __malloc_usable_size
0000003ab9a75020 l F .text 0000000000000062 _IO_str_underflow_internal
0000003ab9a750b0 l F .text 000000000000002b _IO_str_finish
0000003ab9a75090 l F .text 0000000000000012 _IO_str_count
0000003ab9a755c0 l F .text 00000000000000ae _IO_str_init_static_internal
0000003ab9a750e0 l F .text 0000000000000015 _IO_str_pbackfail_internal
0000003ab9a759e0 w F .text 0000000000000031 malloc_usable_size
0000003ab9a75020 g F .text 0000000000000062 _IO_str_underflow
0000003ab9a750e0 g F .text 0000000000000015 _IO_str_pbackfail
0000003ab9a75410 g F .text 00000000000001aa _IO_str_overflow
0000003ab9a75670 g F .text 000000000000001d _IO_str_init_readonly
0000003ab9a75690 g F .text 0000000000000012 _IO_str_init_static
0000003ab9a75280 g F .text 0000000000000187 _IO_str_seekoff
0000003ab9a750e0 g DF .text 0000000000000015 GLIBC_2.2.5 _IO_str_pbackfail
0000003ab9a75690 g DF .text 0000000000000012 GLIBC_2.2.5 _IO_str_init_static
0000003ab9a759e0 w DF .text 0000000000000031 GLIBC_2.2.5 malloc_usable_size
0000003ab9a75020 g DF .text 0000000000000062 GLIBC_2.2.5 _IO_str_underflow
0000003ab9a75280 g DF .text 0000000000000187 GLIBC_2.2.5 _IO_str_seekoff
0000003ab9a75410 g DF .text 00000000000001aa GLIBC_2.2.5 _IO_str_overflow
0000003ab9a75670 g DF .text 000000000000001d GLIBC_2.2.5 _IO_str_init_readonly为了进一步定位问题点，我们使用objdump命令并指定起始点
objdump -d /lib64/libc-2.12.so --start-address=0x3ab9a75000 | head -n2000 | grep 75f62输出如下：
3ab9a75ec8: 0f 85 94 00 00 00 jne 3ab9a75f62 <malloc_consolidate+0xe2>
3ab9a75f62: 48 8b 43 08 mov 0x8(%rbx),%rax基本能够确定在进行malloc的时候，出现了问题。
精准定位在上节中，我们定位到原因是malloc导致，但是代码量太大，任何一个对象底层都有可能调用了malloc(new也会调用malloc)，所以一时半会，不知道从哪下手。
为了定位原因，采用最近定位法，分析最近一次上线的代码改动，这次改动，将之前的redis Sentinel改为了redis cluster，而redis 官方没有提供cluster的client，所以自己手撸了个client，而在这个client中调用malloc顺序如下：
-> Init
--> redisClusterInit
----> calloc
------> malloc好了，到此，进程崩溃的代码点基本定位了，下面我进行原因分析。
程序对RedisClusterClient进行初始化的地方有两个：
- 程序启动的时候
- 当连接断开的时候
因为程序已经运行了一段时间，所以第一条基本不成立，那么我们看下本次改动使用的命令之一ZRangeByScore的实现：
void RedisClusterClient::ZRangeByScore(std::string& key, std::string min, std::string max,
std::vector<std::string> *vals,
bool withscores,
std::string *msg) {
// ....
redisReply *reply = static_cast<redisReply*>(
redisClusterCommandArgv(cc_, argv.size(), &(argv[0]), &(argvlen[0])));
if (!reply || reply->type != REDIS_REPLY_ARRAY) {
// ...
redisClusterFree(cc_);
cc_ = nullptr;
Init(host_, password_, &connect_timeout_, &op_timeout_, msg);
}
return;
}
// ...
}单纯这块代码，是不会有问题的，所以需要把使用这块代码的都考虑进来。我们重新理下请求的调用链：
-> Load
--> GetHandler
----> GetSession
------> GetRedisClient重新进行代码分析，发现在特定条件下，GetRedisClient可能会被多个线程同时调用，如果不进行Init的话，一切正常，而当一个线程Init的时候，恰好另外一个线程进行读，因此引起了访问一个已经释放的内存地址，所以导致了进程崩溃。
这种情况发生的概率很低，很难重现。毕竟连接突然断开的同时，又有一个线程在同时访问，在线上还是很难出现(当然可以在线下通过tcpkill进行模拟，这就是另外一回事了)，总体来说，还是比较幸运，能够迅速定位。
在整个bug的分析和解决过程中，定位segfault是最困难的地方，如果知道了segfault的地方，分析原因，就相对来说简单多了。当然，知道了崩溃原因，解决就更不在话下了😃。
程序崩溃，基本上都跟内存有关，无非是越界、访问无效地址等。在本例中，就是因为访问一个已经释放的内存地址而导致的，根据代码的实际使用场景，在对应的地方，加锁，线上灰度，然后全量上线。
遇到线上问题，一定不能慌，如果是频繁的coredump或者重启，那么就先回滚到上个版本，然后再分析和解决问题。
如果有生成coredump，那么可以使用gdb进行调试，查看coredump产生位置，然后根据上下文分析产生coredump的原因，进而解决问题。
如果没有生成coredump，这个时候，就需要借助其他方式，比如先查看是否因为OOM导致的进程消失，这个时候需要查看部署本服务的其他进程的内存占用情况;如果排除了OOM原因，那么可能就是其他原因了，这个时候，可以借助系统日志来初步定为进程消失的原因，比如本例中的segfault，然后采用对应的方式来解决问题。
好了，本期的文章就到这，我们下期见!
分享到微信 
分享到微博Recommend
About Joyk
Aggregate valuable and interesting links.
Joyk means Joy of geeK