[TGL] [I2S/SDW][max98373 DSM]: sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76

[naveen-manohar]

Observe following Log randomly, during stress cycling.. Speaker Audio-Functionality post this scenario is yet to be verified as its a cold-reboot stress test.
Log: system_logs.txt

[ 1432.644301] max98373 sdw:1:19f:8373:0:7: ASoC: error at soc_component_read_no_lock on sdw:1:19f:8373:0:7: -16
[ 1432.644318] max98373 sdw:1:19f:8373:0:7: ASoC: error at soc_component_read_no_lock on sdw:1:19f:8373:0:7: -16
[ 1432.644331] max98373 sdw:1:19f:8373:0:7: ASoC: error at soc_component_read_no_lock on sdw:1:19f:8373:0:7: -16
[ 1432.644563] max98373 sdw:1:19f:8373:0:3: ASoC: error at soc_component_read_no_lock on sdw:1:19f:8373:0:3: -16
[ 1432.644576] max98373 sdw:1:19f:8373:0:3: ASoC: error at soc_component_read_no_lock on sdw:1:19f:8373:0:3: -16
[ 1432.644586] max98373 sdw:1:19f:8373:0:3: ASoC: error at soc_component_read_no_lock on sdw:1:19f:8373:0:3: -16
[ 1432.748544] max98373 sdw:1:19f:8373:0:7: ASoC: error at soc_component_read_no_lock on sdw:1:19f:8373:0:7: -16

Recipe Based on SoF_V0.8/0.9 Release
Hardware: Volteer Proto Board

[naveen-manohar]

Customer reported an issue which broke down into no audio with the same error signature.. Can we bump the priority in-par with customer's priority P-1

[plbossart]

@naveen-manohar unless you help us by using the topic/sof-dev kernel and providing more detailed logs, changing the priority is not going to help. Keep in mind I am the only SoundWire support for the next week or so (Chinese Fall festival)....

Specifically I don't see where "soc_component_read_no_lock" is called and what sequence leads to this problem. Please add dynamic debug for the soundwire parts as well, e.g. by adding this in /etc/modprobe.d/sof-ddbug.conf
ddebug.txt

[naveen-manohar]

Sure @plbossart , ww40.5 is India Site Holiday, by ww41.1 EoD, shall post the specified data.

[naveen-manohar]

With chrome latest kernel based on SoF_v010 was to able to reproduce issue during warm_boot stress test with debug logs..
Seems like the DSP fails to enter D3 during certain iteration and further access to soundwire device fails
Logs:
dmesg-issue_ipc_timeout.log - FAILS
dmesg-working.log - PASS

sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000
sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
sof-audio-pci 0000:00:1f.3: unknown ROM status value ffffffff
sof-audio-pci 0000:00:1f.3: invalid header size 0xffffffff. FW oops is bogus
sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
sof-audio-pci 0000:00:1f.3: ctx_save ipc error -110, proceeding with suspend
sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x9010f0f successful
sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x9000f0f successful
sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000010 at  00000044
sof-audio-pci 0000:00:1f.3: Turning i915 HDAC power 0
sof-audio-pci 0000:00:1f.3: Current DSP power state: D3
max98373 sdw:1:19f:8373:0:7: ASoC: error at soc_component_read_no_lock on sdw:1:19f:8373:0:7: -16

Please let me know if any more information required.

[kv2019i]

Discussed with @naveen-manohar and we'll try to get:

• DSP FW logs
• more debug from the codec driver

One thing that pops up in the error case log is that we are getting traces from the codec driver after
2020-10-04T15:35:01,501726+05:30 intel-sdw intel-sdw.1: intel_link_power_down: powering down all links
...
2020-10-04T15:35:27,168791+05:30 max98373 sdw:1:19f:8373:0:7: ASoC: error at soc_component_read_no_lock on sdw:1:19f:8373:0:7: -16

The ordering is not right, something is wrong here.

[kv2019i]

Quick update. The soc_component_read_no_lock errors are probably amixer reads after all, and regmap_read returns -EBUSY if regmap is in cache_only mode, which would be the case when powered down, so these look harmless in the end. So the main question is now to why the IPC fails.

[naveen-manohar]

Thanks @kv2019i for the quick support.. Sure I'm working on the DSP FW logs during Failure Scenario
Things is, Issue is reproduced in stress test, so I need to make find some way to stop the test during failure.
Let me reproduce and update with FW trace. Thanks

[naveen-manohar]

attached firmware trace..
trace.log
dmesg.log

[plbossart]

Quick update. The soc_component_read_no_lock errors are probably amixer reads after all, and regmap_read returns -EBUSY if regmap is in cache_only mode, which would be the case when powered down, so these look harmless in the end. So the main question is now to why the IPC fails.

can you share a pointer to this behavior @kv2019i? that's not intended, the point about cache_only mode was to avoid sending commands on the bus but there's no reason to return an error.

[plbossart]

@naveen-manohar I don't see a smoking gun but I don't understand the sequence either. it looks like in the tests the failure happens on the first suspend, which is not really a stress test...I also don't see if this is due to pm_runtime or a system suspend. more info would be good here.

[naveen-manohar]

Hi @plbossart ,
Apologies for not sharing the exact test being tried..
The stress test is about cold-boot test ran using a set of scripts.. sequence is like below:
Boot -> Check all devices are loaded -> Dump corresponding logs -> cold-reboot -> redo test till iteration specified.
Here Cold reboot = ectool reboot_ec cold at-shutdown, shutdown -h now

Each iteration's boot log/dump will be stored in a separate folder..
Finally i did a grep to check any iteration failed..

[ranj063]

@plbossart looking at intel_suspend_runtime() it looks we disable interrupts before powering down the links. Is that intended?

[kv2019i]

@plbossart wrote:

@kv2019i wrote:

-EBUSY if regmap is in cache_only mode, which would be the case when powered down, so these look harmless in the end.

can you share a pointer to this behavior @kv2019i? that's not intended, the point about cache_only mode was to avoid sending commands on the bus but there's no reason to return an error.

Basicly I was searching the codebase where codec soc_component_read I/O would return -EBUSY and pretty much the only place
is regmap.c:_regmap_read(). There's code that checks map->cache_only and returns -EBUSY in this case.

[plbossart]

@plbossart looking at intel_suspend_runtime() it looks we disable interrupts before powering down the links. Is that intended?

yes, we let the workqueue complete, then disable Cadence IP interrupts then power down links.

@naveen-manohar can you double-check if you have the patch "soundwire: cadence: fix race condition between suspend and Slave device alerts", that's the only thing I can think of on the suspend path that we fixed recently (August).