Questiion on commit: demo/cyclictest: fix time delta calculation

Questiion on commit: demo/cyclictest: fix time delta calculation

[Richard Weinberger]

Hello,

I'm investigating into a cyclictest issue where it reports negative values just like this commit states:
https://source.denx.de/Xenomai/xenomai/-/commit/3069a7bbc48559f4d2a6184d6159b771f193a4e9

Since I'm on Xenomai 3.1.2 the said commit is already included.
But I have a hard time to understand what problem the commit actually fixes.
Why is the old calculation wrong?

PREEMPT_RT's rt-test does it the same way:
https://git.kernel.org/pub/scm/utils/rt-tests/rt-tests.git/tree/src/include/rt-utils.h#n60

Except that it casts tv_secs/tv_nsecs to int first, which shouldn't make a difference.

Thanks,
//richard

Re: Questiion on commit: demo/cyclictest: fix time delta calculation

[Bezdeka, Florian]

Hi Richard,

On Fri, 2022-03-04 at 12:35 +0100, Richard Weinberger via Xenomai
wrote:
> Hello,
> 
> I'm investigating into a cyclictest issue where it reports negative values just like this commit states:
> https://source.denx.de/Xenomai/xenomai/-/commit/3069a7bbc48559f4d2a6184d6159b771f193a4e9

Ipipe or Dovetail? Does running "autotune" help?

> 
> Since I'm on Xenomai 3.1.2 the said commit is already included.
> But I have a hard time to understand what problem the commit actually fixes.
> Why is the old calculation wrong?

old code: In case the second wrapped we have
ts1.nsec = <small> (we consider t1 to be the later point in time)
ts2.nsec = <big>

diff += t1 - t2 is now negative. Right?

> 
> PREEMPT_RT's rt-test does it the same way:
> https://git.kernel.org/pub/scm/utils/rt-tests/rt-tests.git/tree/src/include/rt-utils.h#n60
> 
> Except that it casts tv_secs/tv_nsecs to int first, which shouldn't make a difference.
> 
> Thanks,
> //richard
> 

Re: Questiion on commit: demo/cyclictest: fix time delta calculation

[Richard Weinberger]

Florian,

----- Ursprüngliche Mail -----
> Von: "Florian Bezdeka" <florian.bezdeka@siemens.com>
> An: "xenomai" <xenomai@xenomai.org>, "richard" <richard@nod.at>
> Gesendet: Freitag, 4. März 2022 13:01:08
> Betreff: Re: Questiion on commit: demo/cyclictest: fix time delta calculation

> Hi Richard,
> 
> On Fri, 2022-03-04 at 12:35 +0100, Richard Weinberger via Xenomai
> wrote:
>> Hello,
>> 
>> I'm investigating into a cyclictest issue where it reports negative values just
>> like this commit states:
>> https://source.denx.de/Xenomai/xenomai/-/commit/3069a7bbc48559f4d2a6184d6159b771f193a4e9
> 
> Ipipe or Dovetail? Does running "autotune" help?

I'm on ipipe on an arm i.mx6 system. Let me try autotune. :)

>> 
>> Since I'm on Xenomai 3.1.2 the said commit is already included.
>> But I have a hard time to understand what problem the commit actually fixes.
>> Why is the old calculation wrong?
> 
> old code: In case the second wrapped we have
> ts1.nsec = <small> (we consider t1 to be the later point in time)
> ts2.nsec = <big>
> 
> diff += t1 - t2 is now negative. Right?

It did:
> diff = NSEC_PER_SEC * (int64_t)(t1.tv_sec - t2.tv_sec);

At this point diff is always a multiple of NSEC_PER_SEC or 0.
It is only 0 if t1.tv_sec are the same t2.tv_sec value.

> diff += (t1.tv_nsec - t2.tv_nsec);

Here is where we seem to disagree.
t1.tv_nsec - t2.tv_nsec can be negative, yes.
But it can get only negative if t1.tv_sec - t2.tv_sec is non-zero.
So subtracting the negative delta from diff (which is a multiple of NSEC_PER_SEC)
cannot get negative.

Of course the whole calculation works only of the clock does not go backwards.

Thanks,
//richard

Re: Questiion on commit: demo/cyclictest: fix time delta calculation

[Philippe Gerum]

Richard Weinberger via Xenomai <xenomai@xenomai.org> writes:

> Florian,
>
> ----- Ursprüngliche Mail -----
>> Von: "Florian Bezdeka" <florian.bezdeka@siemens.com>
>> An: "xenomai" <xenomai@xenomai.org>, "richard" <richard@nod.at>
>> Gesendet: Freitag, 4. März 2022 13:01:08
>> Betreff: Re: Questiion on commit: demo/cyclictest: fix time delta calculation
>
>> Hi Richard,
>> 
>> On Fri, 2022-03-04 at 12:35 +0100, Richard Weinberger via Xenomai
>> wrote:
>>> Hello,
>>> 
>>> I'm investigating into a cyclictest issue where it reports negative values just
>>> like this commit states:
>>> https://source.denx.de/Xenomai/xenomai/-/commit/3069a7bbc48559f4d2a6184d6159b771f193a4e9
>> 
>> Ipipe or Dovetail? Does running "autotune" help?
>
> I'm on ipipe on an arm i.mx6 system. Let me try autotune. :)
>
>>> 
>>> Since I'm on Xenomai 3.1.2 the said commit is already included.
>>> But I have a hard time to understand what problem the commit actually fixes.
>>> Why is the old calculation wrong?
>> 
>> old code: In case the second wrapped we have
>> ts1.nsec = <small> (we consider t1 to be the later point in time)
>> ts2.nsec = <big>
>> 
>> diff += t1 - t2 is now negative. Right?
>
> It did:
>> diff = NSEC_PER_SEC * (int64_t)(t1.tv_sec - t2.tv_sec);
>
> At this point diff is always a multiple of NSEC_PER_SEC or 0.
> It is only 0 if t1.tv_sec are the same t2.tv_sec value.
>
>> diff += (t1.tv_nsec - t2.tv_nsec);
>
> Here is where we seem to disagree.
> t1.tv_nsec - t2.tv_nsec can be negative, yes.
> But it can get only negative if t1.tv_sec - t2.tv_sec is non-zero.
> So subtracting the negative delta from diff (which is a multiple of NSEC_PER_SEC)
> cannot get negative.
>
> Of course the whole calculation works only of the clock does not go backwards.
>
> Thanks,
> //richard

