利用 Guru Meditation 错误打印定位问题

[English]

目前可先参考 ESP-IDF 编程指南里的 Guru Meditation 错误 来了解常见的错误及对应的原因。此文档包含常见错误的进一步说明及展示一些可行的分析思路。

备注

以下主要以 ESP32-C3 所代表的 RISC-V 架构出现的错误进行分析,ESP32 等 Xtensa 架构对应的错误在命名上会有区别,但错误本质相同,某种架构的一些专属错误会单独分析。

Guru Meditation 错误分为两种类型: ARCH 异常和 SOC 异常。

ARCH 常见异常主要包含以下类型:

  • Load access fault

  • Store Access Fault

  • Instruction Access Fault

  • IllegalInstruction

SOC 常见异常主要包含以下类型:

  • Interrupt wdt timeout on CPU0/CPU1

  • Cache disable but cached memory region accessed

很多时候,Guru Meditation 错误并不能很快的确定原因,因为这些 Guru Meditation crash 只是表象,实际问题会和 FreeRTOS,memory, flash, interrupt 等模块相关,需要具体问题具体分析。

Load access fault(LoadProhibited)

测试用例

使用加载指令(如 lw )加载无效的内存就会发生此类异常。触发此类 crash 的示例代码如下:

uint8_t *buff = NULL;
load_fault = buff[1];

异常现象

  • RISC-V

Guru Meditation Error: Core  0 panic'ed (Load access fault). Exception was unhandled.

Core  0 register dump:
Stack dump detected
MEPC    : 0x4200696a  RA      : 0x4200696a  SP      : 0x3fc8f7c0  GP      : 0x3fc8b400
TP      : 0x3fc87d74  T0      : 0x4005890e  T1      : 0x3fc8f41c  T2      : 0x00000000
S0/FP   : 0x3c023000  S1      : 0x00000000  A0      : 0x0000000f  A1      : 0x3fc8f3f8
A2      : 0x00000000  A3      : 0x00000001  A4      : 0x3fc8c000  A5      : 0x00000000
A6      : 0x60023000  A7      : 0x0000000a  S2      : 0x00000000  S3      : 0x00000000
S4      : 0x00000000  S5      : 0x00000000  S6      : 0x00000000  S7      : 0x00000000
S8      : 0x00000000  S9      : 0x00000000  S10     : 0x00000000  S11     : 0x00000000
T3      : 0x00000000  T4      : 0x00000000  T5      : 0x00000000  T6      : 0x00000000
MSTATUS : 0x00001881  MTVEC   : 0x40380001  MCAUSE  : 0x00000005  MTVAL   : 0x00000001
  • XTENSA

Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x42007c2f  PS      : 0x00060a30  A0      : 0x82007c42  A1      : 0x3fc97d70
A2      : 0x42011934  A3      : 0x3c023f48  A4      : 0x3c023fc8  A5      : 0x3fc97d90
A6      : 0x3fc97d70  A7      : 0x0000000c  A8      : 0x00000000  A9      : 0x3fc97d20
A10     : 0x0000000f  A11     : 0x3fc97fac  A12     : 0x3fc97d70  A13     : 0x0000000c
A14     : 0x3fc941e4  A15     : 0x00000000  SAR     : 0x00000004  EXCCAUSE: 0x0000001c

Backtrace: 0x42007c2c:0x3fc97d70 0x42007c3f:0x3fc97d90 0x42019247:0x3fc97db0 0x40379e71:0x3fc97de0

定位方法

如果此时进一步分析汇编代码(步骤可参考 附录 1 - ESP 反汇编对应的指令),可以发现能对应到以下指令:

lw a1, 1(zero)               // RSIC-V
l8ui    a11, a8, 1           // XTENSA

在触发此类异常时,MTVAL/EXCVADDR 会自动更新为与异常有关的数据,从 RISC-V 异常信息中可以看到 MTVAL : 0x00000001

一般来说 MTVAL 为 NULL(0x00000000) 代表的是从 NULL 地址取值,而接近 NULL 代表的是尝试从 NULL 地址访问某个数组或者结构体的成员。

  • 对于 RSIC-V 架构来说,PC 和 RA 寄存器包含了异常的函数指针,从 elf 中找出对应的函数排查即可

  • 对于 Xtensa 架构来说,异常时会打印 backtrace,从 elf 中也可以找出对应的函数

实际案例

下图是一个典型的 ESP32-C3 Load access fault 问题。

../../../_images/load_access_fault.png

从上图可以看出,出问题的地方在于 lw a5, 20(s0)s0 是 0x0, 这对应了一个 NULL 指针,此时可以继续分析前一句汇编 lw s0, 24(sp),对应的代码段为 pxTimer = xMessage.u.xTimerParameters.pxTimer;,此时问题可变成 pxTimer 为什么为 NULL。

通过添加如下调试日志来进一步定位问题:

