Interrupt Latency Measurement

Post your cool example code here.
User avatar
Pito
Posts: 1628
Joined: Sat Mar 26, 2016 3:26 pm
Location: Rapa Nui

Interrupt Latency Measurement

Post by Pito » Fri Aug 25, 2017 8:37 am

Here is an example with measuring Interrupt Latency.
AttachInterrupt function used.
In the code the PA14 and PA15 are used for INTR_IN and SIG_OUT. You may change that.

Code: Select all

// INTERRUPT LATENCY MEASUREMENT DEMONSTRATOR v1.2
// ATTACHINTERRUPT function used
// TESTED with MAPLE MINI and BLACK F407 (Libmaple F1 F4 and STM32GENERIC F1 F4)
// Wire PA14 with PA15 together
// Pito 8/2017
// Provided As-Is, no warranties of any kind are provided

#include "Arduino.h"

#define DWTEn()         (*((uint32_t*)0xE000EDFC)) |= (1<<24)
#define CpuTicksEn()    (*((uint32_t*)0xE0001000)) = 0x40000001
#define CpuTicksDis()   (*((uint32_t*)0xE0001000)) = 0x40000000
#define CpuGetTicks()   (*((uint32_t*)0xE0001004))

#define INTR_IN PA14   // INTERRUPT INPUT PIN
#define SIG_OUT PA15   // RANDOM JITTER RISING EDGE GENERATOR

volatile uint32_t start, stop;
uint32_t lat_max = 0;
uint32_t lat_min = 99999999;
uint32_t lat_over = 0;
uint32_t lat_digwr = 0;
uint32_t i = 0;
float lat_sum = 0.0;
float lat_aver = 0.0;

void setup() {
  Serial.begin(115200);
  DWTEn();
  CpuTicksEn();
  pinMode(INTR_IN, INPUT);
  pinMode(SIG_OUT, OUTPUT);

  start = CpuGetTicks();   // MEASURE THE DIGWRITE LATENCY
  digitalWrite(SIG_OUT, 0);
  lat_digwr = CpuGetTicks() - start;

  attachInterrupt(INTR_IN, intrfun, RISING);
  randomSeed(2345);
}

void loop() {

  digitalWrite(SIG_OUT, 0);

  // CREATING "RANDOM JITTER" BEFORE WE TRIGGER THE INTERRUPT
  delayMicroseconds(1 + random(2100));

  start = CpuGetTicks();
  digitalWrite(SIG_OUT, 1);  // RISING EDGE TRIGGERS THE INTERRUPT

  delay(2);   // WAITING 2ms to capture and process the INTERRUPT

  uint32_t elapsed = stop - start;

  elapsed = elapsed - lat_digwr;  // SUBTRACT the digitalWrite() LATENCY

  i++;
  lat_sum += (float) elapsed;
  lat_aver = lat_sum / i;

  if (elapsed <= lat_min) lat_min = elapsed;
  if (elapsed >= lat_max) lat_max = elapsed;
  
  if ((float)elapsed > lat_aver) lat_over++;

// 1 CLK in ns -> 5.9524ns for F407 and 13.8888ns for F103 at stock clocks
   Serial.print("INTR Latency MIN=");  
   Serial.print(13.88*lat_min,0);
   Serial.print("ns MAX=");
   Serial.print(13.88*lat_max,0);
   Serial.print("ns AVER=");
   Serial.print(13.88*lat_aver,0);
   Serial.print("ns OVER=");
   Serial.println(lat_over);

   if (i > 4000000000) while(1);
}

// ISR
void intrfun() {
  stop = CpuGetTicks();
}
.
Here is with Libmaple, default opt, SerialUSB, MapleMini:
After a few minutes:

Code: Select all

INTR Latency MIN=1693ns MAX=25997ns AVER=1744ns
INTR Latency MIN=1693ns MAX=25997ns AVER=1744ns
..
After an hour:

Code: Select all

INTR Latency MIN=1693ns MAX=26330ns AVER=1764ns
INTR Latency MIN=1693ns MAX=26330ns AVER=1764ns
..
UPDATE: v1.1 - digitalwrite latency subtracted, waiting 2ms on interrupt processing.
Last edited by Pito on Fri Aug 25, 2017 3:47 pm, edited 6 times in total.
Pukao Hats Cleaning Services Ltd.

User avatar
Pito
Posts: 1628
Joined: Sat Mar 26, 2016 3:26 pm
Location: Rapa Nui

Re: Interrupt Latency Measurement

Post by Pito » Fri Aug 25, 2017 12:45 pm

Here the latencies with MMini, STM32Generic, SerialUSB, after a minute:

Code: Select all

INTR Latency MIN=3262ns MAX=26205ns AVER=3343ns
INTR Latency MIN=3262ns MAX=26205ns AVER=3343ns
..
Last edited by Pito on Fri Aug 25, 2017 3:48 pm, edited 3 times in total.
Pukao Hats Cleaning Services Ltd.

zmemw16
Posts: 1489
Joined: Wed Jul 08, 2015 2:09 pm
Location: St Annes, Lancs,UK

Re: Interrupt Latency Measurement

Post by zmemw16 » Fri Aug 25, 2017 12:59 pm

i;ve no grounds whatsoever for the question, but i'm always suspicious of no variation results when testing.
i suppose it's a variation of too good to be true.
i would have expected a change in the last digit at least.

stephen

peekay123
Posts: 18
Joined: Tue Nov 08, 2016 8:39 pm

