[Xenomai-help] Time for rt_mutex_acquire

[Xenomai-help] Time for rt_mutex_acquire

[Dirk Eibach]

Hello,

I'm wondering how long a rt_mutex_acquire is supposed to take on a PPC405 
platform. I'm getting times about 50 usec here, which is too much for my 
application. Is anything wrong in my kernel/xenomai configuration or is 
this time to expected?

Cheers,
Dirk

Re: [Xenomai-help] Time for rt_mutex_acquire

[Gilles Chanteperdrix]

Dirk Eibach wrote:
 > Hello,
 > 
 > I'm wondering how long a rt_mutex_acquire is supposed to take on a PPC405 
 > platform. I'm getting times about 50 usec here, which is too much for my 
 > application. Is anything wrong in my kernel/xenomai configuration or is 
 > this time to expected?

How do you measure this ? Are you sure the mutex is free when you try to
acquire it ?

-- 


					    Gilles Chanteperdrix.

Re: [Xenomai-help] Time for rt_mutex_acquire

[Dirk Eibach]

gilles.chanteperdrix@xenomai.org wrote:
> Dirk Eibach wrote:
>  > Hello,
>  > 
>  > I'm wondering how long a rt_mutex_acquire is supposed to take on a PPC405 
>  > platform. I'm getting times about 50 usec here, which is too much for my 
>  > application. Is anything wrong in my kernel/xenomai configuration or is 
>  > this time to expected?
> 
> How do you measure this ? Are you sure the mutex is free when you try to
> acquire it ?
> 

I prepared a small testcase. It shows about 8.300 ticks, which is about 30 
usec on my platform (266MHz).

#include <stdio.h>
#include <signal.h>
#include <unistd.h>
#include <sys/mman.h>

#include <native/mutex.h>
#include <native/task.h>
#include <native/timer.h>

#include <rtdm/rtserial.h>

#define TOGGLE \
	do {rt_dev_ioctl(0, _IOR(RTIOC_TYPE_SERIAL, 0xdf, int), 0);} while(0);

RT_TASK demo_task;

/* NOTE: error handling omitted. */
static void
ppc_getcounter(unsigned long long *v)
{
	register unsigned long tbu, tb, tbu2;

     loop:
	asm volatile ("mftbu %0" : "=r" (tbu) );
	asm volatile ("mftb  %0" : "=r" (tb)  );
	asm volatile ("mftbu %0" : "=r" (tbu2));
	if (__builtin_expect(tbu != tbu2, 0)) goto loop;

	/* The slightly peculiar way of writing the next lines is
	compiled better by GCC than any other way I tried. */
	((long*)(v))[0] = tbu;
	((long*)(v))[1] = tb;
}

void demo(void *arg)
{
	RT_MUTEX mutex;

	rt_mutex_create (&mutex, NULL);
	int file_descriptor = rt_dev_open("rtser0", O_RDWR | O_NOCTTY);
	
	unsigned long long count0, count1;
	
	while (1) {
		ppc_getcounter(&count0);
		rt_mutex_acquire(&mutex, TM_INFINITE);
		ppc_getcounter(&count1);
		printf("ticks for rt_mutex_acquire: %lld\n", count1- count0);
		rt_task_sleep(rt_timer_ns2ticks(1 * 1000000000llu));
		rt_mutex_release(&mutex);
		rt_task_sleep(rt_timer_ns2ticks(1 * 1000000000llu));
	}
}

void catch_signal(int sig)
{
}

int main(int argc, char* argv[])
{
	signal(SIGTERM, catch_signal);
	signal(SIGINT, catch_signal);

	/* Avoids memory swapping for this program */
	mlockall(MCL_CURRENT|MCL_FUTURE);

	/*
	 * Arguments: &task,
	 *            name,
	 *            stack size (0=default),
	 *            priority,
	 *            mode (FPU, start suspended, ...)
	 */
	rt_task_create(&demo_task, "trivial", 0, 99, 0);

	/*
	 * Arguments: &task,
	 *            task function,
	 *            function argument
	 */
	rt_task_start(&demo_task, &demo, NULL);

	pause();

	rt_task_delete(&demo_task);
}


-- 
Dirk Eibach
Entwicklung
Guntermann & Drunck GmbH Systementwicklung

Re: [Xenomai-help] Time for rt_mutex_acquire

[Gilles Chanteperdrix]

On 8/17/07, Dirk Eibach <eibach@domain.hid> wrote:
> gilles.chanteperdrix@xenomai.org wrote:
> > Dirk Eibach wrote:
> >  > Hello,
> >  >
> >  > I'm wondering how long a rt_mutex_acquire is supposed to take on a PPC405
> >  > platform. I'm getting times about 50 usec here, which is too much for my
> >  > application. Is anything wrong in my kernel/xenomai configuration or is
> >  > this time to expected?
> >
> > How do you measure this ? Are you sure the mutex is free when you try to
> > acquire it ?
> >
>
> I prepared a small testcase. It shows about 8.300 ticks, which is about 30
> usec on my platform (266MHz).

Did you try to call ppc_getcounter twice in a raw to measure the
overhead of this function ?


-- 
                                               Gilles Chanteperdrix

Re: [Xenomai-help] Time for rt_mutex_acquire

[Dirk Eibach]

gilles.chanteperdrix@xenomai.org wrote:
> On 8/17/07, Dirk Eibach <eibach@domain.hid> wrote:
>> gilles.chanteperdrix@xenomai.org wrote:
>>> Dirk Eibach wrote:
>>>  > Hello,
>>>  >
>>>  > I'm wondering how long a rt_mutex_acquire is supposed to take on a PPC405
>>>  > platform. I'm getting times about 50 usec here, which is too much for my
>>>  > application. Is anything wrong in my kernel/xenomai configuration or is
>>>  > this time to expected?
>>>
>>> How do you measure this ? Are you sure the mutex is free when you try to
>>> acquire it ?
>>>
>> I prepared a small testcase. It shows about 8.300 ticks, which is about 30
>> usec on my platform (266MHz).
> 
> Did you try to call ppc_getcounter twice in a raw to measure the
> overhead of this function ?

Calling ppc_getcounter twice in a raw results in 116 ticks.

Cheers.
-- 
Dirk Eibach
Entwicklung
Guntermann & Drunck GmbH Systementwicklung

Re: [Xenomai-help] Time for rt_mutex_acquire

[Jan Kiszka]

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

Dirk Eibach wrote:
> gilles.chanteperdrix@xenomai.org wrote:
>> On 8/17/07, Dirk Eibach <eibach@domain.hid> wrote:
>>> gilles.chanteperdrix@xenomai.org wrote:
>>>> Dirk Eibach wrote:
>>>>  > Hello,
>>>>  >
>>>>  > I'm wondering how long a rt_mutex_acquire is supposed to take on a PPC405
>>>>  > platform. I'm getting times about 50 usec here, which is too much for my
>>>>  > application. Is anything wrong in my kernel/xenomai configuration or is
>>>>  > this time to expected?
>>>>
>>>> How do you measure this ? Are you sure the mutex is free when you try to
>>>> acquire it ?
>>>>
>>> I prepared a small testcase. It shows about 8.300 ticks, which is about 30
>>> usec on my platform (266MHz).
>> Did you try to call ppc_getcounter twice in a raw to measure the
>> overhead of this function ?
> 
> Calling ppc_getcounter twice in a raw results in 116 ticks.

Is that service RT-safe, means does it stay in user space and issue no
Linux syscall? Maybe some of the PPC gurus can comment on this as well
(/me is lacking comparative numbers).

Besides this, you may want to try running the latency tracer on your
scenario. xntrace_user_start() and xntrace_user_stop(0) would frame the
path you want to measure, /proc/ipipe/trace/frozen will show its kernel
side. For sure, that tool will increase the latency even more, but it
may show better what goes on.

Jan


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 250 bytes --]

Re: [Xenomai-help] (WARNING!!! PGP with incorrect signature) Re: Time

[Dirk Eibach]

jan.kiszka@domain.hid wrote:
> Dirk Eibach wrote:
>> gilles.chanteperdrix@xenomai.org wrote:
>>> On 8/17/07, Dirk Eibach <eibach@domain.hid> wrote:
>>>> gilles.chanteperdrix@xenomai.org wrote:
>>>>> Dirk Eibach wrote:
>>>>>  > Hello,
>>>>>  >
>>>>>  > I'm wondering how long a rt_mutex_acquire is supposed to take on a PPC405
>>>>>  > platform. I'm getting times about 50 usec here, which is too much for my
>>>>>  > application. Is anything wrong in my kernel/xenomai configuration or is
>>>>>  > this time to expected?
>>>>>
>>>>> How do you measure this ? Are you sure the mutex is free when you try to
>>>>> acquire it ?
>>>>>
>>>> I prepared a small testcase. It shows about 8.300 ticks, which is about 30
>>>> usec on my platform (266MHz).
>>> Did you try to call ppc_getcounter twice in a raw to measure the
>>> overhead of this function ?
>> Calling ppc_getcounter twice in a raw results in 116 ticks.
> 
> Is that service RT-safe, means does it stay in user space and issue no
> Linux syscall? Maybe some of the PPC gurus can comment on this as well
> (/me is lacking comparative numbers).

