[SDW][BUG]IO transfer timed out occurred during multi-pipline stress test

[YvonneYang2]

Describe the bug
Occurred IO transfer timed out when run multi-pipline stress test.

To Reproduce

1. Boot up
2. Run with comman "./multiplex_pipeline-test_update.sh pcm0p pcm2p pcm5p pcm1c pcm4c"

script:
multiplex_pipeline-test_update.sh.txt

Reproduced rate
Round1 : Run 300 times, failed at 171th time.
Round2: Run 300 times, failed at 132th time.

Expected result
Run multi-pipline stress test successfully

Actual result
Occurred IO transfer timeed out during multi-pipline stress test

Dmesg

[ 1853.884397] intel-sdw sdw-master-0: intel_startup: SDW0 Pin2: start
[ 1853.884401] intel-sdw sdw-master-0: intel_startup: SDW0 Pin2: done
[ 1853.884403]  Headphone: ASoC: open FE Headphone
[ 1853.884406] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[ 1853.884407] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 1853.884408] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 1853.884408] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 1853.884532]  SDW0-Playback: ASoC: hw_params BE SDW0-Playback
[ 1853.884535] rt711 sdw:0:25d:711:0: rt711_pcm_hw_params rt711-aif1
[ 1855.910857] intel-sdw sdw-master-0: IO transfer timed out
[ 1857.959011] intel-sdw sdw-master-0: IO transfer timed out
[ 1857.959191] rt711 sdw:0:25d:711:0: [rt711_sdw_write] 7203 8283 <= 0031
[ 1860.007068] intel-sdw sdw-master-0: IO transfer timed out

Test recipe:
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: d740a3e
FW: https://github.com/thesofproject/sof/commits/master commit: d740a3e
tplg: Same with FW branch, sof-cml-rt711-rt1308-mono-rt715.tplg
platform: CML Laptop with ALC711+ ALC1308+ ALC715 in SDW mode

Logs:
failed_multipipeline_test_171_dmesg.log
failed_multipipeline_test_171_all_logger.log
multipipeline_test_132_all_logger.log
multipipeline_test_132_dmesg.log

[bardliao]

@YvonneYang2 Could you test it with bardliao@690b151 ?

[YvonneYang2]

Tested it 300 times, issue can still be reproduced with latest integration/soundwire-latest + bardliao@690b151

Run 500 times, failed at 243th time.

Dmesg:

[ 2656.934491] intel-sdw sdw-master-1: intel_suspend_runtime start
[ 2656.934501] intel-sdw sdw-master-0: intel_suspend_runtime start
[ 2656.934638] intel-sdw sdw-master-1: intel_suspend_runtime done
[ 2656.935155] intel-sdw sdw-master-0: Link power down failed: -11
[ 2656.982207] intel-sdw sdw-master-3: intel_suspend_runtime start
[ 2656.982284] intel-sdw sdw-master-3: intel_suspend_runtime done
[ 2658.982463]  HDMI1: ASoC: pop wq checking: Playback status: inactive waiting: yes
[ 2658.982533]  Headphone: ASoC: pop wq checking: Playback status: inactive waiting: yes
[ 2658.982595]  SDW1-speakers: ASoC: pop wq checking: Playback status: inactive waiting: yes
[ 2661.140283]  Headphone: ASoC: found 0 audio playback paths
[ 2661.140285]  Headphone: ASoC: Headphone no valid playback route
[ 2661.140287] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: find BE for widget ALH2.OUT
[ 2661.140288] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: try BE : ALH2.OUT
[ 2661.140289]  Headphone: connected new DPCM playback path Headphone -> SDW0-Playback
[ 2661.140295]  Headphone: ASoC: found 1 new BE paths
[ 2661.140296]  SDW0-Playback: ASoC: open playback BE SDW0-Playback
[ 2661.140302] intel-sdw sdw-master-0: intel_startup: SDW0 Pin2: start
[ 2661.140306] intel-sdw sdw-master-0: intel_startup: SDW0 Pin2: done
[ 2661.140308]  Headphone: ASoC: open FE Headphone
[ 2661.140311] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[ 2661.140312] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 2661.140313] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 2661.140314] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 2661.140438]  SDW0-Playback: ASoC: hw_params BE SDW0-Playback
[ 2661.140440] rt711 sdw:0:25d:711:0: rt711_pcm_hw_params rt711-aif1
[ 2663.142438] intel-sdw sdw-master-0: IO transfer timed out
[ 2665.190452] intel-sdw sdw-master-0: IO transfer timed out
[ 2665.190473] rt711 sdw:0:25d:711:0: [rt711_sdw_write] 7203 8283 <= 0031
[ 2667.238473] intel-sdw sdw-master-0: IO transfer timed out
[ 2669.286264] intel-sdw sdw-master-0: IO transfer timed out
[ 2669.286285] rt711 sdw:0:25d:711:0: [rt711_sdw_write] 7209 8289 <= 0031

