UART baud rate >460800 leads to partial garbage

[rosenrot]

Could someone explain me why I do get partially perfect UART data?

The garbage coming after the "cpu_start" are random ESP_LOGE and printf outputs. However, they are garbage. Could someone tell me why?

UART console baud rate is set to 921600 or 2000000. Both lead to this results. Setting it to 460800 leads to perfect output of all messages.

<\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><\0><27>[0;32mI (181) cpu_start: Pro cpu up.<27>[0m<\r><\n>
<27>[0;32mI (181) cpu_start: Application information:<27>[0m<\r><\n>
<27>[0;32mI (182) cpu_start: App version: 1<27>[0m<\r><\n>
<27>[0;32mI (182) cpu_start: Compile time: Jun 13 2020 00:52:34<27>[0m<\r><\n>
<27>[0;32mI (182) cpu_start: ELF file SHA256: 002ffd6307be9048...<27>[0m<\r><\n>
<27>[0;32mI (182) cpu_start: ESP-IDF: v4.2-dev-1660-g7d7521367-dirty<27>[0m<\r><\n>
<27>[0;32mI (183) cpu_start: Starting app cpu, entry point is 0x40081804<27>[0m<\r><\n>
<27>[0;32mI (0) cpu_start: App cpu up.<27>[0m<\r><\n>
<27>[0;32mI (183) heap_init: Initializing. RAM available for dynamic allocation:<27>[0m<\r><\n>
<27>[0;32mI (184) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM<27>[0m<\r><\n>
<27>[0;32mI (184) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM<27>[0m<\r><\n>
<27>[0;32mI (184) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM<27>[0m<\r><\n>
<27>[0;32mI (185) heap_init: At 3FFC4468 len 0001BB98 (110 KiB): DRAM<27>[0m<\r><\n>
<27>[0;32mI (185) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM<27>[0m<\r><\n>
<27>[0;32mI (185) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM<27>[0m<\r><\n>
<27>[0;32mI (186) heap_init: At 4009516C len 0000AE94 (43 KiB): IRAM<27>[0m<\r><\n>
<27>[0;32mI (186) cpu_start: Pro cpu start user code<27>[0m<\r><\n>
ž`ž<6>˜~<30><24>x枆˜<\0><24>†<6>˜ø˜æ˜˜<24>˜ø<6>fžþfxàž<6>æø<6>ž˜<24><24>xf<6>~fæà<6>~f<6>x<\0>˜à<6>ž†ž<\0>†~<\0>˜xf†žf†øfž<30>æ<30>žf˜ž†<6>ž`ž<6>˜~<30><24>x枆˜<\0><24>†<6>˜ø˜æ˜˜<24>˜ø<6>fžþfxàž<6>æø<6>ž˜<24><24>xàž<6>æø<6>ž<\0>˜˜æž˜<24>˜àfžþžž`ž<6>˜ž†<6>ž`ž<6>˜~<30><24>x枆˜<\0><24>†<6>˜ø˜æ˜˜<24>˜à<6>f~þfø<6>~<6>†ø<6>~˜<24>˜˜<6>~<6>†ø<6>~†žøž~<6>˜øæà<6>žf<6>xf<6>žf†ø<6>˜žøž<\0><24>f˜æ˜<\0>˜€<6>ff††ž`ž<6>˜ž†<6>ž`ž<6>˜~<30><24>x枆˜<\0><24>†<\0>˜˜<24>˜à<6>f~þfø<6>~<6>†ø<6>~˜<24>˜˜<6>~<6>†ø<6>~†žøž~<6>˜øæà<6>žf<6>xf<6>žf†ø<6>˜žøž<\0>˜<\0><6>ff˜€<6>ff††ž`ž<6>˜žf€˜€ž`ž<6>˜~<30><24>x枆˜<\0><24>†<24>˜ø˜<30>††<\0><24>€<6>f`f˜þf<24>†˜†˜`f~<\0><24>€<6>f<\0>˜àæžøž`†øæžàžàžf†ø<6>˜àæžæž<\0>fžàžf<6><24>~f†øæøfžþžøž<\0>˜žf˜†fx<6>˜æ˜x<\0>˜~æ<30>žf˜ž†<6>ž`ž<6>˜~<30><24>x枆˜<\0><24>†<24>˜ø˜<30>††<\0>˜øfæø<6>~ffžþf€<6>fž˜<24><24>€fæøfx<\0>˜<30>fæ€<6>˜€<6>x`†øfx<30>æø<6>˜˜æø<6><24>žþž`<6>˜øfx`æ<30>žf˜ž†<6>ž`ž<6>˜~<30><24>x枆˜<\0><24>†<24>˜ø˜<30>††<\0>˜øfæø<6>~ffžþf€<6>fž˜<24><24>øfx<6><6>x<\0><24>xf†x<6>f~àž`<6><24>àfæøfx<\0>˜<30>fæ€<6>˜€<6>x`†øfx<30>æø<6><24>x<24>æžæž<\0>˜<6>†`ff˜f`ž`ž<6>˜ž†<6>ž`ž<6>˜~<30><24>x枆˜<\0><24>†<30><24>˜<30>††<\0><24><6>ž††~<\0><24><6>ž†æf~f†øæøfžþžøž˜<24><24><30><6><24>˜à<24>†<\0>˜àf˜€<6>˜xf†xà†<\0>˜<30>f†ø<6>˜à<24><24><24>x<\0><24>x<\0><24>†<\0>˜à<24>x˜<24><30>f<24>~<\0><24><30>à†<\0><24><24>†<\0><24>˜<30>žf˜žf€˜€ž`ž<6>˜~<30><24>x枆˜<\0><24>†f˜æ˜à˜˜<24><24>fžþf†æø<6>æx<24><24>~<\0><24>`<24>fx<6>f~f†ž<30>f<6>˜øæ~†ž`æà<6>ž†žøž~<6>˜àæžøžxfž~†~<\0>˜€<6>ffæf<30>f<6>f~<\0>˜à<24><30><\0><24>†<\0>˜<\0><6>f€æf<30>f<6>f~<\0>˜à<24><30><\0><24>†<\0>˜<\0><6>f€æf<30>f˜ø˜˜<24>˜à<24><30><\0><24>†<\0><24>˜†ž~<6>ž`<6>˜ø<6>žffx<\0>†~<\0><24>`†˜<30>f<\0>†€<6>˜f<6>`ž`ž<6>˜ž†<6>ž`ž<6>˜~<30>˜xæž~f<24>†f˜æ˜à˜˜<24>˜†<6>fžøž<30>fx<24>†à枀ž<24><24>~<\0><24>x<24>fxf<6>˜žfxæžþž<24>f†~<\0>˜à˜<30>~<24>˜æ†àæ<30>žf˜ž†<6><6>æ˜<6>`˜€~f<6>f<24>†øæž<30>fx`f~<24>fx<\0>˜˜†ž†ž`fž<6><6>~f<6>x˜<24>˜€<6>xxfx<24><6>~†ž<30>fxž<24><24>x†ž<30>æàæfžæž`fxæ<24>x<\0>˜€<6>xxæfà<6>ž<6>†žøžf<6>žþfžf<6>f<24><24>˜ž~†žþf€<6>x`†øæf~†<6>fxæ<24><24>˜€<6>xxæfx†žàž`fx<24>æfæžàž†ž<30>ff<24><24>˜€<6>xxæf˜<6>~x<6>žþfžfžøžæ<24><24>˜€<6>xxæf˜<6>~x<6>žþfžf<6>f<24><24><6>~f<6>f<24>†øæž<30>fx`f~<24>fx<\0>˜˜†ž†ž`fž<6><6>~f<6>x˜<24>˜ø<6>~þž<\0><6>˜€<6>xxfx<24><6>~†ž<30>fžøž~††˜€f†ø†øæž<24><6>˜††ž<6>†à<6>ž†žøž~<6>˜€<6>xxfx<24><6>~†ž<30>fxæžf†ž`æ~<\0><24>øæàf˜x<\0><24><6>

[PeterR]

Well 460800 is around 50% of 921600 and even less of 2000000
UART communication is not great at high rates. The A in UART stands for asynchronous which essentially means that there is no clock signal and so the data high low detection depends on sampling multiple times. Add a bit of noise, RC etc and well it just does not work out well. Which is why the world moved on (mostly).
With multiple samples needed per bit you're 'not at all fast' 460,800 is essentially more than x4 that rate, compared to a synchronous protocol such as SPI or I2C.
Then add in electrical/drive considerations, length of cable etc and I would say you should consider yourself lucky to achive 460,800!
RS232 transfers needs a cup of tea and a patient attitude or a good electronics engineer.
You can stream ESP_LOG via Ethernet or any other interface if you want speed. Ethernet won't be great for startup logging though as even if you DHCPS the low level guts will still need to negotiate PHY stuff and that takes seconds sometimes.
Which I guess is one reason why UARTs still exist.

[rosenrot]

I completely understand your answer. However, why is the bootloader output working perfectly alright while the rest isn't. Your answer doesn't explain this fact, does it?

[PeterR]

Hmm, missed that.
Some guesses:
(1) Bootloader is different code & sets up the UART differently
(2) Stuff happens after bootloader which may interfer with the hardware and/or change the configuration

Could even be something about the source clock changing and so changing divider ratios & errors.
One the ESP!

[rosenrot]

Great, I'm not the only one wondering.
1. Shouldn't be the case because it works up to 460800 and then it becomes weird. So any idea would be great.
2. I was thinking about that. WIFI and BLE is turned of at this stage. What might it be?

It is a ESP32-WROOM-32D modul. It happens to all modules I have, even to other TTGO-Micro32 modules.

Everyone of you should be able to reproduce this issue. I'm on the latest master branch of esp-idf.

[PeterR]

Wifi and BLE are not gonna help.

You are going to get some interference. You might also get PSU effects.
Are you on a standalone PSU or USB?

[rosenrot]

I'm on USB and PSU. If this made a difference then why I do see the same effect over any of my esp32 modules. I really think that it might be a bug. Why always the same part of the boot message is perfectly alright without a single error.

I'm always asking this stupid question: Am I the first one to report this issue? If so, the problem might be me, if others reported the problem already, there is a high chance that it is device related.

So again, am I the only one seeing this issue?

[PeterR]

K, so maybe not a PSU issue.
Maybe grab UART settings at power up? If same as you set then that suggests other components interfer somehow.
Quicker maybe to binary chop you're device setup & see where it breaks.

[ESP_Angus]

Hi rosenrot,

Thanks for the report about this. I wasn't able to reproduce it. I used the same IDF commit you're using (7d75213674) and selected the hello_world example with a default configuration and then set the "UART console baud rate" and "idf.py monitor baud rate" values to first 921600 and then 2000000. Both speeds worked, on both ESP32 V1 and V3 (not that I would expect silicon revision to change this behaviour.)

Example output (2000000bps):

Code: Select all

Running idf_monitor in directory /home/angus/esp/32/idf/examples/get-started/hello_world
Executing "/home/angus/.espressif/python_env/idf4.2_py3.8_env/bin/python /home/angus/esp/32/idf/tools/idf_monitor.py -p /dev/ttyUSB0 -b 2000000 --toolchain-prefix xtensa-esp32-elf- /home/angus/esp/32/idf/examples/get-started/hello_world/build/hello-world.elf -m '/home/angus/.espressif/python_env/idf4.2_py3.8_env/bin/python' '/home/angus/esp/32/idf/tools/idf.py'"...
--- idf_monitor on /dev/ttyUSB0 2000000 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
I (32) boot: ESP-IDF v4.2-dev-1660-g7d75213674-dirty 2nd stage bootloader
I (32) boot: compile time 16:53:48
I (32) boot: chip revision: 1
I (32) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (32) boot.esp32: SPI Speed      : 40MHz
I (33) boot.esp32: SPI Mode       : DIO
I (33) boot.esp32: SPI Flash Size : 2MB
I (33) boot: Enabling RNG early entropy source...
I (33) boot: Partition Table:
I (34) boot: ## Label            Usage          Type ST Offset   Length
I (34) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (34) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (35) boot:  2 factory          factory app      00 00 00010000 00100000
I (35) boot: End of partition table
I (36) boot_comm: chip revision: 1, min. application chip revision: 0
I (36) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x058e4 ( 22756) map
I (45) esp_image: segment 1: paddr=0x0001590c vaddr=0x3ffb0000 size=0x021b8 (  8632) load
I (49) esp_image: segment 2: paddr=0x00017acc vaddr=0x40080000 size=0x00404 (  1028) load
0x40080000: _WindowOverflow4 at /home/angus/esp/32/idf/components/freertos/xtensa/xtensa_vectors.S:1730

I (50) esp_image: segment 3: paddr=0x00017ed8 vaddr=0x40080404 size=0x08140 ( 33088) load
I (65) esp_image: segment 4: paddr=0x00020020 vaddr=0x400d0020 size=0x12f60 ( 77664) map
0x400d0020: _stext at ??:?

I (94) esp_image: segment 5: paddr=0x00032f88 vaddr=0x40088544 size=0x019ec (  6636) load
0x40088544: rtc_init at /home/angus/esp/32/idf/components/soc/src/esp32/rtc_init.c:55

I (103) boot: Loaded app from partition at offset 0x10000
I (103) boot: Disabling RNG early entropy source...
I (103) cpu_start: Pro cpu up.
I (104) cpu_start: Application information:
I (104) cpu_start: Project name:     hello-world
I (104) cpu_start: App version:      v4.2-dev-1660-g7d75213674-dirty
I (104) cpu_start: Compile time:     Jun 16 2020 16:53:42
I (105) cpu_start: ELF file SHA256:  51d7165da81cf006...
I (105) cpu_start: ESP-IDF:          v4.2-dev-1660-g7d75213674-dirty
I (105) cpu_start: Starting app cpu, entry point is 0x400815e4
0x400815e4: call_start_cpu1 at /home/angus/esp/32/idf/components/esp32/cpu_start.c:286

I (0) cpu_start: App cpu up.
I (106) heap_init: Initializing. RAM available for dynamic allocation:
I (107) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (107) heap_init: At 3FFB29F0 len 0002D610 (181 KiB): DRAM
I (107) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (108) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (108) heap_init: At 40089F30 len 000160D0 (88 KiB): IRAM
I (108) cpu_start: Pro cpu start user code
I (118) spi_flash: detected chip: gd
I (119) spi_flash: flash io: dio
W (119) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (119) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
Hello world!
This is esp32 chip with 2 CPU cores, WiFi/BT/BLE, silicon revision 1, 2MB embedded flash
Free heap: 299604
Restarting in 10 seconds...
Restarting in 9 seconds...
Restarting in 8 seconds...

• The output goes bad at the same time the user app_main() function starts executing. Is it possible something in the application code is changing either the UART baud rate or something which changes the APB bus frequency?
• It's possible this is a bug exposed by some specific config. If you try the same hello_world example, delete any existing sdkconfig, and then set the two options that I mentioned above then do you get correct output?
• It's possible this is related to specific USB/serial chips or drivers as the USB/serial hardware will have different master UART clock speeds and may configure their internal clock divider differently depending on the driver. I used Linux and CP2102N.
• It's possible this is related to board layout design or noise floor. Some situation like: the UART signal is borderline but happens to be readable for this window of time during startup and then something subtle in the noise background changes again and it goes back to unreadable. However you mentioned it works on multiple generic development boards so this seems less likely as an explanation.

The UART baud rate is divided from the crystal frequency (usually 40MHz) while the bootloader is running, and then the APB peripheral bus frequency (usually 80MHz). It's a fractional clock divider so it should be pretty accurate in all cases, and very accurate for 2Mbps.

[rosenrot]

Thank you for checking. So the hello_world example is working well on my board. I'm searching for the menuconfig change which causes it.

My guess is the FreeRTOS tick rate. However, just changing it to 1000hz didn't cause the effect.

I will report back as soon as possible.