This service should be RT-safe as it consists only of a few assembly 
commands that read the timestamp counter (which is allowed from userspace).

> 
> Besides this, you may want to try running the latency tracer on your
> scenario. xntrace_user_start() and xntrace_user_stop(0) would frame the
> path you want to measure, /proc/ipipe/trace/frozen will show its kernel
> side. For sure, that tool will increase the latency even more, but it
> may show better what goes on.

Here we go (start, acquire, stop):

I-pipe frozen back-tracing service on 2.6.18/ipipe-1.5-00
------------------------------------------------------------
Freeze: 2785703857177 cycles, Trace Points: 30 (+10)

  +--------------- Hard IRQs ('|': locked)
  |             +- Delay flag ('+': > 1 us, '!': > 10 us)
  |             |
   Type     Time   Function (Parent)
: func      -49+  xnshadow_sys_trace (hisyscall_event)
: func      -46   ipipe_trace_frozen_reset (xnshadow_sys_trace)
: func      -45+  __ipipe_global_path_lock (ipipe_trace_frozen_reset)
:|begin     -44+  __ipipe_global_path_lock (ipipe_trace_frozen_reset)
:|end       -41+  __ipipe_global_path_unlock (ipipe_trace_frozen_reset)
:|begin     -39+  __ipipe_dispatch_event (__ipipe_syscall_root)
:|end       -38+  __ipipe_dispatch_event (__ipipe_syscall_root)
: func      -34+  __ipipe_syscall_root (DoSyscall)
: func      -33+  __ipipe_dispatch_event (__ipipe_syscall_root)
:|begin     -31+  __ipipe_dispatch_event (__ipipe_syscall_root)
:|end       -30+  __ipipe_dispatch_event (__ipipe_syscall_root)
: func      -29+  hisyscall_event (__ipipe_dispatch_event)
: func      -27+  __rt_mutex_acquire (hisyscall_event)
: func      -25+  xnregistry_fetch (__rt_mutex_acquire)
:|begin     -24+  xnregistry_fetch (__rt_mutex_acquire)
:|func      -22+  __ipipe_restore_pipeline_head (xnregistry_fetch)
:|end       -20+  __ipipe_restore_pipeline_head (xnregistry_fetch)
: func      -19+  rt_mutex_acquire (__rt_mutex_acquire)
:|begin     -17+  rt_mutex_acquire (__rt_mutex_acquire)
:|func      -15+  __ipipe_restore_pipeline_head (rt_mutex_acquire)
:|end       -14+  __ipipe_restore_pipeline_head (rt_mutex_acquire)
:|begin     -12+  __ipipe_dispatch_event (__ipipe_syscall_root)
:|end       -11+  __ipipe_dispatch_event (__ipipe_syscall_root)
: func       -8+  __ipipe_syscall_root (DoSyscall)
: func       -6+  __ipipe_dispatch_event (__ipipe_syscall_root)
:|begin      -5+  __ipipe_dispatch_event (__ipipe_syscall_root)
:|end        -4+  __ipipe_dispatch_event (__ipipe_syscall_root)
: func       -2+  hisyscall_event (__ipipe_dispatch_event)
: func       -1+  xnshadow_sys_trace (hisyscall_event)
< freeze      0   xnshadow_sys_trace (hisyscall_event)
  |begin       1   __ipipe_dispatch_event (__ipipe_syscall_root)
  |end         3   __ipipe_dispatch_event (__ipipe_syscall_root)
   func       55   __ipipe_syscall_root (DoSyscall)
   func       57   __ipipe_dispatch_event (__ipipe_syscall_root)
  |begin      58   __ipipe_dispatch_event (__ipipe_syscall_root)
  |end        60   __ipipe_dispatch_event (__ipipe_syscall_root)
   func       61   hisyscall_event (__ipipe_dispatch_event)
   func       63   xnshadow_relax (hisyscall_event)
  |begin      64   xnshadow_relax (hisyscall_event)
  |func       66   schedule_linux_call (xnshadow_relax)

Cheers
-- 
Dirk Eibach
Entwicklung
Guntermann & Drunck GmbH Systementwicklung

Re: [Xenomai-help] (WARNING!!! PGP with incorrect signature) Re: Time

[Jan Kiszka]

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

