Atmega2560: xtimer doesn't work correctly

[PeterKietzmann]

The hwtimer tests don't work properly on the arduino-mega2560. The hwtimer_spin test seems to be fine. Running the hwtimer_wait test I never reach the end of the program. Running the hwtimer test I get the following output. The board seems to restart periodically.

INFO # kernel_init(): This is RIOT! (Version: 2014.05-3773-g1aae7-herthel_atmega_gpio)
INFO # kernel_init(): jumping into first task...
INFO # hwtimer test application...
INFO # 
INFO #   Timers should print "callback x" once when they run out.
INFO #   The order for x is 1, n-1, n-2, ..., 2 where n is the number of available hardware timers (3 on this platform).
INFO #   In 1 second, one timer should fire every second/100 until all timers have run out.
INFO #   Additionally the message "hwtimer set." should be printed once 1 second from now.
INFO # 
INFO # Setting timers:
INFO # 
INFO # set callback  1
INFO # set callback  2
INFO # 
INFO # All timers set.
INFO # 
INFO # callback  1
INFO # callback  2
INFO # callback  2
INFO # callback  1
INFO # callback  2
INFO # callback  2
INFO # callback  2
INFO # callback  2
INFO # callback  1
INFO # callback  2
INFO # callback  2
INFO # callback  2
INFO # callback  2
INFO # callback  1
INFO # callback  2
INFO # callback  2
INFO # callback  2
INFO # callback  1
INFO # callback  2
INFO # callback  2
INFO # callback  2
INFO # callback  2
INFO # callback  1
INFO # callback  2
INFO # callback  2
INFO # callback  2
INFO # callback  2
INFO # callback  1
INFO # callback  2
INFO # callback  2
INFO # callback  2
INFO # callback  2
INFO # callback  1
INFO # callback  2
INFO # callback  2
INFO # callback  2
INFO # callback  2
INFO # callback  1
INFO # callback  2
INFO # 

INFO # 

INFO # 

INFO # kernel_init(): This is RIOT! (Version: 2014.05-3773-g1aae7-herthel_atmega_gpio)
INFO # kernel_init(): jumping into first task...
INFO # 
INFO #   Timers should print "callback x" once when they run out.
INFO #   The order for x is 1, n-1, n-2, ..., 2 where n is the number of available hardware timers (3 on this platform).
INFO #   In 1 second,

INFO # kernel_init(): This is RIOT! (Version: 2014.05-3773-g1aae7-herthel_atmega_gpio)
INFO # kernel_init(): jumping into first task...
INFO # hwtimer test application...
INFO # 
INFO #   Timers should print "callback x" once when they run out.
INFO #   The order for x is 1, n-1, n-2, ..., 2 where n is the number of available hardware timers (3 on this platform).
INFO #   In 1 second,

And so on and so on ...

[PeterKietzmann]

Any ideas @N8Fear, @haukepetersen?

[kaspar030]

INFO # Setting timers:
INFO #
INFO # set callback 1
INFO # set callback 2
Shouldn't there be three?

INFO # callback 1
INFO # callback 2
INFO # callback 2
INFO # callback 1
AFAIR each callback should only trigger once. You could check if the
timer ISR disables the interrupt.

[PeterKietzmann]

Yes, I think there should be three (looking at the hwtimer_cpu.h). I currently don't have time to debug that, it was just a side effect. My hope was that someone else has a fix spontaneously :-) . If not I need to look at it hopefully soon

[raidoz]

It seems to me that the atmega2560 timer.c implementation is the problem. I'm having a hard time understanding what it is actually trying to do. It secretly redefines the timer_init us_per_tick as ticks_per_us and then does something I don't yet understand. It could simply use a prescaler to get the 1MHz rate(I think that is what is needed?). Is the timer supposed to run periodically or just once?

[PeterKietzmann]

Hi @raidoz, welcome and thanks for your message! I currently don't find time to go into details here. @kaspar030 does xtimer potentially solve the problem?

[PeterKietzmann]

Is xtimer working correctly on that board? @ReneHerthel?

[ReneHerthel]

@PeterKietzmann Testing results:

• tests/xtimer_hang: I'm not sure about this. It runs sometimes to ~150% of testing process and sometimes it stops at ~30%. And the test says: "If it stops before, the test failed." Someone knows more about this test? Not sure if its successful or not, when it stops sometimes at ~30% and sometimes at ~150%.
• tests/xtimer_msg: Seems to be working fine.
• tests/xtimer_remove: "Test successful."
• tests/xtimer_reset: "Test Completed!"
• tests/xtimer_usleep_until: "Test Complete"
• tests/xtimer_shift_on_compare: "Teste Complete."

[PeterKietzmann]

@kaspar030 any ideas about the outcome of tests/xtimer_hang?
@ReneHerthel what means " Seems to be working fine." ? Rene as a hint: It is always beneficial if you try to understand the happening and not just look at the latest printed serial line. Sorry if I wrong you...

[ReneHerthel]

@PeterKietzmann Thanks for the hint. Just want to say that I testet it and it works, no problem :)

[PeterKietzmann]

Everything went as expected, except tests/xtimer_hang? Or also that one, after your rebased (as you told me)?

[ReneHerthel]

@PeterKietzmann I'm sorry. So now it runs always til 62%. It runs many times and couldn't see anything other. Same behavior as bevor. Only the value changed.
The other tests still works fine.

[OlegHahm]

Any new insights here?

[haukepetersen]

