[Xenomai-help] strange periodic behavior

[Xenomai-help] strange periodic behavior

[Brandt Erickson]

Hey all,
I've been experimenting with writing a simple timer program using the
native API.  Basically, each loop, it writes the current timestamp into
shared memory which then gets read by a slower loop and written to disk. 
The weird thing is, the period I get seems to always be half of what I've
commanded.  That is, if I set the frequency to 1000 Hz, the difference
between each timestamp is a little over 2 ms (500 Hz).  It works the same
way for 10000 Hz and 20000 Hz.  Does anyone know what causes this or how
to fix it?  Thanks.
-Brandt

Re: [Xenomai-help] strange periodic behavior

[Jan Kiszka]

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

Brandt Erickson wrote:
> Hey all,
> I've been experimenting with writing a simple timer program using the
> native API.  Basically, each loop, it writes the current timestamp into
> shared memory which then gets read by a slower loop and written to disk. 
> The weird thing is, the period I get seems to always be half of what I've
> commanded.  That is, if I set the frequency to 1000 Hz, the difference
> between each timestamp is a little over 2 ms (500 Hz).  It works the same
> way for 10000 Hz and 20000 Hz.  Does anyone know what causes this or how
> to fix it?  Thanks.
> -Brandt

[FAQ] ;)
Is powersaving via CPU frequency scaling activated (my notebook, e.g.,
scales by 2 in that mode)? Make sure it's not. Also compare your
findings with the output of the latency test tool. Does it suffer too?

Jan


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

Re: [Xenomai-help] strange periodic behavior

[Brandt Erickson]

Well, I'm working on a desktop but frequency scaling was enabled, so I
recompiled the kernel without frequency scaling support and the behavior
still persists.  I've run the latency program from the test suite, but I'm
not sure how I should interpret the output.  What indicators am I looking
for?
-Brandt

> Brandt Erickson wrote:
>> Hey all,
>> I've been experimenting with writing a simple timer program using the
>> native API.  Basically, each loop, it writes the current timestamp into
>> shared memory which then gets read by a slower loop and written to disk.
>> The weird thing is, the period I get seems to always be half of what
>> I've
>> commanded.  That is, if I set the frequency to 1000 Hz, the difference
>> between each timestamp is a little over 2 ms (500 Hz).  It works the
>> same
>> way for 10000 Hz and 20000 Hz.  Does anyone know what causes this or how
>> to fix it?  Thanks.
>> -Brandt
>
> [FAQ] ;)
> Is powersaving via CPU frequency scaling activated (my notebook, e.g.,
> scales by 2 in that mode)? Make sure it's not. Also compare your
> findings with the output of the latency test tool. Does it suffer too?
>
> Jan
>
>

Re: [Xenomai-help] strange periodic behavior

[Jan Kiszka]

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

Brandt Erickson wrote:
> Well, I'm working on a desktop but frequency scaling was enabled, so I
> recompiled the kernel without frequency scaling support and the behavior
> still persists. 

Sure your kernel was updated? Check /proc/cpuinfo for varying numbers
with and without system load.

> I've run the latency program from the test suite, but I'm
> not sure how I should interpret the output.  What indicators am I looking
> for?

High jitters of the measured delays if the cpu frequency changes. Once
the frequency is different from the calibration time, you either get too
short or too long intervals when reading the time. You will not see any
effect if your CPU is in the same state during both calibration and
measuring time.

But maybe it is better to post a simple excerpt of your test which shows
your problem and let us cross-check.

Jan


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

Re: [Xenomai-help] strange periodic behavior

[Brandt Erickson]

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

> Sure your kernel was updated? Check /proc/cpuinfo for varying numbers
> with and without system load.

Yes, the kernel is up-to-date.  The config file on /boot confirms and
there is no variation in frequency going from and idle load to ~full load.

> But maybe it is better to post a simple excerpt of your test which shows
> your problem and let us cross-check.

sample output from the latency program is attached.  Thanks for the help.
-Brandt

