前言
恒玄软件调试和分析基本是通过日志形式分析的,今天就详细说下日志组成和常用分析方法
1.日志组成解析
bes日志组成一般说由以下组成:tick时钟 +模块+log打印所在线程编码+log内容
[17:31:22.834] 21786/NONE / 2 | CPU USAGE: busy=18 light=82 sys_deep=0 chip_deep=0
[17:31:23.089] 22058/M_SBC / 4 | PLC_bad_frame, HEADER_ERROR
[17:31:24.402] 23450/RT_OS / 3 | feed watchdog
比如上面的log 这个没有加设备状态的打印 首先打印的是芯片上电开始的tick时钟 然后是模块单元,后面是执行log的线程编号 最后是log输出的内容。原型是这样的
后续TWS发展 加了设备模块的状态 格式就变成了
tick时钟 +设备状态+日志等级+模块+log打印所在线程编码+log内容
[10:17:22:130] 132744/R-M/I/NONE / 17 | [anc_fadeout_impl] OK
[10:17:22:130] 132744/R-M/I/NONE / 17 | [app_anc_switch_coef] mode_old: 4, mode_new: 1
[10:17:22:130] 132744/R-M/I/NONE / 17 | anc_set_cfg:0x1
[10:17:22:130] 132744/R-M/I/NONE / 17 | anc_set_cfg:iir0_type|iir1_type:0x1
[10:17:22:169] 132745/R-M/I/NONE / 17 | anc_set_cfg_internal: ff_offset_r=0...
[10:17:22:169] 132745/R-M/I/NONE / 17 | ana: set anc adc gain: type=1
[10:17:22:169] 132745/R-M/I/NONE / 17 | anc_set_cfg_internal: ANC_FEEDFORWARD
[10:17:22:169] 132745/R-M/I/NONE / 17 | anc_set_cfg_internal: ANC_FF ch_L...
[10:17:22:169] 132745/R-M/I/NONE / 17 | anc_set_cfg:0x4
[10:17:22:169] 132745/R-M/I/NONE / 17 | [app_anc_reset_gain] type:1, gain_l:0, gain_r:0
[10:17:22:169] 132745/R-M/I/NONE / 17 | anc_set_gain anc_type:2, gain_ch_l:0,gain_ch_r:0
分析:先打印的还是时间轴 +设备(左/右-主/从)+log等级+模块+调用线程编号+log内容
设备块的打印可以通过 宏定义管理“TRACE_GLOBAL_TAG” ,当TRACE_GLOBAL_TAG =1 log的输出形式就是上图的形式了
1.1 tick
-----体现芯片上电运行时间 下面的log如果不借助电脑时间轴打印请问时间差是多少呢 ?答案是大约2.14s
现在我们看下电脑的结果 是不是完全匹配的
所以 从tick的分析 可以看到log是否连续 (复位重启会重置)是否丢失log,在没有电脑时间的时候也能初略判断事件发生的时间差(计算方式(tick1-tick1)/1000)
1.2. 设备状态
----- 这个是TWS 耳机区分日志引入的打印变量
U--未知 状态 L--左 R--右 M--主 S--从
1.3.日志等级
---- 'C', 'E', 'W', 'N', 'I', 'D', 'V', '-' 对应
1.4.模块
-----这个部分的组成比较灵活 一般是根据功能块划分的
比如我自己写的一个mic声音幅度判断函数里面加个打印 这样的话我只要搜索MUTE_C 全部的信息就都出来了 其实就是为了方便查找
TR_INFO(TR_MOD(MUTE_C), "agv:%d,residual:%d #least:", app_interphone_mute_frame_dat.val_frame_agv,
app_interphone_mute_frame_dat.enery_diff_residual);
DUMP32("%d ", app_interphone_mute_frame_dat.enery_measure, PCM_AUDIO_CNT);
打印运行结果:
121092/MUTE_C/4/ agv:1843,residual:2828265 #least:193875 282826 316619 261641 353510
1.5 打印线程
----这个通常用来查询SDK 或者其他人代码用的 比如封装库了 或者你不知道源码的情况下 大概能推测log出现的位置
比如上图出现的 log PLC_bad_frame 属于线程ID 为4打印发出 feed watchdog 属于线程ID3 发出
下面从log截图追溯下打印的线程验证是否匹配
从代码查阅 确实是属于 audio_flinger 线程执行的处理
这个打印需要修改下代码 在RTOS 底层文件 把函数替换下以下代码即可
static void _rtx_show_thread_usage(const os_thread_t *thread, uint32_t sample_time)
{if (thread) {if (thread->thread_addr && thread->stack_mem) {uint32_t min_free_stack_sz = rtx_thread_get_stack_space(thread);REL_TRACE_NOTS(4,"---Thread name=%s id:%d cpu=%d min-free-stack=%d",thread->name==NULL ? "null" : (char *)thread->name,thread->id,sample_time != 0 ? ((thread->rtime - thread->step_rtime) * 100 / sample_time) : 0,min_free_stack_sz);print_thread_sw_statitics(thread);((os_thread_t *)thread)->step_rtime = thread->rtime;} else {REL_TRACE_NOTS(0,"--- Thread BAD");}} else {REL_TRACE_NOTS(0,"--- Thread NONE");}
}
2.log源代码分析:
2.1 通常情况下为了方便都是用的 "TRACE",翻译的中文为“跟踪/追溯”
比ru
TRACE(3,"app_interphone_captrue_audio work:%d op:%d freq:26M", captrue_isRun, on);
为了区分模块 统一处理 可以加一些自定义字符 :
值得注意的是需要在 hal_trace_mod.h里面添加 要不然会编译出错
简而言之 log是一个分析工具 尽量做到规范和便捷 就好
2.2 代码分析常规 log打印流程
----- 最后的log都是通过这个函数执行的 因为不同线程可能存在打印log 所以有一个list缓存 打印也是单线执行的
除log本身之外的 tick+设备状态+模块+优先级+线程ID 这些其实都在这函数处理的 "hal_trace_print_time"
2.3 非常规的一些log打印
----- 这些包含了dump 的数据 或者死机日志打印接口
dump其实就是转化为数据输出 不会包含上面介绍的前半轴 比如常见的HCI log
死机日志分为两种 但是最后都会走“hal_trace_crash_end” 这个函数
2.3.1 ---hal_trace_fault_handler 空指针 总线执行错误 堆栈溢出等
2.3.1 ---hal_trace_assert_dump 非法数据 或者操作设置强制死机
死机后可以设置为快速重启
详细的死机原因分析其实代码里面也比较明确 “hal_trace_print_fault_info_cm”
3.死机日志追寻
3.1 arm寄存器
Cortex-A处理器的寄存器结构,包括40个32位寄存器中的通用寄存器、状态寄存器如CPSR和SPSR,以及堆栈指针R13、链接寄存器R14和程序寄存器R15.(不是很理解的请百度下冯诺依曼架构)
通用寄存器 R0~R7
-
R0-R3一般作为参数传递,如果参数再多,则通过压栈的方式传递
-
R0、R1还会作为返回值进行传递,如果是32位则是R0,64位则会用R0-R1
-
通用目的寄存器R8-R12
,高组寄存器,32bit,较少的16位thumb指令可以访问,一般是 thumb-2指令访问。
-
R11一般用作FP指针,保存栈帧
-
R12 临时寄存器
寄存器 | 描述 |
---|---|
未分组寄存器 | R0-R7 |
分组寄存器 | R8-R14 |
程序寄存器PC | R15 |
程序状态保存寄存器 | SPSR |
堆栈指针R13(SP)
链接寄存器R14(LR)
程序寄存器R15(PC)
CPSR 当前程序状态寄存器
可以在任何运行模式下被访问
SPSR 备份的程序状态寄存器
当异常发生时,SPSR用于保存CPSR的当前值,从异常退出时则可由SPSR来恢复CPSR
3.2 分析文件
---- list 文件 或者 elf文件
elf 文件会直接在编译工程文件生成
list 由代码编译后加 lst 生成 如:
lst直接在lst文件里面找相应的执行处理函数
如下面的死机log
elf 则借助wsl 工具 输入 "arm-none-eabi-addr2line -apsfCe xx.elf 指针地址 1 2 3 4"
从而找到或者推测出死机的函数和执行处
上面的死机打印IPSR =000 说明不是中断函数 PC是当前指针地址 为 00200DA8
在bes 地址中 :C开头的是flash地址 2开头是 内存地址 说明是内存地址访问错误导致的死机
4.常用log相关宏定义
CRASH_REBOOT 用于死机重启 需要关闭 CORE_DUMP CONTROLLER_DUMP_ENABLE
TRACE_GLOBAL_TAG 设备定义管理
TRACE_BUF_SIZE log缓冲区大小 出现 “loss”时候可能就是缓存不足
TRACE_BAUD_RATE log串口输出波特率
TRACE_PRINTF_LEN 单帧打印长度 默认120 如果出现打印不完整 可能就是长度不够,需要注意的是 hal_trace.c 和hal_uart.c 里面都要改
5. 总结
log作为一个分析工具 能够精准分析和熟练使用是 学习bes 平台必不可少的 只有多练习和实践才能更快的定位问题 解决问题
今天的解说就到这里 有啥不到之处 敬请指出 谢谢 !