Crash when waking up from light sleep

[gatisp]

Hello,

I am attempting to use light sleep in my ESP32 application, but while the test case works fine, in app that contains "more code" it crashes on wakeup:

First the app that works:

#include "esp_wifi.h"
#include "esp_system.h"
#include "esp_event.h"
#include "esp_event_loop.h"
#include "esp_log.h"

void app_main(void) {
printf("light_sleep_enter\n");
esp_sleep_enable_timer_wakeup(1000000);
int ret = esp_light_sleep_start();
printf("light_sleep: %d\n", ret);
}

Serial output from the working app:
2017.09.21-10:17:46.405<2>: target: light_sleep_enter
2017.09.21-10:17:47.409<2>: target: light_sleep: 0



Now here is the app that crashes on wakeup - note how the additional code is actually never reached:

#include "esp_wifi.h"
#include "esp_system.h"
#include "esp_event.h"
#include "esp_event_loop.h"
#include "esp_log.h"

static esp_err_t event_handler(void *ctx, system_event_t *event) {
switch (event->event_id) {
case SYSTEM_EVENT_STA_GOT_IP: {
wifi_ap_record_t ap_rec;
esp_wifi_sta_get_ap_info(&ap_rec);
printf("wifi got ip, rssi: %d\n", ap_rec.rssi);
break;
}
default:
break;
}
return ESP_OK;
}

void app_main(void) {
printf("light_sleep_enter\n");
esp_sleep_enable_timer_wakeup(1000000);
int ret = esp_light_sleep_start();
printf("light_sleep: %d\n", ret);

tcpip_adapter_init();
esp_event_loop_init(event_handler, NULL);
esp_log_level_set("wifi", ESP_LOG_NONE);
wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT();
esp_wifi_init(&cfg);
esp_wifi_set_storage(WIFI_STORAGE_FLASH);
esp_wifi_set_ps(WIFI_PS_MODEM);
esp_wifi_set_mode(WIFI_MODE_STA);
wifi_config_t sta_config = {
.sta = {
.ssid = "xxx",
.password = "1234567890",
},
};
esp_wifi_set_config(WIFI_IF_STA, &sta_config);
esp_wifi_start();
}


The output on serial:

2017.09.21-10:12:58.583<2>: target: ?p?~plight_sleep_enter
2017.09.21-10:12:59.578<2>: target: Guru Meditation Error of type IllegalInstruction occurred on core 0. Exception was unhandled.
2017.09.21-10:12:59.583<2>: target: Register dump:
2017.09.21-10:12:59.589<2>: target: PC : 0x40112162 PS : 0x00060933 A0 : 0x800fc3cd A1 : 0x3ffbcc70
2017.09.21-10:12:59.594<2>: target: A2 : 0x00000000 A3 : 0x3ffb12f8 A4 : 0x00000001 A5 : 0x00000003
2017.09.21-10:12:59.605<2>: target: A6 : 0x00000022 A7 : 0x00060023 A8 : 0x8011215f A9 : 0x3ffbcc50
2017.09.21-10:12:59.610<2>: target: A10 : 0x3ff480b4 A11 : 0x4c4b4c4b A12 : 0x3ff48070 A13 : 0x01000000
2017.09.21-10:12:59.620<2>: target: A14 : 0x00000080 A15 : 0x00000001 SAR : 0x00000016 EXCCAUSE: 0x00000000
2017.09.21-10:12:59.626<2>: target: EXCVADDR: 0x00000000 LBEG : 0x400014fd LEND : 0x4000150d LCOUNT : 0xfffffffb
2017.09.21-10:12:59.626<2>: target:
2017.09.21-10:12:59.647<2>: target: Backtrace: 0x40112162:0x3ffbcc70 0x400fc3ca:0x3ffbcc90 0x400d0af6:0x3ffbcd60
2017.09.21-10:12:59.648<2>: target:
2017.09.21-10:12:59.648<2>: target: Rebooting...
2017.09.21-10:12:59.775<2>: target: light_sleep_enter
2017.09.21-10:13:00.775<2>: target: Guru Meditation Error of type IllegalInstruction occurred on core 0. Exception was unhandled.
2017.09.21-10:13:00.775<2>: target: Register dump:
2017.09.21-10:13:00.780<2>: target: PC : 0x40112162 PS : 0x00060933 A0 : 0x800fc3cd A1 : 0x3ffbcc70
2017.09.21-10:13:00.791<2>: target: A2 : 0x00000000 A3 : 0x3ffb12f8 A4 : 0x00000001 A5 : 0x00000003
2017.09.21-10:13:00.796<2>: target: A6 : 0x00000022 A7 : 0x00060023 A8 : 0x8011215f A9 : 0x3ffbcc50
2017.09.21-10:13:00.807<2>: target: A10 : 0x3ff480b4 A11 : 0x4c4b4c4b A12 : 0x3ff48070 A13 : 0x01000000
2017.09.21-10:13:00.812<2>: target: A14 : 0x00000080 A15 : 0x00000001 SAR : 0x00000016 EXCCAUSE: 0x00000000
2017.09.21-10:13:00.823<2>: target: EXCVADDR: 0x00000000 LBEG : 0x400014fd LEND : 0x4000150d LCOUNT : 0xfffffffb
2017.09.21-10:13:00.823<2>: target:
2017.09.21-10:13:00.839<2>: target: Backtrace: 0x40112162:0x3ffbcc70 0x400fc3ca:0x3ffbcc90 0x400d0af6:0x3ffbcd60
2017.09.21-10:13:00.839<2>: target:
2017.09.21-10:13:00.840<2>: target: Rebooting...




