[Xenomai] rtdm_clock_read overhead/accuracy question

[Xenomai] rtdm_clock_read overhead/accuracy question

[JK.Behnke]

   Hello,

   I'm currently debugging a problem in my xenomai application.
   In order ot get timing information I do the following inside the
   read-handler of my rtdm driver.

   // --- start code snippet ---------------------------------
   nanosecs_abs_t  t1, t2;
   rtdm_lock_get_irqsave(&lockobj, lockctx);

   t1=rtdm_clock_read();
   rtdm_task_busy_sleep(10000); // code block to be measured.
   t2=rtdm_clock_read();

   rtdm_lock_put_irqrestore(&lockobj, lockctx);
   // --- end code snippet ---------------------------------

   I observe the following time differences  t2-t1:
   min=10176 ns,  max=10737 ns, avg=10314 ns

   This means in this case the average overhead of the two rtdm_clock_read
   calls is
   approximately 314 ns/2 = 157 ns.

   Is that realistic?
   Are there any other functions I might use to measure execution time of
   an arbitrary code block?

   I'm running xenomai 2.6.3 on linux kernel 3.8.13.
   Hardware platform is Intel Atom E640 (1.0 GHz)

   Thanks in advance
   Jochen

Re: [Xenomai] rtdm_clock_read overhead/accuracy question

[Gilles Chanteperdrix]

On Wed, Nov 18, 2015 at 02:34:56PM +0100, JK.Behnke@web.de wrote:
>    Hello,
> 
>    I'm currently debugging a problem in my xenomai application.
>    In order ot get timing information I do the following inside the
>    read-handler of my rtdm driver.
> 
>    // --- start code snippet ---------------------------------
>    nanosecs_abs_t  t1, t2;
>    rtdm_lock_get_irqsave(&lockobj, lockctx);
> 
>    t1=rtdm_clock_read();
>    rtdm_task_busy_sleep(10000); // code block to be measured.
>    t2=rtdm_clock_read();
> 
>    rtdm_lock_put_irqrestore(&lockobj, lockctx);
>    // --- end code snippet ---------------------------------
> 
>    I observe the following time differences  t2-t1:
>    min=10176 ns,  max=10737 ns, avg=10314 ns
> 
>    This means in this case the average overhead of the two rtdm_clock_read
>    calls is
>    approximately 314 ns/2 = 157 ns.

No, this means that the average overhead of rtdm_clock_read is
314ns.

what you do is:
read time
convert to ns
busy sleep
read time
convert to ns

As you can see, between the two time reads, there is only one
conversion to nanoseconds, (which we assume is the bulk of the
overhead). And more generally, the overhead of the second time read
is not counted either.


> 
>    Is that realistic?

This seems to be a lot. The "tsc" test will measure the average
difference between two time reads, and the "arith" test will measure
the average time for a "multiply then shift" operation, adding the
two should give you an idea of the overhead. From what I recall,
reading the tsc on an atom N230 (a very old one) had an overhead
around 20ns.

>    Are there any other functions I might use to measure execution time of
>    an arbitrary code block?

You may want to use the tsc. The native skin has rt_timer_tsc and
rt_timer_tsc2ns. Since you are in kernel space, you may want to
use the I-pipe tsc read function, which should reduce even more the
overhead.

> 
>    I'm running xenomai 2.6.3 on linux kernel 3.8.13.
>    Hardware platform is Intel Atom E640 (1.0 GHz)

At 1GHz, you may even skip the rt_timer_tsc2ns ;-)

-- 
					    Gilles.
https://click-hack.org

Re: [Xenomai] rtdm_clock_read overhead/accuracy question

[JK.Behnke]

Hello Gilles,

thanks for your quick response.
See my comments/questions below.

>On Wed, Nov 18, 2015 at 02:34:56PM +0100, JK.Behnke@web.de wrote:
>> Hello,
>>
>> I'm currently debugging a problem in my xenomai application.
>> In order ot get timing information I do the following inside the
>> read-handler of my rtdm driver.
>>
>> // --- start code snippet ---------------------------------
>> nanosecs_abs_t t1, t2;
>> rtdm_lock_get_irqsave(&lockobj, lockctx);
>>
>> t1=rtdm_clock_read();
>> rtdm_task_busy_sleep(10000); // code block to be measured.
>> t2=rtdm_clock_read();
>>
>> rtdm_lock_put_irqrestore(&lockobj, lockctx);
>> // --- end code snippet ---------------------------------
>>
>> I observe the following time differences t2-t1:
>> min=10176 ns, max=10737 ns, avg=10314 ns
>>
>> This means in this case the average overhead of the two rtdm_clock_read
>> calls is
>> approximately 314 ns/2 = 157 ns.
>
>No, this means that the average overhead of rtdm_clock_read is
>314ns.
>
>what you do is:
>read time
>convert to ns
>busy sleep
>read time
>convert to ns
>
>As you can see, between the two time reads, there is only one
>conversion to nanoseconds, (which we assume is the bulk of the
>overhead). And more generally, the overhead of the second time read
>is not counted either.
>
>
>>
>> Is that realistic?
>
>This seems to be a lot. The "tsc" test will measure the average
>difference between two time reads, and the "arith" test will measure
>the average time for a "multiply then shift" operation, adding the
>two should give you an idea of the overhead. From what I recall,
>reading the tsc on an atom N230 (a very old one) had an overhead
>around 20ns.
Where do I find the "tsc test", which test application do I have to run?


>
>> Are there any other functions I might use to measure execution time of
>> an arbitrary code block?
>
>You may want to use the tsc. The native skin has rt_timer_tsc and
>rt_timer_tsc2ns. Since you are in kernel space, you may want to
>use the I-pipe tsc read function, which should reduce even more the
>overhead.
Where do I find the I-pipe tsc read function.
I can't find it in the documentation.


