作者:声东
大家好,今天跟大家分享一个 Linux core dump 分析的案例.
问题症状
问题的症状很简单,就是服务器不定期重启.客户使用的产品是 CentOS 云服务器.
详细分析
首先,用 crash 命令打开客户提供的 core dump,能看到一些内核版本,vCPU 数量,core dump 产生的时间,开机时间等最基本的系统信息.这些信息中,和目前这个问题直接相关的是 PANIC 这一行.
首先,用 crash 命令打开客户提供的 core dump,能看到一些内核版本,vCPU 数量,core dump 产生的时间,开机时间等最基本的系统信息.这些信息中,和目前这个问题直接相关的是 PANIC 这一行.
PANIC 一行可以理解为,内核发生的问题是 "NULL pointer dereference",而被 dereference 的地址是 000000000000001c.其实这句话本身是有点矛盾的,因为 000000000000001c 显然不是 NULL pointer.猜测内核把 "NULL pointer dereference" 定义为一类错误,而不仅代表访问 NULL 指针的异常.
KERNEL: /usr/lib/debug/lib/modules/3.10.0-514.26.2.el7.x86_64/vmlinux
CPUS: 32
DATE: Wed Jan 3 13:42:39 2018
UPTIME: 03:43:14
LOAD AVERAGE: 0.16, 0.12, 0.07
TASKS: 858
MACHINE: x86_64 (2494 Mhz)
MEMORY: 128 GB
PANIC: "BUG: unable to handle kernel NULL pointer dereference at 000000000000001c"
PID: 9377
COMMAND: "nginx"
CPU: 29
STATE: TASK_RUNNING (PANIC)
接下来,分析问题发生时候的调用栈.可以看到 read 系统调用从 user mode 传到了 kernel,再从 kernel,到 vfs,最后被分发到具体的文件系统实现里.在这里,这个调用最终被分发到了 ceph 模块.ceph 是一个分布式文件系统的实现.
除了函数调用关系之外,在这个调用栈上,另一类关键信息是 exception record.exception record 是发生异常的时候,被记录下来的寄存器的值.这个调用栈上记录了两次异常,上边的异常是 page fault,下边的异常是 system call.第二个异常我们略过不细说,问题主要是第一个异常.
crash> bt
PID: 9377 TASK: ffff881c65ee5e20 CPU: 29 COMMAND: "nginx"
#0 [ffff881f66bbf960] machine_kexec at ffffffff81059beb
#1 [ffff881f66bbf9c0] __crash_kexec at ffffffff81105822
#2 [ffff881f66bbfa90] crash_kexec at ffffffff81105910
#3 [ffff881f66bbfaa8] oops_end at ffffffff81690008
#4 [ffff881f66bbfad0] no_context at ffffffff8167fc96
#5 [ffff881f66bbfb20] __bad_area_nosemaphore at ffffffff8167fd2c
#6 [ffff881f66bbfb68] bad_area_nosemaphore at ffffffff8167fe96
#7 [ffff881f66bbfb78] __do_page_fault at ffffffff81692e4e
#8 [ffff881f66bbfbd8] trace_do_page_fault at ffffffff816930a6
#9 [ffff881f66bbfc18] do_async_page_fault at ffffffff8169274b
#10 [ffff881f66bbfc30] async_page_fault at ffffffff8168f238
[exception RIP: __free_pages+5]
RIP: ffffffff8118a075 RSP: ffff881f66bbfce0 RFLAGS: 00010246
RAX: 00000000fffffe00 RBX: 0000000000001a86 RCX: ffff881f66bbffd8
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
RBP: ffff881f66bbfe20 R8: ffff881f66bbfc28 R9: 0000000000000000
R10: df8093c0cb57bc70 R11: 0000000000000000 R12: 0000000000000000
R13: ffff881f66bbfe40 R14: 0000000000000000 R15: 0000000000000002
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
#11 [ffff881f66bbfce0] ceph_aio_read at ffffffffa02deb11 [ceph]
#12 [ffff881f66bbfe28] do_sync_read at ffffffff811fe0bd
#13 [ffff881f66bbff00] vfs_read at ffffffff811fe86e
#14 [ffff881f66bbff38] sys_read at ffffffff811ff43f
#15 [ffff881f66bbff80] system_call_fastpath at ffffffff81697809
RIP: 00007f3ecc5b2c4d RSP: 00007fff64cd5d58 RFLAGS: 00000246
RAX: 0000000000000000 RBX: ffffffff81697809 RCX: ffffffffffffffff
RDX: 0000000000400000 RSI: 00007f3e0c775000 RDI: 0000000000000005
RBP: 0000000000000546 R8: 000000000c184920 R9: 88e78180e80a3431
R10: 0000000000000546 R11: 0000000000000293 R12: 0000000000000000
R13: 0000000000000000 R14: 0000000000000546 R15: 000000000c184840
ORIG_RAX: 0000000000000000 CS: 0033 SS: 002b
这边补充一点关于 page fault 的基础知识.page fault 是内存管理的 "心脏",是它,在不断的驱动着虚拟内存到物理内存的转换.指令访问内存地址时,如果内存地址不能被翻译为物理地址,那么 CPU 就会产生一次 page fault 异常.在 page fault 的处理逻辑中,合法地址和非法地址会被分开处理.对于合法地址,page fault 处理逻辑会通过换页,更新 page table 的方式,让地址可以被顺利地翻译成物理地址.而对于非法地址,page fault 处理逻辑会 crash 系统并生成 core dump.
现在我们回头观察调用栈上的 page fault 异常.首先异常发生在__free_pages+5 这条指令处.
[exception RIP: __free_pages+5]
下边是__free_pages 函数的汇编代码.__free_pages+5 指令是 lock decl 0x1c(%rdi),这条指令做的事情是锁递减 rdi+0x1c 这个地址的值.比较 rdi+0x1c 和最开始提到的 PANIC 报错,可以猜测 rdi 在问题发生的时候是 0,所以当指令 lock decl 0x1c(%rdi) 被执行的时候才会出现 PANIC: "BUG: unable to handle kernel NULL pointer dereference at 000000000000001c" 报错.
去证实这个猜测,需要想办法找出发生问题的时候 rdi 的值.这也就用到了调用栈上的 exception record,我们可以很明显的看出,当时记录的 rdi 确实是 0.
crash> dis __free_pages
0xffffffff8118a070 <__free_pages>: nopl 0x0(%rax,%rax,1) [FTRACE NOP]
0xffffffff8118a075 <__free_pages+5>: lock decl 0x1c(%rdi)
0xffffffff8118a079 <__free_pages+9>: sete %al
0xffffffff8118a07c <__free_pages+12>: test %al,%al
0xffffffff8118a07e <__free_pages+14>: je 0xffffffff8118a08e <__free_pages+30>
0xffffffff8118a080 <__free_pages+16>: push %rbp
0xffffffff8118a081 <__free_pages+17>: test %esi,%esi
0xffffffff8118a083 <__free_pages+19>: mov %rsp,%rbp
0xffffffff8118a086 <__free_pages+22>: je 0xffffffff8118a090 <__free_pages+32>
0xffffffff8118a088 <__free_pages+24>: callq 0xffffffff811897a0 <__free_pages_ok>
0xffffffff8118a08d <__free_pages+29>: pop %rbp
0xffffffff8118a08e <__free_pages+30>: repz retq
0xffffffff8118a090 <__free_pages+32>: callq 0xffffffff81189e70 <free_hot_cold_page>
0xffffffff8118a095 <__free_pages+37>: pop %rbp
0xffffffff8118a096 <__free_pages+38>: jmp 0xffffffff8118a08e <__free_pages+30>
知道问题发生的直接原因,接下来我们需要搞清楚两点,第一,rdi 存储的到底是什么值,第二,rdi 为什么会是 0.
[exception RIP: __free_pages+5]
RIP: ffffffff8118a075 RSP: ffff881f66bbfce0 RFLAGS: 00010246
RAX: 00000000fffffe00 RBX: 0000000000001a86 RCX: ffff881f66bbffd8
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
RBP: ffff881f66bbfe20 R8: ffff881f66bbfc28 R9: 0000000000000000
R10: df8093c0cb57bc70 R11: 0000000000000000 R12: 0000000000000000
R13: ffff881f66bbfe40 R14: 0000000000000000 R15: 0000000000000002
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
关于第一个问题,我们需要研究一下 Linux 在 x86_64 上的 calling conversion.这部分内容可以参考这一页内容.我们可以看到 rdi 实际上是传给函数__free_pages 的第一个参数.
https://en.wikipedia.org/wiki/X86_calling_conventions
关于第二个问题,从 call stack 上可以看出,调用__free_pages 的是 ceph_aio_read 函数.在下边的 code block 里,ceph_aio_read 定义了指针 page,并负责为其分配页面.而也正是在这个 code block 里,ceph_aio_read 负责释放页面.根据我们写代码的一般规则,函数局部变量的指针,函数自己需要维护其生命周期.
if (retry_op > HAVE_RETRIED && ret >= 0) {
int statret;
struct page *page = NULL;
loff_t i_size;
if (retry_op == READ_INLINE) {
page = __page_cache_alloc(GFP_KERNEL);
if (!page)
return -ENOMEM;
}
statret = __ceph_do_getattr(inode, page,
CEPH_STAT_CAP_INLINE_DATA, !!page);
if (statret < 0) {
__free_page(page);
if (statret == -ENODATA) {
BUG_ON(retry_op != READ_INLINE);
goto again;
}
return statret;
}
i_size = i_size_read(inode);
if (retry_op == READ_INLINE) {
BUG_ON(ret > 0 || read > 0);
ret = inline_to_iov(iocb, &i, page, statret, i_size);
__free_pages(page, 0);
return ret;
}
/* hit EOF or hole? */
if (retry_op == CHECK_EOF && iocb->ki_pos < i_size &&
ret < len) {
dout("sync_read hit hole, ppos %lld < size %lld"
", reading more\n", iocb->ki_pos, i_size);
read += ret;
len -= ret;
retry_op = HAVE_RETRIED;
goto again;
}
}
总结
根据上边的分析,基本上可以判断,这个问题发生的原因是 ceph 这个驱动.
了解更多请微博关注 阿里云客户满意中心
来源: https://yq.aliyun.com/articles/401178