diff --git a/case-lib/hijack.sh b/case-lib/hijack.sh index 2c9986c9..60c10b4b 100644 --- a/case-lib/hijack.sh +++ b/case-lib/hijack.sh @@ -7,6 +7,8 @@ trap 'func_exit_handler $?' EXIT function func_exit_handler() { local exit_status=${1:-0} + local loggerBin wcLog; loggerBin=sof-logger + local mtraceBin; mtraceBin=mtrace-reader.py # call trace if [ "$exit_status" -ne 0 ] ; then @@ -24,7 +26,7 @@ function func_exit_handler() fi # when sof logger collect is open - if [ "X$SOF_LOG_COLLECT" == "X1" ]; then + if [ "X$SOF_LOG_COLLECT" == "X1" ] && ! is_ipc4_zephyr; then # when error occurs, exit and catch etrace log [[ $exit_status -eq 1 ]] && { func_lib_start_log_collect 1 @@ -54,7 +56,6 @@ function func_exit_handler() # shellcheck disable=SC2154 logfile="$logfile" - local loggerBin wcLog; loggerBin=$(basename "$SOFLOGGER") # We need this to avoid the confusion of a "Terminated" message # without context. dlogi "pkill -TERM $loggerBin" @@ -100,6 +101,14 @@ function func_exit_handler() fi + if is_ipc4_zephyr; then + dlogi "pkill -TERM -f $mtraceBin" + sudo pkill -TERM -f "$mtraceBin" || { + dloge "mtrace-reader.py was already dead" + exit_status=1 + } + fi + stop_test || exit_status=1 if [ "$ENABLE_STORAGE_CHECKS" = '1' ]; then diff --git a/case-lib/lib.sh b/case-lib/lib.sh index 33f54d0d..fabcf389 100644 --- a/case-lib/lib.sh +++ b/case-lib/lib.sh @@ -293,6 +293,51 @@ find_ldc_file() printf '%s' "$ldcFile" } +func_mtrace_collect() +{ + local clogfile=$LOG_ROOT/mtrace.txt + + if [ -z "$MTRACE" ]; then + MTRACE=$(command -v mtrace-reader.py) || { + dlogw 'No mtrace-reader.py found in PATH' + return 1 + } + fi + + local mtraceCmd="$MTRACE" + dlogi "Starting ${mtraceCmd[*]}" + # Cleaned up by func_exit_handler() in hijack.sh + # shellcheck disable=SC2024 + sudo "${mtraceCmd[@]}" >& "$clogfile" & +} + +func_sof_logger_collect() +{ + logfile=$1 + logopt=$2 + ldcFile=$(find_ldc_file) || return $? + + if [ -z "$SOFLOGGER" ]; then + SOFLOGGER=$(command -v sof-logger) || { + dlogw 'No sof-logger found in PATH' + return 1 + } + fi + + test -x "$SOFLOGGER" || { + dlogw "$SOFLOGGER not found or not executable" + return 2 + } + + # The logger does not like empty '' arguments and $logopt can be + # shellcheck disable=SC2206 + local loggerCmd=("$SOFLOGGER" $logopt -l "$ldcFile") + dlogi "Starting ${loggerCmd[*]}" + # Cleaned up by func_exit_handler() in hijack.sh + # shellcheck disable=SC2024 + sudo "${loggerCmd[@]}" > "$logfile" & +} + SOF_LOG_COLLECT=0 # This function starts a logger in the background using '&' # @@ -315,45 +360,32 @@ SOF_LOG_COLLECT=0 func_lib_start_log_collect() { local is_etrace=${1:-0} ldcFile - - ldcFile=$(find_ldc_file) || return $? - - local logopt="-t" - - if [ -z "$SOFLOGGER" ]; then - SOFLOGGER=$(command -v sof-logger) || { - dlogw 'No sof-logger found in PATH' - return 1 - } - fi - - test -x "$SOFLOGGER" || { - dlogw "$SOFLOGGER not found or not executable" - return 2 - } - - if [ "X$is_etrace" == "X0" ];then - logfile=$LOG_ROOT/slogger.txt - else - logfile=$LOG_ROOT/etrace.txt - logopt="" - fi + local log_file log_opt if func_hijack_setup_sudo_level ;then # shellcheck disable=SC2034 # external script will use it SOF_LOG_COLLECT=1 else - >&2 dlogw "without sudo permission to run $SOFLOGGER command" + >&2 dlogw "without sudo permission to run logging command" return 3 fi - # The logger does not like empty '' arguments and $logopt can be - # shellcheck disable=SC2206 - local loggerCmd=("$SOFLOGGER" $logopt -l "$ldcFile") - dlogi "Starting ${loggerCmd[*]}" - # Cleaned up by func_exit_handler() in hijack.sh - # shellcheck disable=SC2024 - sudo "${loggerCmd[@]}" > "$logfile" & + if [ "X$is_etrace" == "X0" ];then + if is_ipc4_zephyr; then + func_mtrace_collect + else + log_file=$LOG_ROOT/slogger.txt + log_opt="-t" + func_sof_logger_collect "$log_file" "$log_opt" + fi + else + is_ipc4_zephyr || { + log_file=$LOG_ROOT/etrace.txt + log_opt="" + func_sof_logger_collect "$log_file" "$log_opt" + } + fi + } check_error_in_file() @@ -667,6 +699,26 @@ ipc4_used() return 0 } +is_ipc4_zephyr(){ + # check if the ipc_type first + ipc4_used || return 1 + + local firmware_path znum + local firmware_name=dsp_basefw.bin + fw_mod_para=/sys/module/snd_sof_pci/parameters/fw_path + + if [ ! -s "$fw_mod_para" ]; then + firmware_path=$(cat $fw_mod_para) + else + # TODO: let the kernel driver expose the FW path + # and get the FW path by grepping journalctl. + return 1 + fi + + znum=$(strings "/lib/firmware/$firmware_path/$firmware_name" | grep -c -i zephyr) + test "$znum" -gt 10 +} + logger_disabled() { local ldcFile @@ -689,16 +741,12 @@ logger_disabled() return 0 fi - ipc4_used && { - # TODO: - # Need to remove disabling sof-logger - # after sof-logger support for IPC4 has been provided in the future - dlogi 'Currenly sof-logger is not supported when running IPC4 mode' - dlogi 'SOF logs collection is globally disabled because DUT is running IPC4 mode' + if ipc4_used && ! is_ipc4_zephyr; then + # mtrace and sof-logger are not supported for closed source IPC4 Firmware + dlogi 'IPC4 FW logging only support with SOF Zephyr build' + dlogi 'SOF logs collection is globally disabled.' return 0 - } - dlogi 'DUT is running IPC3 mode' - + fi return 1 } diff --git a/test-case/check-playback.sh b/test-case/check-playback.sh index bd40e005..24e38462 100755 --- a/test-case/check-playback.sh +++ b/test-case/check-playback.sh @@ -97,6 +97,15 @@ do func_lib_lsof_error_dump "$snd" die "aplay on PCM $dev failed at $i/$loop_cnt." } + + tplg_basename=$(basename $tplg) + platform=$(sof-dump-status.py -p) + is_ipc4_zephyr && { + data_file=$LOG_ROOT/mtrace.txt + test_reference_key="${platform}-${tplg_basename}-ipc4-zephyr-check-playback-${dev}" + TOPDIR="$(dirname "${BASH_SOURCE[0]}")"/.. + $TOPDIR/tools/sof-ll-timer-check.py ${data_file} $test_reference_key $TOPDIR/tools/sof-ll-timer-check-db.json + } done done done diff --git a/tools/sof-ll-timer-check-db.json b/tools/sof-ll-timer-check-db.json new file mode 100644 index 00000000..edea2068 --- /dev/null +++ b/tools/sof-ll-timer-check-db.json @@ -0,0 +1,11 @@ +[ + { + "test-key": "tgl-sof-tgl-nocodec.tplg-ipc4-zephyr-check-playback-hw:0,0" , + "ll-timer-avg": 2589 + }, + { + "test-key": "tgl-sof-tgl-nocodec.tplg-ipc4-zephyr-check-playback-hw:0,1" , + "ll-timer-avg": 2589 + } +] + diff --git a/tools/sof-ll-timer-check.py b/tools/sof-ll-timer-check.py new file mode 100755 index 00000000..972cc3ec --- /dev/null +++ b/tools/sof-ll-timer-check.py @@ -0,0 +1,59 @@ +#!/usr/bin/env python3 + +'''Script to analyze performance data in SOF FW log output''' + +import sys +import re +import json +from statistics import median + +# allowed error margin before error is raised for +# lower observed performance (1.05 -> 5% difference +# required to raise error) +AVG_ERROR_MARGIN = 1.05 + +max_vals = [] +avg_vals = [] +overruns = 0 + +f = open(sys.argv[1]) + +for line in f: + m = re.search('.*ll timer avg ([0-9]*), max ([0-9]*), overruns ([0-9]*)', line) + if m: + avg_vals.append(int(m.group(1))) + max_vals.append(int(m.group(2))) + overruns += int(m.group(3)) + +median_avg_vals = median(avg_vals) +print("Measurements:\t\t%d" % len(avg_vals)) +print("Median avg reported:\t%d" % median_avg_vals) +print("Median max reported:\t%d" % median(max_vals)) +print("Highest max reported:\t%d" % max(max_vals)) + +if overruns: + print("ERROR: %s overruns detected" % overruns, file=sys.stderr) + sys.exit(-1) + +if len(sys.argv) < 4: + print("No reference data for key '%s', unable to check performance against reference") + sys.exit(0) + +median_avg_ref = None +dbfile = open(sys.argv[3]) +ref_key = sys.argv[2] +ref_data_all = json.load(dbfile) + +for ref in ref_data_all: + if ref["test-key"] == ref_key: + median_avg_ref = ref["ll-timer-avg"] + break + +if not median_avg_ref: + print("No reference data for key '%s', unable to check performance against reference" % ref_key) + sys.exit(0) + +median_avg_ref_w_margin = median_avg_ref * AVG_ERROR_MARGIN +if median_avg_vals > median_avg_ref_w_margin: + print("ERROR: ll-timer-avg median %d over threshold %d (%d without margin)" % (median_avg_vals, median_avg_ref_w_margin, median_avg_ref), file=sys.stderr) + sys.exit(-1)