>
>>
>> I'm running xenomai 2.6.3 on linux kernel 3.8.13.
>> Hardware platform is Intel Atom E640 (1.0 GHz)
>
>At 1GHz, you may even skip the rt_timer_tsc2ns ;-)
>
>--
>Gilles.
>https://click-hack.org

Regards
Jochen
 

Re: [Xenomai] rtdm_clock_read overhead/accuracy question

[Gilles Chanteperdrix]

On Wed, Nov 18, 2015 at 03:36:25PM +0100, JK.Behnke@web.de wrote:
> Hello Gilles,
> 
> thanks for your quick response.
> See my comments/questions below.
> 
> >On Wed, Nov 18, 2015 at 02:34:56PM +0100, JK.Behnke@web.de wrote:
> >> Hello,
> >>
> >> I'm currently debugging a problem in my xenomai application.
> >> In order ot get timing information I do the following inside the
> >> read-handler of my rtdm driver.
> >>
> >> // --- start code snippet ---------------------------------
> >> nanosecs_abs_t t1, t2;
> >> rtdm_lock_get_irqsave(&lockobj, lockctx);
> >>
> >> t1=rtdm_clock_read();
> >> rtdm_task_busy_sleep(10000); // code block to be measured.
> >> t2=rtdm_clock_read();
> >>
> >> rtdm_lock_put_irqrestore(&lockobj, lockctx);
> >> // --- end code snippet ---------------------------------
> >>
> >> I observe the following time differences t2-t1:
> >> min=10176 ns, max=10737 ns, avg=10314 ns
> >>
> >> This means in this case the average overhead of the two rtdm_clock_read
> >> calls is
> >> approximately 314 ns/2 = 157 ns.
> >
> >No, this means that the average overhead of rtdm_clock_read is
> >314ns.
> >
> >what you do is:
> >read time
> >convert to ns
> >busy sleep
> >read time
> >convert to ns
> >
> >As you can see, between the two time reads, there is only one
> >conversion to nanoseconds, (which we assume is the bulk of the
> >overhead). And more generally, the overhead of the second time read
> >is not counted either.
> >
> >
> >>
> >> Is that realistic?
> >
> >This seems to be a lot. The "tsc" test will measure the average
> >difference between two time reads, and the "arith" test will measure
> >the average time for a "multiply then shift" operation, adding the
> >two should give you an idea of the overhead. From what I recall,
> >reading the tsc on an atom N230 (a very old one) had an overhead
> >around 20ns.
> Where do I find the "tsc test", which test application do I have to run?

The application is named "tsc".

> 
> 
> >
> >> Are there any other functions I might use to measure execution time of
> >> an arbitrary code block?
> >
> >You may want to use the tsc. The native skin has rt_timer_tsc and
> >rt_timer_tsc2ns. Since you are in kernel space, you may want to
> >use the I-pipe tsc read function, which should reduce even more the
> >overhead.
> Where do I find the I-pipe tsc read function.
> I can't find it in the documentation.

That is because it is an internal function. Look at the
implementation of rt_timer_tsc. The name is xnarch_get_cpu_tsc();

-- 
					    Gilles.
https://click-hack.org

Re: [Xenomai] rtdm_clock_read overhead/accuracy question

[JK.Behnke]

Hello Gilles,

>On Wed, Nov 18, 2015 at 03:36:25PM +0100, JK.Behnke@web.de wrote:
>> Hello Gilles,
>>
>> thanks for your quick response.
>> See my comments/questions below.
>>
>> >On Wed, Nov 18, 2015 at 02:34:56PM +0100, JK.Behnke@web.de wrote:
>> >> Hello,
>> >>
>> >> I'm currently debugging a problem in my xenomai application.
>> >> In order ot get timing information I do the following inside the
>> >> read-handler of my rtdm driver.
>> >>
>> >> // --- start code snippet ---------------------------------
>> >> nanosecs_abs_t t1, t2;
>> >> rtdm_lock_get_irqsave(&lockobj, lockctx);
>> >>
>> >> t1=rtdm_clock_read();
>> >> rtdm_task_busy_sleep(10000); // code block to be measured.
>> >> t2=rtdm_clock_read();
>> >>
>> >> rtdm_lock_put_irqrestore(&lockobj, lockctx);
>> >> // --- end code snippet ---------------------------------
>> >>
>> >> I observe the following time differences t2-t1:
>> >> min=10176 ns, max=10737 ns, avg=10314 ns
>> >>
>> >> This means in this case the average overhead of the two rtdm_clock_read
>> >> calls is
>> >> approximately 314 ns/2 = 157 ns.
>> >
>> >No, this means that the average overhead of rtdm_clock_read is
>> >314ns.
>> >
>> >what you do is:
>> >read time
>> >convert to ns
>> >busy sleep
>> >read time
>> >convert to ns
>> >
>> >As you can see, between the two time reads, there is only one
>> >conversion to nanoseconds, (which we assume is the bulk of the
>> >overhead). And more generally, the overhead of the second time read
>> >is not counted either.
>> >
>> >
>> >>
>> >> Is that realistic?
>> >
>> >This seems to be a lot. The "tsc" test will measure the average
>> >difference between two time reads, and the "arith" test will measure
>> >the average time for a "multiply then shift" operation, adding the
>> >two should give you an idea of the overhead. From what I recall,
>> >reading the tsc on an atom N230 (a very old one) had an overhead
>> >around 20ns.
>> Where do I find the "tsc test", which test application do I have to run?
>
>The application is named "tsc".

Thanks, meanwhile I found the tsc tool under /usr/xenomai/bin/regression

