MSP432P4111: Possible bug reading TimerA0 TAR when timer runs off 32768Hz oscillator

Hi Julian,

I do not find any related information in the device errata. However, based on your description, I think it is credible that the issue is caused by the asynchronous clock resource on the timer. Which power mode you used when the timer is running? Could you try always let the code runs at active mode?

Best regards,

Cash Hao

I don't know much about SYSBIOS, but Refer TRM (SLAU356I) Sec 19.2.1 ("NOTE", second paragraph). 

It appears that getCount does the recommended fetch-voting based on the "synchronous" flag, set according to a parameter (presumably from the user program) to Timer_Instance_init(). Is that flag set to 0?

[Edit: Just to be clear, that code isn't trying to deal (primarily) with rollovers, rather to deal with overshoots, where -- due presumably to interrupt latency--  the entire next tick has passed by the time you try to update it.]

G'Day Bruce,

>>I don't know much about SYSBIOS, but Refer TRM (SLAU356I) Sec 19.2.1 ("NOTE", second paragraph). 

Thank you, yes, I'm aware of the need for voting for async timer clocks.  We are not reading TAR in our own code here - that's been done by SYSBIOS.  Its interesting to compare how SYSBIOS handles this compared to DriverLib.  Differences are highlighted in orange.

• SYSBIOS
  • [SIMPLELINK]\kernel\tirtos\packages\ti\sysbios\family\arm\msp432\Timer.c -> Timer_getCount()
  • If timer clock is synchronous, TAR is read and returned.
  • If timer clock is asynchronous, TAR is read twice.
    • If secondReading - firstReading <= 10 counts TAR is considered stable and firstReading is returned to the caller.
    • Otherwise TAR is keeps being read until the two readings are within 10 counts

• MSPWARE/DRIVERLIB
  • [SIMPLELINK]\source\ti\devices\msp432p4xx\driverlib\timer_a.c -> Timer_A_getCounerValue()
  • TAR is read twice regardless of whether the timer clock is asynchronous or not
    • Difference between firstReading and secondReading is calculated as largerReading - smallerReading.
    • If the difference <= 50 counts, TAR is considered stable and secondReading is returned to the caller.
    • Otherwise TAR keeps being read until the two readings are within 50 counts.

I wonder why SYSBIOS returns firstReading, not secondReading.  In my mind secondReading is likely to have more correct bits because TAR has had longer to settle.

Also, I don't understand why a 10/50 count band is being allowed here.  Why don't these functions keep reading the TAR until they get two identical readings?  Is this just to speed things up? I worry allowing a band can be problematic in some circumstances.  Consider this example -

• The current TAR value (truncate to 8 bits for simplicity) is 0b00001011 and just about to count up. 
• Timer_getCount() is run as TAR transitions to its new value.
• It is possible that the first read of TAR happens when just the two LSBs have transitioned - i.e. firstReading = 0b00001000
• Then the second read get the final settled value - i.e. secondReading = 0b00001100
• Timer_getCount() calculates secondReading - firstReading = 4
• The different is less than 10 so Timer_getCount() returns firstReading (=0b00001000) to the caller
• This is a problem because firstReading is less than the TAR value we started with

>> It appears that getCount does the recommended fetch-voting based on the "synchronous" flag, set according to a parameter (presumably from the user program) to Timer_Instance_init(). Is that flag set to 0?

This is all handled automatically by the tools.  The tools setup TimerA0 for use by SYSBIOS with a 32768Hz oscillator and TACCTL0.SCS set to 0 (Asynchronous).  You can see this passes through correctly to Timer_getCount() by putting a breakpoint at line 252 of [SISBIOS]\.....\Timer.c waiting for the breakpoint to be hit then examining the obj->synchronous flag in the debugger. 

>> [Edit: Just to be clear, that code isn't trying to deal (primarily) with rollovers, rather to deal with overshoots, where -- due presumably to interrupt latency--  the entire next tick has passed by the time you try to update it.]

Thank you yes, that's right.

Cheers

Julian

Based on the comment, I think the guard band around the fetched time(s) is intended to accommodate a fast (asynchronous) clock, i.e. close to MCLK, which would be expected to advance while the fetches were executing. (My first thought is that this is a very unusual case -- someone who went to the trouble to design-in a fast crystal would probably use it for MCLK as well. It seems like the guard works against you with a slow timer.) Another observation is that in the case of a (small) mismatch it returns first (closer to the call) rather than second (closer to the return).

Are you fairly certain that your breakpoint indicates a failure case? Your symptom  --a two-second stall-- is consistent with missing an overshoot and waiting for the 32kHz timer to wrap around again; in this code that would mean not setting CCIFG when it is needed. But based on your values, it seems that it should have matched case "C".

I agree that this looks somewhat odd. Unfortunately, I can't seem to build your project so all I can do is inspect. I have in the past written code to do something analogous, and there are usually many corner cases.

>> ....is intended to accommodate a fast (asynchronous) clock, i.e. close to MCLK, which would be expected to advance while the fetches were executing....

That makes sense, thank you for the explanation.  As you say, if the timer clock is much slower than MCLK, this band check is not really need. 

>> Another observation is that in the case of a (small) mismatch it returns first (closer to the call) rather than second (closer to the return).

Yes, and I think that's part of the problem because the first value read is more likely to be a transient state than the second value read (when timer clock is slow compared to MCLK).

I notice that TI hasn't been consistent in which value they return: SYSBIOS (Timer_getCount()) returns the first read value, while the equivalent DriverLib/MSPWare call (Timer_A_getCounerValue()) returns the second read value.

>> Are you fairly certain that your breakpoint indicates a failure case?

Yes.  Given how simple our example project is (a HWI and a Clock function, both doing almost no work) it should be impossible to fall into case C with the now value (the value of TAR reported byTimer_getCount()) being one less than the previous CCR0 setting. 

• In order to fall into case C (i.e. now less than previous), we'd need a two second delay (full rollover of the TAR).
• There is nothing in the code that could cause a 2 second delay.  The code barely does any work at all.
• now is always exactly one less than previous when we hit the breakpoint.  I don't see how some external delay (power management?? debugger?? other???) could interact with the code in such a way as to always have now exactly one less than previous.
• Although now is less than previous, the TAR register itself is actually greater than previous so there is nothing wrong with the timer count, only with the now value.

So, given the above, our conjecture is that the now value is incorrect.  And the reason that its incorrect is because reading of the TAR register to set now (a) allows a band of 10 between reads and (b) returns the first read value (which is more likely to be a transient state of the TAR register) rather than the second when the difference between reads is <10.

>> But based on your values, it seems that it should have matched case "C".

Well spotted!  Yes, I've only explained the first bug so far, but we think there is another - when the above bug occurs, it causes the SYBIOS timer interrupt to get into a loop triggering itself.

The chain of events is roughly as follows:

1. The SYSBIOS TimerA0 CCR0 HWI fires (identified as HWI.ti_sysbios_family_arm_msp432_Timer_periodicStub_E() in execution graphs, function Timer_periodicStub() in Timer.c)
2. It advances the CCR0 register (line 185 Timer.c)
3. Timer_setNextTick() runs and finds now is less than previous  (due to first bug - now being read incorrectly) causing "Case C" to run.
4. Case C sets the CCR0 interrupt flag.
5. The SYSBIOS CCR0 HWI completes, then runs again immediately because of step 4 (this is second bug, HWI triggering itself)
6. Now we have a loop
   • per step 1, Timer A0 CCR0 HWI fires
   • per step 2, CCR0 is advanced,
   • per step 3 case C is triggered - this time now because of bug 1, but because we've shifted the CCR0 ahead of where it really should be.
   • per step 4, CCR0 IFG is set,
   • per step 5, the HWI completes then immediately fires again....
7. Loop continues until we catch our tail
8. Not quite sure how this translates to a 2 second delay....... but if you refer back to our older forum post I think (though I haven't quite got the complete mechanism down) this loop does explain why Swi.ti_sysbios_knl_Clock_workFuncDynamic_E() runs for so long in some of our execution graphs.

Cheers

Julian

G'Day Cash,

I've never worked with the power management stuff.  How do I know if a device is always running in active mode?

I do know our main project has .enablePolicy set to false in the power manager stuff (PowerMSP432_ConfigV1).  Is that it?  Is it possible to see what the power management state is at run time?  I don't see anything in ROV.

Cheers

Julian

Hi Julian,

You can check the PCMCTL0 register to get the current power state information of your MCU.

Best regards,

Cash Hao

I was kind of hoping a TI-RTOS wizard would show up, but if I were stuck on this, I would do the two indicated experiments:

1) Set the guard band (READ_LATENCY) to 0, which is what it really should be in your configuration. 

2) Change getCount to return second rather than first, which in theory is benign.

It sounds like your experiments are fairly expensive, so you may want to do both, then work backwards if it fixes the symptom.

I installed CCSv9 and was able to build your project.

I was able to generate your symptom; it took maybe a minute or so. In each of maybe 4-5 occurrences, the indication was that the difference between first and second was (always) 3. This would seem to point to a (long!) carefully-timed pre-emption.

I tried experiment (2) above. and it took maybe 1-2 hours (I wasn't watching closely) to fail. At the breakpoint, CCS seemed to be telling me that second was less than first. (I suspect an illusion, but I haven't found it.) In any case, second was less than (old) CCR0. This seems to point away from a pre-emption as a trigger. It also says that this would not be an effective fix.

I also tried a trivial experiment -- just running a timer from ACLK (i.e. async) and seeing if TAR read at a CCIFG (ever) differs from CCR0. That hasn't failed in 30 minutes or so. This seems to point away from a clock-boundary glitch (reading stale value from timer peripheral).

I have to get up for work in the morning, so I probably won't get further before tomorrow. I suspect there are some clues here, but I don't yet know what they mean.

G'Day Bruce,

Thank you for your effort on this.  There is some comfort in receiving confirmation that this is a real, reproducible problem.

Given I have a work around, I'm not in a hurry for a solution, but I would really appreciate if you could investigate further when you have the time and keep me up to date with what you find.  

We've been working on this bug on and off for two years.  It would be great to definitively squash it!

Cheers

Julian

All,

Thank you for the effort of the investigation throughout this thread. We will summarize this thread and feed it back to our internal bug tracking so this can potentially be addressed in a future release.

In the mean time, I'm glad you were able to find a workaround for the issue. At this time, I'm going to mark the reply where you discuss your workaround as "TI Thinks Resolved" for those who stumble across this thread and are in need of the workaround as well. 

G'Day Jace,

Thank you for your feedback.

We do have a work around for our particular situation where a cascade of at least two bugs messes up SYSBIOS timing for things like Task_sleep(), clock functions, semaphore timeouts etc.  [This sentence added to help with keyword searches!]

I'm glad to hear that you've added this to your bug tracking because I worry the primary bug might have broader impact than just our somewhat esoteric SYSBIOS timing problem - its a bug in a commonly used SYSBIOS & DriverLib API across processors.

The primary bug looks to be that both the SYBIOS Timer_getCount() function and the DriverLib Timer_A_getCounerValue() functions can't necessarily be trusted for reading timers with asynchronous clocks, and the timer clock is very different to MCLK (e.g. the default setup for SYSBIOS seems to be MCLK = 48MHz, SYSBIOS timer peripheral clock = 32768Hz)

If my guess for the root cause about this is correct, then I think the SYSBIOS function will have an error of up to 10 counts while the DriverLib function an error of up to 50 (but with a lower probability [though non-zero probability given Bruce's comments above] of an erroneous value being reported), and in both cases, the reported timer count can be LESS than the real value (which is where SYSBIOS's use of Timer_getCount() comes unstuck)

I haven't checked the implementation of these functions for other processors, but I imagine they use the same voting process (which requires two readings of the timer register to be within a tolerance).  If they do, then this same problem may well exist for more than just the MSP432.

Cheers

Julian 

I'll just throw in my subsequent (inconclusive) observations:

1) I tried experiment (1) -- setting the tolerance=0 -- and it ran without fail for 6.5 hours (then I had to use the equipment for something else). This isn't too surprising since it would have caught the particular case where TAR seems to "jump" from ccr0-1 to ccr0+2. 

2) My scope showed the GPIO toggle-burst right on schedule up to the breakpoint. This suggests that the timer is not actually counting all the way around to ccr0-1 (2 seconds), though that's how the code interprets it.

