IO transfer error timeout and system suspend-resume test fails

[Vamshigopal]

Describe the bug

We can see sdw IO transfer timed out when we do suspend test. followed by an alert is raised and prepare clock error.

To Reproduce
run suspend_stress_test -c 10

Reproduce rate
sporadic.
more than 2/100 cycles

Expected result
No issue on the suspend test.

Actual result
suspend test fails.

Platform: ADL-N RVP board with onboard codec ALC711 in soundwire mode.

kernel:
v5.15 chrome kernel

[ 1842.762840] soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 1 addr 45 len 1
[ 1842.779471] Resume caused by IRQ 9, acpi
[ 1842.795331] init: tpm2-simulator main process (3858) killed by SYS signal
[ 1842.803354] PM: suspend exit
[ 1842.818521] init: tpm2-simulator main process ended, respawning
[ 1843.363613] x86/PAT: flashrom:4265 conflicting memory types fe000000-100000000 uncached-minus<->uncached
[ 1843.374211] soundwire sdw-master-0: trf on Slave 1 failed:-110 write addr 45 count 0
[ 1843.384050] x86/PAT: memtype_reserve failed [mem 0xfe000000-0xffffffff], track uncached-minus, req uncached-minus
[ 1843.393768] rt711 sdw:0:025d:0711:00: SDW_SCP_SYSTEMCTRL write failed:-110
[ 1843.395632] rt711 sdw:0:025d:0711:00: Failed to resume device: -22
[ 1843.395643] rt711 sdw:0:025d:0711:00: Slave 1 alert handling failed: -22
[ 1843.467099] tpm tpm1: A TPM error (256) occurred attempting the self test
[ 1843.468777] rt711 sdw:0:025d:0711:00: clock stop prepare failed:-110
[ 1843.479405] tpm tpm1: starting up the TPM manually
[ 1843.489348] soundwire_intel soundwire_intel.link.0: prepare clock stop failed -110
[ 1843.548401] x86/PAT: flashrom:4265 conflicting memory types fe000000-100000000 uncached-minus<->uncached
[ 1843.552310] soundwire_intel soundwire_intel.link.0: cannot enable clock stop on suspend

dmesg_log.txt

[Vamshigopal]

cc: @bardliao @RanderWang @plbossart @kv2019i @ranj063 @sathya-nujella

[plbossart]

@Vamshigopal can you enable dynamic debug for SoundWire (and reduce the rest of the noise that's unrelated?)

options soundwire_bus dyndbg=+p
options soundwire_generic_allocation dyndbg=+p
options soundwire_cadence dyndbg=+p
options soundwire_intel_init dyndbg=+p
options soundwire_intel dyndbg=+p
options snd_soc_rt711 dyndbg=+p

Also double-check that there are no known differences between the code in drivers/soundwire in your kernel and our latest to rule out any backport issues.

Thanks!

[Vamshigopal]

Thanks @plbossart for suggestions.

Here are the logs with dynamic debug enabled.
dmesg_dyndb1.log

Checking the differences between code, so far nothing popped up. will update if any fixes are missed.

All the major fixes are taken care in backport. Since this issue is close to #2026. Below fixes are available from backport series.
soundwire: intel: conditionally exit clock stop mode on system suspend
soundwire: intel: don't return error when clock stop failed
soundwire: bus: update Slave status in sdw_clear_slave_status

Thanks

[plbossart]

We seem to have a race condition here, after the clock stop preparation is done, the codec driver initiates a read. we'd need a trace to see when the clock is actually stopped, it looks like the read happens after the bus is stopped, which is clearly incorrect.

[ 4112.100014] soundwire sdw-master-0: clock stop prep/de-prep done slave:15
[ 4112.100753] rt711 sdw:0:025d:0711:00: [rt711_sdw_read] 7520 85a0 9c20 aca0 => 00000580
[ 4112.618645] soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 1 addr 7520 len 1
[ 4112.629375] soundwire sdw-master-0: trf on Slave 1 failed:-110 write addr 7520 count 0
[ 4112.638273] Failed to set private value: 75206f <= 0583 ret=-110
[ 4113.146626] soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 1 addr 3501 len 1
[ 4113.157360] soundwire sdw-master-0: trf on Slave 1 failed:-110 write addr 3501 count 0
[ 4113.166256] rt711 sdw:0:025d:0711:00: rt711_calibration calibration complete, ret=0

I think it's possible that the headset calibration deferred work is still running.

[Vamshigopal]

ack, working to collect the traces, will share by tomorrow.

[Vamshigopal]

Facing some board issues, hence the delay in collecting traces.

[Vamshigopal]

I can see after bus clock stop there is a BUS CLASH and codec driver initiates a write.

soix_failing.txt
soix_working.txt

logs from: failing case-

[ 555.695971] soundwire_intel soundwire_intel.link.0: vamshi bus clock stopped 0
[ 555.696004] soundwire_intel soundwire_intel.link.0: Slave status change: 0x21
[ 555.704184] soundwire_intel soundwire_intel.link.0: vamshi clock stopped 0
[ 555.712062] rt711 sdw:0:025d:0711:00: sdw_modify_slave_status: signaling enumeration completion for Slave 1
[ 555.719767] soundwire_intel soundwire_intel.link.0: vamshi can enable clock stop on suspend:0 intel_suspend_runtime
[ 556.232647] soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 2 device 1 addr 40 len 1
[ 556.243174] soundwire sdw-master-0: trf on Slave 1 failed:-110 read addr 40 count 0
[ 556.251760] rt711 sdw:0:025d:0711:00: SDW_SCP_INT1 (BUS_CLASH) read failed:-110
[ 556.259948] rt711 sdw:0:025d:0711:00: Slave 1 initialization failed: -110
[ 556.267544] vamshi inside: rt711_sdw_write

[naveen-manohar]

Is this related to #2582, can you check commits exists in your kernel ?

[Vamshigopal]

yes, we have commits from #2582 in my kernel.