Here are my "tsc" results
Atom E640 (1.0 GHz): min: 26, max: 936, avg: 34.0001 -> 0.0262211 us  ==> 26 ns
Atom E660 (1.3 GHz): min: 26, max: 1105, avg: 34.0001 -> 0.0262211 us ==> 26 ns

The "arith" tool delivered these results (only lines containing "llmulshft")
Atom E640 (1.0 GHz):
inlined llmulshft: 0x79364d92ffffffe1: 29.088 ns, rejected 0/10000     ==> 29 ns
out of line llmulshft: 0x79364d92ffffffe1: 40.097 ns, rejected 0/10000 ==> 40 ns
inlined llmulshft: 0x86c9b26d0000001e: 30.222 ns, rejected 0/10000     ==> 30 ns
out of line llmulshft: 0x86c9b26d0000001e: 44.118 ns, rejected 1/10000 ==> 44 ns

Atom E660 (1.3 GHz):
inlined llmulshft: 0x79364d92ffffffe1: 22.372 ns, rejected 1/10000     ==> 22 ns
out of line llmulshft: 0x79364d92ffffffe1: 30.851 ns, rejected 0/10000 ==> 31 ns
inlined llmulshft: 0x86c9b26d0000001e: 23.916 ns, rejected 0/10000     ==> 24 ns
out of line llmulshft: 0x86c9b26d0000001e: 33.936 ns, rejected 1/10000 ==> 34 ns
What do you think about these results?
>
>>
>>
>> >
>> >> Are there any other functions I might use to measure execution time of
>> >> an arbitrary code block?
>> >
>> >You may want to use the tsc. The native skin has rt_timer_tsc and
>> >rt_timer_tsc2ns. Since you are in kernel space, you may want to
>> >use the I-pipe tsc read function, which should reduce even more the
>> >overhead.
>> Where do I find the I-pipe tsc read function.
>> I can't find it in the documentation.
>
>That is because it is an internal function. Look at the
>implementation of rt_timer_tsc. The name is xnarch_get_cpu_tsc();

OK, I'll have look at it.


Thanks
Jochen
 

Re: [Xenomai] rtdm_clock_read overhead/accuracy question

[Gilles Chanteperdrix]

On Wed, Nov 18, 2015 at 06:11:00PM +0100, JK.Behnke@web.de wrote:
> Hello Gilles,
> 
> >On Wed, Nov 18, 2015 at 03:36:25PM +0100, JK.Behnke@web.de wrote:
> >> Hello Gilles,
> >>
> >> thanks for your quick response.
> >> See my comments/questions below.
> >>
> >> >On Wed, Nov 18, 2015 at 02:34:56PM +0100, JK.Behnke@web.de wrote:
> >> >> Hello,
> >> >>
> >> >> I'm currently debugging a problem in my xenomai application.
> >> >> In order ot get timing information I do the following inside the
> >> >> read-handler of my rtdm driver.
> >> >>
> >> >> // --- start code snippet ---------------------------------
> >> >> nanosecs_abs_t t1, t2;
> >> >> rtdm_lock_get_irqsave(&lockobj, lockctx);
> >> >>
> >> >> t1=rtdm_clock_read();
> >> >> rtdm_task_busy_sleep(10000); // code block to be measured.
> >> >> t2=rtdm_clock_read();
> >> >>
> >> >> rtdm_lock_put_irqrestore(&lockobj, lockctx);
> >> >> // --- end code snippet ---------------------------------
> >> >>
> >> >> I observe the following time differences t2-t1:
> >> >> min=10176 ns, max=10737 ns, avg=10314 ns
> >> >>
> >> >> This means in this case the average overhead of the two rtdm_clock_read
> >> >> calls is
> >> >> approximately 314 ns/2 = 157 ns.
> >> >
> >> >No, this means that the average overhead of rtdm_clock_read is
> >> >314ns.
> >> >
> >> >what you do is:
> >> >read time
> >> >convert to ns
> >> >busy sleep
> >> >read time
> >> >convert to ns
> >> >
> >> >As you can see, between the two time reads, there is only one
> >> >conversion to nanoseconds, (which we assume is the bulk of the
> >> >overhead). And more generally, the overhead of the second time read
> >> >is not counted either.
> >> >
> >> >
> >> >>
> >> >> Is that realistic?
> >> >
> >> >This seems to be a lot. The "tsc" test will measure the average
> >> >difference between two time reads, and the "arith" test will measure
> >> >the average time for a "multiply then shift" operation, adding the
> >> >two should give you an idea of the overhead. From what I recall,
> >> >reading the tsc on an atom N230 (a very old one) had an overhead
> >> >around 20ns.
> >> Where do I find the "tsc test", which test application do I have to run?
> >
> >The application is named "tsc".
> 
> Thanks, meanwhile I found the tsc tool under
> /usr/xenomai/bin/regression

Yeah, well, not a very good default directory. You can onverride it
with an option from the configure script.

> 
> Here are my "tsc" results
> Atom E640 (1.0 GHz): min: 26, max: 936, avg: 34.0001 -> 0.0262211 us  ==> 26 ns
> Atom E660 (1.3 GHz): min: 26, max: 1105, avg: 34.0001 -> 0.0262211 us ==> 26 ns

Well, there is a problem with the time conversion routines. 34
cycles on a 1.0 GHz machine should be 34ns, not 26ns. Other than
that, it seems consistent with what I observe on my old atom.

