rtc_clk_cpu_freq_set() lockups

[permal]

Hi,

I'm having issues very early in the boot process on my ESP32 Thing from Spakfun (26Mhz XTAL). I can only describe the problem as a total lockup of the entire system.

To track down the issue I've enabled every debug option I've found but since that didn't yield any additional information I'm not back a nearly default config; only verbose logging, 26Mhz XTAL and increased main task stack size (8192) changed.

The only thing I know is that the boot process locks up in, or very soon after the call to rtc_clk_cpu_freq_set(). I've determined this though old-fashioned printf() (or as is the case here ESP_EARLY_LOGI) logging.

My clk.c currently looks as follows:

Code: Select all

<Line 90> // Wait for UART TX to finish, otherwise some UART output will be lost
            // when switching APB frequency
             ESP_EARLY_LOGI("esp_clk_init", "%d", __LINE__);
             uart_tx_wait_idle(CONFIG_CONSOLE_UART_NUM);
             ESP_EARLY_LOGI("esp_clk_init", "%d", __LINE__);

            uint32_t freq_before = rtc_clk_cpu_freq_value(rtc_clk_cpu_freq_get()) / MHZ ;
<Line 97>  ESP_EARLY_LOGI("esp_clk_init", "%d", __LINE__);

             rtc_clk_cpu_freq_set(freq);
             ESP_EARLY_LOGI("esp_clk_init", "%d", __LINE__);

             // Re calculate the ccount to make time calculation correct. 
             uint32_t freq_after = CONFIG_ESP32_DEFAULT_CPU_FREQ_MHZ;

This produces the following output (startcpu0_default() is also sprinkled with logging)

Code: Select all

I (0) cpu_start: App cpu up.
I (305) heap_init: Initializing. RAM available for dynamic allocation:
D (312) heap_init: New heap initialised at 0x3ffae6e0
I (317) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
D (323) heap_init: New heap initialised at 0x3ffb9e48
I (328) heap_init: At 3FFB9E48 len 000261B8 (152 KiB): DRAM
I (335) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (341) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (347) heap_init: New heap initialised at 0x4008ffb4
I (352) heap_init: At 4008FFB4 len 0001004C (64 KiB): IRAM
I (359) cpu_start: Pro cpu start user code
I (363) start_cpu0_default: 257
I (367) start_cpu0_default: 259
I (371) start_cpu0_default: 300
I (375) esp_clk_init: 53
I (378) esp_clk_init: 55
I (381) esp_clk_init: 57
I (384) esp_clk_init: 59
I (388) esp_clk_init: 66
D (398) clk: RTC_SLOW_CLK calibration value: 3272350
I (398) esp_clk_init: 68
I (399) esp_clk_init: 71
I (402) esp_clk_init: 88
I (406) esp_clk_init: 92
I (420) esp_clk_init: 94
I (420) esp_clk_init: 97

There is no output after the last line, garbled or otherwise. The lockup happens about 50% of the time the device starts. The log on line 100 is never seen.

Anyone with an idea of what is going on?

[ESP_igrr]

What is the CPU frequency set in menuconfig? (Component config > ESP32 specific)? Does the behaviour (rate of failure) change if you set different CPU frequency?

[permal]

Default 160Mhz. I'll make some measurements using 80 and 240Mhz

[permal]

It does seem to make a difference. At 80Mhz it hangs slightly more often than on 160Mhz. ~70% vs ~50%. At 240Mhz I didn't get it to hang at all.

[ESP_igrr]

This probably indicates that 320M PLL is failing to get a lock. I wonder why you haven't been seeing this issue in the past and then it suddenly appeared. There haven't been any changes to PLL configuration code recently...
Could you please add a log to rtc_clk to verify what value is returned by rtc_clk_xtal_freq_get when PLL is getting enabled?

[permal]

I'm not 100% sure I understand what you want (what is a 320M PLL?), but I printed the value retrieved via rtc_clk_xtal_freq_get() at the beginning of rtc_clk_cpu_freq_set() at all three frequences, with the following result:

240MHz: 26
160MHz: 26
80MHz: 26

If it matters, the app hung during the test at 160MHz.

The reason I've not seen this earliermight be that I've always run on 240MHz earlier. But surely others are running at 80 and 160MHz?

[ESP_igrr]

I guess if anyone else who has a 26MHz board can do a test with 80/160 MHz and chime in here, that would be very helpful.

320MHz PLL is the PLL from which 80 and 160MHz clocks are derived. When you use 240MHz CPU frequency, a different PLL (480MHz) is used. They have different parameters, and it looks like the 320MHz one is failing to lock in your case. PLL parameters depend on XTAL frequency, which is why the issue is not observed with a 40MHz XTAL.

The question is whether the chip or XTAL on your board is somehow out of spec, or this is common behavior for all boards with 26MHz XTAL.

[loboris]

I've tested my SparkFun ESP32 Thing with 80MHz and 160MHz (~ 50 reboots) and it boots and runs without error.

Code: Select all

