[BUG]DMIC capture pause-release cause ipc timed out 0x60070000 size 12

[dengyangchao]

Describe the bug
DMIC capture pauce-realse quickly cause ipc timed out 0x60070000 size12, when issue occur, wait for a while(maybe5 or 10 mins) sometimes will occur system hang

To Reproduce
1.Reboot system via "sudo reboot"
2.Wait audio device to enter runtime PM suspended status
3.Dmic arecord via arecord -Dhw:0,1 -r48000 -c4 -fs32_le test.wav -vv -i
4.Pause-realse quickly and repeat

Reproduction Rate
Tried 4 times
1.occur at 15th
2.occur at 28th
3.occur at 10th
4.occur at 22th

Expected behavior
Dmic capture pause-release can work normal

Impact
Cause ipc timed out

Environment
Firmware: e5fe2ca https://github.com/thesofproject/sof/commits/master
Kernel:4e76b4a1 https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology: file: tools/topology/sof-cml-rt5682-max98357a.tplg same as firmware
Platform:CML Chrome i2s

Dmesg

[   92.468680] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[   92.468922] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[   92.468935] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
[   92.526194] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[   92.526216] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   92.645439] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 1 dir 1 cmd 4
[   92.645982] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2024001e successful
[   92.645994] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[   93.149688] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60070000 size 12
[   93.149700] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[   93.149713] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   93.149817] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   93.149832] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000003 rirb 00
[   93.149837] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[   93.149845] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[   93.149850] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   93.149860]  DMIC01: ASoC: trigger FE cmd: 4 failed: -110
[   93.149873] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 1 dir 1 cmd 3
[   93.149881] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[   93.653704] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60060000 size 12
[   93.653718] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[   93.653728] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   93.653837] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   93.653856] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000003 rirb 00
[   93.653862] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[   93.653874] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[   93.653879] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   93.653895] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
[   93.653906]  DMIC01: ASoC: trigger FE cmd: 3 failed: -110

logger-error

 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1           SA         101277929.375000 101277928.000000      src/lib/agent.c:57  	validate(), ll drift detected, delta = 26063
    0      1           SA         108954141.041667   7676211.500000      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25470
    0      1           SA         110066660.416667   1112519.375000      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25801
    0      1           SA         110475391.770833    408731.343750      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25466
    0      1           SA         110880397.552083    405005.781250      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25574
    0      1           SA         111302906.354167    422508.812500      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25741
    0      1           SA         111715395.572917    412489.218750      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25538
    0      1           SA         112211660.677083    496265.093750      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25833
    0      1           SA         112611643.281250    399982.593750      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25499
    0      1           SA         112989147.968750    377504.687500      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25584
    0      1           SA         113386660.885417    397512.906250      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25849
    0      1           SA         113759144.531250    372483.656250      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25516
    0      1           SA         114114140.989583    354996.468750      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25450
    0      1           SA         114487903.020833    373762.031250      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25678
    0      1           SA         114909149.270833    421246.250000      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25606
    0      1           SA         115336650.312500    427501.031250      src/lib/agent.c:57  	validate(), ll drift detected, delta = 25630

amixer.txt
dmesg.log
logger.log
logger-error.log

[dengyangchao]

issue also can reproduce on ICL RVP HDA, CFL-S RVP HDA, GLK Chrome i2s

[dengyangchao]

https://github.com/thesofproject/linux/issues/1415 a related issue for reference

[aiChaoSONG]

try hundreds times on ASUS CML , this issue reproduced.
issue also reproduced on Dell CML HDA platform, 16k 2ch dmic pipeline

[sinahuang]

This issue can be reproduced with kernel sof-dev on CML-S RVP with onboard ALC711 in HDA mode..

Test recipe:

Kernel: https://github.com/thesofproject/linux/commits/topic/sof-dev commit: 4e76b4a
FW: https://github.com/thesofproject/sof/commits/master commit: 0e8cf66
Tplg: master e5fe2ca sof-hda-generic-4ch.tplg
Platform: CML-S RVP with onboard ALC711 in HDA mode.

dmesg1104.txt
logger1104.log

[wwittbrx]

The issue can be reproduced on our platforms, @bkokoszx will take a look at it once he finishes other tasks.

Could you specify the priority for this issue? From our tests this only happens when doing pause/release very rapidly, is it a common use case?

Also, please specify if this is a regression or a new test case, if this is a regression we can bisect and try to find a commit that introduced the issue.