> 
> The "arith" tool delivered these results (only lines containing "llmulshft")
> Atom E640 (1.0 GHz):
> inlined llmulshft: 0x79364d92ffffffe1: 29.088 ns, rejected 0/10000     ==> 29 ns
> out of line llmulshft: 0x79364d92ffffffe1: 40.097 ns, rejected 0/10000 ==> 40 ns
> inlined llmulshft: 0x86c9b26d0000001e: 30.222 ns, rejected 0/10000     ==> 30 ns
> out of line llmulshft: 0x86c9b26d0000001e: 44.118 ns, rejected 1/10000 ==> 44 ns

These values have the calibration subtracted, you may want to re-add
the calibration value to have an idea of the time it really took.
But other than that, it seems reasonably short.

-- 
					    Gilles.
https://click-hack.org

Re: [Xenomai] rtdm_clock_read overhead/accuracy question

[Jeroen Van den Keybus]

>>
>>    Is that realistic?
>
> This seems to be a lot.

It looks quite long, yes, for what should essentially be an RDTSC instruction.

Why not test without the sleep and compare two back-to-back
rtdm_clock_read()s to make sure that you're not measuring jitter from
the sleep function ?


Jeroen.

Re: [Xenomai] rtdm_clock_read overhead/accuracy question

[JK.Behnke]

Hello Jeroen,

>>>
>>> Is that realistic?
>>
>> This seems to be a lot.
>
>It looks quite long, yes, for what should essentially be an RDTSC instruction.
>
>Why not test without the sleep and compare two back-to-back
>rtdm_clock_read()s to make sure that you're not measuring jitter from
>the sleep function ?
OK, I removed the sleep.
On Atom E640 (1.0 GHz) I get min=70 ns, max=91 ns, avg=79 ns
On Atom E660 (1.3 GHz) I get min=50 ns, max=71 ns, avg=62 ns

Regards
Jochen

Re: [Xenomai] rtdm_clock_read overhead/accuracy question

[Gilles Chanteperdrix]

On Wed, Nov 18, 2015 at 03:38:38PM +0100, Jeroen Van den Keybus wrote:
> >>
> >>    Is that realistic?
> >
> > This seems to be a lot.
> 
> It looks quite long, yes, for what should essentially be an RDTSC instruction.

rtdm_clock_read does more than calling rdtsc, it calls rdtsc then
converts the result from tsc counts to nanoseconds, which is not
negligible compared to the time for rdtsc.

> 
> Why not test without the sleep and compare two back-to-back
> rtdm_clock_read()s to make sure that you're not measuring jitter from
> the sleep function ?

rtdm_task_busy_sleep does not sleep, it reads the tsc and wait for it
to reach a known value. So, there should be little jitter involved.
Maybe the difference comes from some difference in the time
conversion routines involved ?

-- 
					    Gilles.
https://click-hack.org

Re: [Xenomai] rtdm_clock_read overhead/accuracy question

[JK.Behnke]

>On Wed, Nov 18, 2015 at 06:11:00PM +0100, JK.Behnke at web.de wrote:
>> Hello Gilles,
>> 
>> >On Wed, Nov 18, 2015 at 03:36:25PM +0100, JK.Behnke at web.de wrote:
>> >> Hello Gilles,
>> >>
>> >> thanks for your quick response.
>> >> See my comments/questions below.
>> >>
>> >> >On Wed, Nov 18, 2015 at 02:34:56PM +0100, JK.Behnke at web.de wrote:
>> >> >> Hello,
>> >> >>
>> >> >> I'm currently debugging a problem in my xenomai application.
>> >> >> In order ot get timing information I do the following inside the
>> >> >> read-handler of my rtdm driver.
>> >> >>
>> >> >> // --- start code snippet ---------------------------------
>> >> >> nanosecs_abs_t t1, t2;
>> >> >> rtdm_lock_get_irqsave(&lockobj, lockctx);
>> >> >>
>> >> >> t1=rtdm_clock_read();
>> >> >> rtdm_task_busy_sleep(10000); // code block to be measured.
>> >> >> t2=rtdm_clock_read();
>> >> >>
>> >> >> rtdm_lock_put_irqrestore(&lockobj, lockctx);
>> >> >> // --- end code snippet ---------------------------------
>> >> >>
>> >> >> I observe the following time differences t2-t1:
>> >> >> min=10176 ns, max=10737 ns, avg=10314 ns
>> >> >>
>> >> >> This means in this case the average overhead of the two rtdm_clock_read
>> >> >> calls is
>> >> >> approximately 314 ns/2 = 157 ns.
>> >> >
>> >> >No, this means that the average overhead of rtdm_clock_read is
>> >> >314ns.
>> >> >
>> >> >what you do is:
>> >> >read time
>> >> >convert to ns
>> >> >busy sleep
>> >> >read time
>> >> >convert to ns
>> >> >
>> >> >As you can see, between the two time reads, there is only one
>> >> >conversion to nanoseconds, (which we assume is the bulk of the
>> >> >overhead). And more generally, the overhead of the second time read
>> >> >is not counted either.
>> >> >
>> >> >
>> >> >>
>> >> >> Is that realistic?
>> >> >
>> >> >This seems to be a lot. The "tsc" test will measure the average
>> >> >difference between two time reads, and the "arith" test will measure
>> >> >the average time for a "multiply then shift" operation, adding the
>> >> >two should give you an idea of the overhead. From what I recall,
>> >> >reading the tsc on an atom N230 (a very old one) had an overhead
>> >> >around 20ns.
>> >> Where do I find the "tsc test", which test application do I have to run?
>> >
>> >The application is named "tsc".
>> 
>> Thanks, meanwhile I found the tsc tool under
>> /usr/xenomai/bin/regression
>
>Yeah, well, not a very good default directory. You can onverride it
>with an option from the configure script.
>
>> 
>> Here are my "tsc" results
>> Atom E640 (1.0 GHz): min: 26, max: 936, avg: 34.0001 -> 0.0262211 us  ==> 26 ns
>> Atom E660 (1.3 GHz): min: 26, max: 1105, avg: 34.0001 -> 0.0262211 us ==> 26 ns
>
>Well, there is a problem with the time conversion routines. 34
>cycles on a 1.0 GHz machine should be 34ns, not 26ns. Other than
>that, it seems consistent with what I observe on my old atom.

