test: PC10 residency and resume time

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 <emiliax.kurdybelska@intel.com>

Author: ekurdybx

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,39 @@ 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['c']='component-name'         OPT_DESC['c']='component for which we check resume time'
+OPT_HAS_ARG['c']=1                     OPT_VAL['c']=''
+
+OPT_NAME['t']='resume-time'            OPT_DESC['t']='resume time threshold'
+OPT_HAS_ARG['t']=1                     OPT_VAL['t']=''
+
+OPT_NAME['a']='acceptance-range'       OPT_DESC['a']='acceptance range for thresholds'
+OPT_HAS_ARG['a']=1                     OPT_VAL['a']=0.3
 
 func_opt_parse_option "$@"
 func_lib_check_sudo
@@ -69,21 +81,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'
@@ -142,8 +161,9 @@ main()
     sleep 1
 
     local keep_modules=true already_unloaded=false
+    sleepgraph_failures=0
 
-    if [ ${OPT_VAL['u']} = 1 ]; then
+    if [ "${OPT_VAL['u']}" = 1 ]; then
         keep_modules=false
     fi
 
@@ -159,7 +179,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
@@ -168,6 +188,51 @@ main()
         die "Failed to reload audio drivers"
     sof-kernel-log-check.sh "$KERNEL_CHECKPOINT" ||
         die "Found kernel error after reloading audio drivers"
+
+    if [ $sleepgraph_failures -eq 0 ]; then
+        dlogi "FINAL TEST RESULT: All time measurements within the thresholds."
+    else
+        die "FINAL TEST RESULT: Some time measurements not within the thresholds!"
+    fi
+}
+
+analyze_sleepgraph_results()
+{
+    dlogi "Analyzing sleepgraph results"
+    results_file=$(find suspend-*/*.html)
+    cp "$results_file" "$LOG_ROOT/"
+
+    thresholds=$( jq -n \
+                --arg component_name "${OPT_VAL['c']}" \
+                --arg resume_time "${OPT_VAL['t']}" \
+                '{$component_name:{"resume":$resume_time}}')
+
+    thresholds_acceptance_range="${OPT_VAL['a']}"
+
+    dlogi "Analyzing $results_file file..."
+    if python3 "$SCRIPT_HOME"/tools/analyze-sleepgraph-results.py "$results_file" "$thresholds" "$thresholds_acceptance_range"; then
+        dlogi "All times measurements within the thresholds"
+    else
+        dlogw "Time measurements not within the thresholds!"
+        sleepgraph_failures=$((sleepgraph_failures+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()
@@ -179,11 +244,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"

test-case/test-socwatch.sh test-case/residency-time-test.shtest-case/test-socwatch.sh renamed to test-case/residency-time-test.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
@@ -54,7 +50,29 @@ start_test
 
 check_socwatch_module_loaded()
 {
-    lsmod | grep -q socwatch || dlogi "socwatch is not loaded"
+    lsmod | grep -q socwatch || die "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()
@@ -63,35 +81,29 @@ socwatch_test_once()
     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,57 @@ 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"
+
+    # Create a dir for all socwatch reports
+    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"
+    dlogi "****** PC10 STATE RESULTS: ******"
+    dlogi "$results"
+    dlogi "*********************************"
 
-    $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 "$@"