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

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

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.

@lyakh

@lyakh are you able to reproduce this issue?

@plbossart

@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?

@keyonjie

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

@xiulipan

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

@xiulipan

@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?

@wenqingfu

@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)) ?

@lyakh

@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.

@keyonjie

Hah, a ghost come back @keyonjie

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

@lyakh

@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.

@ranj063

@ranj063 has the resume issue on CML also been just introduced with this PR? Is there a separate issue for it or can you post a dmesg here?

@lyakh

@lyakh no the resume issue on CML has been there from before. Unfortunately the problem was found only a couple a days ago. Here're the logs but this isnt with your PR (just with the v5 SOF patch posted upstream).
dmesg_detailed_logs.txt

@plbossart

@plbossart do you have an idea how to debug that? So we want to find out the reason and not just skip all ROM messages there? As for a resource leak - can be of course, at least with follow up suspends the stream tag remains the same, it doesn't increment to 0x400 or 0x600.

@wenqingfu

@wenqingfu

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?

As you noticed, there is just stream_id changed, bits [9-13] are allocated for the stream_id in this message, and this exact part should be masked out since the nibble with 4 could be theoretically changed to another value if stream with id > 7 is used.

@lyakh

@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.

@plbossart @lyakh i have a bit more information about this. This error (no reply expected received 0x1004200) happens only when I suspend when a playback stream is open. Basically, when playback is started it claims stream tag 1 and with 1 in use, the code loader ends up getting tag 2 which is what is seen in the IPC from the DSP (stream_tag -1 << 9). Is this acceptable? I thought stream tag 1 was supposed to be reserved exclusively for the code loader or am I mistaken?

@plbossart

@plbossart @ranj063 I pushed #799 even though the actual bug has been fixed already. With that patch snd_sof_ipc_reply() isn't called at all and therefore an error message is avoided.

The root cause of this issue is that the IPC interrupt handler is active during suspend-resume stage, better to fix it in the way that don't let those FW purge IPCs go into the view of the IPC interrupt handler.

The root cause of this issue is that the IPC interrupt handler is active during suspend-resume stage, better to fix it in the way that don't let those FW purge IPCs go into the view of the IPC interrupt handler.

I think it's hard to say which one is better, as long as we leave well written comments in the code while ignoring them. Unless there is evaluation that the effort shooting out FW purge IPC is completely waste of time on all circumstance such as working with other OSes.

net/sched: sch_cbs: Call qdisc_reset for child qdisc

Navigation Menu

Repository navigation

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

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

	/* 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)));

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

Description

Activity

Jiangxinx commented on Apr 2, 2019

plbossart commented on Apr 2, 2019

lyakh commented on Apr 3, 2019

xiulipan commented on Apr 3, 2019

lyakh commented on Apr 3, 2019

wenqingfu commented on Apr 3, 2019

lyakh commented on Apr 3, 2019

plbossart commented on Apr 3, 2019

ranj063 commented on Apr 3, 2019

ranj063 commented on Apr 3, 2019

lyakh commented on Apr 3, 2019

ranj063 commented on Apr 3, 2019

lyakh commented on Apr 3, 2019

mmaka1 commented on Apr 4, 2019

ranj063 commented on Apr 6, 2019

lyakh commented on Apr 8, 2019

keyonjie commented on Apr 8, 2019

wenqingfu commented on Apr 8, 2019

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions