Arduino's micros() method is taking over 500 cycles to execute on Nano 33 BLE Sense

Question

I posted this question over on the Arduino forum first but my questions haven't been receiving much attention lately so here goes...

I worked pretty hard to make a simple sketch proving how slow the micros() method is on the Nano 33 BLE Sense:

#include "mbed.h"
#include "nrf_delay.h"
#include "nrf_gpio.h"

#define OUTPUT_PIN NRF_GPIO_PIN_MAP(1,11)

unsigned long startClock;
unsigned long stopClock;
unsigned long arithmeticMinuend = 4294967295;
unsigned long arithmeticSubtrahend = 2147483648;
unsigned long arithmeticDifference = 0;
unsigned long timeDifference1 = 0;
unsigned long timeDifference2 = 0;

//Assume 1 to 4 clock cycles (15.625 to 62.5 ns) is required for every...
//* call of micros();
//* subtraction of two unsigned longs.
//Therefore we should not be able to measure the time to execute either task by using the micros() - startClock technique, as...
//* micros() - startClock = 0 in either case.

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

  nrf_gpio_cfg_output(OUTPUT_PIN);

  startClock = micros();
  stopClock = micros();
}

void loop() {
  timeDifference1 = microsecondsToSubtract2LongsOnce();
  timeDifference2 = microsecondsToSubtract2LongsTwice();
  Serial.print("timeDifference1 = ");
  Serial.print(timeDifference1);
  Serial.print(" us.\ntimeDifference2 = ");
  Serial.print(timeDifference2);
  Serial.println(" us.");
  
  microsecondsToSubtract2LongsOnceMeasuredWithScope();
  delay(100);
  microsecondsToSubtract2LongsTwiceMeasuredWithScope();
  delay(100);
  microsecondsToToggleOutputPinMeasuredWithScope();
  
  while(1) {
    
  }
}

//Prints 8 us:
unsigned long microsecondsToSubtract2LongsOnce() {
  startClock = micros();
  stopClock = micros();
  return stopClock - startClock;
}

//Prints 9 us:
unsigned long microsecondsToSubtract2LongsTwice() {
  startClock = micros();
  arithmeticDifference = arithmeticMinuend - arithmeticSubtrahend;
  stopClock = micros();
  return stopClock - startClock;
}

//Measured 18 us on scope:
void microsecondsToSubtract2LongsOnceMeasuredWithScope() {
  nrf_gpio_pin_toggle(OUTPUT_PIN);
  startClock = micros();
  stopClock = micros();
  nrf_gpio_pin_toggle(OUTPUT_PIN);
}

//Measured 18 us on scope:
void microsecondsToSubtract2LongsTwiceMeasuredWithScope() {
  nrf_gpio_pin_toggle(OUTPUT_PIN);
  startClock = micros();
  arithmeticDifference = arithmeticMinuend - arithmeticSubtrahend;
  stopClock = micros();
  nrf_gpio_pin_toggle(OUTPUT_PIN);
}

//Measured 500 ns on scope:
void microsecondsToToggleOutputPinMeasuredWithScope() {
  nrf_gpio_pin_toggle(OUTPUT_PIN);
  nrf_gpio_pin_toggle(OUTPUT_PIN);
}

I compare time measurements I made with oscilloscope to the ones I made using micros(). Doing the math we get that the # of clock cycles (CC) required for one micros() call = (0.5*(18000 - 500) ns)/15.625 ns = 560 CC!!!

Can someone give an example for measuring time on this board which doesn't require more than 10 CC???

From my reading, I think a faster (theoretically 1 CC) strategy would involve using the method nrf_drv_timer or the newer nrfx_timer (both strategies would require setting the timer to operate in counter mode), but I couldn't find a concrete example for use on my Arduino's NRF52840.

---

EDIT:

I also tried reducing time by using mbed's us_ticker but the timing results were exactly the same. Here is the code I used for that test:

#include "mbed.h"
#include "nrf_delay.h"
#include "nrf_gpio.h"

#define OUTPUT_PIN NRF_GPIO_PIN_MAP(1,11)

mbed::Timer timer;

uint32_t startClock;
uint32_t stopClock;
uint32_t arithmeticMinuend = 4294967295;
uint32_t arithmeticSubtrahend = 2147483648;
uint32_t arithmeticDifference = 0;
uint32_t timeDifference1 = 0;
uint32_t timeDifference2 = 0;

//Assume 1 to 4 clock cycles (15.625 to 62.5 ns) is required for every...
//* call of micros();
//* subtraction of two unsigned longs.
//Therefore we should not be able to measure the time to execute either task by using the micros() - startClock technique, as...
//* micros() - startClock = 0 in either case.

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

  nrf_gpio_cfg_output(OUTPUT_PIN);
  timer.start();
  startClock = timer.read_us();
  stopClock = timer.read_us();
}