if (pxTimer == NULL) {
    ets_printf("xMessageID: %d\n", xMessage.xMessageID);
}

最终发现问题在于并未成功创建 timer ,此时 timer 对应的指针为 NULL,此时再执行后续 timer 操作就会因空指针导致此 Load access fault(LoadProhibited) 错误。

gtimer_null

注意事项

并不是所有的 Load access fault(LoadProhibited)问题都可以简单通过上述方法确定出问题的位置,如下图所示:

load_fault_2

PC 地址指向了 ROM 函数 rom_i2c_writeReg_mask函数, 而且 Backtrace 没有足够的有效信息,这种情况下,一般需要能够稳定复现来排查,如果此问题本身很难复现,那么可能是硬件或者野指针问题导致的。

Store access fault(StoreProhibited)

测试用例

当应用程序尝试在无效的内存位置进行写入操作时,会发生此类 CPU 异常,测试代码如下所示:

typedef struct {
    uint8_t buf[10];
    uint8_t data;
} store_test_t;

void store_access_fault(store_test_t * store_test)
{
    store_test->data = 0x5F;
    printf("Data: %d\n", store_test->data);
}
void app_main(void)
{
    store_test_t * store_test = NULL;
    store_access_fault(store_test);
}

异常现象

  • RISC-V

在 RISC-V 架构的芯片中,可以看到如下异常的打印,通过观察汇编指令(步骤可参考 附录 1 - ESP 反汇编对应的指令)可发现出现这种异常时 PC 地址都指向了 sb/sw 等 store 相关指令。此时 MTVAL 存储的异常值 0x0000000a 说明想要访问的是 NULL 地址开始的某个数组或者结构体里的内容。

Guru Meditation Error: Core  0 panic'ed (Store access fault). Exception was unhandled.

Core  0 register dump:
Stack dump detected
MEPC    : 0x42006960  RA      : 0x42006984  SP      : 0x3fc8f7c0  GP      : 0x3fc8b400
TP      : 0x3fc87d7c  T0      : 0x4005890e  T1      : 0x20000000  T2      : 0x00000000
S0/FP   : 0x3c023000  S1      : 0x00000000  A0      : 0x00000000  A1      : 0x3fc8f3f8
A2      : 0x00000000  A3      : 0x00000001  A4      : 0x3fc8c000  A5      : 0x0000005f
A6      : 0x60023000  A7      : 0x0000000a  S2      : 0x00000000  S3      : 0x00000000
S4      : 0x00000000  S5      : 0x00000000  S6      : 0x00000000  S7      : 0x00000000
S8      : 0x00000000  S9      : 0x00000000  S10     : 0x00000000  S11     : 0x00000000
T3      : 0x00000000  T4      : 0x00000000  T5      : 0x00000000  T6      : 0x00000000
MSTATUS : 0x00001881  MTVEC   : 0x40380001  MCAUSE  : 0x00000007  MTVAL   : 0x0000000a
  • XTENSA

在 XTENSA 架构的芯片中,可以看到下列异常打印,通过观察汇编指令(步骤可参考 附录 1 - ESP 反汇编对应的指令)可发现出现这种异常时 PC 地址都指向了 s8i/s32i 等 store 相关的指令。此时 EXCVADDR 存储的异常值 0x0000000a 说明想要访问的是 NULL 地址开始的某个数组或者结构体里的内容。

Guru Meditation Error: Core  0 panic'ed (StoreProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x42007c21  PS      : 0x00060630  A0      : 0x82007c38  A1      : 0x3fc97d70
A2      : 0x00000000  A3      : 0x3c023f48  A4      : 0x3c023fc8  A5      : 0x3fc97d90
A6      : 0x3fc97d70  A7      : 0x0000000c  A8      : 0x0000005f  A9      : 0x3fc97d00
A10     : 0x00000031  A11     : 0x3fc97fac  A12     : 0x3fc97d70  A13     : 0x0000000c
A14     : 0x3fc941e4  A15     : 0x00000000  SAR     : 0x00000004  EXCCAUSE: 0x0000001d
EXCVADDR: 0x0000000a  LBEG    : 0x400556d5  LEND    : 0x400556e5  LCOUNT  : 0xfffffffd

Backtrace: 0x42007c1e:0x3fc97d70 0x42007c35:0x3fc97d90 0x4201923f:0x3fc97db0 0x40379e71:0x3fc97de0

定位方法

定位方法与 Load access fault(LoadProhibited) 类似,如果此时观察汇编代码(步骤可参考 附录 1 - ESP 反汇编对应的指令)会看到如下指令:

sb      a5,10(a0)             // RSIC-V
s8i     a8, a2, 10           // XTENSA

