vtimer_msg crashes after some time - unless there is a delay between msg_receive(&m); and accessing m #1811

benpicco · 2014-10-13T21:23:02Z

Now this one had me puzzled for quite a bit.
On ek-tm4c123gxl tests/vtimer_msg crashes after ~53s - that is, just to make debugging even more confusing, shortly after the hardware timer overflows for the first time.
It also crashes on native after 10s, but I know that native isn't quite as stable, so I disregarded that.

Now when adding a short delay after msg_receive(&m); in timer_thread, the crash goes away:

--- vtimer_msg/main.c   2014-10-10 20:23:59.876720869 +0200
+++ vtimer_msg/main.c   2014-10-13 23:14:48.024480356 +0200
@@ -26,6 +26,8 @@
 #include "thread.h"
 #include "msg.h"

+#include "board.h"
+
 char timer_stack[KERNEL_CONF_STACKSIZE_MAIN];
 char timer_stack_local[KERNEL_CONF_STACKSIZE_MAIN];

@@ -55,6 +57,11 @@
     while (1) {
         msg_t m;
         msg_receive(&m);
+
+        for (int i = 0; i < 10000; ++i) 
+          GREEN_LED_TOGGLE;
+
+//        puts("message received");
         struct timer_msg *tmsg = (struct timer_msg *) m.content.ptr;
         vtimer_now(&now);
         printf("now=%" PRIu32 ":%" PRIu32 " -> every %" PRIu32 ".%" PRIu32 "s: %s\n",

The text was updated successfully, but these errors were encountered:

N8Fear · 2014-10-13T21:55:21Z

As stated on IRC: I've got a similar issue on the mega2560 - so either similar code (I think of you, hwtimer_arch.c) or something more general...
My impression from trying to debug it is that the mutex doesn't really work the way it should (something like a race condition).

benpicco · 2014-10-14T11:40:33Z

Some debugging with turning LEDs on and off suggests the crash happens in _msg_receive at tcb_t *me = (tcb_t*) sched_threads[sched_active_pid];
What does that mean? And why does it work if this assignment is delayed?

Kijewski · 2014-10-14T11:43:31Z

sched_threads[sched_active_pid] is nonsense anyways.
Can you please try again with *me = (tcb_t*) sched_active_thread?

benpicco · 2014-10-14T12:04:42Z

Hm, that just moves the place where the fault happens around, looks like I've got some memory corruption going on

2014-10-14 14:04:12,869 - INFO # _msg_receive(): timer local: No msg in queue. Going blocked.
2014-10-14 14:04:13,379 - INFO # Hard fault happened in thread 1
2014-10-14 14:04:13,385 - INFO #    pid | name                 | state    Q | pri | location
2014-10-14 14:04:13,390 - INFO #      1 | idle                 | running  Q |  15 | 0x200000ec
2014-10-14 14:04:13,395 - INFO #      2 | main                 | bl mutex _ |   7 | 0x200001ec
2014-10-14 14:04:13,400 - INFO #    8192 | timer                | bl rx    _ |   6 | 0x20000c78
2014-10-14 14:04:13,405 - INFO #      4 | timer local          | bl rx    _ |   6 | 0x20001878

OlegHahm · 2014-10-27T11:39:51Z

Try to build with DEVELHELP and put a thread_print_all() into the hard fault handler.

LudwigKnuepfer · 2014-10-27T14:52:00Z

native does not crash on my laptop (Intel(R) Core(TM)2 Duo CPU L9400 @ 1.86GHz).

LudwigKnuepfer · 2014-10-27T15:11:01Z

@N8Fear @benpicco can you retry with

diff --git a/core/hwtimer.c b/core/hwtimer.c
index e878ffb..92f634a 100644
--- a/core/hwtimer.c
+++ b/core/hwtimer.c
@@ -148,16 +148,12 @@ static int _hwtimer_set(unsigned long offset, void (*callback)(void*), void *ptr
 {
     DEBUG("_hwtimer_set: offset=%lu callback=%p ptr=%p absolute=%d\n", offset, callback, ptr, absolute);

-    if (!inISR()) {
-        dINT();
-    }
+    unsigned state = disableIRQ();

     int n = lifo_get(lifo);

     if (n == -1) {
-        if (!inISR()) {
-            eINT();
-        }
+        restoreIRQ(state);

         puts("No hwtimer left.");
         return -1;
@@ -177,9 +173,7 @@ static int _hwtimer_set(unsigned long offset, void (*callback)(void*), void *ptr

     lpm_prevent_sleep++;

-    if (!inISR()) {
-        eINT();
-    }
+    restoreIRQ(state);

     return n;
 }

benpicco · 2014-10-27T15:37:36Z

native does not crash on my laptop (Intel(R) Core(TM)2 Duo CPU L9400 @ 1.86GHz).

I've just checked out the latest master branch, I get

RIOT native interrupts/signals initialized.
LED_GREEN_OFF
LED_RED_ON
RIOT native board initialized.
RIOT native hardware initialization complete.

kernel_init(): This is RIOT! (Version: 2014.05-1140-gb7fc)
kernel_init(): jumping into first task...
This is thread 3
sending 1st msg
now=0:323 -> every 2.0s: Hello World
timer_thread: set timer successfully
sending 2nd msg
now=0:353 -> every 5.0s: This is a Test
timer_thread: set timer successfully
This is thread 4
sec=1 min=0 hour=0
now=2:481 -> every 2.0s: Hello World
timer_thread: set timer successfully
now=2:522 -> every 5.0s: This is a Test
timer_thread: set timer successfully
sec=2 min=0 hour=0
sec=3 min=0 hour=0
now=4:671 -> every 5.0s: This is a Test
timer_thread: set timer successfully
now=4:715 -> every 5.0s: This is a Test
timer_thread: set timer successfully
sec=4 min=0 hour=0
sec=5 min=0 hour=0
sec=6 min=0 hour=0
sec=7 min=0 hour=0
sec=8 min=0 hour=0

then it hangs.

If I add usleep(1000); between msg_receive(&m); and struct timer_msg *tmsg = (struct timer_msg *) m.content.ptr; it keeps going till sec=12, but the 'Hello World' thread seems to have died in the process:

RIOT native interrupts/signals initialized.
LED_GREEN_OFF
LED_RED_ON
RIOT native board initialized.
RIOT native hardware initialization complete.

kernel_init(): This is RIOT! (Version: 2014.05-1140-gb7fc)
kernel_init(): jumping into first task...
This is thread 3
sending 1st msg
now=0:1313 -> every 2.0s: Hello World
timer_thread: set timer successfully
sending 2nd msg
now=0:2432 -> every 5.0s: This is a Test
timer_thread: set timer successfully
This is thread 4
sec=1 min=0 hour=0
now=2:2453 -> every 2.0s: Hello World
timer_thread: set timer successfully
sec=2 min=0 hour=0
sec=3 min=0 hour=0
now=4:3718 -> every 2.0s: Hello World
timer_thread: set timer successfully
now=4:4885 -> every 5.0s: This is a Test
timer_thread: set timer successfully
sec=4 min=0 hour=0
sec=5 min=0 hour=0
now=6:4872 -> every 2.0s: Hello World
timer_thread: set timer successfully
sec=6 min=0 hour=0
sec=7 min=0 hour=0
now=8:6170 -> every 5.0s: This is a Test
timer_thread: set timer successfully
now=8:7364 -> every 5.0s: This is a Test
timer_thread: set timer successfully
sec=8 min=0 hour=0
sec=9 min=0 hour=0
sec=10 min=0 hour=0
sec=11 min=0 hour=0
sec=12 min=0 hour=0

Intel(R) Core(TM) i5-4430 CPU @ 3.00GHz if that matters, gcc (Ubuntu 4.8.2-19ubuntu1) 4.8.2

LudwigKnuepfer · 2014-10-27T17:13:20Z

@N8Fear @benpicco can you retry with
...

@kaspar030 just opened a PR for that: #1883

N8Fear · 2014-10-27T19:22:31Z

now=52:7325 -> every 2.0s: Hello World
timer_thread: set timer successfully
now=52:7412 -> every 5.0s: This is a Test
timer_thread: set timer successfully
sec=52 min=0 hour=0
sec=53 min=0 hour=0
now=54:7608 -> every 2.0s: Hello World
timer_thread: set timer successfully
now=54:7655 -> every 5.0s: This is a Test
timer_thread: set timer successfully
sec=54 min=0 hour=0
sec=55 min=0 hour=0
now=56:7780 -> every 2.0s: Hello World
timer_thread: set timer successfully
now=56:7826 -> every 5.0s: This is a Test
timer_thread: set timer successfully

Just tested with #1883 on native - both timers run on ~2 sec. Haven't got my hardware at hand so I can't test on the mega2560 right now.

Edit: Note that this seems to be the same for current master on my laptop as well (with a single "Hello World" every ~18 sek).

OlegHahm · 2014-10-27T22:04:28Z

Weird, I'm not even able to reproduce #547 (comment) It's not crashing, but the output is wrong anyway.

kernel_init(): jumping into first task...
This is thread 2
sending 1st msg
now=0:138 -> every 2.0s: Hello World
timer_thread: set timer successfully
sending 2nd msg
now=0:154 -> every 5.0s: This is a Test
timer_thread: set timer successfully
This is thread 3
sec=1 min=0 hour=0
now=2:218 -> every 2.0s: Hello World
timer_thread: set timer successfully
sec=2 min=0 hour=0
sec=3 min=0 hour=0
now=4:285 -> every 2.0s: Hello World
timer_thread: set timer successfully
sec=4 min=0 hour=0
now=5:200 -> every 5.0s: This is a Test
timer_thread: set timer successfully
sec=5 min=0 hour=0
now=6:316 -> every 2.0s: Hello World
timer_thread: set timer successfully
sec=6 min=0 hour=0
sec=7 min=0 hour=0
now=8:424 -> every 2.0s: Hello World
timer_thread: set timer successfully
now=8:447 -> every 5.0s: This is a Test
timer_thread: set timer successfully

Update: The output varies and it is crashing from time to time.

LudwigKnuepfer · 2014-10-28T07:59:41Z

On my desktop computer (Intel(R) Core(TM) i5-3470 CPU @ 3.20GHz, same software setup) I can achieve crashes in native as well, sadly not when running with Valgrind though.

LudwigKnuepfer · 2014-10-28T08:03:14Z

And: #1883 does not change this.

N8Fear · 2014-10-28T08:08:30Z

From my tries at debugging this (or something similar) on the mega2560 I guess it's the mutex in core/hwtimer.c's hwtimer_wait(...) function that somehow gets corrupted/raced/whatevered...

LudwigKnuepfer · 2014-10-28T08:16:29Z

Changing core/msg.c irq API usage (#1887) does not help either.

OlegHahm · 2014-10-28T09:06:28Z

Funny thing: in current master it misbehaves and crashes on my desktop, but runs correctly on my laptop...

miri64 · 2015-03-30T13:59:16Z

Is this issue fixed by now?

benpicco · 2015-03-30T16:24:09Z

It's still broken on native - although in a different way now:

kernel_init(): This is RIOT! (Version: 2014.12-875-gdbd44)
kernel_init(): jumping into first task...
This is thread 3
sending 1st msg
now=0:116 -> every 2.0s: Hello World <-- this is a lie
sending 2nd msg
now=0:127 -> every 5.0s: This is a Test <-- this is a lie
This is thread 4
sec=1 min=0 hour=0
sec=2 min=0 hour=0
sec=3 min=0 hour=0
sec=4 min=0 hour=0
sec=5 min=0 hour=0
sec=6 min=0 hour=0
sec=7 min=0 hour=0
sec=8 min=0 hour=0
sec=9 min=0 hour=0
sec=10 min=0 hour=0

janoskut · 2015-04-01T19:03:09Z

Please note that the timer_thread in the main has changed, so that messages don't get re-sent. If you add
vtimer_set_msg(&tmsg->timer, tmsg->interval, thread_getpid(), MSG_TIMER, tmsg);
to the end of the while loop, the faulty behaviour will be restored. (Hang after 21 seconds on my machine, which is Intel(R) Core(TM)2 Duo CPU E6750 @ 2.66GHz and Ubuntu 14.04.2 LTS).

kaspar030 · 2015-11-28T22:55:41Z

I just checked native, it doesn't crash anymore. Also, as vtimer got kicked out, this is now using vtimer_compat and thus xtimer. So I'll close this as solved.

benpicco added the Type: bug The issue reports a bug / The PR fixes a bug (including spelling errors) label Oct 13, 2014

OlegHahm assigned N8Fear Oct 13, 2014

LudwigKnuepfer changed the title ~~vtimer_test crashes after some time - unless there is a delay between msg_receive(&m); and accessing m~~ vtimer_msg crashes after some time - unless there is a delay between msg_receive(&m); and accessing m Oct 27, 2014

OlegHahm mentioned this issue Oct 28, 2014

test: hwtimer_wait fails on native #715

Closed

OlegHahm assigned kaspar030 and unassigned N8Fear Apr 9, 2015

N8Fear mentioned this issue Jun 11, 2015

Atmega2560: shell and/or UART_RX dosn't work correctly? #3187

Closed

miri64 mentioned this issue Jul 4, 2015

ng_icmpv6_echo: fix unexpected parameter problem #3311

Merged

kaspar030 closed this as completed Nov 28, 2015

miri64 mentioned this issue Jan 26, 2019

gnrc: crash with (excessive) traffic in native #6123

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

vtimer_msg crashes after some time - unless there is a delay between msg_receive(&m); and accessing m #1811

vtimer_msg crashes after some time - unless there is a delay between msg_receive(&m); and accessing m #1811

benpicco commented Oct 13, 2014

N8Fear commented Oct 13, 2014

benpicco commented Oct 14, 2014

Kijewski commented Oct 14, 2014

benpicco commented Oct 14, 2014

OlegHahm commented Oct 27, 2014

LudwigKnuepfer commented Oct 27, 2014

LudwigKnuepfer commented Oct 27, 2014

benpicco commented Oct 27, 2014

LudwigKnuepfer commented Oct 27, 2014

N8Fear commented Oct 27, 2014

OlegHahm commented Oct 27, 2014

LudwigKnuepfer commented Oct 28, 2014

LudwigKnuepfer commented Oct 28, 2014

N8Fear commented Oct 28, 2014

LudwigKnuepfer commented Oct 28, 2014

OlegHahm commented Oct 28, 2014

miri64 commented Mar 30, 2015

benpicco commented Mar 30, 2015

janoskut commented Apr 1, 2015

kaspar030 commented Nov 28, 2015

vtimer_msg crashes after some time - unless there is a delay between msg_receive(&m); and accessing m #1811

vtimer_msg crashes after some time - unless there is a delay between msg_receive(&m); and accessing m #1811

Comments

benpicco commented Oct 13, 2014

N8Fear commented Oct 13, 2014

benpicco commented Oct 14, 2014

Kijewski commented Oct 14, 2014

benpicco commented Oct 14, 2014

OlegHahm commented Oct 27, 2014

LudwigKnuepfer commented Oct 27, 2014

LudwigKnuepfer commented Oct 27, 2014

benpicco commented Oct 27, 2014

LudwigKnuepfer commented Oct 27, 2014

N8Fear commented Oct 27, 2014

OlegHahm commented Oct 27, 2014

LudwigKnuepfer commented Oct 28, 2014

LudwigKnuepfer commented Oct 28, 2014

N8Fear commented Oct 28, 2014

LudwigKnuepfer commented Oct 28, 2014

OlegHahm commented Oct 28, 2014

miri64 commented Mar 30, 2015

benpicco commented Mar 30, 2015

janoskut commented Apr 1, 2015

kaspar030 commented Nov 28, 2015