test-case: latency-baseline: introduce latency tests

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 in a json report file.

Signed-off-by: Dmitrii Golovanov <dmitrii.golovanov@intel.com>

Author: golowanow

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

test-case/latency-baseline.sh

@@ -0,0 +1,228 @@
+#!/bin/bash
+
+##
+## 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 1/2 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.
+##
+
+# shellcheck source=case-lib/lib.sh
+source "$(dirname "${BASH_SOURCE[0]}")"/../case-lib/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 "$@"
+
+setup_kernel_check_point
+
+# shellcheck disable=SC2016
+AWK_SCRIPT='
+function min(in_array)
+{
+  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 = "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)
+{
+  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)
+{
+  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))
+}
+
+/^[ ]*[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()
+  }
+}
+'
+opts_json()
+{
+  local items_=()
+  for idx_ in "${!OPT_NAME[@]}" ; do
+    items_+=("\"${OPT_NAME[$idx_]}\":\"${OPT_VAL[$idx_]}\"")
+  done
+  echo "$(IFS=',' ; printf "%s" "${items_[*]}")"
+}
+
+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
+  dloge "No playback or capture Jack port is specified. Skip the test."
+  exit 2
+fi
+
+check_jackd_configured()
+{
+  export JACK_NO_AUDIO_RESERVATION=1
+  dlogc "jackd ${JACKD_OPTIONS} -d ${JACKD_BACKEND} ${JACKD_BACKEND_OPTIONS}"
+  # shellcheck disable=SC2086
+  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()
+{
+  export JACK_NO_AUDIO_RESERVATION=1
+  dlogc "jackd ${JACKD_OPTIONS} -d ${JACKD_BACKEND} ${JACKD_BACKEND_OPTIONS}"
+  # shellcheck disable=SC2086
+  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 >(gawk "${AWK_SCRIPT}" > "${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."
+}
+
+# TODO: should we set volume to some pre-defined level (parameterized)
+# reset_sof_volume
+# set_alsa_settings
+
+start_test
+
+logger_disabled || func_lib_start_log_collect
+
+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
+  dloge "No metrics collected"
+  exit 2
+fi
+
+dlogi "Compose results.json"
+echo -n "{\"options\":{$(opts_json)}," > "${LOG_ROOT}/results.json"
+cat "${LOG_ROOT}/metrics.json" >> "${LOG_ROOT}/results.json" && rm "${LOG_ROOT}/metrics.json"
+echo "}" >> "${LOG_ROOT}/results.json"
+
+#