社区编辑申请
注册/登录
【线上故障】通过系统日志分析和定位
系统 其他OS
今天,借助本文,来分享另外一种更为棘手的线上问题解决方案-如何在没有coredump文件的情况下,定位程序崩溃原因。

你好,我是雨乐!

在之前的文章中,我们有讲到如何定位内存泄漏和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,然后采用对应的方式来解决问题。

好了,本期的文章就到这,我们下期见!


责任编辑:武晓燕 来源: 高性能架构探索
相关推荐

2022-06-20 22:37:25

Linux操作系统命令

2022-06-15 11:02:40

网络安全运营

2022-06-13 14:58:19

系统案例

2022-06-15 08:21:49

Linux运维工程师

2022-05-26 16:51:07

网络丢包网络故障网络

2022-05-31 14:46:02

2022-06-09 18:04:46

网络攻击网络安全

2022-06-28 08:40:16

LokiPromtail日志报警

2022-06-26 09:55:00

接口自动化项目

2022-06-27 23:44:37

云原生云存储云计算

2022-05-17 11:06:44

数据库MySQL系统

2022-06-22 09:19:55

HDC鸿蒙ADB命令

2022-06-08 13:25:51

数据

2022-06-01 06:06:28

Web 3元宇宙数字化

2022-06-01 17:47:24

运维监控系统

2022-06-28 10:03:56

CentOSLinux

2022-06-20 12:00:43

MySQL数据库升级

2022-06-14 10:48:55

排查故障

2022-06-07 17:08:51

WizTreewindows工具

2022-06-28 12:35:21

DockerPython

同话题下的热门内容

为什么用C语言编写操作系统?导致系统性能失败的十个原因

编辑推荐

软件卸载不干净怎么办?智能卸载轻松搞定!苹果凌晨1点最新推送iOS 11正式版 如何使用 printf 来格式化输出CentOS Linux 已死—Red Hat 称 Stream 不是替代品BIO、NIO 到多路复用的演进路径,你明白了吗?
我收藏的内容
点赞
收藏

51CTO技术栈公众号