高通平台Linux kernel死机解题心得

原创 2017年08月20日 22:39:28
1、前言
1.1 目的
能够借助相关调试工具,使用一般分析手段分析、定位解决项目过程中遇到的死机类系统稳定性问题,提升工作效率
持续积累,拓宽知识深度和广度
1.2 死机?
指系统发生致命性异常导致主动或者被动进入系统完全不可用的状态,导致系统死机的问题原因有很多,排除硬件问题,还有这些大模块:Android、Linux kenrel、modem、TZ 等等,各个子系统都有可能导致系统死机重启,我们这里主要介绍最常见的Linux kernel panic的一般调试分析手法。
1.3 调试策略
稳定复现的问题,可以借助飞线抓uart log的方式来获取异常现场,kernel在发生panic之前会把很多重要寄存器信息、以及重要的call stack(调用栈)信息打印出来(可参考http://blog.csdn.net/forever_2015/article/details/53235716),通常可以借助相关GNU工具(addr2Line) 解析出异常地址所在的文件、函数、行号来定位问题。这是最常用的分析手法,对于很多简单的死机问题通常可以比较清晰的定位解决。
概率性复现的问题,上面飞线抓uart log的方式就显得有些无力了,由于出现异常的时机存在不确定性,所以必须要一直连着串口线操作才可以,还有些问题几天或者更长时间才出现一次,此种情况下,普通的抓uart log的方式就显得很苍白无力了。这个时候就需要借助另外的分析手段抓ramdump分析了。ramdump是什么?其实就是指内存转储,简单来说就是整个DRAM的运行时内容数据,当系统发生崩溃性异常时候,通过一种机制实现将DRAM中的数据保存起来的一种方式,保留了异常现场,待离线分析用。ramdump中保留了所以异常时候的DRAM中的信息,包括各种全局变量、局部变量、进程状态等待供调试的信息,通过Crash、gdb、Trace32等工具就可以完成这些信息的提前,非常有助于复杂问题的分析。
2、案例描述
2.1 问题现象:
高通8940平台系统灭屏下,快速重复用错误指纹触摸指纹模组(或亮屏在指纹列表目录下),系统死机,持续测试30min出现2-4次,概率很高。
2.2 初步判断
我们知道Android层(用户空间进程)如果主线程(tid == 0)被堵塞了会触发Watchdog time out导致system_server进程被杀 =》zygote被杀 =》开机动画响起,出现Android crash的情况:
services/core/java/com/android/server/Watchdog.java :533
Slog.w(TAG, "*** GOODBYE!");
Process.killProcess(Process.myPid());
System.exit(10);
通常这种情况出现异常后不会马上死机重启,会有一个触发WDT的等待时间(各种组件前台后台进程触发时间设置策略不同),此种类型异常给用户的感觉就是:指纹失效了,然后等个10s左右手机自动重启。
而目前的情况不同,与测试mm沟通确认发现,出问题后手机没有任何等待,直接黑屏死机,没有重启,直接进入了ramdump模式,所以可以初步判断为底层发现异常,而跟指纹相关的最大可能就是发生了kernel panic(TA crash异常最终会以Android wdt方式表现出来)。
3、ramdump的抓取
高通平台首先保证机器是已使能ramdump抓取机制的,默认设置开关:
kernel/drivers/power/reset/msm-poweroff.c
static int download_mode = 1;
如果开启了secboot 支持的项目还需要更改BOOT:
BOOT.BF.3.3/boot_images/core/securemsm/secdbgplcy/oem/oem_debug_policy.c
-//#define SKIP_SERIAL_NUMBER_CHECK 1
+#define SKIP_SERIAL_NUMBER_CHECK 1
高通平台可以使用PC端的QPST工具抓取全部的dump信息,步骤如下:
安装QPST工具(需要安装QBUK驱动),打开程序主界面,选址Ports分页:

插入usb,自动识别抓取ramdump,完全傻瓜式操作:

大概5min左右完成,选择 Help =》Open Log File Directory ,拿到抓取的ramdump数据:

PS: 若仅仅是为了测试调试,可以这样主动触发ramdump
adb root
adb shell
echo c > /proc/sysrq-trigger
其本质就是让内核访问空指针内存,被MMU拦截而触发data abort异常.
4、 ramdump解析
4.1 高通QCAP网站
https://cap.qti.qualcomm.com/default.aspx
登录高通账户后进入如下界面:(此处建议使用google浏览器,个别浏览器有不支持的情况)

点击 START NEW ANALYSIS

将对应模块(KERNEL/TZ/RPM/MODEM/ADSP等)的符号文件(elf、vmlinux)路径加到对应的选项里面选择开始即可,解析完成后会产生一个报告文件:QCAPReport.html ,里面会有各个模块的相关异常信息描述,包括dmesg等等。QCAP的优点是使用简单,工具安装简单,缺点是解析出来的信息很有限,跟抓log差不多的意思,无法分析定位复杂问题。(QCAP的使用可以参考高通文档:80-nr964-54_j_qcap start-up guide.pdf)
4.2 ramdump-parse
(此脚本只能解析kernel的异常,不同子系统需要配合不同的解析脚步)
ramdump-parse脚本配置:http://blog.csdn.net/forever_2015/article/details/70185313
解析前需要确保vimlinux跟ramdump的一致性,可以按下面的方法确认:
$ strings vmlinux |grep "Linux version"
Linux version 3.18.31 (android@ubuntu) (gcc version 4.9 20150123 (prerelease) (GCC) ) #1 SMP PREEMPT Wed Aug 9 23:23:27 CST 2017

$ strings DDRCS0.BIN |grep "Linux version"
Linux version 3.18.31 (android@ubuntu) (gcc version 4.9 20150123 (prerelease) (GCC) ) #1 SMP PREEMPT Wed Aug 9 23:23:27 CST 2017
如果不匹配,无法继续分析,若确认匹配后就可以执行解析:
$ ramdump-parser.sh 
Start ramdump parser..
cd /home/android/tools/ramdump/tools/linux-ramdump-parser-v2
python ramparse.py -v /home/android/share/fp-quick-wakeup/crash/Port_COM112-6901-die/vmlinux -g /home/android/tools/gnu-tools/aarch64-linux-android-4.9/bin/aarch64-linux-android-gdb  -n /home/android/tools/gnu-tools/aarch64-linux-android-4.9/bin/aarch64-linux-android-nm  -j /home/android/tools/gnu-tools/aarch64-linux-android-4.9/bin/aarch64-linux-android-objdump -a /home/android/share/fp-quick-wakeup/crash/Port_COM112-6901-die/ -o /home/android/share/fp-quick-wakeup/crash/Port_COM112-6901-die/out -x

    [1/32] --clock-dump ... 0.848617s
    [2/32] --cpr3-info ... 0.157973s
    [3/32] --cpr-info ... 1.026817s
    [4/32] --cpu-state ... 0.104325s
    [5/32] --ddr-compare ... 5.864537s
    [6/32] --check-for-watchdog ... 0.011254s
    [7/32] --parse-debug-image ... 10.632866s
    [8/32] --dmesg ... 0.519516s
...
out: /home/android/share/fp-quick-wakeup/crash/Port_COM112-6901-die/out
ls out/
ClockDumps.txt  DDRCacheCompare.txt              MSM_DUMP_DATA_L1_DATA_CACHE_0x2  roareadiff.txt               t32_startup_script.cmm  thermal_info.txt
core0_regs.cmm  dmesg_TZ.txt                     MSM_DUMP_DATA_L1_DATA_CACHE_0x3  secure_world_core0_regs.cmm  tasks_sched_stats0.txt  timerlist.txt
core1_regs.cmm  kconfig.txt                      MSM_DUMP_DATA_L1_DATA_CACHE_0x6  secure_world_core1_regs.cmm  tasks_sched_stats1.txt  tmc-etf.bin
core2_regs.cmm  launch_t32.sh                    MSM_DUMP_DATA_L1_DATA_CACHE_0x7  secure_world_core2_regs.cmm  tasks_sched_stats2.txt  tmc-etr.bin
core3_regs.cmm  lpm.txt                          msm_iommu_domain_00.txt          secure_world_core3_regs.cmm  tasks_sched_stats3.txt  tmc_etr.txt
core4_regs.cmm  mdpinfo_out.txt                  msm_iommu_domain_01.txt          secure_world_core4_regs.cmm  tasks_sched_stats4.txt  vmalloc.txt
core6_regs.cmm  memory.txt                       msm_iommu_domain_02.txt          secure_world_core6_regs.cmm  tasks_sched_stats5.txt
core7_regs.cmm  mem_stat.txt                     msm_iommu_domain_03.txt          secure_world_core7_regs.cmm  tasks_sched_stats6.txt
cpr3_info.txt   MSM_DUMP_DATA_L1_DATA_CACHE_0x0  New Folder                       spm.txt                      tasks_sched_stats7.txt
cprinfo.txt     MSM_DUMP_DATA_L1_DATA_CACHE_0x1  page_tables.txt                  t32_config.t32               tasks.txt
5、解题手段
5.1 分析dmesg
上面是解析完成后的文件,有我们需要的kernel log,也就是文件 dmesg_TZ.txt,打开 dmesg_TZ.txt 看下大致发生了什么事情?
搜索关键字发现发生了kernel panic!
...
[  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
...
看到异常调用栈,一眼看不出问题所在,那么我们需要搞清楚CPU发生了什么事情?CPU停下的原因是什么?
先来看当前64位CPU的状态寄存器组PSTATE《ARMv8-A Architecture reference manual-DDI0487A_g_armv8_arm.pdf》

pstate:600001c5
0x600001c5 ==》1610613189 ==》1100000000000000000000111000101
解析后代表的意思就是禁止debug异常,禁止IRQ,切换异常等级到EL1(Exception Level 1),使用SP_EL1为堆栈指针,EL1说明异常确实是发生在kernel层,禁止IRQ是为了不让被中断干扰现场.
继续看Oops:
[423.400124] Internal error: Oops:96000046[#1] PREEMPT SMP
这里Oops后面接的96000046是ARM发生异常后上报的错误码,分析kernel panic流程代码(可参考:http://blog.csdn.net/forever_2015/article/details/53235716)可知,这个错误码就是ESR(异常综合寄存器)寄存器的值,
根据上面PSTATE的解析,ESR寄存器也将是使用ESR_EL1,ESR_EL1寄存器的描述如下:
An ESR_ELx holds the syndrome information for an exception that is taken to AArch64 state

所以,ESR寄存器中的EC值保持了异常的类型等信息,我们可以解析这个值:
0x96000046 ==》2516582470 ==》10010110000000000000000001000110
EC ==》100101
对应如下:

表面kernel层发生数据终止异常,并且没有改变Exception level,也就是没有路由到EL3或者sec-EL1.
==》死机的原因就是因为CPU发生了 Data abort异常!那么什么时候会发生Data abort异常呢?简单来说就是访问了不可访问的虚拟内存地址,被内存管理单元(MMU)拦截到的异常,比如最常见的空指针异常,内核线程访问非内核虚拟地址空间等(内核虚拟地址空间:
0xFFFF_0000_0000_0000 =>0xFFFF_FFFF_FFFF_FFFF )
现在死机的原因是知道了,那么接下来我们最想知道的就是导致死机的代码是在哪里,我们可以借助add2Line工具解析出调用栈所在函数,文件行号:
$ aarch64-linux-android-addr2line -e vmlinux -f -C ffffffc0000feb98
__list_del
/home/android/project/6901-7.1/LA.UM.5.6/LINUX/android/kernel/msm-3.18/include/linux/list.h:89


$ aarch64-linux-android-addr2line -e vmlinux -f -C ffffffc0000a6864
static_key_count
/home/android/project/6901-7.1/LA.UM.5.6/LINUX/android/kernel/msm-3.18/include/linux/jump_label.h:88

$ aarch64-linux-android-addr2line -e vmlinux -f -C ffffffc0000a6c8c
tick_irq_exit
/home/android/project/6901-7.1/LA.UM.5.6/LINUX/android/kernel/msm-3.18/kernel/softirq.c:363
如此便可以还原调用栈的代码,最终是下面的代码导致的异常:
 87 static inline void __list_del(struct list_head * prev, struct list_head * next)
 88 {
 89     next->prev = prev;   ==》猜想那会不会是next->prev指针为NULL所致么?
 90     prev->next = next;
 91 }
要确认是不是NULL指针所致,我们需要来看下对应的汇编指令,打开Trace32,切到汇编源码混合显示(也可以通过objdump -S vmlinux > vmlinux.S 查看):

为方便查看,复制贴出来:
 static inline void __list_del(struct list_head * prev, struct list_head * next)
                       |{
                     89|        next->prev = prev;
   NSX:FFFFFFC0000FE958|F9000420 str x0,[x1,#0x8]; x0,[x1,#8]
                     90|        prev->next = next;
   NSX:FFFFFFC0000FE95C|F9000001            str     x1,[x0]
                    769|        entry->prev = LIST_POISON2;
   NSX:FFFFFFC0000FE960|D2804000            mov     x0,#0x200        ; x0,#512
   NSX:FFFFFFC0000FE964|F2FBD5A0            movk    x0,#0xDEAD,lsl #0x30   ; x0,#57005,lsl #48
   NSX:FFFFFFC0000FE968|F9000760            str     x0,[x27,#0x8]    ; x0,[x27,#8]
                       |...
简单解释下,
FFFFFFC0000FE968 ==》当前汇编指令的虚拟地址
F9000760 ===》汇编机器码,ARM的指令机器码都是32位固定长度
str x0,[x27,#0x8]==》 汇编指令,;后的是注释
根据AAPCS(ARM二进制过程调用标准)参数传递规则,ARM64的 v0 - v7 参数直接由 x0 - x7 传递,其他参数由压栈传递,子程序返回结果保存到x0,
那么这里可推导如下:
x0 == prev
x1 == next
指令:strx0,[x1,#0x8]
x1+0x8 其实就是next+8个字节的偏移,看下struct list_head 的结构:
struct list_head {
    struct list_head *next, *prev;
};
ARM体系结构中,一个指针占4个字节内存,所以next->next就相当于next+0x4, 而next->prev == next+8 == prev,
也就是: [x1+0x8] == prev
所以这个str指令就是对应上面的next->prev = prev ,那么我们来看下具体的寄存器x0,x1值是多少?
从dmesg log中找到当前发生异常的调用栈(注意,一定要找对应的异常栈的寄存器值),如下:
[  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
上面我们有讲过,ARM64内核的虚拟地址空间范围是0xFFFF_0000_0000_0000 =>0xFFFF_FFFF_FFFF_FFFF
很明显这个值0x0000000000000008不在范围内,它属于用户空间的虚拟地址空间,肯定会被MMU拦截掉上报data abort异常!所以此题的真正原因是程序跑飞访问非法地址所致!
CPU发生异常的原因已经明确了,但仔细一看,好像也看不出来具体是哪里源码导致的死机,而且这些都是内核本身的代码,没人改动过的,为什么会报异常呢?
目前看来从kernel log上的信息无法直接分析出导致问题的具体源代码,从dmesg的这些信息我们已经知道出问题的是这个prev指针,但是比较难直接抓到导致异常的真凶源码位置。
5.2 Trace32分析
安装:http://blog.csdn.net/forever_2015/article/details/70185527
5.2.1 启动模拟器
前面使用ramdump-parse脚本解析完成后,out下有生成这几只文件:
launch_t32.sh t32_config.t32 t32_startup_script.cmm
但是需要做一些简单修改才可以使用trace32工具加载(参考http://blog.csdn.net/forever_2015/article/details/70185638
./launch_t32.sh

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

为便于分析传参分析,需要将Locals的框框打钩:

可以看到,异常时候的各种参数都显示出来了,这样就非常有利于我们debug了,这也是单纯从dmesg无法得到的重要信息!注意inline类型的函数会被编译器默认优化掉,所以inline类型的函数的参数不可见,需要通过读汇编代码,分析寄存器传参推导。
输入d.list 查看PC停止的位置,如下高亮:

5.2.2 分析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;
这里就看到,*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;
...
这个就是内核里面实现定时器标准的数据结构了,其中function这个指针就是time out后执行的callback,而且异常发生在CPU 4,
了解这些数据结构背景后就可以借助T32工具来分析了,既然这个定时器发生了异常,那么我们最想知道的是这是哪一个定时器?
它在源码中的定义是在哪个文件哪个行号?这些都可以借助Trace32工具来获取.
首先我们查看*running_timer的数据内容:
工具栏 调出:view -> Watch,输入:(struct timer_list *)0xffffffc001741120

复制出来就是这样:
(struct timer_list *)0xffffffc001741120 = 0xFFFFFFC001741120 -> (
    entry = (next = 0xFFFFFFC0B27BC9B8, prev = 0xFFFFFFC0B27BC9B8),
    expires = 4294979736,
    base = 0xFFFFFFC0B27BC000,
    function = 0xFFFFFFC0006E277C,
    data = 0,
    slack = -1,
    start_pid = -1,
    start_site = 0x0,
    start_comm = (0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0))
这个就是发生异常的那个timer的数据结构实例,我们最希望的就是希望可以通过这里的数据信息找到它在源码的位置,然后进一步分析它,使用Trace32的dump分析功能就可以做到这点。
菜单栏调出:view -》dump

输入地址 0xffffffc001741120 然后点OK

右击高亮,选择view info:

同理,还可以看function的位置(0xFFFFFFC0006E277C):

上面所示,出异常的timer实例就是:fp_drv/m_timer, callback = timer_out_handle,
源码位置也给出来了,那么就可以着手修复问题了。
6、 同源不同表现
6.1 dmesg分析
导致Kernel panic的源码改动是同一处,但是死机后的表现却可能大不一样,像这个问题当时出现的时候有抓到两份ramdump,解开后却发现表现不一样(很可能每次出现死机都在不一样的地方),逆向推导过程总是需要耐心细心分析,加上一定的运气成分,那么就可以比较顺利定位问题点,简单介绍下:
解析ramdump后查看的dmesg是这样的:
[  256.595276] list_add corruption. prev->next should be next (ffffffc0ab1d4178), but was ffffffc0aba4c628. (prev=ffffffc001b77da8).
[  256.595282] Modules linked in: wlan(O)
[  256.595299] CPU: 5 PID: 6210 Comm: mdss_fb0 Tainted: G        W  O   3.18.31 #1
[  256.595305] Hardware name: Qualcomm Technologies, Inc. MSM8940-PMI8950 MTP (DT)
[  256.595311] Call trace:
[  256.595324] [<ffffffc000089b14>] dump_backtrace+0x0/0x270
[  256.595334] [<ffffffc000089d98>] show_stack+0x14/0x1c
[  256.595345] [<ffffffc000dbd254>] dump_stack+0x80/0xa4
[  256.595356] [<ffffffc0000a3240>] warn_slowpath_common+0x8c/0xb0
[  256.595366] [<ffffffc0000a32c4>] warn_slowpath_fmt+0x60/0x80
[  256.595374] [<ffffffc000345dd4>] __list_add+0x74/0xf0
[  256.595384] [<ffffffc00010356c>] __internal_add_timer+0xb4/0xbc
[  256.595392] [<ffffffc000103b30>] internal_add_timer+0x34/0x90
[  256.595404] [<ffffffc000dca78c>] schedule_timeout+0x1f0/0x278
[  256.595414] [<ffffffc0003e95f0>] mdss_mdp_cmd_wait4pingpong+0x12c/0x534
[  256.595424] [<ffffffc0003c1494>] mdss_mdp_display_wait4pingpong+0xd8/0x404
[  256.595432] [<ffffffc0003c2110>] mdss_mdp_display_commit+0x890/0x1128
[  256.595443] [<ffffffc0003f8c30>] mdss_mdp_overlay_kickoff+0x9ec/0x15f4
[  256.595453] [<ffffffc00043e098>] __mdss_fb_display_thread+0x278/0x4c4
[  256.595462] [<ffffffc0000beccc>] kthread+0xf0/0xf8
[  256.595468] ---[ end trace 02fd337171f1bd82 ]---
[  256.595498] ------------[ cut here ]------------
[  256.595506] kernel BUG at /home/android/work/prj/6901-7.1/LA.UM.5.6/LINUX/android/kernel/msm-3.18/lib/list_debug.c:40!
[  256.595513] Internal error: Oops - BUG: 0 [#1] PREEMPT SMP
[  256.595519] Modules linked in: wlan(O)
[  256.595533] CPU: 5 PID: 6210 Comm: mdss_fb0 Tainted: G        W  O   3.18.31 #1
[  256.595538] Hardware name: Qualcomm Technologies, Inc. MSM8940-PMI8950 MTP (DT)
[  256.595545] task: ffffffc02f5e6e00 ti: ffffffc002bdc000 task.ti: ffffffc002bdc000
[  256.595553] PC is at __list_add+0xcc/0xf0
[  256.595560] LR is at __list_add+0x74/0xf0
[  256.595567] pc : [<ffffffc000345e2c>] lr : [<ffffffc000345dd4>] pstate: 200001c5
看到红色部分的kernel BUG 我们就知道,这个属于内核主动上报异常的行为,我们看看list_debug.c:40 这里有什么?
如下双链表add实现的红色部分代码,明显就是触发了BUG_ON(x)的条件导致!
void __list_add(struct list_head *new, struct list_head *prev, struct list_head *next)
{
    WARN(next->prev != prev,
        "list_add corruption. next->prev should be "
        "prev (%p), but was %p. (next=%p).\n",
        prev, next->prev, next);
    WARN(prev->next != next,
        "list_add corruption. prev->next should be "
        "next (%p), but was %p. (prev=%p).\n",
        next, prev->next, prev);
    WARN(new == prev || new == next,
         "list_add double add: new=%p, prev=%p, next=%p.\n",
         new, prev, next);

    BUG_ON((prev->next != next || next->prev != prev ||
         new == prev || new == next) && PANIC_CORRUPTION);

    next->prev = new;
    new->next = next;
    new->prev = prev;
    prev->next = new;
}
这个内核双链表标准的插入实现,这个BUG_ON条件满足被触发了Panic所致,表示参数传的有错误。继续看log发现:
[  256.595299] CPU: 5 PID: 6210 Comm: mdss_fb0 Tainted: G        W  O   3.18.31 #1
异常发生在CPU5这个核,进程是mdss_fb0,这个是属于显示相关的进程,一般我们是动不到的,初步判断是别的地方改动埋的雷导致mdss_fb0整个进程在执行的时候炸了的过程。
那么我们要做的就是如何从这个爆炸现场到推出埋雷的地方。
6.2 Trace32分析
打开Trace32,输入 v.f 回车,将call frame内容贴出来:
-000|ipi_cpu_stop(inline)
-000|handle_IPI(ipinr = 3, regs = 0xFFFFFFC0A3BF36E0)
-001|gic_handle_irq(regs = 0xFFFFFFC0A3BF36E0)
-002|el1_irq(asm)
 -->|exception
-003|debug_check_no_obj_freed(address = 0xFFFFFFC028805C00, size = 128)
-004|current_thread_info(inline)
-004|preempt_count(inline)
-004|should_resched(inline)
-004|slab_free(inline)
-004|kfree(x = 0xFFFFFFC028805C00)
-005|ext4_ext_map_blocks(handle = 0x0, inode = 0xFFFFFFC0A3FA8D50, map = 0xFFFFFFC0A3BF3A80, ?)
-006|ext4_map_blocks(handle = 0x0, inode = 0x80, map = 0xFFFFFFC0A3BF3A80, flags = 12)
-007|ext4_get_block(inode = 0xFFFFFFC0A3FA8D50, ?, bh = 0xFFFFFFC0A3BF3AD0, flags = 0)
-008|ext4_get_block(?, ?, ?, ?)
-009|generic_block_bmap(?, ?, ?)
-010|ext4_bmap(mapping = 0xFFFFFFC0A3FA8ED0, block = 12712)
-011|bmap(?, block = 128)
-012|jbd2_journal_bmap(journal = 0xFFFFFFC0A41F3900, ?, retp = 0xFFFFFFC0A3BF3CC0)
-013|jbd2_journal_next_log_block(journal = 0xFFFFFFC0A41F3900, retp = 0xFFFFFFC0A3BF3CC0)
-014|jbd2_journal_commit_transaction(journal = 0xFFFFFFC0A41F3900)
-015|kjournald2(arg = 0xFFFFFFC0A41F3900)
-016|kthread(_create = 0xFFFFFFC0A41E4400)
-017|ret_from_fork(asm)
 ---|end of frame
这个call frame看上去还挺正常的,属于正常的系统异常切换操作?怎么发现跟dmesg里面看到的call statck不对???
我们来看下加载脚本:t32_startup_script.cmm
title "/home/android/share/fp-quick-wakeup/crash/Port_COM29-0813/out"
sys.cpu CORTEXA53
sys.up
data.load.binary /home/android/share/fp-quick-wakeup/crash/Port_COM29-0813/OCIMEM.BIN 0x8600000
data.load.binary /home/android/share/fp-quick-wakeup/crash/Port_COM29-0813/DDRCS0.BIN 0x40000000
data.load.binary /home/android/share/fp-quick-wakeup/crash/Port_COM29-0813/DDRCS1.BIN 0x80000000
Register.Set NS 1
Data.Set SPR:0x30201 %Quad 0x41c22000
Data.Set SPR:0x30202 %Quad 0x00000032B5193519
Data.Set SPR:0x30A20 %Quad 0x000000FF440C0400
Data.Set SPR:0x30A30 %Quad 0x0000000000000000
Data.Set SPR:0x30100 %Quad 0x0000000004C5D93D
Register.Set CPSR 0x3C5
MMU.Delete
MMU.SCAN PT 0xFFFFFF8000000000--0xFFFFFFFFFFFFFFFF
mmu.on
mmu.pt.list 0xffffff8000000000
data.load.elf /home/android/share/fp-quick-wakeup/crash/Port_COM29-0813/vmlinux /nocode
task.config /opt/t32/demo/arm64/kernel/linux/linux-3.x/linux3.t32
menu.reprogram /opt/t32/demo/arm64/kernel/linux/linux-3.x/linux.men
task.dtask
v.v  %ASCII %STRING linux_banner
do /home/android/share/fp-quick-wakeup/crash/Port_COM29-0813/out/core0_regs.cmm
上面可以看到脚本里面配置trace32默认加载的是CPU 0的上下文,而我们从dmesg看到的panic异常是发生在CPU 5,需要手动切换到CPU 5的上下文:
执行:do core1_regs.cmm
(这里有必要需要说明一下,按一般理解应该执行do core5_xx, 但是我发现这样还不对,只能一个个试验了,发现刚好是core1的这个,暂时不知道具体原因)
-000|arch_counter_get_cntvct_cp15()
-001|arch_counter_get_cntvct()
-002|__delay(cycles = 19200)
-003|__const_udelay(?)
-004|msm_trigger_wdog_bite()
-005|do_msm_restart(?, cmd = 0x0)
-006|machine_restart(?)
-007|emergency_restart()
-008|panic(?)
-009|oops_end(inline)
-009|die(?, regs = 0xFFFFFFC002BDF870, err = 0)
-010|arm64_notify_die(?, ?, ?, ?)
-011|do_undefinstr(regs = 0xFFFFFFC002BDF870)  --- 发生未定义指令异常 BUG()
-012|__list_add(new = 0xFFFFFFC002BDF990, prev = 0xFFFFFFC001B77DA8, next = 0xFFFFFFC0AB1D4178)
-013|__internal_add_timer(?, ?)
-014|tbase_get_deferrable(inline)
-014|internal_add_timer(base = 0xFFFFFFC0AB1D4000, timer = 0x0124F800)
-015|spin_unlock_irqrestore(inline)
-015|__mod_timer(inline)
-015|schedule_timeout(?)
-016|mdss_mdp_cmd_wait4pingpong(ctl = 0xFFFFFFC0A791A318, ?)
-017|mdss_mdp_display_wait4pingpong(ctl = 0xFFFFFFC0A791A318, use_lock = FALSE)
-018|mdss_mdp_display_commit(ctl = 0xFFFFFFC0A791A318, ?, commit_cb = 0xFFFFFFC002BDFD38)
-019|mdss_mdp_overlay_kickoff(mfd = 0xFFFFFFC0A7B08360, ?)
-020|__mdss_fb_perform_commit(inline)
-020|__mdss_fb_display_thread(data = 0xFFFFFFC0A7B08360)
-021|kthread(_create = 0xFFFFFFC05ABCE200)
-022|ret_from_fork(asm)
 ---|end of frame
勾选Local、Caller 分析:

双链表的结构有前驱next指针后继prev指针,所以prev->next == next && next->prev == prev,这个条件是必现要成立的,我们来看这里的情况:
-012|__list_add(
    |    new = 0xFFFFFFC002BDF990 -> (
    |      next = 0xFFFFFFC002BDF9C0,
    |      prev = 0xFFFFFFC00010356C),
    |    prev = 0xFFFFFFC001B77DA8 -> (
    |      next = 0xFFFFFFC0ABA4C628,
    |      prev = 0xFFFFFFC0ABA4C628),
    |    next = 0xFFFFFFC0AB1D4178 -> (
    |      next = 0xFFFFFFC001B77DA8,
    |      prev = 0xFFFFFFC001B77DA8))
很显然,prev == next->prev, 但是 prev->netxt != next, 所以导致了上面的BUG_ON(1)异常!.
所以出问题的就是这个prev,我们来看看这个prev具体是什么内容?
前面看过timer的结构知道,这个prev其实就是指向一个struct timer_list *的指针,我们看下这个结构的内容是什么,
调出 view -> Watch 窗口:
(struct timer_list *)0xFFFFFFC001B77DA8 = 0xFFFFFFC001B77DA8 -> (
    entry = (next = 0xFFFFFFC0ABA4C628, prev = 0xFFFFFFC0ABA4C628),
    expires = 4294963038,
    base = 0xFFFFFFC0ABA4C000,
    function_=_0xFFFFFFC00077D4A8,
    data = 0,
    slack = -1,
    start_pid = -1,
    start_site = 0x0,
    start_comm = (0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0))
同上:view -> dump :0xFFFFFFC00077D4A8
address
   NSD:FFFFFFC00077D4A8
address_info
attr: AARCH64
frame:RET:X30 CFA:SP+0x0
line
\\vmlinux\fp_drv     \277--278     /home/android/work/prj/6901-7.1/LA.UM.5.6/LINUX/android/vendor/ti
----------------------------------------------------------------------------------------------------
     P:FFFFFFC00077D4A8--FFFFFFC00077D4AB
function
\\vmlinux\fp_drv\timer_out_handle
...
如此,很清晰的显示了出问题的源码位置,到这里,异常定位分析就已经基本完成了,完成了“追根溯源”,
剩下的就是去分析代码出解决方案了。

版权声明:未经博主允许不得转载,请尊重原创, 谢谢!

相关文章推荐

Trace32 安装 (pc_linux64)

Trace32 属于调试也业内最强大的debug工具了,对于做机的人来说,多掌握一种调试手段意味着关键时候多一条解题的路,对于提升工作效率减轻工作量尤为重要。 下面简单介绍ubuntu14.04下安...

Trace32 加载高通 ramdump

1、高通ramdump解析后有几个重要文件: android@ubuntu:~/tmp/Port_COM6/out$ ls launch_t32.sh t32_config.t32 t32_st...

Yocto tips (7): Yocto Bitbake的clean与cleanall以及cleansstate的区别

Yocto中对于不同的Package,有不同的task,即可以执行不同的操作,有一些是所有包共通的,例如clean,build等。 我们可以使用下面命令来查看一个包都有哪些可执行的task: bi...

高通8937平台手机关机概率卡住问题分析

异常现象: 高通8937平台手机执行开关机压力测试出现概率性无法关机,平均复现概率为1/400次, 问题出现时手机黑屏,看上去像死机,但充电灯在亮着. 分析: 拿到机器发现adb还可以使用,那既...

Clone 新项目TZ导致不开机问题

指纹识别拿到TEE实现之后需要改TA(trust app)内存映射起始地址及增大缓存size, 否则会出现TA load failed 的错误: [ 28.210673] scm_call fai...

导出excle,乱码解决

//传入table的html页面和文件名   public void ExportExcel(string sbExcel, string strFileName)     {       &...

高通 MSM8K bootloader 之四: ramdump

前面说过高通平台,系统crash发生时,抓取crash ramdump非常重要,否则很难定位crash原因。平台默认抓取ramdump的方法都有很强的局限性,如下:1、PC端工具QPST提供的 Mem...

early_suspend 休眠死机

现象: 待机状态下,按Power键或者自动进入休眠,稳定死机. 1、取出db解开获取SYS_MINI_RDUMP, 使用 gdb 调试: android@c0490:~/log/6601/20...

从此使用vim代替si看代码

windows下的开发环境,最好用的看代码写代码工具当然是非source insight莫属了,所以一直以来都是用si写代码,分析代码。 后面转入linux开发环境后一直也是用si(通过wine安装)...

PPP:Calculator用文法实现

文法、calculator、
内容举报
返回顶部
收藏助手
不良信息举报
您举报文章:深度学习:神经网络中的前向传播和反向传播算法推导
举报原因:
原因补充:

(最多只允许输入30个字)