[-- Attachment #2: latency.output --]
[-- Type: application/octet-stream, Size: 3033 bytes --]

== Sampling period: 100 us
== Test mode: periodic user-mode task
== All results in microseconds
warming up...
RTT|  00:00:01  (periodic user-mode task, 100 us period)
RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
RTD|      -1.314|      -1.011|       2.620|       0|      -1.314|       2.620
RTD|      -1.314|      -1.012|       3.710|       0|      -1.314|       3.710
RTD|      -1.347|      -1.013|       2.119|       0|      -1.347|       3.710
RTD|      -1.347|      -1.014|       2.180|       0|      -1.347|       3.710
RTD|      -1.315|      -1.012|       1.719|       0|      -1.347|       3.710
RTD|      -1.341|      -1.013|       1.882|       0|      -1.347|       3.710
RTD|      -1.315|      -1.013|       2.040|       0|      -1.347|       3.710
RTD|      -1.360|      -1.013|       2.181|       0|      -1.360|       3.710
RTD|      -1.315|      -1.013|       1.633|       0|      -1.360|       3.710
RTD|      -1.314|      -1.006|       1.892|       0|      -1.360|       3.710
RTD|      -1.315|      -1.013|       1.618|       0|      -1.360|       3.710
RTD|      -1.319|      -1.012|       1.760|       0|      -1.360|       3.710
RTD|      -1.316|      -1.012|       1.932|       0|      -1.360|       3.710
RTD|      -1.315|      -1.000|       4.799|       0|      -1.360|       4.799
RTD|      -1.316|      -1.012|       1.848|       0|      -1.360|       4.799
RTD|      -1.318|      -1.013|       1.674|       0|      -1.360|       4.799
RTD|      -1.362|      -1.012|       1.850|       0|      -1.362|       4.799
RTD|      -1.316|      -1.013|       1.428|       0|      -1.362|       4.799
RTD|      -1.314|      -1.014|       1.544|       0|      -1.362|       4.799
RTD|      -1.313|      -1.013|       1.384|       0|      -1.362|       4.799
RTD|      -1.314|      -1.013|       1.523|       0|      -1.362|       4.799
RTT|  00:00:22  (periodic user-mode task, 100 us period)
RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
RTD|      -1.313|      -1.013|       1.677|       0|      -1.362|       4.799
RTD|      -1.316|      -1.012|       2.062|       0|      -1.362|       4.799
RTD|      -1.315|      -1.007|       2.444|       0|      -1.362|       4.799
RTD|      -1.315|      -1.004|       1.841|       0|      -1.362|       4.799
RTD|      -1.363|      -1.011|       2.226|       0|      -1.363|       4.799
RTD|      -1.313|      -1.011|       4.542|       0|      -1.363|       4.799
RTD|      -1.314|      -1.012|       2.230|       0|      -1.363|       4.799
RTD|      -1.315|      -1.011|       1.755|       0|      -1.363|       4.799
RTD|      -1.333|      -1.012|       2.231|       0|      -1.363|       4.799
RTD|      -1.315|      -1.012|       1.971|       0|      -1.363|       4.799
RTD|      -1.315|      -1.012|       2.142|       0|      -1.363|       4.799
RTD|      -1.314|      -1.012|       1.724|       0|      -1.363|       4.799
---|------------|------------|------------|--------|-------------------------

Re: [Xenomai-help] strange periodic behavior

[Jan Kiszka]

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

Brandt Erickson wrote:
>> Sure your kernel was updated? Check /proc/cpuinfo for varying numbers
>> with and without system load.
> 
> Yes, the kernel is up-to-date.  The config file on /boot confirms and
> there is no variation in frequency going from and idle load to ~full load.
> 
>> But maybe it is better to post a simple excerpt of your test which shows
>> your problem and let us cross-check.
> 
> sample output from the latency program is attached.  Thanks for the help.

Grmbl, my fault. Your test looks ok, but I was rather referring to your
*code*.

Jan


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

Re: [Xenomai-help] strange periodic behavior

[Brandt Erickson]

 > Grmbl, my fault. Your test looks ok, but I was rather referring to your
> *code*.

Sorry, here's a small portion of what it outputs.  The first column is the
timestamp and the second is the overrun value from rt_task_wait_period. 
In this case, the "control loop" is supposed to be running at 10 KHz.

0.000087,	0
0.000302,	0
0.000522,	0
0.000742,	0
0.000962,	0
0.001182,	0
0.001402,	0
0.001623,	0
0.001843,	0
0.002063,	0
0.002283,	0
0.002503,	0
0.002723,	0
0.002944,	0
0.003164,	0
0.003384,	0
0.003604,	0
0.003824,	0
0.004045,	0
0.004265,	0
0.004485,	0
0.004705,	0
0.004925,	0
0.005146,	0
0.005366,	0
0.005586,	0
0.005806,	0
0.006026,	0
0.006246,	0
0.006467,	0
0.006687,	0
0.006907,	0
0.007127,	0
0.007347,	0
0.007568,	0
0.007788,	0
0.008008,	0
0.008228,	0
0.008448,	0
0.008669,	0
0.008889,	0
0.009109,	0
0.009329,	0
0.009549,	0
0.009769,	0
0.009990,	0
0.010210,	0

Re: [Xenomai-help] strange periodic behavior

[Jan Kiszka]

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

Brandt Erickson wrote:
>  > Grmbl, my fault. Your test looks ok, but I was rather referring to your
>> *code*.
> 
> Sorry, here's a small portion of what it outputs.  The first column is the
> timestamp and the second is the overrun value from rt_task_wait_period. 
> In this case, the "control loop" is supposed to be running at 10 KHz.
> 

Let's try this again :): Could you post your test program or better a
reduced version of it that demonstrate the wrong timing? We can then
analyse and/or compile and run it on some of our test systems.

Jan


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

Re: [Xenomai-help] strange periodic behavior

[Jan Kiszka]

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

Brandt Erickson wrote:
>  > Grmbl, my fault. Your test looks ok, but I was rather referring to your
>> *code*.
> 
> Sorry, here's a small portion of what it outputs.  The first column is the
> timestamp and the second is the overrun value from rt_task_wait_period. 
> In this case, the "control loop" is supposed to be running at 10 KHz.
> 
> 0.000087,	0
> 0.000302,	0
> 0.000522,	0
> 0.000742,	0
> 0.000962,	0
> 0.001182,	0
> 0.001402,	0
> 0.001623,	0
> 0.001843,	0
> 0.002063,	0
> 0.002283,	0
> 0.002503,	0
> 0.002723,	0
> 0.002944,	0
> 0.003164,	0
> 0.003384,	0
> 0.003604,	0
> 0.003824,	0
> 0.004045,	0
> 0.004265,	0
> 0.004485,	0
> 0.004705,	0
> 0.004925,	0
> 0.005146,	0
> 0.005366,	0
> 0.005586,	0
> 0.005806,	0
> 0.006026,	0
> 0.006246,	0
> 0.006467,	0
> 0.006687,	0
> 0.006907,	0
> 0.007127,	0
> 0.007347,	0
> 0.007568,	0
> 0.007788,	0
> 0.008008,	0
> 0.008228,	0
> 0.008448,	0
> 0.008669,	0
> 0.008889,	0
> 0.009109,	0
> 0.009329,	0
> 0.009549,	0
> 0.009769,	0
> 0.009990,	0
> 0.010210,	0
> 

[looking at it again]
Ah, this is drifting! The more important is the code to see what clock
sources you use. They are obviously not in sync.

Jan


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

Re: [Xenomai-help] strange periodic behavior

[Brandt Erickson]

Turns out the timestamp was calculated using rt_timer_tsc() so on a
machine with a processor speed close to 1GHz the value is close to the
wall clock time but on a 2.2GHz machine the value is off.  Using
rt_timer_tsc2ns() solves the issue.  Thanks for the help.
-Brandt