ESP32S3 SPIFFS flash access during RMT transmission causes panic (IDFGH-11099)

[higaski]

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v5.2-dev-2934-g3b748a6cb7

Operating System used.

Linux

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

None

Development Kit.

ESP32-S3-DevKitC-1

Power Supply used.

USB

What is the expected behavior?

I've an application in which I need to access a SPIFFS partition upon a HTTP request to serve some data while RMT transmissions are running on a high priority task. For some reason I can't get that combination to work properly. Every time I access the SPIFFS partition while the RMT transmission is ongoing I'm getting core0 panics

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


Core  0 register dump:
PC      : 0x4037a8f0  PS      : 0x00060034  A0      : 0x4037ba9c  A1      : 0x3fca04e0  
0x4037a8f0: shared_intr_isr at /home/vinci/esp/esp-idf/components/esp_hw_support/intr_alloc.c:450

0x4037ba9c: _xt_lowint1 at /home/vinci/esp/esp-idf/components/xtensa/xtensa_vectors.S:1236

A2      : 0x3c134c60  A3      : 0xb33fffff  A4      : 0x600c4000  A5      : 0x403860e6  
0x403860e6: _frxt_int_enter at /home/vinci/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/portasm.S:139

A6      : 0x00000000  A7      : 0xb33fffff  A8      : 0x00000bad  A9      : 0x3fca04b0  
A10     : 0x00000001  A11     : 0x00060021  A12     : 0x00000000  A13     : 0x00060023  
A14     : 0xb33fffff  A15     : 0xb33fffff  SAR     : 0x0000001d  EXCCAUSE: 0x00000007  
EXCVADDR: 0x00000000  LBEG    : 0x400570e8  LEND    : 0x400570f3  LCOUNT  : 0x00000000  
0x400570e8: memset in ROM

0x400570f3: memset in ROM

I can't tell why though. I've enabled the CONFIG_RMT_ISR_IRAM_SAFE option and attached the IRAM attribute to my RMT callback. Thankfully I can reproduce the issue in about 200 lines of code. The example connects to WiFi using the "common protocols example" code. HTTP requests to the devices IP address will read an index.html and text.png file from SPIFFS and show them in a browser. A high priority task does some RMT transmissions in the meantime.

#include <driver/rmt_tx.h>
#include <esp_http_server.h>
#include <esp_log.h>
#include <esp_spiffs.h>
#include <esp_task.h>
#include <esp_vfs.h>
#include <esp_wifi.h>
#include <nvs_flash.h>
#include <protocol_examples_common.h>
#include <protocol_examples_utils.h>
#include <sys/param.h>
#include <array>
#include <cstdint>
#include <cstdio>
#include <string_view>

// -----------------------------------------------------------------------------
// HTTP ------------------------------------------------------------------------
// -----------------------------------------------------------------------------
// server handle and file buffer for requests
httpd_handle_t server{};
constexpr auto file_buffer_size{16384uz};
char file_buffer[file_buffer_size]{};

// Initialize SPIFFS storage
esp_err_t spiffs_init() {
  static constexpr esp_vfs_spiffs_conf_t conf{.base_path = "",
                                              .partition_label = NULL,
                                              .max_files = 5,
                                              .format_if_mount_failed = true};
  return esp_vfs_spiffs_register(&conf);
}

