Timer mystery

D

DrM

Well-known member
Consider the following code. In a nut shell, one function launches the other on a timer, and the other then delays for some time and then cancels the timer. This is running on a Teensy 4.0

To make things easy to follow, each function toggles PinA, and PinB is set when the timer is started and then cleared by the other function soon after it is called by the timer (before the delay).

Below are two oscilloscope images.

When the timer is longer than the delay, everything is fine. In this example, the first time it is run the pulses are 10 usecs apart.

Now, if the delay is longer than the clock, the first time it is okay, but the second time the pulses are 4 usecs apart.

After that, no matter how the times are set., the pulses are always 4 usecs apart. In other words, the timer appears to be corrupted, and, it never recovers until the device is powered off or rebooted.

Code: 
unsigned int u1 = 10;
unsigned int u2 = 1;

void testinner( ) {
  digitalWriteFast(PinA, HIGH);
  delayMicroseconds(1);
  digitalWriteFast(PinA, LOW);
  digitalWriteFast( PinB, LOW );
  delayMicroseconds( u2);
  shutterTimer.end( );
}

void testclock( ) {
  digitalWriteFast(PinA, HIGH);
  delayMicroseconds(1);
  digitalWriteFast(PinA, LOW);
  digitalWriteFast( PinB, HIGH );
  shutterTimer.begin( testinner, u1 );
}


IMGA.jpg

IMGB.jpg
 
P/S, The behavior is not altered by bracketing with noInterrupts(), interrupts().

In other words, the following code produces the same result as the above.

Code: 
unsigned int test_u1 = 10;
unsigned int test_u2 = 1;

void testinner( ) {
  noInterrupts();
  digitalWriteFast(SHPin, HIGH);
  delayMicroseconds(1);
  digitalWriteFast(SHPin, LOW);
  digitalWriteFast( busyPin, LOW );
  delayMicroseconds(test_u2);
  shutterTimer.end( );
  interrupts();
}

void testclock( ) {
  digitalWriteFast(SHPin, HIGH);
  delayMicroseconds(1);
  digitalWriteFast(SHPin, LOW);
  digitalWriteFast( busyPin, HIGH );
  shutterTimer.begin( testinner, test_u1 );
}
 
Missing some context without complete sketch.

If both are same "timers" 'Interval'? then they will have same priority, so can't interrupt each other.

Seems the first scope image is correct?

What about code re-ordering moving .end() up to top - though doesn't seem long enough to trigger again before ending - almost looks like .begin() is firing a prior expired event:
Code: 
void testinner( ) {
[B]  shutterTimer.end( );[/B]
  digitalWriteFast(PinA, HIGH);
  delayMicroseconds(1);
  digitalWriteFast(PinA, LOW);
  digitalWriteFast( PinB, LOW );
  delayMicroseconds( u2);
}
 
I assume this is an IntervalTimer object?

What happens if you move the "shutterTimer.end()" line to the start of testinner so that the shutterTimer doesn't get a chance to fire again while you're in the delayMicroseconds(test_u2) call in testinner?
 
@defragster, That delay to longer than one interval is the point.

Let me try to explain the intent of the example it in a more simple way:

A function is launched by an interval timer, by calling begin().

Inside that function, there is a delay and then it stops the timer, by calling end() .

When the function called by the interval timer, runs for more than one interval of time and then calls end(), the timer becomes polluted.

The way it is seen to be polluted is that after the above, any call to begin() with any value for the interval, always results in an inteval of 4 usecs.

I think that is a bug. (a) The timer should not be able to retrigger, and surely not with interrupts disabled (but then we dont know that it really did), and (b) end() should not pollute the timer just because it is called after one interval by its isr.


There that is it, sorry for the edits, It took a few passes to get my thoughts organized.
 
Rather than explain, can you fill in the rest of the code so it is a complete program any of us could run and see the behavior?

Even if the missing setup() and loop() code is trivial, it's guesswork for anyone to try to reproduce the problem.


DrM said:
I think that is a bug.
Click to expand...

It is possible you've found some previously unknown bug. But it won't ever be investigated and fixed without a test case to reproduce the problem!
 
