[BUG] arecord TGLU_SKU0A32_SDCA ########+| MAX

[keqiaozhang]

linux #3750 -> sof-test -> #3766

---

UPDATED SUMMARY by @marc-hb : this is a plain arecord issue. Reproduction does not require any test code and it does not require pause/resume. It was found by sheer luck when an upgrade from Ubuntu 2020 to 2022 turned on a capture setting. It was found in pause/resume testing because no other test looks at what arecord captures.

Original description below.

---

Describe the bug
We observed this issue in CI, This codec error happens when testing pause/resume related cases. At first, I suspected it's a upstream regression, this issue can be reproduced on 2 TGLU_SKU0A32_SDCA(jf-tglu-sku0a32-sdca-02 and jf-tglu-sku0a32-sdca-03) devices with 100% reproduction rate when testing pause/resume on hw:0,4. But I didn't see such issue on jf-tglu-sku0a32-sdca-01. Since we replaced the NVME for jf-tglu-sku0a32-sdca-02 and jf-tglu-sku0a32-sdca-03 recently, so not sure if it's a hardware specific issue. I will do further debugging.

To Reproduce
~/sof-test/test-case/check-pause-resume.sh -c 100 -m capture

Reproduction Rate
100%

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel:linux-bccf5da2acbf
   • SOF: sof-9d9c28848def
2. Name of the topology file
   • Topology: sof-tgl-rt711-rt1316-rt714.tplg
3. Name of the platform(s) on which the bug is observed.
   • Platform: TGLU_SKU0A32_SDCA

Screenshots or console output

2022-07-12 02:26:16 UTC [REMOTE_INFO] Entering expect script with:
      arecord   -D hw:0,4 -r 48000 -c 2 -f S16_LE -vv -i /dev/null -q
spawn arecord -D hw:0,4 -r 48000 -c 2 -f S16_LE -vv -i /dev/null -q
Hardware PCM card 0 'sof-soundwire' device 4 subdevice 0
Its setup is:
  stream       : CAPTURE
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 48000
  exact rate   : 48000 (48000/1)
  msbits       : 16
  buffer_size  : 16384
  period_size  : 4096
  period_time  : 85333
  tstamp_mode  : NONE
  tstamp_type  : MONOTONIC
  period_step  : 1
  avail_min    : 4096
  period_event : 0
  start_threshold  : 1
  stop_threshold   : 16384
  silence_threshold: 0
  silence_size : 0
  boundary     : 4611686018427387904
  appl_ptr     : 0
  hw_ptr       : 0

#+                                                 | 00%
(1/100) Wait for 109 ms before pause
 
##################################################+| MAX
=== PAUSE ===                                                            
(1/100) Wait for 174 ms before resume
                                                                           

##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
...
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX2022-07-12 02:26:26 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2022-07-12 02:26:26 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/check-pause-resume.sh
2022-07-12 02:26:26 UTC [REMOTE_INFO] Starting /usr/local/bin/sof-logger -l /etc/sof/sof-tgl.ldc -o /home/ubuntu/sof-test/logs/check-pause-resume/2022-07-12-02:25:43-10951/etrace.txt
2022-07-12 02:26:28 UTC [REMOTE_INFO] pkill -TERM sof-logger
Terminated

dmesg

[ 2769.923098] kernel: soundwire_bus:sdw_modify_slave_status: rt715-sdca sdw:3:025d:0714:01: initializing enumeration and init completion for Slave 7
[ 2769.924089] kernel: soundwire_cadence:cdns_update_slave_status_work: soundwire_intel soundwire_intel.link.3: Slave status change: 0x2
[ 2769.924098] kernel: soundwire_bus:sdw_handle_slave_status: soundwire sdw-master-3: Slave attached, programming device number
[ 2769.924281] kernel: soundwire_bus:sdw_extract_slave_id: soundwire sdw-master-3: SDW Slave Addr: 30025d071401
[ 2769.924284] kernel: soundwire_bus:sdw_extract_slave_id: soundwire sdw-master-3: SDW Slave class_id 0x01, mfg_id 0x025d, part_id 0x0714, unique_id 0x0, version 0x3
[ 2769.924287] kernel: soundwire_bus:sdw_assign_device_num: soundwire sdw-master-3: Slave already registered, reusing dev_num:7
[ 2769.924526] kernel: soundwire_cadence:cdns_fill_msg_resp: soundwire_intel soundwire_intel.link.3: Msg ignored for Slave 0
[ 2769.924529] kernel: soundwire_bus:sdw_program_device_num: soundwire sdw-master-3: No more devices to enumerate
[ 2769.924564] kernel: soundwire_cadence:cdns_update_slave_status_work: soundwire_intel soundwire_intel.link.3: Slave status change: 0x20000001
[ 2769.924572] kernel: soundwire_bus:sdw_modify_slave_status: rt715-sdca sdw:3:025d:0714:01: signaling enumeration completion for Slave 7
[ 2769.924771] kernel: soundwire_bus:sdw_slave_set_frequency: rt715-sdca sdw:3:025d:0714:01: Configured bus base 1, scale 3, mclk 19200000, curr_freq 4800000
[ 2769.924917] kernel: rt715-sdca sdw:3:025d:0714:01: PARITY error detected before INT mask is enabled
[ 2769.928486] kernel: soundwire_bus:sdw_handle_slave_status: rt715-sdca sdw:3:025d:0714:01: signaling initialization completion for Slave 7
[ 2769.944367] kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: open stream 4 dir 1
[ 2769.944369] kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-tgl 0000:00:1f.3: period min 192 max 16384 bytes
[ 2769.944370] kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-tgl 0000:00:1f.3: period count 2 max 16
[ 2769.944371] kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-tgl 0000:00:1f.3: buffer max 65536 bytes
[ 2769.945164] kernel: snd_sof:sof_pcm_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: hw params stream 4 dir 1

