All of lore.kernel.org
 help / color / mirror / Atom feed
* an off-by-one error in dm_test_rtc_set_get()?
@ 2021-10-27  4:43 Bin Meng
  2021-10-27 13:22 ` Tom Rini
  0 siblings, 1 reply; 6+ messages in thread
From: Bin Meng @ 2021-10-27  4:43 UTC (permalink / raw)
  To: Simon Glass; +Cc: Tom Rini, U-Boot Mailing List

Hi Simon,

gitlab reported the following test error below:

=================================== FAILURES ===================================
__________________________ test_ut[ut_dm_rtc_set_get] __________________________
test/py/tests/test_ut.py:43: in test_ut
assert output.endswith('Failures: 0')
E AssertionError: assert False
E + where False = <built-in method endswith of str object at
0x7f3bb792dcb0>('Failures: 0')
E + where <built-in method endswith of str object at 0x7f3bb792dcb0> =
'Test: dm_test_rtc_set_get: rtc.c\r\r\nexpected: 27/10/2021
03:38:15\r\r\nactual: 27/10/2021 03:38:14\r\r\ntest/dm/rtc...w, &cmp,
1): Expected 0x0 (0), got 0xffffffea (-22)\r\r\nTest:
dm_test_rtc_set_get: rtc.c (flat tree)\r\r\nFailures: 1'.endswith
----------------------------- Captured stdout call -----------------------------
=>

See https://source.denx.de/u-boot/custodians/u-boot-x86/-/jobs/341905

But the same branch same commit, azure test results passed:
https://dev.azure.com/bmeng/GitHub/_build/results?buildId=460&view=results

It looks like the error is an off-by-one where actual time is 1 second
behind the expected time?

expected: 27/10/2021 03:38:15
actual: 27/10/2021 03:38:14

Is this a known issue?

Regards,
Bin

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: an off-by-one error in dm_test_rtc_set_get()?
  2021-10-27  4:43 an off-by-one error in dm_test_rtc_set_get()? Bin Meng
@ 2021-10-27 13:22 ` Tom Rini
  2021-10-27 13:43   ` Bin Meng
  2021-10-28  7:22   ` Rasmus Villemoes
  0 siblings, 2 replies; 6+ messages in thread
From: Tom Rini @ 2021-10-27 13:22 UTC (permalink / raw)
  To: Bin Meng; +Cc: Simon Glass, U-Boot Mailing List

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

On Wed, Oct 27, 2021 at 12:43:38PM +0800, Bin Meng wrote:
> Hi Simon,
> 
> gitlab reported the following test error below:
> 
> =================================== FAILURES ===================================
> __________________________ test_ut[ut_dm_rtc_set_get] __________________________
> test/py/tests/test_ut.py:43: in test_ut
> assert output.endswith('Failures: 0')
> E AssertionError: assert False
> E + where False = <built-in method endswith of str object at
> 0x7f3bb792dcb0>('Failures: 0')
> E + where <built-in method endswith of str object at 0x7f3bb792dcb0> =
> 'Test: dm_test_rtc_set_get: rtc.c\r\r\nexpected: 27/10/2021
> 03:38:15\r\r\nactual: 27/10/2021 03:38:14\r\r\ntest/dm/rtc...w, &cmp,
> 1): Expected 0x0 (0), got 0xffffffea (-22)\r\r\nTest:
> dm_test_rtc_set_get: rtc.c (flat tree)\r\r\nFailures: 1'.endswith
> ----------------------------- Captured stdout call -----------------------------
> =>
> 
> See https://source.denx.de/u-boot/custodians/u-boot-x86/-/jobs/341905
> 
> But the same branch same commit, azure test results passed:
> https://dev.azure.com/bmeng/GitHub/_build/results?buildId=460&view=results
> 
> It looks like the error is an off-by-one where actual time is 1 second
> behind the expected time?
> 
> expected: 27/10/2021 03:38:15
> actual: 27/10/2021 03:38:14
> 
> Is this a known issue?

Yes, which is why the test checks for a certain amount of "fuzz" around
the return value.  I've wondered about if we need to increase that value
slightly sometimes, or just live with hitting the re-run failed jobs
button on whatever CI system was a bit too slow sometimes.

