[U-Boot] [PATCH 1/1] test/py/tests/test_sleep.py: test time approximately

[U-Boot] [PATCH 1/1] test/py/tests/test_sleep.py: test time approximately

[Heinrich Schuchardt]

On qemu errors like
assert 2.999650001525879 >= 3
occur.

According to the comment in the code the test is meant to be
approximate. So we should accept some milliseconds less.

Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
---
 test/py/tests/test_sleep.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/test/py/tests/test_sleep.py b/test/py/tests/test_sleep.py
index b59a4cfc0f..5f0c4c2bfc 100644
--- a/test/py/tests/test_sleep.py
+++ b/test/py/tests/test_sleep.py
@@ -17,7 +17,7 @@ def test_sleep(u_boot_console):
     u_boot_console.run_command('sleep %d' % sleep_time)
     tend = time.time()
     elapsed = tend - tstart
-    assert elapsed >= sleep_time
+    assert elapsed >= (sleep_time - 0.25)
     if not u_boot_console.config.gdbserver:
         # 0.25s margin is hopefully enough to account for any system overhead.
         assert elapsed < (sleep_time + 0.25)
-- 
2.14.1

[U-Boot] [PATCH 1/1] test/py/tests/test_sleep.py: test time approximately

[Stephen Warren]

On 10/05/2017 01:52 PM, Heinrich Schuchardt wrote:
> On qemu errors like
> assert 2.999650001525879 >= 3
> occur.

Can you work out why? I guess 1-999650001525879 is a really tiny amount, 
so perhaps it's OK. However, I'd like to keep the test strict if 
possible; maybe rather than:

 > +    assert elapsed >= (sleep_time - 0.25)

can we use:

 > +    assert elapsed >= (sleep_time - 0.01)

?

> According to the comment in the code the test is meant to be
> approximate. So we should accept some milliseconds less.

This test is deliberately very strict about the minimum time taken 
during sleep, and slightly sloppy about over-sleeping. That's because 
sleep should never wait too little time, but we allow a little extra 
time due to e.g. the test system being a bit busy and not noticing when 
the sleep wakes up.

[U-Boot] [PATCH 1/1] test/py/tests/test_sleep.py: test time approximately

[Tom Rini]

On Thu, Oct 05, 2017 at 03:10:43PM -0600, Stephen Warren wrote:
> On 10/05/2017 01:52 PM, Heinrich Schuchardt wrote:
> >On qemu errors like
> >assert 2.999650001525879 >= 3
> >occur.
> 
> Can you work out why? I guess 1-999650001525879 is a really tiny amount, so
> perhaps it's OK. However, I'd like to keep the test strict if possible;
> maybe rather than:

It would be good to know.  Today we just always skip this on all qemu
targets as it fails like this much of the time.

-- 
Tom
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 819 bytes
Desc: not available
URL: <http://lists.denx.de/pipermail/u-boot/attachments/20171005/b945e2ae/attachment.sig>

[U-Boot] [PATCH 1/1] test/py/tests/test_sleep.py: test time approximately

[Heinrich Schuchardt]

On 10/05/2017 11:10 PM, Stephen Warren wrote:
> On 10/05/2017 01:52 PM, Heinrich Schuchardt wrote:
>> On qemu errors like
>> assert 2.999650001525879 >= 3
>> occur.
> 
> Can you work out why? I guess 1-999650001525879 is a really tiny amount,
> so perhaps it's OK. However, I'd like to keep the test strict if
> possible; maybe rather than:
> 
>> +    assert elapsed >= (sleep_time - 0.25)
> 
> can we use:
> 
>> +    assert elapsed >= (sleep_time - 0.01)
> 
> ?
> 
>> According to the comment in the code the test is meant to be
>> approximate. So we should accept some milliseconds less.
> 
> This test is deliberately very strict about the minimum time taken
> during sleep, and slightly sloppy about over-sleeping. That's because
> sleep should never wait too little time, but we allow a little extra
> time due to e.g. the test system being a bit busy and not noticing when
> the sleep wakes up.
>

You are making unreasonable assumptions about the accuracy of system clocks.

I am not aware of U-Boot making any guarantees that the clock is never
too fast.

If you want sleep to never consume less time than requested you would at
least always have to add 1 timer tick to the requested time in the sleep
function.

The test does not even use a timer function that is meant to measure
with the accuracy that you expect.

It uses Python function time.time() that is not guaranteed to have a
resolution better than one second and has no guarantee to be non-decreasing.

The right way to measure time for performance measurements is Python 3.3
function time.perf_counter().

QEMU provides no guarantees concerning time synchroniation. So shouldn't
we be happy with the little randomness that we see in some systems, e.g.

3.000195026397705
3.000035047531128
3.000230073928833
2.9996659755706787
3.0026118755340576
3.0025811195373535
3.0034120082855225
3.002816915512085
3.002542018890381
3.0020010471343994

Best regards

Heinrich

[U-Boot] [PATCH 1/1] test/py/tests/test_sleep.py: test time approximately

[Stephen Warren]