在触发此类异常时,MTVAL/EXCVADDR 会自动更新为与异常有关的数据,从 RISC-V 异常信息中可以看到 MTVAL : 0x0000000a。一般来说 MTVAL 为 NULL 代表 CPU 尝试向 NULL 地址写数据,而接近 NULL 代表的是尝试向 NULL 地址开始的某个数组或者结构体的成员中写数据。

  • 对于 RSIC-V 架构,PC 和 RA 寄存器包含了异常的函数指针,从 elf 中找出对应的函数排查即可

  • 对于 Xtensa 架构,异常时会打印 backtrace,从 elf 中也可以找出对应的函数排查

实际案例

请参考 测试用例

注意事项

Load access fault(LoadProhibited) 问题类似,存在野指针导致无法解析的情况,此时需要根据实际应用代码进一步分析。

Instruction Access Fault(InstrFetchProhibited)

测试用例

当应用程序尝试从无效的地址读取指令时,会发生此类 CPU 异常,此时 PC 寄存器往往会指向无效的内存地址,测试代码如下所示:

typedef void (*fptr_t)(void);
volatile fptr_t fptr = (fptr_t) 0x4;
fptr();

对应的 RISC-V 汇编指令(步骤可参考 附录 1 - ESP 反汇编对应的指令)如下:

42006958:       1101                    addi    sp,sp,-32
4200695a:       ce06                    sw      ra,28(sp)
4200695c:       4791                    li      a5,4
4200695e:       c63e                    sw      a5,12(sp)
42006960:       47b2                    lw      a5,12(sp)
42006962:       9782                    jalr    a5
42006964:       40f2                    lw      ra,28(sp)
42006966:       6105                    addi    sp,sp,32
42006968:       8082                    ret

异常现象

  • RISC-V

Guru Meditation Error: Core  0 panic'ed (Instruction access fault). Exception was unhandled.

Core  0 register dump:
Stack dump detected
MEPC    : 0x00000004  RA      : 0x42006964  SP      : 0x3fc8f7b0  GP      : 0x3fc8b400
TP      : 0x3fc87d8c  T0      : 0x4005890e  T1      : 0x20000000  T2      : 0x00000000
S0/FP   : 0x3c023000  S1      : 0x00000000  A0      : 0x00000031  A1      : 0x3fc8f3f8
A2      : 0x00000000  A3      : 0x00000001  A4      : 0x3fc8c000  A5      : 0x00000004
A6      : 0x60023000  A7      : 0x0000000a  S2      : 0x00000000  S3      : 0x00000000
S4      : 0x00000000  S5      : 0x00000000  S6      : 0x00000000  S7      : 0x00000000
S8      : 0x00000000  S9      : 0x00000000  S10     : 0x00000000  S11     : 0x00000000
T3      : 0x00000000  T4      : 0x00000000  T5      : 0x00000000  T6      : 0x00000000
MSTATUS : 0x00001881  MTVEC   : 0x40380001  MCAUSE  : 0x00000001  MTVAL   : 0x00000004
  • Xtensa

Guru Meditation Error: Core  0 panic'ed (InstrFetchProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x00000004  PS      : 0x00060630  A0      : 0x800d539a  A1      : 0x3ffb4a30
A2      : 0x400de738  A3      : 0x3f40379c  A4      : 0x3f40381c  A5      : 0x3ffb4a60
A6      : 0x3ffb4a40  A7      : 0x0000000c  A8      : 0x800e4dbe  A9      : 0x3ffb49d0
A10     : 0x00000031  A11     : 0x3ffafc64  A12     : 0x3ffb4a40  A13     : 0x0000000c
A14     : 0x3ffb2770  A15     : 0x0000cdcd  SAR     : 0x00000004  EXCCAUSE: 0x00000014
EXCVADDR: 0x00000004  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xfffffffd

Backtrace: 0x00000001:0x3ffb4a30 0x400d5397:0x3ffb4a60 0x400e54f8:0x3ffb4a80 0x400858e9:0x3ffb4ab0

定位方法

一般来说,此类问题都是由野指针导致的,此时 PC 寄存器已经没有价值,其他寄存器是否值得分析取决于野指针运行的时间,对于此用例来说,因为在当前函数已经触发 CPU 异常,因此 RA 寄存器中包含了上层函数指针(Xtensa 架构通过 Backtrace),此时可以分析出来异常。但是大多数时间, RA 寄存器也会被破坏,此时如果需要分析,可以根据如下步骤进行:

  1. 稳定复现问题,保证每次出现的问题相同

  2. 找寻问题的规律,比如执行哪些操作,或者打印哪些日志后开始异常

  3. 根据程序异常的位置来结合代码分析,通过加调试日志以及逐步减少工程的代码量来看是否仍能复现问题

实际案例

如下图所示,异常时的现场已经完全被破坏,通过这些信息,没有办法去反推问题的原因,不过大多数寄存器都被破坏成一个固定值本身也是一个规律,像这种寄存器全被破坏的情况,一般是内存踩踏导致的问题,可以用 堆内存调试 的方法进行分析。

../../../_images/InstrFetchProhibited.png

Illegal Instruction

测试用例