// Wildcard handler to answer HTTP GET requests
esp_err_t wildcard_get_handler(httpd_req_t* req) {
  using namespace std::literals;

  struct stat file_stat;
  FILE* fd{};

  // 308 / to index.html
  if (req->uri == "/"sv) {
    httpd_resp_set_status(req, "308 Permanent Redirect");
    httpd_resp_set_hdr(req, "Location", "/index.html");
    httpd_resp_send(req, NULL, 0);
    return ESP_OK;
  }
  // SPIFFS
  else if (!stat(req->uri, &file_stat))
    fd = fopen(req->uri, "r");
  // 404
  else {
    httpd_resp_send_404(req);
    return ESP_FAIL;
  }

  // Couldn't open file
  if (!fd) {
    ESP_LOGE("RMT_PANIC", "Failed to read existing file");
    httpd_resp_send_500(req);
    return ESP_FAIL;
  }

  // Set content type
  std::string_view const uri{req->uri};
  if (uri.ends_with(".css")) httpd_resp_set_type(req, "text/css");
  else if (uri.ends_with(".js")) httpd_resp_set_type(req, "text/javascript");
  else if (uri.ends_with(".otf")) httpd_resp_set_type(req, "font/otf");
  else if (uri.ends_with(".png")) httpd_resp_set_type(req, "image/png");
  else if (uri.ends_with(".svg")) httpd_resp_set_type(req, "image/svg+xml");
  else if (uri.ends_with(".ttf")) httpd_resp_set_type(req, "font/ttf");

  // Send file
  ESP_LOGD(
    "RMT_PANIC", "Sending file : %s (%ldB)", req->uri, file_stat.st_size);
  size_t chunksize;
  do {
    if (!(chunksize = fread(file_buffer, sizeof(char), file_buffer_size, fd)))
      continue;
    if (httpd_resp_send_chunk(req, file_buffer, chunksize) != ESP_OK) {
      ESP_LOGE("RMT_PANIC", "File sending failed");
      httpd_resp_send_chunk(req, NULL, 0);  // Abort sending file
      httpd_resp_send_500(req);
      fclose(fd);
      return ESP_FAIL;
    }
  } while (chunksize);

  httpd_resp_send_chunk(req, NULL, 0);
  fclose(fd);
  return ESP_OK;
}

// HTTP init
esp_err_t http_init() {
  httpd_config_t config = HTTPD_DEFAULT_CONFIG();
  config.core_id = 0;
  config.lru_purge_enable = true;
  config.keep_alive_enable = true;
  config.uri_match_fn = httpd_uri_match_wildcard;
  ESP_ERROR_CHECK(httpd_start(&server, &config));
  httpd_uri_t uri{
    .uri = "/*", .method = HTTP_GET, .handler = wildcard_get_handler};
  return httpd_register_uri_handler(server, &uri);
}

// -----------------------------------------------------------------------------
// RMT -------------------------------------------------------------------------
// -----------------------------------------------------------------------------
constexpr auto rmt_gpio_num{GPIO_NUM_19};
auto default_notify_index{tskDEFAULT_INDEX_TO_NOTIFY + 1u};
TaskHandle_t rmt_task_handle{};
rmt_channel_handle_t rmt_channel{};
rmt_encoder_handle_t rmt_encoder{};
rmt_transmit_config_t rmt_transmit_config{};
rmt_tx_channel_config_t chan_config{
  .gpio_num = rmt_gpio_num,
  .clk_src = RMT_CLK_SRC_DEFAULT,
  .resolution_hz = 1'000'000u,
  .mem_block_symbols = 384uz / 4uz,  // 8 channels sharing 384x32 bit RAM
  .trans_queue_depth = 1uz,
  .flags = {
    .invert_out = false,
    .with_dma = false,
    .io_loop_back = false,
    .io_od_mode = false,
  }};
rmt_bytes_encoder_config_t encoder_config{
  .bit0 =
    rmt_symbol_word_t{
      .duration0 = 200u,
      .level0 = 0u,
      .duration1 = 200u,
      .level1 = 1u,
    },
  .bit1 =
    rmt_symbol_word_t{
      .duration0 = 100u,
      .level0 = 1u,
      .duration1 = 100u,
      .level1 = 0u,
    },
};

// RMT callback
bool IRAM_ATTR rmt_callback(rmt_channel_handle_t,
                            rmt_tx_done_event_data_t const*,
                            void*) {
  BaseType_t high_task_awoken{pdFALSE};
  vTaskNotifyGiveIndexedFromISR(
    rmt_task_handle, default_notify_index, &high_task_awoken);
  return high_task_awoken == pdTRUE;
}

// RMT task function
void rmt_task_function(void*) {
  std::array<char, 4uz> const chunk{
    0b1100'0000u,
    0b0011'0000u,
    0b0000'1100u,
    0b0000'0011u,
  };
  for (;;) {
    ESP_ERROR_CHECK(rmt_transmit(rmt_channel,
                                 rmt_encoder,
                                 data(chunk),
                                 size(chunk),
                                 &rmt_transmit_config));
    auto const notification_value{
      ulTaskNotifyTakeIndexed(pdTRUE, default_notify_index, portMAX_DELAY)};
  }
}

