问题症状

问题的症状很简单，就是服务器不定期重启。客户使用的产品是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这个驱动。

了解更多请微博关注阿里云客户满意中心

ceph驱动引起的内核Crash分析

问题症状

详细分析

总结

阿里云支持与服务

热门文章

最新文章

相关课程

相关电子书