Millis() running slow?


#1

Hi! I’m goofing around with a Particle Photon, an RGB light strip, and the FastLED library. One thing I noticed is that some animations that are based on a “bpm” seem super slow. For example, if I specify something to animate using a 60 “bpm” period, it actually animates much slower.

FastLED bases it’s bpm calculations off of the millis() function. So for debugging I added the following to my loop(): EVERY_N_SECONDS( 1 ) { Spark.publish("DEBUG", String(millis())); }

That’s generating logs like:

DEBUG	15001	February 2nd at 9:41:54 pm
DEBUG	14003	February 2nd at 9:41:50 pm
DEBUG	13008	February 2nd at 9:41:46 pm
DEBUG	12008	February 2nd at 9:41:42 pm
DEBUG	11005	February 2nd at 9:41:37 pm
DEBUG	10000	February 2nd at 9:41:33 pm
DEBUG	9000	February 2nd at 9:41:29 pm
DEBUG	8005	February 2nd at 9:41:25 pm
DEBUG	7002	February 2nd at 9:41:20 pm
DEBUG	6007	February 2nd at 9:41:16 pm

The “millisecond” values look great, about 1000 between each log as I’d expect. But, the timestamp on each one is about 4 or 5 seconds apart!

So, what the heck is going on here? My only guess is that FastLED is doing some magic that is causing the clock to run slow. But the docs for millis() don’t mention that anything like that is possible: it’s just milliseconds.


#2

I would say it has something to do with the time taken by Spark.publish(). Normally 1sec should be OK, but it depends on your internet connection, etc.
You can try the same code but removing the SPark.publish() and using serial.print(). Since serial have very minor delays, you can check on your computer if the code is actually executing as you expect.


#3

@Zor, you can also use the Photon’s Time class to stamp your samples “at the source” and publish that. Also, don’t forget that the publish function is in the user thread so it is subject to the speed of loop(). You can add a Particle.process() after the publish to help things along. As @Fabien points out, publish is not a “real-time” event though I wonder when the timestamp is added (I’ll poke @Dave for that).

[quote=“Zor, post:1, topic:19713”]
So, what the heck is going on here?
[/quote]Don’t confuse millis(), which appear to be correct, with publish() timestamp!


#4

Hey all!

Sorry about the slow reply, just catching up on emails. :slight_smile:

Great observation, yes you’re correct! The publish event message from the device actually doesn’t send the timestamp from the device at all. So the cloud stamps the event with the current timestamp the instant it’s received. So you might be observing the difference caused by connection latency, rate limiting, etc, etc.

The real time clock on your device is synced to the cloud’s clock, so if you used that, I imagine they’d be much closer minus some latency.

Thanks!
David


#5

Well, here’s my next trick. :slight_smile: I replaced the publish with the following:

Spark.publish("DEBUG", Time.timeStr() + " " + String(millis())); 

And here’s the output:

DEBUG 	Sat Feb 6 03:39:29 2016 19002	February 5th at 9:39:33 pm
DEBUG 	Sat Feb 6 03:39:25 2016 18003	February 5th at 9:39:29 pm
DEBUG 	Sat Feb 6 03:39:20 2016 17004	February 5th at 9:39:25 pm
DEBUG 	Sat Feb 6 03:39:16 2016 16005	February 5th at 9:39:20 pm
DEBUG 	Sat Feb 6 03:39:12 2016 15006	February 5th at 9:39:16 pm
DEBUG 	Sat Feb 6 03:39:08 2016 14006	February 5th at 9:39:12 pm
DEBUG 	Sat Feb 6 03:39:04 2016 13006	February 5th at 9:39:08 pm
DEBUG 	Sat Feb 6 03:38:59 2016 12008	February 5th at 9:39:04 pm
DEBUG 	Sat Feb 6 03:38:55 2016 11008	February 5th at 9:39:00 pm
DEBUG 	Sat Feb 6 03:38:51 2016 10008	February 5th at 9:38:55 pm
DEBUG 	Sat Feb 6 03:38:47 2016 9009 	February 5th at 9:38:51 pm
DEBUG 	Sat Feb 6 03:38:43 2016 8000 	February 5th at 9:38:47 pm
DEBUG 	Sat Feb 6 03:38:38 2016 7001 	February 5th at 9:38:43 pm
DEBUG 	Sat Feb 6 03:38:34 2016 6002 	February 5th at 9:38:39 pm

Yep, I dunno. Local time doesn’t match the server time, but they’re consistent at least. But local Photon time doesn’t match the output of millis()!

I put my code up at https://github.com/jjbott/LEDSandbox . It’s mainly the FastLED library and their DemoReal ino with some changes I’ve made while screwing around. It’s a mess right now, but nothing crazy.

For what it’s worth, the following simple code works just fine:

void setup() {
}

void loop() {
    Spark.publish("DEBUG", Time.timeStr() + " " + String(millis())); 
    delay(1000);
}

Oh, I’m not using Serial.print() only because I’m using an external 5v power supply to power the Photon, so connecting usb with it’s extra 5v supply makes me nervous. Maybe for no good reason, but there you have it. :slight_smile:


#6

Here’s a thought - does changing the length of the LED strip make a difference in the amount of time seemingly lost? I wonder if disabled interrupts are resulting in the whack timekeeping you’re seeing. Then again, FastLED seems like it’s better in this regard than the Neopixel library I’m using:

