Repository navigation
[BUG]DMIC capture pause-release cause ipc timed out 0x60070000 size 12 #2044
Description
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
Activity
dengyangchao commentedon Nov 4, 2019
issue also can reproduce on ICL RVP HDA, CFL-S RVP HDA, GLK Chrome i2s
dengyangchao commentedon Nov 4, 2019
https://github.com/thesofproject/linux/issues/1415 a related issue for reference
aiChaoSONG commentedon Nov 4, 2019
try hundreds times on ASUS CML , this issue reproduced.
issue also reproduced on Dell CML HDA platform, 16k 2ch dmic pipeline
[-][BUG][CML][i2s]DMIC capture pauce-realse cause ipc timed out 0x60070000 size12[/-][+][BUG][CML][i2s]DMIC capture pause-release cause ipc timed out 0x60070000 size 12[/+]sinahuang commentedon Nov 4, 2019
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 commentedon Nov 4, 2019
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.
[-][BUG][CML][i2s]DMIC capture pause-release cause ipc timed out 0x60070000 size 12[/-][+][BUG]DMIC capture pause-release cause ipc timed out 0x60070000 size 12[/+]1 remaining item
lgirdwood commentedon Nov 5, 2019
@wwittbrx @bkokoszx This is P1 due to impact across multiple platforms.
@dengyangchao I assume rapid pause/release will cause this on any device i.e. HDA, SSP, DMIC ?
dengyangchao commentedon Nov 6, 2019
@lgirdwood Can't reproduce only on CML laptop with onboard codec ALC3204 in HDA mode, and observed this platform use 2ch.
Other issue reproduced platforms use 4ch
aiChaoSONG commentedon Nov 6, 2019
this issue reproduced on dell CML laptop with onborad codec ALC3204 in HDA mode.
wwittbrx commentedon Nov 6, 2019
Sorry, missclick. From my tests this issue does not happen when rapidly pause/releasing SSP capture stream, I tested it with 48kHz 32b/32b 4 channel format.
wwittbrx commentedon Nov 6, 2019
Looks like 8e4d0c9 is the commit that introduced this issue.
dengyangchao commentedon Nov 7, 2019
Yes, also tried on ICL RVP with onboard codec ALC700 in HDA mode,
issue occurred from 8e4d0c9
plbossart commentedon Nov 7, 2019
@tlauda we have a slew of problems that seem related to this commit 8e4d0c9, do you mind taking a look?
bkokoszx commentedon Nov 8, 2019
I think that we had deadlock in dmic_work() function. Do you still have a reproduction with PR #2078?
wwittbrx commentedon Nov 8, 2019
#2078 fixes the issue for me, @dengyangchao please confirm it on your side and close the issue. #2068 should be fixed by this too.
dengyangchao commentedon Nov 11, 2019
After applied #2078 , issue can't reproduce on my side too.