-- 
Tom

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 659 bytes --]

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: an off-by-one error in dm_test_rtc_set_get()?
  2021-10-27 13:22 ` Tom Rini
@ 2021-10-27 13:43   ` Bin Meng
  2021-10-28  7:22   ` Rasmus Villemoes
  1 sibling, 0 replies; 6+ messages in thread
From: Bin Meng @ 2021-10-27 13:43 UTC (permalink / raw)
  To: Tom Rini; +Cc: Simon Glass, U-Boot Mailing List

On Wed, Oct 27, 2021 at 9:22 PM Tom Rini <trini@konsulko.com> wrote:
>
> On Wed, Oct 27, 2021 at 12:43:38PM +0800, Bin Meng wrote:
> > Hi Simon,
> >
> > gitlab reported the following test error below:
> >
> > =================================== FAILURES ===================================
> > __________________________ test_ut[ut_dm_rtc_set_get] __________________________
> > test/py/tests/test_ut.py:43: in test_ut
> > assert output.endswith('Failures: 0')
> > E AssertionError: assert False
> > E + where False = <built-in method endswith of str object at
> > 0x7f3bb792dcb0>('Failures: 0')
> > E + where <built-in method endswith of str object at 0x7f3bb792dcb0> =
> > 'Test: dm_test_rtc_set_get: rtc.c\r\r\nexpected: 27/10/2021
> > 03:38:15\r\r\nactual: 27/10/2021 03:38:14\r\r\ntest/dm/rtc...w, &cmp,
> > 1): Expected 0x0 (0), got 0xffffffea (-22)\r\r\nTest:
> > dm_test_rtc_set_get: rtc.c (flat tree)\r\r\nFailures: 1'.endswith
> > ----------------------------- Captured stdout call -----------------------------
> > =>
> >
> > See https://source.denx.de/u-boot/custodians/u-boot-x86/-/jobs/341905
> >
> > But the same branch same commit, azure test results passed:
> > https://dev.azure.com/bmeng/GitHub/_build/results?buildId=460&view=results
> >
> > It looks like the error is an off-by-one where actual time is 1 second
> > behind the expected time?
> >
> > expected: 27/10/2021 03:38:15
> > actual: 27/10/2021 03:38:14
> >
> > Is this a known issue?
>
> Yes, which is why the test checks for a certain amount of "fuzz" around
> the return value.  I've wondered about if we need to increase that value
> slightly sometimes, or just live with hitting the re-run failed jobs
> button on whatever CI system was a bit too slow sometimes.
>

Thanks Tom. So it is a known issue. It's just my first time seeing
this failure in CI :)

Regards,
Bin

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: an off-by-one error in dm_test_rtc_set_get()?
  2021-10-27 13:22 ` Tom Rini
  2021-10-27 13:43   ` Bin Meng
@ 2021-10-28  7:22   ` Rasmus Villemoes
  2021-10-28 11:58     ` Tom Rini
  1 sibling, 1 reply; 6+ messages in thread
From: Rasmus Villemoes @ 2021-10-28  7:22 UTC (permalink / raw)
  To: Tom Rini, Bin Meng; +Cc: Simon Glass, U-Boot Mailing List

On 27/10/2021 15.22, Tom Rini wrote:
> On Wed, Oct 27, 2021 at 12:43:38PM +0800, Bin Meng wrote:
>> Hi Simon,
>>
>> gitlab reported the following test error below:
>>
>> =================================== FAILURES ===================================
>> __________________________ test_ut[ut_dm_rtc_set_get] __________________________
>> test/py/tests/test_ut.py:43: in test_ut
>> assert output.endswith('Failures: 0')
>> E AssertionError: assert False
>> E + where False = <built-in method endswith of str object at
>> 0x7f3bb792dcb0>('Failures: 0')
>> E + where <built-in method endswith of str object at 0x7f3bb792dcb0> =
>> 'Test: dm_test_rtc_set_get: rtc.c\r\r\nexpected: 27/10/2021
>> 03:38:15\r\r\nactual: 27/10/2021 03:38:14\r\r\ntest/dm/rtc...w, &cmp,
>> 1): Expected 0x0 (0), got 0xffffffea (-22)\r\r\nTest:
>> dm_test_rtc_set_get: rtc.c (flat tree)\r\r\nFailures: 1'.endswith
>> ----------------------------- Captured stdout call -----------------------------
>> =>
>>
>> See https://source.denx.de/u-boot/custodians/u-boot-x86/-/jobs/341905
>>
>> But the same branch same commit, azure test results passed:
>> https://dev.azure.com/bmeng/GitHub/_build/results?buildId=460&view=results
>>
>> It looks like the error is an off-by-one where actual time is 1 second
>> behind the expected time?
>>
>> expected: 27/10/2021 03:38:15
>> actual: 27/10/2021 03:38:14
>>
>> Is this a known issue?
> 
> Yes, which is why the test checks for a certain amount of "fuzz" around
> the return value. 

You said the same thing about dm_test_rtc_reset() in
https://lore.kernel.org/u-boot/20210831124441.GC858@bill-the-cat/ , but
I can't find anything about any fuzz in the code. Could you point out
where you think that's implemented? In both cases, the expected and
actual values were just 1 from each other, and I fail to see how any
fuzz value could be smaller than that.

 I've wondered about if we need to increase that value
> slightly sometimes, or just live with hitting the re-run failed jobs
> button on whatever CI system was a bit too slow sometimes.

It has nothing to do with a CI being slow, it's plain and simple buggy
test code AFAICT. It's essentially "assert(time(NULL) == time(NULL))".
If a call to time() takes 1us, do this a million times and it will on
average fail once. Obviously, a loaded system increases the chance of
being preempted between the two calls and hence effectively increases
the delta and proportionally the probability of hitting this.

Rasmus

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: an off-by-one error in dm_test_rtc_set_get()?
  2021-10-28  7:22   ` Rasmus Villemoes
