test: PC10 residency and resume time

ekurdybx · ekurdybx · commit 4dafa3479c41 · 2025-12-01T18:20:38.000+01:00
Add option to run check-suspend-resume test with sleepgraph, to measure
resume time. Updated test-socwatch to measure residency time.

Signed-off-by: Emilia Kurdybelska &lt;emiliax.kurdybelska@intel.com&gt;
diff --git a/test-case/check-suspend-resume.sh b/test-case/check-suspend-resume.sh
@@ -5,7 +5,7 @@ set -e
 ##
 ## Case Name: check suspend/resume status
 ## Preconditions:
-##    N/A
+##    - (if ran with --sleepgraph) Sleepgraph installed on dut
 ## Description:
 ##    Run the suspend/resume command to check device status
 ## Case step:
@@ -26,27 +26,33 @@ source "$TOPDIR"/case-lib/lib.sh
 random_min=3    # wait time should >= 3 for other device wakeup from sleep
 random_max=20
 
-OPT_NAME['l']='loop'     OPT_DESC['l']='loop count'
-OPT_HAS_ARG['l']=1       OPT_VAL['l']=5
+OPT_NAME['l']='loop'                   OPT_DESC['l']='loop count'
+OPT_HAS_ARG['l']=1                     OPT_VAL['l']=5
 
-OPT_NAME['T']='type'     OPT_DESC['T']="suspend/resume type from /sys/power/mem_sleep"
-OPT_HAS_ARG['T']=1       OPT_VAL['T']=""
+OPT_NAME['T']='type'                   OPT_DESC['T']="suspend/resume type from /sys/power/mem_sleep"
+OPT_HAS_ARG['T']=1                     OPT_VAL['T']=""
 
-OPT_NAME['S']='sleep'    OPT_DESC['S']='suspend/resume command:rtcwake sleep duration'
-OPT_HAS_ARG['S']=1       OPT_VAL['S']=5
+OPT_NAME['S']='sleep'                  OPT_DESC['S']='suspend/resume command:rtcwake sleep duration'
+OPT_HAS_ARG['S']=1                     OPT_VAL['S']=5
 
-OPT_NAME['u']='unload-audio'  OPT_DESC['u']='unload audio modules for the test'
-OPT_HAS_ARG['u']=0            OPT_VAL['u']=0
+OPT_NAME['u']='unload-audio'           OPT_DESC['u']='unload audio modules for the test'
+OPT_HAS_ARG['u']=0                     OPT_VAL['u']=0
 
-OPT_NAME['w']='wait'     OPT_DESC['w']='idle time after suspend/resume wakeup'
-OPT_HAS_ARG['w']=1       OPT_VAL['w']=5
+OPT_NAME['w']='wait'                   OPT_DESC['w']='idle time after suspend/resume wakeup'
+OPT_HAS_ARG['w']=1                     OPT_VAL['w']=5
 
-OPT_NAME['r']='random'   OPT_DESC['r']="Randomly setup wait/sleep time, range is [$random_min-$random_max], this option will overwrite s & w option"
-OPT_HAS_ARG['r']=0       OPT_VAL['r']=0
+OPT_NAME['r']='random'                 OPT_DESC['r']="Randomly setup wait/sleep time, range is [$random_min-$random_max], this option will overwrite s & w option"
+OPT_HAS_ARG['r']=0                     OPT_VAL['r']=0
 
 # processid is set by check-suspend-resume-with-audio.sh for audio test case
-OPT_NAME['p']='processid'     OPT_DESC['p']='Fail immediately if this process dies'
-OPT_HAS_ARG['p']=1            OPT_VAL['p']=''
+OPT_NAME['p']='processid'              OPT_DESC['p']='Fail immediately if this process dies'
+OPT_HAS_ARG['p']=1                     OPT_VAL['p']=''
+
+OPT_NAME['s']='sleepgraph'             OPT_DESC['s']='run with sleepgraph (http://github.com/intel/pm-graph.git)'
+OPT_HAS_ARG['s']=0                     OPT_VAL['s']=0
+
+OPT_NAME['t']='resume-time'            OPT_DESC['t']='resume time threshold'
+OPT_HAS_ARG['t']=1                     OPT_VAL['t']=''
 
 func_opt_parse_option "$@"
 func_lib_check_sudo
@@ -69,21 +75,28 @@ dlogi "Current suspend/resume type mode: $(cat /sys/power/mem_sleep)"
 loop_count=${OPT_VAL['l']}
 declare -a sleep_lst wait_lst
 
-if [ ${OPT_VAL['r']} -eq 1 ]; then
+if [ "${OPT_VAL['r']}" -eq 1 ]; then
     # create random number list
