前言
這篇文章主要分享在 CentOS 下，使用 crash 分析 vmcore 除錯的經驗。
上星期收到一件來自日本的客服案例：客戶的 Linux server 發生 panic 導致系統重啟。客戶將 kernel panic 產生的 vmcore 以及 server vendor – Red Hat 的反饋一起傳給我們，由於 Red Hat 反饋表示這是我們 driver 的問題，於是客戶就要求我們針對 7GB 的 vmcore 進行分析。
其實我沒有處理過 Linux kernel panic 的經驗(只有接過 Windows BSOD1 的案子)，問了公司幾位前輩，通常發生這種問題時，客戶只會給我們純文字 error log 以及問題的複現流程。但這次客戶只發生過一次 panic，也不知道如何複製問題，我唯一的資訊只有 vmcore，因此我才花了一些時間學習如何分析 vmcore。
工具準備及環境建置
這次分析需要安裝：
- crash
- vmlinux
yum install crash
vmlinux and vmcore do not match! 的錯誤。要怎麼知道 vmcore 是在哪一版的 kernel 產生的呢？可以用 strings 去抓 vmcore 的資訊：
[root@localhost ~]# strings vmcore | grep OSRELEASE
OSRELEASE=3.10.0-327.el7.x86_64
^C
[root@localhost ~]#
OSRELEASE=3.10.0-327.el7.x86_64，就可以到 debuginfo.centos.org 下載對應版本的 kernel-debuginfo 了，其中 vmlinux 就包含在 debuginfo package 裡面。由於 debuginfo 依存於 debuginfo-common ，因此這兩項都要下載並透過 rpm 安裝：
[root@localhost ~]# rpm -ivh kernel-debuginfo-common-x86_64-3.10.0-327.el7.x86_64.rpm
[root@localhost ~]# rpm -ivh kernel-debuginfo-3.10.0-327.el7.x86_64.rpm
[root@localhost ~]# find /usr/lib/debug/lib/modules/3.10.0-327.el7.x86_64/ -name vmlinux
/usr/lib/debug/lib/modules/3.10.0-327.el7.x86_64/vmlinux
[root@localhost ~]#
開始分析
執行 crash 並帶入 vmlinux 與 vmcore，會看到類似以下畫面：
[root@localhost ~]# crash /usr/lib/debug/lib/modules/3.10.0-327.el7.x86_64/vmlinux vmcore
crash 7.1.5-2.el7
Copyright (C) 2002-2016 Red Hat, Inc.
...(略)
KERNEL: /usr/lib/debug/lib/modules/3.10.0-327.el7.x86_64/vmlinux
DUMPFILE: vmcore
CPUS: 8
DATE: Mon Apr 3 04:16:14 2017
UPTIME: 47 days, 02:41:16
LOAD AVERAGE: 0.74, 0.33, 0.18
TASKS: 676
NODENAME: xxx
RELEASE: 3.10.0-327.el7.x86_64
VERSION: #1 SMP Thu Oct 29 17:29:29 EDT 2015
MACHINE: x86_64 (2594 Mhz)
MEMORY: 31.7 GB
PANIC: "Kernel panic - not syncing: Watchdog detected hard LOCKUP on cpu 5"
PID: 0
COMMAND: "swapper/5"
TASK: ffff8808541f5c00 (1 of 8) [THREAD_INFO: ffff880852b98000]
CPU: 5
STATE: TASK_RUNNING (PANIC)
Kernel panic - not syncing: Watchdog detected hard LOCKUP on cpu 5 。有興趣可以 google 一下 soft/hard LOCKUP 的差別。crash 內建了許多好用的指令，首先
bt 可以說是必用的指令之一。bt - backtrace
crash> bt
PID: 0 TASK: ffff8808541f5c00 CPU: 5 COMMAND: "swapper/5"
#0 [ffff88087fd459c8] machine_kexec at ffffffff81051beb
#1 [ffff88087fd45a28] crash_kexec at ffffffff810f2542
#2 [ffff88087fd45af8] panic at ffffffff8162ea73
#3 [ffff88087fd45b78] watchdog_overflow_callback at ffffffff8111b512
#4 [ffff88087fd45b88] __perf_event_overflow at ffffffff8115ed71
#5 [ffff88087fd45c00] perf_event_overflow at ffffffff8115f844
#6 [ffff88087fd45c10] intel_pmu_handle_irq at ffffffff810325a8
#7 [ffff88087fd45e60] perf_event_nmi_handler at ffffffff8163ebeb
#8 [ffff88087fd45e80] nmi_handle at ffffffff8163e339
#9 [ffff88087fd45ec8] do_nmi at ffffffff8163e4e9
#10 [ffff88087fd45ef0] end_repeat_nmi at ffffffff8163d771
[exception RIP: ioread8+66]
RIP: ffffffff81309532 RSP: ffff88087fd43e28 RFLAGS: 00000092
RAX: ffffc90013422a7e RBX: 0000000000000020 RCX: 0000000000000000
RDX: 0000000000009580 RSI: ffff88085f408a00 RDI: ffffc90013422a06
RBP: ffff88087fd43ea8 R8: 0000000000000000 R9: 0000000000000082
R10: ffff88085f403500 R11: 000e783a5cdff909 R12: 0000000000000022
R13: 000000000000000e R14: 0000000000000f50 R15: ffffffffa03fac10
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
--- <NMI exception stack> ---
#11 [ffff88087fd43e28] ioread8 at ffffffff81309532
#12 [ffff88087fd43e28] mx_interrupt at ffffffffa03f1940 [mxupcie]
#13 [ffff88087fd43eb0] handle_irq_event_percpu at ffffffff8111c2be
#14 [ffff88087fd43ef8] handle_irq_event at ffffffff8111c49d
#15 [ffff88087fd43f20] handle_fasteoi_irq at ffffffff8111f90a
#16 [ffff88087fd43f40] handle_irq at ffffffff81016ecf
#17 [ffff88087fd43f78] do_IRQ at ffffffff81647daf
--- <IRQ stack> ---
...(略)
[exception RIP: ioread8+66]，其中 RIP 是一個 instruction pointer 的暫存器，它指向了正在被執行的指令的記憶體位置。更重要的是，我發現了在 call trace #12 顯示的 mx_interrupt at ffffffffa03f1940 [mxupcie] 正好是我們 driver 的一個函式。獲得以上訊息，接著我們可以利用
dis 命令將其反組譯：dis - disassembling instruction
dis 後面接 address 或 symbol，加個-l 參數可以直接指出 source code line number。crash> dis -l ioread8+66
/usr/src/debug/kernel-3.10.0-327.el7/linux-3.10.0-327.el7.x86_64/lib/iomap.c: 73
0xffffffff81309532 <ioread8+66>: movzbl %al,%eax
crash>
crash> dis -l ffffffffa03f1940
0xffffffffa03f1940 <mx_interrupt+384>: test $0xf,%al
crash>
ioread8+66 可以指出位於 iomap.c: 73，但是反組譯 mx_interrupt 所在位置 ffffffffa03f1940 卻不知道是哪一行程式。其實原因是沒有載入 driver module 的 symbol，所以認不出來，因此只要利用 mod 指令載入 module 2就沒問題囉！crash> mod -s mxupcie /mydriver/mxupcie.ko
MODULE NAME SIZE OBJECT FILE
ffffffffa03f9120 mxupcie 69583 /mydriver/mxupcie.ko
crash> dis -l ffffffffa03f1940
/mydriver/mxpcie.c: 2485
0xffffffffa03f1940 <mx_interrupt+384>: test $0xf,%al
crash>
mxpcie.c: 2485 ，恭喜你終於可以開始對程式碼 debug 啦~!註釋
- Blue Screen of Death (BSOD) - Windows 當機，顯示藍屏畫面。Windows BSOD 預設會產生 minidump，R&D 可以透過 minidump 查詢當機的原因，個人覺得與本案例 Linux 的 vmcore 類似。有需要也可以修改 Windows 系統預設值，使當機時產生full dump，而非只有部分核心訊息的 minidump。 ↩
- 載入 module symbol 時，有意識到客戶用 Red Hat build 出來的 driver 和我在 CentOS build 出來的可能會有差異，雖然都是 Kernel 3.10，但不確定有無影響。因此我使用了 objdump 反組譯 CentOS build 出來的組合語言，比對
test $0xf,%al這一行是否指到同一行程式碼，還好結果是相同的。 ↩
沒有留言:
張貼留言