[Xenomai-help] mq_send takes longer than expected

[Xenomai-help] mq_send takes longer than expected

[Steve]

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

Hi,

Calling mq_send takes significantly varied amounts of time depending
on the queue length.  I was not expecting this behaviour, particularly
as this does not happen when using RTAI mq_send calls.  I can
understand that queue creation / opening times will heavily depend on
the queue's overall size, however I would have thought that sending a
message (adding it to the queue's data structure (linked list?)) would
take a constant time.

Is this a bug, or expected behaviour?  I have attached an example.

I am running:
Linux 2.6.29.4
Adeos 2.6.29.4-x86-2.4-01
Xenomai 2.4.8

Let me know if you need any more info,

Steve

[-- Attachment #2: MessageQueueTest.cpp --]
[-- Type: text/x-c++src, Size: 4423 bytes --]

#include "rtdk.h"
#include "posix/posix.h"

#define RTIME unsigned long long
#define NANO_PER_SEC 1000000000

const int MAX_Q_LEN_LARGE = 10000;
const int MAX_Q_LEN_MED = 1000;
const int MAX_Q_LEN_SMALL = 100;
const int MAX_MSG_SIZE = 8;
const int MAX_Q_NAME_LEN = 12;

int main()
{
   mlockall(MCL_CURRENT | MCL_FUTURE);
   rt_print_auto_init(1);

   // The timing variables
   struct timespec* Pause = new struct timespec;
   struct timespec* StartS = new struct timespec;
   struct timespec* StartM = new struct timespec;
   struct timespec* StartL = new struct timespec;
   struct timespec* EndS = new struct timespec;
   struct timespec* EndM = new struct timespec;
   struct timespec* EndL = new struct timespec;
   RTIME DurationL = 0;
   RTIME DurationM = 0;
   RTIME DurationS = 0;

   // Create and open the two queues
   mqd_t MsgQL; // Large
   mqd_t MsgQM; // Medium
   mqd_t MsgQS; // Small
   const char pMsg[MAX_MSG_SIZE] = "aaaaaaa";
   const char pMsgQNameL[MAX_Q_NAME_LEN] = "/MsgQLarge";
   const char pMsgQNameM[MAX_Q_NAME_LEN] = "/MsgQMedium";
   const char pMsgQNameS[MAX_Q_NAME_LEN] = "/MsgQSmall";
   struct mq_attr* pMsgQAttrL = new mq_attr;
   struct mq_attr* pMsgQAttrM = new mq_attr;
   struct mq_attr* pMsgQAttrS = new mq_attr;
   pMsgQAttrL->mq_flags = O_NONBLOCK;
   pMsgQAttrL->mq_maxmsg = MAX_Q_LEN_LARGE;
   pMsgQAttrL->mq_msgsize = MAX_MSG_SIZE;
   pMsgQAttrM->mq_flags = O_NONBLOCK;
   pMsgQAttrM->mq_maxmsg = MAX_Q_LEN_LARGE;
   pMsgQAttrM->mq_msgsize = MAX_MSG_SIZE;
   pMsgQAttrS->mq_flags = O_NONBLOCK;
   pMsgQAttrS->mq_maxmsg = MAX_Q_LEN_SMALL;
   pMsgQAttrS->mq_msgsize = MAX_MSG_SIZE;

   clock_gettime(CLOCK_MONOTONIC, StartL);
   MsgQL = mq_open(pMsgQNameL, O_RDWR | O_CREAT | O_EXCL, 0777, pMsgQAttrL);
   if(MsgQL == (mqd_t) -1 && errno == EEXIST)
   {
      mq_unlink(pMsgQNameL);
      MsgQL = mq_open(pMsgQNameL, O_RDWR | O_CREAT | O_EXCL, 0777, pMsgQAttrL);
   }
   clock_gettime(CLOCK_MONOTONIC, EndL);

   clock_gettime(CLOCK_MONOTONIC, StartM);
   MsgQM = mq_open(pMsgQNameM, O_RDWR | O_CREAT | O_EXCL, 0777, pMsgQAttrM);
   if(MsgQM == (mqd_t) -1 && errno == EEXIST)
   {
      mq_unlink(pMsgQNameM);
      MsgQM = mq_open(pMsgQNameM, O_RDWR | O_CREAT | O_EXCL, 0777, pMsgQAttrM);
   }
   clock_gettime(CLOCK_MONOTONIC, EndM);

   clock_gettime(CLOCK_MONOTONIC, StartS);
   MsgQS = mq_open(pMsgQNameS, O_RDWR | O_CREAT | O_EXCL, 0777, pMsgQAttrS);
   if(MsgQS == (mqd_t) -1 && errno == EEXIST)
   {
      mq_unlink(pMsgQNameS);
      MsgQL = mq_open(pMsgQNameS, O_RDWR | O_CREAT | O_EXCL, 0777, pMsgQAttrS);
   }
   clock_gettime(CLOCK_MONOTONIC, EndS);

   DurationS = (EndS->tv_sec - StartS->tv_sec) * NANO_PER_SEC + EndS->tv_nsec - StartS->tv_nsec;
   DurationM = (EndM->tv_sec - StartM->tv_sec) * NANO_PER_SEC + EndM->tv_nsec - StartM->tv_nsec;
   DurationL = (EndL->tv_sec - StartL->tv_sec) * NANO_PER_SEC + EndL->tv_nsec - StartL->tv_nsec;

   rt_printf("Small Q Creation Duration  %llu\n", DurationS);
   rt_printf("Medium Q Creation Duration %llu\n", DurationM);
   rt_printf("Large Q Creation Duration  %llu\n", DurationL);

   // Send the message to each queue

   clock_gettime(CLOCK_MONOTONIC, StartS);
   mq_send(MsgQS, pMsg, MAX_MSG_SIZE, 0);
   clock_gettime(CLOCK_MONOTONIC, EndS);

   clock_gettime(CLOCK_MONOTONIC, StartM);
   mq_send(MsgQM, pMsg, MAX_MSG_SIZE, 0);
   clock_gettime(CLOCK_MONOTONIC, EndM);

   clock_gettime(CLOCK_MONOTONIC, StartL);
   mq_send(MsgQL, pMsg, MAX_MSG_SIZE, 0);
   clock_gettime(CLOCK_MONOTONIC, EndL);

   DurationS = (EndS->tv_sec - StartS->tv_sec) * NANO_PER_SEC + EndS->tv_nsec - StartS->tv_nsec;
   DurationM = (EndM->tv_sec - StartM->tv_sec) * NANO_PER_SEC + EndM->tv_nsec - StartM->tv_nsec;
   DurationL = (EndL->tv_sec - StartL->tv_sec) * NANO_PER_SEC + EndL->tv_nsec - StartL->tv_nsec;

   rt_printf("Small Q Send Duration  %llu\n", DurationS);
   rt_printf("Medium Q Send Duration %llu\n", DurationM);
   rt_printf("Large Q Send Duration  %llu\n", DurationL);

   // Pause to allow printing

   Pause->tv_sec = 5;
   Pause->tv_nsec = 0;
   nanosleep(Pause, NULL);

   // Clean up

   mq_close(MsgQL);
   mq_close(MsgQM);
   mq_close(MsgQS);
   mq_unlink(pMsgQNameL);
   mq_unlink(pMsgQNameM);
   mq_unlink(pMsgQNameS);

   delete pMsgQAttrS;
   delete pMsgQAttrM;
   delete pMsgQAttrL;
   delete StartS;
   delete StartM;
   delete StartL;
   delete EndS;
   delete EndM;
   delete EndL;
   delete Pause;
}

Re: [Xenomai-help] mq_send takes longer than expected

[Gilles Chanteperdrix]

Steve wrote:
> Hi,
> 
> Calling mq_send takes significantly varied amounts of time depending
> on the queue length.  I was not expecting this behaviour, particularly
> as this does not happen when using RTAI mq_send calls.  I can
> understand that queue creation / opening times will heavily depend on
> the queue's overall size, however I would have thought that sending a
> message (adding it to the queue's data structure (linked list?)) would
> take a constant time.
> 
> Is this a bug, or expected behaviour?  I have attached an example.

mq_send is expected by the posix specification to block its caller when
the queue is full. If you do not want this behaviour, you should pass
O_NONBLOCK to mq_open and be prepared for mq_send to return -1 with
errno set to EAGAIN/EWOULDBLOCK.

Would this be your problem ?

-- 
                                          Gilles

Re: [Xenomai-help] mq_send takes longer than expected

[Gilles Chanteperdrix]

Gilles Chanteperdrix wrote:
> Steve wrote:
>> Hi,
>>
>> Calling mq_send takes significantly varied amounts of time depending
>> on the queue length.  I was not expecting this behaviour, particularly
>> as this does not happen when using RTAI mq_send calls.  I can
>> understand that queue creation / opening times will heavily depend on
>> the queue's overall size, however I would have thought that sending a
>> message (adding it to the queue's data structure (linked list?)) would
>> take a constant time.
>>
>> Is this a bug, or expected behaviour?  I have attached an example.
> 
> mq_send is expected by the posix specification to block its caller when
> the queue is full. If you do not want this behaviour, you should pass
> O_NONBLOCK to mq_open and be prepared for mq_send to return -1 with
> errno set to EAGAIN/EWOULDBLOCK.
> 
> Would this be your problem ?

Ok, I now have looked at your test code, you measure when posting the
first message, and you already have O_NONBLOCK set. Could you try to
create the queues in the reverse order and see what happens?

-- 
                                          Gilles

Re: [Xenomai-help] mq_send takes longer than expected

[Gilles Chanteperdrix]

Gilles Chanteperdrix wrote:
> Gilles Chanteperdrix wrote:
>> Steve wrote:
>>> Hi,
>>>
>>> Calling mq_send takes significantly varied amounts of time depending
>>> on the queue length.  I was not expecting this behaviour, particularly
>>> as this does not happen when using RTAI mq_send calls.  I can
>>> understand that queue creation / opening times will heavily depend on
>>> the queue's overall size, however I would have thought that sending a
>>> message (adding it to the queue's data structure (linked list?)) would
>>> take a constant time.
>>>
>>> Is this a bug, or expected behaviour?  I have attached an example.
>> mq_send is expected by the posix specification to block its caller when
>> the queue is full. If you do not want this behaviour, you should pass
>> O_NONBLOCK to mq_open and be prepared for mq_send to return -1 with
>> errno set to EAGAIN/EWOULDBLOCK.
>>
>> Would this be your problem ?
> 
> Ok, I now have looked at your test code, you measure when posting the
> first message, and you already have O_NONBLOCK set. Could you try to
> create the queues in the reverse order and see what happens?

Also, would you have CONFIG_XENO_OPT_DEBUG_QUEUES activated ? In this
case, list operations are no longer O(1).

-- 
                                          Gilles

Re: [Xenomai-help] mq_send takes longer than expected

[Steve]

On 15/07/2009, Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org> wrote:
> Gilles Chanteperdrix wrote:
>> Gilles Chanteperdrix wrote:
>>> Steve wrote:
>>>> Hi,
>>>>
>>>> Calling mq_send takes significantly varied amounts of time depending
>>>> on the queue length.  I was not expecting this behaviour, particularly
>>>> as this does not happen when using RTAI mq_send calls.  I can
>>>> understand that queue creation / opening times will heavily depend on
>>>> the queue's overall size, however I would have thought that sending a
>>>> message (adding it to the queue's data structure (linked list?)) would
>>>> take a constant time.
>>>>
>>>> Is this a bug, or expected behaviour?  I have attached an example.
>>> mq_send is expected by the posix specification to block its caller when
>>> the queue is full. If you do not want this behaviour, you should pass
>>> O_NONBLOCK to mq_open and be prepared for mq_send to return -1 with
>>> errno set to EAGAIN/EWOULDBLOCK.
>>>
>>> Would this be your problem ?
>>
>> Ok, I now have looked at your test code, you measure when posting the
>> first message, and you already have O_NONBLOCK set. Could you try to
>> create the queues in the reverse order and see what happens?
>
> Also, would you have CONFIG_XENO_OPT_DEBUG_QUEUES activated ? In this
> case, list operations are no longer O(1).
>
> --
>                                           Gilles
>
>

I did have CONFIG_XENO_OPT_DEBUG_QUEUES activated, I must have been a
little overzealous when choosing my config options.  Everything now
runs as expected.

Thanks for the help,

Steve