This is observed using current ESP-IDF head commit: 3924594aed7f44a09b6137479ca1ca18d138c310
Attached is sdkconfig as used to demonstrate the problem

Best regards,
Gatis

[ESP_igrr]

It looks like the flash chip is not waking up fast enough after sleep. Can you try increasing CONFIG_ESP32_DEEP_SLEEP_WAKEUP_DELAY even further? (i see that you have it set to 1500 already).

[gatisp]

Tried setting CONFIG_ESP32_DEEP_SLEEP_WAKEUP_DELAY to 2000, 5000, 10000, 100000, crash did not change.

I am using ESP-WROOOM-32 module BTW, with original flash chip, MACADDR:24:0a:c4:0f:1b:6c

The board has no problems waking up from deep sleep (no watchdog reboots when waking up from deep sleep).

Tried it on 2 other boards, with same results.

Anybody using light sleep in actual programs?

[gatisp]

Confirmed same behaviour with DevBoard

[ESP_igrr]

Thanks for the report again, i was able to reproduce the issue. We will have it fixed shortly. In the meantime, you may enable dual core mode as a workaround (the issue only happens in single core mode).

[gatisp]

Thanks esp_igrr, just tried the fix, the situation has improved, but there is still a problem with light sleep.

I have boiled it down to following code where there seems to happen some random crash on wakeup:

#include "esp_spi_flash.h"
#include "nvs_flash.h"
#include "esp_system.h"

#define FLASH_NV_DATA_ADDR 0x2b0000
unsigned char xxx[256];

void app_main(void) {
spi_flash_init();
spi_flash_read_encrypted(FLASH_NV_DATA_ADDR, &xxx, 16);
// spi_flash_read(FLASH_NV_DATA_ADDR, &xxx, 16);
printf("%llu: light sleep start\n", 0llu);
esp_sleep_enable_timer_wakeup(1000000);
esp_light_sleep_start();
printf("%llu: light sleep out\n", 1llu);
}


The key part here is spi_flash_read_encrypted - without that call it wakes up just fine. With it I get either silent reboot or some garbage on serial output + reboot.

SDK version: 845c3fba3515df90f20ac6ee552aed504375b9d4

Attached is sdkconfig as used to compile the code