MONITOR
--- idf_monitor on /dev/ttyUSB0 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
ets Jun  8 2016 00:22:57

rst:0x10 (RTCWDT_RTC_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:5736
load:0x40078000,len:0
ho 12 tail 0 room 4
load:0x40078000,len:12476
entry 0x40078f74
W (55) rtc_clk: Possibly invalid CONFIG_ESP32_XTAL_FREQ setting (26MHz). Detected 26 MHz.
I (39) boot: ESP-IDF ESP32_LoBo_v1.9.1-31-g7a7a956-dirty 2nd stage bootloader
I (39) boot: compile time 20:54:15
I (52) boot: Enabling RNG early entropy source...
I (52) boot: SPI Speed      : 40MHz
I (52) boot: SPI Mode       : DIO
I (54) boot: SPI Flash Size : 4MB
I (58) boot: Partition Table:
I (62) boot: ## Label            Usage          Type ST Offset   Length
I (69) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (77) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (84) boot:  2 MicroPython      factory app      00 00 00010000 00270000
I (92) boot:  3 internalfs       Unknown data     01 81 00280000 00140000
I (99) boot: End of partition table
I (103) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x46c90 (289936) map
I (213) esp_image: segment 1: paddr=0x00056cb8 vaddr=0x3ffb0000 size=0x09358 ( 37720) load
I (228) esp_image: segment 2: paddr=0x00060018 vaddr=0x400d0018 size=0xbce14 (773652) map
0x400d0018: _stext at ??:?

I (496) esp_image: segment 3: paddr=0x0011ce34 vaddr=0x3ffb9358 size=0x02e44 ( 11844) load
I (501) esp_image: segment 4: paddr=0x0011fc80 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _iram_start at /home/LoBo2_Razno/ESP32/MicroPython/test/MicroPython_ESP32_psRAM_LoBo/Tools/esp-idf/components/freertos/./xtensa_vectors.S:1675

I (503) esp_image: segment 5: paddr=0x00120088 vaddr=0x40080400 size=0x14a94 ( 84628) load
I (546) esp_image: segment 6: paddr=0x00134b24 vaddr=0x400c0000 size=0x00064 (   100) load
I (547) esp_image: segment 7: paddr=0x00134b90 vaddr=0x50000000 size=0x00400 (  1024) load
I (569) boot: Loaded app from partition at offset 0x10000
I (569) boot: Disabling RNG early entropy source...
I (570) cpu_start: Pro cpu up.
I (573) cpu_start: Starting app cpu, entry point is 0x40081244
0x40081244: call_start_cpu1 at /home/LoBo2_Razno/ESP32/MicroPython/test/MicroPython_ESP32_psRAM_LoBo/Tools/esp-idf/components/esp32/./cpu_start.c:219

I (0) cpu_start: App cpu up.
I (584) heap_init: Initializing. RAM available for dynamic allocation:
D (590) heap_init: New heap initialised at 0x3ffae6e0
I (595) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
D (602) heap_init: New heap initialised at 0x3ffc2b80
I (607) heap_init: At 3FFC2B80 len 0001D480 (117 KiB): DRAM
I (613) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (619) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (626) heap_init: New heap initialised at 0x40094e94
I (631) heap_init: At 40094E94 len 0000B16C (44 KiB): IRAM
I (637) cpu_start: Pro cpu start user code
D (649) clk: RTC_SLOW_CLK calibration value: 3687188
D (659) intr_alloc: Connected src 46 to int 2 (cpu 0)
D (659) intr_alloc: Connected src 57 to int 3 (cpu 0)
D (660) intr_alloc: Connected src 16 to int 9 (cpu 0)
D (664) intr_alloc: Connected src 24 to int 12 (cpu 0)
I (670) cpu_start: Starting scheduler on PRO CPU.
D (0) intr_alloc: Connected src 25 to int 2 (cpu 1)
I (4) cpu_start: Starting scheduler on APP CPU.
D (694) heap_init: New heap initialised at 0x3ffe0440
D (699) heap_init: New heap initialised at 0x3ffe4350
D (706) nvs: nvs_flash_init_custom partition=nvs start=9 count=6

By the way, there is a confusing warning at the begining:
W (55) rtc_clk: Possibly invalid CONFIG_ESP32_XTAL_FREQ setting (26MHz). Detected 26 MHz.
This warning is also present on boards with 40MHz crystal (ESP32-WROVER-KIT)...

[ESP_igrr]

W (55) rtc_clk: Possibly invalid CONFIG_ESP32_XTAL_FREQ setting (26MHz). Detected 26 MHz.

Yes, that's a bug in the code printing the warning. We have a fix for this sitting somewhere in the merge queue.

[permal]

For others who don't know what a PLL is, read about it here: Phase Locked Loop.

Ok, so if this is a hardware error, then both by ESP32 Things are broken because they both exhibit these same symptoms.


As a side note, what does this log message mean? I can't find it in the soruces?

PTK has been installed, it may be an attack, ignor it