一个 oops 分析实例

分类于 ， ， 阅读次数： Waline： 本文字数： 1.3k 阅读时长 ≈ 5 分钟

最近出现了比较多的内核崩溃的问题，之前也曾转发过网上一篇关于内核崩溃问题的跟踪方法，我在这里借 xxx 提供的这个死机现场，再给大家描述一下这类问题的分析方法和 debug 过程，也希望能让大家真正掌握这类问题的调试方法。让大家明白，内核崩溃问题的调试方法其实也就是这样一些固定的套路。问题的分析过程如下：

确认死机现场

1
2
3
4
5
6
7
8
9
10
11
12
13
[56400.437450] Unable to handle kernel paging request at virtual address f7fe44a1
[56400.440040] pgd = d112c000
[56400.440040] [f7fe44a1] *pgd=00000000
[56400.440040] Internal error: Oops: 5 [#1] PREEMPT SMP ARM
[56400.440040] Modules linked in: 8188eu gt82x mma8452 rtl8150 mcs7830 qf9700 asix sunxi_keyboard sw_device vfe_v4l2 gc2035 gc0307 vfe_subdev vfe_os cci videobuf_dma_contig videobuf_core mali(O) lcd disp nand(O)
[56400.440040] CPU: 0    Tainted: G           O  (3.4.39 #428)
[56400.440040] PC is at cpuacct_charge+0x68/0xa8
[56400.440040] LR is at cpuacct_charge+0x30/0xa8
[56400.440040] pc : [<c004b93c>]    lr : [<c004b904>]    psr: a0000093
[56400.440040] sp : ca25bda0  ip : 0061b000  fp : ca25bdb4
[56400.440040] r10: 00000000  r9 : 00000000  r8 : 000b64fe
[56400.440040] r7 : 00000000  r6 : 000b64fe  r5 : 00000000  r4 : c06e4480
[56400.440040] r3 : f7fe4479  r2 : db506884  r1 : c07312c8  r0 : c06c8a00

根据死机现场的打印分析，死机的原因是因为执行 0xc004b93c 处的代码访问数据时，取到一个非法地址：0xf7fe44a1，访问该地址的时候，会导致系统异常；

反汇编内核代码，分析原因

通过命令"arm-none-linux-gnueabi-objdump -d vmlinux > vmlinux.lst "，可以反汇编出内核的代码。 固件不是在我的机器上编出来的，所以反汇编得到的代码和在机器上实际运行的不是完全一致的，但是，没关系，这不影响我们分析问题。 由于本地的反汇编代码和设备上的不一致，所以不能用 PC 值 0xc004b93c 去定位代码，而是用"PC is at cpuacct_charge+0x68/0xa8"这个信息来确认死机时的代码位置。 "cpuacct_charge+0x68/0xa8"的含义是：函数"cpuacct_charge"的代码为 0xa8 个字节，出错时，PC 位于"cpuacct_charge"偏移 0x68 字节处。 OK，根据此信息，我们来查看反汇编得到的代码。cpuacct_charge 位于 0xc004bab4 处，偏移 0x68 字节，即 0xc004bab4 + 0x68 = 0xc004bb1c 处出现异常。

1
2
3
4
5
6
7
8
c004bab4 <cpuacct_charge>:
c004bab4: e92d48f0  push {r4, r5, r6, r7, fp, lr}
。
c004bb0c: e5913000  ldr r3, [r1]
c004bb10: e5933018  ldr r3, [r3, #24]
c004bb14: e3530000  cmp r3, #0
c004bb18: 0a000002  beq c004bb28 <cpuacct_charge+0x74>
c004bb1c: e5931028  ldr r1, [r3, #40] ; 0x28

再回头看异常现场：r3 : f7fe4479，发现 r3 + 0x28 = f7fe44a1，代码和异常现场相吻合。 接下来就是尝试分析出错的代码执行过程，这个有一定的难度，需要结合 C 源代码，和对汇编代码的理解来进行分析。

定位出错位置的源代码

通过反汇编得知，出错时的 PC 位置在我编出来的 vmlinux 的 0xc004bb1c 地址处，采用命令：

1
arm-none-linux-gnueabi-addr2line -e vmlinux -f c004bb1c

来行源码定位： 

1
2
3
kevin@Exdroid6:~/aw1650-47/lichee/linux-3.4$ arm-none-linux-gnueabi-addr2line -e vmlinux -f c004bb1c
cgroup_subsys_state
/home/kevin/aw1650-47/lichee/linux-3.4/include/linux/cgroup.h:508

发现出错的源代码是在操作一个链表上的指针，这些数据不是全局变量，很难分析出其出错的本质原因，所以源码分析一步在这时可以放弃；

分析出错的汇编代码

结合"cpuacct_charge"函数的 C 代码实现，再回头看出错时的汇编代码，发现出错的代码其实是位于一个循环体中：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
c004baf0: ea00000a  b c004bb20 <cpuacct_charge+0x6c>
c004baf4: e794c105  ldr ip, [r4, r5, lsl #2]
c004baf8: e5910010  ldr r0, [r1, #16]
c004bafc: e18020dc  ldrd r2, [r0, ip]
c004bb00: e0922006  adds r2, r2, r6
c004bb04: e0a33007  adc r3, r3, r7
c004bb08: e18020fc  strd r2, [r0, ip]
c004bb0c: e5913000  ldr r3, [r1]
c004bb10: e5933018  ldr r3, [r3, #24]
c004bb14: e3530000  cmp r3, #0
c004bb18: 0a000002  beq c004bb28 <cpuacct_charge+0x74>
c004bb1c: e5931028  ldr r1, [r3, #40] ; 0x28
c004bb20: e3510000  cmp r1, #0
c004bb24: 1afffff2  bne c004baf4 <cpuacct_charge+0x40>

出错的代码是："c004bb1c: e5931028 ldr r1, [r3, #40] ; 0x28"，即 r3 的值是错的，我们来尝试分析 r3 这个数据的来源。 从："c004bb1c: e5931028 ldr r1, [r3, #40] ; 0x28"这句代码向前找，发现 r3 数据的直接来源是 r1，

1
2
c004bb0c: e5913000  ldr r3, [r1]
c004bb10: e5933018  ldr r3, [r3, #24]

再回头看异常现场的 r1 值为"r1 : c07312c8"，以及 r1 所指向的数据：

1
2
3
4
5
6
[56400.440040] R1: 0xc0731248:
[56400.440040] 1248  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[56400.440040] 1268  00000000 00000000 00000000 00000000 d9833700 00989680 00000000 00000000
[56400.440040] 1288  00000000 00000000 00000000 d9818e40 00000000 00000000 00000000 d9847380
[56400.440040] 12a8  d9800dc0 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[56400.440040] 12c8  d8dd2018 00000001 00000001 00000000 c06c8a00 c06c5768 00000000 00000000

可以看到"c004bb0c: e5913000 ldr r3, [r1]"取到的 r3 值为 0xd8dd2018，再看接下来的一条汇编： "c004bb10: e5933018 ldr r3, [r3, #24]"，即错误的数据是从 0xd8dd2018 + 24 = 0xd8dd2030 处取到的。

此时如果想再往下分析，就只能借助 Jtag 了。

Jtag 分析

当前死机的这一台，DS-5 无法打开，所以没有办法直接通过 DS-5 来查看 0xd8dd2030 处的数据是否真的错了。 此时，可以先推断 CPU 模块本身已经出错了，导致 jtag 无法通过 CPU 访问数据。 我们再来尝试一下用 JTAG 的 CSAT 方式，访问一下，发现 CSAT 可以连接上，而且可以读取物理内存的内容。 由于 CSAT 是绕过 CPU 来访问内存的数据，所以无法直接访问"0xd8dd2030"处的内容。但是，我们知道，内核 空间有近 700Mbyte 的是直接映射的，即 0x40000000 -> 0xc0000000，那么 0xd8dd2030 所对应的物理地址应该 为 0x58dd2030，通过 CSAT 查看一下 0x58dd2030 处的数据：

1
2
3
4
5
%>dmr 0 0x58dc6010 16
0x58DC6010 : 0xC06ED7EC 0xC06ED7EC 0x00000002 0x00000001
0x58DC6020 : 0xD8DC6020 0xD8DC6020 0xD9A32088 0xD9A32088
0x58DC6030 : 0x00000000 0xD9432F70 0x00000000 0x00000000
0x58DC6040 : 0xC07312C8 0x00000000 0x00000000 0x00000000

我们发现，0x58dd2030 处的数据是 0x00000000，即：0xd8dd2030 处的数据应该是 0x00000000。

再回头看把汇编出来的代码：

1
2
3
4
c004bb10: e5933018  ldr r3, [r3, #24]
c004bb14: e3530000  cmp r3, #0
c004bb18: 0a000002  beq c004bb28 <cpuacct_charge+0x74>
c004bb1c: e5931028  ldr r1, [r3, #40] ; 0x28

如果 r3 是 0，应该是退出循环，而不是再去取值，因此，可以先推断，出错的原因可能是：

  • cpu 本身出错，导致指令执行不正常，从而导致 r3 中的数据出错
  • DRAM 访问出错，导致取回到 r3 的数据是错的

再结合我们之前的推断，CPU 模块本身可能已经出错了，因此，我们更环疑该问题是 CPU 工作不稳定导致的。 我们再来确认一下此时 CPU 的工作频率和电压：

1
2
%>dmr 0 0x1c20000 16
0x01C20000 : 0x90001410 0x00000000 0x90034E14 0x00000000

根据寄存器的值可以推出 CPU 当前工作频率为 1008Mhz；测得当前的 CPU 工作电压为：1.17v；

分析下来，并没有真正查明问题的原因，只是初步推测了一个问题可能的方向，后续的实验可以重点观注该方向上的一些实验。

其他常用命令

根据函数名拿到函数的地址：

1
2
arm-linux-gnueabi-nm vmlinux | grep __cpuinfo_store_cpu
ffffff80100919c0 t __cpuinfo_store_cpu

根据出错的位置计算起始和结束地址

1
2
3
4
$ echo "obase=16;ibase=10;$((0x80100919c0+0x80))" | bc -l
8010091A40
$ echo "obase=16;ibase=10;$((0x80100919c0+0x1d0))" | bc -l
8010091B90

根据起始地址和结束地址 dump 出出错的汇编和源码，结合 oops 现场进行复盘分析

1
arm-linux-gnueabi-objdump -dS vmlinux --start-address=0xffffff80100919c0 --stop-address=0xffffff8010091b90