Hello Phillippe,
thanks for the instant reply.
Here is the output of your test code:
# while `true`
> do
> ./simple_test
> done
t_create(tid=54) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=54) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=57) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=57) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=60) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=60) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=63) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=63) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=66) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=66) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=69) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=69) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=72) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=72) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=75) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 0, ev=0x3
t_start(tid=75) = 0
t_create(tid=78) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=78) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=81) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=81) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=84) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=84) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=87) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=87) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=90) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=90) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=93) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=93) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=96) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=96) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=99) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=99) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=102) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=102) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=105) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=105) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=108) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=108) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=111) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=111) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=114) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=114) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=117) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 0, ev=0x3
t_start(tid=117) = 0
t_create(tid=120) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=120) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=123) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 0, ev=0x3
t_start(tid=123) = 0
t_create(tid=126) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=126) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=129) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=129) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=132) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=132) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=135) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=135) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
t_create(tid=138) = 0
Started... (1, 2, 3, 4)
tm_evevery(4, 3, &tmid) => 0
tm_cancel(&tmid) => 0
t_start(tid=138) = 0
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
As you can see, in some cases the event is received, even it the timeout
value is 4.
This is the same observation as I did in my code. I also see the event being
received with timeout values of 1 AND 2.
This is the testcode I have used. It is almost identical with the code you
have send me, I needed to change 2 things to make it work:
- "ret = ev_receive(4, EV_ANY|EV_WAIT, 10, &ev)" replaced by "ret =
ev_receive(3, EV_ANY|EV_WAIT, 10, &ev);"
- added a sleep at the end of main and foo to make the output printed on the
screen. If the sleep is not there, the last printf statement is not visible.
#include <stdio.h>
#include <unistd.h>
#include <sys/types.h>
#include <sys/mman.h>
#include <psos+/psos.h>
void foo (u_long a0, u_long a1, u_long a2, u_long a3)
{
u_long ret, ev = 0, tmid;
printf("Started... (%lu, %lu, %lu, %lu)\n", a0, a1, a2, a3);
ret = tm_evevery(4, 3, &tmid);
printf("tm_evevery(4, 3, &tmid) => %lu\n", ret);
ret = tm_cancel(tmid);
printf("tm_cancel(&tmid) => %lu\n", ret);
ret = ev_receive(3, EV_ANY|EV_WAIT, 10, &ev);
printf("ev_receive(3, EV_ANY|EV_WAIT, 10, &ev) => %lu, ev=0x%lx\n",
ret, ev);
tm_wkafter(100);
}
int main (int ac, char **av)
{
u_long ret, tid = 0, args[4];
mlockall(MCL_CURRENT | MCL_FUTURE);
ret = t_create("TEST", 1, 0, 0, 0, &tid);
printf("t_create(tid=%lu) = %lu\n", tid, ret);
args[0] = 1;
args[1] = 2;
args[2] = 3;
args[3] = 4;
ret = t_start(tid, 0, foo, args);
printf("t_start(tid=%lu) = %lu\n", tid, ret);
tm_wkafter(100);
return 0;
}
About the pending question: I indeed recieve error code 60 (ERR_NOEVS) in
case no event is pending.
Best regards,
Ronny
On Wed, Nov 17, 2010 at 3:01 PM, Philippe Gerum <[email protected]> wrote:
> On Wed, 2010-11-17 at 14:49 +0100, ronny meeus wrote:
> > Hello
> >
> > I did some more tests on QEMU since the behavior on Simics is
> > identical to the behavior I see on QEMU.
> > This is the testcode I have used:
> >
> > void test_timer_cancel(void)
> > {
> > unsigned long tmr_id,ev,ret,i;
> > unsigned long failed = 0;
> >
> > for (i=1;i<3;i++)
> > {
> > ret = tm_evevery(i,1,&tmr_id);
> > ut_printf("tm_evevery(%lu,1,&tmr_id) => %lu\n",
> > i,ret);
> >
> > ret = tm_cancel(tmr_id);
> > ut_printf("tm_cancel(&tmid) => %lu\n", ret);
> >
> > ev = 0;
> > ret = ev_receive(1, EV_ANY|EV_WAIT, 200, &ev);
> > ut_printf("ev_receive(1, EV_ANY|EV_WAIT, 10, &ev) => %
> > lu, ev=0x%lx\n", ret, ev);
> >
> > tm_wkafter(2);
> >
> > if (ret == 0)
> > failed++;
> > }
> > ut_printf("#events received after cancel %lu (loopcount=%lu)\n
> > \n",failed,i);
> > }
> >
> > void run_test(void)
> > {
> > test_timer_cancel();
> > }
> >
> > static void task_body_wrapper(unsigned long func,unsigned long
> > count,unsigned long smid,unsigned long d)
> > {
> > unsigned long i;
> > ut_printf("In task_body_wrapper\n");
> > test_function test = (test_function)func;
> > for (i=0;i<count;i++)
> > test();
> > sm_v(smid);
> > }
> >
> > static void task_wrapper(test_function f,unsigned long count)
> > {
> > unsigned long tid,smid;
> > unsigned long args[4] = {(unsigned long)f,count,0,0};
> >
> > sm_create("BLOC",0,SM_PRIOR,&smid);
> > args[2] = smid;
> >
> > t_create("TEST",25,16000,16000,0,&tid);
> > t_start(tid,0,task_body_wrapper,args);
> >
> > sm_p(smid,SM_WAIT,0);
> > sm_delete(smid);
> >
> > t_delete(tid);
> > }
> >
> > int main(int argc, char **argv)
> > {
> > unsigned long rnid,rsize,i;
> >
> > mlockall(MCL_CURRENT|MCL_FUTURE);
> > rt_print_auto_init(1);
> >
> > /* Body of the test goes here */
> > while (1)
> > {
> > task_wrapper(run_test,1);
> >
> > for (i=0;i<1;i++)
> > run_test();
> >
> > task_wrapper(run_test,1);
> > }
> > }
> >
> > (The ut_printf function is mapped on rt_printf.)
> > So this test is identical to the test you proposed.
>
> No, the reason I sent you this frag, is because we are currently
> assuming that no tick will happen between tm_evevery() and ev_receive(),
> which is wrong, at least in theory. So this small frag is actually
> reducing the complexity to the bare minimum, so that we don't chase wild
> gooses uselessly.
>
> The clock is not synchronized with your application in periodic mode, so
> you can't be sure that a pending tick won't hit the kernel - and thus
> deliver the event - prior to entering ev_receive(). The odds of being
> preempted by ev_send() on behalf of the tick handler before entering
> ev_receive() is even higher with a period set to one tick, like in your
> example, which is therefore wrong once again. Slowing down the code with
> trace output may introduce variations if timing is involved.
>
> Besides, you did not answer to the question regarding ERR_NOEVS, which
> might be useful to assess where the problem might be.
>
> > The function "test_timer_cancel" is called both from the context of
> > the main thread and a TEST thread.
> >
> > This is the output I get when running the test:
> >
> > In task_body_wrapper
> > tm_evevery(1,1,&tmr_id) => 0
> > tm_cancel(&tmid) => 0
> > ev_receive(1, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
> > tm_evevery(2,1,&tmr_id) => 0
> > tm_cancel(&tmid) => 0
> > ev_receive(1, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
> > #events received after cancel 0 (loopcount=3)
> >
> > tm_evevery(1,1,&tmr_id) => 0
> > tm_cancel(&tmid) => 0
> > ev_receive(1, EV_ANY|EV_WAIT, 10, &ev) => 0, ev=0x1
> > tm_evevery(2,1,&tmr_id) => 0
> > tm_cancel(&tmid) => 0
> > ev_receive(1, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
> > #events received after cancel 1 (loopcount=3)
> >
> > In task_body_wrapper
> > tm_evevery(1,1,&tmr_id) => 0
> > tm_cancel(&tmid) => 0
> > ev_receive(1, EV_ANY|EV_WAIT, 10, &ev) => 0, ev=0x1
> > tm_evevery(2,1,&tmr_id) => 0
> > tm_cancel(&tmid) => 0
> > ev_receive(1, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
> > #events received after cancel 1 (loopcount=3)
> >
> > In task_body_wrapper
> > tm_evevery(1,1,&tmr_id) => 0
> > tm_cancel(&tmid) => 0
> > ev_receive(1, EV_ANY|EV_WAIT, 10, &ev) => 1, ev=0x0
> > tm_evevery(2,1,&tmr_id) => 0
> > tm_cancel(&tmid) => 0
> >
> > As you can see in most of the cases the system behaves correctly.
> > In some cases, the event is received. This is the case both from the
> > context of the main thread and the special thread.
> > I just copy-pasted a part of the output. In most cases, the event is
> > not received. I think something like 1 times out of 50 I see the event
> > being received.
> >
> > It looks like, if it happens, it is always the first iteration of the
> > loop (the one with a timeout of 1 tick). Even if I change the initial
> > timeout value to 2, the event is also received sporadically.
> >
> > [ Phillippe, please note that in your test code, you have also swapped
> > the parameters. You send event 3 and lateron check whether you have
> > received event 4. :-) ]
> >
> > Another observation is that after removing the ut_printf statements, I
> > do not see the issue anymore.
> > It looks like the printf/rt_printf has an impact on the system
> > behavior.
> >
> > I had a quick look to the LTTng as well, but I need to fix the patches
> > before I will be able to integrate.
> > I think this will be my next step.
> >
> > Best regards,
> > Ronny
> >
> >
> > On Mon, Nov 15, 2010 at 10:30 AM, Philippe Gerum <[email protected]>
> > wrote:
> > On Sun, 2010-11-14 at 01:24 +0100, ronny meeus wrote:
> > > Hello
> > >
> > > I'm currently fighting with a problem in the pSOS+ skin.
> > > This my system information:
> > >
> > > [ 2.314676] pci 0000:00:01.0: Activating ISA DMA hang
> > workarounds
> > > [ 2.416025] I-pipe: Domain Xenomai registered.
> > > [ 2.418183] Xenomai: hal/i386 started.
> > > [ 2.422780] Xenomai: scheduling class idle registered.
> > > [ 2.424116] Xenomai: scheduling class rt registered.
> > > [ 2.566737] Xenomai: real-time nucleus v2.5.4 (Sleep
> > Walk) loaded.
> > > [ 2.590628] Xenomai: starting native API services.
> > > [ 2.604491] Xenomai: starting pSOS+ services.
> > > [ 2.619941] HugeTLB registered 4 MB page size,
> > pre-allocated 0
> > > pages
> > >
> > > This is a piece of testcode I have created:
> > >
> > > check("tm_evevery",tm_evevery(4,3,&tmr_id),0);
> > > check("tm_cancel",tm_cancel(tmr_id),0);
> > > ev_rcvd = 0;
> > > ret = ev_receive(4,EV_ANY|EV_WAIT,10,&ev_rcvd);
> > > check("ev_receive",ret,ERR_TIMEOUT);
> > >
> > > I just start a periodic timer that expires every 3 ticks and
> > at expiry
> > > sends event 4 to my task.
> >
> >
> > You test rather arms a timer for sending event_list=0x3 each 4
> > ticks.
> >
> > > I want to check the cancel of the timer, so I cancel it and
> > I would
> > > expect not to receive any event.
> > >
> > > What I observe is that this code is not working: I
> > immediately receive
> > > the event after starting the timer.
> >
> >
> > Please try this test code as well:
> >
> > #include <stdio.h>
> > #include <unistd.h>
> > #include <sys/types.h>
> > #include <sys/mman.h>
> > #include <psos+/psos.h>
> >
> > void foo (u_long a0, u_long a1, u_long a2, u_long a3)
> > {
> > u_long ret, ev = 0, tmid;
> >
> > printf("Started... (%lu, %lu, %lu, %lu)\n", a0, a1, a2,
> > a3);
> > ret = tm_evevery(4, 3, &tmid);
> > printf("tm_evevery(4, 3, &tmid) => %lu\n", ret);
> >
> > ret = tm_cancel(tmid);
> > printf("tm_cancel(&tmid) => %lu\n", ret);
> >
> > ret = ev_receive(4, EV_ANY|EV_WAIT, 10, &ev);
> > printf("ev_receive(4, EV_ANY|EV_WAIT, 10, &ev) => %lu,
> > ev=0x%lx\n", ret, ev);
> > }
> >
> > int main (int ac, char **av)
> > {
> > u_long ret, tid = 0, args[4];
> >
> > mlockall(MCL_CURRENT | MCL_FUTURE);
> >
> > ret = t_create("TEST", 1, 0, 0, 0, &tid);
> > printf("t_create(tid=%lu) = %lu\n", tid, ret);
> > args[0] = 1;
> > args[1] = 2;
> > args[2] = 3;
> > args[3] = 4;
> > ret = t_start(tid, 0, foo, args);
> > printf("t_start(tid=%lu) = %lu\n", tid, ret);
> >
> > return 0;
> > }
> >
> > > If I change the code like shown below (I added the
> > ev_receive with the
> > > NO_WAIT option after starting the timer), the code works
> > fine.
> > >
> > > check("tm_evevery",tm_evevery(4,3,&tmr_id),0);
> > > ret = ev_receive(4,EV_ANY|EV_NOWAIT,0,&ev_rcvd);
> >
> >
> > Do you receive ERR_NOEVS as expected here?
> >
> > > check("tm_cancel",tm_cancel(tmr_id),0);
> > > ev_rcvd = 0;
> > > ret = ev_receive(4,EV_ANY|EV_WAIT,10,&ev_rcvd);
> > > check("ev_receive",ret,ERR_TIMEOUT);
> > >
> >
> >
> > > Now my question is: how do I investigate an issue like this?
> > In other
> > > words, which are the best tools since this code involves
> > both user and
> > > kernel space debugging.
> > > Are there some trace tools available that are able to
> > generate a kind
> > > of sequence / trace of what is happing over time.
> > >
> > > I also have other issues that are not consistently
> > reproducible. For
> > > this kind of problems trace tools would also be useful.
> > >
> >
> >
> > If you want to validate the pSOS emulation core, the best tool
> > is the
> > simulator. Unfortunately, this tools still requires to be
> > built with an
> > antiquated C++ toolchain, so the only sane way to enable it
> > nowadays is
> > via qemu. You would need ~2 hours to set this up.
> >
> > If you want to try this, I can help. Otherwise, other
> > suggestions you
> > already got on this list will do.
> >
> > > Thanks
> > > Ronny
> > > _______________________________________________
> > > Xenomai-help mailing list
> > > [email protected]
> > > https://mail.gna.org/listinfo/xenomai-help
> >
> >
> > --
> > Philippe.
> >
> >
> >
>
> --
> Philippe.
>
>
>
_______________________________________________
Xenomai-help mailing list
[email protected]
https://mail.gna.org/listinfo/xenomai-help
