死机分析之二---如何分析死机原因
实际上,死机日志能给我们提供非常多的信息,分析一个死机问题通常需要综合多方面的信息,下面是分类介绍的,但是实际上是要综合所有信息来做分析。本次分析的日志基于本人文章xxxx 里的构建。本篇文章基于我之前遇到的死机问题进行讲解,会比较长,本文基于STM32+FreeRTOS进行分析。基本来自于本人开源项目 https://gitee.com/cyytx/intelligent_lock
根据死机时跳到的中断函数做初步判断
进入不同中断函数,代表着不同的死机原因,通过在日志里记录属于属于哪个中断可以做初步判断。比如下面,我就知道是软件看门狗超时导致的死机。至于是什么原因,还得看后续分析。
TIM7_IRQHandler, WATCHDOG TIMEOUT DETECTED!
EXC_RETURN = 0xFFFFFFFD
Stack used: PSP
=== Current tick: 14132 ===
=== SP addr: 0x2002F618 ===
根据LR PC定位死机时的代码位置
首先要搞清楚PC,LR所对应的代码或函数,需要先生成反汇编文件,这里我使用的是keil armclang编译器,所以下面以它为例子说明,当然如果是GCC等编译器道理也是一样,GCC 的addr2line 指令更加好用,直接指出所在代码行。
生成反汇编文件
一种自动化的方法是在keil 里面设置在编译链接完成后自动触发指令生成反汇编文件,如下图,在keil的Options for Target >User 里面可看到配置After Build/Rebuild 里面,支持输入用户的命令。在构建完成之后自动执行,这里我输入了如下指令,它就会在构建成功后执行我的命令
"C:\Program Files\keil_v5\ARM\ARMCLANG\bin\fromelf.exe" --text -c -a -d --interleave=source --output="$L@L.dis" "#L"

如图,配置之后在编译链接后,就会执行我们输入的After Build 命令

如图就生成了。

当然手动也是一样的 在 smart_lock.axf文件的目录下输入下面指令即可,当然fromelf.exe要换成自己的地址,另外值得注意的是,&这个符号需要有,& 是PowerShell中的调用操作符(Call Operator),用于执行命令、脚本或表达式。当可执行文件的路径包含空格时,PowerShell需要 & 来正确识别这是一个要执行的命令
& "C:/Program Files/keil_v5/ARM/ARMCLANG/bin/fromelf.exe" --text -c -a -d --interleave=source -o disassembly.txt smart_lock.axf

查找PC LR 对应代码
另外有一点值得非常注意点是,你会发现一个问题,就是LR是奇数,在汇编文件也不到这个地址 ,这个就比较奇怪,因为我们知道Flash的起始地址值0x08000000,而cortex-m 的thumb-2 指令占2/4 字节,所以指令地址只可能是偶数而不可能奇数。其实这是个历史遗留问题,在早起的ARM7/9架构时期,存在两种指令集,thumb和ARM 指令集,thumb 指令集固定16bit 而ARM指令集固定是32bit.它们都是2大倍数,所以地址都最低位永远是0,干脆就将它来用作分辨是thumb还是ARM指令作用,所以LR的最后一位是用来标志返回时使用thumb还是ARM指令集,不过现在的的cortex-m是属于ARMV7_M 已经是全部使用了thumb指令集了,所以它其实是没啥用的,然后我们也知道最后一位其实不属于地址,所以应该用它来减1后才是真实的地址。,当然PC不用减1
LR = 0x0803FC1B //最后一位是B 也就是11,是奇数
PC = 0x0806BC6C
所以我们将LR减1在反汇编文件搜索可以找到它,向上追溯知道它属于一个叫lv_event_send的函数

同理搜索 PC 可知它属于 wait_for_flushing

