Unexpected TG1WDT_SYS_RESET in deep sleep

kostyan5
Posts: 50
Joined: Mon Mar 06, 2017 3:16 pm

Unexpected TG1WDT_SYS_RESET in deep sleep

Postby kostyan5 » Wed Jul 26, 2017 6:20 pm

Every once in a while, we're seeing esp32 being woken up by TG1WDT_SYS_RESET. From the logs below, you can see the device wakes up once as expected from DEEPSLEEP_RESET, then goes to sleep and is woken up by TG1WDT_SYS_RESET, goes to sleep again, and then woken up normally by DEEPSLEEP_RESET.

Deep sleep was set for 1 minute. The device does do a flash write before going to sleep as noted by "Saving current time..." log.

The sleep routine looks like this:

Code: Select all

esp_deep_sleep_enable_timer_wakeup(60 * 1000000);

//.... do normal operational stuff

    esp_err_t err = nvs_set_blob(m_nvs_handle, PARAMS_BLOB_KEY, &m_params, sizeof(m_params));
    if (err != ESP_OK)
    {
        ESP_LOGE(TAG, "Failed to set blob (error %x)", err);
        return;
    }

    if (nvs_commit(m_nvs_handle) != ESP_OK)
    {
        ESP_LOGE(TAG, "Failed to commit params");
        return;
    }

esp_deep_sleep_start();

Code: Select all

