External Abort on mutex from ISR

[WeinanCai]

Environment
• Chip used: ESP32D0WDQ6
• Peripheral used: ICM20602 gyroscope
• IDF version: v3.3
• Power Supply: USB
Problem Description
I'm suffering an abort when my ESP32 board communicates with ICM20602 gyroscope. After running for some time (around 30 minutes), the board reboots because of the abort in IRQ handler. However, it completely works as I expected until then. I can't find any other similar case like this and it is really hard to figure it out because it's occurring in IRQ handler.
Code snippets

Code: Select all

void ICM20602_enable_irq(void){
    gpio_config_t gpioConfig;   
    gpioConfig.pin_bit_mask = GPIO_SEL_17;   
    gpioConfig.mode         = GPIO_MODE_INPUT;   
    gpioConfig.pull_up_en   = GPIO_PULLUP_DISABLE;
    gpioConfig.pull_down_en = GPIO_PULLDOWN_ENABLE;   
    gpioConfig.intr_type    = GPIO_INTR_POSEDGE; //GPIO interrupt type : rising edge
    ESP_ERROR_CHECK(gpio_config(&gpioConfig));   
    ESP_ERROR_CHECK(gpio_install_isr_service(0));   
    ESP_ERROR_CHECK(gpio_isr_handler_add(GPIO_NUM_17, icm_irq_handler, (void*)GPIO_NUM_17));
    //configure transaction for dma in irq
    memset(&irq_trans_desc, 0, sizeof(irq_trans_desc));
    irq_trans_desc.addr = FIFO_R_W;
    irq_trans_desc.cmd = 1;
    irq_trans_desc.flags = 0;
    irq_trans_desc.length = DMA_CHUNK_SZ * 8;
    irq_trans_desc.rxlength = 0;
    irq_trans_desc.tx_buffer = datatx;
    irq_trans_desc.user=(void*)1; 
}