CPU 取指阶段,取到非法指令(RISC-V spec 中定义为 16 bit 全为 0 的指令)会打印此错误。测试代码如下所示:

uint32_t instr_dram_addr = 0x0;
intptr_t instr_addr = MAP_DRAM_TO_IRAM((intptr_t)&instr_dram_addr);
typedef void (*illegal_instr_t)(void);
illegal_instr_t illegal_instr = (uint32_t *)instr_addr; // 确保 instr_addr 内存数据为 0x0
illegal_instr();

备注

Xtensa 平台中的 ESP32 不支持上述测试用例,其他芯片如要运行此测试用例,需要先关闭内存保护功能。

异常现象

  • RISC-V

Guru Meditation Error: Core  0 panic'ed (Illegal instruction). Exception was unhandled.

Core  0 register dump:
Stack dump detected
MEPC    : 0x4005f002  RA      : 0x42006962  SP      : 0x3fc8f7c0  GP      : 0x3fc8b400
0x42006962: illegal_instr_fault at /home/jacques/useful_example/crash_sim/store_access_fault/main/hello_world_main.c:79

TP      : 0x3fc87d8c  T0      : 0x4005890e  T1      : 0x20000000  T2      : 0x00000000
S0/FP   : 0x3c023000  S1      : 0x00000000  A0      : 0x3fc8f840  A1      : 0x3fc8f3f8
A2      : 0x00000000  A3      : 0x00000001  A4      : 0x3fc8c000  A5      : 0x4005f000
A6      : 0x60023000  A7      : 0x0000000a  S2      : 0x00000000  S3      : 0x00000000
S4      : 0x00000000  S5      : 0x00000000  S6      : 0x00000000  S7      : 0x00000000
S8      : 0x00000000  S9      : 0x00000000  S10     : 0x00000000  S11     : 0x00000000
T3      : 0x00000000  T4      : 0x00000000  T5      : 0x00000000  T6      : 0x00000000
MSTATUS : 0x00001881  MTVEC   : 0x40380001  MCAUSE  : 0x00000002  MTVAL   : 0x00000000
  • Xtensa

Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x403e298c: 00000000 00000000 00000000
Core  0 register dump:
PC      : 0x403e2990  PS      : 0x00060130  A0      : 0x820059fe  A1      : 0x3fcf2990
A2      : 0x4200c030  A3      : 0x3c0232fc  A4      : 0x3c02337c  A5      : 0x3fcf29c0
A6      : 0x3fcf29a0  A7      : 0x0000000c  A8      : 0x820059f4  A9      : 0x3fcf2930
A10     : 0x00000031  A11     : 0x3fcf2be4  A12     : 0x3fcf29a0  A13     : 0x0000000c
A14     : 0x3fc922c4  A15     : 0x00000000  SAR     : 0x00000004  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x400556d5  LEND    : 0x400556e5  LCOUNT  : 0xfffffffd

Backtrace: 0x403e298d:0x3fcf2990 |<-CORRUPTED

定位方法

虽然在 ESP-IDF 文档中有 Illegal instruction 说明 ,其中提到可能有 3 类情况触发此问题 ,但是实际使用中,大多数都是 CPU 从 flash 取指令异常触发此问题,还有一部分是类似测试用例这种野指针导致的从内存取值异常,从 PC 地址一般可以看出是从 IRAM 还是从 flash 取址异常。

从 flash 取指出现问题可能的原因包括 ESP 芯片休眠时 flash 下电、CS 上拉不稳定,flash 供电不稳定,以及 flash suspend 功能等。

实际案例

下图是 ESP 芯片在低功耗场景下的一种异常情况,从日志中可以看到异常前有 power save 的打印,可以怀疑问题跟芯片休眠有关。后在 menuconfig 配置项中关闭休眠时给 flash 掉电(CONFIG_ESP_SLEEP_POWER_DOWN_FLASH),以及开启休眠时 CS 软件上拉(CONFIG_ESP_SLEEP_FLASH_LEAKAGE_WORKAROUND) 这两个选项 ,问题不再复现。

illegal_instr

Cache disable but cached memory region accessed(Cache error)

异常原理

在 flash 操作(读写擦)时会关闭 cache ,如果此时中断触发 (使用 ESP_INTR_FLAG_IRAM 修饰的中断可以在 cache 关闭的时候触发),如中断函数中存在函数需要通过 cache 从 flash 中取指或取数据(包括mmap),会因为 cache 被关闭导致异常。

测试用例

在关闭 cache 后,访问并打印 flash 中的数据。测试代码如下所示:

static const uint32_t s_in_rodata[8] = { 0x12345678, 0xfedcba98 };
spi_flash_disable_interrupts_caches_and_other_cpu();
volatile uint32_t* src = (volatile uint32_t*) s_in_rodata;
uint32_t v1 = src[0];
uint32_t v2 = src[1];
ets_printf("%lx %lx\n", v1, v2);

异常现象

  • RISC-V

