BES（恒玄）平台log分析

前言 

    恒玄软件调试和分析基本是通过日志形式分析的，今天就详细说下日志组成和常用分析方法

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字符或函数

4.1 常用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 里面都要改

4.2常用GCC内置嵌套函数

TRACE(2,"app_bt_scan_mgr:set_access_mode=%d, LR=%p", mode, __builtin_return_address(0));
/*打印当前函数的第n级调用者的地址，用的最多的就是__builtin_return_address(0)，即获得当前函数的调用者的地址。注意，该函数实现是体系结构相关的，有些体系结构只实现了n=0的返回结果*/

TRACE(2,"[%s] ,%d", __func__,__LINE__); /*打印当前所在函数名字和行数*/

TRACE(2，"app_audio_free_size:%ld\n",__builtin_object_size(heap_buff,0));/*
返回ptr所指向的内存区域的大小，type影响整个函数的行为，最低两位：
*/
struct V { char buf1[10]; int b; char buf2[10]; } var;
char *p = &var.buf1[1], *q = &var.b;

/* Here the object p points to is var.  */
assert (__builtin_object_size (p, 0) == sizeof (var) - 1);
/* The subobject p points to is var.buf1.  */
assert (__builtin_object_size (p, 1) == sizeof (var.buf1) - 1)

4.3 assert 函数

     ----上文有说到这个用于人为制造死机，检测函数运行情况 比如：在A2DP stream 初始化发生了变异 传递了非法解码类型

5. 总结 

log作为一个分析工具  能够精准分析和熟练使用是 学习bes 平台必不可少的 只有多练习和实践才能更快的定位问题 解决问题 

   今天的解说就到这里 有啥不到之处 敬请指出 谢谢 ！