[CML][BUG]DP sound output volume turned so low that can barely be heard after wake up from s3 during DP playback

[dengyangchao]

Describe the bug
DP output no sound after wake up from s3 during DP playback.

To Reproduce

1.Connect DP external
2.Wait till runtime PM status is suspned
3.Play DP music(aplay -Dhw:0,4 -f dat 1.wav -vv -i)
4.Run command "sudo rtcwake -m mem -s 10" enter S3 then wake up

frequency
3/3

Expected result
DP keep playing after wake up from s3

Actual result
DP output no sound after s3 while console shows music is still playing.

Environment
Firmware: 9152ba7 https://github.com/thesofproject/sof/commits/master
Kernel: 9d7da69 https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology: file: tools/topology/sof-hda-generic-2ch.tplg same as firmware
platform： CML

dmesg

[  788.675930] Restarting tasks ... done.
[  788.679653] sof-audio-pci 0000:00:1f.3: hda: prepare stream dir 0
[  788.679662] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  788.679804] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[  788.679830] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[  788.679859] sof-audio-pci 0000:00:1f.3: pcm: prepare stream 4 dir 0
[  788.679861] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 4 dir 0
[  788.679872] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[  788.679895] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[  788.679900] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[  788.679902] sof-audio-pci 0000:00:1f.3: periods:4
[  788.679925] sof-audio-pci 0000:00:1f.3: stream_tag 1
[  788.679931] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[  788.680125] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[  788.680128] sof-audio-pci 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790528
[  788.680280] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 0 cmd 1
[  788.680953] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x14001e successful
[  788.680957] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  788.681143] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  788.681149] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=1
[  788.715396] PM: suspend exit
[  789.481187] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  789.481226] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  823.800138] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 0 cmd 0
[  823.800708] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[  823.800717] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  823.800919] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  823.800927] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  823.801105] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  823.801122] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=0
[  823.801137] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  823.801275] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[  823.801416] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  823.801537] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[  823.801602] sof-audio-pci 0000:00:1f.3: pcm: close stream 4 dir 0
[  823.802512] sof-audio-pci 0000:00:1f.3: some codecs still powered (00000004), not idle
[  824.480983] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  824.481023] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  826.006261] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[  826.041431] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[  826.041614] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[  826.041640] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
[  826.041644] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[  826.041647] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
[  826.041678] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000010 at  00000044
[  905.540892] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[  905.540902] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000040 at  00000048
[  905.540907] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000000 at  00000048
[  905.543948] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
[  905.543957] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000040 at  00000048
[  905.544018] sof-audio-pci 0000:00:1f.3: loading firmware
[  905.544024] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000002 at  00000048
[  905.544028] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000000 at  00000048
[  905.544034] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[  905.544038] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000004 at  00000044
[  905.544040] sof-audio-pci 0000:00:1f.3: booting DSP firmware
[  905.544139] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[  905.544157] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[  905.544162] sof-audio-pci 0000:00:1f.3: period_bytes:0x0
[  905.544164] sof-audio-pci 0000:00:1f.3: periods:1
[  905.544259] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f0f0f successful
[  905.544269] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f0f0e successful
[  905.544273] sof-audio-pci 0000:00:1f.3: unstall/run core: core_mask = 1
[  905.544278] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
[  905.544753] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x80000000 successful
[  905.544759] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010e0e successful
[  905.544813] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[  905.623813] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x5000001 successful
[  905.635744] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x5 successful
[  905.635758] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x140000 successful
[  905.635763] sof-audio-pci 0000:00:1f.3: Firmware download successful, booting...
[  905.641428] sof-audio-pci 0000:00:1f.3: ipc rx: 0x70000000: FW_READY
[  905.641436] sof-audio-pci 0000:00:1f.3: ipc: DSP is ready 0x70000000 offset 0x81000
[  905.641450] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x70000000: FW_READY
[  905.641510] sof-audio-pci 0000:00:1f.3: firmware boot complete
[  905.641526] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
[  905.641532] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000002 at  00000048
[  905.641539] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000004 at  00000044
[  905.641543] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000000 at  00000044
[  905.641553] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[  905.641572] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[  905.641577] sof-audio-pci 0000:00:1f.3: period_bytes:0x0
[  905.641580] sof-audio-pci 0000:00:1f.3: periods:1
[  905.641595] sof-audio-pci 0000:00:1f.3: stream_tag: 1
[  905.641609] sof-audio-pci 0000:00:1f.3: ipc tx: 0x90030000: GLB_TRACE_MSG
[  905.641891] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x90030000: GLB_TRACE_MSG
[  905.642471] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2014001e successful
[  905.642487] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30010000: GLB_TPLG_MSG: COMP_NEW
[  905.642630] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x30010000: GLB_TPLG_MSG: COMP_NEW

dp_s3_noSound_dmesg.log
logger.log

[YvonneYang2]

