intermittent tests/posix/common/ failure

[andrewboie]

Seen on x86, probably affects others

----------------sanity-out/qemu_x86/tests/posix/common/portability.posix/handler.log----------------
�cSeaBIOS (version rel-1.11.2-0-gf9626ccb91-prebuilt.qemu-project.org)
Booting from ROM..***** Booting Zephyr OS zephyr-v1.13.0-4051-g44906b118f *****
Running test suite posix_apis
===================================================================
starting test - 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
===================================================================
starting test - 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
===================================================================
starting test - test_posix_multiple_threads_single_key

Different threads set different values to same key:
thread 0: set value = 4207348 and retrieved value = 4207348
thread 1: set value = 4207604 and retrieved value = 4207604

PASS - test_posix_multiple_threads_single_key
===================================================================
starting test - test_posix_single_thread_multiple_keys

Single thread associates its value with different keys:
key 0: set value = 4207092 and retrieved value = 4207092
key 1: set value = 4207092 and retrieved value = 4207092

PASS - test_posix_single_thread_multiple_keys
===================================================================
starting test - test_posix_clock
POSIX clock APIs
POSIX clock APIs test done
PASS - test_posix_clock
===================================================================
starting test - test_posix_semaphore
PASS - test_posix_semaphore
===================================================================
starting test - test_posix_normal_mutex
mutex lock is taken
PASS - test_posix_normal_mutex
===================================================================
starting test - test_posix_recursive_mutex
recrusive mutex lock is taken
PASS - test_posix_recursive_mutex
===================================================================
starting test - test_posix_mqueue
PASS - test_posix_mqueue
===================================================================
starting test - test_posix_realtime
POSIX clock set APIs

    Assertion failed at /home/buildslave/src/github.com/zephyrproject-rtos/zephyr/tests/posix/common/src/clock.c:112: test_posix_realtime: (error < 110 is false)
Clock inaccurate
FAIL - test_posix_realtime
===================================================================
starting test - test_posix_timer
POSIX timer test
Timer fires every 0 secs and  100000000 nsecs
Time remaining to fire 0 secs and  890000000 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
===================================================================
starting test - test_posix_rw_lock

main acquire WR lock and 3 threads acquire RD lock
Thread 2 scheduling policy = 1 & priority 3 started
Not able to get RD lock on trying, try again
Thread 1 scheduling policy = 1 & priority 2 started
Not able to get RD lock on trying, try again
Thread 0 scheduling policy = 1 & priority 1 started
Not able to get RD lock on trying, try again
Parent thread releasing WR lock
Thread 2 got RD lock
Thread 1 got RD lock
Thread 0 got RD lock
Parent thread acquiring WR lock again
Thread 2 releasing RD lock
Thread 2 acquiring WR lock
Thread 1 releasing RD lock
Thread 1 acquiring WR lock
Thread 0 releasing RD lock
Parent thread acquired WR lock again
Thread 0 acquiring WR lock
Parent thread releasing WR lock again

3 threads acquire WR lock
Main thread acquiring RD lock
Thread 2 acquired WR lock
Thread 2 releasing WR lock
Main thread acquired RD lock
Main thread releasing RD lock
Thread 1 acquired WR lock
Thread 1 releasing WR lock
Thread 0 acquired WR lock
Thread 0 releasing WR lock
PASS - test_posix_rw_lock
===================================================================
Test suite posix_apis failed.
===================================================================
PROJECT EXECUTION FAILED
----------------sanity-out/qemu_x86/tests/posix/common/portability.posix/handler.log----------------

[andyross]

FWIW: this is almost certainly resolved by all the workarounds detailed in #12553, but the testing I did there was against the tests/kernel directory so I don't have numbers on this specific test. Will rerun it overnight and close once I do.

[andyross]

Yeah, this is a timing phantom. I got through 200 runs for each of the variants of this test (all qemu variants, with and without newlib) using a fast[1] fedora[2] machine with the unloaded sanity runner script[3] from #12553 with zero failures on any.

[1] Hosts slower than ~3GHz fall behind on ARM userspace
[2] Fedora has CONFIG_HZ=1000, which is needed for precision on some tests
[3] Sanitycheck runs threads with nontrivial CPU load simultaneous to qemu and steals cycles