[Xenomai-help] rt_queue_write strange behaviour ++

[Xenomai-help] rt_queue_write strange behaviour ++

[Roderik.Wildenburg]

Sorry, but in my last mail (see below) I had forgotten to tell you my 
Xenomai-Version and architecture.
I still use Xenomai 2.3.2 on PPC.

In the meantime I had a deeper look into the Xenomai source code 
and I would say, the case we observed (msg->refcount == 0 ; see below)
isn´t possible with rt_queue_write, as this function implicitly allocate 
its messagebuffer and rt_queue_alloc initilaizes refcount to 1.
Immediatelly after this rt_queue_send is called, where the 
plausibility test if( msg->refcount == 0) is done and fails. 
So, I can´t see a gap where refcount falls back to 0.

Does any guru have a good idea, I am quite clueless.

Original mail :
--------------------------------------------------------------------

Sometimes we get an EINVAL-Error with rt_queue_write.
If we immediatelly after the EINVAL-Error try an a second time to write
to the queue (with exactly the same parameters as at the first time) the
rt_queue_write succeeds (see appended code sniped) !!??

I traced down (xnprintf) the error to the function rt_queue_send where a
plausibility test is made :

if (xnheap_check_block(&q->bufpool, msg) || msg->refcount == 0) 
[approx at line 614]

this test fail as (msg->refcount == 0).
If I understand the comment correctly :

/* In case of invalid block or if the sender does not own the
   message, just bail out. */

the sender does not own the message.
But if so, the second try should fail also (and I am quite sure the
message belongs to the sender) ?
Does anyone (probabliy Philipe) has an idea in what situation this
problem could occur or what is the reason for this strange behaviour ?

Unfortunately I could not reproduce this problem in a simple testcase, 
but with our application the error occurs regularly (~10 times a hour).
So I rely on your intuition to spike this problem.

Many thanks in advance and best regards
Roderik 

MAN Roland Druckmaschinen AG
Vorsitzender des Aufsichtsrates: Hanno C. Fiedler
Vorstand: Gerd Finkbeiner (Vorsitzender), Dr. Ingo Koch, Dr. Markus Rall, Paul Steidle    
Sitz der Gesellschaft: Offenbach am Main, Registergericht: Amtsgericht Offenbach HRB-Nr. 42592    
USt-Ident-Nr. DE 250200933

Re: [Xenomai-help] rt_queue_write strange behaviour ++

[Philippe Gerum]

[-- Attachment #1: Type: text/plain, Size: 748 bytes --]

Roderik.Wildenburg@domain.hid wrote:
> Sorry, but in my last mail (see below) I had forgotten to tell you my 
> Xenomai-Version and architecture.
> I still use Xenomai 2.3.2 on PPC.
> 
> In the meantime I had a deeper look into the Xenomai source code 
> and I would say, the case we observed (msg->refcount == 0 ; see below)
> isn´t possible with rt_queue_write, as this function implicitly allocate 
> its messagebuffer and rt_queue_alloc initilaizes refcount to 1.
> Immediatelly after this rt_queue_send is called, where the 
> plausibility test if( msg->refcount == 0) is done and fails. 
> So, I can´t see a gap where refcount falls back to 0.

Does the attached patch trigger any message when your app fails?

-- 
Philippe.

[-- Attachment #2: heap-check-block-trace.patch --]
[-- Type: text/x-patch, Size: 849 bytes --]

Index: ksrc/nucleus/heap.c
===================================================================
--- ksrc/nucleus/heap.c	(revision 3224)
+++ ksrc/nucleus/heap.c	(working copy)
@@ -911,8 +911,10 @@
 			break;
 	}
 
-	if (!holder)
+	if (!holder) {
+		printk(KERN_DEBUG "XNHEAP: no extent found: block=%p\n", block);
 		goto bad_block;
+	}
 
 	/* Compute the heading page number in the page map. */
 	pagenum = ((caddr_t) block - extent->membase) >> heap->pageshift;
@@ -922,9 +924,11 @@
 	ptype = extent->pagemap[pagenum].type;
 
 	if (ptype == XNHEAP_PFREE ||	/* Unallocated page? */
-	    ptype == XNHEAP_PCONT)	/* Not a range heading page? */
+	    ptype == XNHEAP_PCONT) {	/* Not a range heading page? */
+		printk(KERN_DEBUG "XNHEAP: bad page type: 0x%x\n", ptype);
   bad_block: 
 		err = -EINVAL;
+	}
 
 	xnlock_put_irqrestore(&heap->lock, s);
 

