ehl_crb: portability.posix.common.posix_realtime failed.

[chen-png]

Bug Description
The posix_realtime test in the /tests/posix/common test suite is failing due to assert:

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)

This is observed in the other configurations of testcase.yml

• portability.posix.common
• portability.posix.common.newlib
• portability.posix.common.tls
• portability.posix.common.tls.newlib

To Reproduce
Steps to reproduce the behavior:

1. Example for a single configuration: west build -b ehl_crb -p auto tests/posix/common/
   --DCONFIG_NEWLIB_LIBC=n
2. copy binary to USB/PXE boot media
3. boot
4. See error

Logs and console output
Booting Zephyr OS build zephyr-v2.5.0-1430-g911ba334a06a
...
START - test_posix_recursive_mutex
recrusive mutex lock is taken
PASS - test_posix_recursive_mutex in 0.4 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.19 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.112 seconds

Environment (please complete the following information):

• OS: Fedora33
• Toolchain: zephyr-sdk-0.12.3
• Commit ID: 911ba33

[jenmwms]

I can reproduce this, looking into root cause.
Also, the bug report describes uses west to reproduce, but wanted to check with @chen-png and @yerabolu if this is observed on the other configurations. When I run this with twister for tests/posix/common/, all (4) configurations fail on this test at this 911ba33. If confirmed, we'll update the bug description.

[jenmwms]

For consideration in debug, Spoorthy and I confirmed this is observed in the other configurations of testcase.yml

• portability.posix.common
• portability.posix.common.newlib
• portability.posix.common.tls
• portability.posix.common.tls.newlib

[jenmwms]

I'm curious when was the last time this was known to be passing? I can reproduce the issue back a couple weeks already 2134f9b:
driver: clock: npcx: remove useless operands. I'll keep going and update here.

[jenmwms]

Got some feedback offline and bisecting may not yield success in this case. Suggested to move forward with debug without bisect point.

[jenmwms]

Printing out the values that fail the zassert_equal( ), we see there is an off by 1 in the index 2 from the left:

DEBUG   - DEVICE: START - test_posix_realtime
DEBUG   - DEVICE: POSIX clock set APIs
DEBUG   - DEVICE: DEBUG - jen - rts.tv_nsec 21800000 mts.tv_nsec 21700000
DEBUG   - DEVICE: 
DEBUG   - DEVICE: Assertion failed at WEST_TOPDIR/zephyr/tests/posix/common/src/clock.c:76: test_posix_realtime: (rts.tv_nsec not equal to mts.tv_nsec)
DEBUG   - DEVICE: Nanoseconds not equal
DEBUG   - DEVICE: FAIL - test_posix_realtime in 0.24 seconds

[jenmwms]

Just saw a recently resolved issue that looks very similar to this issue, #25453. The solution was merged in patch #28516.

If I revert that change by moving the printk( ) after the k_usleep( ), then this issue with tests/posix/common on ehl_crb. Reverting that patch may not be the best solution here, so seeking other options.

@andyross @jhedberg Is there a timing configuration we need to adjust for ehl_crb?

[jenmwms]

This is not observed on acrn_ehl_crb at this point in the code base. A different issue is seen but is easily resolved using the CONFIG_APIC_TIMER_IRQ=48, recently discovered while working on #33593 (merged).

Adding the same APIC timer irq for this native EHL configuration did not resolve the assert observed here.

[jenmwms]

Adding the same APIC timer irq for this native EHL configuration did not resolve the assert observed here.

ehl_crb uses HPET_TIMER. APIC_TIMER is not set on ehl_crb, that is one of the differences between acrn_ehl_crb and ehl_crb.

[jenmwms]

Hi @andyross ! Did you get a chance to look at this test case failing, fixed by moving the printk?

Just saw a recently resolved issue that looks very similar to this issue, #25453. The solution was merged in patch #28516.

If I revert that change by moving the printk( ) after the k_usleep( ), then this issue with tests/posix/common on ehl_crb. Reverting that patch may not be the best solution here, so seeking other options.

[jenmwms]

ping @andyross Can you please offer feedback or recommendation?

[andyross]

Some general ideas:

• Would be interesting to try this with CONFIG_APIC_TSC_DEADLINE_TIMER=y to see if this is specific to the HPET driver or if it's something general.

• Similarly ehl_crb is an SMP platform (and, like up_squared, a very fast one) so it tends to discover races in tests that other platforms don't. Does setting SMP=n or MP_NUM_CPUS=1 also address the problem? If so, was this one of the tests that recently had SMP enabled (there was a big PR that turned SMP on in a lot of places where it wasn't)? If that is true, then it argues that the test was probably always racy and we just never noticed.

[jenmwms]

• Would be interesting to try this with CONFIG_APIC_TSC_DEADLINE_TIMER=y to see if this is specific to the HPET driver or if it's something general.

With that, I get build error (ld) for HPET definitions. There must be a kconfig I need to adjust as well?

