最近又有一个奇怪的 coredump, 在我们的集群中, 开始悄悄地出现:
#6 0x00000000003d101e in hologres::SegfaultHandler (sig=11, info=0x7ffd27d367b0, ctx=0x7ffd27d36680) at Z.cc:296
#7 <signal handler called>
#8 BugClass<(unsigned char)19>::BugClass (this=0x7f70d18122a0 <>) at X.h:50
#9 0x00007f70b89e36cc in __cxx_global_var_init.44(void) () at Y.h:501
#10 0x00007f712ea383a3 in _dl_init_internal () from /lib64/ld-linux-x86-64.so.2
#11 0x00007f712ea3cab6 in dl_open_worker () from /lib64/ld-linux-x86-64.so.2
#12 0x00007f712ea381b4 in _dl_catch_error () from /lib64/ld-linux-x86-64.so.2
#13 0x00007f712ea3c1ab in _dl_open () from /lib64/ld-linux-x86-64.so.2
#14 0x00007f7125b7f02b in dlopen_doit () from /lib64/libdl.so.2
#15 0x00007f712ea381b4 in _dl_catch_error () from /lib64/ld-linux-x86-64.so.2
#16 0x00007f7125b7f62d in _dlerror_run () from /lib64/libdl.so.2
很明显, 是加载 so 之后, 执行 so init 段来初始化全局变量时 crash 了. 我一开始以为是全局变量之间的依赖关系没有搞好导致, C++ 标准中并没有规定全局变量初始化的执行顺序, 很可能会出现逻辑上全局变量 A 的初始化依赖全局变量 B, 但在实际执行时, A 先于 B 执行初始化, 导致 A 访问到未初始化区域. 在我年幼的时候还特意研究过 Gcc 使用 init priority 控制全局变量初始化顺序. 但看了下相关代码并不是如此, 如下所示, global_bug_var 的初始化并不会依赖其他全局变量:
template <UInt8 K> struct BugClass {
BugClass() {
l[0] = 0.0;
for (size_t i = 1; i <= M; ++i) // M = 4096
l[i] = std::log(static_cast<double>(i)); // <--- coredump frame 8 对应着这里
}
private:
static constexpr size_t M = 1 << ((static_cast<unsigned int>(K) <= 12) ? K : 12); // K = 19, M = 4096
public:
double l[M + 1];
};
static BugClass<19> global_bug_var;
下图是 frame 8 当前指令周边的控制流程图片段:
vcvtusi2sd 指令负责将 QWORD PTR [rbp-0x10] 从整数类型转换为浮点类型, 并保存在 xmm0 中. gdb 可以看出 crash 时 [rbp-0x10] 对应地址是合法的, 可以访问的.
(gdb) x/dg $rbp - 0x10
0x7ffd27d37380: 894
有点奇怪, 哪是谁触发的 SIGSEGV? 好在自 为什么 r14 为 0? 之后我改造了 sighandler, 会准确地记录 crash 事发现场; frame 6 中 info, ctx 参数记录了由 Linux 内核填充的, SIGSEGV 事发现场, 对我们有价值的主要是事发时几个通用寄存器的值:
(gdb) p *(struct zy_ucontext*) ctx
$2 = {uc_flags = 7, uc_link = 0x0, uc_stack = {ss_sp = 0x7f711e47a000, ss_flags = 0, __padding0 = "\375\177\000", ss_size = 32768}, uc_mcontext = {r8 = 107271103641984, r9 = 720896, r10 = 0, r11 = 140123904033400, r12 = 140725271637456,
r13 = 140122521111592, r14 = 16, r15 = 140122521108792, di = 140122527965856, si = 0, bp = 140725271622544, bx = 6, dx = 140123912721480, ax = 894, cx = 140122527973000, sp = 140725271622496, ip = 140122110441288, flags = 66183, cs = 51, gs = 0,
fs = 0, ss = 43, err = 20, trapno = 14, oldmask = 4096, cr2 = 140119617223800, fpstate = 140725271619648, reserved1 = {140124077894724, 2, 140124081433544, 8542868489239527424, 12, 12, 0, 140725271619680}}, uc_sigmask = {sig = {4096}}}
(gdb) p *(struct zy_siginfo*) info
$3 = {si_signo = 11, si_errno = 0, si_code = 1, __padding0 = "\000\000\000", _sifields = {_pad = {604159096, 32624, 875840, 24640, 34, 0, 875840, 24640, 499564544, 32625, 781792024, 32625, 668166224, 32765, 769952180, 32625, 499564640, 32625, 499564768,
32625, 668166224, 32765, 875856, 24640, 668184016, 32765, -1304090544, 32624}, _kill = {_pid = 604159096, _uid = 32624}, _timer = {_tid = 604159096, _overrun = 32624, __unknown_type2 = "@]\r\000@`\000", _sys_private = 34}, _rt = {_pid = 604159096,
_uid = 32624, _sigval = {sival_int = 875840, sival_ptr = 0x6040000d5d40, __HIDVA_dont_use4 = "@]\r\000@`\000"}}, _sigchld = {_pid = 604159096, _uid = 32624, _status = 875840, __padding6 = "@`\000", _utime = 34, _stime = 105827995049280},
_sigfault = {_addr = 0x7f702402bc78, _addr_lsb = 23872, __padding8 = "\r\000@`\000", __anon9 = {_addr_bnd = {_lower = 0x22, _upper = 0x6040000d5d40}, _pkey = 34, __HIDVA_dont_use11 = "\"\000\000\000\000\000\000\000@]\r\000@`\000"}}, _sigpoll = {
_band = 140119617223800, _fd = 875840}, _sigsys = {_call_addr = 0x7f702402bc78, _syscall = 875840, _arch = 24640},
__HIDVA_dont_use16 = "x\274\002$p\177\000\000@]\r\000@`\000\000\"\000\000\000\000\000\000\000@]\r\000@`\000\000\000\300\306\035q\177\000\000\030\063\231.q\177\000\000Ph\323'\375\177\000\000\264\211\344-q\177\000\000`\300\306\035q\177\000\000\340\300\306\035q\177\000\000Ph\323'\375\177\000\000P]\r\000@`\000\000Э\323'\375\177\000\000P(E\262p\177\000"}}
从 _sigfault._addr, cr2 的值可以看到触发 SIGSEGV 的地址是 0x7f702402bc78(140119617223800)! err = 20 意味着 X86_PF_INSTR | X86_PF_USER, trapno = 14 意味着 X86_TRAP_PF. 结合内核的 page_fault 链路可以想像出当时的场景是:
- CPU 结束上一条指令的执行, 开始执行下一条指令, rip=0x7f702402bc78
- CPU 开始取指令阶段, 此时触发 page fault, CPU 硬件将 error_code X86_PF_INSTR 压入到当前栈顶.
- linux page_fault() 开始介入, 其从栈顶取出 error_code X86_PF_INSTR, 从 cr2 寄存器读取出引发 page fault 的地址 0x7f702402bc78,
- balabala… 一路执行, 直到用户进程 coredump.
可是为什么 CPU 会尝试执行 0x7f702402bc78 的指令???!!! 我使用了 gdb maintenance info sections 以及 jegdb 的 parse_info_sections() 能力 生成了在 coredump 所有 section 中搜索 0x7f702402bc78 的 gdb 脚本
find /g 0,2101248,(long)140119617223800
find /g 2097920,3529709,(long)140119617223800
find /g 3529712,3618303,(long)140119617223800
...
可以看到只有 2 处地址, 对应的值是 0x7f702402bc78, 这 2 处就是上面 ucontext/siginfo, 是由内核填充的.
warning: Unable to access 15738 bytes of target memory at 0x7f712ec49287, halting search.
Pattern not found.
0x7ffd27d36758 # 对应着 ucontext.cr2
0x7ffd27d367c0 # 对应着 siginfo._sigfault._addr
warning: Unable to access 15545 bytes of target memory at 0x7ffd27d42348, halting search.
2 patterns found.
接下来该咋办?
硬件问题?
难道是硬件问题? 到是听说过 CPU CR2 寄存器故障, 高 16bit 被清 0. 在我们这里, 预期的值是 rip 寄存器中的值, 实际的值是 cr2 中的值, 两者异或了下, 不一样的 bit 并没有什么特征…
>>> bin(140119617223800 ^ 140122110441288)
'0b10011100100111001000101100110000'
而且这个问题已经在多台机器上出现过了, 如下是其中 3 台机器在 sigsegv 现场时各个通用寄存器的值:
内核问题?
内核问题??? 目前出问题的机器倒是都具有完全一致的内核版本号. 难道是内核 context switch 时错误地设置了 rip??
我现在是在其中一台机器上搞了个小脚本, 周期性地在每个 cpu 上执行下我的探测小程序, 就看能不能拿到更多的信息了…
for cpuid in 0 1 2 ... # CPU id 列表
do
taskset -c $cpuid ./hetui
done
echo `date` "hetui"
程序问题?
哈哈哈哈!!! 在这篇文章刚刚发表的瞬间, 我又想到了另一种可能, 如果一个 so libHeTui.so 在其 init 段中注册了某个信号 SIGINT 的 handler, 之后主进程 dlclose(dlopen(libHeTui.so)), 之后主进程在收到 SIGINT, 便会遇到如上几乎一样的情况:
(gdb) bt
#0 0x00007f428952f5f7 in raise () from /lib64/libc.so.6
#1 0x00007f4289530ce8 in abort () from /lib64/libc.so.6
#2 0x0000000000400796 in SegfaultHandler (sig=11, info=0x7ffe74a096f0, ctx=0x7ffe74a095c0) at main.c:9
#3 <signal handler called>
#4 0x00007f42892f8698 in ?? () # 这个是 libHeTui.so 针对 SIGINT 注册的 handler, 由于 libHeTui 已经被 dlclose 所以无法执行.
#5 <signal handler called>
#6 0x00007f42895b7400 in __nanosleep_nocancel () from /lib64/libc.so.6
#7 0x00007f42895b72b4 in sleep () from /lib64/libc.so.6
#8 0x0000000000400812 in main () at main.c:23
(gdb) p (struct ucontext*)ctx
$2 = (struct ucontext *) 0x7ffe74a095c0
(gdb) p *$2
$3 = {uc_flags = 7, uc_link = 0x0, uc_stack = {ss_sp = 0x0, ss_flags = 0, __padding15046 = "\000\000\000", ss_size = 0}, uc_mcontext = {r8 = 140730855108816, r9 = 140730855108368, r10 = 8, r11 = 582, r12 = 140730855108688, r13 = 140730855109408,
r14 = 0, r15 = 0, di = 2, si = 140730855105520, bp = 4294967295, bx = 140730855108560, dx = 140730855105216, ax = 0, cx = 139923749041152, sp = 140730855105208, ip = 139923746162328, flags = 66118, cs = 51, gs = 0, fs = 0, ss = 43, err = 20,
trapno = 14, oldmask = 2, cr2 = 139923746162328, fpstate = 140730855102336, reserved1 = {0, 0, 0, 0, 0, 0, 0, 0}}, uc_sigmask = {sig = {2}}}
# ip = cr2 = 139923746162328.
但如果我们这几个 coredump 也是类似情况, 那么应该也会有如下特征:
- ucontext 中 ip 寄存器具有与 cr2 寄存器一样的值!
- bt 能够看到 cr2 中错误地址出现过!
可是我们没有这几个特征… 哈不起来了…
曙光?
我的大佬同事(也是我大老板)给了一个有意思的输入, 他们(很久)之前也遇到过一个 bug, 当时也是类似的情况, 其中出问题的指令指针 PTR 是由合法地址 PTR1 的高 32bit PTR1.HIGH, 合法地址 PTR2 的低 32bit PTR2.LOW 组成. 当时内核版本依稀记得是 2.X; CPU 是 skylake; PTR1, PTR2 与 vdso clock_gettime 有关. 具体根因没有定位到, 修复方式是通过改写, 绕过 vdso/clock_gettime. 受此启发, 我在多个 coredump 中看了下问题指针, 他们的低 32bit 都来自于 __ieee754_log_avx+1960:
# 这一小节使用另外一个 coredump 环境, 该 coredump CR2 = 0x7ff602ab5c78, 可以看下上面 excel 表格了解其他寄存器的状态.
# 0x7ff602ab5c78, 其低 32bit 来自于 0x7ff702ab5c78
(gdb) x/i 0x7ff702ab5c78
0x7ff702ab5c78 <__ieee754_log_avx+1960>: jne 0x7ff702ab5743 <__ieee754_log_avx+627>
写个小 demo, 等到程序执行到 __ieee754_log_avx+1960 时暂停下, 看下此时 FPU 各个寄存器的状态, 看看能不能与我们 coredump 找到点相似之处. 可以看到两者 FPU 寄存器状态几乎完全一样:
所以目前看起来 coredump 事发时情况是:
- 我们完成了 log(1632) 的计算, 局部变量 i += 1, i = 1633, 准备计算 1633.
由于某种原因, 内核进行了 context switch, 并且在 switch 回来之后rip 被赋予 0x7ff6973ed748, 从语义上讲, 这个是符合预期的.- 又由于某种原因, CPU 从 0x7ff602ab5c78 处取指令准备执行, 0x7ff602ab5c78 低 32bit 来自于
__ieee754_log_avx+1960, 高 32bit 来自于 rip 寄存器. 然后挂了..
继续研究下 rip 与 cr2 有哪些关联, 如下所示这 3 例 coredump 现场 rip 与 cr2 值的差值/异或结果有点意思, 但又说不清有哪些意思…
>>> hex(0x7f70b89e3748 - 0x7f702402bc78)
'0x949b7ad0'
>>> hex(0x7ff6973ed748 - 0x7ff602ab5c78)
'0x94937ad0'
>>> hex(0x7ff6edeed748 - 0x7ff6595a5c78)
'0x94947ad0'
>>> hex(0x7f70b89e3748 ^ 0x7f702402bc78)
'0x9c9c8b30'
>>> hex(0x7ff6973ed748 ^ 0x7ff602ab5c78)
'0x95958b30'
>>> hex(0x7ff6edeed748 ^ 0x7ff6595a5c78)
'0xb4b48b30'
不过目前看起来应该是 linux 内核或者硬件问题了, 这样子我上面那个小探测程序应该最终是能复现出来的, 等吧. 而且这几台机器内核都是 4.9 版本了, 难到我同事他们遇到的那个 bug 从 2.X 活到了 4.9??? 另外也问了下 google, 好像有几个类似的 bugfix, 比如 Don’t restore the FPU state directly from userland in __fpu__restore_sig() 等, 太晚了没细看.
zy_ucontext, zy_siginfo?
Q: zy_ucontext, zy_siginfo 什么意思?
A: info, ctx 的值是 Linux 内核负责填充, 在 Linux 内核中会有 info, ctx 对应结构 siginfo, ucontext 的详细定义. 虽然 glibc 中也有一份等价的定义, 这里 “等价” 是指两者具有相同的 memory layout; 但 glibc 中定义会比较含糊, 以 ucontext 为例, 其将 ucontext.uc_mcontext.gregs 简单地定义为 long long [23]. 而内核中的定义则会详细地列举出每一个寄存器. 所以 zy_ucontext/zy_siginfo 是使用 hidva/clayout 生成的内核侧定义:
# clayout 会读取 vmlinux .debug_info section 中记录的 dwarf 调试信息, 根据这个调试信息生成
# ucontext/siginfo 结构的定义, 并输出到 zy_siginfo_ucontext.h.
$ clayout -i /usr/lib/debug/lib/modules/`uname -r`/vmlinux -o zy_siginfo_ucontext ucontext siginfo
$ gcc -O0 -g -o zy_siginfo_ucontext zy_siginfo_ucontext.c
# 加载 zy_siginfo_ucontext 中的调试信息到 gdb 中, 此后便可使用 `struct zy_ucontext`
(gdb) add-symbol-file zy_siginfo_ucontext
如下是 clayout 生成的 zy_siginfo_ucontext.h 中与 ucontext 相关的代码片段, 可以看到与 glibc 中简单地使用 long long[23] 来表示 sigcontext_64 相比, 内核中 sigcontext_64 更为详细:
// Generated by hidva/clayout! 大吉大利!
#pragma once
#include <linux/types.h>
// tyname=::sigaltstack tyidx=TypeIndex { input_id: 0, typoff: TypeOffset(4574272) }
struct sigaltstack {
void* ss_sp;
int ss_flags;
__u8 __padding0[4];
long unsigned int ss_size;
} __attribute__((__packed__));
typedef long long unsigned int int_Array8[8];
// tyname=::sigcontext_64 tyidx=TypeIndex { input_id: 0, typoff: TypeOffset(4554140) }
struct sigcontext_64 {
long long unsigned int r8;
long long unsigned int r9;
long long unsigned int r10;
long long unsigned int r11;
long long unsigned int r12;
long long unsigned int r13;
long long unsigned int r14;
long long unsigned int r15;
long long unsigned int di;
long long unsigned int si;
long long unsigned int bp;
long long unsigned int bx;
long long unsigned int dx;
long long unsigned int ax;
long long unsigned int cx;
long long unsigned int sp;
long long unsigned int ip;
long long unsigned int flags;
short unsigned int cs;
short unsigned int gs;
short unsigned int fs;
short unsigned int ss;
long long unsigned int err;
long long unsigned int trapno;
long long unsigned int oldmask;
long long unsigned int cr2;
long long unsigned int fpstate;
int_Array8 reserved1;
} __attribute__((__packed__));
typedef long unsigned int int_Array1[1];
// tyname=::<anon> tyidx=TypeIndex { input_id: 0, typoff: TypeOffset(4574168) }
struct AnonType1 {
int_Array1 sig;
} __attribute__((__packed__));
// tyname=::ucontext tyidx=TypeIndex { input_id: 0, typoff: TypeOffset(4619506) }
struct ucontext {
long unsigned int uc_flags;
void* uc_link;
struct sigaltstack uc_stack;
struct sigcontext_64 uc_mcontext;
struct AnonType1 uc_sigmask;
} __attribute__((__packed__));