Guru Meditation Error: Core  0 panic'ed (Cache error).
access to cache while dbus or cache is disabled

Stack dump detected
Core  0 register dump:
MEPC    : 0x40000040  RA      : 0x40381e82  SP      : 0x3fc8f7c0  GP      : 0x3fc8b400
0x40381e82: cache_access_test_func at /home/jacques/useful_example/crash_sim/store_access_fault/main/hello_world_main.c:38

TP      : 0x3fc87d5c  T0      : 0x4005890e  T1      : 0x20000000  T2      : 0x00000000
S0/FP   : 0x3c023000  S1      : 0x00000000  A0      : 0x3c025610  A1      : 0x00000000
A2      : 0x00000000  A3      : 0x00000200  A4      : 0x600c4000  A5      : 0x3c02561c
A6      : 0x60023000  A7      : 0x0000000a  S2      : 0x00000000  S3      : 0x00000000
S4      : 0x00000000  S5      : 0x00000000  S6      : 0x00000000  S7      : 0x00000000
S8      : 0x00000000  S9      : 0x00000000  S10     : 0x00000000  S11     : 0x00000000
T3      : 0x00000000  T4      : 0x00000000  T5      : 0x00000000  T6      : 0x00000000
MSTATUS : 0x00001881  MTVEC   : 0x40380001  MCAUSE  : 0x00000019  MTVAL   : 0x6944806f
  • Xtensa

Guru Meditation Error: Core  0 panic'ed (Cache disabled but cached memory region accessed).

Core  0 register dump:
PC      : 0x400830ed  PS      : 0x00060a34  A0      : 0x800d539a  A1      : 0x3ffb4a40
0x400830ed: cache_access_test_func at /home/jacques/useful_example/crash_sim/store_access_fault/main/hello_world_main.c:32

A2      : 0x400de738  A3      : 0x3f40379c  A4      : 0x3f40381c  A5      : 0x3ffb4a60
0x400de738: vprintf at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vprintf.c:30

A6      : 0x3ffb4a40  A7      : 0x0000000c  A8      : 0x3f4040c4  A9      : 0x3ffb4a10
A10     : 0x00000001  A11     : 0xbad00bad  A12     : 0x3ffb2608  A13     : 0x0000000c
A14     : 0x3ffb2770  A15     : 0x0000cdcd  SAR     : 0x00000004  EXCCAUSE: 0x00000007
EXCVADDR: 0x00000000  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xfffffffd

Backtrace: 0x400830ea:0x3ffb4a40 0x400d5397:0x3ffb4a60 0x400e54e4:0x3ffb4a80 0x40085915:0x3ffb4ab0

分析方法

在出现此类问题,主要观察异常时的 PC 地址,如果地址在 flash 中,说明在关闭 cache 的时候从 flash 读指令,此时只需要把对应的函数使用 IRAM_ATTR 修饰即可,需要注意的是 IRAM_ATTR 只针对当前函数,如果此函数还有子函数,那么子函数也需要使用 IRAM_ATTR 进行修饰。

如果地址在 IRAM 中,说明此函数本身没问题,可能是此函数对应的输入参数等需要从 flash 中读取。

实际案例

在 flash 读写操作(导致 cache 关闭)时已放入 IRAM 的 gptimer 中断也触发,gptimer ISR 里执行了一些需要从 flash 读取内容的操作触发此问题:

cache_disable

从上述截图我们可以观察到几个问题点

  1. 可确定问题为在 flash 读写操作的时候触发了 gptimer 中断,且 ISR 里有存在于 flash 里的内容

  2. 异常时 PC 指向的函数 gpio_set_level 已放入 IRAM,而不是在 flash 中,因此不需要经过 cache,在 cache 关闭时也应正常运行

经过分析,最终排查到是函数 gpio_set_level 的输入参数 LED_matrix 使用 const 修饰导致的,被 const 修饰的参数会放置在 flash 的 .rodata 段,因此读取此参数需通过 cache。

cache_disable2

注意事项

Cache disable 的异常在 Xtensa 平台上捕捉的更好,在 RISC-V 平台上可能会表现为因 cache 读不到数据导致的其他错误,如 Illegal instruction. 代码示例如下:

gpio_set_level(12, 1);
spi_flash_disable_interrupts_caches_and_other_cpu();
gpio_set_level(12, 0);

在 ESP32-C3(RISC-V 平台) 中运行时,出现的 crash 如下

Guru Meditation Error: Core  0 panic'ed (Illegal instruction). Exception was unhandled.

