chipKIT® Development Platform

Inspired by Arduino™

Uno32: microseconds timer glitch every 107.4 seconds?

Created Tue, 11 Oct 2011 16:58:36 +0000 by jbeale

jbeale

Tue, 11 Oct 2011 16:58:36 +0000

I'm using the Uno32. I have an input signal which has 1 pulse per second (1 pps)*. My program watches the input and on each rising edge of the PPS signal, I print out the value of millis() and micros(). It looks like the microsecond timer has some kind of a glitch at 107.4 seconds after startup, and every 107.4 seconds afterwards. In the table below, the second column is microseconds divided by 1000000, and the third column shows a delta-time, that is the difference between the current microsecond reading and the reading one second ago. The difference is usually 999988 microseconds (because my Uno32 clock is apparently 12 ppm slow) but at second #108, suddenly I've lost about 0.3 seconds on the microsecond timer. Note that the millisecond timer remains accurate to 1 millisecond. I expect a rollover at 32 bits, but that should take over 70 minutes to occur. This glitch occurs every 107.4 seconds, showing up again at second 215, 323, 430, 537, etc.

*The input signal is from an OCXO-based clock and is stable and accurate at the 1E-8 level (10 ppb) relative to GPS time.

milliseconds/1000.0, INT(microseconds/1E6), delta_microseconds
(...)
105.078,105,999988
106.078,106,999987
107.078,107,999988
108.078,107,704878  <== not what I expect
109.078,108,999988
110.078,109,999988
111.078,110,999988
112.078,111,999987

drBart

Sun, 30 Oct 2011 16:43:47 +0000

I used a 555 timer with C1 = 1uF, R1 = 10KOhm, and R2 = 1MOhm, giving me a period of ~ 1.4 seconds.

Here's my source:

#define trigger 3

bool trigState = 0;
bool trigLast = 0;
unsigned long currentMillis = 0,
              lastMillis = 0,
              currentMicros = 0,
              lastMicros = 0;

void setup()
{
  Serial.begin(115200);
  
  pinMode(trigger, INPUT);
}

void loop()
{
  trigState = digitalRead(trigger);
  if(trigState && !trigLast)
  {
    currentMillis = millis();
    currentMicros = micros();
    Serial.print(currentMillis / 1000.0);
    Serial.print(" - ");
    Serial.print(currentMicros / 1000000);
    Serial.print(" - ");
    Serial.println(currentMicros - lastMicros);
    lastMillis = currentMillis;
    lastMicros = currentMicros;
  }
  trigLast = trigState;
}

I ran this on the Arduino Uno for just over two hours and got a plot that showed a slight upward trend, but no periodic errors like the ones you described.

I then ran the same code on the Max32 hooked up to the same 555 timer circuit overnight and got a plot that showed very interesting discrepancies in the deltamicros values.

Here's an example of one such discrepancy. The changes in millis() look fine, but the deltaMicros value is way off.

6977.88    2636    1438845    0.739461997
6979.32    2637    1648       99.88461674
6980.76    2638    1438407    0.708795814

Also, not that integer overflow does not effect the deltaMicros value, dut to the nature of integer math. Example:

4321.67    4292    1438481    0.713976859
4323.11    4294    1439940    0.816127455
4324.55    0       1438816    0.737431588
4325.99    2       1439152    0.760956331
4327.43    3       1439965    0.817877808

In both cases, there was some drift in the deltaMicros value, but I can't say weather this is due to the board or my 555 timer. The drift was rather small, but noticeable[see charts].

WestfW

Sun, 30 Oct 2011 18:42:24 +0000

Suspiciously close to when the 32bit "core timer" would overflow, clocking along at 40MHz. (2^32 / 40e6 == 107.374)

I haven't actually looked hard at how the chipkit libraries implement millis() and micros(), but I believe I've seen the core timer mentioned.