Okay I can do that. Here is a self contained program that demonstrates the behavior. In the serial console enter the command "test clock 10 1", and everything is okay. Enter the command "test clock 10 11" and you will see the bug.

Oh... and don't forget to monitor pins 1 and 11 with an oscilloscope. To save you a few seconds of time, here are the settings, 2v/div, 5 usec/div, trigger on rising or faling edge of pin 1


Code: 
#include "Arduino.h"

#include <digitalWriteFast.h>

#include <limits.h>

const int PinB   = 11;
const int busyPin = 1;
const int led = 13;

#define RCVLEN 256
char rcvbuffer[RCVLEN];
uint16_t nrcvbuf = 0;

IntervalTimer testTimer;

unsigned int test_u1 = 10;
unsigned int test_u2 = 1;

void testinner( ) {
  noInterrupts();
  digitalWriteFast(PinB, HIGH);
  delayMicroseconds(1);
  digitalWriteFast(PinB, LOW);
  digitalWriteFast( busyPin, LOW );
  delayMicroseconds(test_u2);
  testTimer.end( );
  interrupts();
}

void testclock( ) {
  digitalWriteFast(PinB, HIGH);
  delayMicroseconds(1);
  digitalWriteFast(PinB, LOW);
  digitalWriteFast( busyPin, HIGH );
  testTimer.begin( testinner, test_u1 );
}

char *startsWith( char *s, const char *key ) {
  int n = strlen(key);
  if ( !strncmp( s, key, n ) ) {
    return s + n;
  }
  return 0;
}

char *parseUint( char *s, unsigned int *u ) {
  unsigned long int l;
  char *p = s;
  l = strtoul( s, &p, 0 );
  if ( (p > s) && (l <= UINT_MAX) ) {
    *u = (unsigned int) l;
    return p;
  }
  return 0;
}


void setup() {

  pinMode(led, OUTPUT);  

  pinMode(busyPin, OUTPUT);
  pinMode(PinB,     OUTPUT);

  digitalWriteFast(busyPin, LOW);
  digitalWriteFast(PinB, LOW);

  Serial.begin(9600);
  delay(100);


}

void loop() {

  uint16_t nlen = 0;
  char *pc;
  char c;
  
  while ( Serial.available() ) {

    c = Serial.read();

    if ( c ) {

      if ( iscntrl( c )  ) {
        nlen = nrcvbuf;
        rcvbuffer[nrcvbuf] = 0;
        nrcvbuf = 0;
        break;
      }

      else if ( nrcvbuf || !isspace(c) ) {
        rcvbuffer[nrcvbuf++] = c;        
      }

      if ( nrcvbuf >= RCVLEN ) {
        Serial.println( (char *)"Error: buffer overflow" );
        nrcvbuf = 0;
      }
    }
    
  }
  
  if ( nlen > 0 ) {

    if ( (pc = startsWith( rcvbuffer, "test clock")) ) {

      (pc = parseUint( pc, &test_u1 ) ) && (pc = parseUint( pc, &test_u2 ) );

      Serial.print( "test clock ");
      Serial.print( test_u1 );
      Serial.print( " " );
      Serial.println( test_u2 );
      
      testclock();
    }

    else {
      Serial.print( "unknown command //" );
      Serial.print( (char *) rcvbuffer );
      Serial.println( "//" );
      
    }

    
    nlen = 0;

    Serial.println( "DONE" );
    
  }
    
  delay(100);
   
}
 
@joepasquariello Look at the oscilloscope traces. The spacing between the two leading edges in the lower trace, or the duration of the pulse upper trace, should be roughly equal to the value of test_u2 in usecs, in all cases.
 
@PaulStoffregen


Paul, is there a register where the interrupt from the specific timer can be masked? Is that done when the ISR is invoked?
 
Last edited:
@joepasquariello cc @PaulStoffregen

No, not really. It is not about my design. It looks a lot like what happens sometimes on not having masked the source of the interrupt before jiumping to the ISR.

But i did discover the problem by trying to implement around the assumption that I could put off calling end() for the timer, which indeed came from your comment. I saw that code too and thought the same thing..
 
