From 7566e8d78630f4e7399f2f90b46e97114df01f38 Mon Sep 17 00:00:00 2001 From: Ricardo Salveti Date: Wed, 26 Aug 2026 16:06:40 +0000 Subject: [PATCH 1/2] utils: add clock step detection helpers Boards without a valid RTC boot at the epoch, get bumped to a build-time fallback by systemd, then stepped to real time once NTP reaches them: rtc-pm8xxx ...: setting system clock to 1970-01-01T00:00:16 UTC (16) A step landing inside a measurement invalidates every wall-clock interval taken across it. Add get_monotonic_seconds() for interval measurement, clock_step_seconds() to report how far the wall clock moved beyond an interval's monotonic duration, and wait_for_time_sync() to settle the clock beforehand, bounded and skipped when no time source exists. These live in functestlib.sh rather than lib_display.sh because nothing about them is display-specific; they validate input through the existing is_unsigned_number(), and rt_now_seconds() in lib_rt.sh now delegates to get_monotonic_seconds() instead of carrying its own copy, so display and real-time suites share one timing implementation. Whether a time source exists is decided by time_sync_service_active(), not by timedatectl being installed: timedatectl ships on every systemd image, configured or not, and waiting on its presence alone would stall every run on images with no synchronization service. Check the timedated NTP property, the systemd-timesyncd runtime directory, and running systemd-timesyncd, chronyd or ntpd daemons instead. Also count single-frame samples in display_parse_fps_log() and export DISPLAY_FPS_SINGLE_FRAME. A clock step turns every reporting window into one, so a high count next to a healthy max distinguishes bad samples from slow rendering. Signed-off-by: Ricardo Salveti --- Runner/utils/functestlib.sh | 187 ++++++++++++++++++++++++++++++++++++ Runner/utils/lib_display.sh | 29 +++++- Runner/utils/lib_rt.sh | 9 +- 3 files changed, 217 insertions(+), 8 deletions(-) diff --git a/Runner/utils/functestlib.sh b/Runner/utils/functestlib.sh index da1202fc0..e8ab66ff8 100755 --- a/Runner/utils/functestlib.sh +++ b/Runner/utils/functestlib.sh @@ -1294,6 +1294,193 @@ ensure_reasonable_clock() { return 1 } +############################################################################### +# Monotonic time and wall-clock step helpers +# +# Boards without a valid RTC boot at the epoch and get stepped to real time +# once NTP reaches them. A step landing inside a measurement invalidates +# every wall-clock interval taken across it. +############################################################################### + +# Print whole seconds from a monotonic source, falling back to the wall clock. +get_monotonic_seconds() { + gms_value="" + + if [ -r /proc/uptime ]; then + gms_value="$(awk '{ printf "%d", $1 }' /proc/uptime 2>/dev/null)" + fi + + if ! is_unsigned_number "$gms_value"; then + gms_value="$(date +%s 2>/dev/null)" + fi + + if ! is_unsigned_number "$gms_value"; then + gms_value=0 + fi + + printf '%s\n' "$gms_value" +} + +# Print how far the wall clock moved beyond the monotonic duration of an +# interval, in either direction. Malformed input reports 0, no step detected. +# +# Usage: +# clock_step_seconds MONO_START REAL_START MONO_END REAL_END +clock_step_seconds() { + css_mono_start="$1" + css_real_start="$2" + css_mono_end="$3" + css_real_end="$4" + css_step=0 + + for css_value in \ + "$css_mono_start" \ + "$css_real_start" \ + "$css_mono_end" \ + "$css_real_end"; do + if ! is_unsigned_number "$css_value"; then + printf '%s\n' 0 + return 0 + fi + done + + css_step=$(((css_real_end - css_real_start) - (css_mono_end - css_mono_start))) + + if [ "$css_step" -lt 0 ]; then + css_step=$((0 - css_step)) + fi + + printf '%s\n' "$css_step" +} + +# Report whether the system clock is synchronized to a time source. +# +# Return: +# 0 - synchronized +# 1 - not synchronized, or no way to tell +clock_is_synchronized() { + cis_value="" + + if command -v timedatectl >/dev/null 2>&1; then + cis_value="$(timedatectl show -p NTPSynchronized --value 2>/dev/null)" + + if [ -z "$cis_value" ]; then + cis_value="$( + timedatectl status 2>/dev/null | + sed -n 's/^[[:space:]]*System clock synchronized:[[:space:]]*//p' | + head -n 1 + )" + fi + + case "$cis_value" in + yes|true|1) + return 0 + ;; + no|false|0) + return 1 + ;; + esac + fi + + # Covers images without timedatectl. + [ -e /run/systemd/timesync/synchronized ] && return 0 + + return 1 +} + +# Report whether a time synchronization service is enabled or running. +# timedatectl alone is not enough: it exists on every systemd image, even +# ones with no synchronization service configured. +# +# Return: +# 0 - a time synchronization service is enabled or running +# 1 - none detected +time_sync_service_active() { + # NTP enabled per timedated; covers systemd-timesyncd and daemons such + # as chronyd that register through ntp-units.d. + if command -v timedatectl >/dev/null 2>&1; then + tssa_value="$(timedatectl show -p NTP --value 2>/dev/null)" + + if [ -z "$tssa_value" ]; then + tssa_value="$( + timedatectl status 2>/dev/null | + sed -n 's/^[[:space:]]*NTP service:[[:space:]]*//p' | + head -n 1 + )" + fi + + case "$tssa_value" in + yes|true|1|active) + return 0 + ;; + esac + fi + + # Runtime directory created by a running systemd-timesyncd. + [ -d /run/systemd/timesync ] && return 0 + + # Daemons running without timedated integration. + if command -v pidof >/dev/null 2>&1; then + for tssa_daemon in systemd-timesyncd chronyd ntpd; do + if pidof "$tssa_daemon" >/dev/null 2>&1; then + return 0 + fi + done + fi + + return 1 +} + +# Wait, bounded, for the system clock to synchronize, so a correction cannot +# land mid-measurement. Skipped when no time source exists, so boards without +# one do not stall on every run. +# +# Usage: +# wait_for_time_sync [TIMEOUT_SECONDS] +# +# TIMEOUT_SECONDS defaults to TIME_SYNC_WAIT, then 20. 0 disables the wait. +# +# Return: +# 0 - clock is synchronized +# 1 - still unsynchronized at the timeout, or no time source exists +wait_for_time_sync() { + wfts_timeout="${1:-${TIME_SYNC_WAIT:-20}}" + wfts_waited=0 + + if ! is_unsigned_number "$wfts_timeout"; then + wfts_timeout=20 + fi + + if clock_is_synchronized; then + log_info "System clock is already synchronized" + return 0 + fi + + if ! time_sync_service_active; then + log_info "No active time synchronization service detected, not waiting" + return 1 + fi + + if [ "$wfts_timeout" -le 0 ]; then + return 1 + fi + + log_info "Waiting up to ${wfts_timeout}s for the system clock to synchronize" + + while [ "$wfts_waited" -lt "$wfts_timeout" ]; do + sleep 1 + wfts_waited=$((wfts_waited + 1)) + + if clock_is_synchronized; then + log_info "System clock synchronized after ${wfts_waited}s" + return 0 + fi + done + + log_warn "System clock did not synchronize within ${wfts_timeout}s; a later correction may disturb timing-sensitive measurements" + return 1 +} + # If the tar file already exists,then function exit. Otherwise function to check the network connectivity and it will download tar from internet. extract_tar_from_url() { url="$1" diff --git a/Runner/utils/lib_display.sh b/Runner/utils/lib_display.sh index f8d473839..62860fd9d 100755 --- a/Runner/utils/lib_display.sh +++ b/Runner/utils/lib_display.sh @@ -2304,6 +2304,9 @@ display_fps_gate_avg() { # DISPLAY_FPS_AVG # DISPLAY_FPS_MIN # DISPLAY_FPS_MAX +# DISPLAY_FPS_SINGLE_FRAME - single-frame samples. A clock step turns every +# reporting window into one, so a high count next to a healthy +# DISPLAY_FPS_MAX means untrustworthy samples, not slow rendering. # # Return: # 0 - one or more usable FPS samples remain after warm-up handling @@ -2316,6 +2319,7 @@ display_parse_fps_log() { DISPLAY_FPS_AVG="-" DISPLAY_FPS_MIN="-" DISPLAY_FPS_MAX="-" + DISPLAY_FPS_SINGLE_FRAME=0 [ -n "$dpfl_log_file" ] || return 1 [ -r "$dpfl_log_file" ] || return 1 @@ -2329,6 +2333,7 @@ display_parse_fps_log() { if ($i == "frames" && i > 1 && $(i + 1) == "in") { + frames = $(i - 1) for (j = i + 2; j <= NF; j++) { # Weston 14: # 601 frames in 5 seconds: 120.199997 fps @@ -2353,6 +2358,7 @@ display_parse_fps_log() { if (value ~ /^[0-9]+([.][0-9]+)?$/) { all_n++ all_values[all_n] = value + 0.0 + all_frames[all_n] = (frames ~ /^[0-9]+$/) ? frames + 0 : -1 } } @@ -2366,11 +2372,16 @@ display_parse_fps_log() { first = (all_n > 1) ? 2 : 1 count = 0 sum = 0.0 + single = 0 for (i = first; i <= all_n; i++) { value = all_values[i] count++ sum += value + + if (all_frames[i] >= 0 && all_frames[i] <= 1) { + single++ + } if (count == 1 || value < min) { min = value @@ -2382,11 +2393,12 @@ display_parse_fps_log() { } if (count > 0) { - printf "n=%d avg=%.6f min=%.6f max=%.6f\n", + printf "n=%d avg=%.6f min=%.6f max=%.6f single=%d\n", count, sum / count, min, - max + max, + single } } ' "$dpfl_log_file" 2>/dev/null @@ -2417,6 +2429,18 @@ display_parse_fps_log() { awk '{ print $4 }' | sed 's/^max=//' )" + + DISPLAY_FPS_SINGLE_FRAME="$( + printf '%s\n' "$dpfl_stats" | + awk '{ print $5 }' | + sed 's/^single=//' + )" + + case "$DISPLAY_FPS_SINGLE_FRAME" in + ''|*[!0-9]*) + DISPLAY_FPS_SINGLE_FRAME=0 + ;; + esac case "$DISPLAY_FPS_COUNT" in ''|*[!0-9]*) @@ -2424,6 +2448,7 @@ display_parse_fps_log() { DISPLAY_FPS_AVG="-" DISPLAY_FPS_MIN="-" DISPLAY_FPS_MAX="-" + DISPLAY_FPS_SINGLE_FRAME=0 return 1 ;; esac diff --git a/Runner/utils/lib_rt.sh b/Runner/utils/lib_rt.sh index bbc53513e..8900e69ad 100755 --- a/Runner/utils/lib_rt.sh +++ b/Runner/utils/lib_rt.sh @@ -1947,14 +1947,11 @@ rt_evaluate_baseline_gate() { # rt_now_seconds # Return monotonic uptime seconds when available. # This avoids elapsed-time jumps when wall clock is corrected by NTP/RTC. +# Delegates to get_monotonic_seconds() from functestlib.sh, which every +# consumer sources first. # --------------------------------------------------------------------------- rt_now_seconds() { - if [ -r /proc/uptime ]; then - awk '{ printf "%d\n", $1 }' /proc/uptime 2>/dev/null - return 0 - fi - - date +%s 2>/dev/null || echo 0 + get_monotonic_seconds } # --------------------------------------------------------------------------- From f4b03bbbf3e63f483291a905e1ea4e341c118180 Mon Sep 17 00:00:00 2001 From: Ricardo Salveti Date: Wed, 26 Aug 2026 16:06:40 +0000 Subject: [PATCH 2/2] graphics: harden weston-simple-egl against wall-clock steps weston-simple-egl fails intermittently on iq-9075-evk while every other test on the same boot passes, including weston-simple-shm and KMSCube. A failing run: Client finished, rc=143 elapsed=2885113s FPS stats, samples=1471 avg=0.253841 min=0.200000 max=74.800003 A passing run on the same board: Client finished, rc=143 elapsed=30s FPS stats, samples=4 avg=74.850002 min=74.800003 max=75.000000 The difference is not the GPU. In failing runs the clock steps 33 days mid-measurement, from the image's build-time fallback to real time, which is the 2885113s. The client's frame accounting jumps with it and prints one single-frame report per frame; those flood the sample set and drag the mean under the gate, even though the first window read 74.8 fps, the same figure the passing run averages on a 75Hz link. Whether the correction lands inside the 30s window is timing, hence the flakiness. Wait for the clock to settle, take elapsed from a monotonic source, and check for a step afterwards. When one occurred, report SKIP rather than asserting on numbers that cannot be right, and record the step size and single-frame count in the summary. The wait bound and step tolerance are tunable through TIME_SYNC_WAIT and CLOCK_STEP_TOLERANCE, exposed as parameters in the LAVA test definition so jobs can override them consistently. Signed-off-by: Ricardo Salveti --- .../Graphics/weston-simple-egl/run.sh | 65 ++++++++++++++++--- .../weston-simple-egl/weston-simple-egl.yaml | 4 +- 2 files changed, 59 insertions(+), 10 deletions(-) diff --git a/Runner/suites/Multimedia/Graphics/weston-simple-egl/run.sh b/Runner/suites/Multimedia/Graphics/weston-simple-egl/run.sh index 04e6458a7..c3914c27f 100755 --- a/Runner/suites/Multimedia/Graphics/weston-simple-egl/run.sh +++ b/Runner/suites/Multimedia/Graphics/weston-simple-egl/run.sh @@ -74,6 +74,7 @@ FPS_TOL_PCT="${FPS_TOL_PCT:-10}" MIN_FPS_PCT="${MIN_FPS_PCT:-85}" REQUIRE_FPS="${REQUIRE_FPS:-1}" DESKTOP_FUNCTIONAL_FPS_CAP="${DESKTOP_FUNCTIONAL_FPS_CAP:-60}" +CLOCK_STEP_TOLERANCE="${CLOCK_STEP_TOLERANCE:-2}" REQUESTED_GRAPHICS_MODE="default" ALLOW_RELAUNCH="${ALLOW_RELAUNCH:-0}" @@ -166,6 +167,8 @@ Environment: FPS_TOL_PCT Fixed-mode tolerance, default: 10 MIN_FPS_PCT Minimum percentage, default: 85 DESKTOP_FUNCTIONAL_FPS_CAP Desktop auto-mode FPS cap, default: 60 + TIME_SYNC_WAIT Clock sync wait bound in seconds, 0 disables, default: 20 + CLOCK_STEP_TOLERANCE Wall-clock step tolerance in seconds, default: 2 EOF_USAGE exit 0 ;; @@ -226,6 +229,11 @@ if [ "$DESKTOP_FUNCTIONAL_FPS_CAP" -le 0 ]; then exit 1 fi +if ! is_unsigned_number "$CLOCK_STEP_TOLERANCE"; then + echo "[ERROR] CLOCK_STEP_TOLERANCE must be a non-negative integer: $CLOCK_STEP_TOLERANCE" >&2 + exit 1 +fi + test_path="$(find_test_case_by_name "$TESTNAME" 2>/dev/null || true)" if [ -z "$test_path" ] || [ ! -d "$test_path" ]; then @@ -570,9 +578,15 @@ WESTON_SIMPLE_EGL_FPS=1 export SIMPLE_EGL_FPS export WESTON_SIMPLE_EGL_FPS +# A clock step inside the window corrupts both the interval and the client's +# frame accounting. Settle the clock first, measure monotonically, then check +# whether a step slipped in anyway. +wait_for_time_sync || true + log_info "Launching $TESTNAME for $DURATION" start_ts="$(date +%s)" +start_mono="$(get_monotonic_seconds)" rc=0 if command -v run_with_timeout >/dev/null 2>&1; then @@ -651,10 +665,28 @@ else fi end_ts="$(date +%s)" -elapsed=$((end_ts - start_ts)) +end_mono="$(get_monotonic_seconds)" +elapsed=$((end_mono - start_mono)) + +clock_step="$( + clock_step_seconds \ + "$start_mono" \ + "$start_ts" \ + "$end_mono" \ + "$end_ts" +)" + +clock_stepped=0 + +if [ "$clock_step" -gt "$CLOCK_STEP_TOLERANCE" ]; then + clock_stepped=1 +fi log_info "Client finished, rc=${rc} elapsed=${elapsed}s" +if [ "$clock_stepped" -eq 1 ]; then + log_warn "System clock stepped by ${clock_step}s during the run; FPS samples from the client are not trustworthy" +fi fps_count=0 fps_avg="-" @@ -668,7 +700,7 @@ if command -v display_parse_fps_log >/dev/null 2>&1 && fps_min="$DISPLAY_FPS_MIN" fps_max="$DISPLAY_FPS_MAX" - log_info "FPS stats, samples=${fps_count} avg=${fps_avg} min=${fps_min} max=${fps_max}" + log_info "FPS stats, samples=${fps_count} avg=${fps_avg} min=${fps_min} max=${fps_max} single_frame=${DISPLAY_FPS_SINGLE_FRAME:-0}" else log_warn "No FPS samples were detected in $RUN_LOG" fi @@ -704,14 +736,21 @@ if [ "$elapsed" -le 1 ]; then fi -if ! display_apply_test_fps_gate_policy \ +if [ "$clock_stepped" -eq 1 ]; then + # Averaging across a step measures the step, not the GPU. + log_skip "$TESTNAME SKIP - system clock stepped by ${clock_step}s during the ${elapsed}s run, FPS gate skipped (samples=${fps_count} avg=${fps_avg} max=${fps_max} single_frame=${DISPLAY_FPS_SINGLE_FRAME:-0})" + + if [ "$final" = "PASS" ]; then + final="SKIP" + fi +elif ! display_apply_test_fps_gate_policy \ "$fps_avg" \ "$fps_count" \ "$REQUIRE_FPS"; then final="FAIL" fi -if [ "$final" = "FAIL" ]; then +if [ "$final" != "PASS" ]; then log_info "----- Last 200 client log lines -----" tail -n 200 "$RUN_LOG" 2>/dev/null | @@ -737,7 +776,9 @@ fi printf '%s\n' "fps_gate_minimum=${DISPLAY_TEST_FPS_MIN_OK:-unknown}" printf '%s\n' "client_rc=$rc" printf '%s\n' "elapsed_seconds=$elapsed" + printf '%s\n' "clock_step_seconds=$clock_step" printf '%s\n' "fps_samples=$fps_count" + printf '%s\n' "fps_single_frame_samples=${DISPLAY_FPS_SINGLE_FRAME:-0}" printf '%s\n' "fps_average=$fps_avg" printf '%s\n' "fps_minimum=$fps_min" printf '%s\n' "fps_maximum=$fps_max" @@ -749,11 +790,17 @@ echo "$TESTNAME $final" >"$RES_FILE" trap - EXIT HUP INT TERM cleanup_client -if [ "$final" = "PASS" ]; then - log_pass "$TESTNAME : PASS" -else - log_fail "$TESTNAME : FAIL" -fi +case "$final" in + PASS) + log_pass "$TESTNAME : PASS" + ;; + SKIP) + log_skip "$TESTNAME : SKIP" + ;; + *) + log_fail "$TESTNAME : FAIL" + ;; +esac log_info "------------------- Completed ${TESTNAME} Testcase -------------------------" exit 0 diff --git a/Runner/suites/Multimedia/Graphics/weston-simple-egl/weston-simple-egl.yaml b/Runner/suites/Multimedia/Graphics/weston-simple-egl/weston-simple-egl.yaml index b12b3d7a7..12e43352d 100755 --- a/Runner/suites/Multimedia/Graphics/weston-simple-egl/weston-simple-egl.yaml +++ b/Runner/suites/Multimedia/Graphics/weston-simple-egl/weston-simple-egl.yaml @@ -11,10 +11,12 @@ params: DURATION: "30s" WAIT_SECS: "10" REQUIRE_FPS: "1" + TIME_SYNC_WAIT: "20" + CLOCK_STEP_TOLERANCE: "2" run: steps: - REPO_PATH=$PWD - cd Runner/suites/Multimedia/Graphics/weston-simple-egl - - DURATION="${DURATION}" WAIT_SECS="${WAIT_SECS}" REQUIRE_FPS="${REQUIRE_FPS}" ./run.sh || true + - DURATION="${DURATION}" WAIT_SECS="${WAIT_SECS}" REQUIRE_FPS="${REQUIRE_FPS}" TIME_SYNC_WAIT="${TIME_SYNC_WAIT}" CLOCK_STEP_TOLERANCE="${CLOCK_STEP_TOLERANCE}" ./run.sh || true - $REPO_PATH/Runner/utils/send-to-lava.sh weston-simple-egl.res || true