Re: [Xenomai] [xenomai-forge] psos: crash while stressing event timers

[Philippe Gerum <rpm@xenomai.org>]

On 06/05/2013 11:51 AM, Tom Philips wrote:
> Philippe,
>
> I tried the asserts you suggested and here's the output:
>
> +++
> xenomai: timerobj.c:308: timerobj_start: Assertion
> `timer_getoverrun(tmobj->timer) >= 0' failed.
> Aborted (core dumped)
> +++
>
>
> So this means the call to timer_getoverrun() fails.
> Then I did some further investigation.
> I changed the code in timerobj_start() to this:
>
>
> +++
>    if (__RT(timer_settime(tmobj->timer, TIMER_ABSTIME, it, NULL))) {
>      int error = errno;
>      errno = 0;
>      if (timer_getoverrun(tmobj->timer) < 0) {
>        __bt(-errno);           => @ line 311
>      }
> /*  assert(timer_getoverrun(tmobj->timer) >= 0); */
>      assert(it->it_value.tv_sec >= 0 && it->it_value.tv_nsec < 1000000000);
>      assert(it->it_interval.tv_sec >= 0 && it->it_interval.tv_nsec <
> 1000000000);
>      return __bt(-error);      => @ line 316
>    }
> +++
>
>
> This gives following (strange) result:
> (The 'tm_evafter(x,y) returned' traces are from my test app)
>
>
> +++
> ------------------------------------------------------------------------------
> [ ERROR BACKTRACE: thread 0.0 ]
>
>     #0  EINVAL in timerobj_start(), timerobj.c:316
> => #1  EINVAL in timerobj_start(), timerobj.c:311
> ------------------------------------------------------------------------------
> tm_evafter(0,0) returned 75 (errno 22): tmid=3066037456
> ------------------------------------------------------------------------------
> [ ERROR BACKTRACE: thread 4.0 ]
>
> => #0  EINVAL in timerobj_start(), timerobj.c:316
> ------------------------------------------------------------------------------
> tm_evafter(4,0) returned 75 (errno 0): tmid=67192088
> ------------------------------------------------------------------------------
> [ ERROR BACKTRACE: thread 4.0 ]
>
>     #0  EINVAL in timerobj_start(), timerobj.c:316
> => #1  EINVAL in timerobj_start(), timerobj.c:311
> ------------------------------------------------------------------------------
> tm_evafter(4,0) returned 75 (errno 22): tmid=67191880
> +++
>
>
> So timer_getoverrun() fails and sets errno to EINVAL (22)
> This can only mean that the given timerid is (or has become) invalid.
>
> But timer_getoverrun() does not always fail when timer_settime() fails.
> My rough estimate is that 1 out of 20 times timer_getoverrun()
> does not fail when timer_settime() fails.
>
> Might it be that there is a race condition between the above code
> and the code excuted at timer elapse (i.e. were the timer is destroyed)?


Yes, I think there is some race in the Xenomai code, and running SMP 
makes it more likely. I just got the backtrace below:

#0  __timer_settime_new (timerid=0x0, flags=1, value=0x7f78b2102d60,
     ovalue=0x0) at ../nptl/sysdeps/unix/sysv/linux/timer_settime.c:58
#1  0x00007f78b229c2e0 in timerobj_start (tmobj=0x7f78440008f8,
     handler=0x7f78b24ca9c1 <post_event_once>, it=0x7f78b2102d60)
     at /home/rpm/git/xenomai-forge/lib/copperplate/timerobj.c:309
#2  0x00007f78b24cabf6 in start_evtimer (events=2, it=0x7f78b2102d60,
     tmid_r=0x7f78b2102db0) at /home/rpm/git/xenomai-forge/lib/psos/tm.c:133
#3  0x00007f78b24cac86 in tm_evafter (ticks=1, events=2,
     tmid_r=0x7f78b2102db0) at /home/rpm/git/xenomai-forge/lib/psos/tm.c:153
#4  0x0000000000400c64 in thread_timer (bidx=24, tidx=0) at settime.c:73
#5  0x000000000040101c in thread_receive (bidx=24, tidx=0) at settime.c:117
#6  0x00000000004013a6 in thread_entry (a1=24, a2=0, a3=0, a4=0)
     at settime.c:149
#7  0x00007f78b24c9835 in task_trampoline (arg=0x67efc80)
     at /home/rpm/git/xenomai-forge/lib/psos/task.c:200
#8  0x0000003d71c07d15 in start_thread (arg=0x7f78b2103700)
     at pthread_create.c:308
#9  0x0000003d714f248d in clone ()
     at ../sysdeps/unix/sysv/linux/x86_64/clone.S:114

The timerid is definitely broken in some cases.

-- 
Philippe.