What can I do about that?

By the way, I measured the difference of two consecutive xnarch_get_cpu_tsc() calls.
Atom E640 (1.0 GHz): min=30 max=40 avg=30.2

As in my case I have disabled interrupts using rtdm_lock_get_irqsave() during
execution of xnarch_get_cpu_tsc(), I wonder why I get different min/max values at all?
I assume that xnarch_get_cpu_tsc() is compiled to a single RDTSC instruction.
Doesn't a RDTSC machine instruction have a deterministic number of cpu cycles?
Aah, obviously this has something to do with so called serializing instructions inside the cpu.
Some people recommend using the new RDTSCP instruction to measure execution times.
Is it for performance reasons that xnarch_get_cpu_tsc uses RDTSC instruction?


Regards
Jochen

Re: [Xenomai] rtdm_clock_read overhead/accuracy question

[Gilles Chanteperdrix]

On Thu, Nov 19, 2015 at 09:09:52AM +0100, JK.Behnke@web.de wrote:
> >On Wed, Nov 18, 2015 at 06:11:00PM +0100, JK.Behnke at web.de wrote:
> >> Hello Gilles,
> >> 
> >> >On Wed, Nov 18, 2015 at 03:36:25PM +0100, JK.Behnke at web.de wrote:
> >> >> Hello Gilles,
> >> >>
> >> >> thanks for your quick response.
> >> >> See my comments/questions below.
> >> >>
> >> >> >On Wed, Nov 18, 2015 at 02:34:56PM +0100, JK.Behnke at web.de wrote:
> >> >> >> Hello,
> >> >> >>
> >> >> >> I'm currently debugging a problem in my xenomai application.
> >> >> >> In order ot get timing information I do the following inside the
> >> >> >> read-handler of my rtdm driver.
> >> >> >>
> >> >> >> // --- start code snippet ---------------------------------
> >> >> >> nanosecs_abs_t t1, t2;
> >> >> >> rtdm_lock_get_irqsave(&lockobj, lockctx);
> >> >> >>
> >> >> >> t1=rtdm_clock_read();
> >> >> >> rtdm_task_busy_sleep(10000); // code block to be measured.
> >> >> >> t2=rtdm_clock_read();
> >> >> >>
> >> >> >> rtdm_lock_put_irqrestore(&lockobj, lockctx);
> >> >> >> // --- end code snippet ---------------------------------
> >> >> >>
> >> >> >> I observe the following time differences t2-t1:
> >> >> >> min=10176 ns, max=10737 ns, avg=10314 ns
> >> >> >>
> >> >> >> This means in this case the average overhead of the two rtdm_clock_read
> >> >> >> calls is
> >> >> >> approximately 314 ns/2 = 157 ns.
> >> >> >
> >> >> >No, this means that the average overhead of rtdm_clock_read is
> >> >> >314ns.
> >> >> >
> >> >> >what you do is:
> >> >> >read time
> >> >> >convert to ns
> >> >> >busy sleep
> >> >> >read time
> >> >> >convert to ns
> >> >> >
> >> >> >As you can see, between the two time reads, there is only one
> >> >> >conversion to nanoseconds, (which we assume is the bulk of the
> >> >> >overhead). And more generally, the overhead of the second time read
> >> >> >is not counted either.
> >> >> >
> >> >> >
> >> >> >>
> >> >> >> Is that realistic?
> >> >> >
> >> >> >This seems to be a lot. The "tsc" test will measure the average
> >> >> >difference between two time reads, and the "arith" test will measure
> >> >> >the average time for a "multiply then shift" operation, adding the
> >> >> >two should give you an idea of the overhead. From what I recall,
> >> >> >reading the tsc on an atom N230 (a very old one) had an overhead
> >> >> >around 20ns.
> >> >> Where do I find the "tsc test", which test application do I have to run?
> >> >
> >> >The application is named "tsc".
> >> 
> >> Thanks, meanwhile I found the tsc tool under
> >> /usr/xenomai/bin/regression
> >
> >Yeah, well, not a very good default directory. You can onverride it
> >with an option from the configure script.
> >
> >> 
> >> Here are my "tsc" results
> >> Atom E640 (1.0 GHz): min: 26, max: 936, avg: 34.0001 -> 0.0262211 us  ==> 26 ns
> >> Atom E660 (1.3 GHz): min: 26, max: 1105, avg: 34.0001 -> 0.0262211 us ==> 26 ns
> >
> >Well, there is a problem with the time conversion routines. 34
> >cycles on a 1.0 GHz machine should be 34ns, not 26ns. Other than
> >that, it seems consistent with what I observe on my old atom.
> 
> What can I do about that?

Check the boot to see what frequency xenomai uses, and follow all
the operations which compute the constants used for time conversion.
The frequency is probably the culprit though.

You should upgrade to Xenomai 2.6 git head also, in case the issue
you have has already been fixed.

-- 
					    Gilles.
https://click-hack.org

Re: [Xenomai] rtdm_clock_read overhead/accuracy question

