Potential bug in micros()? « LeafLabs Garden

LeafLabs Garden » Support » Maple Hardware Support

Potential bug in micros()?

(16 posts) (4 voices)

Started 3 years ago by palsor
Latest reply from palsor

12 Next »

palsor
Member

Hey guys,

A friend and I are working on a UAV using Maple Mini and we noticed something strange. It looks like every once in while, micros() takes a very long time to return. For example, if I just run the following code...

------------------------------------------------
unsigned long time = 0;

void setup() {
time = micros();
}

void loop() {
unsigned long curTime = micros();

if (curTime - time > 75000)
SerialUSB.println("1");

time = curTime;
}
------------------------------------------------

...then I see a 1 get printed out about once every 10 or 15 seconds. When this delay happens we've seen the delay be anywhere 75ms and 500ms.

Anyone have any thoughts or ideas of where to look? Has anyone else seen this? We would like to keep using micros() to get better resolution on our calculations than we would achieve using millis().

For reference, here is our system setup:
MapleIDE 0.0.12 (no updates made to libmaple since downloading libmaple)
Mac OS X 10.6.8
Writing code in Xcode, but compiling and loading code with MapleIDE

Does anyone have any guidance (or a pointer to a post) on how to update libmaple when using MapleIDE on Mac OSX? I searched but couldn't find anything.

- Andy

Posted 3 years ago #
gbulmer
Moderator

palsor - there was a bug in micros(), explained here:
http://forums.leaflabs.com/topic.php?id=1958#post-11383

So it might be worth checking that you have the fix.

But, I don't think that explains the effect you're seeing.

Posted 3 years ago #
higwoshy
Member
Uh? What is that code meant to do? Replacing the serial print with a togglePin(13) I get a randomly flashing light.

Did you mean this?
```
...

    if (curTime - time > 75000)
    {
        togglePin(13);      //SerialUSB.println("1");
        time = curTime;   // new bit
    }
...

}
```
Or is your code meant to be a test to show when micros() pauses? Cos I don't think your code does that, more like showing that when you exit the main loop (to loop round again), sometimes it takes longer than others to return. I might be getting the wrong end of the stick.

AHH! Ok, got it. Hmmm, try running off battery, as the usb functions can screw timings up. Certainly running your original code with usb connected causes random flashing - disconnecting usb causes a flash every so often as you mention. In fact I altered the code to 375000 and I got a toggle every 11.9 - 12.1 seconds (using a stopwatch, so it might be off by .2 seconds)

HOWEVER, changing the code to this to eliminate the maple-main-loop-code,
```
unsigned long time = 0;

void setup()
{
    time = micros();
    pinMode(13, OUTPUT);
}

void loop()
{

    unsigned long curTime;

    while(1)
    {
        curTime = micros();

        if (curTime - time > 375000)
        {
            togglePin(13);
        }

        time = curTime;
    }

}
```
I get a weird effect going on... toggling like mad for 3 seconds then a pause of 9 seconds. Hmmm. 9+3 = 12. A clue I think.

My head hurts, I'm going to lie down now...

30 seconds later ... It's probably caused when micros() overflows back to zero, causing curTime to be 0 ish and time being a very large number, which overflows again to produce a negative number, which shows up as positive number > 75000 because it's unsigned. Clear? Try changing 375000 to 11375000... And the reason usb causes random flashing? Usb is connected to an expensive Mac which is randomly sending out control signals. Well, not randomly, but you know what I mean.

I think you need to write a better test program :) to make sure it is micros() that is the problem and not something else. Try using an audio out. Scopes are nice as well.
Posted 3 years ago #
gbulmer
Moderator

higwoshy - micros() should overflow when an unsigned long overflows.

IIRC an unsigned long is 32bits, i.e. a maximum of a little over 4,000,000,000

When used to record microseconds, it should overflow every 4000 seconds, which is a tad more than an hour, not every 10 to 15 seconds.

I agree USB is plausibly a culprit.

Posted 3 years ago #
crenn
Moderator

I'll run your code tonight to see if I can replicate your results

I'd put a bracket around (curTime - time), it shouldn't affect it, but I can't remember some of the priorities in the maths (aka how logic fits into BODMAS)

Posted 3 years ago #
palsor
Member

@higwoshy ... Yes, the code I posted was just to demonstrate the problem I'm seeing. The only thing I'll say in addition to what you guys already posted is that if I switch from micros() to millis() and change the delay from 75000 to 75 (due to the change to millis()), then I don't see the problem anymore. That makes me think the problem has to do with micros() rather than the end-of-loop code from libmaple.