void loop() {
  timeDifference1 = microsecondsToSubtract2LongsOnce();
  timeDifference2 = microsecondsToSubtract2LongsTwice();
  Serial.print("timeDifference1 = ");
  Serial.print(timeDifference1);
  Serial.print(" us.\ntimeDifference2 = ");
  Serial.print(timeDifference2);
  Serial.println(" us.");
  
  microsecondsToSubtract2LongsOnceMeasuredWithScope();
  timer.stop();
  delay(100);
  timer.start();
  microsecondsToSubtract2LongsTwiceMeasuredWithScope();
  timer.stop();
  delay(100);
  timer.start();
  microsecondsToToggleOutputPinMeasuredWithScope();
  timer.stop();
  
  while(1) {
    
  }
}

//Prints 8 us:
unsigned long microsecondsToSubtract2LongsOnce() {
  startClock = timer.read_us();
  stopClock = timer.read_us();
  return stopClock - startClock;
}

//Prints 9 us:
unsigned long microsecondsToSubtract2LongsTwice() {
  startClock = timer.read_us();
  arithmeticDifference = arithmeticMinuend - arithmeticSubtrahend;
  stopClock = timer.read_us();
  return stopClock - startClock;
}

//Measured 18 us on scope:
void microsecondsToSubtract2LongsOnceMeasuredWithScope() {
  nrf_gpio_pin_toggle(OUTPUT_PIN);
  startClock = timer.read_us();
  stopClock = timer.read_us();
  nrf_gpio_pin_toggle(OUTPUT_PIN);
}

//Measured 18 us on scope:
void microsecondsToSubtract2LongsTwiceMeasuredWithScope() {
  nrf_gpio_pin_toggle(OUTPUT_PIN);
  startClock = timer.read_us();
  arithmeticDifference = arithmeticMinuend - arithmeticSubtrahend;
  stopClock = timer.read_us();
  nrf_gpio_pin_toggle(OUTPUT_PIN);
}

//Measured 500 ns on scope:
void microsecondsToToggleOutputPinMeasuredWithScope() {
  nrf_gpio_pin_toggle(OUTPUT_PIN);
  nrf_gpio_pin_toggle(OUTPUT_PIN);
}

Answer 1

My "hint", for reference:

For short intervals, you should be able to read cycle counts from either the ARM Core SysTick Timer, or the ARM DWT Cycle Counter (you'd probably have to enable the DWT first.)

    startTime = SysTick->VAL; // 24bit counter, probably resets at ~1ms.  Counts Down!
// or
    start = DWT->CYCCNT;  //CYCCNT wraps at 32bits; never resets, counts up.
// With:
  // Somewhere in system init
  CoreDebug->DEMCR |= CoreDebug_DEMCR_TRCENA_Msk;
  DWT->CTRL |= DWT_CTRL_CYCCNTENA_Msk;

I don't know how those will be affected by (or affect) low power modes and such. (in particular, the DWT may use power, and I don't know whether it turns off in powerdown modes.)

Answer 2

Here is a strategy using mBed's us_ticker_read which is more than an order of magnitude faster than Arduino's micros or mBed's read_us, i.e., 650 ns or 42 CC.

#include "mbed.h"
#include "nrf_delay.h"
#include "nrf_gpio.h"

#define OUTPUT_PIN NRF_GPIO_PIN_MAP(1,11)

uint32_t startClock;
uint32_t stopClock;
uint32_t arithmeticMinuend = 4294967295;
uint32_t arithmeticSubtrahend = 2147483648;
uint32_t arithmeticDifference = 0;
uint32_t timeDifference1 = 0;
uint32_t timeDifference2 = 0;

//Assume 1 to 4 clock cycles (15.625 to 62.5 ns) is required for every...
//* call of micros();
//* subtraction of two unsigned longs.
//Therefore we should not be able to measure the time to execute either task by using the micros() - startClock technique, as...
//* micros() - startClock = 0 in either case.

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

  nrf_gpio_cfg_output(OUTPUT_PIN);
  us_ticker_init();
  startClock = us_ticker_read();
  stopClock = us_ticker_read();
}

void loop() {
  Serial.println("Starting program:");
  timeDifference1 = microsecondsToSubtract2LongsOnce();
  timeDifference2 = microsecondsToSubtract2LongsTwice();
  us_ticker_free();
  Serial.print("timeDifference1 = ");
  Serial.print(timeDifference1);
  Serial.print(" us.\ntimeDifference2 = ");
  Serial.print(timeDifference2);
  Serial.println(" us.");

  us_ticker_init();
  microsecondsToSubtract2LongsOnceMeasuredWithScope();
  us_ticker_free();
  delay(10);
  us_ticker_init();
  microsecondsToSubtract2LongsTwiceMeasuredWithScope();
  us_ticker_free();
  delay(10);
  us_ticker_init();
  microsecondsToToggleOutputPinMeasuredWithScope();
  us_ticker_free();
  
  while(1) {
    
  }
}

//Prints 1 us:
uint32_t microsecondsToSubtract2LongsOnce() {
  startClock = us_ticker_read();
  stopClock = us_ticker_read();
  return stopClock - startClock;
}

//Prints 1 us:
uint32_t microsecondsToSubtract2LongsTwice() {
  startClock = us_ticker_read();
  arithmeticDifference = arithmeticMinuend - arithmeticSubtrahend;
  stopClock = us_ticker_read();
  return stopClock - startClock;
}

