rtc_clk_cpu_freq_set() lockups

[ESP_igrr]

permal: I'll talk to hardware colleagues to see if they can offer a way to diagnose this issue by running some code on your side. Even if this is a hardware issue, we would like to understand the failure mode better.

[permal]

permal: I'll talk to hardware colleagues to see if they can offer a way to diagnose this issue by running some code on your side. Even if this is a hardware issue, we would like to understand the failure mode better.

Ok, I'm up for that.

If I understand this correctly, this issue can happen also at a later time, right? I.e. the PLL getting out of phase long after reboot? (yes, I am getting lockups with the exact same behavior).

[permal]

ESP_iggr, any update on this? I'm still willing to run some diagnostics.

[ESP_igrr]

Do you happen to have a scope which can display 80/160/320 MHz signal? Or a frequency meter? We can pull out these clocks to a pad and check whether PLL is working or not.

[permal]

Sadly, no. My Rigol 1054z has a bandwidth of 100Mhz, so those frequencies are a bit too high to show the true signal form.

[ESP_igrr]

Ok, i think it will still be good enough to show presence/absence of clock signal.

Could you please add the following at the start of esp_clk_init function ($IDF_PATH/components/esp32/clk.c):

Code: Select all

    const int sig_num = 8;
    PIN_FUNC_SELECT(PERIPHS_IO_MUX_GPIO0_U, FUNC_GPIO0_CLK_OUT1);
    REG_WRITE(PIN_CTRL, sig_num);

And then the second test with sig_num = 13.

Value 8 should route the 80MHz clock divided from the PLL, to GPIO0. Value 13 should route 80 or 160MHz clock, depending on the selected CPU frequency.

The result i expect is that when you see that the chip locks up, no clock will be observed on GPIO0 (both in the case of sig_num=8 and sig_num=13). If this is the case, we will proceed to troubleshoot PLL configuration. If this is not the case, we will need to think what else can cause the lock-up.

[permal]

Absolutely, I'll do it this evening.

[permal]

Igrr,

With sig_num = 8 and freq set at 80MHz, I only got noise on GPIO0. Both in functional and non-functional state.

Noice

DS1Z_QuickPrint1.png (84.91 KiB) Viewed 10516 times

However, with sig_num = 13, I got this at 80MHz. The device is in a working state (blinking a LED on GPIO5)

Working, sig_num=13, 80MHz

DS1Z_QuickPrint2.png (46.71 KiB) Viewed 10516 times

When hung, it looks pretty much the same, though the duty cycle is then exactly 50/50 compared to the previous image where it actually differs over time by up to 2%.

Hung, sig_num=13, 80MHz

DS1Z_QuickPrint3.png (46.65 KiB) Viewed 10516 times

Results for 160MHz in the next post (can only add three images it seems)

[permal]

Increasing freq to 160MHz gives the following result. Still a 80MHz signal(I double checked the freq setting to make sure it is at 160MHz)

sig_num=13, 160MHz, functional

DS1Z_QuickPrint4.png (46.63 KiB) Viewed 10516 times

And for completeness, here is sample where it is hung with freq set at 160MHz. Again, 80MHz signal.

sig_num=13, 160MHz, hung

DS1Z_QuickPrint5.png (46.91 KiB) Viewed 10516 times

[permal]

Fwiw, the last few days I've started seeing the lockup also at 240MHz. Same h/w as previously.

Code: Select all

esptool.py v2.1
Flashing app to serial port /dev/ttyUSB0, offset 0x10000...
esptool.py v2.1
Connecting........__
Chip is ESP32D0WDQ6 (revision 0)
Uploading stub...
Running stub...
Stub running...
Changing baud rate to 921600
Changed.
Configuring flash size...
Auto-detected Flash size: 4MB
Compressed 945200 bytes to 529307...
Wrote 945200 bytes (529307 compressed) at 0x00010000 in 11.4 seconds (effective 665.6 kbit/s)...
Hash of data verified.

Leaving...
Hard resetting...
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:5544
load:0x40078000,len:0
ho 12 tail 0 room 4
load:0x40078000,len:12484
entry 0x40078f7c
W (55) rtc_clk: Possibly invalid CONFIG_ESP32_XTAL_FREQ setting (26MHz). Detected 26 MHz.
I (39) boot: ESP-IDF v3.0-dev-960-g6cc8099 2nd stage bootloader
I (39) boot: compile time 10:16:59
I (48) boot: Enabling RNG early entropy source...
I (48) boot: SPI Speed      : 40MHz
I (49) boot: SPI Mode       : DIO
I (53) boot: SPI Flash Size : 4MB
I (57) boot: Partition Table:
I (61) boot: ## Label            Usage          Type ST Offset   Length
I (68) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (76) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (83) boot:  2 factory          factory app      00 00 00010000 00100000
I (90) boot: End of partition table
I (95) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x2bf3c (180028) map
I (139) esp_image: segment 1: paddr=0x0003bf64 vaddr=0x3ffb0000 size=0x03408 ( 13320) load
I (142) esp_image: segment 2: paddr=0x0003f374 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at /home/permal/esp/esp-idf/components/freertos/./xtensa_vectors.S:1685

I (146) esp_image: segment 3: paddr=0x0003f77c vaddr=0x40080400 size=0x00894 (  2196) load
I (155) esp_image: segment 4: paddr=0x00040018 vaddr=0x400d0018 size=0xa72c4 (684740) map
0x400d0018: _flash_cache_start at ??:?

I (297) esp_image: segment 5: paddr=0x000e72e4 vaddr=0x40080c94 size=0x0f918 ( 63768) load
I (311) esp_image: segment 6: paddr=0x000f6c04 vaddr=0x400c0000 size=0x00000 (     0) load
I (315) boot: Loaded app from partition at offset 0x10000
I (315) boot: Disabling RNG early entropy source...
I (321) cpu_start: Pro cpu up.
I (325) cpu_start: Starting app cpu, entry point is 0x40080f3c
0x40080f3c: call_start_cpu1 at /home/permal/esp/esp-idf/components/esp32/./cpu_start.c:222

I (0) cpu_start: App cpu up.
I (335) heap_init: Initializing. RAM available for dynamic allocation:
D (342) heap_init: New heap initialised at 0x3ffae6e0
I (347) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
D (353) heap_init: New heap initialised at 0x3ffba448
I (358) heap_init: At 3FFBA448 len 00025BB8 (150 KiB): DRAM
I (364) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (371) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (378) heap_init: New heap initialised at 0x400905ac
I (382) heap_init: At 400905AC len 0000FA54 (62 KiB): IRAM
I (388) cpu_start: Pro cpu start user code
D (400) clk: RTC_SLOW_CLK calibration value: 3251909