sys/vtimer: Fix two vtimer issues (hwtimer tick conversion).

[lightblu]

I am using a K22 port based on the open K60/mulle port pull request (great work, thanks!)
A little blinking application that uses vtimer_usleep and toggles a LED every second fails to schedule the timer properly after ~1h09.

First I blamed the K60 port or my quick K22 port, but turns out the different timer overflows in vtimer are not handled properly.Maybe I am totally wrong as I have no complete understanding of everything going on there, but I found at least two occurences that do not look right:

in update_shortterm: HWTIMER_TICKS cannot be just applied to next, this will be wrong when next overflows.
in vtimer_now: wrong parentheses mix up vtimer and hwtimer ticks, goes wrong as soon as the first vtimer longterm tick happens and longterm_tick_start becomes nonzero.
Correcting these makes the system run nicely through the first vtimer longterm tick and the first 32bit us overflow, however a long running test (>6hours over night) resulted in a RIOT crash at some later point in time, rerunning this test currently.
Btw, I doubt that this will run through the hwtimer overflow nicely, but this would happen after 36 hours (for 32768 kHz).

I wonder how this could go unnoticed that long, does RIOT usually run with HWTIMER == 1MHz only (it is 32768 kHz here)?
As a newbie, are vtimers kind of optional and I should use something else?

This may also be related to #2435 and/or #1753, however timings (at least the first ticket) are different.

Commit message:
vtimer does not handle well the different timers (vtimer <-> hwtimer)
with regard to their overflows:

• in update_shortterm HWTIMER_TICKS cannot be just applied to next, this will be wrong when next overflows.
• in vtimer_now wrong parentheses mix up vtimer and hwtimer ticks.

Issue:

• vtimer: vtimer_usleep fails after the first longterm timer tick (different overflows not handled properly) #2514

Maybe related issues:

• vtimer_sleep fails after long uptime #2435
• vtimer: vtimer_msg test crashes after ~49'20" #1753

[jnohlgard]

I wonder how this could go unnoticed that long, does RIOT usually run with HWTIMER == 1MHz only (it is 32768 kHz here)?

I believe all platforms are running with hwtimer frequency == 1 MHz, except for Kinetis and MSP430, which is why we have not been seeing this before.

As a newbie, are vtimers kind of optional and I should use something else?

The general opinion is that the vtimer module have a lot of faults, and a new timer implementation is on the road map, but currently not started. A timer task force has been mentioned on the mailing lists, but I don't think there has been any work done there yet.
In short: The vtimer sucks, but we have not yet implemented an alternative.

[jnohlgard]

@lightblu Thank you for investigating this and creating this PR.

Could you try leaving your test running with a debugger connected so that you can get a backtrace from the crash?
GDB will break execution in the default hardfault handler if DEVELHELP is set. (see crash.c)

[jnohlgard]

Could you change this to static const uint32_t us_per_s = 1000ul * 1000ul; while you're poking around here?

[lightblu]

The mentioned RIOT crash maybe just has happened because I tried to reattach the debugger this morning after closing the laptop for the night.

My latest test run stopped after 7992 seconds and seems to be a different kind of error.

[kaspar030]

Thanks for debugging this!

Here's a wiki page collecting thoughts/ideas/facts on how to fix our timer issues once and for all:
https://github.com/RIOT-OS/RIOT/wiki/Timer-Task-Force

Please have a look and share your thoughts!

IMHO we should drop vtimer (and maybe hwtimer) and rewrite it.

[lightblu]

The controller scheduling failing at 7992/7993 was reproducible (and btw, I have not observed the mentioned RIOT crash again).
The reason was that the longterm_timer_tick microseconds had a different meaning / offset in the priority queue as the other timers. Device now ran successfully through second 7993, and also the second longterm_timer_tick at 8192 .. looks pretty good now from my side, but someone really needs to verify and maybe rethink the whole design as you mentioned.

If time permits I will put it somewhere to see what happens when the 32768 kHz timer overflows (>36h, but this would be a different story anyway).

[lightblu]

Device ran successful through the 32768 kHz 32bit hwtimer overflow 36 hour mark and the 1 second scheduling stayed accurate (as accurate as vtimers are).

[PeterKietzmann]

@lightblu, @kaspar030 is it reasonable to merge this PR for now even if the "timer task force" will rework some thins?

[kaspar030]

Sure, don't have time to review though...

[OlegHahm]

@kaspar030, ping?

[OlegHahm]

I haven't tested yet, but I would argue to merge this PR independent from the timer task force. Code looks good.

[jnohlgard]

This could be the problem I am seeing in #3131 as well.

[jnohlgard]

I ran this on a test yesterday and also got past the initial problem at one hour. But also got to the same error as @lightblu, there was a lock up at 7696 seconds wall clock time, 7567 hwtimer seconds. I wasn't looking when it happened so it could have been just a problem with the debugger too, I will run another test today and also see if I have the time to refactor the hwtimer driver for Kinetis because I believe the current implementation is losing too many ticks (129 second difference between the wall clock and the timer tick after only 2 hours is not acceptable IMO, almost 1 second per 60 seconds).

This PR fixes a major bug in the vtimer implementation and should be merged independently of the other timer work. The comment by @OlegHahm and me is not crucial, it is better to get this merged and have a working vtimer and do a follow up PR to remove the set_absolute call from vtimer.c.

ACK

[OlegHahm]

So, should be push the button?

[jnohlgard]

@OlegHahm you have my ACK

I will write a follow up PR for replacing set_absolute with a set(_relative) call.