dmesg.txt
logger.txt

[plbossart]

nor clear to me what the issue is. The PARITY error happens from time to time, it's not fatal.

[marc-hb]

Please always share test run ID for reference: 13893?model=TGLU_SKU0A32_SDCA&testcase=check-pause-resume-capture-100

Very similar failure in 13892?model=TGLU_SKU0A32_SDCA&testcase=check-pause-resume-capture-10. I'm not sure the "parity error" is related to the failure, the user space logs at this second link look the same but without any "parity error".

[fredoh9]

I was trying to figure out the failure from yesterday also. PARITY error is NOT the root cause of the failure.
I was tracking TGLU_SKU0A32_SDCA for days, this was not 100% reproducible, it has started from 1-2 days ago. Test run IDs are available in internal issue 233.

[fredoh9]

The failure is in expect script, that's why hard to pin point the error. The expect script trigger pause/resume command by sending spacebar key. I suspect pause/resume fails but I don't see obvious FW log either. Trying to debug more.

[fredoh9]

Easy to reproduce the problem.
TPLG=/lib/firmware/intel/sof-tplg/sof-tgl-rt711-rt1316-rt714.tplg MODEL=TGLU_SKU0A32_SDCA ~/sof-test/test-case/check-pause-resume.sh -c 20 -m capture
// Puase/resume works on hw:0,1, irrespective of iteration
arecord -D hw:0,1 -r 48000 -c 2 -f S16_LE -vv -i /dev/null -q

// capture hw:0,4, first pause works but resume fails
arecord -D hw:0,4 -r 48000 -c 2 -f S16_LE -vv -i /dev/null -q

I cannot reproduce the problem with manually. I tried same order though.

[marc-hb]

I cannot reproduce the problem with manually. I tried same order though.

Timings then? Near impossible to reproduce expect timings without expect or something like it.

[fredoh9]

thanks @marc-hb.
This is a bug in our expect script. Can't handle with MAX

1. Playing
##    +                                            | 11%
2. Pause
=== PAUSE ===
3. Exception case with MAX
##################################################+| MAX

Don't know how to fix this yet. Will move this to sof-test repo.

[marc-hb]

This is a bug in our expect script. Can't handle with MAX+

While the script should handle MAX better, why is MAX suddenly OK? This test never failed like this before so this really looks like a real bug and recent regression to me. It's not even a short duration MAX, it lasts for a while. Did you listen at the capture?

cc: @plbossart

PS: @aiChaoSONG found an axfer replacement for aplay which could avoid expect alsa-project/alsa-utils#155. Would be interesting how it would deal with a situation like this.

[fredoh9]

There are huge pop in begining of hw:0,1. For 3 seconds, some 'MAX' output was detected

$ arecord -D hw:0,1 -r 48000 -c 2 -f S16_LE -d 10 sdw1_capture.wav
sdw1_capture.zip

######################+                            | 42%
######################+                            | 43%
####################  +                            | 43%
##################################################+| 99%
##################################################+| 99%
##################################################+| 99%
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
##################################################+| MAX
##################################                +| MAX
######################                            +| MAX
#########                                         +| MAX
#######                                           +| MAX
#######                                           +| MAX
#########+                                         | 16%
######### +                                        | 18%

$ arecord -D hw:0,4 -r 48000 -c 2 -f S16_LE -d 10 sdw4_capture.wav

100% DC only with hw:0,4. Due to 100% DC, arecord output is always MAX.

sdw4_capture.zip