一、前言
我們在項目開發過程中，很多時候會出現由於某種原因經常會導致手機系統死機重啟的情況（重啟分Android重啟跟kernel重啟，而我們這里只討論kernel重啟也就是 kernel panic 的情況），死機重啟基本算是影響最嚴重的系統問題了，有穩定復現的，也有概率出現的，解題難度也千差萬別，出現問題后，通常我們會拿到類似這樣的kernel log信息（下面log僅以調用BUG()為例，其它異常所致的死機log信息會有一些不同之處）：
[ 2.052157] <2>-(2)[1:swapper/0]------------[ cut here ]------------
[ 2.052163] <2>-(2)[1:swapper/0]Kernel BUG at c04289dc [verbose debug info unavailable]
[ 2.052169] <2>-(2)[1:swapper/0]Internal error: Oops - BUG: 0 [#1] PREEMPT SMP ARM
[ 2.052178] <2>-(2)[1:swapper/0]disable aee kernel api[ 3.052192] <2>-(2)[1:swapper/0]Non-crashing CPUs did not react to IPI
[ 3.052204] <2>-(2)[1:swapper/0]CPU: 2 PID: 1 Comm: swapper/0 Tainted: G W 3.18.35+ #3
[ 3.052211] <2>-(2)[1:swapper/0]task: df060000 ti: df04a000 task.ti: df04a000
[ 3.052227] <2>-(2)[1:swapper/0]PC is at ltr553_i2c_probe+0x94/0x9c
[ 3.052233] <2>-(2)[1:swapper/0]LR is at 0x0
[ 3.052242] <2>-(2)[1:swapper/0]pc : [<c04289dc>] lr : [<00000000>] psr: a0000113
[ 3.052242] <2>sp : df04bd30 ip : 00000000 fp : df04bd4c
[ 3.052249] <2>-(2)[1:swapper/0]r10: 00000003 r9 : de348fc0 r8 : c0428948
[ 3.052255] <2>-(2)[1:swapper/0]r7 : dea1bc00 r6 : dea1bc04 r5 : dea1bc20 r4 : c0b53358
[ 3.052262] <2>-(2)[1:swapper/0]r3 : c115ef4c r2 : 00000000 r1 : 00000000 r0 : de366a00
[ 4.354655] <2>-(2)[1:swapper/0] oops_end, 1, 11
[ 4.354740] <2>-(2)[1:swapper/0]Kernel panic - not syncing: Fatal exception
這是linux 內核在死機之前輸出的相關重要信息，包括PC指針、調用棧等在內的非常重要的便於Debug的線索，比如我們可以借助GUN tools（add2Line）工具結合內核符號映射表vmlinux來定位當前PC指針所在的代碼具體行數(定位到出錯代碼行並不意味着就找到了問題的根本原因跟修復異常，這個需要根據異常的復雜程度而論)。深入理解這些關鍵打印log信息的含義和機制非常有助於我們對於此類死機問題的定位和分析（對於內存被踩、硬件不穩定導致的一類問題分析有局限性），這也是我們需要深入學習內核異常流程的初衷。
這里我們必須弄清楚幾個問題：
- 這些死機前留下的關鍵register信息是怎么來的，有什么用，具體含義是什么？
- 如何利用這些遺留的線索找到出問題代碼具體在哪支文件，在哪一行？
- 內核發生致命異常到死機的總流程是怎樣的，類似死機問題應該如何着手分析？
為此，本文就從最常見的主動觸發BUG()為例解析上面的疑問及分析整個kernel panic流程。
二、什么是BUG() ?
有過驅動調試經驗的人肯定都知道這個東西，這里的BUG跟我們一般認為的“軟件缺陷”可不是一回事，這里說的BUG()其實是linux kernel中用於攔截內核程序超出預期的行為，屬於軟件主動匯報異常的一種機制。這里有個疑問，就是什么時候會用到呢？一般來說有兩種用到的情況，一是軟件開發過程中，若發現代碼邏輯出現致命fault后就可以調用BUG()讓kernel死掉(類似於assert)，這樣方便於定位問題，從而修正代碼執行邏輯;另外一種情況就是，由於某種特殊原因（通常是為了debug而需抓ramdump），我們需要系統進入kernel panic的情況下使用.
- 原形是什么？
BUG()跟BUG_ON(1)其實本質是一回事，后者只是在前者的基礎上做了簡單的封裝而已，BUG()的實現 本質是埋入一條未定義指令:0xe7f001f2，觸發ARM發起Undefined Instruction異常（PS：ARM有分10種異常類型，詳細可以復習ARM異常模型章節）.
<kernel-3.18/arch/arm/include/asm/bug.h>
#define BUG_INSTR_VALUE 0xe7f001f2
#define BUG_INSTR(__value) __inst_arm(__value)
#define BUG() _BUG(__FILE__, __LINE__, BUG_INSTR_VALUE)
#define _BUG(file, line, value) __BUG(file, line, value)
#define __BUG(__file, __line, __value) \
do { \
asm volatile(BUG_INSTR(__value) "\n"); \
unreachable(); \
} while (0)
三、BUG() 流程分析
- BUG()到系統重啟的總流程圖
調用BUG()會向CPU下發一條未定義指令而觸發ARM發起未定義指令異常，隨后進入kernel異常處理流程歷經 Oops，die()，__die()等流程輸出用於調試分析的關鍵線索，最后進入panic()結束自己再獲得重生的過程,這個就是整個過程的基本流程，下面先來看die()具體做了什么呢？
四、die() 流程
源碼：
void die(const char *str, struct pt_regs *regs, int err)
{
enum bug_trap_type bug_type = BUG_TRAP_TYPE_NONE;
unsigned long flags = oops_begin();
int sig = SIGSEGV;
if (!user_mode(regs))
bug_type = report_bug(regs->ARM_pc, regs);
if (bug_type != BUG_TRAP_TYPE_NONE)
str = "Oops - BUG";
if (__die(str, err, regs))
sig = 0;
oops_end(flags, regs, sig);
}
總流程大致如下：
通常來說，代碼分析過程結合kernel log一起看會理解來得更加深刻，如果是BUG()/BUG_ON(1)導致的異常，那么走到report_bug 就可以看到下面標志性 log：
enum bug_trap_type report_bug(unsigned long bugaddr, struct pt_regs *regs)
{
...
if (!is_valid_bugaddr(bugaddr))
return BUG_TRAP_TYPE_NONE;
...
printk(KERN_DEFAULT "------------[ cut here ]------------\n");
if (file)
pr_crit("kernel BUG at %s:%u!\n", file, line);
else
pr_crit("Kernel BUG at %p [verbose debug info unavailable]\n",
(void *)bugaddr);
===>
[ 2.052157] <2>-(2)[1:swapper/0]------------[ cut here ]------------
[ 2.052163] <2>-(2)[1:swapper/0]Kernel BUG at c04289dc [verbose debug info unavailable]
[ 2.052169] <2>-(2)[1:swapper/0]Internal error: Oops - BUG: 0 [#1] PREEMPT SMP ARM
所以如果在log中看到了這個 “[ cut here ]” 的信息就推斷是軟件發生致命fault而主動call了BUG()所致的系統重啟了，就可以根據相關信息嘗試定位分析修復異常了.這里要注意的是還有另外一種__WARN()的情況也會打印出 “[ cut here ]” 的標志性log但是內核並不會掛掉，容易造成誤導：
#define __WARN() warn_slowpath_null(__FILE__, __LINE__)
#define __WARN_printf(arg...) warn_slowpath_fmt(__FILE__, __LINE__, arg)
void warn_slowpath_fmt(const char *file, int line, const char *fmt, ...)
{
...
warn_slowpath_common(file, line, __builtin_return_address(0),
TAINT_WARN, &args);
static void warn_slowpath_common(const char *file, int line, void *caller,
unsigned taint, struct slowpath_args *args)
{
...
pr_warn("------------[ cut here ]------------\n");
pr_warn("WARNING: CPU: %d PID: %d at %s:%d %pS()\n",
raw_smp_processor_id(), current->pid, file, line, caller);
===>
[ 1.106219] <2>-(2)[1:swapper/0]------------[ cut here ]------------
[ 1.107018] <2>-(2)[1:swapper/0]WARNING: CPU: 2 PID: 1 at /home/android/work/prj/n-6580/kernel-3.18/kernel/irq/manage.c:454 __enable_irq+0x50/0x8c()
所以其實從顯現上很好區分兩種情況，如果是BUG()/BUG_ON(1)那么內核一定會掛掉重啟，而__WARN()只會dump_stack()而不會死機, 從源碼跟log信息也可以容易區分兩種情況，如果是BUG()/BUG_ON(1)的話一定有類似下面的log輸出，只要搜索關鍵字：“Internal error: Oops” 即可.
[ 2.052163] <2>-(2)[1:swapper/0]Kernel BUG at c04289dc [verbose debug info unavailable]
[ 2.052169] <2>-(2)[1:swapper/0]Internal error: Oops - BUG: 0 [#1] PREEMPT SMP ARM
五、__die() 流程分析
從上面輸出的log信息還不足以定位具體出問題的代碼位置，包括定位異常所需要的最關鍵的 PC指針、調用棧等這些對於調試來說至關重要的線索信息都是在__die()中輸出.
流程圖：
打印出標志性log信息：
static int __die(const char *str, int err, struct pt_regs *regs)
{
...
printk(KERN_EMERG "Internal error: %s: %x [#%d]" S_PREEMPT S_SMP
S_ISA "\n", str, err, ++die_counter);
===>
[ 2.052169] <2>-(2)[1:swapper/0]Internal error: Oops - BUG: 0 [#1] PREEMPT SMP ARM
log 顯示異常str是Oops - BUG，error-code 為0，die計數器次數：1
Oops 的本意為 “哎呀” 的一個俚語，這里意形象的意指kernel出現了一件意外而不知道該如何處理的事件.
notify_die() 會通知對Oops感興趣的模塊執行相關回調，比如mtk的aee異常引擎模塊就是通過注冊到die_chain通知鏈上的.
int notrace notify_die(enum die_val val, const char *str,
struct pt_regs *regs, long err, int trap, int sig)
{
struct die_args args = {
.regs = regs,
.str = str,
.err = err,
.trapnr = trap,
.signr = sig,
};
return atomic_notifier_call_chain(&die_chain, val, &args);
}
mtk的aee異常引擎在kernel初始化的時候會去注冊到die_chain通知鏈，而且我們可以看到其實還注冊了panic通知鏈.
int __init aee_ipanic_init(void)
{
spin_lock_init(&ipanic_lock);
mrdump_init();
atomic_notifier_chain_register(&panic_notifier_list, &panic_blk);
register_die_notifier(&die_blk);
register_ipanic_ops(&ipanic_oops_ops);
ipanic_log_temp_init();
ipanic_msdc_init();
LOGI("ipanic: startup, partition assgined %s\n", AEE_IPANIC_PLABEL);
return 0;
}
而對我們調試追蹤有用的關鍵信息是在 __show_regs() 里面打印的：
void __show_regs(struct pt_regs *regs)
{
unsigned long flags;
char buf[64];
show_regs_print_info(KERN_DEFAULT);
print_symbol("PC is at %s\n", instruction_pointer(regs));
print_symbol("LR is at %s\n", regs->ARM_lr);
printk("pc : [<%08lx>] lr : [<%08lx>] psr: %08lx\n"
"sp : %08lx ip : %08lx fp : %08lx\n",
regs->ARM_pc, regs->ARM_lr, regs->ARM_cpsr,
regs->ARM_sp, regs->ARM_ip, regs->ARM_fp);
printk("r10: %08lx r9 : %08lx r8 : %08lx\n",
regs->ARM_r10, regs->ARM_r9,
regs->ARM_r8);
printk("r7 : %08lx r6 : %08lx r5 : %08lx r4 : %08lx\n",
regs->ARM_r7, regs->ARM_r6,
regs->ARM_r5, regs->ARM_r4);
printk("r3 : %08lx r2 : %08lx r1 : %08lx r0 : %08lx\n",
regs->ARM_r3, regs->ARM_r2,
regs->ARM_r1, regs->ARM_r0);
flags = regs->ARM_cpsr;
buf[0] = flags & PSR_N_BIT ? 'N' : 'n';
buf[1] = flags & PSR_Z_BIT ? 'Z' : 'z';
buf[2] = flags & PSR_C_BIT ? 'C' : 'c';
buf[3] = flags & PSR_V_BIT ? 'V' : 'v';
buf[4] = '\0';
printk("Flags: %s IRQs o%s FIQs o%s Mode %s ISA %s Segment %s\n",
buf, interrupts_enabled(regs) ? "n" : "ff",
fast_interrupts_enabled(regs) ? "n" : "ff",
processor_modes[processor_mode(regs)],
isa_modes[isa_mode(regs)],
get_fs() == get_ds() ? "kernel" : "user");
show_extra_register_data(regs, 128);
}
void dump_stack_print_info(const char *log_lvl)
{
printk("%sCPU: %d PID: %d Comm: %.20s %s %s %.*s\n",
log_lvl, raw_smp_processor_id(), current->pid, current->comm,
print_tainted(), init_utsname()->release,
(int)strcspn(init_utsname()->version, " "),
init_utsname()->version);
...
這里打印出了重要的pc停下的位置、相關寄存器信息，發生的是user還是kernel的異常、發生異常的cpu、進程pid等信息.
===>
接下來 dump_mem() 用於dump出當前線程的內存信息：
dump_mem(KERN_EMERG, "Stack: ", regs->ARM_sp,
THREAD_SIZE + (unsigned long)task_stack_page(tsk));
使用 dump_backtrace(regs, tsk) 打印出調試最直觀的調用棧信息：
===>
[ 3.056363] <2>-(2)[1:swapper/0]Backtrace: -(2)[1:swapper/0]
[ 3.056386] <2>-(2)[1:swapper/0][<c010badc>] (dump_backtrace) from [<c010bc7c>] (show_stack+0x18/0x1c)
[ 3.056393] <2>-(2)[1:swapper/0] r6:c103d790-(2)[1:swapper/0] r5:ffffffff-(2)[1:swapper/0] r4:00000000-(2)[1:swapper/0] r3:00000000-(2)[1:swapper/0]
[ 3.056426] <2>-(2)[1:swapper/0][<c010bc64>] (show_stack) from [<c0a91e64>] (dump_stack+0x90/0xa4)
[ 3.056439] <2>-(2)[1:swapper/0][<c0a91dd4>] (dump_stack) from [<c072d264>] (ipan6503] <2>-(2)[1:swapper/0][<c013e6bc>] (notifier_call_chain) from [<c013eb84>] (atomic_notifier_call_chain+0x3c/0x50)
[ 3.056509] <2>-(2)[1:swapper/0] r10:c10efec4-(2)[1:swapper/0] r9:df060000-(2)[1:swapper/0] r8:df04a020-(2)[1:swapper/0] r7:c0caaaf0-(2)[1:swapper/0] r6:c10f0c88-(2)[1:swapper/0] r5:00000001
[ 3.056539] <2>-(2)[1:swapper/0] r4:df04bb74-(2)[1:swapper/0]
[ 3.056554] <2>-(2)[1:swapper/0][<c013eb48>] (atomic_notifier_call_chain) from [<c013f244>] (notify_die+0x44/0x4c)
[ 3.056560] <2>-(2)[1:swapper/0] r6:df04bce8-(2)[1:swapper/0] r5:00000000-(2)[1:swapper/0] r4:00000001-(2)[1:swapper/0]
[ 3.056585] <2>-(2)[1:swapper/0][<c013f200>] (notify_die) from [<c010bd94>] (die+0x114/0x41c)
[ 3.056590] <2>-(2)[1:swapper/0] r4:c102826c-(2)[1:swapper/0]
[ 3.056607] <2>-(2)[1:swapper/0][<c010bc80>] (die) from [<c010c0c0>] (arm_notify_die+0x24/0x5c)
[ 3.056612] <2>-(2)[1:swapper/0] r10:df04a000-(2)[1:swapper/0] r9:00000000-(2)[1:swapper/0] r8:df04bce8-(2)[1:swapper/0] r7:e7f001f2-(2)[1:swapper/0] r6:df04a000-(2)[1:swapper/0] r5:c04289dc
[ 3.056642] <2>-(2)[1:swapper/0] r4:00000004-(2)[1:swapper/0]
[ 3.056658] <2>-(2)[1:swapper/0][<c010c09c>] (arm_notify_die) from [<c01001cc>] (do_undefinstr+0x1a4/0x1ec)
[ 3.056670] <2>-(2)[1:swapper/0][<c0100028>] (do_undefinstr) from [<c010c98c>] (__und_svc_finish+0x0/0x34)
[ 3.056676] <2>-(2)[1:swapper/0]Exception stack(0xdf04bce8 to 0xdf04bd30)
[ 3.056687] <2>-(2)[1:swapper/0]bce0: de366a00 00000000 00000000 c115ef4c c0b53358 dea1bc20
[ 3.056698] <2>-(2)[1:swapper/0]bd00: dea1bc04 dea1bc00 c0428948 de348fc0 00000003 df04bd4c 00000000 df04bd30
[ 3.056706] <2>-(2)[1:swapper/0]bd20: 00000000 c04289dc a0000113 ffffffff
[ 3.056711] <2>-(2)[1:swapper/0] r9:c010c98c-(2)[1:swapper/0] r8:e7100000-(2)[1:swapper/0] r7:00000000-(2)[1:swapper/0] r6:c010cd98-(2)[1:swapper/0] r5:00000000-(2)[1:swapper/0] r4:c04289e0
[ 3.056750] <2>-(2)[1:swapper/0][<c0428948>] (ltr553_i2c_probe) from [<c07d88d8>] (i2c_device_probe+0xd0/0x12c)
[ 3.056756] <2>-(2)[1:swapper/0] r5:dea1bc20-(2)[1:swapper/0] r4:c0b53358-(2)[1:swapper/0]
[ 3.056778] <2>-(2)[1:swapper/0][<c07d8808>] (i2c_device_probe) from [<c03c298c>] (driver_probe_device+0x160/0x43c)
通過上面的調用棧信息結合GUN Tools（add2Line）基本就可以定位發生異常的具體代碼位置了.
最后會通過dump_instr(KERN_EMERG, regs) 打印出pc指針和前4條指令：
static void dump_instr(const char *lvl, struct pt_regs *regs)
{
...
for (i = -4; i < 1 + !!thumb; i++) {
unsigned int val, bad;
if (thumb)
bad = __get_user(val, &((u16 *)addr)[i]);
else
bad = __get_user(val, &((u32 *)addr)[i]);
if (!bad)
p += sprintf(p, i == 0 ? "(%0*x) " : "%0*x ", width, val);
else {
p += sprintf(p, "bad PC value");
break;
}
}
printk("%sCode: %s\n", lvl, str);
..
===>
[ 3.226706] <2>-(2)[1:swapper/0][<c0a8ae74>] (/0]Code: e89da830 e30e3f4c e34c3115 e5830000 (e7f001f2)
看到這個 e7f001f2 了吧，是不是很眼熟？這個就是BUG()中埋入的未定義指令！
到這一步，大部分關鍵信息都已經輸出了，可以通過add2Line工具定位出具體死在的代碼行號，大致看看發生了什么，如果是BUG()導致的異常，那么就可以考慮分析和修復異常了，因為BUG()屬於主動匯報異常，一般來說debug難度會相對其它的被動上報方式容易得多.
例如：
從上面log知PC死在的地址 <c04289dc>，通過add2Line工具結合內核符號映射表 vmlinux 就可以定位出具體代碼所在文件行號：
arm-linux-androideabi-addr2line -e out/target/product/$project/obj/KERNEL_OBJ/vmlinux -f -C c04289dc
ltr553_i2c_probe
/aosp/kernel-3.18/drivers/misc/mediatek/alsps/ltr553/ltr553.c:3278
定位到了具體代碼行號就可以進一步分析代碼log找出問題原因修復異常了(一般來說BUG()導致的異常比較好解，其它的情況難度就是天差地別了..)。 那么接下來kernel要干什么呢？重要信息都輸出完了接下來就直接走 kernel panic 流程了.
六、panic 流程
panic 本意是“恐慌”的意思，這里意旨kernel發生了致命錯誤導致無法繼續運行下去的情況.
流程圖：
相關重要的debug信息已經在之前的__die()流程輸出完成了，panic()其實要干的主要事情就是讓系統先死掉再重生，kernel panic有標志性的log打印，可以作為是否發生panic的搜索關鍵字.
[ 4.354740] <2>-(2)[1:swapper/0]Kernel panic - not syncing: Fatal exception
雖然主要的工作就是讓系統復位，但在去的路上還是會做一些事情，盡可能的不遺余力給事后分析提供線索，比如atomic_notifier_call_chain()會去遍歷panic_notifier_list鏈表，依次通知對panic感興趣的模塊(比如mtk的aee機制在這里會把異常的一小塊內存給dump處理放到expdb分區，不過后面新的機制是改在reboot后再來做了)做一些事情，如果打開了ramdump支持就直接陷入download模式，抓取ramdump供離線分析用，單從這塊來講MTK/QCOM平台流程差不多.
[ 9.772431] Rebooting in 1 seconds..
另外還要說的一點是，以上所有的分析都是基於log信息的分析，簡單易行，這是系統異常調試中最基本也是最重要的分析手段，對於BUG()導致的問題通常可以比較順利的分析解決，但是也有其局限性，比如內存被踩、硬件不穩定導致的概率死機等類型問題分析起來就往往很吃力，而這就需要借助ramdump分析手段才能進一步比較順利的分析解題.
最后附上總時序圖