Dirk Eibach wrote:
> jan.kiszka@domain.hid wrote:
>> Dirk Eibach wrote:
>>> gilles.chanteperdrix@xenomai.org wrote:
>>>> On 8/17/07, Dirk Eibach <eibach@domain.hid> wrote:
>>>>> gilles.chanteperdrix@xenomai.org wrote:
>>>>>> Dirk Eibach wrote:
>>>>>>  > Hello,
>>>>>>  >
>>>>>>  > I'm wondering how long a rt_mutex_acquire is supposed to take
>>>>>> on a PPC405
>>>>>>  > platform. I'm getting times about 50 usec here, which is too
>>>>>> much for my
>>>>>>  > application. Is anything wrong in my kernel/xenomai
>>>>>> configuration or is
>>>>>>  > this time to expected?
>>>>>>
>>>>>> How do you measure this ? Are you sure the mutex is free when you
>>>>>> try to
>>>>>> acquire it ?
>>>>>>
>>>>> I prepared a small testcase. It shows about 8.300 ticks, which is
>>>>> about 30
>>>>> usec on my platform (266MHz).
>>>> Did you try to call ppc_getcounter twice in a raw to measure the
>>>> overhead of this function ?
>>> Calling ppc_getcounter twice in a raw results in 116 ticks.
>>
>> Is that service RT-safe, means does it stay in user space and issue no
>> Linux syscall? Maybe some of the PPC gurus can comment on this as well
>> (/me is lacking comparative numbers).
> 
> This service should be RT-safe as it consists only of a few assembly
> commands that read the timestamp counter (which is allowed from userspace).

Blind as I am, I missed it's in your own code...

Is rt_timer_ns2ticks known to work accurately with it, or is the counter
even the same Xenomai uses?

> 
>>
>> Besides this, you may want to try running the latency tracer on your
>> scenario. xntrace_user_start() and xntrace_user_stop(0) would frame the
>> path you want to measure, /proc/ipipe/trace/frozen will show its kernel
>> side. For sure, that tool will increase the latency even more, but it
>> may show better what goes on.
> 
> Here we go (start, acquire, stop):
> 
> I-pipe frozen back-tracing service on 2.6.18/ipipe-1.5-00
> ------------------------------------------------------------
> Freeze: 2785703857177 cycles, Trace Points: 30 (+10)
> 
>  +--------------- Hard IRQs ('|': locked)
>  |             +- Delay flag ('+': > 1 us, '!': > 10 us)
>  |             |
>   Type     Time   Function (Parent)
> : func      -49+  xnshadow_sys_trace (hisyscall_event)
> : func      -46   ipipe_trace_frozen_reset (xnshadow_sys_trace)
> : func      -45+  __ipipe_global_path_lock (ipipe_trace_frozen_reset)
> :|begin     -44+  __ipipe_global_path_lock (ipipe_trace_frozen_reset)
> :|end       -41+  __ipipe_global_path_unlock (ipipe_trace_frozen_reset)
> :|begin     -39+  __ipipe_dispatch_event (__ipipe_syscall_root)
> :|end       -38+  __ipipe_dispatch_event (__ipipe_syscall_root)

Here we start.

> : func      -34+  __ipipe_syscall_root (DoSyscall)
> : func      -33+  __ipipe_dispatch_event (__ipipe_syscall_root)
> :|begin     -31+  __ipipe_dispatch_event (__ipipe_syscall_root)
> :|end       -30+  __ipipe_dispatch_event (__ipipe_syscall_root)
> : func      -29+  hisyscall_event (__ipipe_dispatch_event)
> : func      -27+  __rt_mutex_acquire (hisyscall_event)
> : func      -25+  xnregistry_fetch (__rt_mutex_acquire)
> :|begin     -24+  xnregistry_fetch (__rt_mutex_acquire)
> :|func      -22+  __ipipe_restore_pipeline_head (xnregistry_fetch)
> :|end       -20+  __ipipe_restore_pipeline_head (xnregistry_fetch)
> : func      -19+  rt_mutex_acquire (__rt_mutex_acquire)
> :|begin     -17+  rt_mutex_acquire (__rt_mutex_acquire)
> :|func      -15+  __ipipe_restore_pipeline_head (rt_mutex_acquire)
> :|end       -14+  __ipipe_restore_pipeline_head (rt_mutex_acquire)
> :|begin     -12+  __ipipe_dispatch_event (__ipipe_syscall_root)
> :|end       -11+  __ipipe_dispatch_event (__ipipe_syscall_root)
> : func       -8+  __ipipe_syscall_root (DoSyscall)

And here we're done. About 26 us minus the tracer overhead, which should
cost us at least a few microseconds. You may already see a bit of this
by disabling CONFIG_IPIPE_TRACE_IRQSOFF (not needed for this measurement).

Still not really short, but it is a full syscall in the end. Anyone with
platform experience around to comment on the numbers?

Jan


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 250 bytes --]