"unexpected spi flash error code:101"

User avatar
mzimmers
Posts: 643
Joined: Wed Mar 07, 2018 11:54 pm
Location: USA

"unexpected spi flash error code:101"

Postby mzimmers » Mon Feb 17, 2020 8:50 pm

Hi all -

Using master branch of IDF, WROVER. I'm getting this error message:

Code: Select all

E (4422) spi_flash: unexpected spi flash error code: 101
abort() was called at PC 0x4008613c on core 1

ELF file SHA256: etc.
when I make this call:

Code: Select all

    err = nvs_flash_init_partition(NVS_PARTITION_SYSLOG);
error 101 is:

Code: Select all

#define ESP_ERR_NO_MEM              0x101   /*!< Out of memory */
I've been trying to get SPI RAM working, though I don't know whether this problem is related to that. In the event that it may be, I'm attaching a screen shot of my SPI RAM config.

Can anyone see something I'm doing wrong here?

Thanks...
Attachments
menu.PNG
menu.PNG (34.53 KiB) Viewed 7920 times

User avatar
mzimmers
Posts: 643
Joined: Wed Mar 07, 2018 11:54 pm
Location: USA

Re: "unexpected spi flash error code:101"

Postby mzimmers » Mon Feb 17, 2020 11:12 pm

As another data point, when I disable the task that throws the above error, I now get this one:

Code: Select all

W (8832) wifi: alloc eb len=36 type=3 fail, heap:4167652

W (8832) wifi: mem fail
I'm almost positive it is some configuration goof I'm making...

ESP_Angus
Posts: 2344
Joined: Sun May 08, 2016 4:11 am

Re: "unexpected spi flash error code:101"

Postby ESP_Angus » Tue Feb 18, 2020 4:30 am

Hi mzimmers,

I guess the natural conclusion is that you're running out of free RAM?

The boot log during startup should give some indication of whether there was any problem initializing SPIRAM, and it will also print a summary of the heap which is available at startup. This information is a good place to start (ie is PSRAM initializing OK, and how much heap is available in total.)

To get a summary of the heap situation at the time you see the out of memory error, include esp_heap_caps.h and run heap_caps_print_heap_info(MALLOC_CAP_8BIT) to dump a summary of runtime heap stats to stdout.

If none of this is helping, can you please let us know the exact IDF version you have? ("git describe --tags")

User avatar
mzimmers
Posts: 643
Joined: Wed Mar 07, 2018 11:54 pm
Location: USA

Re: "unexpected spi flash error code:101"

Postby mzimmers » Tue Feb 18, 2020 5:03 pm

Hi Angus -

I made some changes in my Wifi task, and have advanced the startup procedure a bit. I'm now getting this error:

Code: Select all

E (4475) phy_init: failed to allocate memory for RF calibration data


This happens immediately after a call to esp_wifi_start().
Here's the boot log for the SPI RAM/heap:

Code: Select all

I (1772) spiram: SPI SRAM memory test OK
I (1774) heap_init: Initializing. RAM available for dynamic allocation:
I (1774) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (1779) heap_init: At 3FFC9980 len 00016680 (89 KiB): DRAM
I (1785) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1791) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1798) heap_init: At 4009F08C len 00000F74 (3 KiB): IRAM
I (1804) cpu_start: Pro cpu start user code
I (1809) spiram: Adding pool of 4077K of external SPI memory to heap allocator
I (2426) spi_flash: detected chip: gd
I (2426) spi_flash: flash io: dio
And here's a memory report immediately prior to the call to esp_wifi_start():

Code: Select all

I (4565) memreport: memReport(): there are 4181148 MALLOC_CAP_32BIT bytes free.
I (4575) memreport: memReport(): there are 4177244 MALLOC_CAP_8BIT bytes free.
I (4585) memreport: memReport(): there are 2028 MALLOC_CAP_DMA bytes free.
I (4605) memreport: memReport(): there are 4175216 MALLOC_CAP_SPIRAM bytes free.
I (4615) memreport: memReport(): there are 5932 MALLOC_CAP_INTERNAL bytes free.
I (4615) memreport: memReport(): there are 4177244 MALLOC_CAP_DEFAULT bytes free.
I (4625) memreport: memReport(): there are 0 MALLOC_CAP_INVALID bytes free.
Weird, huh? That's why I'm thinking it must be something I'm doing wrong with my Wifi init/configure. Unfortunately, until someone corrects the latest version of the docs, I'm just guessing as to what I'm supposed to do.