// RMT init
esp_err_t rmt_init() {
  ESP_ERROR_CHECK(rmt_new_tx_channel(&chan_config, &rmt_channel));
  ESP_ERROR_CHECK(rmt_enable(rmt_channel));
  rmt_tx_event_callbacks_t cbs{.on_trans_done = rmt_callback};
  ESP_ERROR_CHECK(rmt_tx_register_event_callbacks(rmt_channel, &cbs, NULL));
  ESP_ERROR_CHECK(rmt_new_bytes_encoder(&encoder_config, &rmt_encoder));
  xTaskCreatePinnedToCore(rmt_task_function,
                          "RMT task",
                          4096uz,
                          NULL,
                          ESP_TASK_PRIO_MAX - 1u,
                          &rmt_task_handle,
                          1);
  return ESP_OK;
}

// -----------------------------------------------------------------------------
// MAIN ------------------------------------------------------------------------
// -----------------------------------------------------------------------------
extern "C" void app_main() {
  printf("\n\nbooting esp_idf_issue_12271\n\n");

  ESP_ERROR_CHECK(nvs_flash_init());
  ESP_ERROR_CHECK(spiffs_init());
  ESP_ERROR_CHECK(esp_netif_init());
  ESP_ERROR_CHECK(esp_event_loop_create_default());
  ESP_ERROR_CHECK(http_init());
  ESP_ERROR_CHECK(example_connect());
  ESP_ERROR_CHECK(rmt_init());

  for (;;)
    vTaskDelay(pdMS_TO_TICKS(1000u));
}

Here is a zip containing everything (sdkconfig might be important?):
esp_idf_issue_12271-master.zip

What is the actual behavior?

ESP32 crashes with a core0 cache panic

Steps to reproduce.

1. Take the example, set WiFi SSID and password with idf.py menuconfig
2. Flash the example on an ESP32S3 (e.g. ESP32-S3-DevKitC-1)
3. Wait for WiFi to connect
4. Get the IP address from LOG and put it in a browser
5. Voila, your ESP32 will panic and reboot

Debug Logs.

No response

More Information.

No response

[suda-morris]

@higaski Could it be that the std::array<char, 4uz> const chunk was placed in the flash. And when the RMT copy encoder doing the job, it needs to read that raw data, however, the cache is disabled at that time

[higaski]

That would only be possible if the data would be static.

[igrr]

I haven't tried this with std::array, but simple C const arrays above certain size also get placed into rodata segment quite often. Could you please check the placement in the .map file, or attach the .map file here?

Edit: no, indeed, that doesn't seem to be the case here. Although the array is stored in Flash (.rodata), it is copied onto the stack before passing it to rmt_transmit. At least that's the case if i build the reproducer project locally.

Disassembly:

│42009b6c ; Start of '_Z17rmt_task_functionPv' function                                          │
│42009b6c _Z17rmt_task_functionPv:                                                               │
│42009b6c     entry    $sp, 6                                                                    │
│42009b6f     $a8 = 0x3c0a6fc0 ; movi*    $a8, 0x3c0a6fc0 ; via 0x42000a64                       │   <- literal value at 0x3c0a6fc0 (.rodata) is 0x030c30c0 — this is the `chunk` array, little endian
│42009b72     $a8 = *(u32*)$a8 ; l32i     $a8, $a8, 0x0                                          │
│42009b75     *(u32*)$sp = $a8 ; s32i     $a8, $sp, 0x0                                          │   <- copied onto the stack
│42009b78              ; xref: 0x42009bb0 j                                                      │
│42009b78 loc_42009b78:                                                                          │
│42009b78     $a14 = rmt_transmit_config ; movi*    $a14, rmt_transmit_config ; via 0x42000a68   │
│42009b7b     $a13 = 0x4 ; movi     $a13, 0x4                                                    │
│42009b7e     $a12 = $sp ; mov.n    $a12, $sp                                                    │   <- stack address of the array gets passed to rm_transmit
│42009b80     $a8 = rmt_encoder ; movi*    $a8, rmt_encoder ; via 0x42000a6c                     │
│42009b83     $a11 = *(u32*)$a8 ; l32i.n   $a11, $a8, 0x0                                        │
│42009b85     $a8 = rmt_channel ; movi*    $a8, rmt_channel ; via 0x42000a70                     │
│42009b88     $a10 = *(u32*)$a8 ; l32i.n   $a10, $a8, 0x0                                        │
│42009b8a     call rmt_transmit ; call8    rmt_transmit                                          │

Please ignore the question about the map file.

[higaski]

