interrupts missing at high rate ( 500k Interrupts/sec ) on Teensy 4.0

Status
Not open for further replies.

ossi

Well-known member
I want a high interrupt rate of 500000 Interrupts/sec. There seem to be other interrupts that interfere with my interrupt routine ( I measure sometimes more than 2400 cycles between interrupts where 1200 cycles is the normal case). Which interrupts are running on the Teensy 4.0 and how can I turn them off. I think I don't need any other interrupts.
 
No code provided to see what the issue at hand may be? IDE version? TeensyDuino version? Too much time in the _isr() code? What else is going on that might be triggering other interrupts?

This runs on a same speed T_4.1 and seeing very repeatable 666,666 interrupts per second. By default there are no interfering interrupts at that rate. The millis() count is updated 1000/sec, and depending on USB output that will take come cycles.

Code:
#include "IntervalTimer.h"
[B]void yield(){}[/B]

IntervalTimer MyTimer;
[B]volatile  [/B]uint32_t mtCount = 0;  // no change in this code - but added volatile as it should be
void mt_isr () {
  mtCount++;
}

elapsedMillis lTime;
void setup() {
  while (!Serial) ; // wait
  Serial.println("\n" __FILE__ " " __DATE__ " " __TIME__);
  lTime = 0;
  MyTimer.begin(mt_isr, 3.0/2);
}

uint32_t lCnt=0;
void loop() {
  uint32_t mtCountL = 0;
  lCnt++;
  if (lTime > 1000) {
    lTime -= 1000;
    __disable_irq();
    mtCountL = mtCount;
    mtCount = 0;
    __enable_irq();
    Serial.printf( "mt#=%lu with LoopCount=%lu\n", mtCountL, lCnt );
    lCnt=0;
  }
}

Output showing 666,666 timer _isr()'s per second and loop() running at 11.6 million passes per second::
Code:
T:\tCode\Interrupts\IntTimerSample\IntTimerSample.ino May 31 2020 02:38:26

mt#=667332 with LoopCount=11592659
mt#=666667 with LoopCount=11665877
mt#=666666 with LoopCount=11665869
mt#=666667 with LoopCount=11665868
mt#=666667 with LoopCount=11665878
mt#=666666 with LoopCount=11665869
*Note void yield(){} used to be repeatable, there are pending yield() changes on this machine that otherwise showed 9.7 that would be higher than TD 1.52 would show.
>> doing this in current code won't hurt if not using any serialEvent() processing for USB or Serial# ports.

> Interrupts disabled in loop() just to get provable counts.
> Adding similar count methods added in problem could give ideas as to the nature of the problem.


<edit> Quick change for timer _isr() each 0.75 microsecond:: MyTimer.begin(mt_isr, 0.75);

Gives expected results and still over 5 Million loop()'s per second:
T:\tCode\Interrupts\IntTimerSample\IntTimerSample.ino May 31 2020 02:46:58

mt#=1334664 with LoopCount=5204716
mt#=1333333 with LoopCount=5199409
mt#=1333332 with LoopCount=5443880
mt#=1333332 with LoopCount=5443883

<2nd Edit> Two timers at that rate are too much. But as second duplicated into the above :: MyTimerB.begin(mt_isrB, 2);
Shows a drop in loop() count that explains why it needs to run slower - but that slower one still hitting 500,000 while the first runs at 1.333M per second:
Code:
T:\tCode\Interrupts\IntTimerSample\IntTimerSample.ino May 31 2020 03:19:48

mt#=1334663 with LoopCount=801439	mtB#=500498
mt#=1333335 with LoopCount=800520	mtB#=500001
mt#=1333330 with LoopCount=800480	mtB#=499999
mt#=1333335 with [B]LoopCount=800520	mtB#=500001[/B]
mt#=1333332 with LoopCount=828842	mtB#=500000
mt#=1333330 with LoopCount=816177	mtB#=499999
mt#=1333332 with LoopCount=816173	mtB#=500000
mt#=1333335 with LoopCount=800502	mtB#=500001
mt#=1333330 with LoopCount=800516	mtB#=499999
mt#=1333332 with LoopCount=800484	mtB#=500000
 
Last edited:
This is a program that shows missing interrupts. I connect pin5 and pin7 to my oscilloscope to see the pulses that are generated. The interrupt rate is 500000/second. The interruptroutine measures the time from the last interrupt to the actual interrupt. If this time is too big a pulse is generated on pin7. The time (in cycles) is also stored in cyclesTime. This variable is displayed by the main routine. For every interrupt a pulse is generated on pin5. On the scope I can see the missing pulses. They are very rare. Sometimes seconds happen without missing pulses.

