tests: posix: test_realtime: improve test reliability

Previously posix_apis.test_realtime was failing (very)
frequently in CI, and in particular, when running on Qemu,
POSIX, or SMP targets.

We are using CLOCK_REALTIME for this test, which incurs an
additional syscall overhead above CLOCK_MONOTONIC. The act
of sleeping itself also incurs a syscall overhead.

The latency from one iteration to the next of the internal
loop is a bit of a random process due to scheduler or clock
noise (although the noise itself is still bounded).

In order to make this test robust against such noise, assert
only on the average time from one iteration to the next,
rather than the instantaneous time.

Rather than calculating a sample mean, use a running average
(aka Cumulative Moving Average) to save some bytes.

Report results, including low and high watermarks before
asserting that the average iteration time within expected
range.

==============================================================
START - test_realtime
I: n: 20, sleep: 100, margin: 10, lo: 110, avg: 110, hi: 110
 PASS - test_realtime in 2.198 seconds
==============================================================

Expect to see the low and high watermarks change more on
Qemu and POSIX platforms when running several jobs in parallel
with twister (such as in CI).

Signed-off-by: Christopher Friedt <cfriedt@meta.com>

tests/posix/common/Kconfig

@@ -0,0 +1,27 @@
+# Copyright (c) 2023, Meta
+# SPDX-License-Identifier: Apache-2.0
+
+# Options specific to clock.c / test_realtime
+
+config TEST_CLOCK_RT_ITERATIONS
+	int "Number of iterations to check clock_gettime() reliability"
+	range 10 100
+	default 20
+	help
+	  This option is specific to posix_apis.test_realtime in clock.c
+
+config TEST_CLOCK_RT_SLEEP_MS
+	int "Time to sleep between iterations in milliseconds"
+	range 50 1000
+	default 100
+	help
+	  This option is specific to posix_apis.test_realtime in clock.c
+
+config TEST_CLOCK_RT_ERROR_MS
+	int "Maximum overshoot (error) in milliseconds"
+	range 10 500
+	default 10
+	help
+	  This option is specific to posix_apis.test_realtime in clock.c
+
+source "Kconfig.zephyr"

tests/posix/common/src/clock.c

@@ -1,5 +1,6 @@
 /*
  * Copyright (c) 2018 Intel Corporation
+ * Copyright (c) 2023, Meta
  *
  * SPDX-License-Identifier: Apache-2.0
  */
@@ -8,118 +9,207 @@
 #include <unistd.h>
 
 #include <zephyr/ztest.h>
+#include <zephyr/logging/log.h>
 
 #define SLEEP_SECONDS 1
 #define CLOCK_INVALID -1
 
