From 6aea288dc3384c431c8d54e6f2a4f85990b16fa8 Mon Sep 17 00:00:00 2001 From: Keqiao Zhang Date: Wed, 14 Sep 2022 09:27:49 +0800 Subject: [PATCH 1/6] lib.sh: move logger collection to a function Signed-off-by: Keqiao Zhang --- case-lib/lib.sh | 68 +++++++++++++++++++++++++++---------------------- 1 file changed, 38 insertions(+), 30 deletions(-) diff --git a/case-lib/lib.sh b/case-lib/lib.sh index 33f54d0d..67eef977 100644 --- a/case-lib/lib.sh +++ b/case-lib/lib.sh @@ -293,6 +293,33 @@ find_ldc_file() printf '%s' "$ldcFile" } +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,29 +342,7 @@ 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 @@ -347,13 +352,16 @@ func_lib_start_log_collect() 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 + log_file=$LOG_ROOT/slogger.txt + log_opt="-t" + func_sof_logger_collect "$log_file" "$log_opt" + else + log_file=$LOG_ROOT/etrace.txt + log_opt="" + func_sof_logger_collect "$log_file" "$log_opt" + fi + } check_error_in_file() From c26ba479626047b9d03dc84cd83e269cd3facb54 Mon Sep 17 00:00:00 2001 From: Keqiao Zhang Date: Wed, 14 Sep 2022 09:33:51 +0800 Subject: [PATCH 2/6] lib.sh: add a function for mtrace collection mtrace is a new logging tool. Tool to stream data from Linux SOF driver mtrace debugfs interface to standard output. Signed-off-by: Keqiao Zhang --- case-lib/lib.sh | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/case-lib/lib.sh b/case-lib/lib.sh index 67eef977..d20f857b 100644 --- a/case-lib/lib.sh +++ b/case-lib/lib.sh @@ -293,6 +293,24 @@ 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 From 273822e9dc513ac0128584ebdac133aa053a0193 Mon Sep 17 00:00:00 2001 From: Keqiao Zhang Date: Wed, 14 Sep 2022 15:00:01 +0800 Subject: [PATCH 3/6] lib.sh: add a function to check the IPC4 Zephyr firmware This function can check if the running firmware is IPC4 Zephyr. Signed-off-by: Keqiao Zhang --- case-lib/lib.sh | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/case-lib/lib.sh b/case-lib/lib.sh index d20f857b..67789e3b 100644 --- a/case-lib/lib.sh +++ b/case-lib/lib.sh @@ -693,6 +693,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 From 684cb644224fe5c671aef37576d55ccc2d9e8461 Mon Sep 17 00:00:00 2001 From: Keqiao Zhang Date: Wed, 14 Sep 2022 13:54:27 +0800 Subject: [PATCH 4/6] lib.sh: enable the mtrace for IPC4 Zephyr platforms The mtrace is only support IPC4 platforms and mtrace should run while tests are running ATM. If mtrace is not running, DSP will stop outputting logs when buffer is full. So we need to keep the mtrace running during the test, or you won't see the error log. Signed-off-by: Keqiao Zhang --- case-lib/lib.sh | 34 ++++++++++++++++++---------------- 1 file changed, 18 insertions(+), 16 deletions(-) diff --git a/case-lib/lib.sh b/case-lib/lib.sh index 67789e3b..fabcf389 100644 --- a/case-lib/lib.sh +++ b/case-lib/lib.sh @@ -366,18 +366,24 @@ func_lib_start_log_collect() # 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 if [ "X$is_etrace" == "X0" ];then - log_file=$LOG_ROOT/slogger.txt - log_opt="-t" - func_sof_logger_collect "$log_file" "$log_opt" + 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 - log_file=$LOG_ROOT/etrace.txt - log_opt="" - func_sof_logger_collect "$log_file" "$log_opt" + is_ipc4_zephyr || { + log_file=$LOG_ROOT/etrace.txt + log_opt="" + func_sof_logger_collect "$log_file" "$log_opt" + } fi } @@ -735,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 } From 22305341e1f80cbbfa464274da9b57906b76d074 Mon Sep 17 00:00:00 2001 From: Keqiao Zhang Date: Fri, 9 Sep 2022 15:47:59 +0800 Subject: [PATCH 5/6] hijack.sh: kill the mtrace after test Need to kill the mtrace-reader.py process after the test to prevent the conflicts between each case. Signed-off-by: Keqiao Zhang --- case-lib/hijack.sh | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) 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 From 897c36f296b359c1e6f3e53a1f032a8194b087ef Mon Sep 17 00:00:00 2001 From: Kai Vehmanen Date: Wed, 14 Sep 2022 13:14:55 +0300 Subject: [PATCH 6/6] check-playback: add check for FW performance Add a tool to analyze the performance traces that are emitted by the FW low-latency scheduler, and use this tool in the check playback test case. The tool requires output of FW logs and currently only supports the mtrace output available in SOF Zephyr IPC4 builds. This can be extended later for other output types. The sof-ll-timer-check.py can do some simple global check like observing occurences of low-latency scheduler overruns and raise an error in this case. For most of the analysis, sof-ll-timer-check.py needs reference data detailing what the expected performance level should be. To implement this, a simple JSON database is added via sof-ll-timer-check-db.json that is used to query the reference data. As this data is manually maintained, it is expected reference data is only used for a small set of key use-cases for any given platform. Signed-off-by: Kai Vehmanen --- test-case/check-playback.sh | 9 +++++ tools/sof-ll-timer-check-db.json | 11 ++++++ tools/sof-ll-timer-check.py | 59 ++++++++++++++++++++++++++++++++ 3 files changed, 79 insertions(+) create mode 100644 tools/sof-ll-timer-check-db.json create mode 100755 tools/sof-ll-timer-check.py 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)