前一陣子有追蹤一個 ARM 平台發生 Kernel BUG_ON 的問題，在同事的協助下花了一點時間終於追出可能的原因。在我剛開始接觸 Linux Kernel 時，遇到這類 log 都很不知道該如何下手，累積了一些經驗以後才慢慢知道該如何切入、分析及找出原因。
這篇會分享實際分析 Kernel Oops log 的過程，以及相關工具的使用方式做為案例分析給各位參考。
Oops!
遇到 Kernel panic 或 Oops 的時候，Kernel 通常會 dump 一些訊息出來，可以在 dmesg 或是 /var/log/kern.log 等地方找到他。以下是這次實際遇到問題時所產生的 log，由於訊息頗長，我有把部分區段省略 :
------------[ cut here ]------------
kernel BUG at fs/ext4/inode.c:2292!
Internal error: Oops - BUG: 0 [#1] SMP ARM
Modules linked in: ecryptfs dm_flakey 8021q fuse vhost_scsi(OF) vhost(OF) tcm_loop(OF) ...
CPU: 0 PID: 24740 Comm: loop1 Tainted: PF O 3.10.108
task: 9f1b4580 ti: 8e0ba000 task.ti: 8e0ba000
PC is at write_cache_pages_da+0x3c0/0x460
LR is at __wait_on_bit_lock+0x80/0xa0
pc : [<801733a4>] lr : [<803f0454>] psr: 00000013
sp : 8e0bbcd8 ip : 00000000 fp : 8e0bbdc0
r10: 00000002 r9 : 00000000 r8 : 000194c3
r7 : 8e0bbe40 r6 : 8df4a788 r5 : 9dc88368 r4 : 8082c1e0
r3 : 0000283d r2 : 9dc8846c r1 : 20000013 r0 : 00000000
Flags: nzcv IRQs on FIQs on Mode SVC_32 ISA ARM Segment kernel
Control: 10c53c7d Table: 1ba0004a DAC: 00000015
Process loop1 (pid: 24740, stack limit = 0x8e0ba238)
Stack: (0x8e0bbcd8 to 0x8e0bc000)
bcc0: 0000000e 805f1510
bce0: 000194c4 00000000 ffffffff 9dc8846c 00000002 0000000e 9edb0f80 7fffff06
bd00: 8e0bbd00 000194d0 0000000e 00000000 80655440 80888300 8082c1e0 808e4b20
...
bfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
bfe0: 00000000 00000000 00000000 00000000 00000013 00000000 7423f168 7423eca8
[<801733a4>] (write_cache_pages_da+0x3c0/0x460) from [<80173688>] (ext4_da_writepages+0x244/0x464)
[<80173688>] (ext4_da_writepages+0x244/0x464) from [<800a466c>] (do_writepages+0x30/0x84)
[<800a466c>] (do_writepages+0x30/0x84) from [<8009b350>] (__filemap_fdatawrite_range+0x4c/0x54)
[<8009b350>] (__filemap_fdatawrite_range+0x4c/0x54) from [<8009b474>] (filemap_write_and_wait_range+0x34/0x74)
[<8009b474>] (filemap_write_and_wait_range+0x34/0x74) from [<8016b104>] (ext4_sync_file+0x48/0x29c)
[<8016b104>] (ext4_sync_file+0x48/0x29c) from [<80106aa0>] (vfs_fsync+0x3c/0x54)
[<80106aa0>] (vfs_fsync+0x3c/0x54) from [<7f345c40>] (loop_thread+0x2a8/0x55c [loop])
[<7f345c40>] (loop_thread+0x2a8/0x55c [loop]) from [<8003d9fc>] (kthread+0xb4/0xb8)
[<8003d9fc>] (kthread+0xb4/0xb8) from [<8000e280>] (ret_from_fork+0x14/0x34)
Code: ebfc9a04 e5943000 e3130a02 0affff6d (e7f001f2)
---[ end trace 1e36d7c9ed058ce2 ]---
每個平台在一些小細節上可能會有一點不一樣，但基本上大同小異。
出錯的原因
Oops 的第一行通常可以得到錯誤的主要原因，例如這次案例所印訊息
kernel BUG at fs/ext4/inode.c:2292!
這個訊息是 Kernel BUG_ON 造成的，BUG_ON(condition) 是一個類似 assert 的函式，condition 預期是不成立的，當成立的時候，表示系統發生 BUG，然後 kernel 就會 dump 這些訊息，通常機器也就掛了。
BUG_ON 通常會明確指出錯誤的程式碼位置，此時就可以打開程式碼直接進行對照，像這次發生問題的位置就在 fs/ext4/inode.c 的 2292 行
/*2291*/ wait_on_page_writeback(page);
/*2292*/ BUG_ON(PageWriteback(page));
除了 BUG_ON 以外，BUG: unable to handle kernel NULL pointer dereference at (null) 也是常見的錯誤訊息。
出錯的程序
知道錯誤的原因後，接下來我們可能會想知道是哪隻 Process 觸發了這個錯誤 :
CPU: 0 PID: 24740 Comm: loop1 Tainted: PF O 3.10.108
從上面的 log 中，我們可知道發生問題的指令(Comm) 為 loop1 這隻程序，出錯當下運行在 CPU 0，而 PID 為 24740。
出錯的程式碼位置
有些時候， dump 出來的訊息可能沒有直接指出錯誤的程式碼位置，此時我們需要借助其他資訊來追蹤，可以利用的就是 PC (Program Counter) 中所記錄的資訊，例如以下 log
PC is at write_cache_pages_da+0x3c0/0x460
PC (Program Counter) 是程式計數器，儲存的是目前電腦執行的指令位址。Oops 發生時，kernel 會把發生當下的暫存器狀態保留下來，而保存下來的 PC 就是出錯時的執行位址囉！在 x86 的系統上，他通常會叫 IP (Instruction Pointer)，但意思是類似的。
現在我們知道出問題的位置是 write_cache_pages_da+0x3c0，代表 write_cache_pages_da 函式中 offset 為 0x3c0 的地方，但如何得知 offset 0x3c0 實際指的是程式的哪一行呢？
我們可以借助 gdb 來讀出 binary 內的除錯訊息。用 gdb 讀入你的 vmlinux 或是函式所在的 kernel module 後，輸入 list*(write_cache_pages_da+0x3c0)，就可以找到錯誤的位置了。
# gdb ext4.ko
(gdb) list *(write_cache_pages_da+0x3c0)
0x53e8 is in write_cache_pages_da (fs/ext4/inode.c:2292).
2289 }
2290
2291 wait_on_page_writeback(page);
2292 BUG_ON(PageWriteback(page));
2293
2294 /*有時候位置可能會誤差一到兩行，但通常也已經足夠精確讓我們進行判斷，另外要注意，如果你的 kernel 沒有打開 CONFIG_DEBUG_INFO 的選項，你可能會需要打開他並重新建置，否則 gdb 會找不到 debug symbol。
出錯的過程 (Call Stack)
接下來我們可能會想知道出錯的程式是從哪些函式一層一層呼叫進來，我們可以從 Oops 所印的 Call Stack 的訊息來得知:
[<801733a4>] (write_cache_pages_da+0x3c0/0x460) from [<80173688>] (ext4_da_writepages+0x244/0x464)
[<80173688>] (ext4_da_writepages+0x244/0x464) from [<800a466c>] (do_writepages+0x30/0x84)
[<800a466c>] (do_writepages+0x30/0x84) from [<8009b350>] (__filemap_fdatawrite_range+0x4c/0x54)
[<8009b350>] (__filemap_fdatawrite_range+0x4c/0x54) from [<8009b474>] (filemap_write_and_wait_range+0x34/0x74)
[<8009b474>] (filemap_write_and_wait_range+0x34/0x74) from [<8016b104>] (ext4_sync_file+0x48/0x29c)
[<8016b104>] (ext4_sync_file+0x48/0x29c) from [<80106aa0>] (vfs_fsync+0x3c/0x54)
[<80106aa0>] (vfs_fsync+0x3c/0x54) from [<7f345c40>] (loop_thread+0x2a8/0x55c [loop])
[<7f345c40>] (loop_thread+0x2a8/0x55c [loop]) from [<8003d9fc>] (kthread+0xb4/0xb8)
[<8003d9fc>] (kthread+0xb4/0xb8) from [<8000e280>] (ret_from_fork+0x14/0x34)
例如以上的 log，出錯時的呼叫過程是 kthread -> loop_thread -> vfs_fsync -> ext4_sync_file -> ... -> write_cache_pages_da 這樣一層一層呼叫走到出錯當下的程式碼。如果有需求的話，像是 ext4_sync_file+0x48 之類的訊息，我們也一樣可以利用 gdb 找出實際在程式碼的哪一行。
出錯的記憶體資訊
有些時候我們還需要記憶體相關的資訊來協助我們判斷問題，例如這次的案例中，BUG 是發生在 page->flags 有 0x2000 (PG_writeback) 這個 bit:
wait_on_page_writeback(page); // 若 page->flags 有 PG_writeback，就等到他被清除
BUG_ON(PageWriteback(page)); // 若 page->flags 的 PG_writeback 還在，就觸發 BUG
page->flags 這個變數當時到底是什麼值呢？我們此時需要 dump 出來的暫存器來協助我們找出當下的變數值。
由於 Oops 並沒有告訴我們各個暫存器當時是在處理什麼變數，因此會需要對照編譯後的組合語言來進行確認，我們可以利用 objdump -d 來解出人比較好看懂的組合語言。以下是這次案例的 objdump 結果:
# objdump -d ext4.ko
...
00005028 <write_cache_pages_da>:
...
53d8: ebfffffe bl 0 <wait_on_page_bit>
53dc: e5943000 ldr r3, [r4] ; 把 [r4] 讀到 r3
53e0: e3130a02 tst r3, #8192 ; 測試 r3 的 0x2000 (PG_writeback) bit 是否為零
53e4: 0affff6d beq 51a0 <write_cache_pages_da+0x178> ; jump
53e8: e7f001f2 .word 0xe7f001f2
...
由於 dump 出來內容很長，所以我只留下了關鍵的部分。至於要如何找到關鍵的組語位置呢？我們知道出錯的地方是 write_cache_pages_da+0x3c0，可以直接在 objdump 搜尋 <write_cache_pages_da>，前方有該函式的位址，像這次的位址是 0x5028，之後再加上 0x3c0 我們可以得到 0x53e8，而關鍵的組語可能就會在這個位址的附近。
從組合語言中可以看到，出錯的當下是把 r4 的位址讀到 r3，並檢查 r3 是否有 0x2000 的 bit。也就是 page->flags 這個變數被放入了 r3 暫存器，而 r4 的暫存器則是存著 page->flags 的記憶體位址，再對照先前的 dump 資訊，我們可以發現出錯當下的 r3 為 0000283d，確實有 0x2000 的 bit！
sp : 8e0bbcd8 ip : 00000000 fp : 8e0bbdc0
r10: 00000002 r9 : 00000000 r8 : 000194c3
r7 : 8e0bbe40 r6 : 8df4a788 r5 : 9dc88368 r4 : 8082c1e0
r3 : 0000283d r2 : 9dc8846c r1 : 20000013 r0 : 00000000
由於 0x283d 是一個合理的 page flags，所以在這個例子中，我們可以暫且排除記憶體溢位之類的因素，導致 page->flags 被別人寫壞的可能性，因為要溢位且寫入合理的變數值，那難度也太高了。
深入追蹤問題
至此我們已經對出錯時的系統狀況有了初步的輪廓，比較簡單的問題可能從以上的資訊就可以找到修復的辦法。
許多複雜問題還需要程式深入的理解才能找出 root cause，這時候只能慢慢檢查程式碼或是找出其他重製步驟等等。在這個案例中，我們後續還實際測試證明程式邏輯，排除了 lock 忘記拿等等可能，才逐步追蹤出真正的錯誤原因。