Mirrors/esp-idf
1
0
Fork 0
mirror of https://github.com/espressif/esp-idf.git synced 2026-09-22 13:01:16 +03:00
Code Issues Packages Projects Releases Wiki Activity

fix(examples): count periodic IRQs during xip_from_psram flash erase

Browse Source 
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.
This commit is contained in:
Michael.B
2026-08-05 20:35:47 +08:00
committed by Armando (Dou Yiwen)
parent a434dc5173
commit c961738157
3 changed files with 133 additions and 86 deletions
Download Patch File Download Diff File Expand all files Collapse all files

30
examples/system/xip_from_psram/README.md
View File

@@ -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

130
examples/system/xip_from_psram/main/xip_from_psram_example_main.c
View File

@@ -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 <stdio.h>
#include <stdlib.h>
#include <stdbool.h>
#include <string.h>
#include <inttypes.h>
#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`");

59
examples/system/xip_from_psram/pytest_xip_from_psram.py
View File

@@ -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')