作者：声东
大家好，今天跟大家分享一个Linux core dump分析的案例。
问题症状
问题的症状很简单，就是服务器不定期重启。客户使用的产品是CentOS云服务器。
详细分析
首先，用crash命令打开客户提供的core dump，能看到一些内核版本，vCPU数量，core dump产生的时间，开机时间等最基本的系统信息。这些信息中，和目前这个问题直接相关的是PANIC这一行。
首先，用crash命令打开客户提供的core dump，能看到一些内核版本，vCPU数量，core dump产生的时间，开机时间等最基本的系统信息。这些信息中，和目前这个问题直接相关的是PANIC这一行。
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)PANIC一行可以理解为，内核发生的问题是"NULL pointer dereference"，而被dereference的地址是000000000000001c。其实这句话本身是有点矛盾的，因为000000000000001c显然不是NULL pointer。猜测内核把"NULL pointer dereference"定义为一类错误，而不仅代表访问NULL指针的异常。
接下来，分析问题发生时候的调用栈。可以看到read系统调用从user mode传到了kernel，再从kernel，到vfs，最后被分发到具体的文件系统实现里。在这里，这个调用最终被分发到了ceph模块。ceph是一个分布式文件系统的实现。
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除了函数调用关系之外，在这个调用栈上，另一类关键信息是exception record。exception record是发生异常的时候，被记录下来的寄存器的值。这个调用栈上记录了两次异常，上边的异常是page fault，下边的异常是system call。第二个异常我们略过不细说，问题主要是第一个异常。
这边补充一点关于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"报错。
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的值。这也就用到了调用栈上的exception record，我们可以很明显的看出，当时记录的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知道问题发生的直接原因，接下来我们需要搞清楚两点，第一，rdi存储的到底是什么值，第二，rdi为什么会是0。
关于第一个问题，我们需要研究一下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这个驱动。
了解更多请微博关注阿里云客户满意中心
