espressif / esp-zigbee-sdk

Espressif Zigbee SDK
Apache License 2.0
178 stars 31 forks source link

Analyzing Zigbee Startup Time of the ESP32C6 (TZ-673) #270

Open susch19 opened 9 months ago

susch19 commented 9 months ago

Question

How can I analyze, why my ESP32-C6 End Device takes so long during boot up? From multiple logs in this repository I saw, that the bootup should require less than a second after reset or deep sleep. But no matter what I try, the "Device rebooted" Message always takes 3 seconds to appear. I tried multiple samples, multiple Coordinators, and different SDK Configs, but nothing changed the outcome at all.

The Coordinator doesn't have this problem, so restarting the coordinator, everything is finished and command successfully send after just 501ms, with no variation.

I'm testing with an ESP32-C6-WROOM-1-N8

I also tried it with the following combinations:

Additional context.

Sample Output of 5.1.2

I (23) boot: ESP-IDF v5.1.2-dirty 2nd stage bootloader
I (24) boot: compile time Mar  3 2024 11:15:43
I (24) boot: chip revision: v0.0
I (27) boot.esp32c6: SPI Speed      : 80MHz
I (32) boot.esp32c6: SPI Mode       : DIO
I (36) boot.esp32c6: SPI Flash Size : 2MB
I (41) boot: Enabling RNG early entropy source...
I (47) 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 000e1000
I (80) boot:  3 zb_storage       Unknown data     01 81 000f1000 00004000
I (87) boot:  4 zb_fct           Unknown data     01 81 000f5000 00000400
I (95) boot: End of partition table
I (99) esp_image: segment 0: paddr=00010020 vaddr=42068020 size=108e0h ( 67808) map
I (121) esp_image: segment 1: paddr=00020908 vaddr=40800000 size=07710h ( 30480) load
I (129) esp_image: segment 2: paddr=00028020 vaddr=42000020 size=65118h (413976) map
I (215) esp_image: segment 3: paddr=0008d140 vaddr=40807710 size=06a08h ( 27144) load
I (222) esp_image: segment 4: paddr=00093b50 vaddr=4080e120 size=01964h (  6500) load
I (228) boot: Loaded app from partition at offset 0x10000
I (228) boot: Disabling RNG early entropy source...
I (244) cpu_start: Unicore app
I (245) cpu_start: Pro cpu up.
W (253) clk: esp_perip_clk_init() has not been implemented yet
I (260) cpu_start: Pro cpu start user code
I (260) cpu_start: cpu freq: 160000000 Hz
I (260) cpu_start: Application information:
I (263) cpu_start: Project name:     on_off_light_bulb
I (269) cpu_start: App version:      2e2b779-dirty
I (274) cpu_start: Compile time:     Mar  3 2024 11:15:23
I (280) cpu_start: ELF file SHA256:  715ffceb798d79ce...
I (286) cpu_start: ESP-IDF:          v5.1.2-dirty
I (292) cpu_start: Min chip rev:     v0.0
I (296) cpu_start: Max chip rev:     v0.99
I (306) heap_init: Initializing. RAM available for dynamic allocation:
I (337) spi_flash: flash io: dio
nary image header.
I (354) sleep: Configure to isolate all GPIO pins in sleep state
I (361) sleep: Enable automatic switching of GPIO sleep configuration
I (368) coexist: coex firmware version: b6d5e8c
I (379) app_start: Starting scheduler on CPU0
I (383) main_task: Started on CPU0
I (383) main_task: Calling app_main()
I (393) gpio: GPIO[8]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (393) phy_init: phy_version 230,c773401,Oct 30 2023,15:07:16
I (433) phy: libbtbb version: 7243671, Oct 30 2023, 15:07:30
I (453) main_task: Returned from app_main()
I (463) ESP_ZB_ON_OFF_LIGHT: ZDO signal: ZDO Config Ready (0x17), status: ESP_FAIL
I (463) ESP_ZB_ON_OFF_LIGHT: Zigbee stack initialized
I (2963) ESP_ZB_ON_OFF_LIGHT: Device started up in non factory-reset mode
I (2963) ESP_ZB_ON_OFF_LIGHT: Device rebooted

Output of 5.3:

I (409) phy_init: phy_version 250,e14681b,Jan 24 2024,17:43:11
I (449) phy: libbtbb version: 939f79c, Jan 24 2024, 17:43:26
I (459) main_task: Returned from app_main()
I (469) ESP_ZB_DEEP_SLEEP: ZDO signal: ZDO Config Ready (0x17), status: ESP_FAIL
I (469) ESP_ZB_DEEP_SLEEP: Zigbee stack initialized
I (3299) ESP_ZB_DEEP_SLEEP: Device started up in non factory-reset mode
I (3299) ESP_ZB_DEEP_SLEEP: Device rebooted

Sample of Coordinator Reboot with 5.1.2:

