[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

[marc-hb]

UPDATE: the git versions below are IRRELEVANT. The issue has been narrowed down to ALSA configuration differences.

---

Last known good daily test run ID 13859 Start Time: 2022-07-10 21:30:24 UTC

Kernel Branch: topic/sof-dev
Kernel Commit:  4fb82baff553
SOF Branch: main
SOF Commit: 912cf91ca69c

First bad daily test run ID 13983 Start Time: 2022-07-12 01:34:48 UTC

Kernel Branch: topic/sof-dev
Kernel Commit: bccf5da2acbf
SOF Branch: main
SOF Commit: 9d9c28848def

Only 4 SOF commits difference:

9d9c28848def [email protected] // topology1: generate new sof-hda-generic version for 2ch PDM1
73fd9248e0ba [email protected] // topology1: intel-generic-dmic: add macro to enable PDM1 for 2ch cases
ef39318ee4b9 [email protected] // dai-zephyr: add a DAI COPY trigger
33f27d3477be [email protected] // xtensa-build-zephyr.py: speed up thanks to an _actually_ shallow clone
912cf91ca69c [email protected] // google_rtc: Do not rely on component type

About 60 Linux commits difference:

git log --oneline --no-merges --graph bccf5da2acbf ^4fb82baff553 | wc -l
58

[marc-hb]

This also started happening with the SOF v2.2 release branch so this is very likely a recent kernel regression @plbossart

Same failure in internal daily v2.2 run 13929?model=TGLU_SKU0A32_SDCA&testcase=check-pause-resume-capture-10 and other v2.2

[fredoh9]

I tried with daily build 2022-07-10 (below has HASHes), I have same issues with MAX volume.

    "version" : {
        "kernelBranch" : "topic/sof-dev",
        "kernelCommit" : "4fb82baff553-4",
        "sofBranch" : "main",
        "sofCommit" : "912cf91ca69c-2",
        "firmwareType" : "xcc"
    },

Hard to tell the connection, but I replaced the NVMe SSD 7/8 (Fri), It may be something to do with the SSD upgrade and leave the laptop without the back cover?

[fredoh9]

jf-tglu-sku0a32-sdca-01 works fine, both jf-tglu-sku0a32-sdca-02/jf-tglu-sku0a32-sdca-03 have MAX volume issue.

I see some differences. First one has Ubuntu 20.04 and alsa version 1.2.2. The latter has Ubuntu 22.04 and alsa version is 1.2.6. I see some of alsa contents are different. I can't store/restore alsa settings from Ubuntu 20.04 to Ubuntu 22.04. Trying to match close possible.

[fredoh9]

For failed device, alsa setting was
sku0a32-2.alsactl.txt

Updated with this after referencing from jf-tglu-sku0a32-sdca-01, then works fine for both of the device.
sku0a32-2.alsactl_new_works.txt

[keqiaozhang]

It seems that this issue is related to rt714 FU02 Capture. If we turn the rt714 FU02 Capture Switch on and set the volume of rt714 FU02 Capture Volume above 52, we will hit such issue.
For example:

amixer -c sofsoundwire cset name='rt714 FU02 Capture Switch' on
amixer -c sofsoundwire cset name='rt714 FU02 Capture Volume' 55

But the question is that why does pausing PCM0,4 make the volume reach to maximum under a certain probability?

[fredoh9]

But the question is that why does pausing PCM0,4 make the volume reach to maximum under a certain probability?

This question is already answered. When playback starts volume is 100% due to high gain. expect script don't know what to do with this output.
"##################################################+| MAX"
So no pause command is issued, then expect script is timeout, then the test case failed.

With thesofproject/sof-test#931, error message is more readable.

[plbossart]

I will repeat my question: Why on earth do we care about volume settings when doing the pause_push/pause_release transitions? This has nothing to do with mixer changes, which can happen both when the stream is running or paused.

ALSA provides different 'strreaming' and 'control' interfaces. this test is only about the former.

[fredoh9]

I compared alsa contents and double checked capture output from jf-tglu-sku0a32-sdca-01 (working, Ubuntu20.04)

This is wave capture hw:0.4. Note, left and right channel gain is different but no saturation.

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

		name 'rt714 FU06 Capture Volume'
		value.0 47
		value.1 47
		value.2 0
		value.3 0

For hw:0,1, the Capture Switch was off(false), So only silence was recorded.

		name 'rt711 FU0F Capture Switch'
		value.0 false

[plbossart]

@fredoh9 so now that we've established that it's a arecord problem (pause is irrelevant), can you dump the rt714 control settings in the Ubuntu 20.04 and Ubuntu 22.04 cases?

One possible change is that UCM provides default boot values, that may be the difference. See https://github.com/alsa-project/alsa-ucm-conf/blob/master/ucm2/codecs/rt715-sdca/init.conf

This sets the FU02 values while you look at FU06. Could be a red-herring or not...

[fredoh9]

I tested with 47 in relatively silent office in normal distance for laptop user. The captured waveform is nice and good.
Definitely 124 is MAX it cause just 100% saturation. Even with 100, it is way higher than it is required

[keqiaozhang]

CI detected this issue on TGLU_SKU0A3E_SDW. I think this is because @fredoh9 replaced the NVME to solve the https://github.com/intel-innersource/drivers.audio.ci.sof-framework/issues/233 and installed Ubuntu22.04 LTS on jf-tglu-sku0a3e-sdw-01, therefore, some default amixer values may be changed after this.
I changed the rt711 ADC 09 Capture Volume to 14 and issue can not be reproduced anymore.

amixer -c sofsoundwire cget name='rt711 ADC 08 Capture Volume'
numid=5,iface=MIXER,name='rt711 ADC 08 Capture Volume'
  ; type=INTEGER,access=rw---R--,values=2,min=0,max=63,step=0
  : values=14,14
  | dBscale-min=-17.25dB,step=0.75dB,mute=0

I checked the UCM2, the volume is set to 63 in init.conf:
https://github.com/alsa-project/alsa-ucm-conf/blob/master/ucm2/codecs/rt711/init.conf

# RT711 specific volume control settings

BootSequence [
	cset "name='rt711 DAC Surr Playback Volume' 87"
	cset "name='rt711 ADC 08 Capture Volume' 63"
	cset "name='rt711 ADC 23 Mux' 'MIC2'"
	cset "name='rt711 ADC 08 Capture Switch' 1"
	cset "name='rt711 AMIC Volume' 1"
]

[plbossart]

@keqiaozhang You should not manually change anything. Run 'alsactrl init', reboot and see if the problem still exists with default settings. If we still have an issue, report it with a different issue and we change the settings. We should not fix things quickly without a trace of what the issue was.

[plbossart]

In addition to my previous remark, the TGLU_SKU0A3E_SDW device has nothing to do with TGLU_SKU0A32_SDCA @keqiaozhang. Let's track issues separately please.

[keqiaozhang]

Let's track issues separately please.

Let's track the rt711 issue in #3804

[plbossart]

@keqiaozhang can we close this issue for RT715 now that the proper gain was set?

[fredoh9]

All TGLU_SKU0A32_SDCA have proper gain now. Haven't seen same issue for a long time. Closing the issue.

[marc-hb]

All TGLU_SKU0A32_SDCA have proper gain now.

This has not been my experience at all: using arecord on the jack input still shows the same "huge pop at the beginning" pictured previously:

arecord -D hw:0,1 -r 48000 -c 2 -f S16_LE -vv

• [BUG] arecord TGLU_SKU0A32_SDCA ########+| MAX #3766 (comment)

[plbossart]

@marc-hb is this with IPC3/stable2.2 or IPC4/main? We have a known topology issue where the IIR is not included in some paths, the implementation is inconsistent between topology1 and topology2.

[marc-hb]

Only with IPC3/stable2.2. I just switched to IPC4 and tried and while there is a small, deterministic and initial pop (see below) it does not go anywhere near MAX.

I also spotted a lot of MAX volume on other, IPC4 devices too but they don't look like this initial "pop".

[plbossart]

It's because for IPC3 the headset capture does not have any filters, see the topology

For IPC4 we do have an EQIIR on that path so we can't compare the two solutions.

I would rate this as won't fix, the pop is likely due to some codec problem anyways.

[marc-hb]

I would rate this as won't fix, the pop is likely due to some codec problem anyways.

Isn't TGLU_SKU0A32_SDCA a real product? I mean, not a development platform.

[plbossart]

yeah, but it's TGL and no one complained in the last 3 years.... We can't fix everything.

[marc-hb]

ok, will close as "wontfix" as soon as thesofproject/sof-test#1222 is merged.

Just for the record, some commands useful for interactively testing this:

source sof-test/alsa_settings/TGLU_SKU0A32_SDCA.sh


amixer cset name='PGA2.0 2 Master Capture Switch' 1 # only one is on by default?!
amixer cset name='PGA2.0 2 Master Capture Volume' 80
amixer cset name='rt711 FU0F Capture Volume' 63
amixer cset name='rt711 FU44 Gain Volume' 3 

# For no MAX:
amixer cset name='rt711 FU44 Gain Volume' 1


# Show values
amixer cget name='PGA2.0 2 Master Capture Volume'
amixer cget name='rt711 FU0F Capture Volume' 
amixer cget name='rt711 FU44 Gain Volume' 
amixer cget name='PGA2.0 2 Master Capture Switch'

# make sure the microphone is MAXed out:
arecord   -D hw:0,1 -r 48000 -c 1 -f S16_LE -vv -i /dev/null -q