[BUG][S3] Regression test: Trying resume playback failed after suspend/resume on APL-pcm512x and APL-nocodec.

[Jiangxinx]

Summary
Fail to resume playback after suspend/resume 1 times on APL-pcm512x and APL-nocodec. sof-logger is empty. sof-logger -t log is attached below.

To Reproduce
1.aplay -Dhw:0,0 -fS16_LE -c2 -r48000 /dev/zero& sudo ~/test/stress-s3.sh 50 1 1

Expected behavior
Success to resume playback.

Dmesg

[ 2035.606826] sof-audio-pci 0000:00:0e.0: error: no reply expected, received 0x1004200
[ 2035.611920] ata1: SATA link down (SStatus 4 SControl 300)
[ 2035.611977] ata2: SATA link down (SStatus 4 SControl 300)
[ 2035.757111] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x81000010 timedout
[ 2035.757120] sof-audio-pci 0000:00:0e.0: unknown ROM status value 81000010
[ 2035.757126] sof-audio-pci 0000:00:0e.0: error: status = 0xecc00302 panic = 0x00000000
[ 2035.757131] sof-audio-pci 0000:00:0e.0: unknown ROM status value 81000010
[ 2035.757139] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1010303 successful
[ 2035.757145] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1000303 successful
[ 2035.757152] sof-audio-pci 0000:00:0e.0: DSP core(s) enabled? 0 : core_mask 3
[ 2035.757157] sof-audio-pci 0000:00:0e.0: error: Error code=0xffffffff: FW status=0xffffffff
[ 2035.757161] sof-audio-pci 0000:00:0e.0: error: iteration 1 of Core En/ROM load failed: -110
[ 2035.757168] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x3030303 successful
[ 2035.757174] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x3030302 successful
[ 2035.757179] sof-audio-pci 0000:00:0e.0: unstall/run core: core_mask = 1
[ 2035.757184] sof-audio-pci 0000:00:0e.0: DSP core(s) enabled? 1 : core_mask 1
[ 2035.757744] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x40000000 successful
[ 2035.757751] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1010202 successful
[ 2035.757915] sof-audio-pci 0000:00:0e.0: error: no reply expected, received 0x1004200
[ 2035.908277] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x81000010 timedout
[ 2035.908309] sof-audio-pci 0000:00:0e.0: unknown ROM status value 81000010
[ 2035.908315] sof-audio-pci 0000:00:0e.0: error: status = 0xecc00302 panic = 0x00000000
[ 2035.908321] sof-audio-pci 0000:00:0e.0: unknown ROM status value 81000010
[ 2035.908329] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1010303 successful
[ 2035.908335] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1000303 successful
[ 2035.908341] sof-audio-pci 0000:00:0e.0: DSP core(s) enabled? 0 : core_mask 3
[ 2035.908347] sof-audio-pci 0000:00:0e.0: error: Error code=0xffffffff: FW status=0xffffffff
[ 2035.908351] sof-audio-pci 0000:00:0e.0: error: iteration 2 of Core En/ROM load failed: -110
[ 2035.908355] sof-audio-pci 0000:00:0e.0: error: dsp init failed after 3 attempts with err: -110
[ 2035.908385] sof-audio-pci 0000:00:0e.0: unknown ROM status value ffffffff
[ 2035.908390] sof-audio-pci 0000:00:0e.0: error: status = 0xffffffff panic = 0xffffffff
[ 2035.908395] sof-audio-pci 0000:00:0e.0: unknown ROM status value ffffffff
[ 2035.908401] sof-audio-pci 0000:00:0e.0: error: failed to reset DSP
[ 2035.908405] sof-audio-pci 0000:00:0e.0: error: failed to boot DSP firmware after resume -110
[ 2035.908417] dpm_run_callback(): pci_pm_resume+0x0/0xa0 returns -110
[ 2035.908427] PM: Device 0000:00:0e.0 failed to resume: error -110
[ 2035.908584] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 5:0
[ 2035.908625] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 6:0
[ 2035.908638] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 7:0
[ 2035.909295] OOM killer enabled.
[ 2035.909298] Restarting tasks ... done.
[ 2035.914218] video LNXVIDEO:00: Restoring backlight state
[ 2035.914224] PM: suspend exit
[ 2035.922088] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 6
[ 2035.922093] sof-audio-pci 0000:00:0e.0: PCM: resume stream 0 dir 0 DMA position 0
[ 2035.922096] sof-audio-pci 0000:00:0e.0: pcm: hw params stream 0 dir 0
[ 2035.922114] sof-audio-pci 0000:00:0e.0: period_bytes:0xfc0
[ 2035.922116] sof-audio-pci 0000:00:0e.0: periods:16
[ 2035.922124] sof-audio-pci 0000:00:0e.0: stream_tag 1
[ 2035.922131] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 2036.228550] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60010000 size 108
[ 2036.228569] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 2036.228589] sof-audio-pci 0000:00:0e.0: error: status = 0x001d003c panic = 0x00000000
[ 2036.228596] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 2036.228600] sof-audio-pci 0000:00:0e.0: error: hw params ipc failed for stream 1
[ 2036.228604] sof-audio-pci 0000:00:0e.0: error: set pcm hw_params after resume
[ 2036.228609]  Port5: ASoC: trigger FE failed -110
[ 2036.241691] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 1
[ 2036.241698] sof-audio-pci 0000:00:0e.0: PCM: resume stream 0 dir 0 DMA position 0
[ 2036.241701] sof-audio-pci 0000:00:0e.0: pcm: hw params stream 0 dir 0
[ 2036.241913] sof-audio-pci 0000:00:0e.0: error: timeout waiting for stream reset
[ 2036.241921] sof-audio-pci 0000:00:0e.0: error: hdac prepare failed: ffffff92
[ 2036.241924] sof-audio-pci 0000:00:0e.0: error: platform hw params failed
[ 2036.241928] sof-audio-pci 0000:00:0e.0: error: set pcm hw_params after resume
[ 2036.241931]  Port5: ASoC: trigger FE failed -110
[ 2036.241936] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 0
[ 2036.844677] sof-audio-pci 0000:00:0e.0: pcm: free stream 0 dir 0
[ 2036.844693] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 2037.148545] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60030000 size 12
[ 2037.148566] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 2037.148573] sof-audio-pci 0000:00:0e.0: error: status = 0x001d003c panic = 0x00000000
[ 2037.148582] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 2037.151017] sof-audio-pci 0000:00:0e.0: pcm: close stream 0 dir 0
[ 2037.516193] r8169 0000:02:00.0 enp2s0: Link is Up - 100Mbps/Full - flow control rx/tx
[ 2039.316156] sof-audio-pci 0000:00:0e.0: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 2039.620543] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x40010000 size 76
[ 2039.620563] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 2039.620571] sof-audio-pci 0000:00:0e.0: error: status = 0x001d003c panic = 0x00000000
[ 2039.620579] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 2039.620586] sof-audio-pci 0000:00:0e.0: error: ctx_save ipc error during suspend -110
[ 2039.620606] sof-audio-pci 0000:00:0e.0: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -110)