I (23) boot: ESP-IDF v5.1.2-dirty 2nd stage bootloader
I (24) boot: compile time Mar  3 2024 11:20:49
I (24) boot: chip revision: v0.0
I (27) boot.esp32c6: SPI Speed      : 80MHz
I (32) boot.esp32c6: SPI Mode       : DIO
I (36) boot.esp32c6: SPI Flash Size : 2MB
I (41) boot: Enabling RNG early entropy source...
I (47) 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 000e1000
I (80) boot:  3 zb_storage       Unknown data     01 81 000f1000 00004000
I (87) boot:  4 zb_fct           Unknown data     01 81 000f5000 00000400
I (95) boot: End of partition table
I (99) esp_image: segment 0: paddr=00010020 vaddr=42088020 size=10670h ( 67184) map
I (121) esp_image: segment 1: paddr=00020698 vaddr=40800000 size=07980h ( 31104) load
I (129) esp_image: segment 2: paddr=00028020 vaddr=42000020 size=86c9ch (552092) map
I (244) esp_image: segment 3: paddr=000aecc4 vaddr=40807980 size=05e68h ( 24168) load
I (250) esp_image: segment 4: paddr=000b4b34 vaddr=4080d7f0 size=01a7ch (  6780) load
I (256) boot: Loaded app from partition at offset 0x10000
I (256) boot: Disabling RNG early entropy source...
I (273) cpu_start: Unicore app
I (273) cpu_start: Pro cpu up.
W (282) clk: esp_perip_clk_init() has not been implemented yet
I (288) cpu_start: Pro cpu start user code
I (289) cpu_start: cpu freq: 160000000 Hz
I (289) cpu_start: Application information:
I (291) cpu_start: Project name:     on_off_switch
I (297) cpu_start: App version:      2e2b779-dirty
I (302) cpu_start: Compile time:     Mar  3 2024 11:20:30
I (308) cpu_start: ELF file SHA256:  89a2ebed...
I (314) cpu_start: ESP-IDF:          v5.1.2-dirty
I (319) cpu_start: Min chip rev:     v0.0
I (324) cpu_start: Max chip rev:     v0.99
I (329) cpu_start: Chip rev:         v0.0
I (333) heap_init: Initializing. RAM available for dynamic allocation:
I (341) heap_init: At 40818D60 len 000638B0 (398 KiB): D/IRAM
I (347) heap_init: At 4087C610 len 00002F54 (11 KiB): STACK/DIRAM
I (354) heap_init: At 50000000 len 00003FE8 (15 KiB): RTCRAM
I (361) spi_flash: detected chip: generic
I (365) spi_flash: flash io: dio
W (369) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (382) sleep: Configure to isolate all GPIO pins in sleep state
I (389) sleep: Enable automatic switching of GPIO sleep configuration
I (396) coexist: coex firmware version: b6d5e8c
I (401) coexist: coexist rom version 5b8dcfa
I (406) app_start: Starting scheduler on CPU0
I (411) main_task: Started on CPU0
I (411) main_task: Calling app_main()
I (421) gpio: GPIO[9]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2
I (421) phy_init: phy_version 230,c773401,Oct 30 2023,15:07:16
I (461) phy: libbtbb version: 7243671, Oct 30 2023, 15:07:30
I (471) main_task: Returned from app_main()
I (481) ESP_ZB_ON_OFF_SWITCH: ZDO signal: ZDO Config Ready (0x17), status: ESP_FAIL
I (481) ESP_ZB_ON_OFF_SWITCH: Zigbee stack initialized
W (491) ESP_ZB_ON_OFF_SWITCH: Network(0x54f1) closed, devices joining not allowed.
I (491) ESP_ZB_ON_OFF_SWITCH: Device started up in non factory-reset mode
I (491) ESP_ZB_ON_OFF_SWITCH: Device rebooted
I (501) ESP_ZB_ON_OFF_SWITCH: Send 'on_off toggle' command
xieqinan commented 8 months ago

@susch19 ,

Could you please attempt to set the channel_mask to ESP_ZB_BDB_CHANNEL_SET_MASK_MINIMUM (only a single channel) and retry again? About 2 seconds are spent on the channel scan when the device rejoins, if you set the channel_mask to ESP_ZB_BDB_CHANNEL_SET_MASK_MAXIMUM.

nomis commented 8 months ago

Is there an API get the channel of the network that an end device has previously been registered on?

Perhaps it could avoid a channel scan on startup if the network is reachable on that channel?

susch19 commented 8 months ago

@xieqinan I actually don't know what you mean with ESP_ZB_BDB_CHANNEL_SET_MASK_MINIMUM, since I can't find it anywhere. So I just put a single channel inside primary channel and than all channels into secondary. Now the Bootup Time is roughly 1.2 seconds

I (463) main_task: Returned from app_main()
I (464) ESP_ZB_SLEEP: ZDO signal: ZDO Config Ready (0x17), status: ESP_FAIL
I (467) ESP_ZB_SLEEP: Zigbee stack initialized
I (1214) ESP_ZB_SLEEP: Device started up in non factory-reset mode
I (1215) ESP_ZB_SLEEP: Device rebooted

That's already better, but still double the time the logs of the deep sleep sample take. I would've never guessed, that the end device doesn't remember the channel, because the coordinator does, and the end device could always just try the last known channel, before falling back to the primary and secondary channel configs.

Could I have analyzed since myself without just changing things and hoping for a better result? Or are the inner workings of the Zigbee stack not analyzable for us, except for the log lines that are printed at the beginning?

xieqinan commented 7 months ago

@susch19 ,

That's already better, but still double the time the logs of the deep sleep sample take. I would've never guessed, that the end device doesn't remember the channel, because the coordinator does, and the end device could always just try the last known channel, before falling back to the primary and secondary channel configs.

I have checked the reboot process of the ZBOSS stack and found that it scans channels based on the channel_mask set by the user for rejoining the network. This method seems to trigger the above issue, and it appears to conflict with the Zigbee BDB spec. I will confirm this with the relevant staff members to ensure accuracy.

image

Could I have analyzed since myself without just changing things and hoping for a better result? Or are the inner workings of > > the Zigbee stack not analyzable for us, except for the log lines that are printed at the beginning?

We plan to provide more logs for users, and I expect this feature to be released within the next two versions. Additionally, the ESP-Zigbee-SDK offers a development mode specifically designed for debugging purposes. You can refer to the documentation for more information on enabling debug mode and trace logging.