posix_apis: fails at test_posix_realtime for mimxrt1024_evk

[hakehuang]

Describe the bug

Assertion failed at WEST_TOPDIR/zephyr/tests/posix/common/src/clock.c:75: test_posix_realtime: (rts.tv_nsec not equal to mts.tv_nsec)

only this board has such issue, all other rt1xxx series boards are OK.

To Reproduce
Steps to reproduce the behavior:

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

Expected behavior
pass

Impact
posix realtime

Logs and console output

*** Booting Zephyr OS build v2.6.0-rc1-323-gae4fb20f6733  ***

Running test suite posix_apis

===================================================================

START - test_posix_pthread_execution

Thread 0 starting with scheduling policy 0 & priority 15

Thread 1 starting with scheduling policy 0 & priority 15

Thread 2 starting with scheduling policy 0 & priority 15

Bounce test OK

Barrier test OK

 PASS - test_posix_pthread_execution in 0.643 seconds

===================================================================

START - test_posix_pthread_error_condition

 PASS - test_posix_pthread_error_condition in 0.1 seconds

===================================================================

START - test_posix_pthread_termination

Thread 0 starting with a priority of 4

Cancelling thread 0

Thread 1 starting with a priority of 3

Cancelling thread 1

Thread 1 could not be cancelled

Thread 2 starting with a priority of 2

Cancelling thread 2

Thread 3 starting with a priority of 1

Cancelling thread 3

Thread 3 could not be cancelled

 PASS - test_posix_pthread_termination in 1.14 seconds

===================================================================

START - test_posix_multiple_threads_single_key



Different threads set different values to same key:

thread 0: set value = -2147477408 and retrieved value = -2147477408

thread 1: set value = -2147477184 and retrieved value = -2147477184



 PASS - test_posix_multiple_threads_single_key in 0.17 seconds

===================================================================

START - test_posix_single_thread_multiple_keys



Single thread associates its value with different keys:

key 0: set value = -2147476984 and retrieved value = -2147476984

key 1: set value = -2147476984 and retrieved value = -2147476984



 PASS - test_posix_single_thread_multiple_keys in 0.17 seconds

===================================================================

START - test_posix_clock

POSIX clock APIs

POSIX clock APIs test done

 PASS - test_posix_clock in 2.5 seconds

===================================================================

START - test_posix_semaphore

 PASS - test_posix_semaphore in 5.1 seconds

===================================================================

START - test_posix_normal_mutex

mutex lock is taken

 PASS - test_posix_normal_mutex in 0.103 seconds

===================================================================

START - test_posix_recursive_mutex

recrusive mutex lock is taken

 PASS - test_posix_recursive_mutex in 0.3 seconds

===================================================================

START - test_posix_mqueue

 PASS - test_posix_mqueue in 0.11 seconds

===================================================================

START - test_posix_realtime

POSIX clock set APIs



    Assertion failed at WEST_TOPDIR/zephyr/tests/posix/common/src/clock.c:75: test_posix_realtime: (rts.tv_nsec not equal to mts.tv_nsec)

Nanoseconds not equal

 FAIL - test_posix_realtime in 0.17 seconds

===================================================================

START - test_posix_timer

POSIX timer test

Timer fires every 0 secs and  100000000 nsecs

Time remaining to fire 0 secs and  899000000 nsecs

Handler Signal value :20 for 1 times

Handler Signal value :20 for 2 times

Handler Signal value :20 for 3 times

Handler Signal value :20 for 4 times

Handler Signal value :20 for 5 times

Handler Signal value :20 for 6 times

Handler Signal value :20 for 7 times

Handler Signal value :20 for 8 times

Handler Signal value :20 for 9 times

Handler Signal value :20 for 10 times

Handler Signal value :20 for 11 times

Handler Signal value :20 for 12 times

 PASS - test_posix_timer in 2.111 seconds

===================================================================

START - test_posix_rw_lock



main acquire WR lock and 3 threads acquire RD lock

Thread 2 scheParent thread releasing WR lock

duling policParent thread acquiring WR lock again

Parent thread acquired WR lock again

y = 1 & prioParent thread releasing WR lock again



3 threads acquire WR lock

Main thread acquiring RD lock

Main thread acquired RD lock

rity 3 startMain thread releasing RD lock

ed

Thread 2 got RD lock

Thread 1 scThread 2 releasing RD lock

Thread 2 acquiring WR lock

Thread 2 acquired WR lock

heduling polThread 2 releasing WR lock

icy = 1 & priority 2 started

Thread 1 got RD lock

Thread 0 schThread 1 releasing RD lock

Thread 1 acquiring WR lock

Thread 1 acquired WR lock

eduling poliThread 1 releasing WR lock

cy = 1 & priority 1 started

Thread 0 got RD lock

Thread 0 releasing RD lock

Thread 0 acquiring WR lock

Thread 0 acquired WR lock

Thread 0 releasing WR lock

 PASS - test_posix_rw_lock in 0.79 seconds

===================================================================

START - test_nanosleep_NULL_NULL

 PASS - test_nanosleep_NULL_NULL in 0.1 seconds

===================================================================