3) Mis-matches (second != first) happen moderately often. I put in a little histogram and (a) mismatches were counted maybe 5 times per second over a few minutes and (b) maybe 1% of these show a difference > 1 (up to at least 10). The code of interest is running IRQ-enabled, so this wouldn't be startling except in how often it happens -- right between 2 consecutive instructions. In the failure case the RTOS trace didn't show any "surprise" interrupts.

4) The overt symptom isn't quite a "stall", rather the code sets CCIFG repeatedly to cause the RTOS code to step very fast (maybe a half-second) around the timer cycle to get to (original) ccr0-1 (as Julian described above). The scope shows non-stop GPIO toggle-bursts from pin_toggle during that time.

I focused on Timer.c. I'm not familiar enough with TI-RTOS to speculate what other parts of the system might be involved. 

Thank you for this additional testing Bruce! 

It's a great independent analysis and confirmation of the chain of issues I'm experiencing. 

Based on your testing I think the right solution for the first bug is to set the tolerance to 0 in Timer_getCount() / Timer_A_getCounerValue() [will work for timer peripherals with asynchronous clock, much slower than MCLK].

The work around I'm using (not letting SYSBIOS use a timer with async clock) is a bit heavy handed, and doesn't solve the issue for people using the Timer_getCount() / Timer_A_getCounerValue() in their own code.

I *think* once the first bug is fixed (so that the count read from the timer can longer longer be less than the actual register value), the second bug can't be triggered.

I guess now we wait to see if the issue is fixed in the next release. 

Thanks again Bruce. 

Cheers

Julian