Serial Port Log Analysis of the Blink Program
Once the firmware compilation and download are completed, navigate to
the project folder, and run the command idf.py monitor. This will open
a monitor with coloured font. The monitor will output the serial port
log of the target ESP32-C3. The content is divided into three parts by
default: first-level bootloader information, second-level
bootloader information, and user program output. During the output
of log, you can press the Ctrl+] key combination to exit the log
output.
ESP-ROM:esp32c3-api1-20210207
Build:Feb 7 2021
rst:0x1 (POWERON),boot:0xc (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fcd6100,len:0x1798
load:0x403ce000,len:0x8dc
load:0x403d0000,len:0x2984
entry 0x403ce000
First-level bootloader information
By default, the first-level bootloader information is output from UART
and cannot be turned off through configuration in ESP-IDF version 4.3.2.
This information includes the ROM code version information fixed
internally in the chip. Different chips in the same series may have
different ROM code versions due to ROM repairs and feature expansions.
It also includes the reason for the chip restart, such as rst:0x1
indicating power-on restart of the chip, rst:0x3 indicating
software-triggered restart, rst:0x4 indicating software exception
restart, etc. You can use this information to assess the status of the
chip. Additionally, it provides details about the chip's boot mode, such
as boot:0xc indicating SPI Flash Boot mode (normal operation mode, in
which the code in flash is loaded and executed), and boot:0x4
indicating Flash Download mode, in which the content of flash can be
erased and programmed.
Second-level bootloader information
The output of second-level bootloader information can be disabled by
setting menuconfig(Top) → Bootloader config → Bootloader log verbosity to No output.
This information mainly includes the ESP-IDF version, flash operating mode and speed, system partition and stack allocation, as well as the application name and version.
I (30) boot: ESP-IDF v4.3.2-1-g887e7c0c73-dirty 2nd stage bootloader
I (30) boot: compile time 18:27:35
I (30) boot: chip revision: 3
I (34) boot.esp32c3: SPI Speed : 80MHz
I (38) boot.esp32c3: SPI Mode : DIO
I (43) boot.esp32c3: SPI Flash Size : 2MB
I (48) boot: Enabling RNG early entropy source...
I (53) boot: Partition Table:
I (57) boot: ## Label Usage Type ST Offset Length
I (64) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (72) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (79) boot: 2 factory factory app 00 00 00010000 00100000
I (86) boot: End of partition table
I (91) esp_image: segment 0: paddr=00010020 vaddr=3c020020 size=06058h (24664) map
I (103) esp_image: segment 1: paddr=00016080 vaddr=3fc89c00 size=01a88h (6792) load
I (109) esp_image: segment 2: paddr=00017b10 vaddr=40380000 size=08508h (34056) load
I (122) esp_image: segment 3: paddr=00020020 vaddr=42000020 size=15c54h (89172) map
I (138) esp_image: segment 4: paddr=00035c7c vaddr=40388508 size=0157ch (5500) load
I (139) esp_image: segment 5: paddr=00037200 vaddr=50000000 size=00010h (16) load
I (147) boot: Loaded app from partition at offset 0x10000
I (150) boot: Disabling RNG early entropy source...
I (166) cpu_start: Pro cpu up.
I (179) cpu_start: Pro cpu start user code
I (179) cpu_start: cpu freq: 160000000
I (179) cpu_start: Application information:
I (182) cpu_start: Project name: blink
I (186) cpu_start: App version: v4.3.2-1-g887e7c0c73-dirty
I (193) cpu_start: Compile time: Jan 26 2022 18:27:31
I (199) cpu_start: ELF file SHA256: dadcae8e7bb964ab...
I (205) cpu_start: ESP-IDF: v4.3.2-1-g887e7c0c73-dirty
I (212) heap_init: Initializing. RAM available for dynamic allocation:
I (219) heap_init: At 3FC8C4D0 len 00033B30 (206 KiB): DRAM
I (225) heap_init: At 3FCC0000 len 0001F060 (124 KiB): STACK/DRAM
I (232) heap_init: At 50000010 len 00001FF0 (7 KiB): RTCRAM
I (238) spi_flash: detected chip: generic
I (243) spi_flash: flash io: dio
W (247) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (260) sleep: Configure to isolate all GPIO pins in sleep state
I (267) sleep: Enable automatic switching of GPIO sleep configuration
I (274) cpu_start: Starting scheduler.
User program output
The user program output includes all information that is printed using
the printf() function, which is the standard output function in the C
language, or the ESP_LOG() function, which is a custom output function
provided by ESP-IDF. It is recommended to use ESP_LOG() because it
allows you to specify the log level for better organisation and
filtering of logs.
You can configure which logs above a certain level are output through
menuconfig(Top) → Component config → Log output. This allows you to control the
verbosity of the logs and customise the level of detail that is
displayed during runtime.
I (278) gpio: GPIO[5]| InputEn: 0| OutfgputEn: 0| OpenDrain: 0| Pullup: 1|
Pulldown: 0| Intr:0
Turning off the LED
Turning on the LED
Turning off the LED
Turning on the LED
In addition to log output, idf.py monitor can also parse system
exceptions and trace software errors. For example, when the application
crashes, the following register dump and traceback information will be
generated:
Guru Meditation Error of type StoreProhibited occurred on core 0. Exception was unhandled.
Register dump:
PC : 0x400f360d PS : 0x00060330 A0 : 0x800dbf56 A1 : 0x3ffb7e00
A2 : 0x3ffb136c A3 : 0x00000005 A4 : 0x00000000 A5 : 0x00000000
A6 : 0x00000000 A7 : 0x00000080 A8 : 0x00000000 A9 : 0x3ffb7dd0
A10 : 0x00000003 A11 : 0x00060f23 A12 : 0x00060f20 A13 : 0x3ffba6d0
A14 : 0x00000047 A15 : 0x0000000f SAR : 0x00000019 EXCCAUSE : 0x0000001d
EXCVADDR: 0x00000000 LBEG : 0x4000c46c LEND : 0x4000c477 LCOUNT : 0x00000000
Backtrace: 0x400f360d:0x3ffb7e00 0x400dbf56:0x3ffb7e20 0x400dbf5e:0x3ffb7e40 0x400dbf82:0x3ffb7e60 0x400d071d:0x3ffb7e90
Based on the register address, the IDF monitor will query the compiled
ELF file and trace the code call process when the application crashes,
outputting the function call information to the monitor:
Guru Meditation Error of type StoreProhibited occurred on core 0. Exception was unhandled.
Register dump:
PC : 0x400f360d PS : 0x00060330 A0 : 0x800dbf56 A1 : 0x3ffb7e00
0x400f360d: do_something_to_crash at /home/gus/esp/32/idf/examples/get-started/hello_world/main/./hello_world_main.c:57
(inlined by) inner_dont_crash at /home/gus/esp/32/idf/examples/get-started/hello_world/main/./hello_world_main.c:52
A2 : 0x3ffb136c A3 : 0x00000005 A4 : 0x00000000 A5 : 0x00000000
A6 : 0x00000000 A7 : 0x00000080 A8 : 0x00000000 A9 : 0x3ffb7dd0
A10 : 0x00000003 A11 : 0x00060f23 A12 : 0x00060f20 A13 : 0x3ffba6d0
A14 : 0x00000047 A15 : 0x0000000f SAR : 0x00000019 EXCCAUSE : 0x0000001d
EXCVADDR: 0x00000000 LBEG : 0x4000c46c LEND : 0x4000c477 LCOUNT : 0x00000000
Backtrace: 0x400f360d:0x3ffb7e00 0x400dbf56:0x3ffb7e20 0x400dbf5e:0x3ffb7e40 0x400dbf82:0x3ffb7e60 0x400d071d:0x3ffb7e90
0x400f360d: do_something_to_crash at /home/gus/esp/32/idf/examples/get-started/hello_world/main/./hello_world_main.c:57
(inlined by) inner_dont_crash at /home/gus/esp/32/idf/examples/get-started/hello_world/main/./hello_world_main.c:52
0x400dbf56: still_dont_crash at /home/gus/esp/32/idf/examples/get-started/hello_world/main/./hello_world_main.c:47
0x400dbf5e: dont_crash at /home/gus/esp/32/idf/examples/get-started/hello_world/main/./hello_world_main.c:42
0x400dbf82: app_main at /home/gus/esp/32/idf/examples/get-started/hello_world/main/./hello_world_main.c:33
0x400d071d: main_task at /home/gus/esp/32/idf/components/esp32/./cpu_start.c:254
The trace information of the monitor shows that the application crashes
in the function do_something_to_crash(), which is called by the
function app_main() → dont_crash() → still_dont_crash() → inner_dont_crash() → do_something_to_crash(). Based on this, the input/output parameters of each link
can be checked to determine the cause of the crash.