@higwoshy and gbulmer ... I'll try removing USB from the picture and see if that changes anything.

@gbulmer ... Thanks for the link above. I'll try adding in the fix to micros() and see if that changes anything, though I agree that it doesn't look like the bug in the thread you linked to would actually cause the effect I'm seeing. I'm might try playing with the while loop in micros() and see if that causes anything interesting to happen as well.

Thanks for the help guys.

Posted 3 years ago #
higwoshy
Member

@gblumber : Ah, I should have done the maths first, it was getting late here - I'm not fond of late night maths, even simple stuff. It seemed plausible at the time, a kind of harmonic race condition(?). Nevertheless (curtime-time) is definitely creating large numbers.

@crenn : The brackets did seem plausible, but it made no difference. Does the +1 to micros() internal reg happen in two parts? It's not possible to interrupt an addition instruction is it? That would create some obscure bugs if it did. :) I'm guessing the answer is no.

@palsor : Yep, I can confirm that changing micros() to millis() doesn't cause any instability.

P.S. I'm running this example in RAM - I know that is a source of some obscure bugs. Just tried it in flash memory and it's a lot more stable as in the USB doesn't effect it now, but it still "times out" every 12 seconds. How strange.

Anyway, I'll let the experts work it out, over to you guys.

Posted 3 years ago #
higwoshy
Member

UPDATE : It was the fix gbulmer pointed to : a systick overflow. Edit file /Developer/MapleIDE.app/Contents/Resources/Java/hardware/leaflabs/cores/maple/wirish_time.cpp and change the code accordingly (this is under OSX, but just look for your maple core and you'll find it).

Posted 3 years ago #
gbulmer
Moderator

higwoshy - That is very helpful of you to follow up for the OP.
That result is interesting. I think that implies that the system is so deterministic that the bug is repeatable. Impressive.

Posted 3 years ago #
palsor
Member

@higwoshy - Yes, thank you. Work has been all consuming this week so I haven't gotten a chance to try anything, but I'll definitiely try gbulmer's fix first.

Posted 3 years ago #
palsor
Member

Well bad news. Even with the fix gbulmer pointed too, and without USB, the problem doesn't seem to be have resolved itself. My friend and I did a pass at logging all of our sensors while driving around his neighborhood. Our loop time is normally between 5ms and 30ms depending on what happens. However, over the course of logging for 10 minutes, we saw 5 instances where our loop time jumped up to 450ms, and 38 instances where the loop time jumped up to 300ms. Interestingly, the instances of getting a 300ms loop occured on a pretty regular interval, with almost exactly 15 seconds between each instance. Any guesses as to what would cause that?

@crenn, did you have any luck reproducing this? If needed, I could send you our log file so you have some data to look at.

Posted 3 years ago #
gbulmer
Moderator

palsor - would you please post a minimal program that demonstrates the bug?

Is the delay of 300ms or 450ms a slow call of micros() or is it where currTime and time differ by a lot?

(Would you try (an irrational) thing just to set my mind at ease, and change the name of variable time to prevTime or something just to ensure their isn't a weird clash? The linker should notice, but it should be easy enough to change.)

When you say " Interestingly, the instances of getting a 300ms loop occured on a pretty regular interval, with almost exactly 15 seconds between each instance."
How close to 15 seconds is that repetition rate? Could it be closer to 16.8 seconds?

Edit: I should have said, 16.8 seconds could correspond to the cycle time of the underlying 24bit hardware SysTick timer, if it were counting at 1us. SysTick andmicros() should not be behave strangely at 16.8 seconds (IIRC it should be much faster), but I'm just trying to exclude possibilities.

Posted 3 years ago #
palsor
Member

Yeah, I'll try a few experiments and post back.

Posted 3 years ago #
crenn
Moderator

@crenn, did you have any luck reproducing this? If needed, I could send you our log file so you have some data to look at.

Unfortunately not, as it's approaching the end of my university semester, I've got a lot of work due this week. I'll most likely be looking into the issue either this weekend or next week.

If you're waiting for 300ms? Why not just use millis()?

Posted 3 years ago #
gbulmer
Moderator

crenn - AFAIK, they are not trying to wait for 300ms; the bug seems to give the effect that micros() sometimes takes 300ms to return, rather than a microsecond (or less). They don't want that effect.

Posted 3 years ago #

RSS feed for this topic

12 Next »

Reply »

You must log in to post.