START - test_nanosleep_NULL_notNULL

 PASS - test_nanosleep_NULL_notNULL in 0.1 seconds

===================================================================

START - test_nanosleep_notNULL_NULL

 PASS - test_nanosleep_notNULL_NULL in 0.1 seconds

===================================================================

START - test_nanosleep_notNULL_notNULL

 PASS - test_nanosleep_notNULL_notNULL in 0.1 seconds

===================================================================

START - test_nanosleep_req_is_rem

 PASS - test_nanosleep_req_is_rem in 0.1 seconds

===================================================================

START - test_nanosleep_n1_0

 PASS - test_nanosleep_n1_0 in 0.1 seconds

===================================================================

START - test_nanosleep_0_n1

 PASS - test_nanosleep_0_n1 in 0.1 seconds

===================================================================

START - test_nanosleep_n1_n1

 PASS - test_nanosleep_n1_n1 in 0.1 seconds

===================================================================

START - test_nanosleep_0_1

 PASS - test_nanosleep_0_1 in 0.1 seconds

===================================================================

START - test_nanosleep_0_1001

 PASS - test_nanosleep_0_1001 in 0.1 seconds

===================================================================

START - test_nanosleep_0_500000000

 PASS - test_nanosleep_0_500000000 in 0.501 seconds

===================================================================

START - test_nanosleep_1_0

 PASS - test_nanosleep_1_0 in 1.1 seconds

===================================================================

START - test_nanosleep_1_1

 PASS - test_nanosleep_1_1 in 1.1 seconds

===================================================================

START - test_nanosleep_1_1001

 PASS - test_nanosleep_1_1001 in 1.1 seconds

===================================================================

START - test_posix_pthread_create_negative

 PASS - test_posix_pthread_create_negative in 0.1 seconds

===================================================================

Test suite posix_apis failed.

===================================================================

PROJECT EXECUTION FAILED

Environment (please complete the following information):

• OS: (e.g. Linux)
• Toolchain (e.g Zephyr SDK, ...)
• Commit SHA or Version used: v2.6.0-rc1-323-gae4fb20f6733

[hakehuang]

@MaureenHelm , @dleach02

[galak]

possibly related to #33544

[cfriedt]

I find the test that is failing to be somewhat confusing.

        ret = clock_gettime(CLOCK_MONOTONIC, &mts);
        zassert_equal(ret, 0, "Fail to get monotonic clock");

        ret = clock_gettime(CLOCK_REALTIME, &rts);
        zassert_equal(ret, 0, "Fail to get realtime clock");

        zassert_equal(rts.tv_sec, mts.tv_sec, "Seconds not equal");
        zassert_equal(rts.tv_nsec, mts.tv_nsec, "Nanoseconds not equal");

• it's entirely feasible that some number of nanoseconds could have expired between the two calls to clock_gettime(), so it's almost as if the test had been designed under the wrong assumption. Assuming that the timer resolution would always be coarse enough is probably not the safest assumption.
• even assuming that CLOCK_REALTIME and CLOCK_MONOTONIC would report the same absolute times is very likely an unsafe assumption (even duration could be different, based on individual clock resolution).
• the test should minimally include a call to clock_getres() (not yet supported)

Some related items do rank fairly high on the nice-to-have scale though (#6498, #25559, #28542) and it would be great to chat about it at the next review.

[PerMac]

I see the exact same failure on nrf9160dk_nrf9160_ns. Other platforms on our farm don't show it.

[dleach02]

I reproduced this on the rt1024_evk I have.

[dleach02]

@cfriedt is correct in his assessment. You can minimize the problem by putting the two clock_gettime() calls back to back without the zassert_equal() check. But I think this test case should account for edge conditions. I converted the tv_nsec to TICKS and did some test runs and when it fails it is typically off by 1 TICK. The "Nanoseconds not equal" should probably be ((rts-mts) <= 1) type of test or make the 1 be some sort of configurable value that would encompass the edge cases.

On the rt1024, there are 10000 ticks per sec so the two calls to have to happen within the same 100usec window.

[cfriedt]

@dleach02 - Thanks for tagging me - improving clocking has been on my to-do list for a very long time. Probably not going to make it for LTS but it would be great to being it up in dev-review at some point

[dleach02]

I looked at this because it initially was flagged against an NXP board. I just received the board and tried it out. The "fix" I was suggesting would be the following:

	k_usleep(1);

	ret = clock_gettime(CLOCK_MONOTONIC, &mts);
	ret2 = clock_gettime(CLOCK_REALTIME, &rts);

	zassert_equal(ret, 0, "Fail to get monotonic clock");
	zassert_equal(ret2, 0, "Fail to get realtime clock");

	zassert_equal(rts.tv_sec, mts.tv_sec, "Seconds not equal");
	zassert_true((k_ns_to_ticks_floor64(rts.tv_nsec) - k_ns_to_ticks_floor64(mts.tv_nsec)) <= 1, "Nanoseconds outside of threshold");

Or remove this particular test case...

[cfriedt]

I would be open to removing the test

[galak]

dev-review: (sept 2, 2021): suggestion to @cfriedt to open an issue to track rfc/enhancement around this area.