test-case: latency-metrics: introduce latency tests

golowanow · golowanow · commit 4dd2fbae364e · 2025-05-23T11:05:08.000+02:00
Introduce latency tests using `JACK` Audio Connection Kit:
run `jackd` audio service, connect ports with loopback
and run `jack_iodelay` to collect latency measurements,
calculate and save statistics into a json report file.

Signed-off-by: Dmitrii Golovanov &lt;dmitrii.golovanov@intel.com&gt;
diff --git a/case-lib/jack_iodelay_metrics.awk b/case-lib/jack_iodelay_metrics.awk
@@ -0,0 +1,31 @@
+#!/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("\"metrics\":[")
+    printf("{\"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))
+    printf("]")
+    fflush()
+  }
+}
diff --git a/case-lib/lib.awk 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
@@ -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,16 @@ 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
+  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
@@ -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
@@ -0,0 +1,156 @@
+#!/bin/bash
+
+# SPDX-License-Identifier: BSD-3-Clause
+# Copyright(c) 2025 Intel Corporation. All rights reserved.
+
+##
+## Case Name: latency baseline statistics collection on a signal path
+##
+## Preconditions:
+##    - JACK Audio Connection Kit is installed.
+##    - loopback connection to measure latency over its signal path.
+##
+## Description:
+##    Run `jackd` audio server; execute `jack_iodelay` with its in/out ports
+##    connected to the loopback-ed ports and give it some time ot collect
+##    latency measurements (on each 0.5 sec.)
+##
+## Case step:
+##    1. Probe to start `jackd` with parameters given and read configuration.
+##    2. Start `jackd` again for latency measurements.
+##    3. Start `jack_iodelay` which awaits for its ports connected to loopback.
+##    4. Connect `jack_iodelay` ports to signal path ports with the loopback.
+##    5. Wait for the period given to collect enough latency measurements.
+##    6. Calculate latency statistics and save into a JSON file.
+##
+## Expect result:
+##    Latency statistics collected and saved in `results.json`.
+##    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']='run_period'      OPT_DESC['R']='Time period (in seconds) to measure latency.'
+OPT_HAS_ARG['R']=1              OPT_VAL['R']="30"
+
+OPT_NAME['d']='device'          OPT_DESC['d']='ALSA pcm device to use by JACK'
+OPT_HAS_ARG['d']=1              OPT_VAL['d']="hw:0"
+
+OPT_NAME['r']='rate'            OPT_DESC['r']='Sample rate to try latency with'
+OPT_HAS_ARG['r']=1              OPT_VAL['r']=48000
+
+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. Example: system:playback_1'
+OPT_HAS_ARG['p']=1              OPT_VAL['p']=''
+
+OPT_NAME['c']='port_c'          OPT_DESC['c']='Jack capture port with loopback. Example: system:capture_1'
+OPT_HAS_ARG['c']=1              OPT_VAL['c']=''
+
+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
+
+func_opt_parse_option "$@"
+
+alsa_device=${OPT_VAL['d']}
+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 '')
+
+RUN_PERIOD_MAX="$((run_period + 30))s"
+JACKD_TIMEOUT="$((run_period + 15))s"
+JACKD_OPTIONS="${run_verbose} --realtime --temporary"
+JACKD_BACKEND="alsa"
+JACKD_BACKEND_OPTIONS="-d ${alsa_device} -r ${rate} ${alsa_shorts}"
+WAIT_JACKD="2s"
+IODELAY_TIMEOUT="${run_period}s"
+WAIT_IODELAY="2s"
+
+if [ "$port_playback" == "" ] || [ "$port_capture" == "" ];
+then
+  skip_test "No playback or capture Jack port is specified. Skip the test."
+fi
+
+setup_kernel_check_point
+
+start_test
+
+logger_disabled || func_lib_start_log_collect
+
+check_jackd_configured()
+{
+  dlogc "jackd ${JACKD_OPTIONS} -d ${JACKD_BACKEND} ${JACKD_BACKEND_OPTIONS}"
+  # shellcheck disable=SC2086
+  JACK_NO_AUDIO_RESERVATION=1 timeout --kill-after ${RUN_PERIOD_MAX} ${run_verbose} ${JACKD_TIMEOUT} \
+      jackd ${JACKD_OPTIONS} -d ${JACKD_BACKEND} ${JACKD_BACKEND_OPTIONS} & jackdPID=$!
+
+  sleep ${WAIT_JACKD}
+
+  dlogc "jack_lsp"
+  jack_lsp -AclLpt
+
+  dlogi "Waiting Jackd to stop without a client"
+  wait ${jackdPID}
+}
+
+collect_latency_data()
+{
+  dlogc "jackd ${JACKD_OPTIONS} -d ${JACKD_BACKEND} ${JACKD_BACKEND_OPTIONS}"
+  # shellcheck disable=SC2086
+  JACK_NO_AUDIO_RESERVATION=1 timeout --kill-after ${RUN_PERIOD_MAX} ${run_verbose} ${JACKD_TIMEOUT} \
+      jackd ${JACKD_OPTIONS} -d ${JACKD_BACKEND} ${JACKD_BACKEND_OPTIONS} & jackdPID=$!
+
+  sleep ${WAIT_JACKD}
+  dlogc "jack_iodelay"
+  # shellcheck disable=SC2086
+  timeout --kill-after ${RUN_PERIOD_MAX} ${run_verbose} ${IODELAY_TIMEOUT} \
+      stdbuf -oL -eL jack_iodelay | \
+      tee >(AWKPATH="${TESTLIB}:${AWKPATH}" \
+          gawk -f "${TESTLIB}/jack_iodelay_metrics.awk" > "${LOG_ROOT}/metrics.json") & iodelayPID="$!"
+
+  sleep ${WAIT_IODELAY}
+  dlogi "jack_connect:  ${port_capture} ==>[jack_delay]==> ${port_playback}"
+  jack_connect jack_delay:out "${port_playback}" && jack_connect jack_delay:in "${port_capture}"
+
+  dlogi "Latency data collection"
+  wait ${jackdPID} ${iodelayPID}
+  dlogi "Latency data collection completed."
+}
+
+main()
+{
+  # TODO: should we set volume to some pre-defined level (parameterized)
+  # reset_sof_volume
+  # set_alsa_settings
+
+  dlogi "Check Jack server can be started"
+  check_jackd_configured   # "$@"
+
+  dlogi "Start collecting latency data"
+  collect_latency_data   # "$@"
+
+  if [ ! -f "${LOG_ROOT}/metrics.json" ] || [ "$(grep -ce 'metrics' "${LOG_ROOT}/metrics.json")" -lt 1 ]; then
+    skip_test "No metrics collected"
+  fi
+
+  dlogi "Compose results.json"
+  echo -n "{\"options\":{$(options2json)}," > "${LOG_ROOT}/results.json"
+  cat "${LOG_ROOT}/metrics.json" >> "${LOG_ROOT}/results.json" && rm "${LOG_ROOT}/metrics.json"
+  echo "}" >> "${LOG_ROOT}/results.json"
+  cat "${LOG_ROOT}/results.json"
+}
+
+{
+  main "$@"; exit "$?"
+}