Last edited:
Thanks for complete code - wrongly assumed there were two competing IntervalTimer()'s.
SEE POST #3 for the ANSWER!
Code: 
code re-ordering moving .end() up to top
: needed change marked in testinner( )
Gives this correct result, because the duration of the _isr code allows the timer to trigger a second time creating a PENDING interrupt before the .end() is called:
Code: 
C:\T_Drive\tCode\FORUM\iTimerChange\iTimerChange.ino Jan 16 2023 02:14:56
test clock 10 1
	A INdelay us=12.156667 [B]Delta=2.393333[/B] B IN CYC=2973357490 Delta us=1.620000 
DONE
test clock 10 1
	A INdelay us=12.183333 Delta=2.393333 B IN CYC=3693429474 Delta us=1.646667 
DONE
	[B]CHANGE _u2[/B] 
test clock 10 11
	A INdelay us=12.210000 [B]Delta=12.393333[/B] B IN CYC=1018533438 Delta us=1.673333 
DONE
test clock 10 11
	A INdelay us=12.190000 Delta=12.393333 B IN CYC=1798604574 Delta us=1.653333 
DONE
	[B]CHANGE _u2[/B] 
test clock 10 1
	A INdelay us=12.170000 [B]Delta=2.393333[/B] B IN CYC=2878676086 Delta us=1.633333 
DONE
test clock 10 1
	A INdelay us=12.190000 Delta=2.393333 B IN CYC=3418747174 Delta us=1.653333 
DONE

Wrote this edit since no scope here:
Code: 
#include "Arduino.h"

#include <digitalWriteFast.h>

#include <limits.h>

const int PinB   = 11;
const int busyPin = 1;
const int led = 13;

#define RCVLEN 256
char rcvbuffer[RCVLEN];
uint16_t nrcvbuf = 0;

IntervalTimer testTimer;

unsigned int test_u1 = 10;
unsigned int test_u2 = 1;

volatile uint32_t tiA = 0;
volatile uint32_t toA = 0;
volatile uint32_t tdA = 0;
uint32_t tiB = 0;
uint32_t toB = 0;

void testinner( ) {
[B][COLOR="#FF0000"]//  testTimer.end( );[/COLOR][/B] // Change suggested in Post #3: uncomment this and comment out the .end() below!
  tiA = ARM_DWT_CYCCNT;
  digitalWriteFast(PinB, HIGH);
  delayMicroseconds(1);
  digitalWriteFast(PinB, LOW);
  digitalWriteFast( busyPin, LOW );
  delayMicroseconds(test_u2);
[B][COLOR="#FF0000"]  testTimer.end( );[/COLOR][/B]
  toA = ARM_DWT_CYCCNT;
  tdA = toA - tiA;
}

void testclock( ) {
  tiB = ARM_DWT_CYCCNT;
  digitalWriteFast(PinB, HIGH);
  delayMicroseconds(1);
  digitalWriteFast(PinB, LOW);
  digitalWriteFast( busyPin, HIGH );
  testTimer.begin( testinner, test_u1 );
  toB = ARM_DWT_CYCCNT;
}

char *startsWith( char *s, const char *key ) {
  int n = strlen(key);
  if ( !strncmp( s, key, n ) ) {
    return s + n;
  }
  return 0;
}

char *parseUint( char *s, unsigned int *u ) {
  unsigned long int l;
  char *p = s;
  l = strtoul( s, &p, 0 );
  if ( (p > s) && (l <= UINT_MAX) ) {
    *u = (unsigned int) l;
    return p;
  }
  return 0;
}


void setup() {

  pinMode(led, OUTPUT);

  pinMode(busyPin, OUTPUT);
  pinMode(PinB,     OUTPUT);

  digitalWriteFast(busyPin, LOW);
  digitalWriteFast(PinB, LOW);

  Serial.begin(115200);
  while (!Serial && millis() < 4000 );
  Serial.println("\n" __FILE__ " " __DATE__ " " __TIME__);
  delay(100);


}

