[Bug][CML][UCM]UCM stop work after plug headset during suspend. (intermittent)

[YvonneYang2]

Describe the bug
UCM stop work when wake up from suspend.

To Reproduce
1.Enter suspended via "sudo rtcwake -m mem -s 15"
2. Do HDMI & DP hot-plug during suspended.
3.Wake up and check the UCM. Enter suspended again via "sudo rtcwake -m mem -s 15"
4. Do headset hot plug during suspended.
5.Check the Sound setting after wake up

Expected behavior
UCM works normally when wake up from suspended.

Impact
After step 3, UCM works well after wak up.
After step 5, UCM not work anymore after wake up from suspended.

Reproduce rate
2/50

Environment
Rander UCM https://github.com/RanderWang/intel-UCM  
Kernel repo：c99938c https://github.com/thesofproject/linux/tree/release/sof-v5.0
Firmware repo: 05d4e19 https://github.com/thesofproject/sof/commits/master |  
Topology: https://github.com/thesofproject/sof/commits/master . Same as above SOF repo
file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg

SOF logger error log

    0      1          DMA           1452986.770833   1452986.750000 intel/cavs/hda-dma.c:480 	hda-dmac: 4 no free channel 1
    0      1         HOST           1452993.437500         6.666667     src/audio/host.c:601 	host_params() error: hd->chan < 0
    0      1         PIPE           1452998.854167         5.416667 src/audio/pipeline.c:329 	pipeline_params() error: ret = -19, host->comp.id = 9
    0      1          IPC           1453005.104167         6.250000    src/ipc/handler.c:317 	ipc: pipe 2 comp 9 params failed -19
    0      1          DMA           1453020.208333        15.104167 intel/cavs/hda-dma.c:616 	hda-dmac: 4 invalid channel -19
    0      1          DMA           1462257.187500      9236.979492 intel/cavs/hda-dma.c:616 	hda-dmac: 4 invalid channel -1

dmesg log

[ 3846.540122] sof-audio-pci 0000:00:1f.3: pcm: prepare stream 0 dir 1
[ 3846.540124] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 1
[ 3846.540168] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[ 3846.540169] sof-audio-pci 0000:00:1f.3: periods:4
[ 3846.540202] sof-audio-pci 0000:00:1f.3: stream_tag 2
[ 3846.540207] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 3846.540381] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60010000 size 20
[ 3846.540386] sof-audio-pci 0000:00:1f.3: error: hw params ipc failed for stream 2
[ 3846.540387] sof-audio-pci 0000:00:1f.3: error: set pcm hw_params after resume
[ 3846.540390] sof-audio-pci 0000:00:1f.3: ASoC: platform prepare error: -22
[ 3846.540392]  HDA Analog: ASoC: prepare FE HDA Analog failed
[ 3846.542281] sof-audio-pci 0000:00:1f.3: pcm: open stream 6 dir 1
[ 3846.542285] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 3846.542286] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 3846.542288] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 3846.542415] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 6 dir 1
[ 3846.542419] sof-audio-pci 0000:00:1f.3: generating page table for 00000000a293dba2 size 0xffc0 pages 16
[ 3846.542459] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[ 3846.542460] sof-audio-pci 0000:00:1f.3: periods:4
[ 3846.542477] sof-audio-pci 0000:00:1f.3: stream_tag 3
[ 3846.542490] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 3846.542680] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 3846.542684] sof-audio-pci 0000:00:1f.3: pcm: stream dir 1, posn mailbox offset is 790604
[ 3846.542802] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 6 dir 1 cmd 1
[ 3846.542812] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START

ucmDmesg.log
ucm_logger.log

[mengdonglin]

@RanderWang Please provide clues by check the error log.

[RanderWang]

[ 3846.540390] sof-audio-pci 0000:00:1f.3: ASoC: platform prepare error: -22
[ 3846.540392]  HDA Analog: ASoC: prepare FE HDA Analog failed

It should be a driver issue. There is a HDMI monitor connected, I don't know whether this would affect the issue.

[mengdonglin]

@RanderWang @libinyang to check with HDMI support on CML

[RanderWang]

The error sequence is:
(1) pcm: prepare stream 0 dir 1
(2) pcm: hw params stream 0 dir 1
(3) pcm: trigger stream 0 dir 1 start
(4) pcm: trigger stream 0 dir 1 cmd stop
// miss pcm free
(5) pcm: prepare stream 0 dir 1
(6) pcm: hw params stream 0 dir 1
error: hda dma is not free for application didn't free this hda dma by calling pcm free.

This bug is hard to be reproduced, so I can't make sure it is caused by application or ASoC.

[ClarexZhou]

@RanderWang
Found one way to reproduce ipc error for 0x60010000 . Same dmesg and error sof logger. But UCM still works after these steps.

To Reproduce

1. aplay -Dhw:0,0 -f dat wav/48California_Dreaming.wav -vv -i
2. Pause music
3. Open another terminal, run 'sudo rtcwake -m mem -s 2' to enter S3 and wake up
4. Resume music
5. Ctl+z to put background
6. 'fg'. failed and error seen now.

Terminal output

dmesg

[ 3722.528030] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 3722.528066] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 3724.556977] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 0
[ 3724.556997] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 3724.557203] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 3724.557217] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=0
[ 3725.527644] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 3725.527676] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 3725.932393] sof-audio-pci 0000:00:1f.3: pcm: prepare stream 0 dir 0
[ 3725.932397] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 0
[ 3725.932429] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[ 3725.932431] sof-audio-pci 0000:00:1f.3: periods:4
[ 3725.932450] sof-audio-pci 0000:00:1f.3: stream_tag 1
[ 3725.932464] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 3725.932761] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60010000 size 20
[ 3725.932770] sof-audio-pci 0000:00:1f.3: error: hw params ipc failed for stream 1
[ 3725.932774] sof-audio-pci 0000:00:1f.3: error: set pcm hw_params after resume
[ 3725.932778] sof-audio-pci 0000:00:1f.3: ASoC: platform prepare error: -22
[ 3725.932783]  HDA Analog: ASoC: prepare FE HDA Analog failed
[ 3725.932873] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 3725.932882] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 3725.933048] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 3725.933166] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[ 3726.527978] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 3726.528010] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 3728.371886] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 3728.372112] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 3728.372165] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
[ 3728.372172] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[ 3728.372175] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
[ 3728.372209] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000010 at  00000044

error logger

ipcError_dmesg.log
ipcError_All_logger.log

[libinyang]

hmm, it seems to be the pcm FE/BE resume issue. It may be caused by one Ranjani's patch. This is what I'm concerning when I reviewed Ranjani's patch. There is one argument state not precise. I will submit a patch next week after my HDMI jack task finished.

[wenqingfu]

Found one way to reproduce ipc error for 0x60010000

how often can these steps trigger the error? 100% or still intermittent? @ClarexZhou