ESP32 cycletime regularly > 10ms

[geschild]

A simple code to measure the cycletime of an ESP32 Wroom 32.

unsigned long startTime;

void setup() {
Serial.begin(115200);

}

void loop() {
startTime=micros();

Serial.print("Zykluszeit: ");
Serial.println(micros() - startTime);
}

If you on the result on a terminal you will see, that the cycletime is regularly > 10ms. Why? How to avoid?

(Bad english, sorry I'm german)

[ESP_Sprite]

I have no idea what you mean by 'cycle time', but you're effectively measuring how long the first Serial.print takes. As that call involves UART stuff, the time taken there is highly dependent on e.g. what's in the UART buffer.

[geschild]

With 'cycletime' I mean the time the program need to run one time and than starts again.
This is what the terminal shows:

First the ESP information after <reset>
Then most cycles take 18-19 microseconds, but every 6..7 cycles more then 10.000 microseconds.

rst:0x1 (POWERON_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:1
load:0x3fff0030,len:1344
load:0x40078000,len:13964
load:0x40080400,len:3600
entry 0x400805f0
Zykluszeit: 58
Zykluszeit: 18
Zykluszeit: 18
Zykluszeit: 18
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 10243
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 18
Zykluszeit: 18
Zykluszeit: 18
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 21
Zykluszeit: 18
Zykluszeit: 18
Zykluszeit: 19
Zykluszeit: 10233
Zykluszeit: 18
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 18
Zykluszeit: 10208
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 18
Zykluszeit: 10265
Zykluszeit: 18
Zykluszeit: 19
Zykluszeit: 23
Zykluszeit: 19
Zykluszeit: 26
Zykluszeit: 19
Zykluszeit: 18
Zykluszeit: 10193
Zykluszeit: 19
Zykluszeit: 18
Zykluszeit: 18
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 10267
Zykluszeit: 18
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 19
Zykluszeit: 18
Zykluszeit: 10206
Zykluszeit: 19
Zykluszeit: 18
Zykluszeit: 19

[ESP_Sprite]

My point stands then. You're starting measurement before the serial.print and end it after that, so you're measuring the performance of that statement. That is slightly related with your definition of 'cycle time' because the serial.print forms the bulk of what happens in the cycle (but not all of it as the serial.println is also part of the cycle but is not measured), but it is not the cycle time as you're not measuring it from cycle start to cycle start. Regardless, your 10ms are likely caused by the UARTs buffers filling up and the serial.print needing to wait until the buffer contents are sent.

[geschild]

unsigned long startTime, endTime;
void setup()
{
Serial.begin(115200);
}
void loop()
{
startTime=micros();
endTime = micros() - startTime;
Serial.print("Zykluszeit: ");
Serial.println(endTime);
}

You are right, I changed the code and now:

Zykluszeit: 1
Zykluszeit: 1
Zykluszeit: 1
Zykluszeit: 1
Zykluszeit: 1
Zykluszeit: 1
Zykluszeit: 1
Zykluszeit: 1
Zykluszeit: 0
Zykluszeit: 0
Zykluszeit: 0
Zykluszeit: 0
Zykluszeit: 1

THX

From Bottrop in Germany