Environment
sof master: acf2bd5
kernel sof-dev: f93c4ee
tplg: sof-apl-nocodec.tplg & sof-apl-pcm512x.tplg

Log file
dmesg.log
logger.log

[Jiangxinx]

This case is OK on version f304b5c . And Only #740 was merged between f304b5c and f93c4ee .
Howere, there are several commits in #740, need do bisect to target which commit ID.

[plbossart]

@lyakh are you able to reproduce this issue?

[lyakh]

@plbossart yes, I can reproduce it. And it's a very nice one! I'd say - an old bug biting back. Now, I have a fix, but it makes an ugly location in the code even uglier. Here it is:

diff --git a/sound/soc/sof/intel/hda-ipc.c b/sound/soc/sof/intel/hda-ipc.c
index b7e6781..873c4a9 100644
--- a/sound/soc/sof/intel/hda-ipc.c
+++ b/sound/soc/sof/intel/hda-ipc.c
@@ -160,7 +160,7 @@ irqreturn_t hda_dsp_ipc_irq_thread(int irq, void *context)
 					HDA_DSP_REG_HIPCCTL_DONE, 0);
 
 		/* handle immediate reply from DSP core - ignore ROM messages */
-		if (msg != 0x1004000) {
+		if (msg != 0x1004000 && msg != 0x1004200) {
 			hda_dsp_ipc_get_reply(sdev);
 			reply = snd_sof_ipc_reply(sdev, msg);
 		}

An explanation: you see a message:

sof-audio-pci 0000:00:0e.0: error: no reply expected, received 0x1004200

both before and after my patches. Before my patches it was harmless, because .get_reply() wasn't called because the unexpected message was caught in snd_sof_ipc_reply() per above message. After my patches the same code, that is performing .get_reply() now is called before that check... The above patch fixes that, but it's rather ugly. Do we want it or do we want to come up with some prettier solution?

[xiulipan]

sof-audio-pci 0000:00:0e.0: error: no reply expected, received 0x1004200

Hah, a ghost come back @keyonjie

@lyakh
Actually this is some message from the ROM response the purge message.
0x1004000 means you have select stream_tag 1 for the FW loading, and
0x1004200 means you have select stream_tag 2 for the FW loading.

In fact we may have more than this, and some 0x1004400 0x1004600 also
notice ((stream_tag - 1) << 9))

linux/sound/soc/sof/intel/hda-loader.c

Lines 95 to 98 in f3adfd6

	/* step 2: purge FW request */
	snd_sof_dsp_write(sdev, HDA_DSP_BAR, chip->ipc_req,
	chip->ipc_req_mask | (HDA_DSP_IPC_PURGE_FW |
	((stream_tag - 1) << 9)));

And I do not think the following if is used for fix. @keyonjie it only hide the error message from demsg right?

-		if (msg != 0x1004000) {
+		if (msg != 0x1004000 && msg != 0x1004200) {

Maybe we need to check what and why the stream tag 1 is be used. Maybe some related issue with #779

[lyakh]

@xiulipan what do you mean it would only hide the error? It fixes it - with that diff suspend-resume works again.

[wenqingfu]

@xiulipan what do you mean it would only hide the error? It fixes it - with that diff suspend-resume works again.

I think what @xiulipan means is if it is always right to simply ignore the 0x1004n00 msg, and if so, we need to ignore more than 0x1004200. Maybe @mmaka1 can help confirm?

[lyakh]

@wenqingfu is 0x1004n00 the correct mask? Judging by ((stream_tag - 1) << 9) it seems it's either (0x1004000 | (3 << 9)) or (0x1004000 | (7 << 9)) or maybe even (0x1004000 | (0x1f << 9)) ?

[plbossart]

@lyakh it feels like there is some sort of resource leak that leads us to use a different stream_tag. I don't get at all why stream_tag 2 would be used, it's an indication that stream_tag 1 is marked as used. We should not mask the error here but figure out why we get a different reply in the first place.

[ranj063]

Hah, a ghost come back @keyonjie

@xiulipan it never went away. We just fixed the other things in GLK and left this alone.

[ranj063]

@lyakh we're having resume issues on CML as well and I'm not sure it is the same fix. Whats interesting is during the stress test the same error reply appears after every single resume. But it only causes a failure occasionally and not every time.