[JK.Behnke]

   Hello Gilles,

   many thanks for your help up to now.
   I still have some questions, see below.

   >On Thu, Nov 19, 2015 at 09:09:52AM +0100, JK.Behnke@web.de wrote:
   >> >On Wed, Nov 18, 2015 at 06:11:00PM +0100, JK.Behnke at web.de
   wrote:
   >> >> Hello Gilles,
   >> >>
   >> >> >On Wed, Nov 18, 2015 at 03:36:25PM +0100, JK.Behnke at web.de
   wrote:
   >> >> >> Hello Gilles,
   >> >> >>
   >> >> >> thanks for your quick response.
   >> >> >> See my comments/questions below.
   >> >> >>
   >> >> >> >On Wed, Nov 18, 2015 at 02:34:56PM +0100, JK.Behnke at web.de
   wrote:
   >> >> >> >> Hello,
   >> >> >> >>
   >> >> >> >> I'm currently debugging a problem in my xenomai
   application.
   >> >> >> >> In order ot get timing information I do the following
   inside the
   >> >> >> >> read-handler of my rtdm driver.
   >> >> >> >>
   >> >> >> >> // --- start code snippet ---------------------------------
   >> >> >> >> nanosecs_abs_t t1, t2;
   >> >> >> >> rtdm_lock_get_irqsave(&lockobj, lockctx);
   >> >> >> >>
   >> >> >> >> t1=rtdm_clock_read();
   >> >> >> >> rtdm_task_busy_sleep(10000); // code block to be measured.
   >> >> >> >> t2=rtdm_clock_read();
   >> >> >> >>
   >> >> >> >> rtdm_lock_put_irqrestore(&lockobj, lockctx);
   >> >> >> >> // --- end code snippet ---------------------------------
   >> >> >> >>
   >> >> >> >> I observe the following time differences t2-t1:
   >> >> >> >> min=10176 ns, max=10737 ns, avg=10314 ns
   >> >> >> >>
   >> >> >> >> This means in this case the average overhead of the two
   rtdm_clock_read
   >> >> >> >> calls is
   >> >> >> >> approximately 314 ns/2 = 157 ns.
   >> >> >> >
   >> >> >> >No, this means that the average overhead of rtdm_clock_read
   is
   >> >> >> >314ns.
   >> >> >> >
   >> >> >> >what you do is:
   >> >> >> >read time
   >> >> >> >convert to ns
   >> >> >> >busy sleep
   >> >> >> >read time
   >> >> >> >convert to ns
   >> >> >> >
   >> >> >> >As you can see, between the two time reads, there is only one
   >> >> >> >conversion to nanoseconds, (which we assume is the bulk of
   the
   >> >> >> >overhead). And more generally, the overhead of the second
   time read
   >> >> >> >is not counted either.
   >> >> >> >
   >> >> >> >
   >> >> >> >>
   >> >> >> >> Is that realistic?
   >> >> >> >
   >> >> >> >This seems to be a lot. The "tsc" test will measure the
   average
   >> >> >> >difference between two time reads, and the "arith" test will
   measure
   >> >> >> >the average time for a "multiply then shift" operation,
   adding the
   >> >> >> >two should give you an idea of the overhead. From what I
   recall,
   >> >> >> >reading the tsc on an atom N230 (a very old one) had an
   overhead
   >> >> >> >around 20ns.
   >> >> >> Where do I find the "tsc test", which test application do I
   have to run?
   >> >> >
   >> >> >The application is named "tsc".
   >> >>
   >> >> Thanks, meanwhile I found the tsc tool under
   >> >> /usr/xenomai/bin/regression
   >> >
   >> >Yeah, well, not a very good default directory. You can onverride it
   >> >with an option from the configure script.
   >> >
   >> >>
   >> >> Here are my "tsc" results
   >> >> Atom E640 (1.0 GHz): min: 26, max: 936, avg: 34.0001 -> 0.0262211
   us ==> 26 ns
   >> >> Atom E660 (1.3 GHz): min: 26, max: 1105, avg: 34.0001 ->
   0.0262211 us ==> 26 ns
   >> >
   >> >Well, there is a problem with the time conversion routines. 34
   >> >cycles on a 1.0 GHz machine should be 34ns, not 26ns. Other than
   >> >that, it seems consistent with what I observe on my old atom.
   >>
   >> What can I do about that?
   >
   >Check the boot to see what frequency xenomai uses, and follow all
   >the operations which compute the constants used for time conversion.
   >The frequency is probably the culprit though.
   I can't find any hint on the frequency used by xenomai.
   The single line I get by dmesg is:
   tsc: Refined TSC clocksource calibration: 997.507 MHz

   Where do I get the right information?
   Where should I start digging in the sourcecode?
   >You should upgrade to Xenomai 2.6 git head also, in case the issue
   >you have has already been fixed.
   >
   How can I verify that time conversion is working?
   Do I just have to run the "tsc " test tool and compare the avg value
   against the computed us value ?


   Regards
   Jochen

Re: [Xenomai] rtdm_clock_read overhead/accuracy question

[Gilles Chanteperdrix]