Core  0 register dump:
Stack dump detected
MEPC    : 0x42006ef2  RA      : 0x40381e7e  SP      : 0x3fc8f7f0  GP      : 0x3fc8b400
0x42006ef2: gpio_set_level at /home/jacques/sdk/esp-idf/components/driver/gpio/gpio.c:233
0x40381e7e: cache_access_test_func at /home/jacques/useful_example/crash_test/main/hello_world_main.c:50
TP      : 0x3fc87d4c  T0      : 0x4005890e  T1      : 0x20000000  T2      : 0x00000000
S0/FP   : 0x3c023000  S1      : 0x00000000  A0      : 0x0000000c  A1      : 0x00000000
A2      : 0x00000200  A3      : 0x00000200  A4      : 0x600c4000  A5      : 0x00000000
A6      : 0x60023000  A7      : 0x0000000a  S2      : 0x00000000  S3      : 0x00000000
S4      : 0x00000000  S5      : 0x00000000  S6      : 0x00000000  S7      : 0x00000000
S8      : 0x00000000  S9      : 0x00000000  S10     : 0x00000000  S11     : 0x00000000
T3      : 0x00000000  T4      : 0x00000000  T5      : 0x00000000  T6      : 0x00000000
MSTATUS : 0x00001881  MTVEC   : 0x40380001  MCAUSE  : 0x00000002  MTVAL   : 0x00000000

Interrupt wdt timeout on CPU0/CPU1

异常原理

中断看门狗使用 Timer group 1 上的硬件看门狗定时器,通过在滴答定时器 SysTick 中断中添加喂狗操作来监控系统任务调度是否正常。当长时间(默认 300 ms)未在 SysTick 中断中做喂狗处理时,中断看门狗中断触发。更多信息请参考 Interrupt Watchdog Timer (IWDT)

测试用例

可以通过关中断的方式来触发此问题,测试代码如下所示:

static portMUX_TYPE s_init_spinlock = portMUX_INITIALIZER_UNLOCKED;
portENTER_CRITICAL(&s_init_spinlock);
while (1) {
}

异常现象

  • RISC-V

Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0).

Core  0 register dump:
Stack dump detected
MEPC    : 0x42006964  RA      : 0x42006964  SP      : 0x3fc911a0  GP      : 0x3fc8b400
0x42006964: interrupt_wdt_fault_task at /home/jacques/useful_example/crash_test/main/hello_world_main.c:121 (discriminator 1)

TP      : 0x3fc8971c  T0      : 0x00000000  T1      : 0x00000000  T2      : 0x00000000
S0/FP   : 0x00000000  S1      : 0x00000000  A0      : 0x00000001  A1      : 0x00000000
A2      : 0x00000000  A3      : 0x00000004  A4      : 0x00000001  A5      : 0x3fc8c000
A6      : 0x00000000  A7      : 0x00000000  S2      : 0x00000000  S3      : 0x00000000
S4      : 0x00000000  S5      : 0x00000000  S6      : 0x00000000  S7      : 0x00000000
S8      : 0x00000000  S9      : 0x00000000  S10     : 0x00000000  S11     : 0x00000000
T3      : 0x00000000  T4      : 0x00000000  T5      : 0x00000000  T6      : 0x00000000
MSTATUS : 0x00001881  MTVEC   : 0x40380001  MCAUSE  : 0x00000018  MTVAL   : 0x0000a001
  • Xtensa

Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0).

Core  0 register dump:
PC      : 0x40378b06  PS      : 0x00060634  A0      : 0x82002239  A1      : 0x3fc984f0
0x40378b06: esp_cpu_wait_for_intr at /home/jacques/sdk/esp-idf/components/esp_hw_support/cpu.c:110

A2      : 0x00000000  A3      : 0x00000000  A4      : 0x3fc96c70  A5      : 0x3fc96c50
A6      : 0x42005e10  A7      : 0x00000000  A8      : 0x82009452  A9      : 0x3fc984b0
0x42005e10: timer_task at /home/jacques/sdk/esp-idf/components/esp_timer/src/esp_timer.c:470

A10     : 0x00000000  A11     : 0x00000000  A12     : 0x3fc96c50  A13     : 0x3fc96c30
A14     : 0x00000000  A15     : 0x00000000  SAR     : 0x00000000  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000


Backtrace: 0x40378b03:0x3fc984f0 0x42002236:0x3fc98510 0x4037b5a9:0x3fc98530 0x40379e71:0x3fc98550
0x40378b03: xt_utils_wait_for_intr at /home/jacques/sdk/esp-idf/components/xtensa/include/xt_utils.h:81
 (inlined by) esp_cpu_wait_for_intr at /home/jacques/sdk/esp-idf/components/esp_hw_support/cpu.c:101
0x42002236: esp_vApplicationIdleHook at /home/jacques/sdk/esp-idf/components/esp_system/freertos_hooks.c:59
0x4037b5a9: prvIdleTask at /home/jacques/sdk/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:4269 (discriminator 1)
0x40379e71: vPortTaskWrapper at /home/jacques/sdk/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:149

Core  1 register dump:
PC      : 0x42007c32  PS      : 0x00060034  A0      : 0x80379e74  A1      : 0x3fc99f20
0x42007c32: interrupt_wdt_fault_task at /home/jacques/useful_example/crash_test/main/hello_world_main.c:121 (discriminator 1)