void loop() {

  uint16_t nlen = 0;
  char *pc;
  char c;

  if (0 != tdA) {
    Serial.printf( "A INdelay us=%f Delta=%f B IN CYC=%lu Delta us=%f \n", (tiA - tiB) / 600.0, tdA / 600.0, tiB, (toB - tiB) / 600.0 );
    tdA = 0;
  }

  while ( Serial.available() ) {

    c = Serial.read();

    if ( c ) {

      if ( iscntrl( c )  ) {
        nlen = nrcvbuf;
        rcvbuffer[nrcvbuf] = 0;
        nrcvbuf = 0;
        break;
      }

      else if ( nrcvbuf || !isspace(c) ) {
        rcvbuffer[nrcvbuf++] = c;
      }

      if ( nrcvbuf >= RCVLEN ) {
        Serial.println( (char *)"Error: buffer overflow" );
        nrcvbuf = 0;
      }
    }

  }

  if ( nlen > 0 ) {

    if ( (pc = startsWith( rcvbuffer, "test clock")) ) {
      unsigned int test_u2B = 0;

      (pc = parseUint( pc, &test_u1 ) ) && (pc = parseUint( pc, &test_u2B ) );
      if (test_u2 != test_u2B) Serial.println( "\tCHANGE _u2 " );
      test_u2 = test_u2B;
      Serial.print( "test clock ");
      Serial.print( test_u1 );
      Serial.print( " " );
      Serial.println( test_u2 );

      testclock();
      delayMicroseconds(100);
      if (0 != tdA) {
        Serial.printf( "\tA INdelay us=%f Delta=%f B IN CYC=%lu Delta us=%f \n", (tiA - tiB) / 600.0, tdA / 600.0, tiB, (toB - tiB) / 600.0 );
        tdA = 0;
      }

    }

    else {
      Serial.print( "unknown command //" );
      Serial.print( (char *) rcvbuffer );
      Serial.println( "//" );

    }


    nlen = 0;

    Serial.println( "DONE" );

  }

  delay(100);

}

It shows with above code and belated .end(): After the time change the NEXT interval timing is based on the PRIOR setting due to pending interrupt.
Code: 
C:\T_Drive\tCode\FORUM\iTimerChange\iTimerChange.ino Jan 16 2023 02:08:25
test clock 10 1
	A INdelay us=12.110000 Delta=2.361667 B IN CYC=201008866 Delta us=1.640000 
DONE
test clock 10 1
	A INdelay us=12.063333 Delta=2.361667 B IN CYC=741080842 Delta us=1.593333 
DONE
test clock 10 1
	A INdelay us=12.130000 Delta=2.361667 B IN CYC=1161151654 Delta us=1.660000 
DONE
	[B]CHANGE _u2[/B] 
test clock 10 11
	A INdelay us=[B]12.110000 [/B]Delta=12.361667 B IN CYC=1621353706 Delta us=1.640000 
DONE
test clock 10 11
	A INdelay us=[B]2.116667 [/B]Delta=12.361667 B IN CYC=3721424826 Delta us=1.646667 
DONE
test clock 10 11
	A INdelay us=2.136667 Delta=12.361667 B IN CYC=3326528318 Delta us=1.666667 
DONE
	[B]CHANGE _u2[/B] 
test clock 10 1
	A INdelay us=[B]2.076667 [/B]Delta=2.361667 B IN CYC=1866730070 Delta us=1.606667 
DONE
test clock 10 1
	A INdelay us=[B]12.136667 [/B]Delta=2.361667 B IN CYC=2286800586 Delta us=1.666667 
DONE
test clock 10 1
	A INdelay us=12.083333 Delta=2.361667 B IN CYC=2706871366 Delta us=1.613333 
DONE
 
Last edited:
I believe there may be 2 separate issues at play here, which makes for an extremely confusing situation. Even just diagnosing a single issue is hard enough...

IntervalTimer end() may indeed have a bug. Or maybe begin() followed by certain usage of end(). Normally IntervalTimer is used for periodic interrupts. This sort of single-shot usage isn't commonly done, so this code is exercising paths that haven't been as extensively tested as the normal usage for periodic interrupts.