-    for i in $(seq 1 $loop_count)
+    for i in $(seq 1 "$loop_count")
     do
-        sleep_lst[$i]=$(func_lib_get_random $random_max $random_min)
-        wait_lst[$i]=$(func_lib_get_random $random_max $random_min)
+        sleep_lst[i]=$(func_lib_get_random $random_max $random_min)
+        wait_lst[i]=$(func_lib_get_random $random_max $random_min)
     done
 else
-    for i in $(seq 1 $loop_count)
+    for i in $(seq 1 "$loop_count")
     do
-        sleep_lst[$i]=${OPT_VAL['S']}
-        wait_lst[$i]=${OPT_VAL['w']}
+        sleep_lst[i]=${OPT_VAL['S']}
+        wait_lst[i]=${OPT_VAL['w']}
     done
 fi
 
+if [ "${OPT_VAL['s']}" -eq 1 ]; then
+    if ! command -v sleepgraph >/dev/null 2>&1; then
+        echo "Sleepgraph is not installed! Exiting..."
+        exit 1
+    fi
+fi
+
 save_initial_stats()
 {
     printf '\n\n'
@@ -143,7 +156,7 @@ main()
 
     local keep_modules=true already_unloaded=false
 
-    if [ ${OPT_VAL['u']} = 1 ]; then
+    if [ "${OPT_VAL['u']}" = 1 ]; then
         keep_modules=false
     fi
 
@@ -159,7 +172,7 @@ main()
     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)
+    for i in $(seq 1 "$loop_count")
     do
         sleep_once "$i"
     done
@@ -170,6 +183,43 @@ main()
         die "Found kernel error after reloading audio drivers"
 }
 