@ 2021-10-28 11:58     ` Tom Rini
  2021-11-25  0:11       ` Simon Glass
  0 siblings, 1 reply; 6+ messages in thread
From: Tom Rini @ 2021-10-28 11:58 UTC (permalink / raw)
  To: Rasmus Villemoes; +Cc: Bin Meng, Simon Glass, U-Boot Mailing List

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

On Thu, Oct 28, 2021 at 09:22:30AM +0200, Rasmus Villemoes wrote:
> On 27/10/2021 15.22, Tom Rini wrote:
> > On Wed, Oct 27, 2021 at 12:43:38PM +0800, Bin Meng wrote:
> >> Hi Simon,
> >>
> >> gitlab reported the following test error below:
> >>
> >> =================================== FAILURES ===================================
> >> __________________________ test_ut[ut_dm_rtc_set_get] __________________________
> >> test/py/tests/test_ut.py:43: in test_ut
> >> assert output.endswith('Failures: 0')
> >> E AssertionError: assert False
> >> E + where False = <built-in method endswith of str object at
> >> 0x7f3bb792dcb0>('Failures: 0')
> >> E + where <built-in method endswith of str object at 0x7f3bb792dcb0> =
> >> 'Test: dm_test_rtc_set_get: rtc.c\r\r\nexpected: 27/10/2021
> >> 03:38:15\r\r\nactual: 27/10/2021 03:38:14\r\r\ntest/dm/rtc...w, &cmp,
> >> 1): Expected 0x0 (0), got 0xffffffea (-22)\r\r\nTest:
> >> dm_test_rtc_set_get: rtc.c (flat tree)\r\r\nFailures: 1'.endswith
> >> ----------------------------- Captured stdout call -----------------------------
> >> =>
> >>
> >> See https://source.denx.de/u-boot/custodians/u-boot-x86/-/jobs/341905
> >>
> >> But the same branch same commit, azure test results passed:
> >> https://dev.azure.com/bmeng/GitHub/_build/results?buildId=460&view=results
> >>
> >> It looks like the error is an off-by-one where actual time is 1 second
> >> behind the expected time?
> >>
> >> expected: 27/10/2021 03:38:15
> >> actual: 27/10/2021 03:38:14
> >>
> >> Is this a known issue?
> > 
> > Yes, which is why the test checks for a certain amount of "fuzz" around
> > the return value. 
> 
> You said the same thing about dm_test_rtc_reset() in
> https://lore.kernel.org/u-boot/20210831124441.GC858@bill-the-cat/ , but
> I can't find anything about any fuzz in the code. Could you point out
> where you think that's implemented? In both cases, the expected and
> actual values were just 1 from each other, and I fail to see how any
> fuzz value could be smaller than that.
> 
>  I've wondered about if we need to increase that value
> > slightly sometimes, or just live with hitting the re-run failed jobs
> > button on whatever CI system was a bit too slow sometimes.
> 
> It has nothing to do with a CI being slow, it's plain and simple buggy
> test code AFAICT. It's essentially "assert(time(NULL) == time(NULL))".
> If a call to time() takes 1us, do this a million times and it will on
> average fail once. Obviously, a loaded system increases the chance of
> being preempted between the two calls and hence effectively increases
> the delta and proportionally the probability of hitting this.