Code:
IntervalTimer myTimer;

void setup() {
  pinMode(5, OUTPUT);
  pinMode(7, OUTPUT);
  
  Serial.begin(115200);  
  while(!Serial) ;
  Serial.println("start teensy40...") ;

  myTimer.begin(InterruptCode, 2);
  Serial.println("end setup...") ;
  }


int cycles,cyclesLast,cyclesTime ;

void InterruptCode(void) {
 
  cycles = ARM_DWT_CYCCNT ;
  int cyclesTime1=cycles-cyclesLast ;
  if(cyclesTime1>2100){       // if time between interrupts is too big
     cyclesTime=cyclesTime1 ; // store for display by main loop
     CORE_PIN7_PORTSET = CORE_PIN7_BITMASK; // signalize on pin
     }
  cyclesLast=cycles ;
  CORE_PIN5_PORTSET = CORE_PIN5_BITMASK; // each interrupt signalize
  
  CORE_PIN5_PORTCLEAR = CORE_PIN5_BITMASK;
  CORE_PIN7_PORTCLEAR = CORE_PIN7_BITMASK;
  }

int count=0 ;
int count2=0 ;

void loop(){
  while(1){
    count++ ;
    if(count==10000){
      count=0 ;
      count2++ ;
      Serial.printf("count2=%d cyclesTime=%d\n",count2,cyclesTime) ;
      }
  } }
 
Variables which are used both inside and outside the interrupt routine must be declared volatile.
Code:
int cycles;
volatile int cyclesLast,cyclesTime ;

Pete
 
Variables which are used both inside and outside the interrupt routine must be declared volatile.
Code:
int cycles;
volatile int cyclesLast,cyclesTime ;

Pete

Indeed - counting code above p#2 was giving the right results but the vars at hand should have been volatile ... left a note to myself to fix that. Just did and the counts are still holding.

Also before posting started to add ARM_DWT_CYCCNT tracking code - but the counts were showing that all expected timer hits were arriving each second { both 1,333,332 and 500,000 } so there are no interrupts missing at high rate ( 500k Interrupts/sec ) on Teensy 4.0

There may be some jitter - but none are 'missed'
 
SCR01.PNG
See the picture of my oscilloscope. The upper blue trace is pin 7 and has a pulse if a gap is detected. The lower green trace is pin 5 and has a pulse for every interrupt. I would say that one green pulse is missing.
 
SCR02.PNG
Here pin 5 is toggled with maximal rate in the main routine. Always when interrupts happen the toggling stops. One sees the short gaps due to my interrupt routine. But there is also a lon gap that probably belongs to another interrupt routine.
 
No new code shown. And no output from sketch provided.

This inner loop() code will bypass the yield() overhead noted above. That inner while() will cycles about 10 to 20+M times per second - so this will be printing out Serial USB 1000 to 2000 times per second? Is that what is observed?
Code:
  while(1){
    count++ ;
    if(count==10000){
      count=0 ;
      count2++ ;
      Serial.printf("count2=%d cyclesTime=%d\n",count2,cyclesTime) ;
      }
  }

With that .printf() output rate on USB it wouldn't be unheard of for USB to take some time on occasion to keep thing straight. T_4.0 USB can print at 500K+ lines per second - but sent in small 30 Byte chunks they will AFAIK accumulate into a 512B buffer for transmit. That would be about every 17 printf()'s and about 120 of those buffers per second? There is timing on sending out partial buffers - perhaps this is hitting some trigger point in the USB code for that rate of printing.

No scope here and my LA is a $15 unit I've not seen the need to connect beyond looking at it after the big buy. Reading that scope output it isn't clear here how long the 'gap' is, and no code shown to see what changed between scope images p#6 and #7.

If the code were presented one could quickly see and change that to only print when the trigger even happens - and in slowing down the debug spew the problem might not ever happen. Other than USB and the regular millisecond systick interrupt the Teensy generally only does what the sketch tells it to do.