Oh:

Code: Select all

C:\esp-idf>git describe --tags
v4.1-dev-1986-gca735340f

C:\esp-idf>
Thanks for any insight.

User avatar
mzimmers
Posts: 643
Joined: Wed Mar 07, 2018 11:54 pm
Location: USA

Re: "unexpected spi flash error code:101"

Postby mzimmers » Tue Feb 18, 2020 11:14 pm

UPDATE: this problem is just bizarre. I've gotten my app to start up and run until I get a failure:

Code: Select all

E (13124) HTTP_CLIENT: Allocation failed
I then hit the reset button on my board, and now I'm back to getting the wifi stack overflow earlier in the boot sequence.

What could be causing erratic behavior like this?

ESP_Angus
Posts: 2344
Joined: Sun May 08, 2016 4:11 am

Re: "unexpected spi flash error code:101"

Postby ESP_Angus » Tue Feb 18, 2020 11:29 pm

Hi mzimmers,

Judging from the "memreport" log lines compared to the initial heap sizes, something is indeed allocating almost all the available internal memory from heap during startup.

The remaining amounts of DMA-capable and internal memory seem quite low (these also overlap), and these free sizes may also be fragmented (you can run heap_caps_print_heap_info(MALLOC_CAP_8BIT | MALLOC_CAP_DMA) and heap_caps_print_heap_info(MALLOC_CAP_8BIT | MALLOC_CAP_INTERNAL) to get some info about this).

The wifi libraries will allocate some buffers during config and some while wifi is started, and several of these need to be in internal memory. But they shouldn't be allocating anything close to the total amount of memory that seems to be taken up here.

Suggest logging the output of heap_caps_get_free_size(MALLOC_CAP_INTERNAL) at every step of the initialization procedure (starting at the top of app_main() and logging before/after wifi init, wifi configure, wifi start), and trying to pin down the step that causes the available free memory to come down dramatically.

You can also use the heap tracing feature to do this automatically:
https://docs.espressif.com/projects/esp ... ap-tracing
That's why I'm thinking it must be something I'm doing wrong with my Wifi init/configure. Unfortunately, until someone corrects the latest version of the docs, I'm just guessing as to what I'm supposed to do.
Sorry, I don't understand what you're suggesting is incorrect.

Is some specific information missing from here?
https://docs.espressif.com/projects/esp ... ffer-usage


Angus

User avatar
mzimmers
Posts: 643
Joined: Wed Mar 07, 2018 11:54 pm
Location: USA

Re: "unexpected spi flash error code:101"

Postby mzimmers » Wed Feb 19, 2020 2:29 am

Hi Angus - I'll try those memory reports you suggested in the morning.

I'm not sure I understand - are you saying that there would be expected to be *more* memory available than what I'm showing in the reports? It looks like I have plenty of the 8-bit (which from what I understand is what malloc() uses).

It seems strange that I'd be short on memory now that I've enabled SPI RAM, as I had enough memory without SPI RAM before I went to v4.1. Something just isn't right.

I was commenting on the inaccuracy in the docs:

https://docs.espressif.com/projects/esp ... /wifi.html

states this:
s1.2: The main task calls esp_event_loop_init() to create a system Event task and initialize an application event’s callback function.
It's my understanding that this call is deprecated in V4.1. So, this would seem to be an error in the docs. If this is there, there may be more errors.

Thanks...

ESP_Angus
Posts: 2344
Joined: Sun May 08, 2016 4:11 am

Re: "unexpected spi flash error code:101"

Postby ESP_Angus » Wed Feb 19, 2020 3:24 am

mzimmers wrote:
Wed Feb 19, 2020 2:29 am
Hi Angus - I'll try those memory reports you suggested in the morning.

I'm not sure I understand - are you saying that there would be expected to be *more* memory available than what I'm showing in the reports? It looks like I have plenty of the 8-bit (which from what I understand is what malloc() uses).