A2      : 0x00000000  A3      : 0x00000000  A4      : 0x00000001  A5      : 0x00000000
A6      : 0x00000001  A7      : 0x00000000  A8      : 0x82007c32  A9      : 0x3fc99ef0
A10     : 0x00000001  A11     : 0x3fc93a54  A12     : 0x00060020  A13     : 0x00060023
A14     : 0x00060323  A15     : 0x0000abab  SAR     : 0x00000000  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000


Backtrace: 0x42007c2f:0x3fc99f20 0x40379e71:0x3fc99f40
0x42007c2f: vPortEnterCritical at /home/jacques/sdk/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/include/freertos/portmacro.h:573
 (inlined by) interrupt_wdt_fault_task at /home/jacques/useful_example/crash_test/main/hello_world_main.c:120
0x40379e71: vPortTaskWrapper at /home/jacques/sdk/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:149

分析方法

在出现此类问题,主要观察异常时的 PC 地址,即可确定触发 crash 的位置。对于多核架构,需要观察几个核心的寄存器,分析其中触发问题的方法。

可能的原因及具体解释如下:

  1. 长时间关中断

  2. ISR 函数中存在阻塞

  3. 没有清中断

长时间关中断

关中断操作本身是为了保护一些不能中途停止执行的程序而设计的,它用来禁止系统响应中断源的中断请求。长时间关中断是导致中断看门狗触发的最主要原因。

测试用例 中进入临界区的操作会关闭中断。关中断之后, SysTick 中断无法触发来及时进行喂狗操作,这后续会导致中断看门狗超时(关中断无法屏蔽看门狗中断)并触发看门狗异常处理程序,此时需要用户自己排查上层关中断的逻辑,依据出问题的代码位置进一步分析。

ISR 函数中存在阻塞

在 ESP 芯片产生某一中断之后,会调用对应的 ISR 进行处理,在 ISR 函数中应做的操作应尽可能少,可以将需要耗时的操作转移到其他非中断函数中处理。如 ISR 函数需耗费大量时间来运行或存在阻塞导致未在中断看门狗触发前退出 ISR,就会触发异常。

以下是 GPIO ISR 阻塞的一个简单示例:

#define GPIO_INPUT_IO_0     4

static void IRAM_ATTR gpio_isr_handler(void* arg)
{
    ets_printf("ISR\n");
    while(1){}
}

void app_main(void)
{
    gpio_config_t io_conf;
    io_conf.intr_type = GPIO_INTR_POSEDGE;
    io_conf.pin_bit_mask = (1ULL<<GPIO_INPUT_IO_0);
    io_conf.mode = GPIO_MODE_INPUT;
    io_conf.pull_up_en = 1;
    gpio_config(&io_conf);

    gpio_install_isr_service(0);
    gpio_isr_handler_add(GPIO_INPUT_IO_0, gpio_isr_handler, (void*) GPIO_INPUT_IO_0);
}

将 GPIO 4 手动拉高,触发 GPIO 中断,打印如下 crash 信息:

ISR
Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0).
Core  0 register dump:
PC      : 0x40082580  PS      : 0x00060034  A0      : 0x80081560  A1      : 0x3ffb07c0
0x40082580: gpio_isr_handler at /home/jacques/problem/wdt/int_wdt/build/../main/hello_world_main.c:40 (discriminator 1)

A2      : 0x00000004  A3      : 0x3ff0015c  A4      : 0x800d6d82  A5      : 0x3ffb3400
A6      : 0x00000000  A7      : 0x00000001  A8      : 0x80082580  A9      : 0x3ffb0730
A10     : 0x00000004  A11     : 0x00000004  A12     : 0x00000004  A13     : 0x00000000
A14     : 0x00000000  A15     : 0x3ffb3400  SAR     : 0x0000001c  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000
Core  0 was running in ISR context:
EPC1    : 0x400d1097  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x40082580
0x400d1097: uart_hal_write_txfifo at /home/jacques/sdk/esp-idf/components/hal/uart_hal_iram.c:35

0x40082580: gpio_isr_handler at /home/jacques/problem/wdt/int_wdt/build/../main/hello_world_main.c:40 (discriminator 1)

Backtrace:0x4008257d:0x3ffb07c0 0x4008155d:0x3ffb07e0 0x40082102:0x3ffb0800 0x400d6702:0x3ffb3450 0x400862a2:0x3ffb3470 0x40087865:0x3ffb3490

通过 PC 和 Backtrace,我们可以确认问题出现在 gpio_isr_handle 函数中。此外, Core 0 was running in ISR context 这行日志也表明当前在中断函数中运行。

没有清中断

在 ISR 函数结束后,需要手动清除相应的中断,如果此时不做清除,中断将会一直触发,从而使得 Systick 中断无法响应。