Just checked that doing regular spi_flash_read also works (the cpu wakes just fine). Also note that on board the flash encryption is not actually enabled. Tried it on dev-board - same problem.

[gatisp]

Hello,

So I have investigated the problem some more and found that actual culprit of esp32 not being able to wake from light sleep is call to

Cache_Flush_rom(0);

called by Cache_Flush(0);
called by spi_flash_mmap_pages();
called by spi_flash_mmap
called by spi_flash_read_encrypted

when I comment out the lines in spi_flash_mmap_pages:
// Cache_Flush(0);
// Cache_Flush(1);

Then the board is able to wake up from light sleep afterwards.

Of course as the name implies there is no source code for Cache_Flush_rom as it is burned into ROM.

Tried enabling the second core, with same results.

[gatisp]

Just to explain why we need spi_flash_read_encrypted is because we are planning to use the very cool feature of esp32 - encrypted flash.

And when using encrypted flash the bootloader is doing spi_flash_read_encrypted to load partition table or something thus preventing light sleep in apps that use encrypted flash.

[ESP_igrr]

Thanks once again for a very detailed description of the issue.

This time the issue was caused by combination of two factors:

1. You have release mode enabled in sdkconfig. In release mode, we use -Os optimization flag, which makes GCC produce jump tables for some of the switches. In this case it happened for rtc_clk_bbpll_set function, which is called immediately after exiting light sleep via rtc_clk_cpu_freq_set. In the linker script, all the code of soc component was placed into IRAM, but constant data was not placed into IRAM.

2. Call to Cache_Flush (rom) function would flush all the contents of cache memory. Under normal circumstances, rtc_clk_bbpll_set is called at least once after startup, so if there is no significant cache pressure, the constant data of rtc_clk_bbpll_set would still be in the cache (this was the case in our unit tests). However after a call to Cache_Flush, constant data of rtc_clk_bbpll_set was removed from the cache.

So the constant data (jump tables for switch statements) ended up in cached data region, and we attempted to use it while flash was not ready so serve cache requests yet, due to power-on time restriction.

The fix is basically one line, which we will have in master branch soon:

Code: Select all

From 73e8afc5b9fa90f9dc63d0d056abbb3fadd6a420 Mon Sep 17 00:00:00 2001
From: Ivan Grokhotkov <ivan@espressif.com>
Date: Tue, 26 Sep 2017 17:08:49 +0800
Subject: [PATCH] soc: place constant data from rtc_clk.c into DRAM

In release mode, switches in rtc_clk_bbpll_set would be converted to
jump tables. These tables would be placed into .rodata, which caused
rtc_clk_cpu_freq_set to be unusable while cache is disabled. This
manifested itself in crashes when exiting from light sleep:

https://esp32.com/posting.php?mode=reply&f=13&t=3089#pr14590
---
 components/esp32/ld/esp32.common.ld | 1 +
 1 file changed, 1 insertion(+)

diff --git a/components/esp32/ld/esp32.common.ld b/components/esp32/ld/esp32.common.ld
index 5b5be9a67..32fc089d3 100644
--- a/components/esp32/ld/esp32.common.ld
+++ b/components/esp32/ld/esp32.common.ld
@@ -117,6 +117,7 @@ SECTIONS
     *(.dram1 .dram1.*)
     *libesp32.a:panic.o(.rodata .rodata.*)
     *libphy.a:(.rodata .rodata.*)
+    *libsoc.a:rtc_clk.o(.rodata .rodata.*)
     *libapp_trace.a:(.rodata .rodata.*)
     *libgcov.a:(.rodata .rodata.*)
     *libheap.a:multi_heap.o(.rodata .rodata.*)
-- 
2.11.0 (Apple Git-81)

It's actually a very good idea to use Cache_Flush to detect if something that should be non-cached ends up in the cache (*). I will try sprinkling this in our unit tests, that could uncover some issues.

(*) unless one is using pSRAM.

[gatisp]

Thanks ESP_igrr, the light sleep does work now!