内核调试之Panic-Oops日志分析

这部分我们接着之前的思考，看看内核异常日志的分析。

1 Panic 调试

2 Oops调试

内核出现Panic或Oops错误，如何分析定位问题原因？

首先，保留现场，如下所示为一次非法虚拟地址访问错误。

  EXT4-fs (sdc3): recovery completeEXT4-fs (sdc3): mounted filesystem with ordered data mode. Opts: (null)Unable to handle kernel NULL pointer dereference at virtual address 00000004pgd = cd3cc000[00000004] *pgd=4d3bf831, *pte=00000000, *ppte=00000000Internal error: Oops: 17 [#1] SMP ARMModules linked in: hi_rtc(O) hi_ir(O) hi3536_adec(PO) hi3536_aenc(PO) hi3536_ao(PO) hi3536_ai(PO) hi3536_aio(PO) acodec(PO) gpioi2c(O) hi3536_ive(PO) hi3536_vda(PO) hi3536_jpege(PO) hi3536_h264e(PO) hi3536_chnl(PO) hi3536_venc(PO) hi3536_rc(PO) hi3536_hdmi(O) hifb(PO) hi3536_vou(PO) hi3536_vpss(PO) hi3536_viu(PO) hi3536_vgs(PO) hi3536_region(PO) hi3536_tde(PO) hi3536_jpegd(O) hi3536_vfmw(PO) hi3536_vdec(PO) hi3536_sys(PO) hi3536_base(PO) hiuser(O) hi_media(O) mmz(O) stmmacCPU: 2 PID: 1786 Comm: vecsupgradehisi Tainted: P           O 3.10.0_hi3536 #39task: cfb2bc00 ti: ce164000 task.ti: ce164000PC is at rb_insert_color+0x1c/0x17cLR is at SyS_epoll_ctl+0x584/0x860pc : [<c027e574>]    lr : [<c00f9e2c>]    psr: 60000013sp : ce165f1c  ip : 00000000  fp : 00000000r10: 00000001  r9 : cd3b2304  r8 : cd3b2300r7 : c075a1a8  r6 : cd080980  r5 : cf35a6c0  r4 : cd306000r3 : 00000000  r2 : cd080000  r1 : cd3b233c  r0 : cd080980Flags: nZCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment userControl: 10c5387d  Table: 4d3cc06a  DAC: 00000015PC: 0xc027e4f4:e4f4  e8bd41f0 e12fff13 e3833001 e5843000 e8bd81f0 e5963008 e1a00005 e1a01006e514  e3530000 e5853004 13852001 e5865008 e5846008 15832000 e12fff37 e1a03005e534  e1a05006 e5952004 e3851001 e3520000 e5842008 e5854004 e5831000 1affffd6e554  eaffffd9 e5902000 e3520000 0a000054 e5923000 e3130001 112fff1e e92d4030e574  e593c004 e383e001 e1a05003 e152000c 0a000019 e35c0000 0a000002 e59c4000e594  e3140001 0a00001b e592c004 e15c0000 11a0e002 0a00002c e35c0000 e583c008e5b4  e5823004 0a000001 e3830001 e58c0000 e5930000 e3d0c003 e5820000 e583e000e5d4  05812000 08bd8030 e59c1008 e1530001 058c2008 158c2004 e8bd8030 e593c008LR: 0xc00f9dac:9dac  e288703c e3a02000 e58d7020 e1a03007 ea000005 e596101c e59b201c e06220019dcc  e3520000 da000009 e1a0200b e593b000 e35b0000 0a000007 e5961018 e28b30049dec  e59b2018 e1510002 8afffff6 2afffff0 e28b3008 eafffff3 e30a71a8 e34c70759e0c  e5862000 e1a00006 e586b004 e586b008 e59d1020 e5836000 e58d7018 eb0611ca9e2c  e597c000 e157000c e24cc08c 0a000069 e1a0e00d e3ceed7f e3cee03f e3057dd89e4c  e58d502c e34c7079 e58d4030 e1a0500e e58d6014 e1a0400c e59d6018 ea0000039e6c  e594c08c e156000c e24c408c 0a000056 e595300c e3050dd8 e3091060 e34c00799e8c  e34c100f e1a02004 e58d3000 e1a03004 e587b024 e587b028 e587b02c e587b030SP: 0xce165e9c:5e9c  00000000 00000040 000000d0 c00f9cb4 c09bfef0 00000000 00100100 c027e5745ebc  60000013 ffffffff ce165f04 cd3b2300 c0012b58 cd080980 cd3b233c cd0800005edc  00000000 cd306000 cf35a6c0 cd080980 c075a1a8 cd3b2300 cd3b2304 000000015efc  00000000 00000000 ce165f1c c00f9e2c c027e574 60000013 ffffffff c0446b145f1c  cd306000 cf35a6c0 c00f9e2c 00000000 00000000 00000000 cd08098c cd0809b05f3c  cd306000 c075a1a8 c07500b4 cd3b233c 00000104 cd306018 c00bef44 000000005f5c  0000001c 00000000 c00f8d04 0000001c cd080980 0000001c b3197858 000000105f7c  00000001 00000000 b1e00f08 00000004 b2ffc5e0 000000fb c0013128 ce164000R0: 0xcd080900:0900  00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000000920  00000000 00000000 00000000 00000000 ffffffff ffffffff ffffffff ffffffff0940  ffffffff ffffffff c0756cf0 c0756d20 c0757510 c904b240 c0048858 002000340960  00280006 001d0020 00000000 00000000 00000000 00000000 00000000 000000000980  cd080000 00000000 00000000 cd3b2334 cd3b240c ffffffff cd306000 0000001009a0  00000001 cd23d000 cd23d000 cd3b2300 cd306084 cd306084 00000000 ffffffff09c0  0000001c b3197858 00000010 00000001 c0757510 cecca0c0 c0048858 0020003409e0  00280006 001d0020 00000000 00000000 00000000 00000000 00000000 00000000R1: 0xcd3b22bc:22bc  00000000 00000001 00000001 c0960640 00000000 00000000 cf28f800 0000000022dc  00000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000022fc  00000000 36c236c2 00000000 00000000 cd3b230c cd3b230c cfb2bc00 00000000231c  00000000 cd3b2320 cd3b2320 00000000 cd3b232c cd3b232c cd3b240c cd08098c233c  cd080000 ffffffff 00000000 c0756cf0 cf35a6c0 00000000 00000000 00000000235c  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000237c  00000000 cd3b2400 00000000 00000001 00050005 00000000 00000000 00000000239c  00000000 00000000 00000000 00000000 00000380 00000000 00000000 cd3c1f00R2: 0xcd07ff80:ff80  38343730 205d3032 203c3c3c 696d6448 74636f49 756f206c 2e2e2e74 3c23230affa0  31303030 33303030 23233e33 3030305b 34373030 5d303238 3e3e3e20 6d644820ffc0  636f4969 69206c74 2e2e2e6e 3c23230a 31303030 33303031 30305b23 37303030ffe0  33343834 3c3c205d 6448203c 6f49696d 206c7463 2e74756f 230a2e2e 30303c230000  00000000 cd3b2400 cd080980 cd08000c cd08000c ffffffff cd306180 000000110020  00000001 cd23d028 cd23d028 cd3b2300 cd306204 cd306204 00000000 ffffffff0040  0000001c 00000073 00000011 00000000 c0757510 cf32f780 c0048858 002000340060  00280006 001d0020 00000000 00000000 00000000 00000000 00000000 00000000R4: 0xcd305f80:5f80  00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000005fa0  00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000005fc0  00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000005fe0  00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000006000  cd306000 cd306000 cf823850 cf429aa0 cf4e64a0 c05a5200 00040004 000000006020  00000002 00000802 00000003 00000000 00000000 00000000 00000000 000000006040  00000000 00000000 00000000 00000000 cd3b2200 00000000 00000000 000000006060  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000R5: 0xcf35a640:a640  00000000 00000000 00000000 00000000 cf24a980 00000000 00000000 00000000a660  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000a680  00000000 cf35a684 cf35a684 cf35a68c cf35a68c 00000000 00000000 00000000a6a0  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000a6c0  cf35a6c0 cf35a6c0 cfa58910 cb8b1220 cf4362c0 c0556b74 00000000 00000000a6e0  00000002 00000002 00000003 00000000 00000000 00000000 00000000 00000000a700  00000000 00000000 00000000 00000000 cd3b2200 00000000 00000000 00000000a720  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000R6: 0xcd080900:0900  00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000000920  00000000 00000000 00000000 00000000 ffffffff ffffffff ffffffff ffffffff0940  ffffffff ffffffff c0756cf0 c0756d20 c0757510 c904b240 c0048858 002000340960  00280006 001d0020 00000000 00000000 00000000 00000000 00000000 000000000980  cd080000 00000000 00000000 cd3b2334 cd3b240c ffffffff cd306000 0000001009a0  00000001 cd23d000 cd23d000 cd3b2300 cd306084 cd306084 00000000 ffffffff09c0  0000001c b3197858 00000010 00000001 c0757510 cecca0c0 c0048858 0020003409e0  00280006 001d0020 00000000 00000000 00000000 00000000 00000000 00000000R7: 0xc075a128:a128  00000000 c002e900 00000000 c0795dd4 00000000 c065aa7c c07500b0 00000004a148  000001a4 00000000 c002e900 00000000 c0795dd4 00000000 c065aa90 c07500a8a168  00000004 000001a4 00000000 c002e900 00000000 c0795dd4 00000000 00000000a188  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000a1a8  cd30608c cd30608c c075a1b0 c075a1b0 00000000 00000000 c075a1c0 c075a1c0a1c8  cfb2bc00 00000000 c065aa7c c07500b8 00000004 000001a4 00000000 c002e2c4a1e8  00000000 c0795e10 c075a218 00000000 00000000 00000000 00000000 00000000a208  00000000 00000000 00000000 00000000 7fffffff c0664070 00000000 c00fa6c4R8: 0xcd3b2280:2280  00000001 00000000 cd3b2288 cd3b2288 00000000 00000000 000b000b cd3c3bdc22a0  cd3c3bdc 00000000 00000003 00000010 00000001 00000001 00000002 0000000022c0  00000001 00000001 c0960640 00000000 00000000 cf28f800 00000000 0000000022e0  00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000002300  36c236c2 00000000 00000000 cd3b230c cd3b230c cfb2bc00 00000000 000000002320  cd3b2320 cd3b2320 00000000 cd3b232c cd3b232c cd3b240c cd08098c cd0800002340  ffffffff 00000000 c0756cf0 cf35a6c0 00000000 00000000 00000000 000000002360  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000R9: 0xcd3b2284:2284  00000000 cd3b2288 cd3b2288 00000000 00000000 000b000b cd3c3bdc cd3c3bdc22a4  00000000 00000003 00000010 00000001 00000001 00000002 00000000 0000000122c4  00000001 c0960640 00000000 00000000 cf28f800 00000000 00000000 0000000022e4  00000000 00000000 00000000 00000000 00000000 00000000 00000000 36c236c22304  00000000 00000000 cd3b230c cd3b230c cfb2bc00 00000000 00000000 cd3b23202324  cd3b2320 00000000 cd3b232c cd3b232c cd3b240c cd08098c cd080000 ffffffff2344  00000000 c0756cf0 cf35a6c0 00000000 00000000 00000000 00000000 000000002364  00000000 00000000 00000000 00000000 00000000 00000000 00000000 cd3b2400Process vecsupgradehisi (pid: 1786, stack limit = 0xce164238)Stack: (0xce165f1c to 0xce166000)5f00:                                                                cd3060005f20: cf35a6c0 c00f9e2c 00000000 00000000 00000000 cd08098c cd0809b0 cd3060005f40: c075a1a8 c07500b4 cd3b233c 00000104 cd306018 c00bef44 00000000 0000001c5f60: 00000000 c00f8d04 0000001c cd080980 0000001c b3197858 00000010 000000015f80: 00000000 b1e00f08 00000004 b2ffc5e0 000000fb c0013128 ce164000 000000005fa0: 01fc727c c0012f80 b1e00f08 00000004 0000000e 00000001 00000010 b2ffc5e05fc0: b1e00f08 00000004 b2ffc5e0 000000fb 00000001 00000001 01fc7668 01fc727c5fe0: b3627ddc b2ffc4fc b334f0b0 b608d3bc 60000010 0000000e 00000000 00000000[<c027e574>] (rb_insert_color+0x1c/0x17c) from [<c00f9e2c>] (SyS_epoll_ctl+0x584/0x860)[<c00f9e2c>] (SyS_epoll_ctl+0x584/0x860) from [<c0012f80>] (ret_fast_syscall+0x0/0x30)Code: e5923000 e3130001 112fff1e e92d4030 (e593c004)---[ end trace a35b773550a06f61 ]---

对于最终分析问题原因来讲，以上信息的每一行都很重要。

从上述信息中，我们可以获得出现问题的主要原因（比如，这里的地址错误），出现问题时的现场信息，包括：

1 现场PC指针，LR指针（函数返回时的地址，上一级调用点的下一条指令地址），寄存器地址，堆栈指针等

2 问题出现时当前的进程或者内核线程，关键的调用堆栈

3 除此，内核还将上述寄存器内容所对应内存地址附近的内存信息dump了出来。对于PC来讲，则是机器指令，如最后的Code行

基于上述信息，我们需要分析问题产生的原因，代码中的BUG。

为了便于调试，可以按下述步骤进行操作

首先，编译带debug版本的kernel，在menuconfig中，kernel hacking中，选中with debug info选项

其次，反汇编当前编译的kernel源码，使用交叉编译工具的objdump命令，输入文件为未压缩的内核二进制文件vmlinux

第一步中便于我们定位代码行，第二步便于我们查看实际的汇编指令，以便对应到上述日志信息

完成上述两步后，首先直接调用交叉编译工具链的gdb程序，调试 kernel的 vmlinux文件

输入l *func+0Xab 即可显示问题所在行。对于本奔溃，输入 l *rb_insert_color+0x1c，gdb输出

  0xc027e574 is in rb_insert_color (lib/rbtree.c:94).89                      } else if (rb_is_black(parent))90                              break;9192                      gparent = rb_red_parent(parent);9394                      tmp = gparent->rb_right;95                      if (parent != tmp) {    /* parent == gparent->rb_left */96                              if (tmp && rb_is_red(tmp)) {97                                      /*98                                       * Case 1 - color flips

可见地址0xc027e574能够对应上，且显示了出问题的代码行，为tmp = gparent->rb_right;

其实，有了这个信息，结合日志虚拟地址错误，我们可以猜到gparent是一个空地址。4正好是成员变量的偏移。

一般，找到出问题的代码行之后，可以简单扫扫代码，是否有明显的问题或者问题的原因可能出在什么地方。但是，一般而言，这一步也不会有什么收获。如果是很明显的错误，应该不会这么容易留下来。不过，我们可以先走一个捷径，比如查看Linux内核的修改记录，看看是否有针对当前文件或函数的补丁记录。方法是打开下面的网址，

  https://git.kernel.org/ 在其中找source tree，进一步找针对当前使用的版本

  kernel/git/torvalds/linux.git - Linux kernel source tree

找到对应目录，进入查看修改日志，以确认是否后续更新版本有对当前版本所定位到问题点的代码的修改或补丁

这一步不一定有明显的收获，但是可以用于快速检查，如果正好有，就避免了时间浪费。

如果没有明显的收获，我们可以下载更新版本的完整源码，进行简单对比，看看有什么更新。如果对比后，还是没有收获，则可能需要进一步阅读源码，用以获取更加准确和详细的信息。

实际源码分析时，我们需要注意到，出问题的点只是最后暴露问题的点，问题的引入很可能在之前的调用路径上，所以，可能不仅需要分析当前定位到的代码附近，还需要分析调用者及调用者的调用者

这里，更详细的进一步调试，可以结合反汇编内核得到的汇编指令进行。还是对于上一个例子

  arm-hisiv400-linux-objdump -d vmlinux_nodebug > vmlinux_nodebug_assembler

用上面命令生成汇编代码，用二进制编辑工具打开

也可以只反汇编出问题文件的目标文件，即.o格式的文件，进行汇编代码查看分析

输入出问题的PC地址0xc027e574，可以查看问题点的汇编代码

  c027e558 <rb_insert_color>:c027e558:	e5902000 	ldr	r2, [r0]c027e55c:	e3520000 	cmp	r2, #0c027e560:	0a000054 	beq	c027e6b8 <rb_insert_color+0x160>c027e564:	e5923000 	ldr	r3, [r2]c027e568:	e3130001 	tst	r3, #1c027e56c:	112fff1e 	bxne	lrc027e570:	e92d4030 	push	{r4, r5, lr}c027e574:	e593c004 	ldr	ip, [r3, #4]

可以看到，r3加上4给了IP寄存器，这里r3的内容是多少，可以对应问题现场日志

  pc : [<c027e574>]    lr : [<c00f9e2c>]    psr: 60000013sp : ce165f1c  ip : 00000000  fp : 00000000r10: 00000001  r9 : cd3b2304  r8 : cd3b2300r7 : c075a1a8  r6 : cd080980  r5 : cf35a6c0  r4 : cd306000r3 : 00000000  r2 : cd080000  r1 : cd3b233c  r0 : cd080980

看到r3是0，加4作为虚拟地址，显然是错误的。

其他寄存器，最近的寄存器，及寄存器值作为地址的内存空间，都可以从第一现场获取到，也包括SP堆栈内容。结合寄存器和堆栈及内存，大概可以分析代码出问题的原因。只不过这部分需要对照代码、汇编以及内存数据，仔细分析了。可能需要画出一些数据结构，及相关的地址来仔细分析。

对这里例子，从代码来看，eventpoll结构体对应着一个file描述符，挂载着rbtree的根。每次add ctrl时，添加新的节点。如果节点的父节点为空，说明是根节点，会打上黑树标识，之后会不断添加子节点。

但是从汇编和现场日志来看，当前要添加的节点地址为cd080980，其父节点地址为cd080000，但是父节点的第一个域也就是再上一级节点，为00000000，这与黑树节点类型不符。进一步从内存地址来看，该节点的右孩子，也就是cd080004地址为cb3b2400，左孩子也就是cd080008地址为cd080980，符合当前要添加节点的地址。这样来看，从代码来看，正常应该是不会出现0000000的根节点，至少也是00000001。那问题会出在哪里，内存被修改？节点添加过程意外退出？

另外，需要关注arm调用时，堆栈和参数传递问题。

如此分析，epoll的红黑树应该是出了问题，父节点的父节点为空，代码中没有做判断，是因为基于红黑树的规则不需要进行判断？比如红节点的父节点不是红节点？

最后补充说明内核受污染的信息，来自网络：

  1: 'G': 所有的模块都是GPL的License。如果有模块缺少MODULE_LICENSE()或者声明是Proprietary的，则为'P'。

  2: 'F': 如果有模块是使用 insmod -f 强制载入的。否则为空。

  3: 'S': 如果Oops发生在SMP的CPU上，但这个型号的CPU还没有被认为是SMP安全的。

  4: 'R': 如果有模块是使用 rmmod -f 强制卸载的。否则为空。

  5: 'M': 有CPU报告了Machine Check Exception，否则为空。

  6: 'B': 如果有page-release函数发现一个错误的page或未知的page标志。

  7: 'U': 来自用户空间的程序设置的这个标志位。

  8: 'D': 内核刚刚死掉，比如Oops或者是bug。

  9: 'A': ACPI表被覆盖。

  10: 'W': 之前kernel已经产生过警告。

3 =====RCU-STALL调试=====

补充一下，内核打印中，版本信息中的#xx后面的数字是版本的编译次数。该次数由scripts目录下的脚本生成，每次新生成内核时，该计数增加1，并且会生成一个头文件，包含启动 banner需要的信息。

言归正传。内核运行过程中会出现rcu-stall现象

该现象的典型日志（0702的日志较为有价值，其他的日志，stall所发生的核信息不全）

INFO: rcu_sched detected stalls on CPUs/tasks: { 0 1} (detected by 3, t=4002984 jiffies, g=59256, c=59255, q=494001){ 1}  (t=4003098 jiffies g=59256 c=59255 q=494001)

与rcu有关的一些背景知识，关于tree rcu等，参考博主文档：

https://blog.csdn.net/wwwyue1985/article/details/127347496

基于上述背景，分析该现象的产生原因

要定位具体的问题点，需要继续进一步研究 rcu的调试方法和手段

RCU的调试方法

阅读内核文档中的相关说明，通过分析现象，对应日志，对问题进行定位。另外，也可以尝试人为修改代码引入问题，从而辅助对问题的判断。

修改内核，主动触发rcu，就是人为制造rcu-stall现象

要触发内核错误，最直接的方式就是修改内核代码。应用层要完成这一工作，较为空难，否则，这将是内核的一个漏洞或者BUG被利用了。之前想到可以通过内存的操作，影响到内核，比如通过mmap，进行物理虚拟内存映射进行操作，但是细想起来，映射的还是应用的地址空间，并不能操作到内核地址空间，所以应该是行不通的。

除了应用层，最自然的修改内核的方式就是改动核心代码或者驱动。显然，驱动更直接，且容易切入，影响点较为具体，扩散面也较为容易控制，整体又方便操作实施。这里，为了方便调试，我们采用动态加载的方式进行调试。

RCU-STALL既然是CPU有卡住逻辑，导致宽限期内没有发生调度，即产生平静状态切换（参考内核文档 stallwarn.txt)，那么模拟一个死循环，卡住CPU，应该就可以出发STALL了

显然，模拟CPU看著，最简单的就是在中断中或者原子上下文中进行delay，让CPU忙等，类似死锁状态。实际中，采用定时器方案，注册一个字符设备，每当打开设备时，定时器开始工作，这里在定时器中循环调用mdelay，产生长时间忙等状态

另外，为了更详细的展示问题发生时的信息，内核中配置了诸多RCU调试相关的配置。具体参见stallwarn文档。实际中感觉没有多出多少信息。

重新便于内核，刷写，运行。驱动加载并运行后，现象比较容易出现：

  entry test cdev init test cdev have added to system!cdev open file pointer addr is cd2da6c0 entry cdevdev open pdev=  (null)  cdev=  (null) cdev timer will entry after 1s  current jiffies = -15420 cdev timer will entry after 1s  current jiffies2 = -15419 entry cdevdev write 26953552 cdev write file pointer addr is cd2da6c0  pos=0 Driver got data(write by app) 1 Driver got data(write by app) 2 Driver got data(write by app) 3 Driver got data(write by app) 4 Driver got data(write by app) entry cdevdev release cdev release file pointer addr is cd2da6c0 cur atomic count is -1 cdev timer will entry after 1s  current jiffies3 = -15319 timer param is 10004 timer mdelay... 999 timer mdelay... 998 timer mdelay... 997 timer mdelay... 996 timer mdelay... 941 timer mdelay... 940 timer mdelay... 939 INFO: rcu_sched self-detected stall on CPU { 1}  (t=6001 jiffies g=382 c=381 q=106563)Backtrace for cpu 1 (current):INFO: rcu_sched detected stalls on CPUs/tasks: { 1} (detected by 3, t=6002 jiffies, g=382, c=381, q=106563)CPU: 1 PID: 0 Comm: swapper/1 Tainted: P           O 3.10.0_hi3536 #43[<c0019d30>] (unwind_backtrace+0x0/0xf4) from [<c0016de4>] (show_stack+0x10/0x14)[<c0016de4>] (show_stack+0x10/0x14) from [<c0018460>] (smp_send_all_cpu_backtrace+0x70/0xcc)[<c0018460>] (smp_send_all_cpu_backtrace+0x70/0xcc) from [<c007e61c>] (rcu_check_callbacks+0x3a4/0x654)[<c007e61c>] (rcu_check_callbacks+0x3a4/0x654) from [<c00328e0>] (update_process_times+0x40/0x6c)[<c00328e0>] (update_process_times+0x40/0x6c) from [<c00645c8>] (tick_nohz_handler+0xb4/0x11c)[<c00645c8>] (tick_nohz_handler+0xb4/0x11c) from [<c002194c>] (sp804_timer_isr+0x20/0x28)[<c002194c>] (sp804_timer_isr+0x20/0x28) from [<c0076a50>] (handle_irq_event_percpu+0x54/0x17c)[<c0076a50>] (handle_irq_event_percpu+0x54/0x17c) from [<c0076bb8>] (handle_irq_event+0x40/0x60)[<c0076bb8>] (handle_irq_event+0x40/0x60) from [<c0079920>] (handle_fasteoi_irq+0x80/0x158)[<c0079920>] (handle_fasteoi_irq+0x80/0x158) from [<c00762d0>] (generic_handle_irq+0x28/0x40)[<c00762d0>] (generic_handle_irq+0x28/0x40) from [<c0013e9c>] (handle_IRQ+0x40/0x90)[<c0013e9c>] (handle_IRQ+0x40/0x90) from [<c0008514>] (gic_handle_irq+0x34/0x8c)[<c0008514>] (gic_handle_irq+0x34/0x8c) from [<c0012bc0>] (__irq_svc+0x40/0x50)Exception stack(0xcf867e60 to 0xcf867ea8)7e60: 00084885 ffffffff 00003548 c026cfd8 00000342 c07504a4 000003aa cf8660387e80: bf83c03c cf812a14 cf812c14 cf812000 00000001 cf867ea8 bf83c08c c026d0087ea0: 20000113 ffffffff[<c0012bc0>] (__irq_svc+0x40/0x50) from [<c026d008>] (__loop_delay+0x0/0x10)sending IPI to all other CPUs:IPI backtrace for cpu 3CPU: 3 PID: 0 Comm: swapper/3 Tainted: P           O 3.10.0_hi3536 #43task: cf85d400 ti: cf86a000 task.ti: cf86a000PC is at arch_cpu_idle+0x2c/0x30LR is at arch_cpu_idle+0x28/0x30pc : [<c00142a8>]    lr : [<c00142a4>]    psr: 60000013sp : cf86bfe0  ip : 00000000  fp : c0741cf0r10: cf86a000  r9 : cf86a000  r8 : c07775e5r7 : cf86a000  r6 : c0545e6c  r5 : c0741d50  r4 : c07775e5r3 : 00000000  r2 : 00013868  r1 : 00000000  r0 : c09b6930Flags: nZCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment kernelControl: 10c5387d  Table: 4da4c06a  DAC: 00000015PC: 0xc0014228:4228  f10c0040 e3053e6c e34c3054 e5933000 e5930000 e200000f eb09a380 e1a010044248  e59f200c e30400a8 e34c0001 eb0958f2 e7f001f2 c0777888 f1080040 e12fff1e4268  e3a00001 ea004e39 e3a00002 ea004e37 ea148cf5 e92d4008 e3073808 e34c30774288  e5933080 e3530000 0a000002 e12fff33 f1080080 e8bd8008 eb0033ce f108008042a8  e8bd8008 ea004e8b e92d4008 eb0010f8 f10c0080 eafffffe e92d4010 eb0010f442c8  e3073808 e34c3077 e5933084 e3530000 08bd8010 e8bd4010 e12fff13 e92d403842e8  e1a04000 eb0010ea e3053988 e34c3074 e1a01004 e30054a4 e593205c e34c50754308  e5d30000 e3a04ffa e12fff32 e30605b0 e5953004 e3400666 e12fff33 e2544001LR: 0xc0014224:4224  f10c0080 f10c0040 e3053e6c e34c3054 e5933000 e5930000 e200000f eb09a3804244  e1a01004 e59f200c e30400a8 e34c0001 eb0958f2 e7f001f2 c0777888 f10800404264  e12fff1e e3a00001 ea004e39 e3a00002 ea004e37 ea148cf5 e92d4008 e30738084284  e34c3077 e5933080 e3530000 0a000002 e12fff33 f1080080 e8bd8008 eb0033ce42a4  f1080080 e8bd8008 ea004e8b e92d4008 eb0010f8 f10c0080 eafffffe e92d401042c4  eb0010f4 e3073808 e34c3077 e5933084 e3530000 08bd8010 e8bd4010 e12fff1342e4  e92d4038 e1a04000 eb0010ea e3053988 e34c3074 e1a01004 e30054a4 e593205c4304  e34c5075 e5d30000 e3a04ffa e12fff32 e30605b0 e5953004 e3400666 e12fff33

因为RCU-STALL检测超时时间设置为了60，所以可以看到，60秒后，stall现象暴露出来

  INFO: rcu_sched self-detected stall on CPU 

跟实际设备上的原因信息一致，当然，具体原因有差异

我们来分析日志，看是否能够从日志中定位出人为制造的问题点

首先，主要看看堆栈信息，从日志打印的堆栈中可以看出，最终是在时钟滴答中断中，调用rcucallback检查，发现超过了宽限期，然后主动dump内核异常信息。并且发送了IPI给其他核心，触发其他核心的寄存器、内存和堆栈信息。不过，对于这里的stall问题，其他核心的信息仅仅参考，当前看来，并不具有太大意义这样，整体一看，整个日志信息似乎表达的都是废话

但是我们需要注意一个细节，问题出现的核心的硬件中断前的日志信息，这是最关键的，结合当前情况，个人的理解。

  [<c0008514>] (gic_handle_irq+0x34/0x8c) from [<c0012bc0>] (__irq_svc+0x40/0x50)Exception stack(0xcf867e60 to 0xcf867ea8)7e60: 00084885 ffffffff 00003548 c026cfd8 00000342 c07504a4 000003aa cf8660387e80: bf83c03c cf812a14 cf812c14 cf812000 00000001 cf867ea8 bf83c08c c026d0087ea0: 20000113 ffffffff[<c0012bc0>] (__irq_svc+0x40/0x50) from [<c026d008>] (__loop_delay+0x0/0x10)

中断irq_svc是在loop_delay的时候调用的，这非常关键

对于这里给出的地址，像c026d008  c0012bc0 我们可以在当前编译内核的目录进行定位，通过交叉编译链的arm----gdb工具，不过前提是内核需要是debug版本。

如果没有编译debug的vmlinux，还是可以分析的，有两种方法

一种是在当前编译内核的目录下通过System.map文件来分析，该文件中保存有内核符号和地址的映射对应关系

一种是根据运行设备的/proc/kallsyms符号表进行定位

鉴于这里，内核已经卡死了，我们选择第一种，可以在不用重启设备的情况下，进行分析

比如，选择这种方法，

  cat System.map | grep c0012bc0

但是考虑到地址可能对于函数开始有偏移，所以大部分时候除非是在函数调用开始，否则几乎不会输出任何东西。所以我们可以查看该地址附近的信息，比如，通过下面这种方法，省略掉后两位地址位，看是否有匹配

  cat System.map | grep c0012b

  c0012b20 t __dabt_svc

  c0012b80 t __irq_svc

  c0012bd0 t __und_fault

  c0012be0 t __und_svc

我们看到这个地址附近的函数，跟上述日志信息里的函数是有一致的。从这里获取开始地址，加上日志中的偏移，结合反汇编，基本可以定位出调用栈所在的代码。当然，前提是内核不要有新的修改编译，否则，上述地址就可能发生变化。

我们再看看调用者的地址

  cat System.map | grep c026d008

  c026d008 T __loop_delay

说明是在loog_delay函数中发生了中断，然后触发了stall的检查条件。所以，问题很可能是在该loop_delay相关的函数中。这里有两点引申含义：

1 是说问题可能是由delay导致。这一点比较容易猜想。当delay在让CPU卡住等待时，如果时间过长，显然肯定会触发rcu-stall的。

2 是说大概就是在delay相关的接口中。为什么是大概呢？当然，这里的前提还是假设是由delay导致了问题。这涉及到内核的编译处理。

我们知道，函数调用涉及入栈出栈的问题，如果只是一个简单的函数，当被频繁调用，那么光是栈处理消耗的CPU就可能远大于函数本身的逻辑处理对CPU的占用。所以，这就导致内联函数的产生。更进一步的，如果一个函数是静态的，且只在当前文件中被调用了一次，那么编译器可能也会将其优化为类似内联函数形式。

说了这么多，其实要表达的核心思想是代码中看到的函数调用不一定在编译后还是原本的函数调用，可能就被嵌入到调用者的汇编里了，在汇编代码中看不出有函数调用痕迹。这样一来，对定位代码，就产生了一些干扰。我们需要结合dump栈中的偏移和汇编代码，结合内核代码，一起定位调用点在原始C代码中的那个位置。

实际调试时，常会发现，汇编中的调用总是少于实际C代码的，就是因为很多成为了调用者内部逻辑，规避了利用栈传递参数的逻辑。

对于ARM架构来讲，大部分介绍是说函数调用通过寄存器结合堆栈进行参数传递的，这一点在跟踪汇编代码时需要注意。

有了上述信息，就可以围绕已有线索，展开问题原因的定位分析。

单纯看delay，虽然与问题的原因很容易对应上，但是范围太广。delay是非常基础的函数，在内核中调用点散步很广，很难直接下手。这时候，就需要对当前CPU的堆栈进行分析。因为堆栈可能会给出这个delay的具体调用者。从而提供更准确的信息。堆栈中记录的调用者，与真正导致问题的代码，可能比较接近。

上面的日志中也给出了异常栈信息。按照从高地址向低地址增长的方式来看，低地址处应该是更接近CPU现场的被调用点，高地址是调用者

考虑到内核地址在3-4GB范围内，即C0000000--F0000000地址空间，所以可以特别关注C开头的地址，很可能是内核地址

  c026d008     c026d008 T __loop_delay

  cf867ea8  非内核地址

  cf812000  cf81开始的这几个也不是内核地址 可能是内核数据空间，也可能是参数地址

  c07504a4 c07504a4 D arm_delay_ops

可见loop_delay是由该函数调用到的

struct arm_delay_ops arm_delay_ops = {.delay		= __loop_delay,.const_udelay	= __loop_const_udelay,.udelay		= __loop_udelay,};

从实际的代码中可以对应上

  c026cfd8    c026cfd8 T __loop_const_udelay

从目前的堆栈分析来看，函数调用似乎就这么多了。另外一些数据，可以猜测验证，也是有帮助的。比如000003aa，十进制就是938，是timedelay的计数值，反推时，我们可以使用该值验证人为的出发点，比如1000-938接近60。但是正向跟踪其实是有点难度的.不过，不管怎样，也是一些重要信息。可能就在这些蛛丝马迹中发现问题点。还比如，一些0或者1的值，可能就跟布尔条件变量有关等等。

其实这里的例子，还有一些特殊性。为了验证问题，采用了动态加载模块的方式

我们对模块进行反汇编看一下arm-hisiv400-linux-objdump -d testdrv.ko

发现其中的地址都是相对地址，偏移是基于00000000的，所以模块的实际地址，可能是在insmod的时候，由内核重新分配的。这样来看，堆栈中的地址在内核编译符号中找不到，可能能够讲得通了。同时，从另外一个角度来看，如果产品中存在这种动态加载的模块，那么当问题产生时，给问题的定位会带来一些额外的复杂度和工作。

在保留堆栈日志信息的前提下，我们重新加载模块，进行进一步的定位分析。

  cat /proc/modules 可以查看到外部模块的地址信息

  testdrv 6256 0 - Live 0xbf83c000 (O)

比如这里的测试模块，可以看到是在0xbf83c000这个地址开始的空间内

此时，再回看堆栈日志信息，可以看到有两个地址可疑

第一个，bf83c08c，此时模块是动态加载，需要在运行的内核中查看，方法同前述

~ # cat /proc/kallsyms | grep bf83c0bf83c000 t $a   [testdrv]bf83c00c t my_tasklet_func      [testdrv]bf83c0b4 t cdevdev_write        [testdrv]bf83c03c t cdevdev_timer        [testdrv]bf83c000 t add_var      [testdrv]

第二个，bf83c03c，跟之前一样

从这两个地址，可以初步定位出问题关键点，timer函数。

接下来，就需要根据上述地址的具体便宜结合汇编定位出C代码，然后检查代码了。因为是人为制造的触发流程，代码简单直接

   int count = 1000;while(count--) {mdelay(1000);printk(KERN_INFO "timer mdelay... %d \n", count);}

到这一步，根据日志定位代码的流程基本就完成了。从上述流程来看，异常栈是非常非常重要的信息。

在这整个过程中，还有几个问题需要明确：

需要明确，每次insmod模块时，CPU会分配相同的地址吗？从上面重新加载模块，定位函数来看，地址似乎是一样的。这是巧合还是固有设计，待验证。

insmod模块时，是加载到用户空间地址还是内核空间地址？从上述日志来看，是在用户空间了？因为是B开头的地址。

虽然如上分析，问题定位在delay中，但也只是一种可能得到了验证。因为根据RCU-STALL的原理来讲，还是有其他可能的，包括

 本cpu的其他地点，这里只是凑巧在中断前的地址中发现了问题，并凑巧在模块中得到了定位。关键还是要找到宽限期后未经历静止状态的CPU核及其上任务。

2 其他CPU的可能性。这一点可以通过绑定CPU核心来验证。比如将驱动模块的定时器绑定到其他CPU核心上，默认时钟滴答是否应该在CPU0上？可以编码来验证这一点。

如果得到验证，那么其他CPU的寄存器和堆栈就非常值得分析了。

答案应该是明确的。因为存在其他CPU检测到当前CPU出现stall问题。

如果问题最终能定位，则可以用该内核放到产品中定位产品测试中出现的stall现象

如果不能，则采用重启等补充手段？

手段1 ，使用延迟队列的 restart，参见前述kernel_restart部分。

如果循环触发rcu-stall，放在工作队列中的restart是否有机会调用，待验证。

经过验证，该restart几乎没有机会执行。

在应用层，部分命令还是可以正常执行，比如top，可以查看进程和线程的情况。

但是，应用层的定时喂狗似乎是存在问题的，超时后，单片机重启了设备，是因为内核卡住定时器不准了还是应用执行被停住了？猜测这里是因为insmod的测试驱动使用了mdelay,卡住了cpu，可能导致该核心上的应用定时器不再准确，从而导致喂狗mcu失败

该机制目前看不太可靠，内核的运行逻辑不是固定的。

手段2，使用panic，当发现rcu-stall后，主动触发panic，可以挂死上层应用，触发单片机看门狗

手段3，启用看门狗，验证panic和rcu-stall是否会影响到内核中断处理，从而触发cpu内部看门狗

首先，对于单纯rcu-stall，感觉不会影响到硬件中断，实际测试，确实不会影响中断，串口输入还可以正常使用。但是reboot命令本身不起作用。

其次，对于panic加看门狗，测试看可以生效，到时间后，cpu被复位

综上，针对rcu-stall要重启设备的话，可以使用panic结合上层应用使用的MCU喂狗机制，可以完成系统的硬复位。内核看门狗作为一种补充手段保留。

其实，panic可以使用一个超时参数，在panic发生后，经过超时时间后重启设备。这需要配置内核，但是这个重启是否管用，待测试。

经过测试，该超时在rcu-stall上下文掉用不能够完成重启，跟前述kernel_restart表现一致。因为之前直接调用重启函数不管用，才使用了工作队列方式，才有了这里所描述的上述方案。

最终的方式就是：出现RCU-STALL--触发panic--触发内核看门狗--如果失败，触发应用看门狗。两重保障。panic timeout可以保留，也可以不保留，应该会屏蔽CPU中断，这里选择保留。

根据stallwarn文档，产生stall的可能原因包括：

1 一个CPU在一个RCU读关键区循环. == 对应RCU的宽限期图示，如果CPU没有出来，宽限期就会超时.

2 一个CPU在中断关闭的情况下循环。这个条件会导致RCU-sched和RCU-bh产生stall == 中断关闭时，如果循环，则存在无法打破循环的问题。

3 一个CPU在抢占关闭的情况下循环。这个条件可以导致RCU-sched stalls，并且如果ksoftirqd在使用，RCU-bh 会stalls。

4 一个CPU在下半部关闭的情况下循环。这个条件会导致RCU-sched和RCU-bh stalls

5 对于非抢占内核，CPU在内核任意地方循环，而没有主动执行调度。===这个条件有个疑问，（2 3 4 条也是），就是中断是否会影响stall的判断？从stall堆栈中还能看到中断来看，中断本身对stall的影响是比较小的

6 其他一些条件，包括RCU本身的bug、硬件bug等。