esp32-wrover-b fail to run esp-idf example --> ~$IDF_PATH/examples/system/himem

INSTRUCTIONS

Environment

• Development Kit: [ESP32-Wrover-Kit]
• Kit version (for WroverKit): [v3]
• Module or chip used: [ESP32-WROVER-B]
• IDF version (run git describe --tags to find it): v3.3
• Build System: [CMake]
• Compiler version (run xtensa-esp32-elf-gcc --version to find it): xtensa-esp32-elf-gcc (crosstool-NG crosstool-ng-1.22.0-80-g6c4433a) 5.2.0
• Operating System: [Linux]
• Power Supply: [USB]

Problem Description

esp-idf system example for psram test --> ~$IDF_PATH/examples/system/himem don’t work

Expected Behavior

rst:0x1 (POWERON_RESET),boot:0x1e (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0018,len:4 load:0x3fff001c,len:6124 load:0x40078000,len:10084 load:0x40080400,len:6552 entry 0x40080764 I (28) boot: ESP-IDF v3.2-dev-1455-ga51d5706f-dirty 2nd stage bootloader I (29) boot: compile time 18:51:28 I (30) boot: Enabling RNG early entropy source… I (35) boot: SPI Speed : 40MHz I (39) boot: SPI Mode : DIO I (43) boot: SPI Flash Size : 4MB I (47) boot: Partition Table: I (51) boot: ## Label Usage Type ST Offset Length I (58) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (66) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (73) boot: 2 factory factory app 00 00 00010000 00100000 I (81) boot: End of partition table I (85) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x0dde0 ( 56800) map I (114) esp_image: segment 1: paddr=0x0001de08 vaddr=0x3ff80000 size=0x00000 ( 0) load I (114) esp_image: segment 2: paddr=0x0001de10 vaddr=0x3ff80000 size=0x00000 ( 0) load I (120) esp_image: segment 3: paddr=0x0001de18 vaddr=0x3ffb0000 size=0x01fb4 ( 8116) load I (132) esp_image: segment 4: paddr=0x0001fdd4 vaddr=0x3ffb1fb4 size=0x00000 ( 0) load I (138) esp_image: segment 5: paddr=0x0001fddc vaddr=0x40080000 size=0x00234 ( 564) load I (147) esp_image: segment 6: paddr=0x00020018 vaddr=0x400d0018 size=0x180d4 ( 98516) map I (191) esp_image: segment 7: paddr=0x000380f4 vaddr=0x40080234 size=0x001cc ( 460) load I (191) esp_image: segment 8: paddr=0x000382c8 vaddr=0x40080400 size=0x0e14c ( 57676) load I (221) esp_image: segment 9: paddr=0x0004641c vaddr=0x400c0000 size=0x00000 ( 0) load I (222) esp_image: segment 10: paddr=0x00046424 vaddr=0x50000000 size=0x00000 ( 0) load I (228) esp_image: segment 11: paddr=0x0004642c vaddr=0x50000000 size=0x00000 ( 0) load I (245) boot: Loaded app from partition at offset 0x10000 I (246) boot: Disabling RNG early entropy source… I (250) spiram: Found 64MBit SPI RAM device I (254) spiram: SPI RAM mode: flash 40m sram 40m I (259) spiram: PSRAM initialized, cache is in low/high (2-core) mode. I (266) cpu_start: Pro cpu up. I (270) cpu_start: Starting app cpu, entry point is 0x40081174 I (0) cpu_start: App cpu up. I (735) spiram: SPI SRAM memory test OK I (735) heap_init: Initializing. RAM available for dynamic allocation: I (735) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM I (741) heap_init: At 3FFB3448 len 0002CBB8 (178 KiB): DRAM I (748) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (754) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (760) heap_init: At 4008E54C len 00011AB4 (70 KiB): IRAM I (767) cpu_start: Pro cpu start user code I (771) spiram: Adding pool of 2112K of external SPI memory to heap allocator I (121) esp_himem: Initialized. Using last 62 32KB address blocks for bank switching on 6080 KB of physical memory. I (122) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (132) spiram: Reserving pool of 32K of internal memory for DMA/internal allocations Himem has 6080 KiB of memory, 6080 KiB of which is free. Testing the free memory… Done!

Actual Behavior

ets Jun 8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0018,len:4 load:0x3fff001c,len:6308 load:0x40078000,len:11624 load:0x40080400,len:6648 entry 0x40080764 I (28) boot: ESP-IDF v3.3-dirty 2nd stage bootloader I (28) boot: compile time 18:56:45 I (29) boot: Enabling RNG early entropy source… I (33) boot: SPI Speed : 40MHz I (37) boot: SPI Mode : DIO I (41) boot: SPI Flash Size : 4MB I (46) boot: Partition Table: I (49) boot: ## Label Usage Type ST Offset Length I (56) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (64) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (71) boot: 2 factory factory app 00 00 00010000 00100000 I (79) boot: End of partition table I (83) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x111b8 ( 70072) map I (117) esp_image: segment 1: paddr=0x000211e0 vaddr=0x3ffb0000 size=0x01f2c ( 7980) load I (120) esp_image: segment 2: paddr=0x00023114 vaddr=0x40080000 size=0x00400 ( 1024) load 0x40080000: _WindowOverflow4 at /home/sagar/esp/esp-idf/components/freertos/xtensa_vectors.S:1779

I (124) esp_image: segment 3: paddr=0x0002351c vaddr=0x40080400 size=0x0ca88 ( 51848) load I (154) esp_image: segment 4: paddr=0x0002ffac vaddr=0x00000000 size=0x00064 ( 100) I (154) esp_image: segment 5: paddr=0x00030018 vaddr=0x400d0018 size=0x189a4 (100772) map 0x400d0018: _flash_cache_start at ??:?

I (203) boot: Loaded app from partition at offset 0x10000 I (203) boot: Disabling RNG early entropy source… I (204) psram: This chip is ESP32-D0WD I (209) spiram: Found 64MBit SPI RAM device I (213) spiram: SPI RAM mode: flash 40m sram 40m I (218) spiram: PSRAM initialized, cache is in low/high (2-core) mode. I (225) cpu_start: Pro cpu up. I (229) cpu_start: Application information: I (234) cpu_start: Project name: himem_test I (239) cpu_start: App version: v3.3-dirty I (244) cpu_start: Compile time: Nov 5 2019 18:56:48 I (250) cpu_start: ELF file SHA256: 33d23b69a2c8eb6b… I (256) cpu_start: ESP-IDF: v3.3-dirty I (262) cpu_start: Starting app cpu, entry point is 0x400813e4 0x400813e4: call_start_cpu1 at /home/sagar/esp/esp-idf/components/esp32/cpu_start.c:270

I (0) cpu_start: App cpu up. E (1128) spiram: SPI SRAM memory test fail. 126976/126976 writes failed, first @ 3F800000

E (1128) cpu_start: External RAM failed memory test! abort() was called at PC 0x4008162a on core 0 0x4008162a: call_start_cpu0 at /home/sagar/esp/esp-idf/components/esp32/cpu_start.c:240 (discriminator 1)

ELF file SHA256: 33d23b69a2c8eb6be8cfaa99c0c1f7e32909681276738a2d97bdaac8fa5f2231

Backtrace: 0x40086494:0x3ffe3bb0 0x400866d9:0x3ffe3bd0 0x4008162a:0x3ffe3bf0 0x4007940b:0x3ffe3c30 0x400794bd:0x3ffe3c60 0x400794db:0x3ffe3ca0 0x400797c1:0x3ffe3cc0 0x40080796:0x3ffe3df0 0x40007c31:0x3ffe3eb0 0x4000073d:0x3ffe3f20 0x40086494: invoke_abort at /home/sagar/esp/esp-idf/components/esp32/panic.c:715

0x400866d9: abort at /home/sagar/esp/esp-idf/components/esp32/panic.c:715

0x4008162a: call_start_cpu0 at /home/sagar/esp/esp-idf/components/esp32/cpu_start.c:240 (discriminator 1)

Steps to repropduce

1. goto example location of himem
2. make menuconfig

• Set serial port under Serial Flasher Options
• SPI RAM bank switching is enabled : Component config > ESP32-specific > Support for external, SPI-connected RAM > SPI RAM config

1. make flash monitor

Code to reproduce this issue

/* Himem API example

   This example code is in the Public Domain (or CC0 licensed, at your option.)

   Unless required by applicable law or agreed to in writing, this
   software is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR
   CONDITIONS OF ANY KIND, either express or implied.
*/
#include <stdio.h>
#include <stdbool.h>
#include <stdint.h>
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "freertos/queue.h"
#include "esp_system.h"
#include "nvs_flash.h"
#include "esp_heap_caps.h"
#include "esp_spiram.h"
#include "rom/cache.h"
#include "sdkconfig.h"
#include "esp_himem.h"


//Fill memory with pseudo-random data generated from the given seed.
//Fills the memory in 32-bit words for speed.
static void fill_mem_seed(int seed, void *mem, int len)
{
    uint32_t *p = (uint32_t *)mem;
    unsigned int rseed = seed ^ 0xa5a5a5a5;
    for (int i = 0; i < len / 4; i++) {
        *p++ = rand_r(&rseed);
    }
}

//Check the memory filled by fill_mem_seed. Returns true if the data matches the data
//that fill_mem_seed wrote (when given the same seed).
//Returns true if there's a match, false when the region differs from what should be there.
static bool check_mem_seed(int seed, void *mem, int len, int phys_addr)
{
    uint32_t *p = (uint32_t *)mem;
    unsigned int rseed = seed ^ 0xa5a5a5a5;
    for (int i = 0; i < len / 4; i++) {
        uint32_t ex = rand_r(&rseed);
        if (ex != *p) {
            printf("check_mem_seed: %x has 0x%08x expected 0x%08x\n", phys_addr+((char*)p-(char*)mem), *p, ex);
            return false;
        }
        p++;
    }
    return true;
}

//Allocate a himem region, fill it with data, check it and release it.
static bool test_region(int check_size, int seed)
{
    esp_himem_handle_t mh; //Handle for the address space we're using
    esp_himem_rangehandle_t rh; //Handle for the actual RAM.
    bool ret = true;

    //Allocate the memory we're going to check.
    ESP_ERROR_CHECK(esp_himem_alloc(check_size, &mh));
    //Allocate a block of address range
    ESP_ERROR_CHECK(esp_himem_alloc_map_range(ESP_HIMEM_BLKSZ, &rh));
    for (int i = 0; i < check_size; i += ESP_HIMEM_BLKSZ) {
        uint32_t *ptr = NULL;
        //Map in block, write pseudo-random data, unmap block.
        ESP_ERROR_CHECK(esp_himem_map(mh, rh, i, 0, ESP_HIMEM_BLKSZ, 0, (void**)&ptr));
        fill_mem_seed(i ^ seed, ptr, ESP_HIMEM_BLKSZ); //
        ESP_ERROR_CHECK(esp_himem_unmap(rh, ptr, ESP_HIMEM_BLKSZ));
    }
    vTaskDelay(5); //give the OS some time to do things so the task watchdog doesn't bark
    for (int i = 0; i < check_size; i += ESP_HIMEM_BLKSZ) {
        uint32_t *ptr;
        //Map in block, check against earlier written pseudo-random data, unmap block.
        ESP_ERROR_CHECK(esp_himem_map(mh, rh, i, 0, ESP_HIMEM_BLKSZ, 0, (void**)&ptr));
        if (!check_mem_seed(i ^ seed, ptr, ESP_HIMEM_BLKSZ, i)) {
            printf("Error in block %d\n", i / ESP_HIMEM_BLKSZ);
            ret = false;
        }
        ESP_ERROR_CHECK(esp_himem_unmap(rh, ptr, ESP_HIMEM_BLKSZ));
        if (!ret) break; //don't check rest of blocks if error occurred
    }
    //Okay, all done!
    ESP_ERROR_CHECK(esp_himem_free(mh));
    ESP_ERROR_CHECK(esp_himem_free_map_range(rh));
    return ret;
}


void app_main()
{
    size_t memcnt=esp_himem_get_phys_size();
    size_t memfree=esp_himem_get_free_size();
    printf("Himem has %dKiB of memory, %dKiB of which is free. Testing the free memory...\n", (int)memcnt/1024, (int)memfree/1024);
    assert(test_region(memfree, 0xaaaa));
    printf("Done!\n");
}

Debug Logs

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:6308
load:0x40078000,len:11624
load:0x40080400,len:6648
entry 0x40080764
I (28) boot: ESP-IDF v3.3-dirty 2nd stage bootloader
I (28) boot: compile time 18:56:45
I (29) boot: Enabling RNG early entropy source...
I (33) boot: SPI Speed      : 40MHz
I (37) boot: SPI Mode       : DIO
I (41) boot: SPI Flash Size : 4MB
I (46) boot: Partition Table:
I (49) boot: ## Label            Usage          Type ST Offset   Length
I (56) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (64) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (71) boot:  2 factory          factory app      00 00 00010000 00100000
I (79) boot: End of partition table
I (83) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x111b8 ( 70072) map
I (117) esp_image: segment 1: paddr=0x000211e0 vaddr=0x3ffb0000 size=0x01f2c (  7980) load
I (120) esp_image: segment 2: paddr=0x00023114 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at /home/sagar/esp/esp-idf/components/freertos/xtensa_vectors.S:1779

I (124) esp_image: segment 3: paddr=0x0002351c vaddr=0x40080400 size=0x0ca88 ( 51848) load
I (154) esp_image: segment 4: paddr=0x0002ffac vaddr=0x00000000 size=0x00064 (   100) 
I (154) esp_image: segment 5: paddr=0x00030018 vaddr=0x400d0018 size=0x189a4 (100772) map
0x400d0018: _flash_cache_start at ??:?

I (203) boot: Loaded app from partition at offset 0x10000
I (203) boot: Disabling RNG early entropy source...
I (204) psram: This chip is ESP32-D0WD
I (209) spiram: Found 64MBit SPI RAM device
I (213) spiram: SPI RAM mode: flash 40m sram 40m
I (218) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (225) cpu_start: Pro cpu up.
I (229) cpu_start: Application information:
I (234) cpu_start: Project name:     himem_test
I (239) cpu_start: App version:      v3.3-dirty
I (244) cpu_start: Compile time:     Nov  5 2019 18:56:48
I (250) cpu_start: ELF file SHA256:  33d23b69a2c8eb6b...
I (256) cpu_start: ESP-IDF:          v3.3-dirty
I (262) cpu_start: Starting app cpu, entry point is 0x400813e4
0x400813e4: call_start_cpu1 at /home/sagar/esp/esp-idf/components/esp32/cpu_start.c:270

I (0) cpu_start: App cpu up.
E (1128) spiram: SPI SRAM memory test fail. 126976/126976 writes failed, first @ 3F800000

E (1128) cpu_start: External RAM failed memory test!
abort() was called at PC 0x4008162a on core 0
0x4008162a: call_start_cpu0 at /home/sagar/esp/esp-idf/components/esp32/cpu_start.c:240 (discriminator 1)


ELF file SHA256: 33d23b69a2c8eb6be8cfaa99c0c1f7e32909681276738a2d97bdaac8fa5f2231

Backtrace: 0x40086494:0x3ffe3bb0 0x400866d9:0x3ffe3bd0 0x4008162a:0x3ffe3bf0 0x4007940b:0x3ffe3c30 0x400794bd:0x3ffe3c60 0x400794db:0x3ffe3ca0 0x400797c1:0x3ffe3cc0 0x40080796:0x3ffe3df0 0x40007c31:0x3ffe3eb0 0x4000073d:0x3ffe3f20
0x40086494: invoke_abort at /home/sagar/esp/esp-idf/components/esp32/panic.c:715

0x400866d9: abort at /home/sagar/esp/esp-idf/components/esp32/panic.c:715

0x4008162a: call_start_cpu0 at /home/sagar/esp/esp-idf/components/esp32/cpu_start.c:240 (discriminator 1)


Rebooting...
ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:6308
load:0x40078000,len:11624
load:0x40080400,len:6648
entry 0x40080764
I (29) boot: ESP-IDF v3.3-dirty 2nd stage bootloader
I (29) boot: compile time 18:56:45
I (29) boot: Enabling RNG early entropy source...
I (34) boot: SPI Speed      : 40MHz
I (38) boot: SPI Mode       : DIO
I (42) boot: SPI Flash Size : 4MB
I (46) boot: Partition Table:
I (50) boot: ## Label            Usage          Type ST Offset   Length
I (57) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (65) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (72) boot:  2 factory          factory app      00 00 00010000 00100000
I (80) boot: End of partition table
I (84) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x111b8 ( 70072) map
I (117) esp_image: segment 1: paddr=0x000211e0 vaddr=0x3ffb0000 size=0x01f2c (  7980) load
I (121) esp_image: segment 2: paddr=0x00023114 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at /home/sagar/esp/esp-idf/components/freertos/xtensa_vectors.S:1779

I (124) esp_image: segment 3: paddr=0x0002351c vaddr=0x40080400 size=0x0ca88 ( 51848) load
I (154) esp_image: segment 4: paddr=0x0002ffac vaddr=0x00000000 size=0x00064 (   100) 
I (155) esp_image: segment 5: paddr=0x00030018 vaddr=0x400d0018 size=0x189a4 (100772) map
0x400d0018: _flash_cache_start at ??:?

I (204) boot: Loaded app from partition at offset 0x10000
I (204) boot: Disabling RNG early entropy source...
I (204) psram: This chip is ESP32-D0WD
E (210) cpu_start: Failed to init external RAM!
abort() was called at PC 0x40081496 on core 0
0x40081496: call_start_cpu0 at /home/sagar/esp/esp-idf/components/esp32/cpu_start.c:174 (discriminator 1)


ELF file SHA256: 33d23b69a2c8eb6be8cfaa99c0c1f7e32909681276738a2d97bdaac8fa5f2231

Backtrace: 0x40086494:0x3ffe3bb0 0x400866d9:0x3ffe3bd0 0x40081496:0x3ffe3bf0 0x4007940b:0x3ffe3c30 0x400794bd:0x3ffe3c60 0x400794db:0x3ffe3ca0 0x400797c1:0x3ffe3cc0 0x40080796:0x3ffe3df0 0x40007c31:0x3ffe3eb0 0x4000073d:0x3ffe3f20
0x40086494: invoke_abort at /home/sagar/esp/esp-idf/components/esp32/panic.c:715

0x400866d9: abort at /home/sagar/esp/esp-idf/components/esp32/panic.c:715

0x40081496: call_start_cpu0 at /home/sagar/esp/esp-idf/components/esp32/cpu_start.c:174 (discriminator 1)