[SOLVED] Why do multiple identical function calls have significant differences in execution time on Arduino?

I have written a memberfunction of my class Adf, bool Adf::sendAndReceive(char *data, uint8_t length) on Arduino that sends a char array over the Serial port pointed to by Adf::pSerial, and then reads the rx buffer. The rx and tx lines are connected, so each sent byte is echoed back into the rx buffer. Further, I use the ArduinoLog library to trace the whole traffic. Now I ran into a case where something really strange happened: I called sendAndReceive twice in a row with the same arguments, and during the first call, Logging the outgoing message took less than 1ms, but in the second call it took 29 milliseconds.

How can it be that the same function call with the same arguments takes differnt times?

These are the called functions:

bool Adf::sendAndReceive(char *data, uint8_t length)
{
  uint8_t rxTxLength = 0;

  // send data
  unsigned long start = millis();
  rxTxLength = pSerial->write(data, length);
  unsigned long end = millis();
  Logger.trace("TX start: %lu, end: %lu, duration: %lu\n", start, end, end - start);

  // STRANGE BEHAVIOUR HAPPENS HERE ===================
  unsigned long start2 = millis();
  // Trace the sent bytes
  Logger.trace("%s - data: ", __func__);
  traceCharArray(data, rxTxLength);
  unsigned long end2 = millis();
  Logger.trace("Trace start: %lu, end: %lu, duration: %lu\n", start2, end2, end2 - start2);
  // ==================================================

  // handle write error
  unsigned long start3 = millis();
  if (rxTxLength != length)
  {
    Logger.errorln("%s - Error writing to serial. Only %d of %d bytes written.",
                    __func__,
                    rxTxLength,
                    length);
    return false; // Failure: error writing to serial
  }
  unsigned long end3 = millis();
  Logger.trace("Error start: %lu, end: %lu, duration: %lu\n", start3, end3, end3 - start3);

  // Read all echoed bytes
  unsigned long start4 = millis();
  char echo[length];
  getAdfResponse(echo, length);
  unsigned long end4 = millis();
  Logger.trace("Echo start: %lu, end: %lu, duration: %lu\n", start4, end4, end4 - start4);

  // Compare sent and echoed bytes
  unsigned long start5 = millis();
  if (memcmp(data, echo, length) != 0)
  {
    Logger.errorln("%s - Serial was not echoed correctly", __func__);
    return false; // Failure: echoed bytes do not match sent bytes  
  }
  unsigned long end5 = millis();
  Logger.trace("Compare start: %lu, end: %lu, duration: %lu\n", start5, end5, end5 - start5);
  return true; // Success: all bytes echoed correctly
}

void Adf::traceCharArray(char *data, uint8_t length)
{
  for (int i = 0; i < length; i++)
  {
    Logger.trace("%x, ", static_cast<unsigned char>(data[i])); 
    /* static cast to ensure that the data is correctly interpreted as an 
    ** unsigned value when logging in hexadecimal format */
  }
  Logger.traceln("");
}

The problem occurs in the "Trace" section, where the function Adf::traceCharArray is called.

This is the main file

#include <Arduino.h>
#include <ADF.h>

#define ADDRESS_WIRE 33
#define BAUD_RATE    2400

Adf adf(ADDRESS_WIRE, &Wire1, BAUD_RATE, &Serial3);
char msg = 0x81;

void setup()
{
  // initialize Serial
  Serial.begin(9600);
  Serial.println("Hello ADF");

  adf.Logger.begin(LOG_LEVEL_TRACE, &Serial, false);

  // initialize ADF
  if (!adf.begin())
  {
    Serial.println("Init failed.");
  }

  if (!adf.sendAndReceive(&msg, 1))
  {
    Serial.println("sendAndReceive failed.");
  }
  Serial.println("====================================");
  if (!adf.sendAndReceive(&msg, 1))
  {
    Serial.println("sendAndReceive failed.");
  }


  // signal setup OK
  Serial.println("Setup done.");
}

void loop()
{

}

And this is the output printed by the Logger (along with my notes):

---- Opened the serial port COM3 ----
13:29:10:875 -> Hello ADF
13:29:16:384 -> TX start: 5513u, end: 5513u, duration: 0u
13:29:16:429 -> sendAndReceive - data: 81, 
13:29:16:458 -> Trace start: 5513u, end: 5513u, duration: 0u <--- compare this
13:29:16:503 -> Error start: 5513u, end: 5513u, duration: 0u
13:29:16:552 -> getAdfResponse - resp: 81, 
13:29:16:581 -> Echo start: 5545u, end: 5574u, duration: 29u
13:29:16:626 -> Compare start: 5621u, end: 5621u, duration: 0u
13:29:16:677 -> ====================================
13:29:16:716 -> TX start: 5709u, end: 5709u, duration: 0u
13:29:16:761 -> sendAndReceive - data: 81, 
13:29:16:790 -> Trace start: 5753u, end: 5782u, duration: 29u <--- to this
13:29:16:835 -> Error start: 5830u, end: 5830u, duration: 0u
13:29:16:884 -> getAdfResponse - resp: 81, 
13:29:16:913 -> Echo start: 5877u, end: 5906u, duration: 29u
13:29:16:958 -> Compare start: 5953u, end: 5953u, duration: 0u
13:29:17:007 -> Setup done.

Question: Why does the call to Adf::traceCharArray take 0ms the first time, and 29ms the second time, even if the same arguments are passed to it?

Note: After some further research I found out that if Adf::traceCharArray is called directly (not from within another function), this issue doesn't occur:

In the main file

  unsigned long start = millis();
  adf.traceCharArray(&msg, 1);
  unsigned long end = millis();
  Serial.print("duration: ");
  Serial.println(end - start);
  Serial.println("====================================");
  unsigned long start2 = millis();
  adf.traceCharArray(&msg, 1);
  unsigned long end2 = millis();
  Serial.print("duration: ");
  Serial.println(end2 - start2);

And the output

---- Opened the serial port COM3 ----
13:46:12:418 -> Hello ADF
13:46:17:927 -> 81, 
13:46:17:935 -> duration: 0
13:46:17:958 -> ====================================
13:46:17:988 -> 81, 
13:46:17:992 -> duration: 0
13:46:18:004 -> Setup done.

Edit: I found out that the problem remains the same, even if the call to traceCharArray(data, rxTxLength); is commented out. So it is the execution of the line Logger.trace("%s - data: ", __func__); varies between 0 and 29ms.