what might cause functions to periodically run more slowly?

[skybrian]

Hi, I've been timing some functions to see how long they take (mostly just to understand how things work) and noticed some puzzling behavior. At regular intervals, about 130ms apart, the functions slow down by 25 microseconds or so. Here is a screenshot:

This is in a program that uses the ADC to read two pins at 1ms intervals. I noticed that if I vary the sample rate a little then the slowdowns still happen but are less periodic. It also seems odd that the slowdown doesn't happen on the same sample for each function (even thought they are all called together in the read function) and sometimes the slowdown happens in two consecutive ticks.

Do you have any ideas about what might cause this? Are there interrupt handlers enabled by default?

I'm using a Raspberry Pi Pico and PlatformIO. Here is the code:

#include <Arduino.h>
#include <Adafruit_TinyUSB.h>
#include <elapsedMillis.h>

const int lightPin = 22;
const int leftSensorPin = A0;
const int rightSensorPin = A1;

// times in microseconds
const int warmupTime = 100 * 1000;
const int samplePeriod = 1000;
const int sampleCount = 1000;

void setup() {
  pinMode(lightPin, OUTPUT);
  digitalWrite(lightPin, HIGH);
}

elapsedMicros sinceStart;
int nextReadTime;

struct Reading {
  int leftV;
  int rightV;

  int jitter;
  int leftReadTime;
  int rightReadTime;
  int yieldTime;
};

void printHeader() {
  Serial.println("Left V,Right V,Jitter,Left Read Time,Right Read Time,Yield Time");
}

void printLine(Reading r) {
  Serial.print(r.leftV); Serial.print(", ");
  Serial.print(r.rightV); Serial.print(", ");

  Serial.print(r.jitter); Serial.print(", ");
  Serial.print(r.leftReadTime); Serial.print(", ");
  Serial.print(r.rightReadTime); Serial.print(",");
  Serial.println(r.yieldTime);
  Serial.flush();
}

Reading read() {
  Reading out;

  int start = sinceStart;
  out.leftV = analogRead(leftSensorPin);
  int leftDone = sinceStart;
  out.leftReadTime = leftDone - start;

  out.rightV = analogRead(rightSensorPin);
  int rightDone = sinceStart;
  out.rightReadTime = rightDone - leftDone;

  yield();
  out.yieldTime = sinceStart - rightDone;

  return out;
}

Reading samples[sampleCount];
int nextSample = 0;

void writeCSV() {
  printHeader();
  for (int i = 0; i < sampleCount; i++) {
    printLine(samples[i]);
  }
}

enum State { disconnected, reading, done };
State state = disconnected;

void loop() {
  switch (state) {
    case disconnected:
      if (Serial.dtr()) {
        state = reading;
        sinceStart = -warmupTime;
        nextSample = 0;
        nextReadTime = 0;
      }
      break;
    case reading:
      do {
        int now = sinceStart;
        int jitter = now - nextReadTime;
        if (jitter > 0) {
          samples[nextSample] = read();
          samples[nextSample].jitter = jitter;
          nextSample++;
          nextReadTime += samplePeriod;
          if (nextSample >= sampleCount) {
            state = done;
            writeCSV();
          }
        }
      } while (state == reading);
      break;
    case done:
      if (!Serial.dtr()) {
        state = disconnected;
      }
      break;
  }
}

[earlephilhower]

Could be USB code responding to scans from the PC. You could disable all USB (there's a define for it) and use a UART serial port. Or, you could try running your code on the 2nd core (loop->loop1). The USB is handler only runs on core0.

[skybrian]

Thanks! Do you know where the built-in interrupts are defined? I'd like to learn more about them.

[earlephilhower]

Datasheet is here: https://datasheets.raspberrypi.com/rp2040/rp2040-datasheet.pdf
SDK docs: https://datasheets.raspberrypi.com/pico/raspberry-pi-pico-c-sdk.pdf

In your example I think the only IRQ base process is the USB port.

You might also have flash read delays (i.e. if you need guaranteed microsecond latency, don't use the flash XIP cache and instead move your code to RAM...see the core for the not_in_flash() macro usage).

[skybrian]

To summarize what I found:

It looks like the place to start reading is the main() function. I can see the TinyUSB initialization, which, after some indirection, calls an RP2040-specific version of TinyUSB_Port_InitDevice.

The periodic task interval is defined by USB_TASK_INTERVAL to be 1000. (Microseconds I presume.) The actual interrupt handler is usb_irq. It looks like, in theory, grabbing __usb_mutex would put off the USB handler for a bit, but I don't see a way to get at it.

Meanwhile, in the main loop there is a call to __loop which calls yield(), which calls TinyUSB_Device_Task() and TinyUSB_Device_FlushCDC(). I guess this is the high-level code since it reads events from a tu_fifo_mutex_t object.

It seems I had the bad luck to pick a sample period that almost exactly matches theirs. If I write my code to be less careful about trying to run at exactly 1 millisecond intervals, it would probably get pushed out of phase with it and conflict less often.

[skybrian]

I found that running on the second core and locking out the other processor using rp2040.idleOtherCore() and rp2040.resumeOtherCore() does the trick. I lock it out 60 microseconds before it's time to read.