From c961738157a668c24db0cdd80de27264bfd120ed Mon Sep 17 00:00:00 2001 From: "Michael.B" Date: Wed, 5 Aug 2026 20:35:47 +0800 Subject: [PATCH] fix(examples): count periodic IRQs during xip_from_psram flash erase Replace the oneshot latency assumption with a 1ms periodic timer that runs only across a forced dirty-partition erase, and fail if irq_count falls below 80% of the expected count from erase duration. --- examples/system/xip_from_psram/README.md | 30 ++-- .../main/xip_from_psram_example_main.c | 130 +++++++++++++----- .../xip_from_psram/pytest_xip_from_psram.py | 59 +++----- 3 files changed, 133 insertions(+), 86 deletions(-) diff --git a/examples/system/xip_from_psram/README.md b/examples/system/xip_from_psram/README.md index 9d14aa67e11..9208252cc6e 100644 --- a/examples/system/xip_from_psram/README.md +++ b/examples/system/xip_from_psram/README.md @@ -27,23 +27,22 @@ To show this feature, in this example we go through the following steps: `General Steps`: 1. Create a partition for Flash Erase Operation -2. Create an esp_timer in one-shot mode +2. Create an ISR-dispatched periodic esp_timer with a 1 ms interval. Overdue + events are skipped so callbacks delayed by the erase are not counted afterward. `PSRAM Steps`: -3. Do a Flash erase operation, and start the timer -4. ESP-Timer callback is dispatched and it calls a function in PSRAM during the flash erase operation -5. The Flash erase operation finishes -6. Show the result about the callback(in PSRAM) response and execute time +3. Program the partition with non-erased data, then start the periodic timer +4. Erase the partition while timer callbacks call a function in PSRAM +5. Stop the timer and wait for any in-flight callback to finish +6. Verify that at least 80% of the expected callbacks ran during the erase `IRAM Steps`: -7. Do a Flash erase operation, and start the timer -8. ESP-Timer callback is dispatched and it calls a function in IRAM during the flash erase operation -9. The flash erase operation finishes -10. Show the result about the callback(in IRAM) response and execute time +7. Repeat the same process with timer callbacks calling a function in IRAM +8. Verify the callback count during the erase ### Timeline -Initialization and config -> Flash erase start -> ESP-Timer callback(in PSRAM) appear -> Flash erase finish -> Flash erase start -> ESP-Timer callback(in IRAM) appear -> Flash erase finish +Initialization and config -> Start periodic timer -> Flash erase with callbacks in PSRAM -> Stop timer -> Start periodic timer -> Flash erase with callbacks in IRAM -> Stop timer ISR CPU | | @@ -76,8 +75,10 @@ Initialization and config -> Flash erase start -> ESP-Timer callback(in PSRAM) a ## Example Result -The ISR which call a function in IRAM happening during Flash erase operations. CPU fetches instructions and data from internal RAM. -The ISR which call a function in PSRAM happening during Flash erase operations and its response time is longer than calling a function in IRAM. That's because fetching instructions from PSRAM takes more time than fetching from IRAM. +The example verifies that ISR-dispatched periodic timer callbacks can continue to +run during flash erase operations when they call functions in either PSRAM or +IRAM. It reports the erase duration, timer interval, actual callback count, and +expected callback count for each case. ## Configure the project @@ -102,9 +103,8 @@ See the [Getting Started Guide](https://docs.espressif.com/projects/esp-idf/en/l I (742) esp_psram: Reserving pool of 32K of internal memory for DMA/internal allocations I (742) example: found partition 'storage1' at offset 0x110000 with size 0x10000 -I (1152) example: callback(in PSRAM) response time: 7 us -I (1362) example: callback(in IRAM) response time: 5 us - +I (...) example: erase with callback in PSRAM: duration_ms=..., interval_ms=1.000, irq_count=..., expected=... +I (...) example: erase with callback in IRAM: duration_ms=..., interval_ms=1.000, irq_count=..., expected=... ``` ## Troubleshooting diff --git a/examples/system/xip_from_psram/main/xip_from_psram_example_main.c b/examples/system/xip_from_psram/main/xip_from_psram_example_main.c index 129a46ca2ce..b5cd4633d01 100644 --- a/examples/system/xip_from_psram/main/xip_from_psram_example_main.c +++ b/examples/system/xip_from_psram/main/xip_from_psram_example_main.c @@ -1,11 +1,13 @@ /* - * SPDX-FileCopyrightText: 2022-2024 Espressif Systems (Shanghai) CO LTD + * SPDX-FileCopyrightText: 2022-2026 Espressif Systems (Shanghai) CO LTD * * SPDX-License-Identifier: Unlicense OR CC0-1.0 */ #include #include #include +#include +#include #include "sdkconfig.h" #include "esp_log.h" #include "esp_cpu.h" @@ -13,64 +15,131 @@ #include "esp_partition.h" #include "esp_flash.h" #include "esp_timer.h" +#include "freertos/FreeRTOS.h" -#if CONFIG_IDF_TARGET_ESP32C5 || CONFIG_IDF_TARGET_ESP32C61 || CONFIG_IDF_TARGET_ESP32S31 -#define EXAMPLE_TIMER_ALERT_TIME (1 * 3 * 1000) -#else -#define EXAMPLE_TIMER_ALERT_TIME (1 * 10 * 1000) -#endif +/* Periodic ISR interval. Dirty 64KB erase is typically tens~hundreds of ms, + * so 1ms yields well above 10 IRQs per erase on supported targets. */ +#define EXAMPLE_TIMER_INTERVAL_US (1000) -static void oneshot_timer_callback(void* arg); +static void periodic_timer_callback(void* arg); static void cb_in_psram(void); static void cb_in_iram(void); static const esp_partition_t *s_get_partition(void); +static esp_err_t s_prepare_partition_for_erase(const esp_partition_t *part); +static esp_err_t s_run_callbacks_during_erase(esp_timer_handle_t timer, bool instructions_in_psram, + const esp_partition_t *part); -static int time_cb_start; //Time when ISR callback start -static int time_cb_end; //Time when ISR callback end +static volatile uint32_t s_irq_count; const static char *TAG = "example"; void app_main(void) { - bool instructions_in_psram = true; //Flags to indicate where the instructions in + bool instructions_in_psram = true; - esp_timer_handle_t oneshot_timer; - const esp_timer_create_args_t oneshot_timer_args = { - .callback = &oneshot_timer_callback, + esp_timer_handle_t periodic_timer; + const esp_timer_create_args_t periodic_timer_args = { + .callback = &periodic_timer_callback, .arg = &instructions_in_psram, .dispatch_method = ESP_TIMER_ISR, - .name = "one-shot" + .name = "periodic", + .skip_unhandled_events = true, }; - ESP_ERROR_CHECK(esp_timer_create(&oneshot_timer_args, &oneshot_timer)); + ESP_ERROR_CHECK(esp_timer_create(&periodic_timer_args, &periodic_timer)); const esp_partition_t *part = s_get_partition(); ESP_LOGI(TAG, "found partition '%s' at offset 0x%"PRIx32" with size 0x%"PRIx32, part->label, part->address, part->size); - ESP_ERROR_CHECK(esp_flash_erase_region(part->flash_chip, part->address, part->size)); - ESP_ERROR_CHECK(esp_timer_start_once(oneshot_timer, EXAMPLE_TIMER_ALERT_TIME)); - ESP_ERROR_CHECK(esp_flash_erase_region(part->flash_chip, part->address, part->size)); - - ESP_LOGI(TAG, "callback(in PSRAM) response time: %d us", time_cb_end - time_cb_start); + instructions_in_psram = true; + ESP_ERROR_CHECK(s_run_callbacks_during_erase(periodic_timer, true, part)); instructions_in_psram = false; + ESP_ERROR_CHECK(s_run_callbacks_during_erase(periodic_timer, false, part)); - ESP_ERROR_CHECK(esp_timer_start_once(oneshot_timer, EXAMPLE_TIMER_ALERT_TIME)); - ESP_ERROR_CHECK(esp_flash_erase_region(part->flash_chip, part->address, part->size)); - - ESP_LOGI(TAG, "callback(in IRAM) response time: %d us", time_cb_end - time_cb_start); - - ESP_ERROR_CHECK(esp_timer_delete(oneshot_timer)); + ESP_ERROR_CHECK(esp_timer_delete(periodic_timer)); } -static IRAM_ATTR void NOINLINE_ATTR oneshot_timer_callback(void* arg) +static esp_err_t s_prepare_partition_for_erase(const esp_partition_t *part) +{ + /* Program non-0xFF data so erase cannot take the already-erased fast path. */ + static uint8_t write_buf[256]; + memset(write_buf, 0xA5, sizeof(write_buf)); + + for (uint32_t offset = 0; offset < part->size; offset += sizeof(write_buf)) { + uint32_t write_size = part->size - offset; + if (write_size > sizeof(write_buf)) { + write_size = sizeof(write_buf); + } + esp_err_t err = esp_flash_write(part->flash_chip, write_buf, part->address + offset, write_size); + if (err != ESP_OK) { + ESP_LOGE(TAG, "failed to program partition before erase: %s", esp_err_to_name(err)); + return err; + } + } + return ESP_OK; +} + +static esp_err_t s_run_callbacks_during_erase(esp_timer_handle_t timer, bool instructions_in_psram, + const esp_partition_t *part) +{ + const char *where = instructions_in_psram ? "PSRAM" : "IRAM"; + + esp_err_t err = s_prepare_partition_for_erase(part); + if (err != ESP_OK) { + return err; + } + + s_irq_count = 0; + + const int64_t t_start_us = esp_timer_get_time(); + err = esp_timer_start_periodic(timer, EXAMPLE_TIMER_INTERVAL_US); + if (err != ESP_OK) { + ESP_LOGE(TAG, "start periodic timer failed: %s", esp_err_to_name(err)); + return err; + } + + esp_err_t erase_err = esp_flash_erase_region(part->flash_chip, part->address, part->size); + + /* Stop immediately after erase returns so later IRQs are not counted. */ + err = esp_timer_stop_blocking(timer, portMAX_DELAY); + if (err != ESP_OK) { + ESP_LOGE(TAG, "stop periodic timer failed: %s", esp_err_to_name(err)); + return err; + } + const int64_t t_end_us = esp_timer_get_time(); + + const uint32_t irq_count = s_irq_count; + const double duration_ms = (double)(t_end_us - t_start_us) / 1000.0; + const double interval_ms = (double)EXAMPLE_TIMER_INTERVAL_US / 1000.0; + const double expected = (double)(t_end_us - t_start_us) / (double)EXAMPLE_TIMER_INTERVAL_US; + + ESP_LOGI(TAG, + "erase with callback in %s: duration_ms=%.3f, interval_ms=%.3f, irq_count=%"PRIu32", expected=%.2f", + where, duration_ms, interval_ms, irq_count, expected); + + if (erase_err != ESP_OK) { + ESP_LOGE(TAG, "flash erase failed: %s", esp_err_to_name(erase_err)); + return erase_err; + } + + if ((double)irq_count < 0.8 * expected) { + ESP_LOGE(TAG, "irq_count=%"PRIu32" < 0.8 * expected(%.2f) during erase (callback in %s)", + irq_count, expected, where); + return ESP_FAIL; + } + + return ESP_OK; +} + +static IRAM_ATTR void NOINLINE_ATTR periodic_timer_callback(void* arg) { bool in_psram = *(bool*) arg; - time_cb_start = esp_timer_get_time(); if (in_psram == true) { cb_in_psram(); - } else { + } else { cb_in_iram(); } + s_irq_count++; } static IRAM_ATTR NOINLINE_ATTR void cb_in_iram(void) @@ -78,7 +147,6 @@ static IRAM_ATTR NOINLINE_ATTR void cb_in_iram(void) for (int i = 0; i < 100; i++) { asm volatile("nop"); } - time_cb_end = esp_timer_get_time(); } static NOINLINE_ATTR void cb_in_psram(void) @@ -86,12 +154,10 @@ static NOINLINE_ATTR void cb_in_psram(void) for (int i = 0; i < 100; i++) { asm volatile("nop"); } - time_cb_end = esp_timer_get_time(); } static const esp_partition_t *s_get_partition(void) { - //Find the "storage1" partition defined in `partitions.csv` const esp_partition_t *result = esp_partition_find_first(ESP_PARTITION_TYPE_DATA, ESP_PARTITION_SUBTYPE_ANY, "storage1"); if (!result) { ESP_LOGE(TAG, "Can't find the partition, please define it correctly in `partitions.csv`"); diff --git a/examples/system/xip_from_psram/pytest_xip_from_psram.py b/examples/system/xip_from_psram/pytest_xip_from_psram.py index 55e3ff9938a..98005f6fc8a 100644 --- a/examples/system/xip_from_psram/pytest_xip_from_psram.py +++ b/examples/system/xip_from_psram/pytest_xip_from_psram.py @@ -6,6 +6,16 @@ from pytest_embedded_idf.utils import idf_parametrize from pytest_embedded_idf.utils import soc_filtered_targets +def _expect_erase_irq_stats(dut: Dut, where: str) -> None: + res = dut.expect( + rf'erase with callback in {where}: duration_ms=(\d+\.\d+), interval_ms=(\d+\.\d+), ' + rf'irq_count=(\d+), expected=(\d+\.\d+)' + ) + irq_count = int(res.group(3).decode('utf8')) + expected = float(res.group(4).decode('utf8')) + assert irq_count >= 0.8 * expected + + @pytest.mark.generic # in order to build the default sdkconfig(the CI won't build the sdkconfig.defaults if there is a sdkconfig.ci.xx) @pytest.mark.parametrize( @@ -18,14 +28,8 @@ from pytest_embedded_idf.utils import soc_filtered_targets @idf_parametrize('target', soc_filtered_targets('SOC_SPIRAM_XIP_SUPPORTED == 1'), indirect=['target']) def test_xip_from_psram_example_generic(dut: Dut) -> None: dut.expect_exact('found partition') - - res = dut.expect(r'callback\(in PSRAM\) response time: (\d{1,3}) us') - response_time = res.group(1).decode('utf8') - assert float(response_time) <= 12 - - res = dut.expect(r'callback\(in IRAM\) response time: (\d{1,3}) us') - response_time = res.group(1).decode('utf8') - assert float(response_time) <= 12 + _expect_erase_irq_stats(dut, 'PSRAM') + _expect_erase_irq_stats(dut, 'IRAM') @pytest.mark.MSPI_F4R8 @@ -39,14 +43,8 @@ def test_xip_from_psram_example_generic(dut: Dut) -> None: @idf_parametrize('target', ['esp32s3'], indirect=['target']) def test_xip_from_psram_example_f4r8(dut: Dut) -> None: dut.expect_exact('found partition') - - res = dut.expect(r'callback\(in PSRAM\) response time: (\d{1,3}) us') - response_time = res.group(1).decode('utf8') - assert float(response_time) <= 12 - - res = dut.expect(r'callback\(in IRAM\) response time: (\d{1,3}) us') - response_time = res.group(1).decode('utf8') - assert float(response_time) <= 12 + _expect_erase_irq_stats(dut, 'PSRAM') + _expect_erase_irq_stats(dut, 'IRAM') @pytest.mark.generic @@ -60,14 +58,9 @@ def test_xip_from_psram_example_f4r8(dut: Dut) -> None: @idf_parametrize('target', ['esp32p4'], indirect=['target']) def test_xip_from_psram_example_p4_200m(dut: Dut) -> None: dut.expect_exact('found partition') + _expect_erase_irq_stats(dut, 'PSRAM') + _expect_erase_irq_stats(dut, 'IRAM') - res = dut.expect(r'callback\(in PSRAM\) response time: (\d{1,3}) us') - response_time = res.group(1).decode('utf8') - assert float(response_time) <= 10 - - res = dut.expect(r'callback\(in IRAM\) response time: (\d{1,3}) us') - response_time = res.group(1).decode('utf8') - assert float(response_time) <= 10 @pytest.mark.flash_120m @pytest.mark.parametrize( @@ -80,14 +73,8 @@ def test_xip_from_psram_example_p4_200m(dut: Dut) -> None: @idf_parametrize('target', ['esp32p4'], indirect=['target']) def test_xip_from_psram_example_p4_250m(dut: Dut) -> None: dut.expect_exact('found partition') - - res = dut.expect(r'callback\(in PSRAM\) response time: (\d{1,3}) us') - response_time = res.group(1).decode('utf8') - assert float(response_time) <= 10 - - res = dut.expect(r'callback\(in IRAM\) response time: (\d{1,3}) us') - response_time = res.group(1).decode('utf8') - assert float(response_time) <= 10 + _expect_erase_irq_stats(dut, 'PSRAM') + _expect_erase_irq_stats(dut, 'IRAM') @pytest.mark.generic @@ -101,11 +88,5 @@ def test_xip_from_psram_example_p4_250m(dut: Dut) -> None: @idf_parametrize('target', ['esp32s31'], indirect=['target']) def test_xip_from_psram_example_s31(dut: Dut) -> None: dut.expect_exact('found partition') - - res = dut.expect(r'callback\(in PSRAM\) response time: (\d{1,3}) us') - response_time = res.group(1).decode('utf8') - assert float(response_time) <= 5 - - res = dut.expect(r'callback\(in IRAM\) response time: (\d{1,3}) us') - response_time = res.group(1).decode('utf8') - assert float(response_time) <= 5 + _expect_erase_irq_stats(dut, 'PSRAM') + _expect_erase_irq_stats(dut, 'IRAM')