static void icm_irq_handler(void *args) {  
    if (dmapos >= DMA_RX_SZ) {
        dmapos = 0;
        timepos = 0;
        secondbuffer = !secondbuffer;
    }
    irq_trans_desc.rx_buffer = ((secondbuffer)? datarx2 : datarx) + dmapos;
    ESP_ERROR_CHECK(spi_device_queue_trans(spi,&irq_trans_desc, portMAX_DELAY));
    //spi_transaction_t *rtrans;
    //ESP_ERROR_CHECK(spi_device_get_trans_result(spi,&rtrans, portMAX_DELAY))；
    dmapos += DMA_CHUNK_SZ;
    gettimeofday((secondbuffer)? &(captimes2[timepos]): &(captimes[timepos]), NULL);//TODO: needs RTC
    timepos++;
}
int app_main(void)
{
This is the while(1) loop in app_main()
while(1){
    if (lastbuffer_a != secondbuffer) {
        buflen = prepare_buf(sdbuf);
        fwrite(sdbuf,sizeof(char), buflen, fp);
        lastbuffer_a = secondbuffer;
        filesize += buflen;
        if (filesize >= MAXFILESIZE){
            fclose(fp);
            filenum++;
            sprintf(filename, "/sdcard/data/raw-%d-%d.bin", instance, filenum);
            fp = fopen(filename, "wb");
            filesize = 0;
    }
}
}

backtrace

Code: Select all

abort() was called at PC 0x400829f3 on core 0
0x400829f3: lock_acquire_generic at /home/sophist/esp/esp-idf/components/newlib/locks.c:148


ELF file SHA256: 0639271aeafabe899db24c268a4da79232291e00dae2edb1cab819349cd30d42

Backtrace: 0x40084a5c:0x3ffb0560 0x40084ca5:0x3ffb0580 0x400829f3:0x3ffb05a0 0x40082ae9:0x3ffb05d0 0x400e5509:0x3ffb05f0 0x4008286a:0x3ffb0610 0x400d8e54:0x3ffb0630 0x400d2da8:0x3ffb0650 0x40084089:0x3ffb0670 0x40082285:0x3ffb0690 0x400e5375:0x3ffb4ab0 0x400e53cb:0x3ffb4ad0 0x400e550c:0x3ffb4af0 0x4008286a:0x3ffb4b10 0x4000bc69:0x3ffb4b30 0x40001850:0x3ffb4b50 0x400ec011:0x3ffb4b80 0x400ee638:0x3ffb4bd0 0x400ecb3b:0x3ffb4e40 0x400e6afe:0x3ffb4e70 0x4000bd67:0x3ffb4e90 0x400d3821:0x3ffb4eb0 0x400d38a8:0x3ffb4ee0 0x400d370a:0x3ffb4f00 0x400d132e:0x3ffb4fa0 0x40086941:0x3ffb4fc0
0x40084a5c: invoke_abort at /home/sophist/esp/esp-idf/components/esp32/panic.c:715

0x40084ca5: abort at /home/sophist/esp/esp-idf/components/esp32/panic.c:715

0x400829f3: lock_acquire_generic at /home/sophist/esp/esp-idf/components/newlib/locks.c:148

0x40082ae9: _lock_acquire at /home/sophist/esp/esp-idf/components/newlib/locks.c:167

0x400e5509: get_adjusted_boot_time at /home/sophist/esp/esp-idf/components/newlib/time.c:220

0x4008286a: _gettimeofday_r at /home/sophist/esp/esp-idf/components/newlib/time.c:220

0x400d8e54: gettimeofday at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/syscalls/../../../.././newlib/libc/syscalls/sysgettod.c:12

0x400d2da8: icm_irq_handler at /home/sophist/esp/project/spi_icm20602/main/spi_icm20602.c:160 (discriminator 4)

0x40084089: gpio_intr_service at /home/sophist/esp/esp-idf/components/driver/gpio.c:592

0x40082285: _xt_lowint1 at /home/sophist/esp/esp-idf/components/freertos/xtensa_vectors.S:1154

0x400e5375: get_boot_time at /home/sophist/esp/esp-idf/components/newlib/time.c:220

0x400e53cb: adjust_boot_time at /home/sophist/esp/esp-idf/components/newlib/time.c:220

0x400e550c: get_adjusted_boot_time at /home/sophist/esp/esp-idf/components/newlib/time.c:220

0x4008286a: _gettimeofday_r at /home/sophist/esp/esp-idf/components/newlib/time.c:220

0x400ec011: get_fattime at /home/sophist/esp/esp-idf/components/fatfs/src/diskio.c:82

0x400ee638: f_open at /home/sophist/esp/esp-idf/components/fatfs/src/ff.c:5068

0x400ecb3b: vfs_fat_open at /home/sophist/esp/esp-idf/components/fatfs/src/vfs_fat.c:315

0x400e6afe: esp_vfs_open at /home/sophist/esp/esp-idf/components/vfs/vfs.c:972

0x400d3821: _fopen_r at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/fopen.c:141

0x400d38a8: fopen at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/fopen.c:181

0x400d370a: app_main at /home/sophist/esp/project/spi_icm20602/main/spi_icm20602.c:596

0x400d132e: main_task at /home/sophist/esp/esp-idf/components/esp32/cpu_start.c:542

0x40086941: vPortTaskWrapper at /home/sophist/esp/esp-idf/components/freertos/port.c:403


Rebooting...

Backtrace analysis
abort(); /* Tried to block on mutex from ISR, couldn't... rewrite your program to avoid libc interactions in ISRs! */
this is the located line 148
0x400829f3: lock_acquire_generic at /home/sophist/esp/esp-idf/components/newlib/locks.c:148
It said it is isr mutex caused the abort and suggest to rewrite the program but I cannot figure it out. If there's a solution it would be great and I'd like to know how to debug aborts like this.

[ESP_Sprite]

Not sure why it works for so long, but you're doing lots of stuff that aren't permissible in an ISR... gettimeofday, logging functions, all are likely to call into blocking code. Please create a task that does all this and waits on a semaphore before actually doing it, and give that semafore in the irq.

[WeinanCai]

Not sure why it works for so long, but you're doing lots of stuff that aren't permissible in an ISR... gettimeofday, logging functions, all are likely to call into blocking code. Please create a task that does all this and waits on a semaphore before actually doing it, and give that semafore in the irq.

Thanks for the advice, Mr Sprite. It is indeed the gettimeofday() problem. Because gettimeofday() function is executed in the main loop, and the ISR is called at the same time. But the gettimeofday() cannot be interrupted. So the mutex is not released.