On these platforms, FastLED will briefly re-enable interrupts between each pixel, to allow handlers to run.
(from https://github.com/FastLED/FastLED/wiki/Interrupt-problems)

4 or 5 seconds is a LOT of time to lose, though, so I’m skeptical, but it’s an easy enough thing to test to set the array size to 1 or something and see if it still happens.


#7

I’ve think I’ve got it. Or, well, I’ve got it narrowed down

Its obvious that millis() is not tied to the real time clock, or they’d both be delayed. Any delay is probably caused by FastLED magic.As suggested, I tried minimizing the amount of work that FastLED is doing to compare. With it only driving 1 LED, everything looked great. I switched back to 300 LEDs but set a super low “fps”, but that still caused the 4-5 second delay, which seemed weird.

Basically it seemed that something was running FastLED’s “show()” function (which sends data to the LEDs) way more often than I’d expect. Even with never explicitly calling “show()” I was getting LED changes, and millis delays. Well, long story short, I found this guy, which is used in my loop (only because it was in the example project):

void CFastLED::delay(unsigned long ms) {
	unsigned long start = ::millis();
	while((::millis()-start) < ms) {
#ifndef FASTLED_ACCURATE_CLOCK
		// make sure to allow at least one ms to pass to ensure the clock moves
		// forward
		::delay(1);
#endif
		show();
	}
}

First, it seems that FASTLED_ACCURATE_CLOCK is not defined, so it’s solely using “show()” to kill time . If enough time has passed, it returns. But it’s using “millis()” to determine time, and it’s something in “show()” that is preventing millis from incrementing! Obviously that’s going to cause it to delay much longer than it expects. No idea why it’s using a busy loop in the first place, or why it’d call “show” over and over. It’s not like anything can update the LED states while we’re in this loop.

If I take the “show()” out of that code and only call “show()” in my own loop, the impact to millis is much less. It’s still not perfect, with each 1000 “millis” taking about 1.5 real seconds. But it’s a start…

I’m wondering what the long term fix is. Obviously the CFastLED::delay probably shouldn’t be used at all. But going further, I wonder if it’s possible to “repair the damage” done to millis() (or probably micros()) by adding in lost time. Or from the firmware side if it’s possible to tie micros and millis more closely to the Photon’s real time clock, so they’re harder to break?


#8

Also, based on tests, the following comments are false - found in the Particle firmware’s ineterrupts.cpp file. I couldnt get millis and micros out of sync with each other.

// millis() will not increment while interrupts are disabled.
// micros() does increment

#9

According to the FastLED docs I linked you to, show() disables interrupts, which in turn means a SysTick timer interrupt is potentially dropped if interrupts are disabled for > 1ms. On the other hand, the docs also claim that interrupts are re-enabled between each pixel, so it remains to be confirmed whether that’s really happening or not.

Looking at the FastLED library in your code, I see two things of interest:

  1. It seems to be playing with the value of DWT->CYCCNT for timekeeping purposes. This is also used by the Photon’s time functions, so there may be some bad interactions happening.
  2. It looks like interrupt enabling is disabled for STM32 devices for whatever reason, which may be a bug in the library, so you might want to change that and retry to see if you recover more time.

#10

@Zor, the statements in the docs ARE misleading. WITHIN an ISR, millis() will not change while micros() will. Hence, you could do a micros() delay in an ISR but not a millis() one. :wink:


#11

@Zor - I realize it’s almost 2 years later, but did you ever figure this out? I’m finding the same weirdness with the “bpm” routing on FastLED, running much slower than it should (vs. on my Arduino which ran at the expected speed).

As a test, I tried using the millis() function to see how long my BPM code was executing, by printing millis() at the start and end of my BPM routine, and got very strange results. Here’s the code, which I’m calling from within loop() using EVERY_N_MILLIS_I from FastLED:

void pulse() {
  Serial.println("----------");
  printTime();
  uint8_t BeatsPerMinute = 62;
  CRGBPalette16 palette = PartyColors_p;
  uint8_t beat = beatsin8( BeatsPerMinute, 64, 255);
  for( int i = startPixel; i <= endPixel; i++) {
    leds[channel][i] = ColorFromPalette(palette, gHue+(i*2), beat-gHue+(i*10));
  }
  FastLED.show();
  printTime();
}

void printTime() {
  Serial.println(millis());
}

And here are the results when I use a 10ms cycle. You’ll see that the start numbers and end numbers are indeed 10ms apart from each other, but I don’t understand how it jumps from 16k to 52k then back again each cycle? It’s running slowly but not 30+ seconds between pulses. :smile:


#12

Hello @rac_atx! I sort of figured some stuff out ages ago, although I’m not sure I remember all of the details.

At some point I switched from using FastLED to using https://github.com/technobly/Particle-NeoPixel . FastLED was messing with DWT->CYCCNT, which screwed up everything, so I gave up and used something else.

I also implemented my own version of micros() and millis() which can be found here along with some other clock related utility functions. The firmware version of millis() lost time due to interrupts, so I made my own. I swear that there was talk of making the firmware versions work fine regardless of interrupts, but I’m not sure if that ever happened. There are almost definitely bugs in my code, especially in rollover cases, but it worked well enough for me.

My full project is at https://github.com/jjbott/UnderCabinetLights . The original “under cabinet” version had hardware issues, and I eventually lost interest. It got resurrected a few months back and was used as fancy Christmas lights,and it even worked. :slight_smile: