为什么多个相同的函数调用在Arduino上的执行时间有明显差异？

我在 Arduino 上编写了我的类的成员函数Adf，bool Adf::sendAndReceive(char *data, uint8_t length)该函数通过指向的串行端口发送一个字符数组Adf::pSerial，然后读取 rx 缓冲区。rx 和 tx 线路已连接，因此每个发送的字节都会回显到 rx 缓冲区中。此外，我使用ArduinoLog库来跟踪整个流量。现在我遇到了一个非常奇怪的情况：我sendAndReceive使用相同的参数连续两次调用，在第一次调用期间，记录传出消息花费不到 1 毫秒，但在第二次调用中花费了 29 毫秒。

为什么使用相同的参数调用相同的函数会花费不同的时间？

这些是被调用的函数：

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("");
}

Adf::traceCharArray问题发生在调用该函数的“Trace”部分。

这是主文件

#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()
{

}

这是 Logger 打印的输出（以及我的注释​​）：

---- 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.

问题Adf::traceCharArray：为什么即使传递了相同的参数，第一次调用也需要0ms，而第二次调用却需要 29ms？

注意：经过进一步研究，我发现如果Adf::traceCharArray直接调用（而不是从另一个函数中调用），则不会发生此问题：

在主文件中

  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);

输出

---- 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.

编辑：我发现问题仍然存在，即使traceCharArray(data, rxTxLength);注释掉了对的调用。因此，该行的执行时间Logger.trace("%s - data: ", __func__);在 0 到 29ms 之间变化。