-ZTEST(posix_apis, test_clock)
-{
-	int64_t nsecs_elapsed, secs_elapsed;
-	struct timespec ts, te;
+LOG_MODULE_REGISTER(clock_test, LOG_LEVEL_DBG);
 
-	printk("POSIX clock APIs\n");
+/* Set a particular time.  In this case, the output of: `date +%s -d 2018-01-01T15:45:01Z` */
+static const struct timespec ref_ts = {1514821501, NSEC_PER_SEC / 2U};
 
-	/* TESTPOINT: Pass invalid clock type */
-	zassert_equal(clock_gettime(CLOCK_INVALID, &ts), -1,
-			NULL);
-	zassert_equal(errno, EINVAL);
+static const clockid_t clocks[] = {
+	CLOCK_MONOTONIC,
+	CLOCK_REALTIME,
+};
+static const bool settable[] = {
+	false,
+	true,
+};
+
+static inline int64_t ts_to_ns(const struct timespec *ts)
+{
+	return ts->tv_sec * NSEC_PER_SEC + ts->tv_nsec;
+}
+
+static inline void tv_to_ts(const struct timeval *tv, struct timespec *ts)
+{
+	ts->tv_sec = tv->tv_sec;
+	ts->tv_nsec = tv->tv_usec * NSEC_PER_USEC;
+}
 
-	zassert_ok(clock_gettime(CLOCK_MONOTONIC, &ts));
-	zassert_ok(k_sleep(K_SECONDS(SLEEP_SECONDS)));
-	zassert_ok(clock_gettime(CLOCK_MONOTONIC, &te));
+#define _tp_op(_a, _b, _op) (ts_to_ns(_a) _op ts_to_ns(_b))
 
-	if (te.tv_nsec >= ts.tv_nsec) {
-		secs_elapsed = te.tv_sec - ts.tv_sec;
-		nsecs_elapsed = te.tv_nsec - ts.tv_nsec;
-	} else {
-		nsecs_elapsed = NSEC_PER_SEC + te.tv_nsec - ts.tv_nsec;
-		secs_elapsed = (te.tv_sec - ts.tv_sec - 1);
+#define _decl_op(_type, _name, _op)                                                                \
+	static inline _type _name(const struct timespec *_a, const struct timespec *_b)            \
+	{                                                                                          \
+		return _tp_op(_a, _b, _op);                                                        \
 	}
 
-	/*TESTPOINT: Check if POSIX clock API test passes*/
-	zassert_equal(secs_elapsed, SLEEP_SECONDS,
-			"POSIX clock API test failed");
+_decl_op(bool, tp_eq, ==);     /* a == b */
+_decl_op(bool, tp_lt, <);      /* a < b */
+_decl_op(bool, tp_gt, >);      /* a > b */
+_decl_op(bool, tp_le, <=);     /* a <= b */
+_decl_op(bool, tp_ge, >=);     /* a >= b */
+_decl_op(int64_t, tp_diff, -); /* a - b */
+
+/* lo <= (a - b) < hi */
+static inline bool tp_diff_in_range_ns(const struct timespec *a, const struct timespec *b,
+				       int64_t lo, int64_t hi)
+{
+	int64_t diff = tp_diff(a, b);
 
-	printk("POSIX clock APIs test done\n");
+	return diff >= lo && diff < hi;
 }
 
-ZTEST(posix_apis, test_realtime)
+ZTEST(posix_apis, test_clock_gettime)
 {
-	int ret;
-	struct timespec rts, mts;
-	struct timeval tv;
+	struct timespec ts;
 
-	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");
+	/* ensure argument validation is performed */
+	errno = 0;
+	zassert_equal(clock_gettime(CLOCK_INVALID, &ts), -1);
+	zassert_equal(errno, EINVAL);
 
-	/* Set a particular time.  In this case, the output of:
-	 * `date +%s -d 2018-01-01T15:45:01Z`
-	 */
-	struct timespec nts;
-	nts.tv_sec = 1514821501;
-	nts.tv_nsec = NSEC_PER_SEC / 2U;
+	if (false) {
+		/* undefined behaviour */
+		errno = 0;
+		zassert_equal(clock_gettime(clocks[0], NULL), -1);
+		zassert_equal(errno, EINVAL);
+	}
 
-	/* TESTPOINT: Pass invalid clock type */
-	zassert_equal(clock_settime(CLOCK_INVALID, &nts), -1,
-			NULL);
-	zassert_equal(errno, EINVAL);
+	/* verify that we can call clock_gettime() on supported clocks */
+	ARRAY_FOR_EACH(clocks, i)
+	{
+		ts = (struct timespec){-1, -1};
+		zassert_ok(clock_gettime(clocks[i], &ts));
+		zassert_not_equal(ts.tv_sec, -1);
+		zassert_not_equal(ts.tv_nsec, -1);
+	}
+}
 
-	ret = clock_settime(CLOCK_MONOTONIC, &nts);
-	zassert_not_equal(ret, 0, "Should not be able to set monotonic time");
+ZTEST(posix_apis, test_gettimeofday)
+{
+	struct timeval tv;
+	struct timespec ts;
+	struct timespec rts;
+
+	if (false) {
+		/* undefined behaviour */
+		errno = 0;
+		zassert_equal(gettimeofday(NULL, NULL), -1);
+		zassert_equal(errno, EINVAL);
+	}
 
-	ret = clock_settime(CLOCK_REALTIME, &nts);
-	zassert_equal(ret, 0, "Fail to set realtime clock");
+	/* Validate gettimeofday API */
+	zassert_ok(gettimeofday(&tv, NULL));
+	zassert_ok(clock_gettime(CLOCK_REALTIME, &rts));
 
-	/*
-	 * Loop 20 times, sleeping a little bit for each, making sure
-	 * that the arithmetic roughly makes sense.  This tries to
-	 * catch all of the boundary conditions of the clock to make
-	 * sure there are no errors in the arithmetic.
+	/* TESTPOINT: Check if time obtained from
+	 * gettimeofday is same or more than obtained
+	 * from clock_gettime
 	 */
-	int64_t last_delta = 0;
-	for (int i = 1; i <= 20; i++) {
-		usleep(USEC_PER_MSEC * 90U);
-		ret = clock_gettime(CLOCK_REALTIME, &rts);
-		zassert_equal(ret, 0, "Fail to read realtime clock");
+	tv_to_ts(&tv, &ts);
+	zassert_true(tp_ge(&rts, &ts));
+}
 
-		int64_t delta =
-			((int64_t)rts.tv_sec * NSEC_PER_SEC -
-			 (int64_t)nts.tv_sec * NSEC_PER_SEC) +
-			((int64_t)rts.tv_nsec - (int64_t)nts.tv_nsec);
+ZTEST(posix_apis, test_clock_settime)
+{
+	int64_t diff_ns;
+	struct timespec ts = {0};
 
-		/* Make the delta milliseconds. */
-		delta /= (NSEC_PER_SEC / 1000U);
+	BUILD_ASSERT(ARRAY_SIZE(settable) == ARRAY_SIZE(clocks));
 
-		zassert_true(delta > last_delta, "Clock moved backward");
-		int64_t error = delta - last_delta;
+	/* ensure argument validation is performed */
+	errno = 0;
+	zassert_equal(clock_settime(CLOCK_INVALID, &ts), -1);
+	zassert_equal(errno, EINVAL);
 
-		/* printk("Delta %d: %lld\n", i, delta); */
+	if (false) {
+		/* undefined behaviour */
+		errno = 0;
+		zassert_equal(clock_settime(CLOCK_REALTIME, NULL), -1);
+		zassert_equal(errno, EINVAL);
+	}
 
-		/* Allow for a little drift upward, but not
-		 * downward
-		 */
-		zassert_true(error >= 90, "Clock inaccurate %d", error);
-		zassert_true(error <= 110, "Clock inaccurate %d", error);
+	/* verify nanoseconds */
+	errno = 0;
+	ts = (struct timespec){0, NSEC_PER_SEC};
+	zassert_equal(clock_settime(CLOCK_REALTIME, &ts), -1);
+	zassert_equal(errno, EINVAL);
+	errno = 0;
+	ts = (struct timespec){0, -1};
+	zassert_equal(clock_settime(CLOCK_REALTIME, &ts), -1);
+	zassert_equal(errno, EINVAL);
 
-		last_delta = delta;
+	ARRAY_FOR_EACH(clocks, i)
+	{
+		if (!settable[i]) {
+			/* should fail attempting to set unsettable clocks */
+			errno = 0;
+			zassert_equal(clock_settime(clocks[i], &ts), -1);
+			zassert_equal(errno, EINVAL);
+			continue;
+		}
+
+		zassert_ok(clock_settime(clocks[i], &ref_ts));
+
+		/* read-back the time */
+		zassert_ok(clock_gettime(clocks[i], &ts));
+		/* dt should be >= 0, but definitely <= 1s */
+		diff_ns = tp_diff(&ts, &ref_ts);
+		zassert_true(diff_ns >= 0 && diff_ns <= NSEC_PER_SEC);
 	}
+}
 
-	/* Validate gettimeofday API */
-	ret = gettimeofday(&tv, NULL);
-	zassert_equal(ret, 0);
+ZTEST(posix_apis, test_realtime)
+{
+	struct timespec then, now;
+	/*
+	 * For calculating cumulative moving average
+	 * Note: we do not want to assert any individual samples due to scheduler noise.
+	 * The CMA filters out the noise so we can make an assertion (on average).
+	 * https://en.wikipedia.org/wiki/Moving_average#Cumulative_moving_average
+	 */
+	int64_t cma_prev = 0;
+	int64_t cma;
+	int64_t x_i;
+	/* lower and uppoer boundary for assertion */
+	int64_t lo = CONFIG_TEST_CLOCK_RT_SLEEP_MS;
+	int64_t hi = CONFIG_TEST_CLOCK_RT_SLEEP_MS + CONFIG_TEST_CLOCK_RT_ERROR_MS;
+	/* lower and upper watermark */
+	int64_t lo_wm = INT64_MAX;
+	int64_t hi_wm = INT64_MIN;
+
+	/* Loop n times, sleeping a little bit for each */
+	(void)clock_gettime(CLOCK_REALTIME, &then);
+	for (int i = 0; i < CONFIG_TEST_CLOCK_RT_ITERATIONS; ++i) {
+
+		zassert_ok(k_usleep(USEC_PER_MSEC * CONFIG_TEST_CLOCK_RT_SLEEP_MS));
+		(void)clock_gettime(CLOCK_REALTIME, &now);
 
-	ret = clock_gettime(CLOCK_REALTIME, &rts);
-	zassert_equal(ret, 0);
+		/* Make the delta milliseconds. */
+		x_i = tp_diff(&now, &then) / NSEC_PER_MSEC;
+		then = now;
+
+		if (x_i < lo_wm) {
+			/* update low watermark */
+			lo_wm = x_i;
+		}
+
+		if (x_i > hi_wm) {
+			/* update high watermark */
+			hi_wm = x_i;
+		}
+
+		/* compute cumulative running average */
+		cma = (x_i + i * cma_prev) / (i + 1);
+		cma_prev = cma;
+	}
 
-	/* TESTPOINT: Check if time obtained from
-	 * gettimeofday is same or more than obtained
-	 * from clock_gettime
-	 */
-	zassert_true(rts.tv_sec >= tv.tv_sec, "gettimeofday didn't"
-			" provide correct result");
-	zassert_true(rts.tv_nsec >= tv.tv_usec * NSEC_PER_USEC,
-			"gettimeofday didn't provide correct result");
+	LOG_INF("n: %d, sleep: %d, margin: %d, lo: %lld, avg: %lld, hi: %lld",
+		CONFIG_TEST_CLOCK_RT_ITERATIONS, CONFIG_TEST_CLOCK_RT_SLEEP_MS,
+		CONFIG_TEST_CLOCK_RT_ERROR_MS, lo_wm, cma, hi_wm);
+	zassert_between_inclusive(cma, lo, hi);
 }