dmesg 初步分析

[  423.400073] Unable to handle kernel NULL pointer dereference at virtual address 00000008
[  423.400075] [silead finger_interrupt_handler 505]:S IRQ 19 , GPIO 12 state is 0
[  423.400083] [silead finger_interrupt_handler 506]:state is 0
[  423.400096] pgd = ffffffc0017eb000
[  423.400103] [00000008] *pgd=000000008ea0a003, *pud=000000008ea0a003, *pmd=000000008ea0b003, *pte=006000000b000707
[  423.400124] Internal error: Oops: 96000046 [#1] PREEMPT SMP
[  423.400132] Modules linked in: wlan(O)
[  423.400148] CPU: 4 PID: 0 Comm: swapper/4 Tainted: G        W  O   3.18.31-perf #1
[  423.400155] Hardware name: Qualcomm Technologies, Inc. MSM8940-PMI8950 MTP (DT)
[  423.400164] task: ffffffc04eae4980 ti: ffffffc0b28bc000 task.ti: ffffffc0b28bc000
[  423.400182] PC is at run_timer_softirq+0x4ac/0x5ec
[  423.400192] LR is at run_timer_softirq+0x324/0x5ec
[  423.400199] pc : [<ffffffc0000feb98>] lr : [<ffffffc0000fea10>] pstate: 600001c5
[  423.400204] sp : ffffffc0b28bfb60
...
[  423.401490] Process swapper/4 (pid: 0, stack limit = 0xffffffc0b28bc058)
[  423.401496] Call trace:
[  423.401510] [<ffffffc0000feb98>] run_timer_softirq+0x4ac/0x5ec
[  423.401523] [<ffffffc0000a6864>] __do_softirq+0x178/0x350
[  423.401532] [<ffffffc0000a6c8c>] irq_exit+0x74/0xb0
[  423.401543] [<ffffffc0000edf18>] __handle_domain_irq+0xb4/0xec
[  423.401553] [<ffffffc00008254c>] gic_handle_irq+0x54/0x84
[  423.401560] Exception stack(0xffffffc0b28bfd40 to 0xffffffc0b28bfe60)
...
[  423.401671] [<ffffffc000085da8>] el1_irq+0x68/0xd4
[  423.401685] [<ffffffc000851480>] cpuidle_enter_state+0xd0/0x224
[  423.401695] [<ffffffc0008516ac>] cpuidle_enter+0x18/0x20
[  423.401706] [<ffffffc0000e1cc0>] cpu_startup_entry+0x288/0x384
[  423.401717] [<ffffffc000091d5c>] secondary_start_kernel+0x108/0x114
[  423.401728] Code: b90052a0 34000840 f9400321 f9400720 (f9000420) 
[  423.401736] ---[ end trace d0daa1892c14378b ]---
[  423.401753] Kernel panic - not syncing: Fatal exception in interrupt
[  423.401774] CPU7: stopping

连上trace32，load vmlinux后通过list source看下汇编源码混合显示，如下：

• FFFFFFC0000FE968: 当前汇编指令的虚拟地址
• F9000760: 汇编机器码，ARM/ARM64的指令机器码都是32位固定长度
• str x0,[x27, #0x8]: 汇编指令，；后的是注释

根据AAPCS（ARM二进制过程调用标准）参数传递规则，ARM64的 v0 - v7 参数直接由 x0 - x7 传递，其他参数由压栈传递，子程序返回结果保存到x0。

那么这里可推导如下：

x0 == prev， x1 == next

指令：str x0 ,[x1,#0x8]
x1+0x8 其实就是next+8个字节的偏移，看下：

struct list_head {
    struct list_head *next, *prev;
};

ARM体系结构中，ARM64一个指针占8个字节内存，也就是: [x1+0x8] == prev

所以这个str指令就是对应上面的next->prev = prev

我们根据异常栈的寄存器值来看下：

[  423.400182] PC is at run_timer_softirq+0x4ac/0x5ec
[  423.400192] LR is at run_timer_softirq+0x324/0x5ec
[  423.400199] pc : [<ffffffc0000feb98>] lr : [<ffffffc0000fea10>] pstate: 600001c5
[  423.400204] sp : ffffffc0b28bfb60
[  423.400210] x29: ffffffc0b28bfb60 x28: ffffffc0b2619038 
[  423.400219] x27: ffffffc000c9a000 x26: 0000000000000000 
[  423.400228] x25: ffffffc001741120 x24: ffffffc0006e277c 
[  423.400237] x23: ffffffc0b2619000 x22: ffffffc0b28bfbf8 
[  423.400246] x21: ffffffc0b28bc000 x20: ffffffc0013d2000 
[  423.400254] x19: ffffffc0b2618000 x18: 0000007f9588e080 
[  423.400263] x17: 0000007f9a36d4b4 x16: ffffffc0001e4f6c 
[  423.400272] x15: 003b9aca00000000 x14: 0000000000000001 
[  423.400280] x13: 0000000000000000 x12: 0000000000000001 
[  423.400289] x11: 000000000000000f x10: ffffffc000c9c3f4 
[  423.400297] x9 : 0000000000000000 x8 : 0000000000000005 
[  423.400305] x7 : 0000000000000000 x6 : 000000000001451c 
[  423.400314] x5 : ffffffc0b2ae8000 x4 : 00135f1aa15bb200 
[  423.400323] x3 : 0000000000000018 x2 : 0000000000000000 
[  423.400331] x1 : 0000000000000000 x0 : ffffffc0b28bfbf8

上面可以看到，x1+0x8 ==0x0000000000000000+0x8==0x0000000000000008，这个和出错时候报的地址一致“Unable to handle kernel NULL pointer dereference at virtual address 00000008”

因为ARM64内核的虚拟地址空间范围是0xFFFF_0000_0000_0000 =>0xFFFF_FFFF_FFFF_FFFF，很明显这个值0x0000000000000008不在范围内，它属于用户空间的虚拟地址空间，肯定会被MMU拦截掉上报data abort异常,所以此题的真正原因是程序跑飞访问非法地址所致。

目前看来从kernel log上的信息无法直接分析出导致问题的具体源代码，从dmesg的这些信息我们已经知道出问题的是这个prev指针，但是比较难直接抓到导致异常的真凶源码位置。

Trace32 分析

利用dmesg我们分析了产生问题时候的来龙去脉，但是想要彻底解决还需要trace32进一步分析。

输入v.f，调出当前的调用栈关系：

可以看到，异常时候的各种参数都显示出来了，这样就非常有利于我们debug了，这也是单纯从dmesg无法得到的重要信息！注意inline类型的函数会被编译器默认优化掉，所以inline类型的函数的参数不可见，需要通过读汇编代码，分析寄存器传参推导。

输入d.list 查看PC停止的位置，如下高亮:

分析Call Stack：

为方便查看，把调用栈信息复制出来，如下：

 1. ...
-007|die(
    |  ?,
    |    regs = 0xFFFFFFC0B28BFA40 -> (
    |      user_regs = (regs = (0xFFFFFFC0B28BFBF8, 0x0, 0x0, 0x18, 0x00135F1AA15BB200, 0xFFFFFFC0B2AE800
    |      regs = (0xFFFFFFC0B28BFBF8, 0x0, 0x0, 0x18, 0x00135F1AA15BB200, 0xFFFFFFC0B2AE8000, 0x0001451C
    |      sp = 0xFFFFFFC0B28BFB60,
    |      pc = 0xFFFFFFC0000FEB98,
    |      pstate = 0x600001C5,
    |      orig_x0 = 0xFFFFFFC0B2618000,
    |      syscallno = 0xFFFFFFC0000FE7D0),
    |    err = 0x96000046)
    |  flags = 0x01C0
    |  ret = 0x1
    |  tsk = 0xFFFFFFC04EAE4980
    |  die_counter = 0x1
-008|__do_kernel_fault.part.5(
    |    mm = 0x0,
    |    addr = 0x8,
    |    esr = 0x96000046,
    |    regs = 0xFFFFFFC0B28BFA40)
-009|do_page_fault(
    |    addr = 0x8,
    |    esr = 0x96000046,
    |    regs = 0xFFFFFFC0B28BFA40)
    |  tsk = 0xFFFFFFC04EAE4980
    |  mm = 0x0
    |  vm_flags = 0xFFFFFFC000C9A000
    |  vma = 0xFFFFFFC0B28BFA40
-010|do_translation_fault(
    |    addr = 0x0A44,
    |    esr = 0x0124F800,
    |  ?)
-011|do_mem_abort(
    |    addr = 0x8,
    |    esr = 0x96000046,
    |    regs = 0xFFFFFFC0B28BFA40)
    |  inf = 0xFFFFFFC0013DC790 -> (
    |    fn = 0xFFFFFFC000099A74,
    |    sig = 0x0B,
    |    code = 0x00030001,
    |    name = 0xFFFFFFC0010DF250 -> 0x6C)
    |  info = (
    |    si_signo = 0x0032D110,
    |    si_errno = 0xFFFFFFC0,
    |    si_code = 0x01C0,
    |    _sifields = (_pad = (0x7, 0x0, 0xB28BF9E0, 0xFFFFFFC0, 0x000A6D78, 0xFFFFFFC0, 0xB28BF9F0, 0xFFF
-012|el1_da(asm)
 -->|exception
-013|__list_del(inline)
-013|detach_timer(inline)
-013|detach_expired_timer(inline)
-013|__run_timers(inline)
-013|run_timer_softirq(
    |  ?)
    |  base = 0xFFFFFFC0B2618000 -> (
    |    lock = (rlock = (raw_lock = (owner = 0x6FCD, next = 0x6FCE))),
    |    running_timer = 0xFFFFFFC001741120 -> (
    |      entry = (next = 0xFFFFFFC0B27BC9B8, prev = 0xFFFFFFC0B27BC9B8),
    |      expires = 0x0000000100003098,
    |      base = 0xFFFFFFC0B27BC000,
    |      function = 0xFFFFFFC0006E277C -> ,
    |      data = 0x0,
    |      slack = 0xFFFFFFFF,
    |      start_pid = 0xFFFFFFFF,
    |      start_site = 0x0,
    |      start_comm = (0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0))
    |    timer_jiffies = 0x0000000100003035,
    |    next_timer = 0x0000000100003034,
    |    active_timers = 0x7,
    |    all_timers = 0x7,
    |    cpu_=_0x4,
    |    tv1 = (vec = ((next = 0xFFFFFFC0B2618038, prev = 0xFFFFFFC0B2618038), (next = 0xFFFFFFC0B2618048
    |    tv2 = (vec = ((next = 0xFFFFFFC0B2619038, prev = 0xFFFFFFC0B2619038), (next = 0xFFFFFFC0B2619048
    |    tv3 = (vec = ((next = 0xFFFFFFC0B2619438, prev = 0xFFFFFFC0B2619438), (next = 0xFFFFFFC0B2619448
    |    tv4 = (vec = ((next = 0xFFFFFFC0B2619838, prev = 0xFFFFFFC0B2619838), (next = 0xFFFFFFC0B2619848
    |    tv5 = (vec = ((next = 0xFFFFFFC0B2619C38, prev = 0xFFFFFFC0B2619C38), (next = 0xFFFFFFC0B2619C48
    |  fn = 0xFFFFFFC0006E277C ->
    |  data = 0x0
    |  it_func_ptr = 0x0
...

看到这里，我们可以猜想是不是run_timer_softirq的参数出现了问题导致后面发生的一系列异常？可以从这个方向开始思考，我们先来看下这个函数的实现：

static void run_timer_softirq(struct softirq_action *h)
{
    struct tvec_base *base = __this_cpu_read(tvec_bases);
    hrtimer_run_pending();
    __run_deferrable_timers();
    if (time_after_eq(jiffies, base->timer_jiffies))
        __run_timers(base);
}

我们看到这个函数最重要的参数变量就是这个base，传入的h没有使用，继续来看下base的结构tvec_base ：

struct tvec_base {
    spinlock_t lock;
    struct timer_list *running_timer;
    unsigned long timer_jiffies;
    unsigned long next_timer;
    unsigned long active_timers;
    unsigned long all_timers;
    int cpu;  // 跟踪所在的CPU是哪个核，这里是CPU 4
    struct tvec_root tv1;
    struct tvec tv2;
    struct tvec tv3;
    struct tvec tv4;
    struct tvec tv5;
} ____cacheline_aligned;

这里就看到 tvec_base 的结构里面有个 struct timer_list * 的结构，我们继续看它的结构是怎么样的：

struct timer_list {
    /*
     * All fields that change during normal runtime grouped to the
     * same cacheline
     */
    struct list_head entry;
    unsigned long expires;
    struct tvec_base *base;
    void (*function)(unsigned long);
    unsigned long data;
    int slack;
...

首先我们查看 running_timer 的数据内容，

工具栏调出：view -> Watch，输入：(struct timer_list *)0xffffffc001741120

这个就是发生异常的那个timer的数据结构实例，我们最希望的就是希望可以通过这里的数据信息找到它在源码的位置，然后进一步分析它，使用Trace32的 dump 分析功能就可以做到这点。

菜单栏调出：view -> dump

输入地址 0xffffffc001741120 然后点OK

右击高亮，选择view info：

同理，还可以看function的位置（0xFFFFFFC0006E277C）：

上面所示，出异常的timer实例就是：fp_drv/m_timer, callback = timer_out_handle，源码位置也给出来了，那么就可以着手修复问题了。