My first impression is we may have a problem where the timer interrupt was pending while end() was called and that state within the PIT & NVIC never gets cleared, so the next begin() results in the timer interrupt happening immediately rather than after the newly configured interval.

The second possible issue may be within the testinner() function.

DrM said:
The spacing between the two leading edges in the lower trace, or the duration of the pulse upper trace, should be roughly equal to the value of test_u2 in usecs, in all cases.
Click to expand...

Perhaps you meant to have "delayMicroseconds(test_u2);" earlier within your testinner() function?

As the code is written, all the pin activity happens BEFORE the test_u2 delay. The only thing actually done after the test_u2 delay is disable of the IntervalTimer. You should never be able to observe any activity on the pins related to the test_u2 delay because your program isn't actually doing anything with the pins after that delay. As written you shouldn't ever see any test_u2 effect on your oscilloscope!

However, there is an observable and rather confusing effect you can see, because these 2 issues play together. If the delay before calling end() is so long that the timer has caused another interrupt to become pending, the timer will almost immediately call testinner() on the next run.

At least that's what I think is probably going on here. Will admit, I could be wrong... only ran it a couple times and looked at the code briefly. Haven't actually dug into IntervalTimer, so my hunch about the prior pending interrupt should be considered guesswork. But hopefully the situation about delayMicroseconds(test_u2) having no observable effect is easy to see just by looking at the code.
 
Indeed, Defragster called it on the first issue, all the way back at msg #3.

Here is a slightly modified copy of the program which calls end() before the timer can trigger again and does the delay before manipulating the pins. I believe this copy should work as desired.

Code: 
#include "Arduino.h"

#include <digitalWriteFast.h>

#include <limits.h>

const int PinB   = 11;
const int busyPin = 1;
const int led = 13;

#define RCVLEN 256
char rcvbuffer[RCVLEN];
uint16_t nrcvbuf = 0;

IntervalTimer testTimer;

unsigned int test_u1 = 10;
unsigned int test_u2 = 1;

void testinner( ) {
  testTimer.end( ); // do this first, before another interrupt becomes pending
  noInterrupts();
  delayMicroseconds(test_u2);  // delay before pulsing the pins
  digitalWriteFast(PinB, HIGH);
  delayMicroseconds(1);
  digitalWriteFast(PinB, LOW);
  digitalWriteFast( busyPin, LOW );
  interrupts();
}

void testclock( ) {
  digitalWriteFast(PinB, HIGH);
  delayMicroseconds(1);
  digitalWriteFast(PinB, LOW);
  digitalWriteFast( busyPin, HIGH );
  testTimer.begin( testinner, test_u1 );
}

char *startsWith( char *s, const char *key ) {
  int n = strlen(key);
  if ( !strncmp( s, key, n ) ) {
    return s + n;
  }
  return 0;
}

char *parseUint( char *s, unsigned int *u ) {
  unsigned long int l;
  char *p = s;
  l = strtoul( s, &p, 0 );
  if ( (p > s) && (l <= UINT_MAX) ) {
    *u = (unsigned int) l;
    return p;
  }
  return 0;
}


void setup() {
  pinMode(led, OUTPUT);
  pinMode(busyPin, OUTPUT);
  pinMode(PinB,     OUTPUT);
  digitalWriteFast(busyPin, LOW);
  digitalWriteFast(PinB, LOW);
  Serial.begin(9600);
  delay(100);
}

void loop() {

  uint16_t nlen = 0;
  char *pc;
  char c;

  while ( Serial.available() ) {
    c = Serial.read();
    if ( c ) {
      if ( iscntrl( c )  ) {
        nlen = nrcvbuf;
        rcvbuffer[nrcvbuf] = 0;
        nrcvbuf = 0;
        break;
      } else if ( nrcvbuf || !isspace(c) ) {
        rcvbuffer[nrcvbuf++] = c;
      }
      if ( nrcvbuf >= RCVLEN ) {
        Serial.println( (char *)"Error: buffer overflow" );
        nrcvbuf = 0;
      }
    }
  }
  if ( nlen > 0 ) {
    if ( (pc = startsWith( rcvbuffer, "test clock")) ) {
      (pc = parseUint( pc, &test_u1 ) ) && (pc = parseUint( pc, &test_u2 ) );
      Serial.print( "test clock ");
      Serial.print( test_u1 );
      Serial.print( " " );
      Serial.println( test_u2 );
      testclock();
    } else {
      Serial.print( "unknown command //" );
      Serial.print( (char *) rcvbuffer );
      Serial.println( "//" );
    }
    nlen = 0;
    Serial.println( "DONE" );
  }
  delay(100);
}