Actually I am looking into, will let you know my findings...

[kaspar030]

@haukepetersen Last time I played with 2560 it seemed to me that there's a general problem with it's interrupt handling. xtimer on itself seemed to work fine (unless having too much isr pressure). Even threaded printf output would sometimes come garbled.

[OlegHahm]

I updated the PR title to match the current problem.

[haukepetersen]

@kaspar030: very likely. I re-implemented the UART and gpio driver so far, looking at the timer now. Also started to re-structure some of the code, so hopefully I will be able to find these issues when testing all my stuff in depth... My (playful) goal is to run RIOT (in some restricted way) on my old ATmega8 with 512 byte RAM...

[PeterKietzmann]

@ReneHerthel would you give it another try please?! Maybe it was fixed in the meantime. Otherwise could you borrow me your board please?

[kYc0o]

Maybe if you will test this you can take a look at #5083 ?

[PeterKietzmann]

@kYc0o can you check if #5254 fixes this issue? Rene does not respond and I don't have an atmega board.

[kYc0o]

I'm looking into it but I have problems with some tests. I'll report them asap.

[kYc0o]

I ran all xtimer tests on Arduino MEGA 2560, initialising the timer at 250000 ticks (prescaler at 16MHz/256)

xtimer_drift: hangs and reboots
xtimer_hang: looks OK but slow
xtimer_longterm: not checked
xtimer_msg: works but very bad results
xtimer_msg_received_timerout: OK but slow
xtimer_now64_continuity: OK
xtimer_remove: OK
xtimer_reset: very bad results
xtimer_shift_on_compare: OK
xtimer_usleep_until: OK

I would say that in general it works but it still need some work... I'm trying to do some improvements but takes time.

[haukepetersen]

Just a side issue: the bad results in some tests (e.g. xtimer_msg) are caused by the very slow UART... With 9600 baud, it is quite obvious, that the pyterm time stamps will look very ugly, as they are timed on incoming UART lines...

[kYc0o]

Yeah that was something I thought too, maybe when the reworked UART is ready we can redo the tests. So, we can say that xtimer works as expected? Please note too that for better results the initialisation ticks for xtimer were reduced significantly. It means that we will need to abstract such initialisation to make it dependent on the CPU clock configured for such board.

[haukepetersen]

Please note too that for better results the initialisation ticks for xtimer were reduced significantly. It means that we will need to abstract such initialisation to make it dependent on the CPU clock configured for such board.

I don't quite understand what you mean herre.

After all, at least the xtimer_drift test still hangs, so the xtimer on this platform is not working as it should. Though I say we will not get this fixed for this release, so I postpone this to the next one

[kYc0o]

I mean that the function timer_init(XTIMER, XTIMER_USEC_TO_TICKS(250000ul), _periph_timer_callback, NULL); is initialised at a lower speed (instead of 1000000) since at higher speeds almost all the test fail.

[haukepetersen]

hä, I still don't get it. The arduino-mega board defines XTIMER_SHIFT to -2, which divides the 1000000 by 4, leading to 250000. This is the case in the current master, already, and this is also how it is meant to work...

[kYc0o]

Shifting it by 4 should be enough, I'll do a PR after the release

[PeterKietzmann]

This is just a report of running the xtimer tests with current master

xtimer_drift: hangs and reboots
xtimer_hang: looks OK but is > 100% normal?

Testing... (195%)
Test successful.

xtimer_longterm: (with #5576) reboots after ~3min

2016-06-28 13:34:16,815 - INFO # main(): This is RIOT! (Version: 2014.12-6532-g8580f-kietzmann-Latitude-E6410-tests_xtimer_longterm_tickstousec)
2016-06-28 13:34:16,840 - INFO # xtimer long-term test
2016-06-28 13:34:16,905 - INFO # Refer to the README to get information on the expected output.
2016-06-28 13:34:16,938 - INFO # sleep -- 18min -- 0 ticks since
2016-06-28 13:34:16,971 - INFO # sleep -- 5min  -- 0 ticks since
2016-06-28 13:35:17,021 - INFO # TICK  -- 1min
2016-06-28 13:36:17,105 - INFO # TICK  -- 1min
2016-06-28 13:37:17,193 - INFO # TICK  -- 1min
2016-06-28 13:37:17,263 - INFO # msg   -- 3min  -- 3 ticks since
2016-06-28 13:37:18,241 - INFO # 
                                 �H�+���): This is RIOT! (Version: 2014.12-6532-g8580f-kietzmann-Latitude-E6410-tests_xtimer_longterm_tickstousec)

xtimer_msg: ok
xtimer_msg_receive_timeout: ok
xtimer_now64_continuity: ok
xtimer_remove: ok
xtimer_reset: ok
xtimer_shift_on_compare: ok
xtimer_usleep_until: gets stuck here

Testing interval 105... (now=6160452)

[kYc0o]

Let's wait for the several xtimer PRs that could improve and even solve this issue... For now changing the XTIMER_SHIFT to 4 gives more stability, but does not solve the problem.

[kYc0o]

Since there are several timer PRs to be reviewed and hopefully merged, I think it's reasonable to move this issue to the next release.

[kYc0o]

Just tested again all xtimer* on arduino-mega2560 with success. Perhaps #5763 fixed it.

[miri64]

@kYc0o "Fixed issue from last release" is for issues mentioned in 2016.07 release notes only ;-)

[kYc0o]

Oh, I thought I had put this on the known issues.