Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

tests/kernel/common seems to fail on nrf52833dk_nrf52833 #32072

Closed
ioannisg opened this issue Feb 8, 2021 · 13 comments
Closed

tests/kernel/common seems to fail on nrf52833dk_nrf52833 #32072

ioannisg opened this issue Feb 8, 2021 · 13 comments
Assignees
@ioannisg
Labels
bug The issue is a bug, or the PR is fixing a bug priority: low Low impact/importance bug Stale

Comments

@ioannisg
Copy link
Member

ioannisg commented Feb 8, 2021

Describe the bug
tests/kernel/common tests variants all fail on nrf52833dk_nrf52833

To Reproduce
Steps to reproduce the behavior:

  1. mkdir build; cd build
  2. cmake -DBOARD=nrf52833dk_nrf52833
  3. make
  4. See error

Expected behavior
The test should not assert.

Impact
Should fix this before release.

Logs and console output

DEBUG   - DEVICE: ***** delaying boot 500ms (per build configuration) *****
DEBUG   - DEVICE: *** Booting Zephyr OS build v2.5.0-rc3-2-g89a909633434  (delayed boot 500ms) ***
DEBUG   - DEVICE: Running test suite common
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_bootdelay
DEBUG   - DEVICE: PASS - test_bootdelay
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_irq_offload
DEBUG   - DEVICE: PASS - test_irq_offload
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_byteorder_memcpy_swap
DEBUG   - DEVICE: PASS - test_byteorder_memcpy_swap
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_byteorder_mem_swap
DEBUG   - DEVICE: PASS - test_byteorder_mem_swap
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_be64
DEBUG   - DEVICE: PASS - test_sys_get_be64
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_be64
DEBUG   - DEVICE: PASS - test_sys_put_be64
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_be48
DEBUG   - DEVICE: PASS - test_sys_get_be48
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_be48
DEBUG   - DEVICE: PASS - test_sys_put_be48
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_be32
DEBUG   - DEVICE: PASS - test_sys_get_be32
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_be32
DEBUG   - DEVICE: PASS - test_sys_put_be32
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_be24
DEBUG   - DEVICE: PASS - test_sys_get_be24
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_be24
DEBUG   - DEVICE: PASS - test_sys_put_be24
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_be16
DEBUG   - DEVICE: PASS - test_sys_get_be16
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_be16
DEBUG   - DEVICE: PASS - test_sys_put_be16
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_le16
DEBUG   - DEVICE: PASS - test_sys_get_le16
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_le16
DEBUG   - DEVICE: PASS - test_sys_put_le16
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_le24
DEBUG   - DEVICE: PASS - test_sys_get_le24
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_le24
DEBUG   - DEVICE: PASS - test_sys_put_le24
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_le32
DEBUG   - DEVICE: PASS - test_sys_get_le32
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_le32
DEBUG   - DEVICE: PASS - test_sys_put_le32
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_le48
DEBUG   - DEVICE: PASS - test_sys_get_le48
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_le48
DEBUG   - DEVICE: PASS - test_sys_put_le48
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_le64
DEBUG   - DEVICE: PASS - test_sys_get_le64
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_le64
DEBUG   - DEVICE: PASS - test_sys_put_le64
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_atomic
DEBUG   - DEVICE: PASS - test_atomic
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_bitfield
DEBUG   - DEVICE: SKIP - test_bitfield
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_printk
DEBUG   - DEVICE: 22 113 10000 32768 40000 22
DEBUG   - DEVICE: p 112 -10000 -32768 -40000 -22
DEBUG   - DEVICE: 0x1 0x01 0x0001 0x00000001 0x0000000000000001
DEBUG   - DEVICE: 0x1 0x 1 0x   1 0x       1
DEBUG   - DEVICE: 42 42 0042 00000042
DEBUG   - DEVICE: -42 -42 -042 -0000042
DEBUG   - DEVICE: 42 42   42       42
DEBUG   - DEVICE: 42 42 0042 00000042
DEBUG   - DEVICE: 255     42    abcdef        42
DEBUG   - DEVICE: 68719476735 -1 18446744073709551615 ffffffffffffffff
DEBUG   - DEVICE: 0xcafebabe 0xbeef 0x2a
DEBUG   - DEVICE: PASS - test_printk
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_timeout_order
DEBUG   - DEVICE: thread 0 synced on timer 0
DEBUG   - DEVICE: thread 1 synced on timer 1
DEBUG   - DEVICE: thread 2 synced on timer 2
DEBUG   - DEVICE: PASS - test_timeout_order
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_clock_uptime
DEBUG   - DEVICE: PASS - test_clock_uptime
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_clock_cycle
DEBUG   - DEVICE: PASS - test_clock_cycle
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_version
DEBUG   - DEVICE: PASS - test_version
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_multilib
DEBUG   - DEVICE: PASS - test_multilib
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_thread_context
DEBUG   - DEVICE: PASS - test_thread_context
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_ms_time_duration
DEBUG   - DEVICE:
DEBUG   - DEVICE: Assertion failed at WEST_TOPDIR/zephyr/tests/kernel/common/src/clock.c:211: test_ms_time_duration: (tdata.duration_count == 1 is false)
DEBUG   - DEVICE: duration 0 not 1
DEBUG   - DEVICE: FAIL - test_ms_time_duration
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_bounds_check_mitigation
DEBUG   - DEVICE: PASS - test_bounds_check_mitigation
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: Test suite common failed.
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: PROJECT EXECUTION FAILED