Edit: no, indeed, that doesn't seem to be the case here. Although the array is stored in Flash (.rodata), it is copied onto the stack before passing it to rmt_transmit. At least that's the case if i build the reproducer project locally.

Yes exactly. I've actually been burned by this before by placing big constexpr std::array luts inside functions (e.g. CRC calculations without specific hardware), thinking that this would be a fast way to handle things. Turns out, yes, the look-up is fast... once the whole array has been copied onto the stack. 😄

[suda-morris]

Hi @higaski

The issue is discovered by this Kconfig: CONFIG_SPIRAM_MALLOC_ALWAYSINTERNAL=0. The interrupt allocator internally allocated some buffer from the PSRAM, so causing the crash.

diff --git a/components/esp_hw_support/intr_alloc.c b/components/esp_hw_support/intr_alloc.c
index 02d72ccd5d1..99906ad9a1f 100644
--- a/components/esp_hw_support/intr_alloc.c
+++ b/components/esp_hw_support/intr_alloc.c
@@ -560,7 +560,7 @@ esp_err_t esp_intr_alloc_intrstatus(int source, int flags, uint32_t intrstatusre
     //Allocate that int!
     if (flags & ESP_INTR_FLAG_SHARED) {
         //Populate vector entry and add to linked list.
-        shared_vector_desc_t *sh_vec=malloc(sizeof(shared_vector_desc_t));
+        shared_vector_desc_t *sh_vec=heap_caps_malloc(sizeof(shared_vector_desc_t), MALLOC_CAP_INTERNAL | MALLOC_CAP_8BIT);
         if (sh_vec == NULL) {
             portEXIT_CRITICAL(&spinlock);
             free(ret);
@@ -583,7 +583,7 @@ esp_err_t esp_intr_alloc_intrstatus(int source, int flags, uint32_t intrstatusre
         vd->flags = VECDESC_FL_NONSHARED;
         if (handler) {
 #if CONFIG_APPTRACE_SV_ENABLE
-            non_shared_isr_arg_t *ns_isr_arg=malloc(sizeof(non_shared_isr_arg_t));
+            non_shared_isr_arg_t *ns_isr_arg=heap_caps_malloc(sizeof(non_shared_isr_arg_t), MALLOC_CAP_INTERNAL | MALLOC_CAP_8BIT)
             if (!ns_isr_arg) {
                 portEXIT_CRITICAL(&spinlock);
                 free(ret);

[higaski]

That was a fast catch, thanks!

[higaski]

Hi @higaski

The issue is discovered by this Kconfig: CONFIG_SPIRAM_MALLOC_ALWAYSINTERNAL=0. The interrupt allocator internally allocated some buffer from the PSRAM, so causing the crash.

diff --git a/components/esp_hw_support/intr_alloc.c b/components/esp_hw_support/intr_alloc.c
index 02d72ccd5d1..99906ad9a1f 100644
--- a/components/esp_hw_support/intr_alloc.c
+++ b/components/esp_hw_support/intr_alloc.c
@@ -560,7 +560,7 @@ esp_err_t esp_intr_alloc_intrstatus(int source, int flags, uint32_t intrstatusre
     //Allocate that int!
     if (flags & ESP_INTR_FLAG_SHARED) {
         //Populate vector entry and add to linked list.
-        shared_vector_desc_t *sh_vec=malloc(sizeof(shared_vector_desc_t));
+        shared_vector_desc_t *sh_vec=heap_caps_malloc(sizeof(shared_vector_desc_t), MALLOC_CAP_INTERNAL | MALLOC_CAP_8BIT);
         if (sh_vec == NULL) {
             portEXIT_CRITICAL(&spinlock);
             free(ret);
@@ -583,7 +583,7 @@ esp_err_t esp_intr_alloc_intrstatus(int source, int flags, uint32_t intrstatusre
         vd->flags = VECDESC_FL_NONSHARED;
         if (handler) {
 #if CONFIG_APPTRACE_SV_ENABLE
-            non_shared_isr_arg_t *ns_isr_arg=malloc(sizeof(non_shared_isr_arg_t));
+            non_shared_isr_arg_t *ns_isr_arg=heap_caps_malloc(sizeof(non_shared_isr_arg_t), MALLOC_CAP_INTERNAL | MALLOC_CAP_8BIT)
             if (!ns_isr_arg) {
                 portEXIT_CRITICAL(&spinlock);
                 free(ret);

Btw, I spot a missing ; at the second change.