patrick/zephyr
1
0
Fork 0
Code Issues Pull requests Actions 8 Packages Projects Releases Wiki Activity

tests: posix: test_realtime: improve test reliability

Browse source 
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>
This commit is contained in:
Christopher Friedt 2023-12-27 17:56:27 -05:00 committed by Stephanos Ioannidis
parent 95a22b1217
commit 67a74e4350
2 changed files with 206 additions and 89 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

27
tests/posix/common/Kconfig Normal file
View file

@ -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"

268
tests/posix/common/src/clock.c
View file

@ -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)
LOG_MODULE_REGISTER(clock_test, LOG_LEVEL_DBG);
/* 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};
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)
{
int64_t nsecs_elapsed, secs_elapsed;
struct timespec ts, te;
printk("POSIX clock APIs\n");
/* TESTPOINT: Pass invalid clock type */
zassert_equal(clock_gettime(CLOCK_INVALID, &ts), -1,
NULL);
zassert_equal(errno, EINVAL);
zassert_ok(clock_gettime(CLOCK_MONOTONIC, &ts));
zassert_ok(k_sleep(K_SECONDS(SLEEP_SECONDS)));
zassert_ok(clock_gettime(CLOCK_MONOTONIC, &te));
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);
}
/*TESTPOINT: Check if POSIX clock API test passes*/
zassert_equal(secs_elapsed, SLEEP_SECONDS,
"POSIX clock API test failed");
printk("POSIX clock APIs test done\n");
return ts->tv_sec * NSEC_PER_SEC + ts->tv_nsec;
}
ZTEST(posix_apis, test_realtime)
static inline void tv_to_ts(const struct timeval *tv, struct timespec *ts)
{
int ret;
struct timespec rts, mts;
struct timeval tv;
ts->tv_sec = tv->tv_sec;
ts->tv_nsec = tv->tv_usec * NSEC_PER_USEC;
}
ret = clock_gettime(CLOCK_MONOTONIC, &mts);
zassert_equal(ret, 0, "Fail to get monotonic clock");
#define _tp_op(_a, _b, _op) (ts_to_ns(_a) _op ts_to_ns(_b))
ret = clock_gettime(CLOCK_REALTIME, &rts);
zassert_equal(ret, 0, "Fail to get realtime clock");
#define _decl_op(_type, _name, _op) \
static inline _type _name(const struct timespec *_a, const struct timespec *_b) \
{ \
return _tp_op(_a, _b, _op); \
}
/* 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;
_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 */
/* TESTPOINT: Pass invalid clock type */
zassert_equal(clock_settime(CLOCK_INVALID, &nts), -1,
NULL);
/* 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);
return diff >= lo && diff < hi;
}
ZTEST(posix_apis, test_clock_gettime)
{
struct timespec ts;
/* ensure argument validation is performed */
errno = 0;
zassert_equal(clock_gettime(CLOCK_INVALID, &ts), -1);
zassert_equal(errno, EINVAL);
ret = clock_settime(CLOCK_MONOTONIC, &nts);
zassert_not_equal(ret, 0, "Should not be able to set monotonic time");
if (false) {
/* undefined behaviour */
errno = 0;
zassert_equal(clock_gettime(clocks[0], NULL), -1);
zassert_equal(errno, EINVAL);
}
ret = clock_settime(CLOCK_REALTIME, &nts);
zassert_equal(ret, 0, "Fail to set realtime clock");
/* 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);
}
}
/*
* 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.
*/
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");
ZTEST(posix_apis, test_gettimeofday)
{
struct timeval tv;
struct timespec ts;
struct timespec rts;
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);
/* Make the delta milliseconds. */
delta /= (NSEC_PER_SEC / 1000U);
zassert_true(delta > last_delta, "Clock moved backward");
int64_t error = delta - last_delta;
/* printk("Delta %d: %lld\n", i, delta); */
/* 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);
last_delta = delta;
if (false) {
/* undefined behaviour */
errno = 0;
zassert_equal(gettimeofday(NULL, NULL), -1);
zassert_equal(errno, EINVAL);
}
/* Validate gettimeofday API */
ret = gettimeofday(&tv, NULL);
zassert_equal(ret, 0);
ret = clock_gettime(CLOCK_REALTIME, &rts);
zassert_equal(ret, 0);
zassert_ok(gettimeofday(&tv, NULL));
zassert_ok(clock_gettime(CLOCK_REALTIME, &rts));
/* 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");
tv_to_ts(&tv, &ts);
zassert_true(tp_ge(&rts, &ts));
}
ZTEST(posix_apis, test_clock_settime)
{
int64_t diff_ns;
struct timespec ts = {0};
BUILD_ASSERT(ARRAY_SIZE(settable) == ARRAY_SIZE(clocks));
/* ensure argument validation is performed */
errno = 0;
zassert_equal(clock_settime(CLOCK_INVALID, &ts), -1);
zassert_equal(errno, EINVAL);
if (false) {
/* undefined behaviour */
errno = 0;
zassert_equal(clock_settime(CLOCK_REALTIME, NULL), -1);
zassert_equal(errno, EINVAL);
}
/* 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);
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);
}
}
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);
/* 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;
}
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);
}