Environment (please complete the following information):

  • OS: (e.g. Linux, MacOS, Windows): Ubuntu 20.04 LTS
  • Toolchain (e.g Zephyr SDK, ...): Zephyr SDK
  • Commit SHA or Version used: 89a9096

Additional context

  • I tested nRF52dk, nrf5340dk and the test is passing. Might be only this platform that fails.
@ioannisg ioannisg added bug The issue is a bug, or the PR is fixing a bug priority: high High impact/importance bug labels Feb 8, 2021
@ioannisg
Copy link
Member Author

ioannisg commented Feb 8, 2021

@carlescufi @anangl @pabigot I would appreciate if anyone else could test on this board and provide feedback.

@PerMac
Copy link
Member

PerMac commented Feb 8, 2021

I don't have nrf52833 in my setups. I've run this test on nrf52dk_nrf52832, nrf9160dk_nrf9160 and nrf52840dk_nrf52840 and all tests passed from this suite

@jfischer-no
Copy link
Collaborator

@ioannisg Tested it on nrf52833dk_nrf52833 version 0.9.0 and 1.0.0, all test pass.

@ioannisg
Copy link
Member Author

ioannisg commented Feb 8, 2021

@ioannisg Tested it on nrf52833dk_nrf52833 version 0.9.0 and 1.0.0, all test pass.

Thanks @jfischer-no I think I've got board revision 0.7.1 - that might be explaining why this fails. Going to remove the blocking priority.

@ioannisg ioannisg removed the priority: high High impact/importance bug label Feb 8, 2021
@anangl
Copy link
Member

anangl commented Feb 8, 2021

@ioannisg FWIW I've just run the test on my board which is revision 0.7.0, and all test cases passed.

@pabigot
Copy link
Collaborator

pabigot commented Feb 8, 2021

@ioannisg I also don't have this board.

You might try running samples/boards/nrf/clock_skew on your board, and compare the error to those of another Nordic board that passes. This tests uses HFCLK to time LFCLK, and a high skew between those clocks is often the source of similar errors. (May sure the clock config is the same as the application uses.)

@nashif nashif assigned ioannisg and unassigned nashif Feb 8, 2021
@ioannisg
Copy link
Member Author

ioannisg commented Feb 8, 2021

Will try that, thanks @pabigot

@ioannisg
Copy link
Member Author

ioannisg commented Feb 8, 2021 •
edited
Loading

@pabigot this is what I getting when i run the sample on my nrf52833 board:

Ty  Latest           Base             Span             Err
HF  00:03:23.060486  00:00:00.015646  00:03:23.044840
LF  00:03:20.804565  00:00:00.410064  00:03:20.394500 -00:00:02.650340
Skew 1.013226 ; err -13225555 ppb

And this is what i get on my nrf52832 board

Ty  Latest           Base             Span             Err
HF  00:00:20.270287  00:00:00.015638  00:00:20.254648
LF  00:00:20.533050  00:00:00.503265  00:00:20.029785 -00:00:00.224863
Skew 1.011226 ; err -11226415 ppb

Could that difference explain the error I see?
@anangl @jfischer-no could you compare this with your findings by running the sample on your boards?

@pabigot
Copy link
Collaborator

pabigot commented Feb 8, 2021

@ioannisg You should let that run for a while; the first reading doesn't have enough duration to estimate accurately. See the output in the sample README. I'd give it at least five minutes.

But yes, that's unusual from my perspective, first in that the skews are negative (LFCLK runs slower than HFCLK) and in magnitude (your skews are at least twice what I see). The sign is most likely to be a problem with the test.

@ioannisg
Copy link
Member Author

ioannisg commented Feb 8, 2021

I'll get back to this with new data @pabigot thanks.

@pabigot pabigot mentioned this issue Feb 8, 2021
Closed
@pabigot
Copy link
Collaborator

pabigot commented Feb 8, 2021 •
edited
Loading

The sign is most likely to be a the cause of the problem with the test.

By which I mean that the test is more likely to be robust if LFCLK is faster than HFCLK, because the timer will fire and increase the count early. If LFCLK is slower the spinning wait will complete before the timer fires. Especially as your board is showing an error of 1.3% so the 1 ms slop as an upper bound is insufficient: you would have to wait for 1.12 additional ms to pass.

You could test that by changing:

        k_busy_wait((DURATION + 1) * 1000);

to

        k_busy_wait((DURATION + 2) * 1000);

@jfischer-no
Copy link
Collaborator

nrf52833 0.9.0

Ty  Latest           Base             Span             Err
HF  00:10:23.455168  00:00:00.015667  00:10:23.439501
LF  00:10:21.659088  00:00:00.404632  00:10:21.254455 -00:00:02.185046
Skew 1.003517 ; err -3517150 ppb

nrf52833 1.0.0

Ty  Latest           Base             Span             Err                                    
HF  00:10:23.760501  00:00:00.015667  00:10:23.744834                                         
LF  00:10:21.651428  00:00:00.397583  00:10:21.253845 -00:00:02.490989                        
Skew 1.004010 ; err -4009604 ppb

@nashif nashif added the priority: low Low impact/importance bug label Feb 9, 2021
@github-actions
Copy link

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.

@github-actions github-actions bot added the Stale label Apr 11, 2021
@ioannisg ioannisg reopened this Apr 26, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ioannisg ioannisg

Labels
bug The issue is a bug, or the PR is fixing a bug priority: low Low impact/importance bug Stale
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@nashif @pabigot @ioannisg @jfischer-no @anangl @PerMac