Re: [Xenomai-help] rt_queue_write strange behaviour ++

[Roderik.Wildenburg]

Thank you for your patch !


I allready had a debug output in the function rt_queue_send :

if ((err2=xnheap_check_block(&q->bufpool, msg)) || msg->refcount == 0) {
   /* In case of invalid block or if the sender does not own the message, just bail out. */
    xnprintf("---- xnheap_check_block failed => EINVAL (err=%d refcount=%d----\n",err2,msg->refcount);
    err = -EINVAL;
    goto unlock_and_exit;
} 

I think this nearly does the same as your patch. It produces an output if xnheap_check_block() fails.
Unfortunatelly if there is an output err2 is allways 0 but msg->refcount is zero. So I think refcount is the problem. 
Excerpt from /var/log/messages :

# tail /var/log/messages
Nov 30 14:01:46 (none) user.info kernel: Xenomai: ---- xnheap_check_block failed => EINVAL (err=0 refcount=0----
Nov 30 14:01:46 (none) user.info kernel: Xenomai: ---- xnheap_check_block failed => EINVAL (err=0 refcount=0----
Nov 30 14:01:54 (none) user.info kernel: Xenomai: ---- xnheap_check_block failed => EINVAL (err=0 refcount=0----
Nov 30 14:01:56 (none) user.info kernel: Xenomai: ---- xnheap_check_block failed => EINVAL (err=0 refcount=0----
Nov 30 14:01:58 (none) user.info kernel: Xenomai: ---- xnheap_check_block failed => EINVAL (err=0 refcount=0----
Nov 30 14:02:02 (none) user.info kernel: Xenomai: ---- xnheap_check_block failed => EINVAL (err=0 refcount=0----


Nevertheless I applied your patch. Unfortunatelly I will get testing time only at monday again.
So please keep patient and enjoy the weekend.

Best regards
Roderik




> -----Ursprüngliche Nachricht-----
> Von: Philippe Gerum [mailto:philippe.gerum@domain.hid] Im 
> Auftrag von Philippe Gerum
> Gesendet: Freitag, 30. November 2007 11:55
> An: Wildenburg, Roderik RAEK3 MRA
> Cc: xenomai@xenomai.org
> Betreff: Re: [Xenomai-help] rt_queue_write strange behaviour ++
> 
> Roderik.Wildenburg@domain.hid wrote:
> > Sorry, but in my last mail (see below) I had forgotten to 
> tell you my 
> > Xenomai-Version and architecture.
> > I still use Xenomai 2.3.2 on PPC.
> > 
> > In the meantime I had a deeper look into the Xenomai source code 
> > and I would say, the case we observed (msg->refcount == 0 ; 
> see below)
> > isn´t possible with rt_queue_write, as this function 
> implicitly allocate 
> > its messagebuffer and rt_queue_alloc initilaizes refcount to 1.
> > Immediatelly after this rt_queue_send is called, where the 
> > plausibility test if( msg->refcount == 0) is done and fails. 
> > So, I can´t see a gap where refcount falls back to 0.
> 
> Does the attached patch trigger any message when your app fails?
> 
> -- 
> Philippe.
> 

MAN Roland Druckmaschinen AG
Vorsitzender des Aufsichtsrates: Hanno C. Fiedler
Vorstand: Gerd Finkbeiner (Vorsitzender), Dr. Ingo Koch, Dr. Markus Rall, Paul Steidle    
Sitz der Gesellschaft: Offenbach am Main, Registergericht: Amtsgericht Offenbach HRB-Nr. 42592    
USt-Ident-Nr. DE 250200933

Re: [Xenomai-help] rt_queue_write strange behaviour ++

[Roderik.Wildenburg]

> Does the attached patch trigger any message when your app fails?

Unforunatelly not (there is no message in /var/log/messages (see below)).
(see also my mail from 30.11. 13:27)

I still can´t see, were refcount can get zero when rt_queue_write is used.
Whatever problem occurs, refcount should stay one, as set by rt_queue_alloc.
Can you imagine a scenario where refcount gets 0 ? If so, please tell me, so I can
build a test case around it.

Many thanks for your help from a very helpless
Roderik


fer1_764_4080605:~ # tail /var/log/messages
Dec  3 15:15:11 (none) user.info kernel: Xenomai: ---- xnheap_check_block failed => EINVAL (err=0 refcount=0----
Dec  3 15:15:11 (none) user.info kernel: Xenomai: ---- xnheap_check_block failed => EINVAL (err=0 refcount=0----
Dec  3 15:15:11 (none) user.info kernel: Xenomai: ---- xnheap_check_block failed => EINVAL (err=0 refcount=0----
Dec  3 15:15:13 (none) user.info kernel: Xenomai: ---- xnheap_check_block failed => EINVAL (err=0 refcount=0----
Dec  3 15:15:16 (none) user.info kernel: Xenomai: ---- xnheap_check_block failed => EINVAL (err=0 refcount=0----
Dec  3 15:15:20 (none) user.info kernel: Xenomai: ---- xnheap_check_block failed => EINVAL (err=0 refcount=0----

> -----Ursprüngliche Nachricht-----
> Von: Philippe Gerum [mailto:philippe.gerum@domain.hid] Im 
> Auftrag von Philippe Gerum
> Gesendet: Freitag, 30. November 2007 11:55
> An: Wildenburg, Roderik RAEK3 MRA
> Cc: xenomai@xenomai.org
> Betreff: Re: [Xenomai-help] rt_queue_write strange behaviour ++
> 
> Roderik.Wildenburg@domain.hid wrote:
> > Sorry, but in my last mail (see below) I had forgotten to 
> tell you my 
> > Xenomai-Version and architecture.
> > I still use Xenomai 2.3.2 on PPC.
> > 
> > In the meantime I had a deeper look into the Xenomai source code 
> > and I would say, the case we observed (msg->refcount == 0 ; 
> see below)
> > isn´t possible with rt_queue_write, as this function 
> implicitly allocate 
> > its messagebuffer and rt_queue_alloc initilaizes refcount to 1.
> > Immediatelly after this rt_queue_send is called, where the 
> > plausibility test if( msg->refcount == 0) is done and fails. 
> > So, I can´t see a gap where refcount falls back to 0.
> 
> Does the attached patch trigger any message when your app fails?
> 
> -- 
> Philippe.
> 

MAN Roland Druckmaschinen AG
Vorsitzender des Aufsichtsrates: Hanno C. Fiedler
Vorstand: Gerd Finkbeiner (Vorsitzender), Dr. Ingo Koch, Dr. Markus Rall, Paul Steidle    
Sitz der Gesellschaft: Offenbach am Main, Registergericht: Amtsgericht Offenbach HRB-Nr. 42592    
USt-Ident-Nr. DE 250200933

Re: [Xenomai-help] rt_queue_write strange behaviour ++ testcase !!

[Roderik.Wildenburg]

[-- Attachment #1: Type: text/plain, Size: 4132 bytes --]

After I realized that the error depends on TM_NONBLOCK in the queue reading task (rt_queue_read(&qtest1q, &buf, sizeof (buf), TM_NONBLOCK)), I finaly succeded in generating a simple testcase !

On my target (PPC 400MHZ) the appended programm produces an EINVAL error with rt_queue_write nearly immediately and the second rt_queue_write succeeds nearly allways.

So, could you/Philippe try this testcase on your target and tell me whether you face the same problem.

Thanks a lot for yor help
Roderik
 

> -----Ursprüngliche Nachricht-----
> Von: xenomai-help-bounces@domain.hid
> [mailto:xenomai-help-bounces@domain.hid] Im Auftrag von 
> Roderik.Wildenburg@domain.hid
> Gesendet: Montag, 3. Dezember 2007 14:31
> An: rpm@xenomai.org
> Cc: xenomai@xenomai.org
> Betreff: Re: [Xenomai-help] rt_queue_write strange behaviour ++
> 
> > Does the attached patch trigger any message when your app fails?
> 
> Unforunatelly not (there is no message in /var/log/messages 
> (see below)).
> (see also my mail from 30.11. 13:27)
> 
> I still can´t see, were refcount can get zero when 
> rt_queue_write is used.
> Whatever problem occurs, refcount should stay one, as set by 
> rt_queue_alloc.
> Can you imagine a scenario where refcount gets 0 ? If so, 
> please tell me, so I can
> build a test case around it.
> 
> Many thanks for your help from a very helpless
> Roderik
> 
> 
> fer1_764_4080605:~ # tail /var/log/messages
> Dec  3 15:15:11 (none) user.info kernel: Xenomai: ---- 
> xnheap_check_block failed => EINVAL (err=0 refcount=0----
> Dec  3 15:15:11 (none) user.info kernel: Xenomai: ---- 
> xnheap_check_block failed => EINVAL (err=0 refcount=0----
> Dec  3 15:15:11 (none) user.info kernel: Xenomai: ---- 
> xnheap_check_block failed => EINVAL (err=0 refcount=0----
> Dec  3 15:15:13 (none) user.info kernel: Xenomai: ---- 
> xnheap_check_block failed => EINVAL (err=0 refcount=0----
> Dec  3 15:15:16 (none) user.info kernel: Xenomai: ---- 
> xnheap_check_block failed => EINVAL (err=0 refcount=0----
> Dec  3 15:15:20 (none) user.info kernel: Xenomai: ---- 
> xnheap_check_block failed => EINVAL (err=0 refcount=0----
> 
> > -----Ursprüngliche Nachricht-----
> > Von: Philippe Gerum [mailto:philippe.gerum@domain.hid] Im 
> > Auftrag von Philippe Gerum
> > Gesendet: Freitag, 30. November 2007 11:55
> > An: Wildenburg, Roderik RAEK3 MRA
> > Cc: xenomai@xenomai.org
> > Betreff: Re: [Xenomai-help] rt_queue_write strange behaviour ++
> > 
> > Roderik.Wildenburg@domain.hid wrote:
> > > Sorry, but in my last mail (see below) I had forgotten to 
> > tell you my 
> > > Xenomai-Version and architecture.
> > > I still use Xenomai 2.3.2 on PPC.
> > > 
> > > In the meantime I had a deeper look into the Xenomai source code 
> > > and I would say, the case we observed (msg->refcount == 0 ; 
> > see below)
> > > isn´t possible with rt_queue_write, as this function 
> > implicitly allocate 
> > > its messagebuffer and rt_queue_alloc initilaizes refcount to 1.
> > > Immediatelly after this rt_queue_send is called, where the 
> > > plausibility test if( msg->refcount == 0) is done and fails. 
> > > So, I can´t see a gap where refcount falls back to 0.
> > 
> > Does the attached patch trigger any message when your app fails?
> > 
> > -- 
> > Philippe.
> > 
> 
> MAN Roland Druckmaschinen AG
> Vorsitzender des Aufsichtsrates: Hanno C. Fiedler
> Vorstand: Gerd Finkbeiner (Vorsitzender), Dr. Ingo Koch, Dr. 
> Markus Rall, Paul Steidle    
> Sitz der Gesellschaft: Offenbach am Main, Registergericht: 
> Amtsgericht Offenbach HRB-Nr. 42592    
> USt-Ident-Nr. DE 250200933
> 
> _______________________________________________
> Xenomai-help mailing list
> Xenomai-help@domain.hid
> https://mail.gna.org/listinfo/xenomai-help
> 

MAN Roland Druckmaschinen AG
Vorsitzender des Aufsichtsrates: Hanno C. Fiedler
Vorstand: Gerd Finkbeiner (Vorsitzender), Dr. Ingo Koch, Dr. Markus Rall, Paul Steidle    
Sitz der Gesellschaft: Offenbach am Main, Registergericht: Amtsgericht Offenbach HRB-Nr. 42592    
USt-Ident-Nr. DE 250200933

[-- Attachment #2: qtest.c --]
[-- Type: application/octet-stream, Size: 4004 bytes --]

#include <stdio.h>
#include <assert.h>
#include <sys/types.h>
#include <sys/ipc.h>
#include <sys/shm.h>
#include <sys/socket.h>
#include <netinet/in.h>
#include <arpa/inet.h>
#include <sys/un.h>
#include <errno.h>
#include <stdlib.h>
#include <stddef.h>
#include <stdarg.h>
#include <sys/ioctl.h>
#include <sys/mman.h>
#include <unistd.h>
#include <time.h>
#include <errno.h>
#include <unistd.h>
#include <signal.h>
#include <pthread.h>

#include <native/task.h>
#include <native/queue.h>

#define einval

#ifdef einval      
   #define  MAXLEN   1830  /* größer maximale Nachrichtenlänge */
   #define  MAXWAIT  100000 
   #define  MINWAIT  100000 
#endif

#ifdef enomem   
   #define  MAXLEN   1024  /* größer maximale Nachrichtenlänge */
#endif
#define CONTROLLER_WAIT1 150000000
#define CONTROLLER_WAIT2 15000000
#define CONTROLLER_WAIT3 12300000


RT_QUEUE qtest1q;
RT_TASK qtest1, qtest2, qtest3;


void qtestrt(void)
{
   ssize_t len;
   static char buf[MAXLEN];
   long twait;

   for (;;)
   {
#ifdef enomem      
      if ((len = rt_queue_read(&qtest1q, &buf, sizeof (buf), TM_INFINITE)) < 0)
      {
         printf("qtest1t: rt_queue_read failed with %d\n",len);
         perror("perror qtest1t: rt_queue_read");
         errno = -len, perror("perror2 qtest1t: rt_queue_read");
      }
#endif      
#ifdef einval      
      rt_queue_read(&qtest1q, &buf, sizeof (buf), TM_NONBLOCK);
      twait= (long) ((float)((float)rand()/(float)RAND_MAX) * (float)MAXWAIT + (float)MINWAIT );
      rt_task_sleep(twait);
#endif      
   }
    
}

void qtestwt(void* par)
{
   int ret, len;
   RT_QUEUE_INFO qinfo;
   char buf[MAXLEN];
   int zuf;
   long twait;

   twait=(int)par;
   printf("qtestwt start ! %ld\n",twait);
   for (;;)
   {
      zuf=rand();
#ifdef einval      
      len=MAXLEN;
      twait=zuf>>5;
#else      
      len= (int) ((float)((float)zuf/(float)RAND_MAX) * (float)(MAXLEN-10) + 2.0 );
#endif      
      //printf("WriteQueue %d %d\n",len,zuf);
      if ((ret = rt_queue_write(&qtest1q, &buf, len , Q_NORMAL)) < 0)
      {
         errno = -ret, perror("qtestwt: rt_queue_write error");
         printf("Message size :%d return : %d\n",len, ret);
         if( (ret=rt_queue_inquire(&qtest1q,&qinfo))<0)
         {
            printf("queue_inquire : %d\n",ret);
         }
         else
         {
            printf("---- %s NMsg:%d Size:%d used:%d\n",qinfo.name, qinfo.nmessages,qinfo.poolsize,qinfo.usedmem);
         }
         printf("2. trial \n");
         if ((ret = rt_queue_write(&qtest1q, &buf, len , Q_NORMAL)) < 0)
            printf("failed\n");
         else
            printf("OK\n");
      }
      rt_task_sleep(twait);
   }
}
    

int startqtest(void)
{
   int err;
   int twait;

   srand (time (0));
   
   if(!rt_queue_bind(&qtest1q,"qtest1q",TM_NONBLOCK))
      rt_queue_delete(&qtest1q);
   if( (err = rt_queue_create(&qtest1q, "qtest1q", MAXLEN*10, Q_UNLIMITED, Q_FIFO)) != 0 )
      printf("q_create qtest1q failed with %d\n",err);

   err = rt_task_create(&qtest1, "qtest1t", 0, 50, 0);   /* Read */
   if (!err)
      rt_task_start(&qtest1, (void(*)(void *))qtestrt, NULL);

   err = rt_task_create(&qtest2, "qtestw2t", 0, 30, 0);   /* Write */
#ifdef enomem   
   twait=CONTROLLER_WAIT1;
#endif
#ifdef einval   
   twait=CONTROLLER_WAIT2;
#endif   
   if (!err)
      rt_task_start(&qtest2, (void(*)(void *))qtestwt, (void*)twait);
   
#ifdef einval
   err = rt_task_create(&qtest3, "qtestw3t", 0, 30, 0);   /* Write */
   if (!err)
      rt_task_start(&qtest3, (void(*)(void *))qtestwt, (void*)CONTROLLER_WAIT3);
#endif
   
   return(0);


}


int main (int ac, char *av[])

{
    sigset_t mask;
    int sig;

    printf("qtest start !\n");
    sleep(2);

    sigemptyset(&mask);
    sigaddset(&mask,SIGINT);
    sigaddset(&mask,SIGTERM);
    sigaddset(&mask,SIGHUP);
    sigaddset(&mask,SIGALRM);

    pthread_sigmask(SIG_BLOCK, &mask, NULL);

    mlockall(MCL_CURRENT|MCL_FUTURE);

    startqtest();


    sigwait(&mask, &sig);

    return 0;
}

Re: [Xenomai-help] rt_queue_write strange behaviour ++ testcase !!

[Philippe Gerum]

Roderik.Wildenburg@domain.hid wrote:
> After I realized that the error depends on TM_NONBLOCK in the queue reading task (rt_queue_read(&qtest1q, &buf, sizeof (buf), TM_NONBLOCK)), I finaly succeded in generating a simple testcase !
> 
> On my target (PPC 400MHZ) the appended programm produces an EINVAL error with rt_queue_write nearly immediately and the second rt_queue_write succeeds nearly allways.
> 
> So, could you/Philippe try this testcase on your target and tell me whether you face the same problem.
>

Do you have this patch in?

--- ksrc/skins/native/syscall.c	(revision 3195)
+++ ksrc/skins/native/syscall.c	(revision 3196)
@@ -2468,10 +2468,10 @@

 		if (size > 0)
 			__xn_copy_to_user(curr, buf, mbuf, size);
+
+		rt_queue_free(q, mbuf);
 	}

-	rt_queue_free(q, mbuf);
-
 	return (int)rsize;
 }

-- 
Philippe.

Re: [Xenomai-help] rt_queue_write strange behaviour ++ testcase !!

[Roderik.Wildenburg]

Hello Philippe,

> 
> Do you have this patch in?
> 

no I hadn´t (still using 2.3.2), but with this patch queues work like I expected.
So, thanks a lot ! 
I hope, you will not hear anything about queues from me for the next year ;-)

Best regards
Roderik 

MAN Roland Druckmaschinen AG
Vorsitzender des Aufsichtsrates: Hanno C. Fiedler
Vorstand: Gerd Finkbeiner (Vorsitzender), Dr. Ingo Koch, Dr. Markus Rall, Paul Steidle    
Sitz der Gesellschaft: Offenbach am Main, Registergericht: Amtsgericht Offenbach HRB-Nr. 42592    
USt-Ident-Nr. DE 250200933