It seems strange that I'd be short on memory now that I've enabled SPI RAM, as I had enough memory without SPI RAM before I went to v4.1. Something just isn't right.
You have plenty of 8-bit memory, but not plenty of "internal" 8-bit memory (MALLOC_CAP_INTERNAL and MALLOC_CAP_DMA). Some functions allocate internal-only RAM because they need to use DMA, need to use the memory from an interrupt when SPI flash may be being written, or for performance reasons. In particular the Wi-Fi library uses some internal 8-bit memory.

There's some more general info about this here:
https://docs.espressif.com/projects/esp ... alloc.html

According to the startup log there's almost 220KB of heap memory initialized in internal DRAM (89+6+111+14). According to the "memreport" log there's 5932 bytes of internal memory left at some point after initial startup. So something has definitely allocated a lot of internal memory.

Note that the default "malloc" behaviour (for allocations where you don't require a particular type of memory) is to favour internal memory for small allocations, and external memory for large allocations. The threshold between "small" and "large" is set in a config item:
https://docs.espressif.com/projects/esp ... ysinternal

(Although this says "always", if internal memory is full and the allocation is a plain malloc() which doesn't require internal memory then the small allocation will fail over to external memory as well, if there's no more internal memory.)

So one thing you could try is tuning that config item down, to encourage more of the small allocations to use up external memory and leave internal memory full. But if you don't have any prime suspect for what is using over 200KB of heap on startup then it may be worth figuring this out, first.
I was commenting on the inaccuracy in the docs:

https://docs.espressif.com/projects/esp ... /wifi.html

states this:
s1.2: The main task calls esp_event_loop_init() to create a system Event task and initialize an application event’s callback function.
It's my understanding that this call is deprecated in V4.1. So, this would seem to be an error in the docs. If this is there, there may be more errors.

Thanks...
Thanks for pointing this out, looks like this wasn't updated when the event library was updated. Will get this fixed. The part of this document describing in the inner workings of the Wi-Fi library is still accurate, as far as I know (the change here is in the app side).

User avatar
mzimmers
Posts: 643
Joined: Wed Mar 07, 2018 11:54 pm
Location: USA

Re: "unexpected spi flash error code:101"

Postby mzimmers » Wed Feb 19, 2020 5:54 pm

Hi Angus - we may be getting somewhere on this. When I begin starting tasks, I have ~152KB of MALLOC_CAP_8BIT | MALLOC_CAP_INTERNAL RAM. Each task I start consumes about 8K (seems reasonable to me). As I have several tasks, the number is reduced to about 64K.

Then, my Wifi initialization runs. The big hit seems to occur when I call esp_wifi_init():

Code: Select all

memReport("after step #1.3 in taskInit()");

    // step 1.4 in https://docs.espressif.com/projects/esp-idf/en/latest/api-guides/wifi.html
    wifi_init_config_t wifiInitConfig;
    wifiInitConfig = WIFI_INIT_CONFIG_DEFAULT();
    err = esp_wifi_init(&wifiInitConfig);
    if (err != ESP_OK)
    {
        ESP_LOGE(TAG, "taskInit(): esp_wifi_init() returned 0x%x; halting task.", err);
        vTaskDelay(portMAX_DELAY);
    }
vTaskDelay(100);
memReport("after step #1.4 in taskInit()");
Here's the results:

Code: Select all

I (9245) memreport: after step #1.3 in taskInit()
I (9245) memreport: memReport(): there are 4233640 MALLOC_CAP_32BIT bytes free.
I (9245) memreport: memReport(): there are 4230088 MALLOC_CAP_8BIT bytes free.
I (9255) memreport: memReport(): there are 55188 MALLOC_CAP_DMA bytes free.
I (9255) memreport: memReport(): there are 4174900 MALLOC_CAP_SPIRAM bytes free.
I (9265) memreport: memReport(): there are 58740 MALLOC_CAP_INTERNAL bytes free.
I (9275) memreport: memReport(): there are 4230088 MALLOC_CAP_DEFAULT bytes free.
I (9285) memreport: memReport(): there are 0 MALLOC_CAP_INVALID bytes free.
I (9285) memreport: memReport(): there are 55188 MALLOC_CAP_8BIT | MALLOC_CAP_DMA bytes free.
I (9295) memreport: memReport(): there are 55188 MALLOC_CAP_8BIT | MALLOC_CAP_INTERNAL bytes free.

I (9325) wifi: wifi driver task: 3fff3f38, prio:23, stack:3584, core=0
I (9345) wifi: wifi firmware version: f1dc391
I (9345) wifi: config NVS flash: enabled
I (9345) wifi: config nano formating: disabled
I (9345) wifi: Init dynamic tx buffer num: 32
I (9345) wifi: Init data frame dynamic rx buffer num: 32
I (9355) wifi: Init management frame dynamic rx buffer num: 32
I (9355) wifi: Init management short buffer num: 32
I (9365) wifi: Init static tx buffer num: 16
I (9375) wifi: Init static rx buffer size: 1600
I (9375) wifi: Init static rx buffer num: 10
I (9375) wifi: Init dynamic rx buffer num: 32
I (10385) memreport: after step #1.4 in taskInit()
I (10385) memreport: memReport(): there are 4180972 MALLOC_CAP_32BIT bytes free.
I (10385) memreport: memReport(): there are 4177420 MALLOC_CAP_8BIT bytes free.
I (10395) memreport: memReport(): there are 4416 MALLOC_CAP_DMA bytes free.
I (10395) memreport: memReport(): there are 4173004 MALLOC_CAP_SPIRAM bytes free.
I (10405) memreport: memReport(): there are 7968 MALLOC_CAP_INTERNAL bytes free.
I (10415) memreport: memReport(): there are 4177420 MALLOC_CAP_DEFAULT bytes free.
I (10425) memreport: memReport(): there are 0 MALLOC_CAP_INVALID bytes free.
I (10435) memreport: memReport(): there are 4416 MALLOC_CAP_8BIT | MALLOC_CAP_DMA bytes free.
I (10435) memreport: memReport(): there are 4416 MALLOC_CAP_8BIT | MALLOC_CAP_INTERNAL bytes free.
So it appears that esp_wifi_init() is using a little over 50KB of internal RAM. What's left isn't enough to run the app, so I get aborts in various places, depending on my exact settings, currently set thus:

Code: Select all

                                         Espressif IoT Development Framework Configuration
    Type of SPI RAM chip in use (Auto-detect)  --->
    Set RAM clock speed (40MHz clock speed)  --->
[*] Initialize SPI RAM during startup
    SPI RAM access method (Make RAM allocatable using heap_caps_malloc(..., MALLOC_CAP_SPIRAM))  --->
[*] Run memory test on SPI RAM initialization
[*] Try to allocate memories of WiFi and LWIP in SPIRAM firstly. If failed, allocate internal memory
[*] Allow .bss segment placed in external memory
[*] Enable workaround for bug in SPI RAM cache for Rev1 ESP32s
[*] Enable bank switching for >4MiB external RAM
(8)     Amount of 32K pages to reserve for bank switching
    PSRAM clock and cs IO for ESP32-DOWD  --->
    PSRAM clock and cs IO for ESP32-D2WD  --->
    PSRAM clock and cs IO for ESP32-PICO  --->
(7) SPI PSRAM WP(SD3) Pin when customising pins via eFuse (read help)
Does this seem "correct" to you? 50K seems like a lot, but if this is what it takes, I guess I need to somehow use less in other areas.

PeterR
Posts: 621
Joined: Mon Jun 04, 2018 2:47 pm

Re: "unexpected spi flash error code:101"

Postby PeterR » Wed Feb 19, 2020 6:37 pm

Yes, 50K is about right for the initialisation call. You can reduce the number of 'static' buffers in menuconfig.
I would be interested in ESP's answers though.
If you read menuconfig Wifi buffer's help then there are both static & dynamic buffers. As I read it your init has allocated some static buffers. The help suggest that you must also have dynamic buffers (why?). Might more heap disappear under high loading?

PS You also loose quite a lot of to Wifi memory as .bss and .data sections.
PPS 8KB stack size is a lot, unless you are using printf() etc. Try uxTaskGetSystemState() after running for a bit and reduce as needed.
Also, starting with 152KB seems wrong. You should be able to start at 200KB (ish) with Wifi. Did you forget to put const in front of some initialisation data? A lot of Linux/PC code will fail to do that.
If you have PSRAM then you can push some .bss and Wifi out. Not sure what the performance hit is.
& I also believe that IDF CAN should be fixed.

Who is online

Users browsing this forum: No registered users and 124 guests