Florian pointed in the right direction when mentioning autotune: if the
core timer is not calibrated properly, Cobalt might try to compensate
for the basic latency of the platform too much, leading to early timer
shots. If such an early shot arrives and the test loop wakes up too
early, say in the code implementing clock_nanosleep (-n) case, 'next'
might actually be later in the timeline than 'now', leading to negative
differences in calcdiff().

The change in calcdiff() is most likely a plain workaround for this
case, assuming the normalized delta is very unlikely to go over the top
and won't be used as a worst-case figure. The commit log is definitely
misleading.

-- 
Philippe.

Re: Questiion on commit: demo/cyclictest: fix time delta calculation

[Richard Weinberger]

Philippe,

----- Ursprüngliche Mail -----
> Von: "Philippe Gerum" <rpm@xenomai.org>
> Florian pointed in the right direction when mentioning autotune: if the
> core timer is not calibrated properly, Cobalt might try to compensate
> for the basic latency of the platform too much, leading to early timer
> shots. If such an early shot arrives and the test loop wakes up too
> early, say in the code implementing clock_nanosleep (-n) case, 'next'
> might actually be later in the timeline than 'now', leading to negative
> differences in calcdiff().

I did some more experiments. The system was already autotuned.
But raising the base interval from 1000 (default) to 5000 made the issue
go away.

Thanks,
//richard

Re: Questiion on commit: demo/cyclictest: fix time delta calculation

[Philippe Gerum]

Richard Weinberger <richard@nod.at> writes:

> Philippe,
>
> ----- Ursprüngliche Mail -----
>> Von: "Philippe Gerum" <rpm@xenomai.org>
>> Florian pointed in the right direction when mentioning autotune: if the
>> core timer is not calibrated properly, Cobalt might try to compensate
>> for the basic latency of the platform too much, leading to early timer
>> shots. If such an early shot arrives and the test loop wakes up too
>> early, say in the code implementing clock_nanosleep (-n) case, 'next'
>> might actually be later in the timeline than 'now', leading to negative
>> differences in calcdiff().
>
> I did some more experiments. The system was already autotuned.
> But raising the base interval from 1000 (default) to 5000 made the issue
> go away.
>

Does the issue persist at any freq when resetting the clock gravity for
user-space timers to zero instead of (or after) autotuning? e.g.

$ echo "0u" > /proc/xenomai/clock/coreclck

-- 
Philippe.

Re: Questiion on commit: demo/cyclictest: fix time delta calculation

[Richard Weinberger]

Philippe,

----- Ursprüngliche Mail -----
> Von: "Philippe Gerum" <rpm@xenomai.org>
>> I did some more experiments. The system was already autotuned.
>> But raising the base interval from 1000 (default) to 5000 made the issue
>> go away.
>>
> 
> Does the issue persist at any freq when resetting the clock gravity for
> user-space timers to zero instead of (or after) autotuning? e.g.
> 
> $ echo "0u" > /proc/xenomai/clock/coreclck

Actually with 0u I get the best results.
Sometimes it takes up to a few minutes until I get negative values
but with values computed autotuned the timings turn negative almost immediately.

$ echo 6333u > /proc/xenomai/clock/coreclk # computed by autotune
$ ./demo/posix/cyclictest/cyclictest -l10000 -m -Sp99 -i100 -n --nsecs
# /dev/cpu_dma_latency set to 0us
policy: fifo: loadavg: 0.00 0.00 0.08 1/81 5159          

T: 0 ( 5158) P:99 I:100 C:  10000 Min:      0 Act:    2999 Avg:2147483647 Max:      -1
T: 1 ( 5159) P:99 I:600 C:   1680 Min:    333 Act:     999 Avg:    1097 Max:    8000

$ echo 0u > /proc/xenomai/clock/coreclk 
$ ./demo/posix/cyclictest/cyclictest -l10000 -m -Sp99 -i100 -n --nsecs
# /dev/cpu_dma_latency set to 0us
policy: fifo: loadavg: 0.00 0.00 0.08 1/81 5176          

T: 0 ( 5175) P:99 I:100 C:  10000 Min:   6000 Act:    6667 Avg:    9236 Max:   20000
T: 1 ( 5176) P:99 I:600 C:   1667 Min:   6000 Act:   14000 Avg:    7444 Max:   15333

Please note that -i100 and -n --nsecs makes the issue appear much faster than without.

Thanks,
//richard