On 10/05/2017 04:33 PM, Heinrich Schuchardt wrote:
> On 10/05/2017 11:10 PM, Stephen Warren wrote:
>> On 10/05/2017 01:52 PM, Heinrich Schuchardt wrote:
>>> On qemu errors like
>>> assert 2.999650001525879 >= 3
>>> occur.
>>
>> Can you work out why? I guess 1-999650001525879 is a really tiny amount,
>> so perhaps it's OK. However, I'd like to keep the test strict if
>> possible; maybe rather than:
>>
>>> +    assert elapsed >= (sleep_time - 0.25)
>>
>> can we use:
>>
>>> +    assert elapsed >= (sleep_time - 0.01)
>>
>> ?
>>
>>> According to the comment in the code the test is meant to be
>>> approximate. So we should accept some milliseconds less.
>>
>> This test is deliberately very strict about the minimum time taken
>> during sleep, and slightly sloppy about over-sleeping. That's because
>> sleep should never wait too little time, but we allow a little extra
>> time due to e.g. the test system being a bit busy and not noticing when
>> the sleep wakes up.
> 
> You are making unreasonable assumptions about the accuracy of system clocks.
> 
> I am not aware of U-Boot making any guarantees that the clock is never
> too fast.

It depends what you mean by "too fast".

The intention of this test was to validate that the clock isn't e.g. 2x 
or 10x too fast. I think it's reasonable to assume that U-Boot 
guarantees that, even if there's no written statement to that effect.

"Too fast" isn't intended to mean anything like "no more than 0.5% too 
fast" for example. The current test does have a bug in that regard.

> If you want sleep to never consume less time than requested you would at
> least always have to add 1 timer tick to the requested time in the sleep
> function.

Yes. I've pointed this out at times when working on delay functions in 
the past. Simon Glass said this didn't matter:-(

> The test does not even use a timer function that is meant to measure
> with the accuracy that you expect.
> 
> It uses Python function time.time() that is not guaranteed to have a
> resolution better than one second and has no guarantee to be non-decreasing.

In practice, the resolution typically is far better than one second 
though. I think that aspect of the test is good enough for now, until 
someone needs to run it on some odd host that doesn't have sub-second 
resolution.

> The right way to measure time for performance measurements is Python 3.3
> function time.perf_counter().

Unfortunately, that API doesn't seem to be available on Python 2. The 
test/py code currently supports Python 2, although recently some patches 
were sent to make it work on Python 3 too. Is there an alternative 
that's better than time.time() and works on both Python versions?

> QEMU provides no guarantees concerning time synchroniation. So shouldn't
> we be happy with the little randomness that we see in some systems, e.g.
> 
> 3.000195026397705
> 3.000035047531128
> 3.000230073928833
> 2.9996659755706787
> 3.0026118755340576
> 3.0025811195373535
> 3.0034120082855225
> 3.002816915512085
> 3.002542018890381
> 3.0020010471343994

Yes, I think that level of randomness would be perfectly acceptable. My 
objection is to allowing e.g. the 0.25 second variation that your 
proposed patch allows; I believe that's far too high of a variation. The 
0.01 variation that I proposed for the low side:

 >>> +    assert elapsed >= (sleep_time - 0.01)

... would work just fine for all those values (there is only one value 
in that list less than 3). The allowed variation on the other side 
should be a bit larger (and already is; 0.25 seconds).

[U-Boot] [PATCH v2 1/1] test/py/tests/test_sleep.py: test time approximately

[Heinrich Schuchardt]

On qemu errors like
assert 2.999650001525879 >= 3
occur.

According to the comment in the code the test is meant to be
approximate. So we should accept some milliseconds less.

Cc: Stephen Warren <swarren@nvidia.com>
Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
---
v2
	reduce negative tolerance to 0.01 seconds
	(instead of 0.25) as proposed by Stephen
---
 test/py/tests/test_sleep.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/test/py/tests/test_sleep.py b/test/py/tests/test_sleep.py
index b59a4cfc0f..64e0571326 100644
--- a/test/py/tests/test_sleep.py
+++ b/test/py/tests/test_sleep.py
@@ -17,7 +17,7 @@ def test_sleep(u_boot_console):
     u_boot_console.run_command('sleep %d' % sleep_time)
     tend = time.time()
     elapsed = tend - tstart
-    assert elapsed >= sleep_time
+    assert elapsed >= (sleep_time - 0.01)
     if not u_boot_console.config.gdbserver:
         # 0.25s margin is hopefully enough to account for any system overhead.
         assert elapsed < (sleep_time + 0.25)
-- 
2.14.1

[U-Boot] [PATCH v2 1/1] test/py/tests/test_sleep.py: test time approximately

[Stephen Warren]

On 10/13/2017 02:28 PM, Heinrich Schuchardt wrote:
> On qemu errors like
> assert 2.999650001525879 >= 3
> occur.
> 
> According to the comment in the code the test is meant to be
> approximate. So we should accept some milliseconds less.

Reviewed-by: Stephen Warren <swarren@nvidia.com>

[U-Boot] [U-Boot, v2, 1/1] test/py/tests/test_sleep.py: test time approximately

[Tom Rini]

On Fri, Oct 13, 2017 at 10:28:31PM +0200, Heinrich Schuchardt wrote:

> On qemu errors like
> assert 2.999650001525879 >= 3
> occur.
> 
> According to the comment in the code the test is meant to be
> approximate. So we should accept some milliseconds less.
> 
> Cc: Stephen Warren <swarren@nvidia.com>
> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
> Reviewed-by: Stephen Warren <swarren@nvidia.com>

Applied to u-boot/master, thanks!

-- 
Tom
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 819 bytes
Desc: not available
URL: <http://lists.denx.de/pipermail/u-boot/attachments/20171016/2f07662d/attachment.sig>