[S3] Trying resume playback failed after suspend/resume on APL-nocodec

[Jiangxinx]

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

Step：
1.aplay -Dhw:0,0 -fS16_LE -c2 -r48000 /dev/zero& sudo ./stress-s3.sh 50 1 1

Output:

+ readonly LOG_DIR=logs
+ LOG_DIR=logs
+ readonly RANDOM_INIT_VALUE=1
+ RANDOM_INIT_VALUE=1
+ readonly RANDOM_RANGE=5
+ RANDOM_RANGE=5
+ readonly S3_SLEEP=2
+ S3_SLEEP=2
+ set +x
== start time: 2019-03-04 16:05:06 ==
Playing raw data '/dev/zero' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
---- test 1 of 50 ----
System will suspend after 1 seconds ...
system will resume after 3 seconds ...
rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Mon Mar  4 08:05:11 2019
Suspended. Trying resume. Failed. Restarting stream. Done.
aplay: pcm_write:2011: write error: Input/output error
aplay doesn't exist!

dmesg:

[ 6338.143778] sof-audio-pci 0000:00:0e.0: Debug PCIR: 00000000 at  00000044
[ 6338.144891] sof-audio-pci 0000:00:0e.0: loading firmware
[ 6338.144912] sof-audio-pci 0000:00:0e.0: Debug PCIR: 00000002 at  00000048
[ 6338.144919] sof-audio-pci 0000:00:0e.0: Debug PCIW: 00000000 at  00000048
[ 6338.144925] sof-audio-pci 0000:00:0e.0: Debug PCIR: 00000000 at  00000044
[ 6338.144931] sof-audio-pci 0000:00:0e.0: Debug PCIW: 00000004 at  00000044
[ 6338.144934] sof-audio-pci 0000:00:0e.0: booting DSP firmware
[ 6338.145063] sof-audio-pci 0000:00:0e.0: period_bytes:0x0
[ 6338.145068] sof-audio-pci 0000:00:0e.0: periods:1
[ 6338.194928] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1d003c timedout
[ 6338.194931] sof-audio-pci 0000:00:0e.0: error: timeout on core powerup
[ 6338.194935] sof-audio-pci 0000:00:0e.0: error: power up core failed core_mask 3adspcs 0x1d003c
[ 6338.194937] sof-audio-pci 0000:00:0e.0: error: dsp core 0/1 power up failed
[ 6338.194941] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6338.194946] sof-audio-pci 0000:00:0e.0: error: status = 0x001d003c panic = 0x00000001
[ 6338.194948] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6338.253450] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1d003c timedout
[ 6338.253462] sof-audio-pci 0000:00:0e.0: error: reset enter failed: core_mask 3 adspcs 0x1d003c
[ 6338.253466] sof-audio-pci 0000:00:0e.0: error: dsp core reset failed: core_mask 3
[ 6338.253473] sof-audio-pci 0000:00:0e.0: error: Error code=0x1d003c: FW status=0x1006701
[ 6338.253478] sof-audio-pci 0000:00:0e.0: error: iteration 0 of Core En/ROM load failed: -5
[ 6338.305090] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1d003c timedout
[ 6338.305097] sof-audio-pci 0000:00:0e.0: error: timeout on core powerup
[ 6338.305105] sof-audio-pci 0000:00:0e.0: error: power up core failed core_mask 3adspcs 0x1d003c
[ 6338.305125] sof-audio-pci 0000:00:0e.0: error: dsp core 0/1 power up failed
[ 6338.305131] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6338.305136] sof-audio-pci 0000:00:0e.0: error: status = 0x001d003c panic = 0x00000001
[ 6338.305141] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6338.356059] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1d003c timedout
[ 6338.356069] sof-audio-pci 0000:00:0e.0: error: reset enter failed: core_mask 3 adspcs 0x1d003c
[ 6338.356073] sof-audio-pci 0000:00:0e.0: error: dsp core reset failed: core_mask 3
[ 6338.356079] sof-audio-pci 0000:00:0e.0: error: Error code=0x1d003c: FW status=0x1006701
[ 6338.356083] sof-audio-pci 0000:00:0e.0: error: iteration 1 of Core En/ROM load failed: -5
[ 6338.407117] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1d003c timedout
[ 6338.407123] sof-audio-pci 0000:00:0e.0: error: timeout on core powerup
[ 6338.407130] sof-audio-pci 0000:00:0e.0: error: power up core failed core_mask 3adspcs 0x1d003c
[ 6338.407133] sof-audio-pci 0000:00:0e.0: error: dsp core 0/1 power up failed
[ 6338.407140] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6338.407146] sof-audio-pci 0000:00:0e.0: error: status = 0x001d003c panic = 0x00000001
[ 6338.407151] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6338.458015] ata1: SATA link down (SStatus 4 SControl 300)
[ 6338.458051] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1d003c timedout
[ 6338.458060] sof-audio-pci 0000:00:0e.0: error: reset enter failed: core_mask 3 adspcs 0x1d003c
[ 6338.458064] sof-audio-pci 0000:00:0e.0: error: dsp core reset failed: core_mask 3
[ 6338.458070] sof-audio-pci 0000:00:0e.0: error: Error code=0x1d003c: FW status=0x1006701
[ 6338.458075] ata2: SATA link down (SStatus 4 SControl 300)
[ 6338.458078] sof-audio-pci 0000:00:0e.0: error: iteration 2 of Core En/ROM load failed: -5
[ 6338.458082] sof-audio-pci 0000:00:0e.0: error: dsp init failed after 3 attempts with err: -5
[ 6338.458114] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6338.458120] sof-audio-pci 0000:00:0e.0: error: status = 0x001d003c panic = 0x00000001
[ 6338.458125] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6338.458130] sof-audio-pci 0000:00:0e.0: error: failed to reset DSP
[ 6338.458134] sof-audio-pci 0000:00:0e.0: error: failed to boot DSP firmware after resume -5
[ 6338.458148] dpm_run_callback(): pci_pm_resume+0x0/0xa0 returns -5
[ 6338.458154] PM: Device 0000:00:0e.0 failed to resume: error -5
[ 6338.459622] OOM killer enabled.
[ 6338.459625] Restarting tasks ...
[ 6338.466342] r8169 0000:02:00.0 enp2s0: Link is Down
[ 6338.466523] r8169 0000:03:00.0 enp3s0: Link is Down
[ 6338.467837] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 6
[ 6338.467849] sof-audio-pci 0000:00:0e.0: PCM: resume stream 0 dir 0 DMA position 0
[ 6338.467854] sof-audio-pci 0000:00:0e.0: pcm: hw params stream 0 dir 0
[ 6338.467863] sof-audio-pci 0000:00:0e.0: generating page table for 00000000e4831e27 size 0xff00 pages 16
[ 6338.467890] sof-audio-pci 0000:00:0e.0: period_bytes:0xfc0
[ 6338.467894] sof-audio-pci 0000:00:0e.0: periods:16
[ 6338.467907] sof-audio-pci 0000:00:0e.0: stream_tag 1
[ 6338.468107] done.
[ 6338.468128] video LNXVIDEO:00: Restoring backlight state
[ 6338.479447] rfkill: input handler enabled
[ 6338.489297] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6338.489345] PM: suspend exit
[ 6338.498771] rfkill: input handler disabled
[ 6338.776085] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60010000 size 0x6c
[ 6338.776112] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6338.776119] sof-audio-pci 0000:00:0e.0: error: status = 0x001d003c panic = 0x00000000
[ 6338.776131] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6338.776143] sof-audio-pci 0000:00:0e.0: error: hw params ipc failed for stream 1
[ 6338.776153] sof-audio-pci 0000:00:0e.0: error: set pcm hw_params after resume
[ 6338.776164]  Port0: ASoC: trigger FE failed -110
[ 6338.776367] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 1
[ 6338.776370] sof-audio-pci 0000:00:0e.0: PCM: resume stream 0 dir 0 DMA position 0
[ 6338.776373] sof-audio-pci 0000:00:0e.0: pcm: hw params stream 0 dir 0
[ 6338.776378] sof-audio-pci 0000:00:0e.0: generating page table for 00000000e4831e27 size 0xff00 pages 16
[ 6338.776582] sof-audio-pci 0000:00:0e.0: error: timeout waiting for stream reset
[ 6338.776591] sof-audio-pci 0000:00:0e.0: error: hdac prepare failed: ffffff92
[ 6338.776598] sof-audio-pci 0000:00:0e.0: error: platform hw params failed
[ 6338.776606] sof-audio-pci 0000:00:0e.0: error: set pcm hw_params after resume
[ 6338.776613]  Port0: ASoC: trigger FE failed -110
[ 6338.776620] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 0
[ 6339.384224] sof-audio-pci 0000:00:0e.0: pcm: free stream 0 dir 0
[ 6339.384256] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6339.688093] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60030000 size 0xc
[ 6339.688124] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6339.688132] sof-audio-pci 0000:00:0e.0: error: status = 0x001d003c panic = 0x00000000
[ 6339.688146] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6339.688301] sof-audio-pci 0000:00:0e.0: pcm: close stream 0 dir 0
[ 6339.876218] r8169 0000:03:00.0 enp3s0: Link is Up - 100Mbps/Full - flow control off
[ 6342.280287] sof-audio-pci 0000:00:0e.0: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 6342.584994] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x40010000 size 0x4c
[ 6342.585014] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6342.585018] sof-audio-pci 0000:00:0e.0: error: status = 0x001d003c panic = 0x00000000
[ 6342.585024] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6342.585034] sof-audio-pci 0000:00:0e.0: error: ctx_save ipc error during suspend -110
[ 6342.641881] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1d003c timedout
[ 6342.641893] sof-audio-pci 0000:00:0e.0: error: reset enter failed: core_mask 3 adspcs 0x1d003c
[ 6342.641913] sof-audio-pci 0000:00:0e.0: error: dsp core reset failed: core_mask 3
[ 6342.641924] sof-audio-pci 0000:00:0e.0: error: failed to power down core during suspend
[ 6342.641935] sof-audio-pci 0000:00:0e.0: error: failed to power down DSP during suspend -5
[ 6342.641957] sof-audio-pci 0000:00:0e.0: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -5)

Env:
sof master: 24e241b
kernel sof-dev: cf5978a
tplg: sof-apl-nocodec.tplg

Log:
dmesg.log
logger.log

[lgirdwood]

@Jiangxinx which board ?

[Jiangxinx]

@lgirdwood APL-UP2-NOCODEC

[lgirdwood]

@Jiangxinx can you try with thesofproject/linux#704 ? @ranj063 fyi.

[zhuyingjiang]

@Jiangxinx can you try with thesofproject/linux#704 ? @ranj063 fyi.

#704 doesn't help, seems not because of the delay.

[ranj063]

@lgirdwood this seems like a regression. let me check today

[zhuyingjiang]

This has the same root cause with #1073