Re: [Xenomai] rtdm_clock_read overhead/accuracy question

[Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org>]

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