+analyze_sleepgraph_results()
+{
+    dlogi "Analyzing sleepgraph results"
+    results_file=$(find suspend-*/*.html)
+    cp "$results_file" "$LOG_ROOT/"
+
+    thresholds=$( jq -n \
+                --arg resume_time "${OPT_VAL['t']}" \
+                '{"sof-audio-pci-intel-ptl":{"resume":$resume_time}}')
+
+    dlogi "Analyzing $results_file file..."
+    if python3 "$SCRIPT_HOME"/tools/analyze-sleepgraph-results.py "$results_file" "$thresholds"; then
+        dlogi "All times measurements within the thresholds"
+        return 0
+    else
+        dlogw "Time measurements not within the thresholds!"
+        return 1
+    fi
+}
+
+run_rtcwake()
+{
+    if [ "${OPT_VAL['s']}" -eq 1 ]; then
+        # remove any files from previous sleepgraph runs
+        rm -rf suspend-*
+
+        dlogc "Run the command: sleepgraph -rtcwake ${sleep_lst[$i]} -m freeze"
+        sudo sleepgraph -rtcwake "${sleep_lst[$i]}" -m freeze ||
+            dump_and_die "rtcwake returned $?"
+        analyze_sleepgraph_results
+    else
+        dlogc "Run the command: rtcwake -m mem -s ${sleep_lst[$i]}"
+        sudo rtcwake -m mem -s "${sleep_lst[$i]}" ||
+            dump_and_die "rtcwake returned $?"
+    fi
+}
+
 sleep_once()
 {
     local i="$1"
@@ -179,11 +229,9 @@ sleep_once()
     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]}" ||
-        dump_and_die "rtcwake returned $?"
+    run_rtcwake
     dlogc "sleep for ${wait_lst[$i]}"
-    sleep ${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" || dump_and_die "Caught error in kernel log"
diff --git a/test-case/test-socwatch.sh b/test-case/test-socwatch.sh
@@ -38,11 +38,7 @@ OPT_NAME['u']='unload-audio'  OPT_DESC['u']='unload audio modules for the test'
 OPT_HAS_ARG['u']=0            OPT_VAL['u']=0
 
 : "${SOCWATCH_PATH:=$HOME/socwatch}"
-SOCWATCH_VERSION=$("$SOCWATCH_PATH"/socwatch --version |grep Version)
-
-# reference cmd: sudo ./socwatch -t 20 -s 5 -f cpu-cstate -f pkg-pwr -o fredtest5
-#SOCWATCH_CMD="./socwatch"
-SOCWATCH_FEATURE_PARAMS=( -f cpu-cstate -f pkg-pwr )
+SOCWATCH_VERSION=$(sudo "$SOCWATCH_PATH"/socwatch --version | grep Version)
 
 func_opt_parse_option "$@"
 func_lib_check_sudo
@@ -57,41 +53,57 @@ check_socwatch_module_loaded()
     lsmod | grep -q socwatch || dlogi "socwatch is not loaded"
 }
 
+check_for_PC10_state()
+{
+    pc10_count=$(awk '/Package C-State Summary: Entry Counts/{f=1; next} f && /PC10/{print $3; exit}' "$socwatch_output".csv)
+    if [ -z "$pc10_count" ]; then
+        die "PC10 State not achieved"
+    fi
+    dlogi "Entered into PC10 State $pc10_count times"
+
+    pc10_per=$(awk '/Package C-State Summary: Residency/{f=1; next} f && /PC10/{print $3; exit}' "$socwatch_output".csv)
+    pc10_time=$(awk '/Package C-State Summary: Residency/{f=1; next} f && /PC10/{print $5; exit}' "$socwatch_output".csv)
+    dlogi "Spent $pc10_time ms ($pc10_per %) in PC10 State"
+
+    json_str=$( jq -n \
+                --arg id "$i" \
+                --arg cnt "$pc10_count" \
+                --arg time "$pc10_time" \
+                --arg per "$pc10_per" \
+                '{$id: {pc10_entires_count: $cnt, time_ms: $time, time_percentage: $per}}' )
+
+    results=$(jq --slurp 'add' <(echo "$results") <(echo "$json_str"))
+}
+
 socwatch_test_once()
 {
     local i="$1"
     dlogi "===== Loop($i/$loop_count) ====="
     dlogi "SoCWatch version: ${SOCWATCH_VERSION}"
 
+    socwatch_output="$LOG_ROOT/socwatch-results/socwatch_output_$i"
+
     # set up checkpoint for each iteration
     setup_kernel_check_point
 
-    # load socwatch module, if the module is loaded, go ahead with the testing (-q)
-    sudo "$SOCWATCH_PATH"/drivers/insmod-socwatch -q || true
-    check_socwatch_module_loaded || die "socwatch module not loaded"
-
     ( set -x
-      sudo "$SOCWATCH_PATH"/socwatch -t "$duration" -s "$wait_time" "${SOCWATCH_FEATURE_PARAMS[@]}" -o "$SOCWATCH_PATH/sofsocwatch-$i" ) ||
+      sudo "$SOCWATCH_PATH"/socwatch -m -f sys -f cpu -f cpu-hw -f pcie -f hw-cpu-cstate \
+      -f pcd-slps0 -f tcss-state -f tcss -f pcie-lpm -n 200 -t "$duration" -s "$wait_time" \
+      -r json -o "$socwatch_output" ) ||
     die "socwatch returned $?"
 
-    # filter output and copy to log directory
-    grep "Package C-State Summary: Residency" -B 8 -A 11 "$SOCWATCH_PATH/sofsocwatch-$i.csv" | tee "$SOCWATCH_PATH/socwatch-$i.txt"
-    grep "Package Power Summary: Average Rate" -B 6 -A 4 "$SOCWATCH_PATH/sofsocwatch-$i.csv" | tee -a "$SOCWATCH_PATH/socwatch-$i.txt"
-    # zip original csv report
-    gzip "$SOCWATCH_PATH/sofsocwatch-$i.csv"
-    mv "$SOCWATCH_PATH/socwatch-$i.txt" "$SOCWATCH_PATH/sofsocwatch-$i.csv.gz" "$LOG_ROOT"/
+    # analyze SoCWatch results
+    check_for_PC10_state
 
-    dlogi "Check for the kernel log status"
     # check kernel log for each iteration to catch issues
+    dlogi "Check for the kernel log status"
     sof-kernel-log-check.sh "$KERNEL_CHECKPOINT" || die "Caught error in kernel log"
-
-    # unload socwatch module
-    sudo "$SOCWATCH_PATH"/drivers/rmmod-socwatch || true
 }
 
-main()
+unload_modules()
 {
-    local keep_modules=true already_unloaded=false
+    keep_modules=true
+    already_unloaded=false
 
     [ -d "$SOCWATCH_PATH" ] ||
         die "SOCWATCH not found in SOCWATCH_PATH=$SOCWATCH_PATH"
@@ -106,22 +118,53 @@ main()
             dlogw 'modules already unloaded, ignoring option -u!'
     }
 
-    $already_unloaded || $keep_modules || "$TOPDIR"/tools/kmod/sof_remove.sh ||
+    if ! [ $already_unloaded ] || [ $keep_modules ]; then
+        "$TOPDIR"/tools/kmod/sof_remove.sh ||
         die "Failed to unload audio drivers"
+    fi
+}
+
+load_modules()
+{
+    if ! [ $already_unloaded ] || [ $keep_modules ]; then
+        "$TOPDIR"/tools/kmod/sof_insert.sh ||
+        die "Failed to reload audio drivers"
+    fi
+
+    sof-kernel-log-check.sh "$KERNEL_CHECKPOINT" ||
+        die "Found kernel error after reloading audio drivers"
+}
+
+run_socwatch_tests()
+{
+    # load socwatch module, if the module is loaded, go ahead with the testing
+    sudo bash "$SOCWATCH_PATH"/drivers/insmod-socwatch || true
+    check_socwatch_module_loaded || die "socwatch module not loaded"
+
+    mkdir "$LOG_ROOT/socwatch-results"
+    pc10_results_file="$LOG_ROOT/socwatch-results/pc10_results.json"
+    touch "$pc10_results_file"
 
-    # socwatch test from here
     for i in $(seq 1 "$loop_count")
     do
         socwatch_test_once "$i"
     done
+    echo "$results" > "$pc10_results_file"
 
-    $already_unloaded || $keep_modules || "$TOPDIR"/tools/kmod/sof_insert.sh ||
-        die "Failed to reload audio drivers"
-    sof-kernel-log-check.sh "$KERNEL_CHECKPOINT" ||
-        die "Found kernel error after reloading audio drivers"
+    # zip all SoCWatch reports
+    cd "$LOG_ROOT"
+    tar -zcvf socwatch-results.tar.gz socwatch-results/
+    rm -rf "$LOG_ROOT/socwatch-results/"
 
-    # DON"T delete socwatch directory after test, delete before new test
-    # rm -rf $SOCWATCH_PATH
+    # unload socwatch module
+    sudo bash "$SOCWATCH_PATH"/drivers/rmmod-socwatch
+}
+
+main()
+{
+    unload_modules
+    run_socwatch_tests
+    load_modules
 }
 
 main "$@"
diff --git a/tools/analyze-sleepgraph-results.py b/tools/analyze-sleepgraph-results.py
@@ -0,0 +1,75 @@
+from bs4 import BeautifulSoup
+from pathlib import Path
+import re
+import sys
+import json
+import os
+
+ACCEPTANCE_RANGE=0.2
+
+
+# pylint: disable=R0914
+def analyze_sleepgraph_file(file, thresholds, acceptance_range=ACCEPTANCE_RANGE):
+    with open(file, 'r', encoding='utf-8') as f:
+        soup = BeautifulSoup(f, 'lxml')
+        complete_results={}
+        test_passed=True
+
+        components=thresholds.keys()
+        for component in components:
+            # pylint: disable=W0621
+            results = {}
+            divs = soup.find_all("div", title=lambda t, component=component: t and component in t)
+
+            for div in divs:
+                title = div.get('title')
+                match = re.search(r'\((\d+(?:\.\d+)?)\s*ms\)\s+(\S+)$', title)
+                if match:
+                    time_ms = float(match.group(1))
+                    measurement_name = match.group(2)
+                    if measurement_name in thresholds[component]:
+                        results[measurement_name] = {"value": time_ms, "pass": True}
+                        threshold = float(thresholds[component][measurement_name])
+                        # pylint: disable=R1716
+                        if time_ms<(threshold * (1-acceptance_range)) or time_ms>(threshold * (1+acceptance_range)):
+                            results[measurement_name]["pass"] = False
+                            test_passed = False
+
+            complete_results[component]=results
+
+        print(complete_results)
+        return test_passed, complete_results
+
+
+def save_results_to_file(result):
+    # pylint: disable=W0621
+    results_file = f"{os.getenv("LOG_ROOT")}/resume_time_results.json"
+    data = []
+
+    if Path(results_file).is_file():
+        with open(results_file, 'r', encoding='utf-8') as f:
+            data = json.load(f)
+            
+    data.append(result)
+    print(f"Current results: {data}")
+
+    with open(results_file, "w", encoding='utf-8') as f:
+        f.write(json.dumps(data))
+    return results_file
+    
+
+if __name__ == "__main__":
+    if len(sys.argv) != 3:
+        print("Incorrect args. Usage: python3 analyze-sleepgraph-results.py <path_to_html_file> <thresholds_as_json_str>")
+        sys.exit(1)
+
+    sleepgraph_file = sys.argv[1]
+    sleepgraph_thresholds = json.loads(sys.argv[2])
+    
+    test_pass, results = analyze_sleepgraph_file(sleepgraph_file, sleepgraph_thresholds)
+    print(f"Sleepgraph report analysis passed: {test_pass}")
+
+    results_file = save_results_to_file(results)
+    print(f"Saved results to file: {results_file}")
+    
+    sys.exit(0 if test_pass else 1)
