从虚拟化前端Bug学习分析Kernel Dump
前言 也许大家都知道，分析 Kernel Dump 有个常用的工具叫 Crash，在我刚开始学习分析 Kernel Dump 的时候，总是花大量的时间折腾这个工具的用法，却总是记不住这个工具的功能。后来有一次在参加某次内部分享的时候，有位大佬说了一句话让我印象非常深刻：这些工具怎么用的大家不用记，等到真正开始用的时候你就会猜到这个工具有什么功能。 这篇文章我想通过分析一个实际的案例，尽量把学习Kernel Dump需要用到的知识串起来，虽然某些知识也许只会在这个案例中用到，但是我相信所用到的方法是可以应用到各个地方的。 起 线上有一台 VM 宕机了，刚好有抓到 dump，拿到一台测试机上就可以开始分析了。首先需要的是 kernel 版本对应的 symbol，如果事先不知道 kernel 的版本，可以通过 `strings corefile | grep "Linux version"' 获取到当前 corefile 的 kernel 版本，例如 3.10.0-862.14.4.el7.x86_64 在获取到内核版本之后，根据相应的发行版以及系统架构到特定的 symbol 发布页面下载 symbol，这里的发行版是 Centos，可以到http://debuginfo.centos.org/下载。如果是 Ubuntu 发行版，可以到http://ddebs.ubuntu.com/下载。要找到指定 kernel 版本的 symbol 很简单，只需要拿着 kernel 版本 3.10.0-862.14.4.el7.x86_64 搜一下就能找到了，通常我们需要的 symbol 的只有下面这三个中的两个，但是我总是记不住是哪两个，所以我会把三个都下载下来并安装：kernel-debug-debuginfo-3.10.0-862.14.4.el7.x86_64.rpm、kernel-debuginfo-3.10.0-862.14.4.el7.x86_64.rpm、kernel-debuginfo-common-x86_64-3.10.0-862.14.4.el7.x86_64.rpm。在安装的时候由于依赖的关系需要先安装 common 的 symbol 才能安装其它 symbol，另外如果测试机上的 kernel 版本比 corefile 的版本新，需要加上 --force 选项才能安装上。 承 在 symbol 安装完之后，就可以通过 crash 载入 corefile 和 symbol 了。 [root@iZxxx1Z crash]# crash /lib/debug/lib/modules/3.10.0-862.14.4.el7.x86_64/vmlinux i-2xxxpe.236725344.208176-2019-02-27-22\:44\:20 crash 7.2.3-8.el7 Copyright (C) 2002-2017 Red Hat, Inc. Copyright (C) 2004, 2005, 2006, 2010 IBM Corporation Copyright (C) 1999-2006 Hewlett-Packard Co Copyright (C) 2005, 2006, 2011, 2012 Fujitsu Limited Copyright (C) 2006, 2007 VA Linux Systems Japan K.K. Copyright (C) 2005, 2011 NEC Corporation Copyright (C) 1999, 2002, 2007 Silicon Graphics, Inc. Copyright (C) 1999, 2000, 2001, 2002 Mission Critical Linux, Inc. This program is free software, covered by the GNU General Public License, and you are welcome to change it and/or distribute copies of it under certain conditions. Enter "help copying" to see the conditions. This program has absolutely no warranty. Enter "help warranty" for details. GNU gdb (GDB) 7.6 Copyright (C) 2013 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-unknown-linux-gnu"... WARNING: kernel relocated [168MB]: patching 82671 gdb minimal_symbol values KERNEL: /lib/debug/lib/modules/3.10.0-862.14.4.el7.x86_64/vmlinux DUMPFILE: i-2xxxpe.236725344.208176-2019-02-27-22:44:20 CPUS: 4 [OFFLINE: 3] DATE: Wed Feb 27 22:44:18 2019 UPTIME: 11:34:59 LOAD AVERAGE: 0.20, 0.07, 0.06 TASKS: 436 NODENAME: iZ2xxxpeZ RELEASE: 3.10.0-862.14.4.el7.x86_64 VERSION: #1 SMP Wed Sep 26 15:12:11 UTC 2018 MACHINE: x86_64 (2500 Mhz) MEMORY: 16 GB PANIC: "kernel BUG at drivers/virtio/virtio_ring.c:278!" PID: 278 COMMAND: "kworker/2:1H" TASK: ffff917c6d3b3f40 [THREAD_INFO: ffff917c64798000] CPU: 2 STATE: TASK_RUNNING (PANIC) 通过 crash 载入 corefile 的时候，crash 会自动输出一段信息，这段信息包含了系统的一些基本信息，如 CPU、内存、架构等。如果后面分析的时候还想看这部分信息，可以通过 sys 命令来查看。这里我们需要重点关注的信息是 PANIC: "kernel BUG at drivers/virtio/virtio_ring.c:278!" 这个信息告诉我们，系统触发了位于 drivers/virtio/virtio_ring.c 这个文件的第 278 行的 Bug，这里系统之所以知道是 Bug，是因为编写这段代码的大佬在这里埋了一个检测的点，这个待会我们会在源码里看到。 在看完上面的信息后，我的习惯是先看看当时系统在做什么，通过 bt 命令可以看到当时的调用堆栈： crash> bt PID: 278 TASK: ffff917c6d3b3f40 CPU: 2 COMMAND: "kworker/2:1H" #0 [ffff917c6479b8a0] die at ffffffff8b82f96b #1 [ffff917c6479b8d0] do_trap at ffffffff8bf1cea0 #2 [ffff917c6479b920] do_invalid_op at ffffffff8b82c284 #3 [ffff917c6479b9d0] invalid_op at ffffffff8bf28aee [exception RIP: virtqueue_add+1186] RIP: ffffffffc023a382 RSP: ffff917c6479ba80 RFLAGS: 00010097 RAX: 0000000000000081 RBX: ffff917c6c67d000 RCX: 0000000000000002 RDX: 0000000000000081 RSI: ffff917c6479bc00 RDI: ffff917c6c67d000 RBP: ffff917c6479bae8 R8: 0000000000000001 R9: ffff917c6b48a380 R10: ffff917c6b410000 R11: 0000000000000002 R12: ffff917c6479bc18 R13: ffff917c6479bc18 R14: ffff917c6479bc00 R15: 0000000000000001 ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018 #4 [ffff917c6479ba80] __kmalloc at ffffffff8b9fbeb0 #5 [ffff917c6479baf0] virtqueue_add_sgs at ffffffffc023a437 [virtio_ring] #6 [ffff917c6479bb48] __virtblk_add_req at ffffffffc03874b2 [virtio_blk] #7 [ffff917c6479bc68] virtio_queue_rq at ffffffffc03876f9 [virtio_blk] #8 [ffff917c6479bcb8] blk_mq_dispatch_rq_list at ffffffff8bb2a8b6 #9 [ffff917c6479bd50] blk_mq_do_dispatch_sched at ffffffff8bb2f76e #10 [ffff917c6479bd98] blk_mq_sched_dispatch_requests at ffffffff8bb3012e #11 [ffff917c6479bde8] __blk_mq_run_hw_queue at ffffffff8bb29362 #12 [ffff917c6479be10] blk_mq_run_work_fn at ffffffff8bb295c5 #13 [ffff917c6479be20] process_one_work at ffffffff8b8b613f #14 [ffff917c6479be68] worker_thread at ffffffff8b8b71d6 #15 [ffff917c6479bec8] kthread at ffffffff8b8bdf21 上图打印的信息包含函数调用堆栈和各寄存器的值，这里挑几个比较重要的寄存器讲一下。 RIP 指向正在执行的指令地址，在发生宕机之前，系统最后执行的函数是 virtqueue_add，导致宕机的语句位于 virtqueue_add+1186。根据 x86_64 Linux 系统的函数调用约定，RDI, RSI, RDX, RCX, R8, R9为传入函数的前六个参数，如果参数超过六个，第七个以上的参数将通过栈传递。注意在实际函数执行的过程中，寄存器的值可能会改变。 现在来看看 ffffffffc023a382+1186 这行代码到底是什么，通过 dis 命令可以查看到对应的汇编。但当我们执行dis virtqueue_add+1186的时候，发现报错了，报错的内容是 symbol 有重复。 crash> dis virtqueue_add+1186 dis: virtqueue_add+1186: duplicate text symbols found: ffffffffc0239ee0 (t) virtqueue_add [virtio_ring] ffffffffc023ab73 (t) virtqueue_add [virtio_ring] 我们可以通过 RIP 的值来计算出当前的 virtqueue_add 对应的是哪个 symbol，计算方法很简单，只要把 RIP 的值减去偏移量 1186 即可。 crash> p/x 0xffffffffc023a382-1186 $1 = 0xffffffffc0239ee0 通过dis ffffffffc0239ee0可以打印出 virtqueue_add 的汇编，找到 virtqueue_add+1186 0xffffffffc023a378 <virtqueue_add+1176>: mov 0x60(%rbx),%eax 0xffffffffc023a37b <virtqueue_add+1179>: jmpq 0xffffffffc023a299 <virtqueue_add+953> 0xffffffffc023a380 <virtqueue_add+1184>: ud2 0xffffffffc023a382 <virtqueue_add+1186>: ud2 该行汇编实际上是 ud2 ，这是一条 undefined 的语句，也正是因为这条语句让系统宕机了。这个时候通常应该往上找，看看之前执行过的指令是什么。这里上一条指令是 jmpq ，这是无条件跳转语句，跳转到 virtqueue_add+953，也就是说 ud2 指令的上一条指令一定不是 jmpq 这条，可以猜到应该是前面有某个跳转直接跳到这里来了，往上找找就可以找到 0xffffffffc0239ef4 <virtqueue_add+20>: mov %rsi,-0x48(%rbp) 0xffffffffc0239ef8 <virtqueue_add+24>: mov %edx,-0x2c(%rbp) 0xffffffffc0239efb <virtqueue_add+27>: mov %ecx,-0x38(%rbp) 0xffffffffc0239efe <virtqueue_add+30>: mov %r8d,-0x58(%rbp) 0xffffffffc0239f02 <virtqueue_add+34>: mov %r9,-0x60(%rbp) 0xffffffffc0239f06 <virtqueue_add+38>: je 0xffffffffc023a384 <virtqueue_add+1188> 0xffffffffc0239f0c <virtqueue_add+44>: cmpb $0x0,0x59(%rdi) 0xffffffffc0239f10 <virtqueue_add+48>: mov %rdi,%rbx 0xffffffffc0239f13 <virtqueue_add+51>: jne 0xffffffffc023a05d <virtqueue_add+381> 0xffffffffc0239f19 <virtqueue_add+57>: mov -0x2c(%rbp),%eax 0xffffffffc0239f1c <virtqueue_add+60>: cmp %eax,0x38(%rdi) 0xffffffffc0239f1f <virtqueue_add+63>: jb 0xffffffffc023a382 <virtqueue_add+1186> 可以看到跳转的语句是jb 0xffffffffc023a382 <virtqueue_add+1186>，跳转的条件是 %eax 小于 [%rdi + 0x38]。那 %eax 和 [%rdi + 0x38] 里面存的值是什么呢？这个时候就需要对照源码来看了。通过dis -l可以看到函数所在的源文件，但是直接执行dis -l ffffffffc0239ee0会发现没有源文件的信息，这种情况通常是对应的 debug 模块没有导进来。通过 mod 命令可以看到当前的模块，找到我们需要的模块，通过 mod -s 找到模块对应的目录，再通过相同的命令导入即可，如： crash> mod -s virtio_ring MODULE NAME SIZE OBJECT FILE ffffffffc023c0e0 virtio_ring 22746 /usr/lib/debug/usr/lib/modules/3.10.0-862.14.4.el7.x86_64/kernel/drivers/virtio/virtio_ring.ko.debug crash> mod -s virtio_ring /usr/lib/debug/usr/lib/modules/3.10.0-862.14.4.el7.x86_64/kernel/drivers/virtio/virtio_ring.ko.debug MODULE NAME SIZE OBJECT FILE ffffffffc023c0e0 virtio_ring 22746 /usr/lib/debug/usr/lib/modules/3.10.0-862.14.4.el7.x86_64/kernel/drivers/virtio/virtio_ring.ko.debug 把所有缺少的模块导入进来之后，再次执行dis -l ffffffffc0239ee0就可以看到对应的源文件了。部分 virtqueue_add 源代码如下： 241 static inline int virtqueue_add(struct virtqueue *_vq, 242 struct scatterlist *sgs[], 243 unsigned int total_sg, 244 unsigned int out_sgs, 245 unsigned int in_sgs, 246 void *data, 247 gfp_t gfp) 248 { 249 struct vring_virtqueue *vq = to_vvq(_vq); 250 struct scatterlist *sg; 251 struct vring_desc *desc; 252 unsigned int i, n, avail, descs_used, uninitialized_var(prev), err_idx; 253 int head; 254 bool indirect; 255 256 START_USE(vq); 257 258 BUG_ON(data == NULL); 259 260 if (unlikely(vq->broken)) { 261 END_USE(vq); 262 return -EIO; 263 } 264 265 #ifdef DEBUG 266 { 267 ktime_t now = ktime_get(); 268 269 /* No kick or get, with .1 second between? Warn. */ 270 if (vq->last_add_time_valid) 271 WARN_ON(ktime_to_ms(ktime_sub(now, vq->last_add_time)) 272 > 100); 273 vq->last_add_time = now; 274 vq->last_add_time_valid = true; 275 } 276 #endif 277 278 BUG_ON(total_sg > vq->vring.num); 279 BUG_ON(total_sg == 0); 280 281 head = vq->free_head; 282 283 /* If the host supports indirect descriptor tables, and we have multiple 284 * buffers, then go indirect. FIXME: tune this threshold */ 285 if (vq->indirect && total_sg > 1 && vq->vq.num_free) 286 desc = alloc_indirect(_vq, total_sg, gfp); 287 else 288 desc = NULL; 289 290 if (desc) { 291 /* Use a single buffer which doesn't continue */ 292 indirect = true; 293 /* Set up rest to use this indirect table. */ 294 i = 0; 295 descs_used = 1; 296 } else { 297 indirect = false; 298 desc = vq->vring.desc; 299 i = head; 300 descs_used = total_sg; 301 } 通过dis -l ffffffffc0239ee0打印出的信息并结合之前的分析，可以知道：1. virtqueue_add 的前五个参数分别是 struct virtqueue、struct scatterlist、 unsigned int、 unsigned int、 unsigned int 类型的，对应的是 RDI, RSI, RDX, RCX, R8 这五个寄存器的值。2. 触发 bug 的语句是第 278 行的BUG_ON(total_sg > vq->vring.num); 通过struct virtqueue ffff917c6c67d000可以解析出第一个参数的结构： crash> struct virtqueue ffff917c6c67d000 struct virtqueue { list = { next = 0xffff917bbefa82c8, prev = 0xffff917bbefa82c8 }, callback = 0xffffffffc0387000, name = 0xffff917c6c7a1dcc "req.0", vdev = 0xffff917bbefa8000, index = 0, num_free = 1, priv = 0xffffadff81b5e010 } 回到刚刚我们讨论的 %eax 和 [%rdi + 0x38] ，[%rdi + 0x38] 实际上就是 virtqueue 中偏移量为 0x38 的值，通过struct -o virtqueue可以打印出 virtqueue 各成员的偏移： crash> struct -o virtqueue struct virtqueue { [0] struct list_head list; [16] void (*callback)(struct virtqueue *); [24] const char *name; [32] struct virtio_device *vdev; [40] unsigned int index; [44] unsigned int num_free; [48] void *priv; } SIZE: 56 这里又出现了一个问题，0x38 是十进制的 56，而这个结构体的大小总共只有 56 个字节，难道是“溢出”了？仔细阅读代码后发现，代码里有一句struct vring_virtqueue *vq = to_vvq(_vq);，to_vvq 是一个宏，定义如下#define to_vvq(_vq) container_of(_vq, struct vring_virtqueue, vq)，实际上这就是对 container_of 的一个封装，container_of 的功能跟字面意思很接近，这里 virtqueue 类型的 _vq 变量实际上是 vring_virtqueue 类型的 vq 变量的一个成员变量，通过 container_of(_vq, struct vring_virtqueue, vq) 把 vq 计算出来。我们通过struct -o vring_virtqueue来查看 vring_virtqueue 的结构： crash> struct -o vring_virtqueue struct vring_virtqueue { [0] struct virtqueue vq; [56] struct vring vring; [88] bool weak_barriers; [89] bool broken; [90] bool indirect; [91] bool event; [92] unsigned int free_head; [96] unsigned int num_added; [100] u16 last_used_idx; [104] bool (*notify)(struct virtqueue *); [112] bool we_own_ring; [120] size_t queue_size_in_bytes; [128] dma_addr_t queue_dma_addr; [136] struct vring_desc_state desc_state[]; } SIZE: 136 可以看到实际上 virtqueue 结构就在 vring_virtqueue 偏移为 0 的地方，因此可以直接通过struct vring_virtqueue ffff917c6c67d000来解析 vring_virtqueue 结构： crash> struct vring_virtqueue ffff917c6c67d000 struct vring_virtqueue { vq = { list = { next = 0xffff917bbefa82c8, prev = 0xffff917bbefa82c8 }, callback = 0xffffffffc0387000, name = 0xffff917c6c7a1dcc "req.0", vdev = 0xffff917bbefa8000, index = 0, num_free = 1, priv = 0xffffadff81b5e010 }, vring = { num = 128, desc = 0xffff917c6bf68000, avail = 0xffff917c6bf68800, used = 0xffff917c6bf69000 }, weak_barriers = true, broken = false, indirect = true, event = false, free_head = 94, num_added = 0, last_used_idx = 38531, notify = 0xffffffffc0249a50, we_own_ring = true, queue_size_in_bytes = 5126, queue_dma_addr = 17917444096, desc_state = 0xffff917c6c67d088 } 因此 [%rdi + 0x38] 实际上获取的是 vring 结构里偏移量为 0 的即第一个成员的值，这里获取到的值就是 128。现在我们已经通过这种方法获取到触发 bug 的语句中BUG_ON(total_sg > vq->vring.num);的 vq->vring.num 值了，而 total_sg 实际上是 virtqueue_add 的第三个参数，保存在 RDX 寄存器里，是 0x81，即十进制的 129。 合 至此，我只是分析了这几个数据结构中相关的变量内容，还没有解释这些变量或者函数的含义，现在我们已经验证了触发 BUG 的条件 total_sg > vq->vring.num，但是为什么会出现这种情况呢？要分析这几个变量的值需要回溯到调用这个函数的函数，最终可能需要一直回溯到发起 IO 请求的应用层程序，这显然是一件非常麻烦的事情。换一个角度来想，total_sg 是 vm 需要的 scatterlist 的总数，scatterlist 是一个跟物理内存有关的结构，这里可以简单理解为 vm 所需要的物理内存，而 vring 是 virtio 前后端数据传输的载体，这里可以简单理解前后端数据传输的能力。直观的感觉是 total_sg 确实不应该比 vring.num 大，但实际上 total_sg 只比 vring.num 大 1，而且这里 total_sg 的值与我刚开始的想法不一样，由于 total_sg 是 unsigned int 类型的，而这里的比较是 total_sg > vq->vring.num，因此我开始的想法是 total_sg 下溢出了。分析到这里，我抱着试一试的态度把BUG_ON(total_sg > vq->vring.num);丢到 Google 上搜了一把，发现这行代码已经在某个版本中 patch 掉了，最新的 kernel 里把 BUG_ON 改成了低一级的 WARN_ON_ONCE，同时把条件改成了 total_sg > vq->vring.num && !vq->indirect。也就是说，在使用了 indirect descriptors 的情况下，是允许 total_sg > vq->vring.num 这中情况出现的，那如何验证 vm 有没有使用 indirect descriptors 呢？实际上在 vring_virtqueue 中的成员 indirect 标示了是否使用 indirect descriptors，在上面执行struct vring_virtqueue ffff917c6c67d000的时候已经把 indirect 的值打印出来了，vm 确实使用了 indirect descriptors，因此这个 bug 实际上触发得并不合理，仅仅只判断 total_sg > vq->vring.num 就触发宕机的条件太过严格了。 总结 这个宕机问题到这里就算分析完了，最后解决的方案是升级内核，考虑到目前 Centos 官方还未接受该 patch，需要手动编译修复或通过第三方 repo 升级。实际上很多奇奇怪怪的问题都可以通过升级内核来解决，但是最新的内核同样可能遇到奇奇怪怪的问题，谁知道下一个发现内核 bug 后写了 patch 最后被社区接受的会不会是自己呢？希望大家通过这篇文章能有所收获。文章写得不好或不对的地方请各位大佬不吝赐教。 作者：半人前 原文链接 本文为云栖社区原创内容，未经允许不得转载。