You're right, I confused this with the sleep test, which does have a bit
of fuzz to it.

-- 
Tom

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 659 bytes --]

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: an off-by-one error in dm_test_rtc_set_get()?
  2021-10-28 11:58     ` Tom Rini
@ 2021-11-25  0:11       ` Simon Glass
  0 siblings, 0 replies; 6+ messages in thread
From: Simon Glass @ 2021-11-25  0:11 UTC (permalink / raw)
  To: Tom Rini; +Cc: Rasmus Villemoes, Bin Meng, U-Boot Mailing List

Hi,

I filed

https://source.denx.de/u-boot/u-boot/-/issues/4

Regards,
Simon


On Thu, 28 Oct 2021 at 05:58, Tom Rini <trini@konsulko.com> wrote:
>
> On Thu, Oct 28, 2021 at 09:22:30AM +0200, Rasmus Villemoes wrote:
> > On 27/10/2021 15.22, Tom Rini wrote:
> > > On Wed, Oct 27, 2021 at 12:43:38PM +0800, Bin Meng wrote:
> > >> Hi Simon,
> > >>
> > >> gitlab reported the following test error below:
> > >>
> > >> =================================== FAILURES ===================================
> > >> __________________________ test_ut[ut_dm_rtc_set_get] __________________________
> > >> test/py/tests/test_ut.py:43: in test_ut
> > >> assert output.endswith('Failures: 0')
> > >> E AssertionError: assert False
> > >> E + where False = <built-in method endswith of str object at
> > >> 0x7f3bb792dcb0>('Failures: 0')
> > >> E + where <built-in method endswith of str object at 0x7f3bb792dcb0> =
> > >> 'Test: dm_test_rtc_set_get: rtc.c\r\r\nexpected: 27/10/2021
> > >> 03:38:15\r\r\nactual: 27/10/2021 03:38:14\r\r\ntest/dm/rtc...w, &cmp,
> > >> 1): Expected 0x0 (0), got 0xffffffea (-22)\r\r\nTest:
> > >> dm_test_rtc_set_get: rtc.c (flat tree)\r\r\nFailures: 1'.endswith
> > >> ----------------------------- Captured stdout call -----------------------------
> > >> =>
> > >>
> > >> See https://source.denx.de/u-boot/custodians/u-boot-x86/-/jobs/341905
> > >>
> > >> But the same branch same commit, azure test results passed:
> > >> https://dev.azure.com/bmeng/GitHub/_build/results?buildId=460&view=results
> > >>
> > >> It looks like the error is an off-by-one where actual time is 1 second
> > >> behind the expected time?
> > >>
> > >> expected: 27/10/2021 03:38:15
> > >> actual: 27/10/2021 03:38:14
> > >>
> > >> Is this a known issue?
> > >
> > > Yes, which is why the test checks for a certain amount of "fuzz" around
> > > the return value.
> >
> > You said the same thing about dm_test_rtc_reset() in
> > https://lore.kernel.org/u-boot/20210831124441.GC858@bill-the-cat/ , but
> > I can't find anything about any fuzz in the code. Could you point out
> > where you think that's implemented? In both cases, the expected and
> > actual values were just 1 from each other, and I fail to see how any
> > fuzz value could be smaller than that.
> >
> >  I've wondered about if we need to increase that value
> > > slightly sometimes, or just live with hitting the re-run failed jobs
> > > button on whatever CI system was a bit too slow sometimes.
> >
> > It has nothing to do with a CI being slow, it's plain and simple buggy
> > test code AFAICT. It's essentially "assert(time(NULL) == time(NULL))".
> > If a call to time() takes 1us, do this a million times and it will on
> > average fail once. Obviously, a loaded system increases the chance of
> > being preempted between the two calls and hence effectively increases
> > the delta and proportionally the probability of hitting this.
>
> You're right, I confused this with the sleep test, which does have a bit
> of fuzz to it.
>
> --
> Tom

^ permalink raw reply	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2021-11-25  0:12 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-10-27  4:43 an off-by-one error in dm_test_rtc_set_get()? Bin Meng
2021-10-27 13:22 ` Tom Rini
2021-10-27 13:43   ` Bin Meng
2021-10-28  7:22   ` Rasmus Villemoes
2021-10-28 11:58     ` Tom Rini
2021-11-25  0:11       ` Simon Glass

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.