如果大家生成反汇编文件,可能会和我一样遇到一个这样的问题,就是在反汇编文件有些汇编能精确到具体的代码行,有些只能精确到函数,我也做了许多尝试,包括反汇编时的–interleave=source参数 以及keil 设置里面的Misc Controls 添加 -g 参数生成最完整的debug tables信息,但是无法做到像在keil里面进行debug时,cisassembly 基本都能精确到代码行,所以无奈之下,如果要精确到具体的代码行,可以选中调试模拟器,之后点debug,搜索通过反汇编文件找到的函数,如上面的wait_for_flushing,再往下一找就能够找到具体的代码行了,另外如果是用GCC编译,他的 addr2line 指令更加好用,主要还是看自己的编译环境选择工具。


分析死机前最后的任务调度顺序,时间和栈地址做分析
比如下面的消息其实非常可以提供非常多的消息,
1、首先死机时的栈地址是 0x2002F618,而通过下面的所有栈道信息可以看到不同任务的栈道范围,所以可以确定到栈地址属LVGL_Task ,
2、从最后时间的任务调度信息也可以看到,最后一次切换到的是任务15,也就是 LVGL_Task 这样可以交叉验证确实问题出在LVGL_Task执行期间
3、从时间看,死机时间是14132,最后调度是10004有4秒没有调度,一直在LVGL_Task里面,并且从最早点时间看为4383,到死机14132接近10s没有看到有IDLE task的身影,我的软件看门狗刚好是在IDLE task 喂狗的,所以基本可以判断死机原因是LVGL_Task一直霸占着MCU导致IDLE task 没有机会执行导致的的看门狗超时。
EXC_RETURN = 0xFFFFFFFD //从它其实可以知道是MSP还是psp,和下面一句做个确认。
Stack used: PSP //从它可以得知 是在任务执行过程出的问题还是在中断或者main里出的问题
=== Current tick: 14132 === //可以和任务调度历史的时间对比,确定任务死机前的调度间隔。
=== SP addr: 0x2002F618 === //它可以用来确定属于哪个任务
=== Last Task Switch History === //最后时刻的调度历史
Task Number | Timestamp
------------|----------
14 | 4383
5 | 4384
14 | 4384
15 | 4386
14 | 4386
15 | 4388
14 | 4388
15 | 4389
14 | 4390
15 | 4397
14 | 4398
15 | 4399
14 | 4399
15 | 4407
3 | 10004
15 | 10004 //可以看到出问题时的任务和调度时间
=== Last Recorded All Task Information ===
[D:14132] TaskName ID Status Prio(C/B) StackStart MaxUsed StackEnd PeakUsage(%)
[D:14132] ---------------- -- ------ --------- ---------- ---------- ---------- ------------
[D:14132] MainTask 1 R 40/40 0x200252e0 2204 0x200262dc 53.86%
[D:14132] IDLE 2 r 0/ 0 0x20000264 56 0x20000464 10.94%
[D:14132] Tmr Svc 3 B 27/27 0x20000b0c 248 0x20000f0c 24.22%
[D:14132] app_task 4 B 29/29 0x200263f8 364 0x20026bf4 17.81%
[D:14132] DisplayTask 5 r 19/19 0x20026d38 168 0x20027534 8.22%
[D:14132] camera_task 6 B 20/20 0x20027610 268 0x20027e0c 13.11%
[D:14132] keyboardTask 7 S 28/28 0x20027e80 112 0x2002867c 5.48%
[D:14132] ledTask 8 B 1/ 1 0x200286f0 80 0x200288ec 15.75%
[D:14132] lock_ctrl_task 9 B 30/30 0x200289c0 292 0x20028dbc 28.63%
[D:14132] FP_Task 10 B 25/25 0x20028ee8 340 0x200296e4 16.63%
[D:14132] NfcTask 11 B 14/14 0x20029790 480 0x20029b8c 47.06%
[D:14132] BLE_Task 12 B 23/23 0x20029e10 192 0x2002a20c 18.82%
[D:14132] FaceTask 13 B 23/23 0x2002a338 356 0x2002b334 8.70%
[D:14132] swdraw 14 r 3/ 3 0x2002b5e8 40 0x2002d5e4 0.49%
[D:14132] LVGL_Task 15 r 18/18 0x2002d770 40 0x2002f76c 0.49%
[E:14132] ----------------------------------------------------------------------------------------
上面的所有log 其实是我之前遇到的一次死机的log的复现,当时我是做LVGL 移植到我的项目,后来发现一上来就出现看门狗死机,查到PC指向的地方就是while(disp->flushing); 后来一查是因为LVGL像素输出到LCD 后要等待显示成功后的回复,我当时记得是有回复的。后来发现确实是因为没回复导致的,原因也很奇葩,就是当时用DMA发送像素到LCD ,但是因为DMA一次最大的buffer是65536,而我一次输出的可能是全屏,不止65536,所以要分包发送,发送最后一包时就给一个标志位置位,代表是最后一包了,这样在DMA的发送完成中断里面就可以给LVGL发消息说显示完成,结果奇葩在哪里呢,我当时有部分代码是让AI写的,结果他在我的发送函数里面给我生成了一个局部变量和我的标志位全局变量名称一样,导致我设置的标志位以为是全局的,在中断能够搜到,结果是局部的,所以没起作用,所以同志们,使用AI是还是要review清楚呀。
static void wait_for_flushing(lv_display_t * disp)
{
..........
while(disp->flushing); //卡在这里
..........
根据屏蔽寄存器分析问题
有些时候可能会因为一些长时间的中断或故障屏蔽,导致了死机问题。
BASEPRI :Base Priority Mask Register(基本优先级屏蔽寄存器), 用于屏蔽优先级低于指定阈值的所有中断,实现优先级过滤
PRIMASK : Primary Interrupt Mask Register(主中断屏蔽寄存器),用于屏蔽所有可配置中断和异常,只允许 NMI 和 HardFault 发生。
FAULTMASK: Fault Mask Register(故障屏蔽寄存器),用于将处理器优先级提升到 HardFault 级别,屏蔽所有可屏蔽异常,只允许 NMI 发生 。
下面是有一次我做架构调整时出现的问题,一执行就死机了,日志如下。日志其实可以看出非常多的信息和问题,我都写在了下面的日志中了。
TIM7_IRQHandler, WATCHDOG TIMEOUT DETECTED! //看门狗超时,说明至少10s时间没有喂狗
EXC_RETURN = 0xFFFFFFE9
Stack used: MSP //MSP 说明不是在任务中出问题,是在MAIN 或是中断
=== Current tick: 0 === //tick 为0 说明操作系统没有启动
=== SP addr: 0x20034F20 === //SP 地址可通过找 map 文件中找到主栈的地址范围0x20034020~0x20035020没有溢出
=== Full Exception Stack Frame ===
R0 = 0x00000001
R1 = 0x00000033
R2 = 0x00000000
R3 = 0x00000000
R4 = 0x00000000
R5 = 0x00000000
R6 = 0x00000000
R7 = 0xFFFFFFE9
R8 = 0x000000AA
R9 = 0x20034F00
R10 = 0x00000000
R11 = 0x0800ECBF
R12 = 0x00000010
LR = 0x080048EB //可以找出出问题的返回地址 在 HAL_Delay
PC = 0x080048EA //可以找出出问题的地址 在 HAL_Delay 说明这个死机死在中断时
PSR = 0x81000000
=== System Control Registers ===
CONTROL = 0x00000000
BASEPRI = 0x00000050 //有中断屏蔽,---------这个需要注意
PRIMASK = 0x00000000
FAULTMASK = 0x00000000
=== Fault Status Info ===
CFSR = 0x00000000
HFSR = 0x00000000
DFSR = 0x00000000
AFSR = 0x00000000
MMFAR = 0x00000000
BFAR = 0x00000000
=== Last Task Switch History === //系统还没启动,都是0
Task Number | Timestamp
------------|----------
0 | 0
0 | 0
0 | 0
0 | 0
0 | 0
0 | 0
0 | 0
0 | 0
0 | 0
0 | 0
0 | 0
0 | 0
0 | 0
0 | 0
0 | 0
0 | 0
=== Last Recorded All Task Information ===
[D:0] TaskName ID Status Prio(C/B) StackStart MaxUsed StackEnd PeakUsage(%)
[D:0] ---------------- -- ------ --------- ---------- ---------- ---------- ------------
[E:0] ----------------------------------------------------------------------------------------
System will reset in 5 seconds...
我在上面日志其实有两个地方特别注意的,
1、是 LR = 0x080048EB ,PC = 0x080048EA LR减去thumb bit 实际上PC地址一样 ,这个就比较奇怪,怎么会一样呢我当时很诧异,后来仔细看原来是死在循环的地方,并且这个循环里刚好有个函数调用,所以LR 和PC地址就一样了,这个也说明死机时实际是在 HAL_Delay 的这个循环里。我在实际调试时经过删减代码及加日志等方法确认HAL_Delay 确实是直接到触发因素

2、 BASEPRI = 0x00000050 这个意思对中断进行0x50的屏蔽,低于0X50的优先级会被屏蔽。

这个0X50代表的意义实际上要根据不同芯片的最大支持优先级的数量来分析,不同芯片的支持的最大优先级数量是不同的,范围在8~256之间,占用的位数是3~8bit 且实际用的位为高位,比如支持优先级为16 占用4个bit,则使用高四位,低四位不使用,我是用的是cotex-m7, 查询架构手册《Arm®v7-M Architecture
Reference Manual》的B1.5.4 Exception priorities and preemption 可以看到如下描述。

所以我需要查询我使用的具体的芯片手册才知道我有几个优先级,以及屏蔽的是什么优先级,我项目中使用的是STM32F767,所以查询我的芯片手册的NVIC一章可以看到如下内容,也就是我的芯片支持16级优先级,使用的是高4位

有此可知 BASEPRI = 0x00000050 代表的意思就是0X50中的低四位是没有到,代表实际意义的是0x5,就是5,意思是低于5的优先级会屏蔽,而我HAL_Delay 靠systick 中断驱动的,**它的优先级为最低优先级15它低于优先级5 所以会屏蔽掉systick 中断导致了 一直卡在HAL_Delay **
到此为止其实死机的直接原因已经知道了,究竟是谁在什么条件下屏蔽了低于5的优先级,其实并不容易找到原因,这个也是死机问题难以解决的一个原因,庆幸的我这个还是必现问题,如果是低概率死机问题那才是不好解决,后来找到原因说实话和我的个人的探索和经验有关,我发现该段代码在main 里执行就有问题,在main_task 就没问题,并且通过查找BASEPRI关键字 发现在FreeRTOS 进入临界区时会屏蔽中断,恰好是优先级5
/* The highest interrupt priority that can be used by any interrupt service
routine that makes calls to interrupt safe FreeRTOS API functions. DO NOT CALL
INTERRUPT SAFE FREERTOS API FUNCTIONS FROM ANY INTERRUPT THAT HAS A HIGHER
PRIORITY THAN THIS! (higher priorities are lower numeric values. */
#define configLIBRARY_MAX_SYSCALL_INTERRUPT_PRIORITY 5
后来经过一番探寻才发现,我当时在使用上有个错误,我当时做架构整改,把一个个模块的驱动初始和服务初始打包在一个类似于lcd_module_init的函数里面,并在main里调用,但是其实这里有个问题,就是在service 初始化会创建任务,之后我又初始化别的模块,驱动初始化可能需要用到HAY_Delay 。后来发现实际上创建任务时会进入临界区会屏蔽中断,之后会退出临界区,但实际上退出临界区有个条件,就是如果是嵌套进入临界区,则需要所有嵌套退出才退出临界区也就是uxCriticalNesting == 0 才退出。但是实际上它的初始化是0xaaaaaaaa ,在任务开始调度时才清0,所有我的错误是在系统没有开始调度前,使用了创建任务接口,屏蔽了中断,后续又使用了 HAL_Delay 但因为中断被屏蔽导致了卡在HAL_Delay,最终导致看门狗超时
static UBaseType_t uxCriticalNesting = 0xaaaaaaaa;
使用错误寄存器分析问题
错误寄存器也是分析死机问题对一大助力,比如程序跑飞,跑到一个不是存储代码的地方,读出的指令无法识别会触发错误,比如往NULL地址写数据,比如除O操作等。下面以我遇到的一个例子作为分析,通常分析过程是查找对应寄存器的值所代表意义,之后以此进一步分析,另外死机日志我只列出重点的,否则太长了,分析我也卸载注释里。
MemManage // 内存管理类错误,触发MemManage_Handler
EXC_RETURN = 0xFFFFFFFD
Stack used: PSP
=== Current tick: 227 ===
=== SP addr: 0x200261F8 ===
................省略.................
LR = 0x080189AF // 分析对应代码地址为 bsp_camera_if.c (288) ,Function: bsp_camera_dcmi_capture_init
PC = 0x0801C6E0 //分析对应代码为 bsp_camera_if.c (158) ,Function: dcmi_dma_init
PSR = 0x61000000
.................... 省略...............
=== Fault Status Info ===
CFSR = 0x00000082 // 错误寄存器有值
HFSR = 0x00000000
DFSR = 0x00000000
AFSR = 0x00000000
MMFAR = 0x00000000
BFAR = 0x00000000
分析错误寄存器值代表意义
首先 CFSR的值为 0x00000082 最小的字节有值,也就是MMFSR有值,首先要阅读内核文档,查看《Arm Cortex-M7 Devices Generic User Guide》的4.3.10 Configurable Fault Status Register 一章寄存器值的具体意义


对它的分析如下,首先分析具体的位所代表的值,可以看到问题原因是因为读写某个地址的数据导致问题,并且访问的地址是保存在MMFAR地址
MMFSR = 0x82 = 1000 0010 (二进制)
├─ Bit 7 (MMARVALID) = 1 ← MMFAR寄存器包含有效的故障地址
├─ Bit 1 (DACCVIOL) = 1 ← 数据访问违规!
下面为寄存器对应位的原文解释。


那么我们从 log 中找到的值为 0x00000000,这个代表程序访问了一个NULL地址 ,这个时候回到PC所指向地址看看为什么会出问题。
MMFAR = 0x00000000 //访问的地址为 0x0 其实就是NULL地址
PC = 0x0801C6E0 //分析对应代码为 bsp_camera_if.c (158) ,Function: dcmi_dma_init
查找到 bsp_camera_if.c (158) 可以看到出问题的是下面的__HAL_DMA_DISABLE_IT(&dcmi_dma_handler,DMA_IT_TC);

这句话怎么就访问了空地址了呢,__HAL_DMA_DISABLE_IT 是个宏,先把它展开
__HAL_DMA_DISABLE_IT(&dcmi_dma_handler,DMA_IT_TC);
//宏原型
#define __HAL_DMA_DISABLE_IT(__HANDLE__, __INTERRUPT__) (((__INTERRUPT__) != DMA_IT_FE)? \
((__HANDLE__)->Instance->CR &= ~(__INTERRUPT__)) : ((__HANDLE__)->Instance->FCR &= ~(__INTERRUPT__)))
//实际展开可得
dcmi_dma_handler.Instance->CR &= ~(DMA_IT_TC); //也就是说这一句有问题,问题原因是范围了OX0 地址,那么也就是dcmi_dma_handler.Instance->CR 这是是空地址?
最后仔细分析,发现是空地址,原因是调用顺序错了,在__HAL_DMA_DISABLE_IT(&dcmi_dma_handler,DMA_IT_TC); 实际调用的是dcmi_dma_handler.Instance->CR 而我当时dcmi_dma_handler是有效地址,但是它的成员Instance 这时还没赋值,所以是0X0,也就是NULL 地址
dcmi_dma_handler.Instance=DMA2_Stream1; //先给Instance成员赋值
__HAL_DMA_DISABLE_IT(&dcmi_dma_handler,DMA_IT_TC); //随后再调用宏
结语
死机问题除了上面的信息外,还需要结合程序本身日常的日志,特别是低概率情景更时要结合测试人员的测试手法,情景,常规日志,死机日志,捋清逻辑,添加辅助日志,大量测试寻找复现方法等等,是不容易处理的问题。我上面的例子都是一些简单的例子。还需要不断学习,与君共勉。