Also digitalWriteFast( (const) pin# , 0|1 ); executes the same code as the BITMASK method as PJRC has it coded.
 
For another thread I revisted the post #2 code.

Separate Issue but it was for the 500KHZ interrupt thread - the T_3.6 is WAY FASTER than the T_4.0.

The T_3.6 can do two of these and have loop() cycles counts to spare!:
Code:
T:\tCode\Interrupts\IntTimerSample\IntTimerSample.ino Jun  2 2020 11:11:52
mt#=1334453 with LoopCount=1866817	mtB#=1334558
[B]mt#=1333134 with LoopCount=1864782	mtB#=1333232[/B]
Timer _isr()'s:
Code:
  MyTimer.begin(mt_isr, 0.75);
  MyTimerB.begin(mt_isrB, 0.75);
T_4 (and T_4.1) is running this today - but less overhead for loop()'s - it looked like it failed the other day but can run:
Code:
T:\tCode\Interrupts\IntTimerSample\IntTimerSample.ino Jun  2 2020 11:20:21
mt#=1143975 with LoopCount=349182	mtB#=1144058
[B]mt#=1142836 with LoopCount=348687	mtB#=1142915[/B]


T_4.0 runs like this with one slower timer:
Code:
  MyTimer.begin(mt_isr, 0.75);
  MyTimerB.begin(mt_isrB, 2);
with slower loop() cycle count:
Code:
T:\tCode\Interrupts\IntTimerSample\IntTimerSample.ino Jun  2 2020 11:07:36
mt#=1334663 with LoopCount=1000782	mtB#=500498
[B]mt#=1333335 with LoopCount=999635	mtB#=500001[/B]

With those same two times the T_3.6 gives:
Code:
T:\tCode\Interrupts\IntTimerSample\IntTimerSample.ino Jun  2 2020 11:15:09
mt#=1334623 with LoopCount=2291905	mtB#=500496
[B]mt#=1333308 with LoopCount=2289473	mtB#=500000[/B]

Here is the base code:
Code:
#include "IntervalTimer.h"
void yield(){}

IntervalTimer MyTimer;
volatile uint32_t mtCount = 0;
void mt_isr () {
  mtCount++;
}

IntervalTimer MyTimerB;
volatile uint32_t mtCountB = 0;
void mt_isrB () {
  mtCountB++;
}

elapsedMillis lTime;
void setup() {
  while (!Serial) ; // wait
  Serial.println("\n" __FILE__ " " __DATE__ " " __TIME__);
  lTime = 0;
  MyTimer.begin(mt_isr, 0.75);
  MyTimerB.begin(mt_isrB, 2);
}

uint32_t lCnt=0;
void loop() {
  uint32_t mtCountL = 0;
  uint32_t mtCountLB = 0;
  lCnt++;
  if (lTime > 1000) {
    lTime -= 1000;
    noInterrupts();
    mtCountL = mtCount;
    mtCount = 0;
    mtCountLB = mtCountB;
    mtCountB = 0;
    interrupts();
    Serial.printf( "mt#=%lu with LoopCount=%lu\t", mtCountL, lCnt );
    Serial.printf( "mtB#=%lu\n", mtCountLB );
    lCnt=0;
  }
}


FOR REFERENCE when the two timers are SLOWED DOWN the FASTER 1062 shines!
Code:
T:\tCode\Interrupts\IntTimerSample\IntTimerSample.ino Jun  2 2020 11:28:31
mt#=100 with LoopCount=[B]16679986	[/B]mtB#=100
mt#=100 with LoopCount=16663308	mtB#=100
mt#=100 with LoopCount=16663307	mtB#=100

The T_3.6 maximum loop()'s is expected much slower:
Code:
T:\tCode\Interrupts\IntTimerSample\IntTimerSample.ino Jun  2 2020 11:29:08
mt#=100 with LoopCount=[B]3750996	[/B]mtB#=100
mt#=100 with LoopCount=3747134	mtB#=100

But doing the faster IntervalTimer's above kills the 1062:
Code:
  MyTimer.begin(mt_isr, 10000.75);
  MyTimerB.begin(mt_isrB, 10000.75);

** This has come up before - but this example brought it up again.
 
These gaps are due to other interrupts running.
1) the systick,
2) usb disables the global interrupt flag.

And, if your core-codebase is not the newest - yield and the EventResponder are problematic, too. This was fixed lately.
You can download the newest core-version from github. This solves the EventResponder issue .

There was a thread re:usb ... I have no link now, but I'm sure Tim can find it. Or search yourself.
 
Tim, yes, the intervaltimer issue is known since the early 4.0 betas. There is no known way to fix it.
 
Tim, yes, the intervaltimer issue is known since the early 4.0 betas. There is no known way to fix it.

I remember that thread - seems it was where @luni ended up making his Timer library from?

When I saw that it was "Somebody Else's Problem" - I just stopped and looked at it without seeing the T_3.6 in context as so much faster as the simple sample above shows.

T_4 goes from 5 times faster than T_3.6 to 5 times slower loop() cycles with just two 'simple' timers in use in p#9 above.

@ossi recent code not posted ... but as noted the post #3 code uses a TIGHT loop(){while(1){ 'code' }} - so yield and event responder not an issue

But indeed as questioned in p#8 - reading that code it is doing quite a number of USB print()'s - so it would be expected USB would take some time for processing that - especially with the T_4 having laggy interrupt response.