On Thu, Nov 19, 2015 at 11:34:47AM +0100, JK.Behnke@web.de wrote:
>    Hello Gilles,
> 
>    many thanks for your help up to now.
>    I still have some questions, see below.
> 
>    >On Thu, Nov 19, 2015 at 09:09:52AM +0100, JK.Behnke@web.de wrote:
>    >> >On Wed, Nov 18, 2015 at 06:11:00PM +0100, JK.Behnke at web.de
>    wrote:
>    >> >> Hello Gilles,
>    >> >>
>    >> >> >On Wed, Nov 18, 2015 at 03:36:25PM +0100, JK.Behnke at web.de
>    wrote:
>    >> >> >> Hello Gilles,
>    >> >> >>
>    >> >> >> thanks for your quick response.
>    >> >> >> See my comments/questions below.
>    >> >> >>
>    >> >> >> >On Wed, Nov 18, 2015 at 02:34:56PM +0100, JK.Behnke at web.de
>    wrote:
>    >> >> >> >> Hello,
>    >> >> >> >>
>    >> >> >> >> I'm currently debugging a problem in my xenomai
>    application.
>    >> >> >> >> In order ot get timing information I do the following
>    inside the
>    >> >> >> >> read-handler of my rtdm driver.
>    >> >> >> >>
>    >> >> >> >> // --- start code snippet ---------------------------------
>    >> >> >> >> nanosecs_abs_t t1, t2;
>    >> >> >> >> rtdm_lock_get_irqsave(&lockobj, lockctx);
>    >> >> >> >>
>    >> >> >> >> t1=rtdm_clock_read();
>    >> >> >> >> rtdm_task_busy_sleep(10000); // code block to be measured.
>    >> >> >> >> t2=rtdm_clock_read();
>    >> >> >> >>
>    >> >> >> >> rtdm_lock_put_irqrestore(&lockobj, lockctx);
>    >> >> >> >> // --- end code snippet ---------------------------------
>    >> >> >> >>
>    >> >> >> >> I observe the following time differences t2-t1:
>    >> >> >> >> min=10176 ns, max=10737 ns, avg=10314 ns
>    >> >> >> >>
>    >> >> >> >> This means in this case the average overhead of the two
>    rtdm_clock_read
>    >> >> >> >> calls is
>    >> >> >> >> approximately 314 ns/2 = 157 ns.
>    >> >> >> >
>    >> >> >> >No, this means that the average overhead of rtdm_clock_read
>    is
>    >> >> >> >314ns.
>    >> >> >> >
>    >> >> >> >what you do is:
>    >> >> >> >read time
>    >> >> >> >convert to ns
>    >> >> >> >busy sleep
>    >> >> >> >read time
>    >> >> >> >convert to ns
>    >> >> >> >
>    >> >> >> >As you can see, between the two time reads, there is only one
>    >> >> >> >conversion to nanoseconds, (which we assume is the bulk of
>    the
>    >> >> >> >overhead). And more generally, the overhead of the second
>    time read
>    >> >> >> >is not counted either.
>    >> >> >> >
>    >> >> >> >
>    >> >> >> >>
>    >> >> >> >> Is that realistic?
>    >> >> >> >
>    >> >> >> >This seems to be a lot. The "tsc" test will measure the
>    average
>    >> >> >> >difference between two time reads, and the "arith" test will
>    measure
>    >> >> >> >the average time for a "multiply then shift" operation,
>    adding the
>    >> >> >> >two should give you an idea of the overhead. From what I
>    recall,
>    >> >> >> >reading the tsc on an atom N230 (a very old one) had an
>    overhead
>    >> >> >> >around 20ns.
>    >> >> >> Where do I find the "tsc test", which test application do I
>    have to run?
>    >> >> >
>    >> >> >The application is named "tsc".
>    >> >>
>    >> >> Thanks, meanwhile I found the tsc tool under
>    >> >> /usr/xenomai/bin/regression
>    >> >
>    >> >Yeah, well, not a very good default directory. You can onverride it
>    >> >with an option from the configure script.
>    >> >
>    >> >>
>    >> >> Here are my "tsc" results
>    >> >> Atom E640 (1.0 GHz): min: 26, max: 936, avg: 34.0001 -> 0.0262211
>    us ==> 26 ns
>    >> >> Atom E660 (1.3 GHz): min: 26, max: 1105, avg: 34.0001 ->
>    0.0262211 us ==> 26 ns
>    >> >
>    >> >Well, there is a problem with the time conversion routines. 34
>    >> >cycles on a 1.0 GHz machine should be 34ns, not 26ns. Other than
>    >> >that, it seems consistent with what I observe on my old atom.
>    >>
>    >> What can I do about that?
>    >
>    >Check the boot to see what frequency xenomai uses, and follow all
>    >the operations which compute the constants used for time conversion.
>    >The frequency is probably the culprit though.
>    I can't find any hint on the frequency used by xenomai.
>    The single line I get by dmesg is:
>    tsc: Refined TSC clocksource calibration: 997.507 MHz
> 
>    Where do I get the right information?

Xenomai on x86 uses the "cpu_kHz" variable, the one reported divided
by 1000 in /proc/cpuinfo 

>    Where should I start digging in the sourcecode?

Start by posting the full logs. From the bootloader up to the moment
when the root filesystem is mounted.

>    >You should upgrade to Xenomai 2.6 git head also, in case the issue
>    >you have has already been fixed.
>    >
>    How can I verify that time conversion is working?

Run the latency test and see if it prints a message once every
second. If the frequency is incorrect, the latency message frequency
will not be exactly 1 Hz.

>    Do I just have to run the "tsc " test tool and compare the avg value
>    against the computed us value ?

This should work too, yes.

-- 
					    Gilles.
https://click-hack.org

Re: [Xenomai] rtdm_clock_read overhead/accuracy question