ISR 函数中存在阻塞 里的示例,如果把 gpio_isr_handler 中的 while(1) 循环去掉, 然后将 ESP-IDF GPIO 驱动中的 gpio_hal_clear_intr_status_bit 注释后重新编译烧写运行上述程序,可以发现同样触发了中断看门狗的 crash。

如果用户没有自行修改默认驱动,清中断一般来说会由驱动底层自行完成,若此时出现了指向内部驱动的中断看门狗异常,则可以进一步查看驱动底层是否正常做了清中断操作。

实际案例

通过上述描述,可能会认为中断看门狗问题极易分析,但实际的应用中中断看门狗问题往往非独立存在,一般会跟 FreeRTOS 相结合,FreeRTOS 很多操作都需要关中断处理,一旦 FreeRTOS 出现异常则容易卡住并表现为中断看门狗问题,实际 crash 案例如下:

Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0)
Core 0 register dump:
PC      : 0x400915d2  PS      : 0x00060b34  A0      : 0x800903ed  A1      : 0x3ffd4e80
A2      : 0x3ffd3598  A3      : 0x3ffd4ff0  A4      : 0x00000c9f  A5      : 0x3f408990
A6      : 0x3ffbf580  A7      : 0x00060023  A8      : 0x3ffd4ff0  A9      : 0x0000000f
A10     : 0x3ffd4ff0  A11     : 0x0000000f  A12     : 0x00060b20  A13     : 0x00000001
A14     : 0x3ffeddf0  A15     : 0x3ffea57c  SAR     : 0x00000018  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xfffffffe

ELF file SHA256: eadf38922e335ed1

Backtrace: 0x400915cf:0x3ffd4e80 0x400903ea:0x3ffd4ea0 0x4008f514:0x3ffd4ec0 0x400ffb91:0x3ffd4f00 0x40136612:0x3ffd4f30

解析 Backtrace 信息,如下:

~$ xtensa-esp32-elf-addr2line -afe esp32_interrupt_wdt.elf 0x400915cf:0x3ffd4e80 0x400903ea:0x3ffd4ea0 0x4008f514:0x3ffd4ec0 0x400ffb91:0x3ffd4f00 0x40136612:0x3ffd4f30
0x400915cf
vListInsert
/arm/esp-idf/components/freertos/list.c:205
0x400903ea
vTaskPlaceOnEventList
/arm/esp-idf/components/freertos/tasks.c:2901 (discriminator 2)
0x4008f514
xQueueGenericReceive
/arm/esp-idf/components/freertos/queue.c:1596
0x400ffb91
arch_os_mbox_fetch
/arm/components/esp32/arch_os.c:352 (discriminator 4)
0x40136612
msg_fetch_block
/arm/components/libs/d0/delayzero.c:631

通过上述日志可看出问题并不是 crash 在中断里,而是指向了 FreeRTOS 本身,通过查找 vListInsert 可发现在以下 for 循环里出现问题:

if( xValueOfInsertion == portMAX_DELAY )
{
    pxIterator = pxList->xListEnd.pxPrevious;
}
else
{
    for( pxIterator = ( ListItem_t * ) &( pxList->xListEnd ); pxIterator->pxNext->xItemValue <= xValueOfInsertion; pxIterator = pxIterator->pxNext )
    {
        /* There is nothing to do here, just iterating to the wanted
        insertion position. */
    }
}

此时可进一步检查对应上层代码在此刻是否有关中断操作,最后在 vTaskPlaceOnEventList 中可看到确实是先关中断,再去执行的链表插入操作。

void vTaskPlaceOnEventList( List_t * const pxEventList, const TickType_t xTicksToWait )
{
    configASSERT( pxEventList );
    taskENTER_CRITICAL(&xTaskQueueMutex);

    vListInsert( pxEventList, &( pxCurrentTCB[xPortGetCoreID()]->xEventListItem ) );

    prvAddCurrentTaskToDelayedList( xPortGetCoreID(), xTicksToWait);
    taskEXIT_CRITICAL(&xTaskQueueMutex);
}

至此分析完成,此问题是一个表现为中断看门狗的 FreeRTOS 问题,因此排查这个问题需要分析为什么会在 for 循环中不再退出。FreeRTOS 本身出现问题的概率极低,此时大多数是由于上层应用代码使用不当导致的,可能的原因包括内存踩踏,关中断后调用阻塞操作等问题。

附录 1 - ESP 反汇编对应的指令

  • Xtensa ESP32 : xtensa-esp32-elf-objdump -S xxx.elf > a.txt

  • Xtensa ESP32-S2 : xtensa-esp32s2-elf-objdump -S xxx.elf > a.txt

  • Xtensa ESP32-S3 : xtensa-esp32s3-elf-objdump -S xxx.elf > a.txt

  • RISC-V : riscv32-esp-elf-objdump -S xxx.elf > a.txt

其中 xxx.elf 为工程 elf 文件,此文件往往在工程目录下的 build 文件夹里。 a.txt 为反汇编的输出问题,里面包含了实际的汇编指令。