The "core timer" is a feature of the MIPS M4K rather than a (Microchip provided) peripheral. It counts continuously every other clock cycle, and has one compare register that can be used to generate an interrupt (I think that that's used for the millisecond interrupt.)

EmbeddedMan

Mon, 31 Oct 2011 02:22:07 +0000

Yes, the core timer fires every 1ms, and is used to keep track of the the milliseconds. And it works quite well, as you've found.

The microsecond value, is determined by grabbing the current value of the core timer counter itself, and compensating for overflows and such. That compensation is handled in the 1ms core timer interrupt (catching overflows properly). This is all at the very end of wiring.c - you can check it out for yourself.

Clearly we have a mistake in the math there - some overflow condition is not being handled properly, and we're forgetting something such that we loose a little bit of time.

The strange thing is that it seems to happen sometimes, and not others. I've been working on reproducing this bug on any of my chipKIT boards for the last week, and have been unsuccessful. However, I have not used the code you provide above yet - I was using some other code provided by another one of the developers.

We are actively looking into the cause and fix for this bug - and if you'd like to help the hunt, we'd sincerely appreciate it. The function of interest is CoreTimerHandler() in wiring.c, and then the micros() function in that same file.

*Brian

WestfW

Mon, 31 Oct 2011 05:08:00 +0000

CoreTimerHandler is rather long :-(

Why does micro() use this complicated interlock scheme instead of just disabling interrupts?

Isn't micros == millis()*1000 + microseconds_since_last_tick ? I'm not understanding why that seems so complicated to calculate, even with overflows. microseconds_since_last_tick should be ((ReadCoreTimer() - core_timer_at_last_interrupt)/CORE_TIMER_TICKS_PR_MICROSECOND unless the core timer overflows more than once, shouldn't it?

And now I'm depressed that ReadCoreTimer() is an actual subroutine and not done inline. It'd be a single instruction...

WestfW

Mon, 31 Oct 2011 07:52:17 +0000

How about some variation of this:

#define read_count(dest) __asm__ __volatile__("mfc0 %0,$9; nop" : "=r" (dest))
#define read_comp(dest) __asm__ __volatile__("mfc0 %0,$11; nop" : "=r" (dest))
#define write_comp(src) __asm__ __volatile__("mtc0 %0,$11; nop" : "=r" (src))

void __ISR(_CORE_TIMER_VECTOR, ipl2) CoreTimerHandler(void)
{
#if NEWCODE
    unsigned int compare, count, millis;

    millis = gTimer0_millis;  // defeat volatility

    read_comp(compare);
    do {
        millis ++;                      /* At least one tick */
        read_count(count);              /* keep current count current */
        compare += CORE_TICK_RATE;      /* increment next compare */
        /*
         * In the common case, we're done.  Now we check special
         * circumstances.  1st, see if the next target compare value has
         * wrapped around, but the current count hasn't.  That means the
         * counter is behind the target, and will deliver another interrupt.
         */
        if (compare < CORE_TICK_RATE) { // next compare overflow?
            if (count > 32*CORE_TICK_RATE) { // but count hasn't overflowed
                break;
            }
        }
        /*
         * Next check for having missed one or more clock ticks entirely,
         * in which case out next computer compare value will be "before"
         * the current count.  In this case we add an extra count to make
         * up for the miss, and try again.
         */
    } while (compare < count);
    write_comp(compare);  /* A compare val that is about 1ms past cur count */
    gCore_timer_last_val = count;  /* Save the count, too, for calculating micros() */
    gTimer0_millis = millis;       /* update millis */
#else

This doesn't do the SW PWM, but it's about 300 bytes shorter that the existing CoreTimerHandler (the new one in the sorcecode) Calling any C function from the handler adds a bunch of extra code saving registers that those functions MIGHT use. As long as the code is within the actual ISR function, it's smart enough to only save the registers it actually uses.

EmbeddedMan

Mon, 31 Oct 2011 22:55:49 +0000

Does your new version have any glitches like the old version did?

WestfW

Tue, 01 Nov 2011 04:31:00 +0000

(I didn't even re-write micros() yet; just trying to get a handle on the problem(s)) Your graphs imply that you have a setup that would quickly confirm or deny correct operation if I were to toss a .hex file in your direction? Wanna try it out if I get finished?)

I suspect my code is much too simple to solve the problem; the current code must be complicated because it needs to be, for reasons that aren't immediately apparent to someone who is just starting out trying to understand MIPS/CPU32 low-level code. But I'm willing to sit here and ask the naive questions, because I've found that this sometimes results in the experts going "you silly person; you need to do that because of ... Oh. Wait a minute; I think I see what's wrong." At least, so I hope.

BTW, the code I found said the "nop" after the coprocessor register read was needed because results wouldn't be immediately available in the pipeline, but the more recently MIPS literature I've been reading seems to imply that that just means the CPU will stall the pipeline as needed. (ie I could make my program faster by putting some useful instruction in that slot, but there is no benefit to explicitly including a "nop." Which is correct?

WestfW

Tue, 01 Nov 2011 07:40:52 +0000

Sigh. I put up DrBart's sketch and used an Arduino as my periodic time source. The 107.4 s glitch shows up nicely with the current binary distribution code (mpide-0022-macosx-20110907-test.dmg, mpide-0022-chipkit-macosx-20110619.dmg): [color=#400040]106.20 - 106 - 1001114 107.20 - 107 - 1001113 108.20 - 108 - 831330 109.21 - 109 - 1001112 110.21 - 110 - 1001117[/color]

Worse, though, is the new source level code with the "issue 124" patch. It still has a glitch in micros(), but millis() seems to be VERY broken. I've submitted: https://github.com/chipKIT32/chipKIT32-MAX/issues/143 [color=#400040]106.07 - 106 - 1001119 107.07 - 107 - 1001120 214.75 - 107 - 698505 214.75 - 108 - 1001118 214.75 - 109 - 1001119 214.75 - 110 - 1001120[/color]

I went and implemented a simplified micros() to go along with the simplified ISR code:

INTDisableInterrupts();
	result = gTimer0_millis * 1000;
	cur_timer_val = ReadCoreTimer();
	cur_timer_val -= gCore_timer_last_val;
	cur_timer_val += CORETIMER_TICKS_PER_MICROSECOND/2;  // rounding
	cur_timer_val /= CORETIMER_TICKS_PER_MICROSECOND;  // convert to microseconds
	INTEnableInterrupts();
	return result + cur_timer_val;

It doesn't seem to glitch, but I haven't run it for very long to see how well it stays in sync, either. My informal analysis says that it should always be consistent with the value returned by millis() (since it's derived from the same tick count), but I'm a little worried that it might not be continuous and monotonically increasing if called very close to actual timer events... (oh wait; I could actually test for that... It seems to run OK for the first 330s (three core timer overflows worth.) [color=#400040]105.71 - 105 - 1001115 106.71 - 106 - 1001115 107.71 - 107 - 1001114 108.71 - 108 - 1001114 109.71 - 109 - 1001116 110.72 - 110 - 1001113[/color]

The modified wiring.c is attached. Try it if you wish...

WestfW

Wed, 02 Nov 2011 06:48:57 +0000

Hmm. I think I can test for excessive drift between the library calls and the core timer.

For each value of millis() or micros(), there is a value that OUGHT to be in the core timer. Just multiply by the appropriate factor and discard the upper bits (they go away all by themselves, actually.) If the drift is OK, the difference between the CT and the value it ought to have should be less than the time interval involved (ie up to 40000 for millis(), because there are 40000 CT ticks in a millisecond.), but if if it's NOT ok, the difference should end up moving upwards (or downwards) as much as a full 32bits worth of CT ticks (~4e9)...

If that's valid, my code is looking pretty good (WRT millis(), anyway.)

KeithV

Wed, 02 Nov 2011 18:23:56 +0000

I am not sure how you get the time, but I looked this up in the MAL and I see for MX3&4 processors there is a wrap problem that needs to be considered and I wonder if this is being considered. See below for the MAL timer code and the comment. Also I do not know if we are reading TMR1, or _TIMER_1_VECTOR interrupt. The _TIMER_1_VECTOR interrupt has a 256 hardware prescaler on it, so it only runs at 312,500Hz, or 3.2usec per tick (with an 80MHz clock).

As for counter wrap, no matter how you slice this we are going to hit counter wraps in a DWORD on a regular basis, so I have made a helper routine to deal with waiting for timeouts and counter wrap. May be helpful.

The MAL code:

do
{
	DWORD dwTempTicks;
	
	IEC0SET = _IEC0_T1IE_MASK;	// Enable interrupt
	Nop();
	IEC0CLR = _IEC0_T1IE_MASK;	// Disable interrupt
	
	// Get low 2 bytes
	((volatile WORD*)vTickReading)[0] = TMR1;
	
	// Correct corner case where interrupt increments byte[4+] but 
	// TMR1 hasn't rolled over to 0x0000 yet
	dwTempTicks = dwInternalTicks;

	// PIC32MX3XX/4XX devices trigger the timer interrupt when TMR1 == PR1 
	// (TMR1 prescalar is 0x00), requiring us to undo the ISR's increment 
	// of the upper 32 bits of our 48 bit timer in the special case when 
	// TMR1 == PR1 == 0xFFFF.  For other PIC32 families, the ISR is 
	// triggered when TMR1 increments from PR1 to 0x0000, making no special 
	// corner case.
	#if __PIC32_FEATURE_SET__ <= 460
		if(((WORD*)vTickReading)[0] == 0xFFFFu)
			dwTempTicks--;
	#elif !defined(__PIC32_FEATURE_SET__)
		#error __PIC32_FEATURE_SET__ macro must be defined.  You need to download a newer C32 compiler version.
	#endif
	
	// Get high 4 bytes
	vTickReading[2] = ((BYTE*)&dwTempTicks)[0];
	vTickReading[3] = ((BYTE*)&dwTempTicks)[1];
	vTickReading[4] = ((BYTE*)&dwTempTicks)[2];
	vTickReading[5] = ((BYTE*)&dwTempTicks)[3];
} while(IFS0bits.T1IF);
IEC0SET = _IEC0_T1IE_MASK;		// Enable interrupt

The counter wrap helper function:

/**************************************************************************** Function: bool TimeElapsed(DWORD tStart, DWORD tWait, DWORD tNow)

Description: Because TickGet is only returning a DWORD, with an 80MHz clock and a 256 prescale, we only have about 3.8 hours for the DWORD to wrap and we get a window of tWait every 3.8 hours that a simple compare will not work correctly. This function accounts for counter wrap.

Precondition: TickGet() is running

Parameters: tStart - The start time tWait - number of ticks to wait tNow - Current time as by TickGet() or millis()

Returns: True if the time has elapsed, false if still waiting.

Remarks: None ***************************************************************************/ bool HasTimeElapsed(DWORD tStart, DWORD tWait, DWORD tNow) { DWORD tEnd = tStart + tWait;

// if we are in a wrap condition
// then shift everything around the wrap.
// We know if we shift by tWait on a wrap
// then start and end are now beyond the wrap and
// are linear to each other
if(tStart > tEnd)
{
    tStart += tWait;
    tEnd += tWait;
    tNow += tWait;
}

// what we don't know is how close to wraping tEnd is. And if the
// current time has gone beyond the tEnd, t may have wrapped
// so a simple t >= tEnd is not good enough
// the only time we know is linear is between tStart -> tEnd
// so we know time HAS NOT elapsed if the curretn time is
// within the range of tStart -> tEnd
return(!(tStart <= tNow  &&  tNow < tEnd));

}

Example Code:

tStart = millis();
do {

    // in order to know what connection state we have
    // we must run the stack tasks
    Ethernet::PeriodicTasks();

    // if it is connected get out
    if(TCPIsConnected(hTCP))
    {
         CState = Connected;
        if(pStatus != NULL) *pStatus = Connected;
        return(true);
    }

   } while(!HasTimeElapsed(tStart, msBlockMax, millis()));

EmbeddedMan

Sat, 19 Nov 2011 20:19:12 +0000

WestfW, I have tried out your new wiring.c, and I really like it. It appears to solve all of our time related problems. Very, very nice job. You write some really sweet code - thank you very much for that.

Now I'm trying to integrate support for the SoftPMMServo library. And you are, of course, right - adding any function calls in an ISR bloats the ISR.

So, what can we do? We can't easily incorporate all of the SoftPWMServo ISR code into wiring.c. But what if there were a way to have two CoreTimerHandler() ISR routines, and we would switch between them when somebody initializes SoftPWMServo? The 'normal' one would be really small and fast (yours), and then the 'softPWMServo' version would make a call to the SoftPWMServo function, and thus would be bloated. But it would mean that, at the expense of two CoreTimerHandler() functions, we'd have the best of both worlds?

What do you think?

*Brian

WestfW

Mon, 21 Nov 2011 08:17:47 +0000

what can we do?

I'm out of town at the moment, so I can't look things up easily, but...

  1. if moving the interrupt vector table is possible (it's NOT on an AVR, for example), that's one possibility.
  2. lightweight (inline ASM) linkage to another lightweight ISR routine; similar to the way it works now, but without the compiler ending up thinking that it has to set up the full C environment. AVR-GCC has some attributes ("naked") for eliminating standard C linkage; PIC32 might have something similar. If not, there's always actual assembler for the important bits.

PS: thanks for the compliments!

EmbeddedMan

Mon, 21 Nov 2011 14:13:04 +0000

I think it should be possible to do the following:

  1. Disable interrupts
  2. Register the 'new' ISR routine
  3. Enable interrupts

We'd do this whenever we want to switch. The new ISR routine (be that the SoftPWMServo version or the 'normal' version) simply replaces whatever was in the old vector spot. So it should work, and it should be pretty easy to do this all within the SoftPWMServo init routine, I think.

I'll take a look at it over the next couple of days. I'd love to keep the 'normal' version really slimmed down and clean.

By the way, I've built upon your code and have sent an updated version of wiring.c to Rick to include with the next test builds. This version passes all of my tests, including keeping accurate millisecond and microsecond time during EEPROM writing, SoftPWMServo running and both EEPROM and SoftPWMServo simultaneously. The only improvement, at this point, that I want to make is this dual-ISR switcharoo thing.

*Brian

ricklon

Mon, 21 Nov 2011 18:59:27 +0000

I'm working on a new experimental build. I should have it completed tonight. It will include the timer fix.

This build also includes some 1.0 features like board variants, progress bar, board, and comp port selections are shown.

Yea!

It's still experimental. But it's going to very nice once we verify all these fixes, and changes.

-_Rick