Might also be worth mentioning the input parsing code might have a subtle timing dependency on the entire input appearing in a single USB packet. That happens when the Arduino Serial Monitor sends, but the timing might end of different with a more traditional terminal emulator which transmits the keystrokes as a person types.
 
I tested it this morning and also found that the problem relates to trigger a second interrupt while the first ISR is running. The processor will store the request (which is a feature) and calls the ISR immediately after the next begin. As mentinoned above, moving the end() up prevents the issue by avoiding a trigger while the ISR is running.

Clearing the timer flag in intervaltimer.end() also fixes this.

Code: 
void IntervalTimer::end() {
#if 1
	if (channel) {
		int index = channel - IMXRT_PIT_CHANNELS;
		// TODO: disable IRQ_PIT, but only if all instances ended
		funct_table[index] = nullptr;
		channel->TCTRL = 0;
		[COLOR="#FF0000"]channel->TFLG = 1;[/COLOR]
		nvic_priorites[index] = 255;
		uint8_t top_priority = 255;
		for (int i=0; i < NUM_CHANNELS; i++) {
			if (top_priority > nvic_priorites[i]) top_priority = nvic_priorites[i];
		}
		NVIC_SET_PRIORITY(IRQ_PIT, top_priority);
		channel = 0;
	}
#endif
}
 
Just made @luni edit p#19 as suggested to prior code with 'LATE .end()' and indeed that is clearing the pending interrupt! :: channel->TFLG = 1;
> Paul suggested a fix forthcoming on the intervalTimer page - maybe this is it:: 'Future Teensyduino releases are expected to fix this issue. '
.... Crosspost p#22 ... Fix made for T_3.x and T_4.x ... {took out the garbage without a refresh} now Zzzzz's

@Paul: You're welcome p#20

Indeed (re @Paul p#15) the parsing worked properly here with TyComm on that short string - but the string building loop might wait a short #ms time for '\n' in case it is in a following packet.
 
@PaulStoffregen Thank you for the fix.

Re the suggestion to move end() to the beginning:

The delay and pin activity are in the intended order. The scope shows test_u1 - that is the interval timer. The delay test_u2 is there only to exercise the bug.

When test_u2 > test_u1, the timer is corrupted, and stays corrupted. That was the point!

- - - - - - - -

Further: on moving end() to the beginning:

Obviously, calling end() right away can be a partial workaround, provided the timer is not too short! A short enough timer would still get corrupted.. But again, I wanted to draw attention to the bug.

- - - - - - -

Re: using intervalTimer for a one shot.

Sometimes inner gets called repeatedly until a counter expires. The problem is the same, it finishes by corrupting the timer for the next go.
 
Last edited:
DrM said:
@PaulStoffregen re post #14.

"interrupt pending" - yes that was the point of the whole thing.

"delayMicroseconds earlier" - No. The delay and pin activity are in the right order. The scope shows the timing for test_u1 - that is the interval timer. The delay test_u2 is there only to exercise the bug.


The point is that the delay in test_u2 (so that another test_u1 is pending when end is called) is what corrupts the timer for test_u1

That was deliberate, again that was the point.
Click to expand...

Interrupt code can easily be broken. Not having the .end() before the next interrupt was queued was the problem. Paul has made a change to the CORES to alter the behavior, but as noted in p#3 it was expected behavior as written. Hopefully there isn't existing code counting on this behavior (as Paul noted in an edit on the intervalTimer page) as losing the pending interrupt may cause unwanted change.
 
You must log in or register to reply here.
Back
Top