diff --git a/case-lib/jack_iodelay_metrics.awk b/case-lib/jack_iodelay_metrics.awk new file mode 100755 index 00000000..edd52818 --- /dev/null +++ b/case-lib/jack_iodelay_metrics.awk @@ -0,0 +1,30 @@ +#!/usr/bin/gawk -f + +# SPDX-License-Identifier: BSD-3-Clause +# Copyright(c) 2025 Intel Corporation. All rights reserved. + +# Process `jack_iodelay` output to extract latency measurements, +# and calculate some general statistics: min, max, avg, stddev. +# The resulting output is a json dictionary. + +@include "lib.awk" + +/^[ ]*[0-9.]+ frames[ ]+[0-9.]+ ms total roundtrip latency/ { + sum_frames+=$1 + sum_ms+=$3 + latency_frames[NR]=$1 + latency_ms[NR]=$3 +} + +END { + if (length(latency_frames) !=0 && length(latency_ms) != 0) { + printf("\"metric_name\":\"roundtrip latency\", ") + printf("\"probes\":%d, ", length(latency_frames)) + printf("\"avg_frames\":%0.3f, ", (length(latency_frames) ? sum(latency_frames) / length(latency_frames) : 0)) + printf("\"min_frames\":%0.3f, \"max_frames\":%0.3f, ", min(latency_frames), max(latency_frames)) + printf("\"avg_ms\":%0.3f, ", (length(latency_ms) ? sum(latency_ms) / length(latency_ms) : 0)) + printf("\"min_ms\":%0.3f, \"max_ms\":%0.3f, ", min(latency_ms), max(latency_ms)) + printf("\"stdev_frames\":%0.6f, \"stdev_ms\":%0.6f", stddev(latency_frames), stddev(latency_ms)) + fflush() + } +} diff --git a/case-lib/jackd_events.awk b/case-lib/jackd_events.awk new file mode 100755 index 00000000..cfca1676 --- /dev/null +++ b/case-lib/jackd_events.awk @@ -0,0 +1,15 @@ +#!/usr/bin/gawk -f + +# SPDX-License-Identifier: BSD-3-Clause +# Copyright(c) 2025 Intel Corporation. All rights reserved. + +# Process `jackd` output to count XRun's. + +/JackEngine::XRun: client = jack_delay/ { + xrun_cnt+=1 +} + +END { + printf("\"xruns\":%d", xrun_cnt) + fflush() +} diff --git a/case-lib/lib.awk b/case-lib/lib.awk new file mode 100755 index 00000000..7c5120d4 --- /dev/null +++ b/case-lib/lib.awk @@ -0,0 +1,55 @@ +#!/usr/bin/gawk -f + +# SPDX-License-Identifier: BSD-3-Clause +# Copyright(c) 2025 Intel Corporation. All rights reserved. + +# A library of functions to re-use in AWK scripts. + +function min(in_array, min_value,idx) +{ + min_value = "N/A" + if (! isarray(in_array) || length(in_array) == 0) return min_value + for(idx in in_array) { + if (min_value == "N/A" || in_array[idx] < min_value) { + min_value = in_array[idx] + } + } + return min_value +} + +function max(in_array, max_value,idx) +{ + max_value = "N/A" + if (! isarray(in_array) || length(in_array) == 0) return max_value + for(idx in in_array) { + if (max_value == "N/A" || in_array[idx] > max_value) { + max_value = in_array[idx] + } + } + return max_value +} + +function sum(in_array, sum_items,idx) +{ + if (! isarray(in_array) || length(in_array) == 0) return 0 + sum_items=0 + for(idx in in_array) { + sum_items += in_array[idx] + } + return sum_items +} + +function stddev(in_array, sum_items,cnt_items,idx,avg,dev) +{ + if (! isarray(in_array) || length(in_array) == 0) return -1 + sum_items=0 + cnt_items=0 + for(idx in in_array) { + sum_items += in_array[idx] + cnt_items += 1 + } + avg = sum_items / cnt_items + dev = 0 + for(idx in in_array) dev += (in_array[idx] - avg)^2 + return sqrt(dev/(cnt_items - 1)) +} diff --git a/case-lib/opt.sh b/case-lib/opt.sh index 7f08690d..8bada3a2 100644 --- a/case-lib/opt.sh +++ b/case-lib/opt.sh @@ -1,7 +1,7 @@ #!/bin/bash # SPDX-License-Identifier: BSD-3-Clause -# Copyright(c) 2021 Intel Corporation. All rights reserved. +# Copyright(c) 2021-2025 Intel Corporation. All rights reserved. # These four arrays are used to define script options, and they should # be indexed by a character [a-zA-Z], which is the option short name. @@ -26,6 +26,17 @@ add_common_options() OPT_DESC['h']='show help information' } +# Convert options to a json dictionary. +options2json() +{ + local items_=() + for idx_ in "${!OPT_NAME[@]}" ; do + items_+=("\"${OPT_NAME[$idx_]}\":\"${OPT_VAL[$idx_]}\"") + done + # NOTE: use [*] to join array elements into a string, so IFS is applied. + echo "$(IFS=',' ; printf "%s" "${items_[*]}")" +} + # validate command line options, override default option value, # and dump help func_opt_parse_option() diff --git a/env-check.sh b/env-check.sh index 2b2a75eb..c47d4a24 100755 --- a/env-check.sh +++ b/env-check.sh @@ -81,11 +81,18 @@ main "$@" out_str="" check_res=0 printf "Checking for some OS packages:\t\t" +func_check_pkg gawk func_check_pkg expect func_check_pkg aplay func_check_pkg sox func_check_pkg tinycap func_check_pkg tinyplay +# JACK Audio Connection Kit +func_check_pkg jackd +func_check_pkg jack_iodelay +func_check_pkg jack_lsp +func_check_pkg jack_connect +# func_check_pkg python3 # jq is command-line json parser func_check_pkg jq diff --git a/test-case/latency-metrics.sh b/test-case/latency-metrics.sh new file mode 100755 index 00000000..0a288177 --- /dev/null +++ b/test-case/latency-metrics.sh @@ -0,0 +1,305 @@ +#!/bin/bash + +# SPDX-License-Identifier: BSD-3-Clause +# Copyright(c) 2025 Intel Corporation. All rights reserved. + +## +## Case Name: collect latency statistics on a signal path using JACK +## +## Preconditions: +## - JACK Audio Connection Kit is installed. +## - loopback connection is set to measure latency over the signal path. +## +## Description: +## Run `jackd` audio server and execute `jack_iodelay` with its in/out ports +## connected to the loopback-ed ports giving it some time to collect latency +## measurements (every 0.5 sec.) and 'xrun' errors, if any. +## The 'xrun' errors can be ignored if there are less than a threshold given. +## Optionally, run in 'triial' mode repeating latency measurements reducing +## buffer size to find the smallest/fastest possible. +## +## Case steps: +## 0. Set ALSA parameters. +## 1. Try to start `jackd` with parameters given and read its configuration. +## 2. Start `jackd` again for the latency measurements. +## 3. Start `jack_iodelay` which awaits for its ports connected to a loopback. +## 4. Connect `jack_iodelay` ports to the loopback signal path ports. +## 5. Run and wait for the time given collecting latency measurements. +## 6. Calculate latency statistics and save them into a JSON file. +## 7. Optionally, repeat the above latency measurements with decreased buffer +## size to find the smallest latency possible. +## +## Expect result: +## Latency statistics collected and saved in `test_result.json` file. +## Exit status 0. +## + +TESTDIR=$(cd "$(dirname "${BASH_SOURCE[0]}")/.." && pwd) +TESTLIB="${TESTDIR}/case-lib" + +# shellcheck source=case-lib/lib.sh +source "${TESTLIB}/lib.sh" + +OPT_NAME['R']='running-time' OPT_DESC['R']='Test running time (in seconds) to collect latency probes.' +OPT_HAS_ARG['R']=1 OPT_VAL['R']="30" + +OPT_NAME['d']='device' OPT_DESC['d']='ALSA pcm device for playback and capture. Example: hw:0' +OPT_HAS_ARG['d']=1 OPT_VAL['d']='' + +OPT_NAME['p']='pcm_p' OPT_DESC['p']='ALSA pcm device for playback only. Example: hw:soundwire,0' +OPT_HAS_ARG['p']=1 OPT_VAL['p']='' + +OPT_NAME['c']='pcm_c' OPT_DESC['c']='ALSA pcm device for capture only. Example: hw:soundwire,1' +OPT_HAS_ARG['c']=1 OPT_VAL['c']='' + +OPT_NAME['r']='rate' OPT_DESC['r']='Sample rate to try latency with' +OPT_HAS_ARG['r']=1 OPT_VAL['r']=48000 + +OPT_NAME['f']='frames' OPT_DESC['f']='jackd alsa --period, number of frames.' +OPT_HAS_ARG['f']=1 OPT_VAL['f']=1024 # JACK's default + +OPT_NAME['n']='nperiods' OPT_DESC['n']='jackd alsa --nperiods, periods in the buffer.' +OPT_HAS_ARG['n']=1 OPT_VAL['n']=2 # JACK's default and min value. + +OPT_NAME['S']='shorts' OPT_DESC['S']='Try to use 16-bit samples instead of 32-bit, if possible.' +OPT_HAS_ARG['S']=0 OPT_VAL['S']=0 + +OPT_NAME['P']='port_p' OPT_DESC['P']='JACK playback port with loopback.' +OPT_HAS_ARG['P']=1 OPT_VAL['P']='system:playback_1' + +OPT_NAME['C']='port_c' OPT_DESC['C']='JACK capture port with loopback.' +OPT_HAS_ARG['C']=1 OPT_VAL['C']='system:capture_1' + +OPT_NAME['s']='sof-logger' OPT_DESC['s']="Open sof-logger trace the data will store at $LOG_ROOT" +OPT_HAS_ARG['s']=0 OPT_VAL['s']=1 + +OPT_NAME['v']='verbose' OPT_DESC['v']='Verbose logging.' +OPT_HAS_ARG['v']=0 OPT_VAL['v']=0 + +OPT_NAME['X']='xruns-ignore' OPT_DESC['X']="How many 'xrun' errors to ignore." +OPT_HAS_ARG['X']=1 OPT_VAL['X']=0 + +OPT_NAME['L']='loopback' OPT_DESC['L']="Set internal loopback at JACK instead of ports." +OPT_HAS_ARG['L']=0 OPT_VAL['L']=0 + +OPT_NAME['t']='trial' OPT_DESC['t']="Trial mode: repeat measurements decreasing buffer." +OPT_HAS_ARG['t']=0 OPT_VAL['t']=0 + +OPT_NAME['T']='trial-until' OPT_DESC['T']="Trial mode: repeat until this value." +OPT_HAS_ARG['T']=1 OPT_VAL['T']=2 + +func_opt_parse_option "$@" + +alsa_device=${OPT_VAL['d']} +pcm_p=${OPT_VAL['p']} +pcm_c=${OPT_VAL['c']} +alsa_shorts=$([ "${OPT_VAL['S']}" -eq 1 ] && echo '--shorts' || echo '') +port_playback=${OPT_VAL['P']} +port_capture=${OPT_VAL['C']} +rate=${OPT_VAL['r']} +run_period=${OPT_VAL['R']} +run_verbose=$([ "${OPT_VAL['v']}" -eq 1 ] && echo '--verbose' || echo '') +max_xruns=${OPT_VAL['X']} +set_loopback=${OPT_VAL['L']} +jackd_frames=${OPT_VAL['f']} +jackd_period=${jackd_frames} +jackd_nperiods=${OPT_VAL['n']} +trial_mode=${OPT_VAL['t']} +trial_until=${OPT_VAL['T']} + +METRICS_JSON="${LOG_ROOT}/metrics_iodelay.json" +EVENTS_JSON="${LOG_ROOT}/events_jackd.json" +RESULT_JSON="${LOG_ROOT}/test_result.json" +RUN_PERIOD_MAX="$((run_period + 30))s" +JACKD_TIMEOUT="$((run_period + 15))s" +JACKD_OPTIONS=("--realtime" "--temporary") +JACKD_BACKEND="alsa" +JACKD_BACKEND_OPTIONS=("-n" "${jackd_nperiods}" "-r" "${rate}" "${alsa_shorts}") +WAIT_JACKD="2s" +IODELAY_TIMEOUT="${run_period}s" +WAIT_IODELAY="2s" + +check_latency_options() +{ + if [ -n "${alsa_device}" ]; then + if [ -n "${pcm_p}" ] || [ -n "${pcm_c}" ]; then + skip_test "Give either ALSA device, or ALSA playback/capture pcm-s." + fi + JACKD_BACKEND_OPTIONS=("-d" "${alsa_device}" "${JACKD_BACKEND_OPTIONS[@]}") + elif [ -z "${pcm_p}" ] || [ -z "${pcm_c}" ]; then + skip_test "No playback or capture ALSA PCM is specified." + else + JACKD_BACKEND_OPTIONS=("-P" "${pcm_p}" "-C" "${pcm_c}" "${JACKD_BACKEND_OPTIONS[@]}") + fi + + if [ "${set_loopback}" == 1 ]; then + port_playback="${set_loopback}" + port_capture="${set_loopback}" + fi + + if [ -z "${port_playback}" ] || [ -z "${port_capture}" ]; then + skip_test "No playback or capture JACK port is specified." + fi +} + +set_alsa() +{ + reset_sof_volume + + # If MODEL is defined, set proper gain for the platform + if [ -z "$MODEL" ]; then + dlogw "NO MODEL is defined. Please define MODEL to run alsa_settings/MODEL.sh" + else + set_alsa_settings "$MODEL" + fi +} + +# set/update commands in case the test iterates or sweep over a range +compose_commands() +{ + TIMEOUT_RUN=(timeout "--kill-after" "${RUN_PERIOD_MAX}") + [ -z "${run_verbose}" ] || TIMEOUT_RUN+=("${run_verbose}") + + [ -z "${run_verbose}" ] || JACKD_OPTIONS+=("${run_verbose}") + JACKD_RUN=(jackd "${JACKD_OPTIONS[@]}" -d "${JACKD_BACKEND}" "${JACKD_BACKEND_OPTIONS[@]}" -p "${jackd_period}") + + TIMEOUT_JACKD_RUN=("${TIMEOUT_RUN[@]}" "${JACKD_TIMEOUT}" "${JACKD_RUN[@]}") +} + +check_jackd_configured() +{ + dlogi "Check JACK audio server can be started" + + compose_commands + + dlogc "${TIMEOUT_JACKD_RUN[*]}" + "${TIMEOUT_JACKD_RUN[@]}" & jackdPID=$! + + sleep ${WAIT_JACKD} + + dlogc "jack_lsp -AclLpt" + jack_lsp -AclLpt + + dlogi "Waiting jackd to stop without a client" + wait ${jackdPID} +} + +collect_latency_data() +{ + dlogi "Start collecting latency data" + + compose_commands + + dlogc "${TIMEOUT_JACKD_RUN[*]}" + "${TIMEOUT_JACKD_RUN[@]}" 2>&1 | \ + tee >(AWKPATH="${TESTLIB}:${AWKPATH}" \ + gawk -f "${TESTLIB}/jackd_events.awk" > "${EVENTS_JSON}") & jackdPID="$!" + + sleep ${WAIT_JACKD} + + dlogc "jack_iodelay" + "${TIMEOUT_RUN[@]}" "${IODELAY_TIMEOUT}" \ + stdbuf -oL -eL jack_iodelay 2>&1 | \ + tee >(AWKPATH="${TESTLIB}:${AWKPATH}" \ + gawk -f "${TESTLIB}/jack_iodelay_metrics.awk" > "${METRICS_JSON}") & iodelayPID="$!" + + sleep ${WAIT_IODELAY} + if [ "${set_loopback}" == 1 ]; then + dlogi "jack_connect: [JACK loopback]<==>[jack_delay]" + jack_connect jack_delay:out jack_delay:in + else + dlogi "jack_connect: [${port_capture}]==>[jack_delay]==>[${port_playback}]" + jack_connect jack_delay:out "${port_playback}" && jack_connect jack_delay:in "${port_capture}" + fi + + dlogi "Latency data collection" + wait ${jackdPID} ${iodelayPID} + + dlogi "Latency data collection completed for period=${jackd_period} frames." +} + +report_start() +{ + dlogi "Compose ${RESULT_JSON}" + printf '{"options":{%s}, "metrics":[' "$(options2json)" > "${RESULT_JSON}" +} + +json_next_sep="" + +report_metric() +{ + printf '%s{"period_frames":%d, "periods":%d, "rate":%d, ' \ + "${json_next_sep}" "${jackd_period}" "${jackd_nperiods}" "${rate}" >> "${RESULT_JSON}" + + if [ ! -f "${METRICS_JSON}" ] || [ "$(grep -ce 'metric_name' "${METRICS_JSON}")" -lt 1 ]; then + printf '"probes":0, "xruns":0}' >> "${RESULT_JSON}" + [ -f "${METRICS_JSON}" ] && rm "${METRICS_JSON}" + [ -f "${EVENTS_JSON}" ] && rm "${EVENTS_JSON}" + [ "${trial_mode}" -ne 0 ] || skip_test "No latency metrics collected" + else + local metrics_ + metrics_=$(cat "${METRICS_JSON}") + dlogi "latency metrics: ${metrics_}" + + if [ -f "${EVENTS_JSON}" ]; then + local events_ + events_=$(cat "${EVENTS_JSON}") + dlogi "jackd events: ${events_}" + rm "${EVENTS_JSON}" + metrics_="${metrics_}, ${events_}" + fi + + printf '%s}' "${metrics_}" >> "${RESULT_JSON}" && rm "${METRICS_JSON}" + + xruns=$(echo "{${metrics_}}" | jq 'select(.xruns > 0).xruns') + if [ -n "${xruns}" ] && [ "${xruns}" -gt "${max_xruns}" ]; then + printf ']}' >> "${RESULT_JSON}" + skip_test "XRuns: ${xruns} detected!" + fi + fi + json_next_sep="," +} + +report_end() +{ + [ -n "${json_next_sep}" ] && printf ']' >> "${RESULT_JSON}" + printf '}\n' >> "${RESULT_JSON}" + cat "${RESULT_JSON}" +} + +main() +{ + check_latency_options + + setup_kernel_check_point + + start_test + + logger_disabled || func_lib_start_log_collect + + set_alsa + + check_jackd_configured + + report_start + + while [ "${jackd_period}" -ge "${trial_until}" ]; do + + dlogi "Measuring latency with period=${jackd_period} frames." + + collect_latency_data + + report_metric + + jackd_period="$((jackd_period / 2))" + + [ "${trial_mode}" -ne 0 ] || break + + done + + report_end +} + +{ + main "$@"; exit "$?" +}