From 471df17c7d2ec01b2c4e67a0e67a1716f2a0ef2c Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Thu, 5 May 2022 16:35:04 -0700 Subject: [PATCH 1/3] suspend-resume: fix sys/power/wakeup_count test "greater or equal" has never ever reported any error. Test for the expected value instead but print only a warning for now because of the high number of failures this causes, example: https://sof-ci.01.org/softestpr/PR900/build18/devicetest/ Also catch any unexpected increase while the system is up - trust no one. Fix the error message to report exactly what was found, not a guess. Signed-off-by: Marc Herbert --- test-case/check-suspend-resume.sh | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/test-case/check-suspend-resume.sh b/test-case/check-suspend-resume.sh index edce695f..9096e29d 100755 --- a/test-case/check-suspend-resume.sh +++ b/test-case/check-suspend-resume.sh @@ -79,12 +79,13 @@ fi # TODO: remove this after issue fixed. sleep 1 +expected_wakeup_count=$(cat /sys/power/wakeup_count) for i in $(seq 1 $loop_count) do dlogi "===== Round($i/$loop_count) =====" # set up checkpoint for each iteration setup_kernel_check_point - sleep_count=$(cat /sys/power/wakeup_count) + expected_wakeup_count=$((expected_wakeup_count+1)) dlogc "Run the command: rtcwake -m mem -s ${sleep_lst[$i]}" sudo rtcwake -m mem -s "${sleep_lst[$i]}" || die "rtcwake returned $?" @@ -96,6 +97,9 @@ do # check wakeup count correct wake_count=$(cat /sys/power/wakeup_count) dlogi "Check for the wakeup_count" - [[ $wake_count -ge $sleep_count ]] || die "suspend/resume didn't happen, because /sys/power/wakeup_count does not increase" + [ "$wake_count" -eq "$expected_wakeup_count" ] || { + dlogw "/sys/power/wakeup_count is $wake_count, expected $expected_wakeup_count" + expected_wakeup_count=${wake_count} + } done From a3f7aae43bf61843cb7d7111ddb55adb1efaa354 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Thu, 5 May 2022 16:47:07 -0700 Subject: [PATCH 2/3] suspend-resume: add test of /sys/power/suspend_stats/success Signed-off-by: Marc Herbert --- test-case/check-suspend-resume.sh | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/test-case/check-suspend-resume.sh b/test-case/check-suspend-resume.sh index 9096e29d..38ae139a 100755 --- a/test-case/check-suspend-resume.sh +++ b/test-case/check-suspend-resume.sh @@ -80,12 +80,14 @@ fi sleep 1 expected_wakeup_count=$(cat /sys/power/wakeup_count) +expected_stats_success=$(cat /sys/power/suspend_stats/success) for i in $(seq 1 $loop_count) do dlogi "===== Round($i/$loop_count) =====" # set up checkpoint for each iteration setup_kernel_check_point expected_wakeup_count=$((expected_wakeup_count+1)) + expected_stats_success=$((expected_stats_success+1)) dlogc "Run the command: rtcwake -m mem -s ${sleep_lst[$i]}" sudo rtcwake -m mem -s "${sleep_lst[$i]}" || die "rtcwake returned $?" @@ -96,10 +98,13 @@ do sof-kernel-log-check.sh "$KERNEL_CHECKPOINT" || die "Caught error in kernel log" # check wakeup count correct wake_count=$(cat /sys/power/wakeup_count) - dlogi "Check for the wakeup_count" + stats_success=$(cat /sys/power/suspend_stats/success) + dlogi "Check for wakeup_count and suspend_stats" [ "$wake_count" -eq "$expected_wakeup_count" ] || { dlogw "/sys/power/wakeup_count is $wake_count, expected $expected_wakeup_count" expected_wakeup_count=${wake_count} } + [ "$stats_success" -eq "$expected_stats_success" ] || + suspend_die "/sys/power/suspend_stats/success is $stats_success, expected $expected_stats_success" done From d34a5f2f2bceeafe3fb723b7b5be2e64e55178aa Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Thu, 5 May 2022 17:09:07 -0700 Subject: [PATCH 3/3] suspend-resume: check /sys/power/suspend_stats/*fail* at every step As requested in #898 Also dumps a lot more system information. Signed-off-by: Marc Herbert --- test-case/check-suspend-resume.sh | 58 +++++++++++++++++++++++++++++-- 1 file changed, 55 insertions(+), 3 deletions(-) diff --git a/test-case/check-suspend-resume.sh b/test-case/check-suspend-resume.sh index 38ae139a..fcd6b327 100755 --- a/test-case/check-suspend-resume.sh +++ b/test-case/check-suspend-resume.sh @@ -74,6 +74,53 @@ else done fi +save_initial_stats() +{ + printf '\n\n' + + INITIAL_DBG_SOURCES="$LOG_ROOT"/initial_wakeup_sources.txt + sudo cat /sys/kernel/debug/wakeup_sources | sudo tee "$INITIAL_DBG_SOURCES" + + INITIAL_STATS="$LOG_ROOT"/initial_suspend_stats.txt + grep ^ /sys/power/suspend_stats/*fail* | + sudo tee "$INITIAL_STATS" > /dev/null + + if grep -E ':[[:digit:]]+$' "$INITIAL_STATS" | grep -q -v ':0$'; then + dlogw "Starting test with earlier suspend failures!" + fi + printf '\n' + + find /sys/devices -wholename '*/power/wakeup' -print0 | + xargs --null grep -H 'enabled'; printf '\n' + dlogi "Note many of the devices above are typically buses, not actual devices" + dlogi "https://docs.kernel.org/driver-api/pm/devices.html#sys-devices-power-wakeup-files" + printf '\n' + lspci; printf '\n' + lsusb -t; printf '\n\n' +} + +check_suspend_fails() +{ + diff -u "$INITIAL_STATS" <(grep ^ /sys/power/suspend_stats/*fail*) +} + +dump_stats() +{ + printf '\n' + grep ^ /sys/power/suspend_stats/* + printf '\n' + sudo cat /sys/kernel/debug/wakeup_sources | head -n 1 + diff -u "$INITIAL_DBG_SOURCES" <(sudo cat /sys/kernel/debug/wakeup_sources) || + true + printf '\n' +} + +dump_and_die() +{ + dump_stats + die "$@" +} + # This is used to workaround https://github.com/thesofproject/sof-test/issues/650, # which may be caused by kernel issue or unstable network connection. # TODO: remove this after issue fixed. @@ -81,6 +128,7 @@ sleep 1 expected_wakeup_count=$(cat /sys/power/wakeup_count) expected_stats_success=$(cat /sys/power/suspend_stats/success) +save_initial_stats for i in $(seq 1 $loop_count) do dlogi "===== Round($i/$loop_count) =====" @@ -90,21 +138,25 @@ do expected_stats_success=$((expected_stats_success+1)) dlogc "Run the command: rtcwake -m mem -s ${sleep_lst[$i]}" sudo rtcwake -m mem -s "${sleep_lst[$i]}" || - die "rtcwake returned $?" + dump_and_die "rtcwake returned $?" dlogc "sleep for ${wait_lst[$i]}" sleep ${wait_lst[$i]} dlogi "Check for the kernel log status" # check kernel log for each iteration to catch issues - sof-kernel-log-check.sh "$KERNEL_CHECKPOINT" || die "Caught error in kernel log" + sof-kernel-log-check.sh "$KERNEL_CHECKPOINT" || dump_and_die "Caught error in kernel log" # check wakeup count correct wake_count=$(cat /sys/power/wakeup_count) stats_success=$(cat /sys/power/suspend_stats/success) dlogi "Check for wakeup_count and suspend_stats" [ "$wake_count" -eq "$expected_wakeup_count" ] || { + dump_stats dlogw "/sys/power/wakeup_count is $wake_count, expected $expected_wakeup_count" + printf '\n' expected_wakeup_count=${wake_count} } [ "$stats_success" -eq "$expected_stats_success" ] || - suspend_die "/sys/power/suspend_stats/success is $stats_success, expected $expected_stats_success" + dump_and_die "/sys/power/suspend_stats/success is $stats_success, expected $expected_stats_success" + check_suspend_fails || dump_and_die "some failure counts have changed" + done