Re: [Xenomai-help] strange latency output (xenomai-2.4.5)

Re: [Xenomai-help] strange latency output (xenomai-2.4.5)

[Gilles Chanteperdrix]

Georg Gottleuber wrote:
> Hi,
> 
> I recently port a  ARM926EJ-S mach to Xenomai
> (like described in http://www.xenomai.org/index.php/I-pipe:ArmPorting).
> 
> While testing with latency I got this output:
> # /usr/xenomai/bin/latency  -p 1000 -h -s -H 500 -t 1
> == Sampling period: 1000 us
> == Test mode: in-kernel periodic task
> == All results in microseconds
> warming up...
> RTT|  00:00:01  (in-kernel periodic task, 1000 us period, priority 99)
> RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
> RTD|      78.992|     104.308|     124.131|       0|      78.992|     124.131
> ...
> RTD|      14.678|      68.413|      96.275|       0|       9.528|     155.321
> RTD|      84.046|     116.435|     175.192|       0|       9.528|     182.139
> ...                                ^^^^^^^                            ^^^^^^^

I do not understand, what is wrong with these values ?

-- 
                                                 Gilles.

[Xenomai-help] strange latency output (xenomai-2.4.5)

[Georg Gottleuber]

Hi,

I recently port a  ARM926EJ-S mach to Xenomai
(like described in http://www.xenomai.org/index.php/I-pipe:ArmPorting).

While testing with latency I got this output:
# /usr/xenomai/bin/latency  -p 1000 -h -s -H 500 -t 1
== Sampling period: 1000 us
== Test mode: in-kernel periodic task
== All results in microseconds
warming up...
RTT|  00:00:01  (in-kernel periodic task, 1000 us period, priority 99)
RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
RTD|      78.992|     104.308|     124.131|       0|      78.992|     124.131
...
RTD|      14.678|      68.413|      96.275|       0|       9.528|     155.321
RTD|      84.046|     116.435|     175.192|       0|       9.528|     182.139
...                                ^^^^^^^                            ^^^^^^^

Some time earlier I had a problem in my clock code and got this:
# /usr/xenomai/bin/latency  -p 1000 -h -s -H 500 -T 900
== Sampling period: 1000 us
== Test mode: periodic user-mode task
== All results in microseconds
warming up...
RTT|  00:00:01  (periodic user-mode task, 1000 us period, priority 99)
RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
RTD|     130.208|     131.944|     135.416|       0|     130.208|     135.416
RTD|      63.368|     132.812|     155.381|       0|      63.368|     155.381
...
RTD|      33.854|      38.194|      55.555|       0|      29.513|     236.979
RTD|      32.986|      38.194|      62.500|      56|      29.513|   56978.298
RTD|      33.854|      38.194|      50.347|      56|      29.513|   56978.298
...

This is a very rare behavior. Normally I got (with bad clock code):
RTD|      36.458|      44.270|     168.402|       0|      33.854|     208.333
RTD|      37.326|     156.250|   56973.958|      28|      33.854|   56973.958
RTD|      36.458|      46.875|     164.062|      28|      33.854|   56973.958

I'm using xenomai-2.4.5 and made a ping test from the host:
ping -l 7 -q -s 10 -f <target IP>

Has anybody seen this behavior before?

Kind regards,
  Georg Gottleuber

Re: [Xenomai-help] strange latency output (xenomai-2.4.5)

[Gilles Chanteperdrix]

Georg Gottleuber wrote:
> 
> Gilles Chanteperdrix schrieb:
>> Georg Gottleuber wrote:
>>> Hi,
>>>
>>> I recently port a  ARM926EJ-S mach to Xenomai
>>> (like described in http://www.xenomai.org/index.php/I-pipe:ArmPorting).
>>>
>>> While testing with latency I got this output:
>>> # /usr/xenomai/bin/latency  -p 1000 -h -s -H 500 -t 1
>>> == Sampling period: 1000 us
>>> == Test mode: in-kernel periodic task
>>> == All results in microseconds
>>> warming up...
>>> RTT|  00:00:01  (in-kernel periodic task, 1000 us period, priority 99)
>>> RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
>>> RTD|      78.992|     104.308|     124.131|       0|      78.992|     124.131
>>> ...
>>> RTD|      14.678|      68.413|      96.275|       0|       9.528|     155.321
>>> RTD|      84.046|     116.435|     175.192|       0|       9.528|     182.139
>>> ...                                ^^^^^^^                            ^^^^^^^
>> I do not understand, what is wrong with these values ?
> 
> It thought, if "lat max" of the current interval is bigger than "lat worst", this "lat
> max" updates the "lat worst". So I ask myself, out of which interval comes the updated 182
> value?

Ok. Got it.

What type of floats are you compiling with ?

-- 
                                                 Gilles.

Re: [Xenomai-help] strange latency output (xenomai-2.4.5)

[Georg Gottleuber]

Gilles Chanteperdrix schrieb:
> Georg Gottleuber wrote:
>> Hi,
>>
>> I recently port a  ARM926EJ-S mach to Xenomai
>> (like described in http://www.xenomai.org/index.php/I-pipe:ArmPorting).
>>
>> While testing with latency I got this output:
>> # /usr/xenomai/bin/latency  -p 1000 -h -s -H 500 -t 1
>> == Sampling period: 1000 us
>> == Test mode: in-kernel periodic task
>> == All results in microseconds
>> warming up...
>> RTT|  00:00:01  (in-kernel periodic task, 1000 us period, priority 99)
>> RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
>> RTD|      78.992|     104.308|     124.131|       0|      78.992|     124.131
>> ...
>> RTD|      14.678|      68.413|      96.275|       0|       9.528|     155.321
>> RTD|      84.046|     116.435|     175.192|       0|       9.528|     182.139
>> ...                                ^^^^^^^                            ^^^^^^^
> 
> I do not understand, what is wrong with these values ?

It thought, if "lat max" of the current interval is bigger than "lat worst", this "lat
max" updates the "lat worst". So I ask myself, out of which interval comes the updated 182
value?

Re: [Xenomai-help] strange latency output (xenomai-2.4.5)

[Gilles Chanteperdrix]

Georg Gottleuber wrote:
> 
> Gilles Chanteperdrix schrieb:
>> Georg Gottleuber wrote:
>>> Hi,
>>>
>>> I recently port a  ARM926EJ-S mach to Xenomai
>>> (like described in http://www.xenomai.org/index.php/I-pipe:ArmPorting).
>>>
>>> While testing with latency I got this output:
>>> # /usr/xenomai/bin/latency  -p 1000 -h -s -H 500 -t 1
>>> == Sampling period: 1000 us
>>> == Test mode: in-kernel periodic task
>>> == All results in microseconds
>>> warming up...
>>> RTT|  00:00:01  (in-kernel periodic task, 1000 us period, priority 99)
>>> RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
>>> RTD|      78.992|     104.308|     124.131|       0|      78.992|     124.131
>>> ...
>>> RTD|      14.678|      68.413|      96.275|       0|       9.528|     155.321
>>> RTD|      84.046|     116.435|     175.192|       0|       9.528|     182.139
>>> ...                                ^^^^^^^                            ^^^^^^^
>> I do not understand, what is wrong with these values ?
> 
> It thought, if "lat max" of the current interval is bigger than "lat worst", this "lat
> max" updates the "lat worst". So I ask myself, out of which interval comes the updated 182
> value?

If your machine is highly loaded, like what you get with a ping -f, the
"display" thread, which is a non real-time one, may be delayed for more
than one second, in which case, it "misses", what is sent by the
"sampling" thread, but the sampling thread never looses the worst
latency itself, so that when the display thread finally manages to print
something, it will print the correct worst case latency.

-- 
                                                 Gilles.

Re: [Xenomai-help] strange latency output (xenomai-2.4.5)

[Georg Gottleuber]

Gilles Chanteperdrix schrieb:
> Georg Gottleuber wrote:
>> Gilles Chanteperdrix schrieb:
>>> Georg Gottleuber wrote:
>>>> Hi,
>>>>
>>>> I recently port a  ARM926EJ-S mach to Xenomai
>>>> (like described in http://www.xenomai.org/index.php/I-pipe:ArmPorting).
>>>>
>>>> While testing with latency I got this output:
>>>> # /usr/xenomai/bin/latency  -p 1000 -h -s -H 500 -t 1
>>>> == Sampling period: 1000 us
>>>> == Test mode: in-kernel periodic task
>>>> == All results in microseconds
>>>> warming up...
>>>> RTT|  00:00:01  (in-kernel periodic task, 1000 us period, priority 99)
>>>> RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
>>>> RTD|      78.992|     104.308|     124.131|       0|      78.992|     124.131
>>>> ...
>>>> RTD|      14.678|      68.413|      96.275|       0|       9.528|     155.321
>>>> RTD|      84.046|     116.435|     175.192|       0|       9.528|     182.139
>>>> ...                                ^^^^^^^                            ^^^^^^^
>>> I do not understand, what is wrong with these values ?
>> It thought, if "lat max" of the current interval is bigger than "lat worst", this "lat
>> max" updates the "lat worst". So I ask myself, out of which interval comes the updated 182
>> value?
> 
> If your machine is highly loaded, like what you get with a ping -f, the
> "display" thread, which is a non real-time one, may be delayed for more
> than one second, in which case, it "misses", what is sent by the
> "sampling" thread, but the sampling thread never looses the worst
> latency itself, so that when the display thread finally manages to print
> something, it will print the correct worst case latency.
> 

Bingo. That's the point. This also explains totally equal lines and missing time
stamps/lines that I have observed.

Thanks a lot.

Re: [Xenomai-help] strange latency output (xenomai-2.4.5)

[Gilles Chanteperdrix]

Georg Gottleuber wrote:
> 
> Gilles Chanteperdrix schrieb:
>> Georg Gottleuber wrote:
>>> Gilles Chanteperdrix schrieb:
>>>> Georg Gottleuber wrote:
>>>>> Hi,
>>>>>
>>>>> I recently port a  ARM926EJ-S mach to Xenomai
>>>>> (like described in http://www.xenomai.org/index.php/I-pipe:ArmPorting).
>>>>>
>>>>> While testing with latency I got this output:
>>>>> # /usr/xenomai/bin/latency  -p 1000 -h -s -H 500 -t 1
>>>>> == Sampling period: 1000 us
>>>>> == Test mode: in-kernel periodic task
>>>>> == All results in microseconds
>>>>> warming up...
>>>>> RTT|  00:00:01  (in-kernel periodic task, 1000 us period, priority 99)
>>>>> RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
>>>>> RTD|      78.992|     104.308|     124.131|       0|      78.992|     124.131
>>>>> ...
>>>>> RTD|      14.678|      68.413|      96.275|       0|       9.528|     155.321
>>>>> RTD|      84.046|     116.435|     175.192|       0|       9.528|     182.139
>>>>> ...                                ^^^^^^^                            ^^^^^^^
>>>> I do not understand, what is wrong with these values ?
>>> It thought, if "lat max" of the current interval is bigger than "lat worst", this "lat
>>> max" updates the "lat worst". So I ask myself, out of which interval comes the updated 182
>>> value?
>> If your machine is highly loaded, like what you get with a ping -f, the
>> "display" thread, which is a non real-time one, may be delayed for more
>> than one second, in which case, it "misses", what is sent by the
>> "sampling" thread, but the sampling thread never looses the worst
>> latency itself, so that when the display thread finally manages to print
>> something, it will print the correct worst case latency.
>>
> 
> Bingo. That's the point. This also explains totally equal lines and missing time
> stamps/lines that I have observed.

Yes, the communication between the sampling and display threads is a
semaphore, so when the display thread is delayed, it will get the
semaphore several times in a row and print the same values.

If your patch is for a machine in the mainline linux, I would be happy
to merge your changes into the I-pipe patch.

It would be interesting if you could try a recent patch with the "FCSE"
option, to see if it works for 926 (it was tested for 920 and xscale
only), and what gains you get on latencies.

-- 
					    Gilles.

Re: [Xenomai-help] strange latency output (xenomai-2.4.5)

[Georg Gottleuber]

Gilles Chanteperdrix schrieb:
> Georg Gottleuber wrote:
>> Gilles Chanteperdrix schrieb:
>>> Georg Gottleuber wrote:
>>>> Gilles Chanteperdrix schrieb:
>>>>> Georg Gottleuber wrote:
>>>>>> Hi,
>>>>>>
>>>>>> I recently port a  ARM926EJ-S mach to Xenomai
>>>>>> (like described in http://www.xenomai.org/index.php/I-pipe:ArmPorting).
>>>>>>
>>>>>> While testing with latency I got this output:
>>>>>> # /usr/xenomai/bin/latency  -p 1000 -h -s -H 500 -t 1
>>>>>> == Sampling period: 1000 us
>>>>>> == Test mode: in-kernel periodic task
>>>>>> == All results in microseconds
>>>>>> warming up...
>>>>>> RTT|  00:00:01  (in-kernel periodic task, 1000 us period, priority 99)
>>>>>> RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
>>>>>> RTD|      78.992|     104.308|     124.131|       0|      78.992|     124.131
>>>>>> ...
>>>>>> RTD|      14.678|      68.413|      96.275|       0|       9.528|     155.321
>>>>>> RTD|      84.046|     116.435|     175.192|       0|       9.528|     182.139
>>>>>> ...                                ^^^^^^^                            ^^^^^^^
>>>>> I do not understand, what is wrong with these values ?
>>>> It thought, if "lat max" of the current interval is bigger than "lat worst", this "lat
>>>> max" updates the "lat worst". So I ask myself, out of which interval comes the updated 182
>>>> value?
>>> If your machine is highly loaded, like what you get with a ping -f, the
>>> "display" thread, which is a non real-time one, may be delayed for more
>>> than one second, in which case, it "misses", what is sent by the
>>> "sampling" thread, but the sampling thread never looses the worst
>>> latency itself, so that when the display thread finally manages to print
>>> something, it will print the correct worst case latency.
>>>
>> Bingo. That's the point. This also explains totally equal lines and missing time
>> stamps/lines that I have observed.
> 
> Yes, the communication between the sampling and display threads is a
> semaphore, so when the display thread is delayed, it will get the
> semaphore several times in a row and print the same values.
> 
> If your patch is for a machine in the mainline linux, I would be happy
> to merge your changes into the I-pipe patch.

The merge to mainline is in progress (look for PNX8181).