[JK.Behnke]

   Hello Gilles,
   >On Thu, Nov 19, 2015 at 11:34:47AM +0100, JK.Behnke@web.de wrote:
   >> Hello Gilles,
   >>
   >> many thanks for your help up to now.
   >> I still have some questions, see below.
   >>
   >> >On Thu, Nov 19, 2015 at 09:09:52AM +0100, JK.Behnke@web.de wrote:
   >> >> >On Wed, Nov 18, 2015 at 06:11:00PM +0100, JK.Behnke at web.de
   >> wrote:
   >> >> >> Hello Gilles,
   >> >> >>
   >> >> >> >On Wed, Nov 18, 2015 at 03:36:25PM +0100, JK.Behnke at web.de
   >> wrote:
   >> >> >> >> Hello Gilles,
   >> >> >> >>
   >> >> >> >> thanks for your quick response.
   >> >> >> >> See my comments/questions below.
   >> >> >> >>
   >> >> >> >> >On Wed, Nov 18, 2015 at 02:34:56PM +0100, JK.Behnke at
   web.de
   >> wrote:
   >> >> >> >> >> Hello,
   >> >> >> >> >>
   >> >> >> >> >> I'm currently debugging a problem in my xenomai
   >> application.
   >> >> >> >> >> In order ot get timing information I do the following
   >> inside the
   >> >> >> >> >> read-handler of my rtdm driver.
   >> >> >> >> >>
   >> >> >> >> >> // --- start code snippet
   ---------------------------------
   >> >> >> >> >> nanosecs_abs_t t1, t2;
   >> >> >> >> >> rtdm_lock_get_irqsave(&lockobj, lockctx);
   >> >> >> >> >>
   >> >> >> >> >> t1=rtdm_clock_read();
   >> >> >> >> >> rtdm_task_busy_sleep(10000); // code block to be
   measured.
   >> >> >> >> >> t2=rtdm_clock_read();
   >> >> >> >> >>
   >> >> >> >> >> rtdm_lock_put_irqrestore(&lockobj, lockctx);
   >> >> >> >> >> // --- end code snippet
   ---------------------------------
   >> >> >> >> >>
   >> >> >> >> >> I observe the following time differences t2-t1:
   >> >> >> >> >> min=10176 ns, max=10737 ns, avg=10314 ns
   >> >> >> >> >>
   >> >> >> >> >> This means in this case the average overhead of the two
   >> rtdm_clock_read
   >> >> >> >> >> calls is
   >> >> >> >> >> approximately 314 ns/2 = 157 ns.
   >> >> >> >> >
   >> >> >> >> >No, this means that the average overhead of
   rtdm_clock_read
   >> is
   >> >> >> >> >314ns.
   >> >> >> >> >
   >> >> >> >> >what you do is:
   >> >> >> >> >read time
   >> >> >> >> >convert to ns
   >> >> >> >> >busy sleep
   >> >> >> >> >read time
   >> >> >> >> >convert to ns
   >> >> >> >> >
   >> >> >> >> >As you can see, between the two time reads, there is only
   one
   >> >> >> >> >conversion to nanoseconds, (which we assume is the bulk of
   >> the
   >> >> >> >> >overhead). And more generally, the overhead of the second
   >> time read
   >> >> >> >> >is not counted either.
   >> >> >> >> >
   >> >> >> >> >
   >> >> >> >> >>
   >> >> >> >> >> Is that realistic?
   >> >> >> >> >
   >> >> >> >> >This seems to be a lot. The "tsc" test will measure the
   >> average
   >> >> >> >> >difference between two time reads, and the "arith" test
   will
   >> measure
   >> >> >> >> >the average time for a "multiply then shift" operation,
   >> adding the
   >> >> >> >> >two should give you an idea of the overhead. From what I
   >> recall,
   >> >> >> >> >reading the tsc on an atom N230 (a very old one) had an
   >> overhead
   >> >> >> >> >around 20ns.
   >> >> >> >> Where do I find the "tsc test", which test application do I
   >> have to run?
   >> >> >> >
   >> >> >> >The application is named "tsc".
   >> >> >>
   >> >> >> Thanks, meanwhile I found the tsc tool under
   >> >> >> /usr/xenomai/bin/regression
   >> >> >
   >> >> >Yeah, well, not a very good default directory. You can onverride
   it
   >> >> >with an option from the configure script.
   >> >> >
   >> >> >>
   >> >> >> Here are my "tsc" results
   >> >> >> Atom E640 (1.0 GHz): min: 26, max: 936, avg: 34.0001 ->
   0.0262211
   >> us ==> 26 ns
   >> >> >> Atom E660 (1.3 GHz): min: 26, max: 1105, avg: 34.0001 ->
   >> 0.0262211 us ==> 26 ns
   >> >> >
   >> >> >Well, there is a problem with the time conversion routines. 34
   >> >> >cycles on a 1.0 GHz machine should be 34ns, not 26ns. Other than
   >> >> >that, it seems consistent with what I observe on my old atom.
   >> >>
   >> >> What can I do about that?
   >> >
   >> >Check the boot to see what frequency xenomai uses, and follow all
   >> >the operations which compute the constants used for time
   conversion.
   >> >The frequency is probably the culprit though.
   >> I can't find any hint on the frequency used by xenomai.
   >> The single line I get by dmesg is:
   >> tsc: Refined TSC clocksource calibration: 997.507 MHz
   >>
   >> Where do I get the right information?
   >
   >Xenomai on x86 uses the "cpu_kHz" variable, the one reported divided
   >by 1000 in /proc/cpuinfo
   >
   >> Where should I start digging in the sourcecode?
   >
   >Start by posting the full logs. From the bootloader up to the moment
   >when the root filesystem is mounted.
   >
   >> >You should upgrade to Xenomai 2.6 git head also, in case the issue
   >> >you have has already been fixed.
   >> >
   >> How can I verify that time conversion is working?
   >
   In the meantime I probably found the cause.
   After having upgraded to xenomai 2.6.4 it worked correctly.
   Then I switched back to xenomai 2.6.3 and it still worked correctly.
   As I have multiple systems used for testing (1.0 GHz and 1.3 GHz CPUs),
   I think that I probably mixed them up at some point in time during
   testing.
   26ns correlates with 34 cycles on a 1.3 GHz CPU.
   On the 1.0 GHz CPU the tsc tool returns 34ns as result.

   Sorry for bothering you with that problem and thanks again for your
   help.
   Nevertheless for me it was very instructional.

   Regards
   Jochen