//Measured 1.8 us on scope:
void microsecondsToSubtract2LongsOnceMeasuredWithScope() {
  nrf_gpio_pin_toggle(OUTPUT_PIN);
  startClock = us_ticker_read();
  stopClock = us_ticker_read();
  nrf_gpio_pin_toggle(OUTPUT_PIN);
}

//Measured 2 us on scope:
void microsecondsToSubtract2LongsTwiceMeasuredWithScope() {
  nrf_gpio_pin_toggle(OUTPUT_PIN);
  startClock = us_ticker_read();
  arithmeticDifference = arithmeticMinuend - arithmeticSubtrahend;
  stopClock = us_ticker_read();
  nrf_gpio_pin_toggle(OUTPUT_PIN);
}

//Measured 500 ns on scope:
void microsecondsToToggleOutputPinMeasuredWithScope() {
  nrf_gpio_pin_toggle(OUTPUT_PIN);
  nrf_gpio_pin_toggle(OUTPUT_PIN);
}

If anyone can post an example with a quicker time in the next few days, I will accept their answer!

---

EDIT(11/12/2021):

I should give credit to westfw at the Arduino Forums for leading me in the right direction. His suggested strategy is so accurate and takes just 1 or 2 CC to execute:

#include "mbed.h"
#include "nrf.h"
#include "nrf_delay.h"
#include "nrf_gpio.h"

#define OUTPUT_PIN NRF_GPIO_PIN_MAP(1,11)

const float MICROS_PER_CYCLE = 0.015625; //Nano 33 BLE Sense operates at 64 MHz -> 15.625 ns/cc.
const byte BYTE_TO_SEND = 170; //b'10101010'.
const int BYTES_PER_TRANSFER = 54;

byte buffer[BYTES_PER_TRANSFER];

volatile uint32_t stopWatchTime1;
volatile uint32_t stopWatchTime2;
volatile uint32_t stopWatchTime3;

void setup(){
  Serial.begin(1000000); //Does nothing on the Nano 33 BLE Sense.
  while (!Serial); //Wait for serial port to connect. Needed for native USB CDC on Nano 33 BLE Sense.

  stopWatchInit();
  
  nrf_gpio_cfg_output(OUTPUT_PIN); //Configure pin as digital output for measuring time of events on scope.
  
  memset(buffer, BYTE_TO_SEND, sizeof(buffer));

  //Measured 300 ns on scope and printed 190 ns.
  togglePinTwice();
  delay(10);

  //Measured 840 ns on scope and printed 730 ns:
  togglePinTwiceAndCallMicrosTwice();
  delay(10);

  //Measured ~68 us on scope and printed 67.69 us:
  togglePinTwiceCallMicrosTwiceAndWriteBytes(); //This result makes sense bc 88 - 9.2 = 78.8 us (which is basically 78 us).
  delay(10);

  //Measured ~68 us on scope:
  togglePinTwiceAndWriteBytes();

  Serial.println("");
  Serial.print(MICROS_PER_CYCLE*((float)stopWatchTime1));
  Serial.println(" us");
  Serial.println("");
  Serial.print(MICROS_PER_CYCLE*((float)stopWatchTime2));
  Serial.println(" us");
  Serial.println("");
  Serial.print(MICROS_PER_CYCLE*((float)stopWatchTime3));
  Serial.println(" us");
}
  
void loop(){}

void togglePinTwice(){
  stopWatchStart();
  nrf_gpio_pin_toggle(OUTPUT_PIN);
  nrf_gpio_pin_toggle(OUTPUT_PIN);
  stopWatchTime1 = stopWatchGet();
}

void togglePinTwiceAndCallMicrosTwice() {
  nrf_gpio_pin_toggle(OUTPUT_PIN);
  stopWatchStart();
  stopWatchTime2 = stopWatchGet();
  nrf_gpio_pin_toggle(OUTPUT_PIN);
}

void togglePinTwiceCallMicrosTwiceAndWriteBytes() {
  nrf_gpio_pin_toggle(OUTPUT_PIN);
  stopWatchStart();
  Serial.write(buffer, sizeof(buffer));
  Serial.flush(); //Patch current Serial.h to use or it will block forever.
  stopWatchTime3 = stopWatchGet();
  nrf_gpio_pin_toggle(OUTPUT_PIN);
}

void togglePinTwiceAndWriteBytes() {
  nrf_gpio_pin_toggle(OUTPUT_PIN);
  Serial.write(buffer, sizeof(buffer));
  Serial.flush();
  nrf_gpio_pin_toggle(OUTPUT_PIN);
}

void stopWatchInit() {
  CoreDebug->DEMCR |= 0x01000000; //Enable the use of DWT.
}

void stopWatchStart() {
  DWT->CYCCNT = 0; //Reset cycle counter.
  DWT->CTRL |= 0x1; //Enable cycle counter.
}

uint32_t stopWatchGet() {
  return DWT->CYCCNT; //Number of clock cycles stored in count variable.
}