[jenmwms]

• Does setting SMP=n or MP_NUM_CPUS=1 also address the problem?

Neither resolved the issue. Thanks for the suggestions!

[jenmwms]

This comment in the test is confusing to me. Why does the test_posix_realtime() tell us to remove the code if we are using posix? and this k_usleep(1) is a known workaround, so its suggested we follow the previous comment of removing the code?

void test_posix_realtime(void)
{
	/* Make sure the realtime and monotonic clocks start out the
	 * same.  This is not true on posix and where there is a
	 * realtime clock, so don't keep this code.
	 */

	int ret;
	struct timespec rts, mts;
	struct timeval tv;

	printk("POSIX clock set APIs\n");

	/* Minimal sleep to align us to the next tick interval. This
	 * helps with a case that 2 consecutive calls to clock_gettime()
	 * below return different values. Note that it's still a workaround,
	 * which may break, in which case follow the suggestion in the
	 * comment above.
	 */
	k_usleep(1);

[jenmwms]

It is not ideal - I know - but noticed this passes with a longer kusleep() (which is a workaround as-is). I extended the sleep by the difference between rts.tv_nsec and mts.tv_nsec is 100000 (100 microseconds):

k_usleep(101);

Is it worth a PR for that? I feel like it may not be acceptable because this kusleep() workaround is meant to be "minimal". However, ehl_crb is a faster board than I think was under consideration at the time this was added.

[andyross]

FWIW: the k_usleep(1) is a tick alignment, not a workaround. The idea is that timer behavior is only deterministic if you start the test at the beginning of an OS tick. Otherwise there are inevitable timer aliasing bugs (think of them as "race conditions against the passage of real time" -- you can't take a lock to stop the universe). So you have to ask the kernel "please sleep until the very next tick expires". And the simplest way to do that is to request a sleep for the smallest unit of time expressible[1].

Playing with timeouts to make this pass makes me nervous, and implies there's something else going on.

[1] Actually there's a nanosecond API now, but nothing uses a MHz+ tick rate so this is shorter and simpler.

[jenmwms]

It looks like there is an issue with clock_gettime(CLOCK_MONOTONIC, &mts);? Perhaps only for this board?

The realtime clock is further tested later in the test sequence, including comparison of gettime API with the gettimeofday API which works as expected [1] with clock_gettime(CLOCK_REALTIME, &rts); with gettimeofday(&tv, NULL);.

As one would expect, at the breakpoint for this bug, when I use the gettimeofday API instead of check against mts, this passes (really just reconfirming comparison described above):

+++ b/tests/posix/common/src/clock.c
@@ -71,8 +71,10 @@ void test_posix_realtime(void)
        ret = clock_gettime(CLOCK_REALTIME, &rts);
        zassert_equal(ret, 0, "Fail to get realtime clock");
 
+       ret = gettimeofday(&tv, NULL);
+
        zassert_equal(rts.tv_sec, mts.tv_sec, "Seconds not equal");
-       zassert_equal(rts.tv_nsec, mts.tv_nsec, "Nanoseconds not equal");
+       zassert_equal(rts.tv_nsec,  tv.tv_usec * NSEC_PER_USEC, "Nanoseconds not equal");

[1] (see

zephyr/tests/posix/common/src/clock.c

Line 142 in 1b129c5

zassert_true(rts.tv_nsec >= tv.tv_usec * NSEC_PER_USEC,

)

[andyross]

This turns out to be a hardware bug. I'm going to close this, there's no point in having this bug in Zephyr's metrics prior to a release, nor in airing Intel's dirty laundry on Github.

Intel folks interested in scrubbing laundry can follow the saga in RTOS-6239

[andyross]

Oh, and I should note:

If there's desire to resolve this test failure in upstream Zephyr for the purposes of tracking or whatever, some workaround in order of my personal preference:

1. Use the APIC_TSC_DEADLINE_TIMER, which is not susceptible to this bug
2. Turn off TICKLESS_KERNEL and use a 100 Hz tick rate, which avoids the slow paths in the HPET hardware
3. Turn the tick rate way down, maybe to 2000 Hz or so, which is more fiddly but would probably work too

[jenmwms]

Hi @andyross - Thanks for noting workarounds. In our sync we considered just excluding ehl_crb for this test case, is that not feasible? Perhaps we cannot exclude for only test_posix_realtime(). This case fails for all configurations in the testcase.yml, how can we exclude the platform for just one test case inside the test suite?

Let's reopen since this will keep showing up. ehl_crb is not excluded and we do not have a workaround implemented so keep this open until resolved, please.

[najumon1980]

Could you please enable TCC Mode in BIOS and verify again ? For enable TCC mode, please go to BIOS "Intel Advance menu" and then go to "Intel(R) Time Coordinated Computing" and then enable "TCC Mode" . This will optimize SOC fabric, memory, etc. for maximum performance for time sensitive application which have stringent real time requirment. Please note that this can impact platform power