From 1b0b5ece9774d47142e1f5fbc22393b99ecd621c Mon Sep 17 00:00:00 2001 From: "C.S.M" Date: Tue, 16 Sep 2025 11:45:20 +0800 Subject: [PATCH] fix(flash): Modify the log safety in timing tuning --- .../mspi_timing_tuning/mspi_timing_tuning.c | 10 +++-- .../port/esp32c5/mspi_timing_config.c | 8 ++-- .../port/esp32c61/mspi_timing_config.c | 8 ++-- .../port/esp32p4/mspi_timing_config.c | 2 +- .../port/esp32s3/mspi_timing_by_mspi_delay.c | 42 +++++++++---------- .../tuning_scheme_impl/mspi_timing_by_dqs.c | 14 +++---- .../mspi_timing_by_flash_delay.c | 12 +++--- .../mspi_timing_by_mspi_delay.c | 18 ++++---- .../test_apps/mspi/main/test_mspi.c | 3 ++ .../test_apps/mspi/pytest_flash_psram.py | 14 +++++++ ...dkconfig.ci.esp32p4_timing_tuning_log_safe | 10 +++++ ...fig.ci.esp32s3_f4r4_timing_tuning_log_safe | 15 +++++++ ...dkconfig.ci.generic_timing_tuning_log_safe | 5 +++ 13 files changed, 105 insertions(+), 56 deletions(-) create mode 100644 components/esp_hw_support/test_apps/mspi/sdkconfig.ci.esp32p4_timing_tuning_log_safe create mode 100644 components/esp_hw_support/test_apps/mspi/sdkconfig.ci.esp32s3_f4r4_timing_tuning_log_safe create mode 100644 components/esp_hw_support/test_apps/mspi/sdkconfig.ci.generic_timing_tuning_log_safe diff --git a/components/esp_hw_support/mspi_timing_tuning/mspi_timing_tuning.c b/components/esp_hw_support/mspi_timing_tuning/mspi_timing_tuning.c index f6b2c39651..62e9d301ae 100644 --- a/components/esp_hw_support/mspi_timing_tuning/mspi_timing_tuning.c +++ b/components/esp_hw_support/mspi_timing_tuning/mspi_timing_tuning.c @@ -233,16 +233,16 @@ static void s_sweep_for_success_sample_points(uint8_t *reference_data, void *con #endif if (memcmp(reference_data, read_data, sizeof(read_data)) == 0) { out_array[config_idx] += 1; - ESP_EARLY_LOGV(TAG, "config_idx: %d, good", config_idx); + ESP_DRAM_LOGV(TAG, "config_idx: %d, good", config_idx); } else { - ESP_EARLY_LOGV(TAG, "config_idx: %d, bad", config_idx); + ESP_DRAM_LOGV(TAG, "config_idx: %d, bad", config_idx); } } } - ESP_EARLY_LOGD(TAG, "test nums: %" PRIu32 ", test result: [id][good/bad][good_times]:", s_tuning_cfg_drv.sweep_test_nums); + ESP_DRAM_LOGD(TAG, "test nums: %" PRIu32 ", test result: [id][good/bad][good_times]:", s_tuning_cfg_drv.sweep_test_nums); for (config_idx = 0; config_idx < timing_config->available_config_num; config_idx++) { - ESP_EARLY_LOGD(TAG, "[%"PRIu32"][%s][%" PRIu32 "] ", config_idx, out_array[config_idx] == s_tuning_cfg_drv.sweep_test_nums ? "good" : "bad", out_array[config_idx]); + ESP_DRAM_LOGD(TAG, "[%"PRIu32"][%s][%" PRIu32 "] ", config_idx, out_array[config_idx] == s_tuning_cfg_drv.sweep_test_nums ? "good" : "bad", out_array[config_idx]); } } @@ -349,6 +349,7 @@ void mspi_timing_flash_tuning(void) * set MSPI related regs to 20mhz configuration, to get reference data from FLASH * see detailed comments in this function (`mspi_timing_enter_low_speed_mode`) */ + ESP_EARLY_LOGI(TAG, "Enter flash timing tuning"); mspi_timing_enter_low_speed_mode(true); #if SOC_MEMSPI_TIMING_TUNING_BY_MSPI_DELAY || SOC_MEMSPI_TIMING_TUNING_BY_FLASH_DELAY @@ -397,6 +398,7 @@ void mspi_timing_psram_tuning(void) * set MSPI related regs to 20mhz configuration, to write reference data to PSRAM * see detailed comments in this function (`mspi_timing_enter_low_speed_mode`) */ + ESP_EARLY_LOGI(TAG, "Enter psram timing tuning"); mspi_timing_enter_low_speed_mode(true); // write data into psram, used to do timing tuning test. diff --git a/components/esp_hw_support/mspi_timing_tuning/port/esp32c5/mspi_timing_config.c b/components/esp_hw_support/mspi_timing_tuning/port/esp32c5/mspi_timing_config.c index 0d1474060b..97ccddfd1e 100644 --- a/components/esp_hw_support/mspi_timing_tuning/port/esp32c5/mspi_timing_config.c +++ b/components/esp_hw_support/mspi_timing_tuning/port/esp32c5/mspi_timing_config.c @@ -27,13 +27,13 @@ const static char *TAG = "MSPI Timing"; //-------------------------------------MSPI Clock Setting-------------------------------------// static void s_mspi_flash_set_core_clock(uint8_t mspi_id, uint32_t core_clock_mhz) { - ESP_EARLY_LOGV(TAG, "flash core clock: %d", core_clock_mhz); + ESP_DRAM_LOGV(TAG, "flash core clock: %d", core_clock_mhz); mspi_timing_ll_set_core_clock(mspi_id, core_clock_mhz); } static void s_mspi_psram_set_core_clock(uint8_t mspi_id, uint32_t core_clock_mhz) { - ESP_EARLY_LOGV(TAG, "psram core clock: %d", core_clock_mhz); + ESP_DRAM_LOGV(TAG, "psram core clock: %d", core_clock_mhz); mspi_timing_ll_set_core_clock(mspi_id, core_clock_mhz); } @@ -49,7 +49,7 @@ void mspi_timing_config_set_flash_clock(uint32_t flash_freq_mhz, mspi_timing_spe s_mspi_flash_set_core_clock(MSPI_TIMING_LL_MSPI_ID_0, core_clock_mhz); uint32_t freqdiv = core_clock_mhz / flash_freq_mhz; - ESP_EARLY_LOGV(TAG, "flash freqdiv: %d", freqdiv); + ESP_DRAM_LOGV(TAG, "flash freqdiv: %d", freqdiv); assert(freqdiv > 0); uint32_t reg_val = mspi_timing_ll_calculate_clock_reg(freqdiv); mspi_timing_ll_set_flash_clock(MSPI_TIMING_LL_MSPI_ID_0, reg_val); @@ -71,7 +71,7 @@ void mspi_timing_config_set_psram_clock(uint32_t psram_freq_mhz, mspi_timing_spe s_mspi_psram_set_core_clock(MSPI_TIMING_LL_MSPI_ID_0, core_clock_mhz); uint32_t freqdiv = core_clock_mhz / psram_freq_mhz; - ESP_EARLY_LOGV(TAG, "psram freqdiv: %d", freqdiv); + ESP_DRAM_LOGV(TAG, "psram freqdiv: %d", freqdiv); assert(freqdiv > 0); uint32_t reg_val = mspi_timing_ll_calculate_clock_reg(freqdiv); mspi_timing_ll_set_psram_clock(MSPI_TIMING_LL_MSPI_ID_0, reg_val); diff --git a/components/esp_hw_support/mspi_timing_tuning/port/esp32c61/mspi_timing_config.c b/components/esp_hw_support/mspi_timing_tuning/port/esp32c61/mspi_timing_config.c index 0d1474060b..97ccddfd1e 100644 --- a/components/esp_hw_support/mspi_timing_tuning/port/esp32c61/mspi_timing_config.c +++ b/components/esp_hw_support/mspi_timing_tuning/port/esp32c61/mspi_timing_config.c @@ -27,13 +27,13 @@ const static char *TAG = "MSPI Timing"; //-------------------------------------MSPI Clock Setting-------------------------------------// static void s_mspi_flash_set_core_clock(uint8_t mspi_id, uint32_t core_clock_mhz) { - ESP_EARLY_LOGV(TAG, "flash core clock: %d", core_clock_mhz); + ESP_DRAM_LOGV(TAG, "flash core clock: %d", core_clock_mhz); mspi_timing_ll_set_core_clock(mspi_id, core_clock_mhz); } static void s_mspi_psram_set_core_clock(uint8_t mspi_id, uint32_t core_clock_mhz) { - ESP_EARLY_LOGV(TAG, "psram core clock: %d", core_clock_mhz); + ESP_DRAM_LOGV(TAG, "psram core clock: %d", core_clock_mhz); mspi_timing_ll_set_core_clock(mspi_id, core_clock_mhz); } @@ -49,7 +49,7 @@ void mspi_timing_config_set_flash_clock(uint32_t flash_freq_mhz, mspi_timing_spe s_mspi_flash_set_core_clock(MSPI_TIMING_LL_MSPI_ID_0, core_clock_mhz); uint32_t freqdiv = core_clock_mhz / flash_freq_mhz; - ESP_EARLY_LOGV(TAG, "flash freqdiv: %d", freqdiv); + ESP_DRAM_LOGV(TAG, "flash freqdiv: %d", freqdiv); assert(freqdiv > 0); uint32_t reg_val = mspi_timing_ll_calculate_clock_reg(freqdiv); mspi_timing_ll_set_flash_clock(MSPI_TIMING_LL_MSPI_ID_0, reg_val); @@ -71,7 +71,7 @@ void mspi_timing_config_set_psram_clock(uint32_t psram_freq_mhz, mspi_timing_spe s_mspi_psram_set_core_clock(MSPI_TIMING_LL_MSPI_ID_0, core_clock_mhz); uint32_t freqdiv = core_clock_mhz / psram_freq_mhz; - ESP_EARLY_LOGV(TAG, "psram freqdiv: %d", freqdiv); + ESP_DRAM_LOGV(TAG, "psram freqdiv: %d", freqdiv); assert(freqdiv > 0); uint32_t reg_val = mspi_timing_ll_calculate_clock_reg(freqdiv); mspi_timing_ll_set_psram_clock(MSPI_TIMING_LL_MSPI_ID_0, reg_val); diff --git a/components/esp_hw_support/mspi_timing_tuning/port/esp32p4/mspi_timing_config.c b/components/esp_hw_support/mspi_timing_tuning/port/esp32p4/mspi_timing_config.c index b0f0330288..d99b6558cf 100644 --- a/components/esp_hw_support/mspi_timing_tuning/port/esp32p4/mspi_timing_config.c +++ b/components/esp_hw_support/mspi_timing_tuning/port/esp32p4/mspi_timing_config.c @@ -25,7 +25,7 @@ void mspi_timing_config_set_psram_clock(uint32_t psram_freq_mhz, mspi_timing_spe { uint32_t freqdiv = MSPI_TIMING_MPLL_FREQ_MHZ / MSPI_TIMING_CORE_CLOCK_DIV / psram_freq_mhz; assert(freqdiv > 0); - ESP_EARLY_LOGD(TAG, "psram_freq_mhz: %" PRIu32 " mhz, bus clock div: %" PRIu32, psram_freq_mhz, freqdiv); + ESP_DRAM_LOGD(TAG, "psram_freq_mhz: %" PRIu32 " mhz, bus clock div: %" PRIu32, psram_freq_mhz, freqdiv); PERIPH_RCC_ATOMIC() { //MSPI2 and MSPI3 share the register for core clock. So we only set MSPI2 here. psram_ctrlr_ll_enable_core_clock(PSRAM_CTRLR_LL_MSPI_ID_2, true); diff --git a/components/esp_hw_support/mspi_timing_tuning/port/esp32s3/mspi_timing_by_mspi_delay.c b/components/esp_hw_support/mspi_timing_tuning/port/esp32s3/mspi_timing_by_mspi_delay.c index cde0bafafa..b00e8d1581 100644 --- a/components/esp_hw_support/mspi_timing_tuning/port/esp32s3/mspi_timing_by_mspi_delay.c +++ b/components/esp_hw_support/mspi_timing_tuning/port/esp32s3/mspi_timing_by_mspi_delay.c @@ -1,5 +1,5 @@ /* - * SPDX-FileCopyrightText: 2023-2024 Espressif Systems (Shanghai) CO LTD + * SPDX-FileCopyrightText: 2023-2025 Espressif Systems (Shanghai) CO LTD * * SPDX-License-Identifier: Apache-2.0 */ @@ -434,15 +434,15 @@ static uint32_t s_select_best_tuning_config_dtr(const mspi_timing_config_t *conf if (consecutive_length <= 2 || consecutive_length >= 6) { //tuning is FAIL, select default point, and generate a warning best_point = configs->default_config_id; - ESP_EARLY_LOGW(TAG, "tuning fail, best point is fallen back to index %"PRIu32"", best_point); + ESP_DRAM_LOGW(TAG, "tuning fail, best point is fallen back to index %"PRIu32"", best_point); } else if (consecutive_length <= 4) { //consecutive length : 3 or 4 best_point = end - 1; - ESP_EARLY_LOGD(TAG, "tuning success, best point is index %"PRIu32"", best_point); + ESP_DRAM_LOGD(TAG, "tuning success, best point is index %"PRIu32"", best_point); } else { //consecutive point list length equals 5 best_point = end - 2; - ESP_EARLY_LOGD(TAG, "tuning success, best point is index %"PRIu32"", best_point); + ESP_DRAM_LOGD(TAG, "tuning success, best point is index %"PRIu32"", best_point); } return best_point; @@ -471,13 +471,13 @@ static uint32_t s_select_best_tuning_config_dtr(const mspi_timing_config_t *conf max_freq = temp_max_freq; best_point = current_point; } - ESP_EARLY_LOGD(TAG, "sample point %" PRIu32 ", max pll is %" PRIu32 " mhz, min pll is %" PRIu32, current_point, temp_max_freq, temp_min_freq); + ESP_DRAM_LOGD(TAG, "sample point %" PRIu32 ", max pll is %" PRIu32 " mhz, min pll is %" PRIu32, current_point, temp_max_freq, temp_min_freq); } if (max_freq == 0) { - ESP_EARLY_LOGW(TAG, "freq scan tuning fail, best point is fallen back to index %" PRIu32, end + 1 - consecutive_length); + ESP_DRAM_LOGW(TAG, "freq scan tuning fail, best point is fallen back to index %" PRIu32, end + 1 - consecutive_length); best_point = end + 1 - consecutive_length; } else { - ESP_EARLY_LOGD(TAG, "freq scan success, max pll is %" PRIu32 "mhz, best point is index %" PRIu32, max_freq, best_point); + ESP_DRAM_LOGD(TAG, "freq scan success, max pll is %" PRIu32 "mhz, best point is index %" PRIu32, max_freq, best_point); } #else uint32_t freq_diff_min = 0xffffffff; @@ -501,7 +501,7 @@ static uint32_t s_select_best_tuning_config_dtr(const mspi_timing_config_t *conf psram_pass_freq_min[current_point] = temp_min_freq / 4; psram_pass_freq_max[current_point] = temp_max_freq / 4; } - ESP_EARLY_LOGD(TAG, "sample point %" PRIu32 ", max pll is %" PRIu32 " mhz, min pll is %" PRIu32 " mhz, max spi is %" PRIu32 " mhz, min spi is %" PRIu32 " mhz", current_point, temp_max_freq, temp_min_freq, psram_pass_freq_max[current_point], psram_pass_freq_min[current_point]); + ESP_DRAM_LOGD(TAG, "sample point %" PRIu32 ", max pll is %" PRIu32 " mhz, min pll is %" PRIu32 " mhz, max spi is %" PRIu32 " mhz, min spi is %" PRIu32 " mhz", current_point, temp_max_freq, temp_min_freq, psram_pass_freq_max[current_point], psram_pass_freq_min[current_point]); // calculate the difference to psram_pass_freq and 120MHz int temp_min_freq_diff = abs(120 - psram_pass_freq_min[current_point]); @@ -514,10 +514,10 @@ static uint32_t s_select_best_tuning_config_dtr(const mspi_timing_config_t *conf } } if (freq_diff_min == 0xffffffff) { - ESP_EARLY_LOGW(TAG, "freq scan tuning fail, best point is fallen back to index %" PRIu32, end + 1 - consecutive_length); + ESP_DRAM_LOGW(TAG, "freq scan tuning fail, best point is fallen back to index %" PRIu32, end + 1 - consecutive_length); best_point = end + 1 - consecutive_length; } else { - ESP_EARLY_LOGD(TAG, "freq scan success, best point is index %" PRIu32, best_point); + ESP_DRAM_LOGD(TAG, "freq scan success, best point is index %" PRIu32, best_point); } #endif @@ -539,11 +539,11 @@ static uint32_t s_select_best_tuning_config_str(const mspi_timing_config_t *conf if (consecutive_length <= 2|| consecutive_length >= 5) { //tuning is FAIL, select default point, and generate a warning best_point = configs->default_config_id; - ESP_EARLY_LOGW(TAG, "tuning fail, best point is fallen back to index %"PRIu32"", best_point); + ESP_DRAM_LOGW(TAG, "tuning fail, best point is fallen back to index %"PRIu32"", best_point); } else { //consecutive length : 3 or 4 best_point = end - consecutive_length / 2; - ESP_EARLY_LOGD(TAG, "tuning success, best point is index %"PRIu32"", best_point); + ESP_DRAM_LOGD(TAG, "tuning success, best point is index %"PRIu32"", best_point); } return best_point; @@ -569,7 +569,7 @@ uint32_t mspi_timing_flash_select_best_tuning_config(const void *configs, uint32 { const mspi_timing_config_t *timing_configs = (const mspi_timing_config_t *)configs; uint32_t best_point = s_select_best_tuning_config(timing_configs, consecutive_length, end, reference_data, is_ddr, true); - ESP_EARLY_LOGI(TAG, "Flash timing tuning index: %"PRIu32"", best_point); + ESP_DRAM_LOGD(TAG, "Flash timing tuning index: %"PRIu32"", best_point); return best_point; } @@ -578,7 +578,7 @@ uint32_t mspi_timing_psram_select_best_tuning_config(const void *configs, uint32 { const mspi_timing_config_t *timing_configs = (const mspi_timing_config_t *)configs; uint32_t best_point = s_select_best_tuning_config(timing_configs, consecutive_length, end, reference_data, is_ddr, false); - ESP_EARLY_LOGI(TAG, "PSRAM timing tuning index: %"PRIu32"", best_point); + ESP_DRAM_LOGD(TAG, "PSRAM timing tuning index: %"PRIu32"", best_point); return best_point; } @@ -799,7 +799,7 @@ void adjust_psram_timing_point_task(void *arg) if (valid_point[point] && valid_point[point + 1]) { // check temperature intersection if (s_point_temp_range_max[point] <= s_point_temp_range_min[point + 1]) { - ESP_EARLY_LOGE(TAG, "no temperature intersection of neighboring phase points"); + ESP_DRAM_LOGE(TAG, "no temperature intersection of neighboring phase points"); abort(); } } @@ -810,7 +810,7 @@ void adjust_psram_timing_point_task(void *arg) point_curr = s_psram_best_point_idx; temperature_sensor_get_celsius_filtered(&temp_curr); - ESP_EARLY_LOGD(TAG, "Getting current temperature value is: %d", temp_curr); + ESP_DRAM_LOGD(TAG, "Getting current temperature value is: %d", temp_curr); // Switch timing point if temperature is beyond the range if (s_point_temp_range_max[point_curr] == 0 && s_point_temp_range_min[point_curr] == 0) { @@ -824,7 +824,7 @@ void adjust_psram_timing_point_task(void *arg) if (temp_curr < (s_point_temp_range_max[point_curr - 1] - temperature_safe_range)) { int point_next = point_curr - 1; set_timing_point(point_next); - ESP_EARLY_LOGD(TAG, "PSRAM set timing point from %d to %ld\n", point_curr, point_next); + ESP_DRAM_LOGD(TAG, "PSRAM set timing point from %d to %ld\n", point_curr, point_next); continue; } } @@ -836,7 +836,7 @@ void adjust_psram_timing_point_task(void *arg) if (temp_curr > s_point_temp_range_min[point_curr + 1] + temperature_safe_range) { int point_next = point_curr + 1; set_timing_point(point_next); - ESP_EARLY_LOGD(TAG, "PSRAM set timing point from %d to %ld\n", point_curr, point_next); + ESP_DRAM_LOGD(TAG, "PSRAM set timing point from %d to %ld\n", point_curr, point_next); continue; } } @@ -847,7 +847,7 @@ void adjust_psram_timing_point_task(void *arg) if (temp_curr > s_point_temp_range_max[point_curr]) { int point_next = point_curr + 1; set_timing_point(point_next); - ESP_EARLY_LOGD(TAG, "PSRAM set timing point from %d to %ld\n", point_curr, point_next); + ESP_DRAM_LOGD(TAG, "PSRAM set timing point from %d to %ld\n", point_curr, point_next); continue; } } @@ -857,7 +857,7 @@ void adjust_psram_timing_point_task(void *arg) if (temp_curr < s_point_temp_range_min[point_curr]) { int point_next = point_curr - 1; set_timing_point(point_next); - ESP_EARLY_LOGD(TAG, "PSRAM set timing point from %d to %ld\n", point_curr, point_next); + ESP_DRAM_LOGD(TAG, "PSRAM set timing point from %d to %ld\n", point_curr, point_next); continue; } } @@ -872,7 +872,7 @@ static esp_err_t psram_adjust_timing_point_via_tsens(void) if (vender_id == 0xC8 || vender_id == 0x20) { xTaskCreatePinnedToCore(adjust_psram_timing_point_task, "adjust_psram_timing_point_task", 1024 * 5, NULL, configMAX_PRIORITIES - 2, NULL, 0); } else { - ESP_EARLY_LOGE(TAG, "The flash model has not been verified support this feature, please contact espressif business support"); + ESP_DRAM_LOGE(TAG, "The flash model has not been verified support this feature, please contact espressif business support"); return ESP_ERR_NOT_SUPPORTED; } return ESP_OK; diff --git a/components/esp_hw_support/mspi_timing_tuning/tuning_scheme_impl/mspi_timing_by_dqs.c b/components/esp_hw_support/mspi_timing_tuning/tuning_scheme_impl/mspi_timing_by_dqs.c index 78a09d422f..79ec3b0db9 100644 --- a/components/esp_hw_support/mspi_timing_tuning/tuning_scheme_impl/mspi_timing_by_dqs.c +++ b/components/esp_hw_support/mspi_timing_tuning/tuning_scheme_impl/mspi_timing_by_dqs.c @@ -122,7 +122,7 @@ void mspi_timing_config_psram_set_tuning_phase(const void *configs, uint8_t id) mspi_ll_dqs_phase_t phase = ((mspi_timing_config_t *)configs)->phase[id]; mspi_timing_ll_set_dqs_phase(MSPI_LL_DQS_ID_0, phase); mspi_timing_ll_set_dqs_phase(MSPI_LL_DQS_ID_1, phase); - ESP_EARLY_LOGD(TAG, "set to phase: %d", phase); + ESP_DRAM_LOGD(TAG, "set to phase: %d", phase); } uint32_t mspi_timing_psram_select_best_tuning_phase(const void *configs, uint32_t consecutive_length, uint32_t end, const uint8_t *reference_data, bool is_ddr) @@ -139,9 +139,9 @@ uint32_t mspi_timing_psram_select_best_tuning_phase(const void *configs, uint32_ } if (success) { - ESP_EARLY_LOGI(TAG, "tuning success, best phase id is %"PRIu32, best_phase_id); + ESP_DRAM_LOGD(TAG, "tuning success, best phase id is %"PRIu32, best_phase_id); } else { - ESP_EARLY_LOGW(TAG, "tuning fail, best phase id is fallen back to index %"PRIu32"", best_phase_id); + ESP_DRAM_LOGW(TAG, "tuning fail, best phase id is fallen back to index %"PRIu32"", best_phase_id); } return best_phase_id; @@ -154,7 +154,7 @@ void mspi_timing_psram_set_best_tuning_phase(const void *configs, uint8_t best_i void mspi_timing_get_psram_tuning_delaylines(mspi_timing_config_t *configs) { - ESP_EARLY_LOGD(TAG, "sizeof(delayline_config_t): %d, sizeof(test_config): %d", sizeof(delayline_config_t), sizeof(s_test_delayline_config)); + ESP_DRAM_LOGD(TAG, "sizeof(delayline_config_t): %d, sizeof(test_config): %d", sizeof(delayline_config_t), sizeof(s_test_delayline_config)); memcpy(configs, &s_test_delayline_config, sizeof(s_test_delayline_config)); } @@ -163,7 +163,7 @@ void mspi_timing_config_psram_set_tuning_delayline(const void *configs, uint8_t assert(s_psram_best_phase != MSPI_LL_DQS_PHASE_MAX); mspi_timing_ll_set_dqs_phase(MSPI_LL_DQS_ID_0, s_psram_best_phase); mspi_timing_ll_set_dqs_phase(MSPI_LL_DQS_ID_1, s_psram_best_phase); - ESP_EARLY_LOGD(TAG, "set to best phase: %d", s_psram_best_phase); + ESP_DRAM_LOGD(TAG, "set to best phase: %d", s_psram_best_phase); const delayline_config_t *delayline_config = &((mspi_timing_config_t *)configs)->delayline_table[id]; for (int i = 0; i < MSPI_LL_PIN_MAX; i++) { @@ -182,10 +182,10 @@ uint32_t mspi_timing_psram_select_best_tuning_delayline(const void *configs, uin if (consecutive_length <= 1) { bset_delayline_id = 0; - ESP_EARLY_LOGW(TAG, "tuning fail, best delayline id is fallen back to index %"PRIu32"", bset_delayline_id); + ESP_DRAM_LOGW(TAG, "tuning fail, best delayline id is fallen back to index %"PRIu32"", bset_delayline_id); } else { bset_delayline_id = end - consecutive_length / 2; - ESP_EARLY_LOGI(TAG, "tuning success, best delayline id is %"PRIu32, bset_delayline_id); + ESP_DRAM_LOGD(TAG, "tuning success, best delayline id is %"PRIu32, bset_delayline_id); } return bset_delayline_id; diff --git a/components/esp_hw_support/mspi_timing_tuning/tuning_scheme_impl/mspi_timing_by_flash_delay.c b/components/esp_hw_support/mspi_timing_tuning/tuning_scheme_impl/mspi_timing_by_flash_delay.c index e99ada255d..3d158a1afc 100644 --- a/components/esp_hw_support/mspi_timing_tuning/tuning_scheme_impl/mspi_timing_by_flash_delay.c +++ b/components/esp_hw_support/mspi_timing_tuning/tuning_scheme_impl/mspi_timing_by_flash_delay.c @@ -34,7 +34,7 @@ void mspi_timing_flash_init(uint32_t flash_freq_mhz) //Power on HCLK mspi_timinng_ll_enable_flash_timing_adjust_clk(MSPI_TIMING_LL_MSPI_ID_0); - ESP_EARLY_LOGD(TAG, "init rom dummy val: %d", g_rom_spiflash_dummy_len_plus[1]); + ESP_DRAM_LOGD(TAG, "init rom dummy val: %d", g_rom_spiflash_dummy_len_plus[1]); } //-------------------------------------FLASH timing tuning register config-------------------------------------// @@ -84,7 +84,7 @@ void mspi_timing_config_flash_read_data(uint8_t *buf, uint32_t addr, uint32_t le int spi0_extra_dummy = 0; mspi_timing_ll_get_flash_dummy(MSPI_TIMING_LL_MSPI_ID_0, &spi0_usr_dummy, &spi0_extra_dummy); mspi_timing_ll_get_flash_dummy(MSPI_TIMING_LL_MSPI_ID_1, &spi1_usr_dummy, &spi1_extra_dummy); - ESP_EARLY_LOGD(TAG, "spi0_usr_dummy: %d, spi0_extra_dummy: %d, spi1_usr_dummy: %d, spi1_extra_dummy: %d", spi0_usr_dummy, spi0_extra_dummy, spi1_usr_dummy, spi1_extra_dummy); + ESP_DRAM_LOGD(TAG, "spi0_usr_dummy: %d, spi0_extra_dummy: %d, spi1_usr_dummy: %d, spi1_extra_dummy: %d", spi0_usr_dummy, spi0_extra_dummy, spi1_usr_dummy, spi1_extra_dummy); } /*------------------------------------------------------------------------------------------------- @@ -98,10 +98,10 @@ static uint32_t s_select_best_tuning_config_str(const mspi_timing_config_t *conf if (consecutive_length < 3) { //tuning fails, select default point, and generate a warning best_point = configs->flash_default_config_id; - ESP_EARLY_LOGW(TAG, "tuning fail, best point is fallen back to index %"PRIu32"", best_point); + ESP_DRAM_LOGW(TAG, "tuning fail, best point is fallen back to index %"PRIu32"", best_point); } else { best_point = end - consecutive_length / 2; - ESP_EARLY_LOGI(TAG, "tuning success, best point is index %"PRIu32"", best_point); + ESP_DRAM_LOGD(TAG, "tuning success, best point is index %"PRIu32"", best_point); } return best_point; @@ -120,7 +120,7 @@ uint32_t mspi_timing_flash_select_best_tuning_config(const void *configs, uint32 { const mspi_timing_config_t *timing_configs = (const mspi_timing_config_t *)configs; uint32_t best_point = s_select_best_tuning_config(timing_configs, consecutive_length, end, reference_data, is_ddr, true); - ESP_EARLY_LOGI(TAG, "Flash timing tuning index: %"PRIu32"", best_point); + ESP_DRAM_LOGD(TAG, "Flash timing tuning index: %"PRIu32"", best_point); return best_point; } @@ -174,7 +174,7 @@ void mspi_timing_flash_config_set_tuning_regs(bool control_both_mspi) int spi0_extra_dummy = 0; mspi_timing_ll_get_flash_dummy(MSPI_TIMING_LL_MSPI_ID_0, &spi0_usr_dummy, &spi0_extra_dummy); mspi_timing_ll_get_flash_dummy(MSPI_TIMING_LL_MSPI_ID_1, &spi1_usr_dummy, &spi1_extra_dummy); - ESP_EARLY_LOGD(TAG, "spi0_usr_dummy: %d, spi0_extra_dummy: %d, spi1_usr_dummy: %d, spi1_extra_dummy: %d", spi0_usr_dummy, spi0_extra_dummy, spi1_usr_dummy, spi1_extra_dummy); + ESP_DRAM_LOGD(TAG, "spi0_usr_dummy: %d, spi0_extra_dummy: %d, spi1_usr_dummy: %d, spi1_extra_dummy: %d", spi0_usr_dummy, spi0_extra_dummy, spi1_usr_dummy, spi1_extra_dummy); } /*------------------------------------------------------------------------------------------------- diff --git a/components/esp_hw_support/mspi_timing_tuning/tuning_scheme_impl/mspi_timing_by_mspi_delay.c b/components/esp_hw_support/mspi_timing_tuning/tuning_scheme_impl/mspi_timing_by_mspi_delay.c index 907a596fa6..ca3efb5b49 100644 --- a/components/esp_hw_support/mspi_timing_tuning/tuning_scheme_impl/mspi_timing_by_mspi_delay.c +++ b/components/esp_hw_support/mspi_timing_tuning/tuning_scheme_impl/mspi_timing_by_mspi_delay.c @@ -181,7 +181,7 @@ static void psram_exec_cmd(int mspi_id, psram_cmd_mode_t mode, static void s_psram_write_data(uint8_t *buf, uint32_t addr, uint32_t len) { if (len % FIFO_SIZE_BYTE != 0) { - ESP_EARLY_LOGE(TAG, "wrong length %d", len); + ESP_DRAM_LOGE(TAG, "wrong length %d", len); assert(false); } @@ -206,7 +206,7 @@ static void s_psram_write_data(uint8_t *buf, uint32_t addr, uint32_t len) static void s_psram_read_data(uint8_t *buf, uint32_t addr, uint32_t len) { if (len % FIFO_SIZE_BYTE != 0) { - ESP_EARLY_LOGE(TAG, "wrong length %d", len); + ESP_DRAM_LOGE(TAG, "wrong length %d", len); assert(false); } @@ -272,17 +272,17 @@ static uint32_t s_select_best_tuning_config_str(const mspi_timing_config_t *conf if (consecutive_length < 3) { //tuning is FAIL, select default point, and generate a warning best_point = configs->default_config_id; - ESP_EARLY_LOGW(TAG, "tuning fail, best point is fallen back to index %"PRIu32"", best_point); + ESP_DRAM_LOGW(TAG, "tuning fail, best point is fallen back to index %"PRIu32"", best_point); } #if MSPI_TIMING_FLASH_CONSECUTIVE_LEN_MAX else if (consecutive_length > MSPI_TIMING_FLASH_CONSECUTIVE_LEN_MAX) { best_point = configs->default_config_id; - ESP_EARLY_LOGW(TAG, "tuning fail, best point is fallen back to index %"PRIu32"", best_point); + ESP_DRAM_LOGW(TAG, "tuning fail, best point is fallen back to index %"PRIu32"", best_point); } #endif else { best_point = end - consecutive_length / 2; - ESP_EARLY_LOGI(TAG, "tuning success, best point is index %"PRIu32"", best_point); + ESP_DRAM_LOGD(TAG, "tuning success, best point is index %"PRIu32"", best_point); } return best_point; @@ -301,7 +301,7 @@ uint32_t mspi_timing_flash_select_best_tuning_config(const void *configs, uint32 { const mspi_timing_config_t *timing_configs = (const mspi_timing_config_t *)configs; uint32_t best_point = s_select_best_tuning_config(timing_configs, consecutive_length, end, reference_data, is_ddr, true); - ESP_EARLY_LOGI(TAG, "Flash timing tuning index: %"PRIu32"", best_point); + ESP_DRAM_LOGD(TAG, "Flash timing tuning index: %"PRIu32"", best_point); return best_point; } @@ -310,7 +310,7 @@ uint32_t mspi_timing_psram_select_best_tuning_config(const void *configs, uint32 { const mspi_timing_config_t *timing_configs = (const mspi_timing_config_t *)configs; uint32_t best_point = s_select_best_tuning_config(timing_configs, consecutive_length, end, reference_data, is_ddr, false); - ESP_EARLY_LOGI(TAG, "PSRAM timing tuning index: %"PRIu32"", best_point); + ESP_DRAM_LOGD(TAG, "PSRAM timing tuning index: %"PRIu32"", best_point); return best_point; } @@ -359,7 +359,7 @@ void mspi_timing_flash_config_set_tuning_regs(bool control_both_mspi) int spi0_extra_dummy = 0; mspi_timing_ll_get_flash_dummy(MSPI_TIMING_LL_MSPI_ID_0, &spi0_usr_dummy, &spi0_extra_dummy); mspi_timing_ll_get_flash_dummy(MSPI_TIMING_LL_MSPI_ID_1, &spi1_usr_dummy, &spi1_extra_dummy); - ESP_EARLY_LOGV(TAG, "flash, spi0_usr_dummy: %d, spi0_extra_dummy: %d, spi1_usr_dummy: %d, spi1_extra_dummy: %d", spi0_usr_dummy, spi0_extra_dummy, spi1_usr_dummy, spi1_extra_dummy); + ESP_DRAM_LOGV(TAG, "flash, spi0_usr_dummy: %d, spi0_extra_dummy: %d, spi1_usr_dummy: %d, spi1_extra_dummy: %d", spi0_usr_dummy, spi0_extra_dummy, spi1_usr_dummy, spi1_extra_dummy); } void mspi_timing_psram_config_clear_tuning_regs(bool control_both_mspi) @@ -378,7 +378,7 @@ void mspi_timing_psram_config_set_tuning_regs(bool control_both_mspi) int spi0_usr_rdummy = 0; int spi0_extra_dummy = 0; mspi_timing_ll_get_psram_dummy(MSPI_TIMING_LL_MSPI_ID_0, &spi0_usr_rdummy, &spi0_extra_dummy); - ESP_EARLY_LOGV(TAG, "psram, spi0_usr_rdummy: %d, spi0_extra_dummy: %d", spi0_usr_rdummy, spi0_extra_dummy); + ESP_DRAM_LOGV(TAG, "psram, spi0_usr_rdummy: %d, spi0_extra_dummy: %d", spi0_usr_rdummy, spi0_extra_dummy); } /*------------------------------------------------------------------------------------------------- diff --git a/components/esp_hw_support/test_apps/mspi/main/test_mspi.c b/components/esp_hw_support/test_apps/mspi/main/test_mspi.c index c6436535b6..f46de1a9b2 100644 --- a/components/esp_hw_support/test_apps/mspi/main/test_mspi.c +++ b/components/esp_hw_support/test_apps/mspi/main/test_mspi.c @@ -28,6 +28,9 @@ static void sorted_array_insert(uint32_t *array, uint32_t *size, uint32_t item) #elif CONFIG_IDF_TARGET_ESP32P4 #define TEST_TIME_CNT 30 #define TEST_TIME_LIMIT_US 30 +#else +#define TEST_TIME_CNT 20 +#define TEST_TIME_LIMIT_US 20 #endif TEST_CASE("MSPI: Test mspi timing tuning time cost", "[mspi]") diff --git a/components/esp_hw_support/test_apps/mspi/pytest_flash_psram.py b/components/esp_hw_support/test_apps/mspi/pytest_flash_psram.py index 41be9d93c5..4925c8c0a9 100644 --- a/components/esp_hw_support/test_apps/mspi/pytest_flash_psram.py +++ b/components/esp_hw_support/test_apps/mspi/pytest_flash_psram.py @@ -53,9 +53,23 @@ def test_flash4_psram4(dut: IdfDut) -> None: 'config', [ 'esp32p4_120sdr_200ddr', + 'esp32p4_timing_tuning_log_safe', ], indirect=True, ) @idf_parametrize('target', ['esp32p4'], indirect=['target']) def test_flash_psram_esp32p4(dut: IdfDut) -> None: dut.run_all_single_board_cases() + + +@pytest.mark.generic +@pytest.mark.parametrize( + 'config', + [ + 'generic_timing_tuning_log_safe', + ], + indirect=True, +) +@idf_parametrize('target', ['esp32c5', 'esp32c61'], indirect=['target']) +def test_flash_psram_generic(dut: IdfDut) -> None: + dut.run_all_single_board_cases() diff --git a/components/esp_hw_support/test_apps/mspi/sdkconfig.ci.esp32p4_timing_tuning_log_safe b/components/esp_hw_support/test_apps/mspi/sdkconfig.ci.esp32p4_timing_tuning_log_safe new file mode 100644 index 0000000000..b8e3d1c163 --- /dev/null +++ b/components/esp_hw_support/test_apps/mspi/sdkconfig.ci.esp32p4_timing_tuning_log_safe @@ -0,0 +1,10 @@ +CONFIG_IDF_TARGET="esp32p4" + +CONFIG_IDF_EXPERIMENTAL_FEATURES=y +CONFIG_SPIRAM=y +CONFIG_SPIRAM_SPEED_200M=y +CONFIG_ESPTOOLPY_FLASHFREQ_120M=y +CONFIG_SPI_FLASH_HPM_ENA=y +CONFIG_BOOTLOADER_FLASH_DC_AWARE=y +CONFIG_SPI_FLASH_AUTO_SUSPEND=y +CONFIG_LOG_IN_IRAM=n diff --git a/components/esp_hw_support/test_apps/mspi/sdkconfig.ci.esp32s3_f4r4_timing_tuning_log_safe b/components/esp_hw_support/test_apps/mspi/sdkconfig.ci.esp32s3_f4r4_timing_tuning_log_safe new file mode 100644 index 0000000000..ba6a6506ae --- /dev/null +++ b/components/esp_hw_support/test_apps/mspi/sdkconfig.ci.esp32s3_f4r4_timing_tuning_log_safe @@ -0,0 +1,15 @@ +# Legacy, F4R4, Flash 120M SDR, PSRAM 120M SDR + +CONFIG_IDF_TARGET="esp32s3" + +CONFIG_PARTITION_TABLE_CUSTOM=y +CONFIG_PARTITION_TABLE_CUSTOM_FILENAME="partitions.csv" +CONFIG_PARTITION_TABLE_FILENAME="partitions.csv" +CONFIG_SPI_FLASH_HPM_ENA=y +CONFIG_ESPTOOLPY_FLASHFREQ_120M=y +CONFIG_BOOTLOADER_FLASH_DC_AWARE=y +CONFIG_ESPTOOLPY_FLASHSIZE_4MB=y +CONFIG_SPIRAM=y +CONFIG_SPIRAM_SPEED_120M=y +CONFIG_SPI_FLASH_AUTO_SUSPEND=y +CONFIG_LOG_IN_IRAM=n diff --git a/components/esp_hw_support/test_apps/mspi/sdkconfig.ci.generic_timing_tuning_log_safe b/components/esp_hw_support/test_apps/mspi/sdkconfig.ci.generic_timing_tuning_log_safe new file mode 100644 index 0000000000..bf6905be42 --- /dev/null +++ b/components/esp_hw_support/test_apps/mspi/sdkconfig.ci.generic_timing_tuning_log_safe @@ -0,0 +1,5 @@ +CONFIG_SPIRAM=y +CONFIG_SPIRAM_SPEED_80M=y +CONFIG_ESPTOOLPY_FLASHFREQ_80M=y +CONFIG_SPI_FLASH_AUTO_SUSPEND=y +CONFIG_LOG_IN_IRAM=n