Issue still reproduced on two CMLs with test recipe as below, reproduce rate is 8/10. Test it on CML-RVP, cannot reproduce the bug, reproduce rate is 0/5.

Test recipe:
Firmware: f837e57 https://github.com/thesofproject/sof/commits/master
Kernel: 8b8f437 https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology:file: tools/topology/sof-hda-generic-2ch.tplg

PM enter suspend is s2idle mode, while on CML-RVP, PM enter suspend is deep mode.

dmesg

[   23.640843] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 0 cmd 1
[   23.641150] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x14001e successful
[   23.641159] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[   23.641339] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[   23.641351] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=1
[   24.127841] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[   24.127864] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   24.628283] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[   24.628325] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   33.358349] PM: suspend entry (s2idle)
[   33.359396] Filesystems sync: 0.001 seconds
[   33.360335] Freezing user space processes ... (elapsed 0.002 seconds) done.
[   33.362366] OOM killer disabled.
[   33.362367] Freezing remaining freezable tasks ... (elapsed 0.000 seconds) done.
[   33.363293] printk: Suspending console(s) (use no_console_suspend to debug)
[   33.363758] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 0 cmd 5
[   33.364157] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[   33.364166] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[   33.364407] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[   33.364415] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[   33.364638] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[   33.364651] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=5
[   33.364667] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[   33.364835] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[   33.366676] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[   33.366696] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[   33.366841] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[   33.366875] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
[   33.366881] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[   33.366885] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
[   33.366929] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000010 at  00000044
[   43.998573] iwlwifi 0000:00:14.3: Applying debug destination EXTERNAL_DRAM
[   44.071443] r8169 0000:01:00.0 enp1s0: Link is Down
[   44.125973] iwlwifi 0000:00:14.3: FW already configured (0) - re-configuring
[   44.128807] iwlwifi 0000:00:14.3: BIOS contains WGDS but no WRDS
[   44.298706] ata1: SATA link down (SStatus 4 SControl 300)
[   44.416167] usb 1-3: reset low-speed USB device number 2 using xhci_hcd
[   44.690852] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[   44.690862] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000040 at  00000048
[   44.690868] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000000 at  00000048
[   44.693722] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
[   44.693731] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000040 at  00000048
[   44.693802] sof-audio-pci 0000:00:1f.3: loading firmware

logger.log

dmesg.log

[YvonneYang2]

Change PM enter suspend mode from s2idle to deep on CML DVT2 , issue still can be reproduced.

[YvonneYang2]

Test it on CML DVT1, issue cannot be reproduced. Only reproduced on CML DVT2, and kernel config must enable cml via echo -e " CONFIG_SND_SOC_SOF_COMETLAKE_LP_SUPPORT=y\nCONFIG_SND_SOC_SOF_COMETLAKE_H_SUPPORT=y\n" >sof-enable-cml.config

[kv2019i]

I've been now trying to reproduce this on the systems I have with latest driver+fw with not much success. I've tested on WHL and CFL systems, with both "s2idle" and "deep" modes. Based on test results, it would seem this problem is specifically related to real S3, i.e. "deep" mode.

@YvonneYang2 can you confirm whether the DP display is working correctly in the cases where sound output fails to recover -- i.e. do you see a picture on the DP monitor?

Second thing, could you try this case with legacy/non-DSP driver just to exclude issues on i915 side?

[YvonneYang2]

Test it with "s2idle" and "deep" modes, both can reproduce the issue. But I found DP actually have sound output instead of no sound after wake up, the volume turned to so low that can barely be heard after wake up.

Reproduced rate: 5/20
When issue reproduced, the DP display was working correctly.
Terminate aplay, and aplay again can recover the issue.

Try this on legacy hda mode 20 times, cannot reproduce the issue.

Test recipe:
Firmware: c6f1b08 https://github.com/thesofproject/sof/commits/master
Kernel: 8714060 https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology:file: sof-hda-generic-2ch.tplg

Logs which reproduced with s2idle mode as below:
dmesg.log
logger.log

[kv2019i]

@YvonneYang2 wrote:

Test it with "s2idle" and "deep" modes, both can reproduce the issue. But I found DP actually
have sound output instead of no sound after wake up, the volume turned to so low that can
barely heard after wake up.

Reproduced rate: 5/20

thank you. This is important. Can you still confirm I got the above right that on the 5 failing cases out of 20, there is audio but is it is very low volume?

I've now tried over 100 iterations on multiple systems with no errors, but I have specifically monitored for no audio error case. I can try to rerun tests observing the volume levels.

[YvonneYang2]

Yes, when issue reproduces, there is audio but it is very low volume. I've tired 10 times with today's test recipe, and still can reproduce 3 times.

Test recipe:
Firmware: c6f1b08 https://github.com/thesofproject/sof/commits/master
Kernel: b45315d https://github.com/thesofproject/linux/commits/topic/sof-dev

[kv2019i]

It seems #1123 is a feasible option to solve this, so I will now focus on this option (rather than fixing this bug in hdac-hdmi).