[0;32mI (10064) MAIN: Going to sleep[0m
[0;32mI (10064) NVS: Saving current time 1500935376[0m
ets Jun  8 2016 00:22:57

rst:0x5 (DEEPSLEEP_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:0x3fff0010,len:4
load:0x3fff0014,len:4184
load:0x40078000,len:0
ho 12 tail 0 room 4
load:0x40078000,len:12068
entry 0x40078ce4
[0;32mI (797) heap_init: Initializing. RAM available for dynamic allocation:[0m
[0;32mI (797) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM[0m
[0;32mI (803) heap_init: At 3FFCCC98 len 00013368 (76 KiB): DRAM[0m
[0;32mI (822) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM[0m
[0;32mI (841) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM[0m
[0;32mI (861) heap_init: At 40095AC4 len 0000A53C (41 KiB): IRAM[0m
[0;32mI (1049) I2C: Init i2c...done[0m
[0;32mI (1050) gpio: GPIO[4]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:1 [0m
[0;32mI (1053) ACC: Threshold 128
[0m
[0;32mI (1056) gpio: GPIO[18]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 [0m
[0;32mI (1064) SPIFFS: fs.start: size:1900 Kb, offset:0x200000
[0m
[0;32mI (1094) SPIFFS: mount res: 0
[0m
Mounted Wifi Store SPIFFS...(used 117 KB out of 1785 KB)
I (1095) wifi: wifi firmware version: f092575
I (1096) wifi: config NVS flash: enabled
I (1100) wifi: config nano formating: enabled
I (1116) wifi: Init dynamic tx buffer num: 32
I (1117) wifi: Init dynamic rx buffer num: 64
I (1117) wifi: wifi driver task: 3ffd3e5c, prio:23, stack:3584
I (1120) wifi: Init static rx buffer num: 10
I (1124) wifi: Init dynamic rx buffer num: 0
I (1128) wifi: Init rx ampdu len mblock:7
I (1132) wifi: Init lldesc rx ampdu entry mblock:4
I (1136) wifi: wifi power manager task: 0x3ffd8fd4 prio: 21 stack: 2048
I (1143) wifi: wifi timer task: 3ffd9e54, prio:22, stack:3072
I (1151) wifi: mode : sta (24:0a:c4:0a:e6:68)

I (3322) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (3322) wifi: state: init -> auth (b0)
I (3324) wifi: state: auth -> assoc (0)
E (3327) wifi: Set status to INIT.


I (3328) wifi: state: assoc -> init (11)
I (3330) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (5168) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (5168) wifi: state: init -> auth (b0)
I (5170) wifi: state: auth -> assoc (0)
E (5173) wifi: Set status to INIT.


I (5173) wifi: state: assoc -> init (11)
I (5176) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1

[0;32mI (11064) MAIN: Going to sleep[0m
[0;32mI (11064) NVS: Saving current time 1500935446[0m
ets Jun  8 2016 00:22:57

rst:0x8 (TG1WDT_SYS_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:0x3fff0010,len:4
load:0x3fff0014,len:4184
load:0x40078000,len:0
ho 12 tail 0 room 4
load:0x40078000,len:12068
entry 0x40078ce4
[0;33mW (32) boot: PRO CPU has been reset by WDT.[0m
[0;33mW (32) boot: WDT reset info: PRO CPU PC=0x40081332[0m
[0;33mW (32) boot: WDT reset info: APP CPU PC=0x255738d7[0m
[0;32mI (813) heap_init: Initializing. RAM available for dynamic allocation:[0m
[0;32mI (813) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM[0m
[0;32mI (819) heap_init: At 3FFCCC98 len 00013368 (76 KiB): DRAM[0m
[0;32mI (838) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM[0m
[0;32mI (858) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM[0m
[0;32mI (877) heap_init: At 40095AC4 len 0000A53C (41 KiB): IRAM[0m
[0;32mI (1065) I2C: Init i2c...done[0m
[0;32mI (1066) gpio: GPIO[4]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:1 [0m
[0;32mI (1069) ACC: Threshold 128
[0m
[0;32mI (1072) gpio: GPIO[18]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 [0m
[0;32mI (1080) SPIFFS: fs.start: size:1900 Kb, offset:0x200000
[0m
[0;32mI (1110) SPIFFS: mount res: 0
[0m
Mounted Wifi Store SPIFFS...(used 117 KB out of 1785 KB)
I (1111) wifi: wifi firmware version: f092575
I (1112) wifi: config NVS flash: enabled
I (1116) wifi: config nano formating: enabled
I (1132) wifi: Init dynamic tx buffer num: 32
I (1133) wifi: Init dynamic rx buffer num: 64
I (1133) wifi: wifi driver task: 3ffd3e5c, prio:23, stack:3584
I (1136) wifi: Init static rx buffer num: 10
I (1140) wifi: Init dynamic rx buffer num: 0
I (1144) wifi: Init rx ampdu len mblock:7
I (1148) wifi: Init lldesc rx ampdu entry mblock:4
I (1152) wifi: wifi power manager task: 0x3ffd8fd4 prio: 21 stack: 2048
I (1159) wifi: wifi timer task: 3ffd9e54, prio:22, stack:3072
I (1180) wifi: mode : sta (24:0a:c4:0a:e6:68)

[0;32mI (7080) MAIN: Going to sleep[0m
[0;32mI (7080) NVS: Saving current time 1500935455[0m
ets Jun  8 2016 00:22:57

rst:0x5 (DEEPSLEEP_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:0x3fff0010,len:4
load:0x3fff0014,len:4184
load:0x40078000,len:0
ho 12 tail 0 room 4
load:0x40078000,len:12068
entry 0x40078ce4

kostyan5
Posts: 50
Joined: Mon Mar 06, 2017 3:16 pm

Re: Unexpected TG1WDT_SYS_RESET in deep sleep

Postby kostyan5 » Fri Jul 28, 2017 9:31 pm

This behavior seems to be related to calling nvs_commit() before going to sleep. The timestamp of the TG1WDT reset is immediately after attempting sleep. I suspect that writing to flash immediately before going to sleep sometimes causes the TG1WDT to time out and fire a reset.
Ignore that. I just saw TG1WDT_SYS_RESET without calling nvs_commit(). The issue is still a puzzle. It seems that sometimes the watchdog is still running while the process that feeds it is asleep.

WiFive
Posts: 3529
Joined: Tue Dec 01, 2015 7:35 am

Re: Unexpected TG1WDT_SYS_RESET in deep sleep

Postby WiFive » Fri Jul 28, 2017 11:36 pm

So this happens right away, the int watchdog resets the chip before it makes it to deep sleep?

kostyan5
Posts: 50
Joined: Mon Mar 06, 2017 3:16 pm

Re: Unexpected TG1WDT_SYS_RESET in deep sleep

Postby kostyan5 » Fri Jul 28, 2017 11:38 pm

WiFive wrote:So this happens right away, the int watchdog resets the chip before it makes it to deep sleep?
It happens within a couple of seconds. I don't know if the chip actually makes it to sleep before it resets.

Who is online

Users browsing this forum: Bing [Bot] and 79 guests