p#9 code could emulate the p#3 prints and see if isr()'s do miss ... but code not provided and there was something else I wanted to do with that code ... testing __STREXW instead of stopping interrupts. When done in that other logger with PSRAM code - it seemed to be failing to work as expected.
 
I think ossi has explained the problem clearly, especially in post #7.
The problem is: something wakes up, every now and then, and disables interrupts for some amount of time.

The main question I have is: If you remove the Serial.print() call from the loop() function, does that still happen?
As indicated by Frank B, the systick interrupt, and the USB hardware, will cause interrupts, and especially USB may have some amount of latency involved.

Also, what is causing these interrupts? Are they pin interrupts, or timer interrupts, or some other form of interrupts? Interrupt priority may end up being a factor.
 
- If you're not using the latest core version (after 1.52), the Eventresponder gets called - in Systick _and_ yield(). It disables the Interrupts globally.
- USB disables the interrupts globally.

Both do it for a short time only, but enough to delay some interrupts. Rising the priority does _not_ help in this case.

so:
- use the latest core from Github
- edit the USB code to disable the USB-Interrupt only (instead using global interrupt disable)
 
I think ossi has explained the problem clearly, especially in post #7.
The problem is: something wakes up, every now and then, and disables interrupts for some amount of time.

The main question I have is: If you remove the Serial.print() call from the loop() function, does that still happen?
As indicated by Frank B, the systick interrupt, and the USB hardware, will cause interrupts, and especially USB may have some amount of latency involved.

Also, what is causing these interrupts? Are they pin interrupts, or timer interrupts, or some other form of interrupts? Interrupt priority may end up being a factor.

Clearly explained what is observed and demonstrated in the scope image - except for repro code to see what may be behind it.

systick and usb prints noted post #8 - prior to p#10 Frank B.
As far as observations here - without high USB SPEW rate - there is no other interference from any other interrupt.

Speculation involved ... Using own sketch evolving p#8 for other purpose - testing __STREXW for atomic update w/_isr() instead of interrupt Off/On the counts always work ... but no intense USB output that as noted in p#8 is possibly the issue - 'ASSUMING' what code may be running and printing as noted.
> from p#9 code when running - the counts per second in the _isr() are hitting 500K - even with two of then running at 500K - so none are being missed.
> added LEDs to this T_4.1 - and more code to _isr()'s to blink lights and using the __STREXW I can see when an interrupt fires during the retrieval of _isr() count values, but even when that happens both 2 us timers never miss a count
> worst (very rare in steady state 1 second print) case is one interval of a second measured in loop hits 499999 and the next interval then shows 500001.
>> Unless I purposefully put a delay in the loop code with a button press causing more code overhead and conditional LED blinks - but no more USB prints.
>> and those 'off' counts typically return when the button is released?
This shows the two timers mt and mtB hitting 500K, then with 'delay' button the loop code is interrupted and repeats 9 extra times per update on the second - oddly 9 extra counts are triggered on button press and the extras are removed on button release and steady state returns.
mt#=500000 with LoopCount=4059687 mtB#=500000
mt#=500005 with LoopCount=4013582 mtB#=500004 Extra STREX#=9
mt#=500000 with LoopCount=4004097 mtB#=500000 Extra STREX#=9
mt#=500000 with LoopCount=4061802 mtB#=500000 Extra STREX#=9
mt#=499995 with LoopCount=3999810 mtB#=499996
mt#=500000 with LoopCount=4060609 mtB#=500000
>> Even here no counts are missed - just shifted in accounting for them

Also in (re)finding the post #9 'lag' or overhead in T_4 timers - KurtE noted this Pull Request from January :: github.com/PaulStoffregen/cores/pull/425
> it is possible it might improve the system and remove the signs of the problem ... but it has some merging needed now as written it seems ...
> Not sure how this affect 'evolving sketch' yet either
 
- If you're not using the latest core version (after 1.52), the Eventresponder gets called - in Systick _and_ yield(). It disables the Interrupts globally.
- USB disables the interrupts globally.

Both do it for a short time only, but enough to delay some interrupts. Rising the priority does _not_ help in this case.

so:
- use the latest core from Github
- edit the USB code to disable the USB-Interrupt only (instead using global interrupt disable)

@Frank B - as noted p#8 the only posted @ossi code in p#3 shows 'tight while(1)' in loop so it never exits loop to hit that yield().
> Turns out code (as in p#2) here has "void yield() {}" defined so not affecting notes above, but removing that is no change - but IIRC I have gotten the 'code in progress update' from github in CORES.
 
Status
Not open for further replies.
Back
Top