Millis() goes backwards inside ISR after woken by pin

Troubleshooting
1

After hours of debugging why I’m getting double counting even with debouncing code I’ve found it’s because millis() is going backwards. Here’s a cut-down sample that shows the problem most of the time:

SYSTEM_THREAD(ENABLED);
SYSTEM_MODE(MANUAL);

static SerialLogHandler logHandler(LOG_LEVEL_INFO);
static system_tick_t log[1000];
static volatile int iLog = 0;

void isr() {
  log[iLog++] = millis();
}

void setup() {
  pinMode(D5, INPUT_PULLDOWN);
  attachInterrupt(D5, isr, RISING);
}

void loop() {
  delay(3000);  // Wait for serial to attach
  for (int i = 0; i < iLog; i++) {
    bool backwards = i > 0 && log[i - 1] > log[i];
    Log.info("%lu %s", log[i], backwards ? "<-" : "");
  }
  iLog = 0;
  System.sleep(D5, RISING, 0);
}

So basically I’ll logging into an array the millis() when the ISR is called. If I let it sleep and then touch 2 wires plugged into D5 and 3V3 (it needs a ‘bouncy’ input to show the problem) I get output like this:

Serial monitor opened successfully:
0000009295 [app] INFO: 6295 
0000009296 [app] INFO: 6295 
0000009296 [app] INFO: 6294 <-
0000009296 [app] INFO: 6294 
0000009296 [app] INFO: 6294 
0000009296 [app] INFO: 6294 
0000009297 [app] INFO: 6294 
0000009297 [app] INFO: 6294 
0000009297 [app] INFO: 6294 
0000009297 [app] INFO: 6294 
...

The first couple interrupts had millis() of 6295, then it was suddenly 6249.

This is similar to the post Bizarre behavior between ISR and loop() which is dealing with micros() instead, and was supposedly fixed in 0.6.0. I’m using 0.8.0-rc.11 on an Electron.

Any ideas? Given the super simple example above I don’t think I’m doing anything wrong.

2

If you are using variables that may be altered out-of-order you should always mark them volatile.

Also since the updating of millis() in itself is performed via a low priority interrupt that may contribute to the issue too. The millis() value is calculated as difference of the SYSTEM_TICKS counter via a timed interrupt - that’s also why millis() can’t be used inside ISRs the same way they can in “normal” code since the millis() counter will be frozen during execution of a GPIO ISR.
Using millis() inside your ISR may freeze the counter in a way that may result in a miscalculation on next timed ISR.
Hence using millis() in an ISR, even only for a millis() snapshot is not advisable.
And having high quantity of very rapid interrupts or longish running ISRs will throw off millis() quite condsiderably over time.

If you want to understand the millis() behaviour a bit more, you can have a look in the open source repo and its implementation there.

1 Like
3

My production code did have volatile, just missed it in the example. I've corrected the example above (and edited the post) and still the same problem shows up.

I also tried setting the lowest priority but that made no difference:

  attachInterrupt(D5, isr, RISING, 127, 255);

I gather firmware/platform/MCU/shared/STM32/src/hw_ticks.c is the correct file for the Electron? If so here's the relevant code:

void System1MsTick(void)
{
	int is = __get_PRIMASK();
	__disable_irq();

    ++system_millis;
    system_millis_clock = DWT->CYCCNT;

    if ((is & 1) == 0) {
        __enable_irq();
    }
}

system_tick_t GetSystem1MsTick()
{
    return GetSystem1MsTick64();
}

uint64_t GetSystem1MsTick64()
{
    uint64_t millis = 0;

    const int is = __get_PRIMASK();
    __disable_irq();

    millis = system_millis + (DWT->CYCCNT - system_millis_clock) / SYSTEM_US_TICKS / 1000;

    if ((is & 1) == 0) {
        __enable_irq();
    }

	return millis;
}

I can't see how that would go backwards unless DWT->CYCCNT did.

But theorectically shouldn't millis() be monotonic no matter what (well, until it overflows and loops around)? There's even a CHANGELOG.md comment as such:

  • millis()/micros() are now atomic to ensure monotonic values. Fixes #916, #925 and #1042

And a test: test(TICKS_03_millis_and_micros_monotonically_increases)

And practically what do other people do for debouncing. Everything I've seen uses millis(). Is there an alternative?

4

You can use SYSTEM_TICK_COUNTER which is definetly monotonic as it's the HW counter that runs independent of any code.
If you want to use it for determinsitic debounce periods across all Particle platfroms you may need to use it in conjunction with SYSTEM_US_TICKS with gives you the count of system ticks per µs.

So something like this should work.

const uint32_t tickDebounce = 50000 * SYSTEM_US_TICKS; // 50ms debounce periode

void ISR(void) {
  static uint32_t lastTick = 0;
  if (SYSTEM_TICK_COUNTER - lastTick < tickDebounce) return;
  lastTick = SYSTEM_TICK_COUNTER;
  // do whatever
}
2 Likes
5

Great. I can definitely take it from there. Thanks @ScruffR.

Should I file an issue on GitHub?

1 Like
6

You can always do. The worst that may happen is that it'll get closed without action taken - but at least a comment from the devs can be expected that way.

7

Thinking further about the Particle firmware code I’ve figured out the bug in it and posted this issue.

5 Likes