failed_multipipeline_test_243_all_logger.log
failed_multipipeline_test_243_dmesg.log

[bardliao]

Look like "Link power down failed: -11" can be seen on all the error dmesg log. Let's fix it first. @YvonneYang2 Could you test it with 0001-soundiwre-Intel-set-link_control-bits-again-when-it-.patch.txt?

patch

diff --git a/drivers/soundwire/intel.c b/drivers/soundwire/intel.c
index 63931cda51ab..91bd6fe550fc 100644
--- a/drivers/soundwire/intel.c
+++ b/drivers/soundwire/intel.c
@@ -407,6 +407,7 @@ static int intel_link_power_down(struct sdw_intel *sdw)
 	unsigned int link_id = sdw->instance;
 	void __iomem *shim = sdw->link_res->shim;
 	u16 ioctl;
+	int retry = 3;
 
 	/* Glue logic */
 	ioctl = intel_readw(shim, SDW_SHIM_IOCTL(link_id));
@@ -424,6 +425,12 @@ static int intel_link_power_down(struct sdw_intel *sdw)
 	link_control &=  spa_mask;
 
 	ret = intel_clear_bit(shim, SDW_SHIM_LCTL, link_control, cpa_mask);
+	while (ret == -EAGAIN && retry >= 0) {
+		msleep(1);
+		ret = intel_clear_bit(shim, SDW_SHIM_LCTL,
+				      link_control, cpa_mask);
+		retry--;
+	}
 	if (ret < 0)
 		return ret;
 

[YvonneYang2]

Tested it 500 times with latest integration/soundwire-latest (commit:d6078f9) +
0001-soundiwre-Intel-set-link_control-bits-again-when-it-.patch.txt
, IO transfer timed out issue and "Link power down failed: -11" both cannot be reproduced.

[bardliao]

@YvonneYang2 To double confirm. Could you check it with below patch instead?

diff --git a/drivers/soundwire/intel.c b/drivers/soundwire/intel.c
index 63931cda51ab..686c409d66c3 100644
--- a/drivers/soundwire/intel.c
+++ b/drivers/soundwire/intel.c
@@ -150,7 +150,7 @@ static inline void intel_writew(void __iomem *base, int offset, u16 value)
 
 static int intel_clear_bit(void __iomem *base, int offset, u32 value, u32 mask)
 {
-	int timeout = 10;
+	int timeout = 100;
 	u32 reg_read;
 
 	writel(value, base + offset);

[YvonneYang2]

@bardliao
Issue can still be reproduced with latest integration/soundwire-latest (commit:d6078f9) + patch as above.

Run 300 times, failed at 175th.

Dmesg:

[ 1878.026234] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[ 1878.026235] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 1878.026236] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 1878.026237] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 1878.026357]  SDW0-Playback: ASoC: hw_params BE SDW0-Playback
[ 1878.026360] rt711 sdw:0:25d:711:0: rt711_pcm_hw_params rt711-aif1
[ 1880.038362] intel-sdw sdw-master-0: IO transfer timed out
[ 1882.086346] intel-sdw sdw-master-0: IO transfer timed out
[ 1882.086368] rt711 sdw:0:25d:711:0: [rt711_sdw_write] 7203 8283 <= 0031

failed_multipipeline_test_175_all_logger.log
failed_multipipeline_test_175_dmesg.log

[bardliao]

@YvonneYang2 Could you test it with #1573?

[plbossart]

@bardliao what's interesting is that the only time when the error happens when the sequences for pm_runtime are interleaved:

[ 1873.951019] intel-sdw sdw-master-1: intel_suspend_runtime start
[ 1873.951031] intel-sdw sdw-master-0: intel_suspend_runtime start
[ 1873.951108] intel-sdw sdw-master-1: intel_suspend_runtime done
[ 1873.956341] intel-sdw sdw-master-0: Link power down failed: -11
[ 1873.963366] intel-sdw sdw-master-3: intel_suspend_runtime start
[ 1873.963433] intel-sdw sdw-master-3: intel_suspend_runtime done

so it's likely we need a mutual exclusion between links...

And looking at the code, it's pretty clear:

static int intel_link_power_up(struct sdw_intel *sdw)
{
	unsigned int link_id = sdw->instance;
	void __iomem *shim = sdw->link_res->shim;
	int spa_mask, cpa_mask;
	int link_control, ret;

	/* Link power up sequence */
	link_control = intel_readl(shim, SDW_SHIM_LCTL);
	spa_mask = (SDW_SHIM_LCTL_SPA << link_id);
	cpa_mask = (SDW_SHIM_LCTL_CPA << link_id);
	link_control |=  spa_mask;

	ret = intel_set_bit(shim, SDW_SHIM_LCTL, link_control, cpa_mask);
	if (ret < 0)
		return ret;

	sdw->cdns.link_up = true;
	return 0;
}

so what happens is that we have a common register which is accessed for different fields independently. that can't be good...