Serial monitor delay at ESP32 startup

PlatformIO IDE
1

When my ESP32 starts up, the first 2.5seconds of any serial output is lost.

Here is an experiment. The first lines of my setup() are:

    ESP_LOGE("kinimain", "App started!");
    uint32_t waitSome = millis();
    uint32_t nowMillis;
    while ((nowMillis = millis()) < waitSome + 3500) {
      delay(100);
      ESP_LOGE("kinimain", "delay %ld", nowMillis - waitSome);
    }

What I see in the VsCode/PIO monitor when I turn the device on:

Reconnecting to /dev/cu.usbmodem831401 ....      Connected!
[  2702][E][KiniMain.cpp:102] setup(): [kinimain] delay 2405
[  2802][E][KiniMain.cpp:102] setup(): [kinimain] delay 2506
[  2902][E][KiniMain.cpp:102] setup(): [kinimain] delay 2606
[  3002][E][KiniMain.cpp:102] setup(): [kinimain] delay 2706
[  3102][E][KiniMain.cpp:102] setup(): [kinimain] delay 2806
[  3202][E][KiniMain.cpp:102] setup(): [kinimain] delay 2906
[  3302][E][KiniMain.cpp:102] setup(): [kinimain] delay 3006
[  3402][E][KiniMain.cpp:102] setup(): [kinimain] delay 3106
[  3502][E][KiniMain.cpp:102] setup(): [kinimain] delay 3206
[  3602][E][KiniMain.cpp:102] setup(): [kinimain] delay 3306
[  3702][E][KiniMain.cpp:102] setup(): [kinimain] delay 3406

If I reset the device while it is plugged in and outputting to serial:

Disconnected (read failed: [Errno 6] Device not configured)
Reconnecting to /dev/cu.usbmodem831401 .         Connected!
[  1602][E][KiniMain.cpp:102] setup(): [kinimain] delay 1305
[  1702][E][KiniMain.cpp:102] setup(): [kinimain] delay 1406
[  1802][E][KiniMain.cpp:102] setup(): [kinimain] delay 1506
[  1902][E][KiniMain.cpp:102] setup(): [kinimain] delay 1606
[  2002][E][KiniMain.cpp:102] setup(): [kinimain] delay 1706
[  2102][E][KiniMain.cpp:102] setup(): [kinimain] delay 1806
[  2202][E][KiniMain.cpp:102] setup(): [kinimain] delay 1906
[  2302][E][KiniMain.cpp:102] setup(): [kinimain] delay 2006
[  2402][E][KiniMain.cpp:102] setup(): [kinimain] delay 2106
[  2502][E][KiniMain.cpp:102] setup(): [kinimain] delay 2206
[  2602][E][KiniMain.cpp:102] setup(): [kinimain] delay 2306
[  2702][E][KiniMain.cpp:102] setup(): [kinimain] delay 2406
[  2802][E][KiniMain.cpp:102] setup(): [kinimain] delay 2506
...

For some reason, it takes 2 seconds or more to start receiving serial output, when the device is first powered on, and 1 second if the device is restarted, severing the serial connection and reconnecting to it.

Why I think this is something that could be done better, is this command line hack:

while true; 
do     
cu -l /dev/cu.usbmodem831401 -s 115200
done

When I turn the power on to the attached device:

cu: /dev/cu.usbmodem831401: Line in use
Connected.
[   599][E][KiniMain.cpp:102] setup(): [kinimain] delay 299
[   699][E][KiniMain.cpp:102] setup(): [kinimain] delay 399
[   799][E][KiniMain.cpp:102] setup(): [kinimain] delay 499
[   899][E][KiniMain.cpp:102] setup(): [kinimain] delay 599
[   999][E][KiniMain.cpp:102] setup(): [kinimain] delay 699
[  1099][E][KiniMain.cpp:102] setup(): [kinimain] delay 799
[  1199][E][KiniMain.cpp:102] setup(): [kinimain] delay 899
[  1299][E][KiniMain.cpp:102] setup(): [kinimain] delay 999
[  1399][E][KiniMain.cpp:102] setup(): [kinimain] delay 1099
...

How can I get that better performance of about ~300ms?

What gets output during the first second is important, and right now I have to put in a delay of about 2.5seconds to ensure that I don’t miss anything. And sadly I miss anything output prior to my app getting started by the OS (If I do a esp_restart() or a crash, I get to see the initial output since there seems to be no serial port detach/reattach).

BTW, I am using a custom ESP32 board with JTAG.

2

Pinging to see if anyone can help.

3

What’s really weird is that it seems to be getting worse! Over the past few days it has taken 4 seconds or more to see the log messages start coming in.

I’m going to try and restart my computer and run nothing else to see if I can eliminate some of the delay. It’s odd though since every now and then, I see it manage to relay the logs in less than 500ms.