Re: Interrupt Latency Measurement

Post by peekay123 » Fri Aug 25, 2017 1:36 pm

The min/max difference is substantial. It would be nice to calculate the standard deviation to get a sense of the distribution. Or count the number of instances where the time is greater than the average.

User avatar
Pito
Posts: 1628
Joined: Sat Mar 26, 2016 3:26 pm
Location: Rapa Nui

Re: Interrupt Latency Measurement

Post by Pito » Fri Aug 25, 2017 1:45 pm

Black F407ZE, Libmaple F4, SerialUSB
After 5minutes:

Code: Select all

INTR Latency MIN=684ns MAX=8205ns AVER=771ns
INTR Latency MIN=684ns MAX=8205ns AVER=771ns
..
Black F407ZE, STM32Generic F4, SerialUSB
After 5minutes:

Code: Select all

INTR Latency MIN=1363ns MAX=13286ns AVER=1383ns
INTR Latency MIN=1363ns MAX=13286ns AVER=1383ns
..
Last edited by Pito on Fri Aug 25, 2017 3:39 pm, edited 1 time in total.
Pukao Hats Cleaning Services Ltd.

User avatar
Pito
Posts: 1628
Joined: Sat Mar 26, 2016 3:26 pm
Location: Rapa Nui

Re: Interrupt Latency Measurement

Post by Pito » Fri Aug 25, 2017 2:21 pm

UPDATE: v1.2 - added number of overshoots (when the actual latency is bigger than the average latency).

Here with MMini, Libmaple F1, SerialUSB, default opt.
After about 7minutes

Code: Select all

INTR Latency MIN=1693ns MAX=29217ns AVER=1743ns OVER=308
INTR Latency MIN=1693ns MAX=29217ns AVER=1743ns OVER=308
..
zmemw16 wrote:
Fri Aug 25, 2017 12:59 pm
i suppose it's a variation of too good to be true.
i would have expected a change in the last digit at least.
There is a lot of measurement per second so you see just a snippet cut off the terminal.
The average latency changes, but slowly - as the number of large latencies is small (a few per second).

Of course you may add a histogram (ie. 30 bins 1us apart) and show a picture :)
Last edited by Pito on Fri Aug 25, 2017 3:49 pm, edited 2 times in total.
Pukao Hats Cleaning Services Ltd.

zmemw16
Posts: 1489
Joined: Wed Jul 08, 2015 2:09 pm
Location: St Annes, Lancs,UK

Re: Interrupt Latency Measurement

Post by zmemw16 » Fri Aug 25, 2017 3:19 pm

my point is that ALL the columns are the same set of numbers.
srp

victor_pv
Posts: 1746
Joined: Mon Apr 27, 2015 12:12 pm

Re: Interrupt Latency Measurement

Post by victor_pv » Fri Aug 25, 2017 6:39 pm

Thanks Pito I think this is a good reference.
If you still have the F4 setup, can you add this attribute to the ISR declaration to see if running it from RAM makes it any faster?

Code: Select all

__attribute__((section (".data")))

User avatar
Pito
Posts: 1628
Joined: Sat Mar 26, 2016 3:26 pm
Location: Rapa Nui

Re: Interrupt Latency Measurement

Post by Pito » Fri Aug 25, 2017 8:06 pm

Black F407ZE, Libmaple F4, SerialUSB, default opt:

Code: Select all

void intrfun()  __attribute__((section (".data")));
..
void  intrfun()  {
  stop = CpuGetTicks();
}

Code: Select all

INTR Latency MIN=649ns MAX=8169ns AVER=736ns OVER=36089
INTR Latency MIN=649ns MAX=8169ns AVER=736ns OVER=36090
INTR Latency MIN=649ns MAX=8169ns AVER=736ns OVER=36091
INTR Latency MIN=649ns MAX=8169ns AVER=736ns OVER=36092
..
When the .data declaration is commented out:

Code: Select all

INTR Latency MIN=655ns MAX=7902ns AVER=744ns OVER=12318
INTR Latency MIN=655ns MAX=7902ns AVER=744ns OVER=12319
Pukao Hats Cleaning Services Ltd.

dannyf
Posts: 167
Joined: Wed May 11, 2016 4:29 pm

Re: Interrupt Latency Measurement

Post by dannyf » Fri Aug 25, 2017 9:04 pm

this is the code piece I typically use to benchmark codes.

Code: Select all

		for (i=0; i<CNT; i++) {
			tick0 = ticks();			//time stamp ticks0
			//benchmark here
			//28 ticks without anything here
			//PORTB;						//29 ticks -> 1tick execution
			_INT0IF = 1;				//fire the eint0 isr - 48 ticks
			//tick1 = ticks() - tick0;	//time elapsed
			tmp_ticks[i]=tick1;			//save the data
			TMR1 = 0;					//reset the timer counter, to minimize timer isr's impact
		}

I'm using external interrupt 0 on a PIC24F here. Manually setting the flag, _INT0IF, fires the ISR. in the isr, I calculate ticks1 - the formula is the same as shown here.

Raw data:
1-> consecutive reads of ticks() takes 28 ticks;
2-> firing eint0 takes 48 ticks, no change over the course of 1000 readings -> expected as there is nothing else going on here.

So the ISR latency here is no more than 20 ticks -> just as expected. I typically budget a little bit more to be safe.

The same approach applies to your STM32, or other chips.

Post Reply