Repository navigation
[BUG][APL-nocodec]arecord use 0,6(DMIC) then pause/resume ,it will I/O error(ipc timed out for 0x60060000 ) #2068
Description
Describe the bug
arecord use 0,6 then pause/resume ,it will I/O error(ipc timed out 0x60060000 size 12)
To Reproduce
1.sudo reboot
2.arecord -Dhw:0,6 -c2 -r48000 -fs32 t1st.wav -vv -i
3.pause/resume
Reproduction Rate
tried 4times
1.reproduced at the 5 time
2.reproduced at the 13 time
3.reproduced at the 36 time
4.reproduced at the 49 time
Expected behavior
can pause/resume normally when arecord use 0,6
Impact
it will tips "I/O error"
Environment
platform: APL UP2 with nocodec
Firmware: 59c9338 https://github.com/thesofproject/sof/commits/master
Kernel: f5e70ce https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology: file: tools/topology/sof-apl-nocodec.tplg same as firmware
Dmesg.log
52.223308] sof-audio-pci 0000:00:0e.0: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 52.223321] sof-audio-pci 0000:00:0e.0: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 52.330851] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 6 dir 1 cmd 3
[ 52.330865] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[ 52.837915] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60060000 size 12
[ 52.837928] sof-audio-pci 0000:00:0e.0: info: preventing DSP entering D3 state to preserve context
[ 52.837938] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[ 52.837987] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[ 52.837999] sof-audio-pci 0000:00:0e.0: error: hda irq intsts 0x00000000 intlctl 0xc0000003 rirb 00
[ 52.838005] sof-audio-pci 0000:00:0e.0: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 52.838013] sof-audio-pci 0000:00:0e.0: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 52.838019] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[ 52.838033] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x20240000 successful
[ 52.838042] DMIC01: ASoC: trigger FE cmd: 3 failed: -110
[ 52.838055] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 6 dir 1 cmd 4
[ 52.838890] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x2024001e successful
[ 52.838918] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[ 53.341861] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60070000 size 12
[ 53.341873] sof-audio-pci 0000:00:0e.0: info: preventing DSP entering D3 state to preserve context
[ 53.341882] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[ 53.341930] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[ 53.341940] sof-audio-pci 0000:00:0e.0: error: hda irq intsts 0x00000000 intlctl 0xc0000003 rirb 00
[ 53.341945] sof-audio-pci 0000:00:0e.0: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 53.341953] sof-audio-pci 0000:00:0e.0: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 53.341958] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[ 53.341968] DMIC01: ASoC: trigger FE cmd: 4 failed: -110
[ 53.342494] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 6 dir 1 cmd 3
[ 53.342504] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[ 53.845868] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60060000 size 12
[ 53.845881] sof-audio-pci 0000:00:0e.0: info: preventing DSP entering D3 state to preserve context
[ 53.845891] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[ 53.845940] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[ 53.845951] sof-audio-pci 0000:00:0e.0: error: hda irq intsts 0x00000000 intlctl 0xc0000003 rirb 00
[ 53.845957] sof-audio-pci 0000:00:0e.0: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 53.845966] sof-audio-pci 0000:00:0e.0: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 53.845971] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[ 53.845985] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x20240000 successful
[ 53.845994] DMIC01: ASoC: trigger FE cmd: 3 failed: -110
[ 53.846008] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 6 dir 1 cmd 4
[ 53.846864] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x2024001e successful
[ 53.846884] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[ 54.349872] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60070000 size 12
[ 54.349881] sof-audio-pci 0000:00:0e.0: info: preventing DSP entering D3 state to preserve context
[ 54.349888] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[ 54.349934] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[ 54.349942] sof-audio-pci 0000:00:0e.0: error: hda irq intsts 0x00000000 intlctl 0xc0000003 rirb 00
[ 54.349946] sof-audio-pci 0000:00:0e.0: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 54.349951] sof-audio-pci 0000:00:0e.0: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 54.349955] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[ 54.349962] DMIC01: ASoC: trigger FE cmd: 4 failed: -110
[ 55.461990] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 6 dir 1 cmd 0
[ 55.462004] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 55.965832] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60050000 size 12
[ 55.965846] sof-audio-pci 0000:00:0e.0: info: preventing DSP entering D3 state to preserve context
[ 55.965856] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[ 55.965905] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[ 55.965918] sof-audio-pci 0000:00:0e.0: error: hda irq intsts 0x00000000 intlctl 0xc0000003 rirb 00
[ 55.965924] sof-audio-pci 0000:00:0e.0: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 55.965932] sof-audio-pci 0000:00:0e.0: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 55.965938] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[ 55.965952] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x20240000 successful
[ 55.965961] DMIC01: ASoC: trigger FE cmd: 0 failed: -110
[ 55.966000] sof-audio-pci 0000:00:0e.0: pcm: free stream 6 dir 1
[ 55.966009] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 56.469834] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60030000 size 12
[ 56.469844] sof-audio-pci 0000:00:0e.0: info: preventing DSP entering D3 state to preserve context
[ 56.469852] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[ 56.469898] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[ 56.469907] sof-audio-pci 0000:00:0e.0: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[ 56.469911] sof-audio-pci 0000:00:0e.0: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 56.469917] sof-audio-pci 0000:00:0e.0: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 56.469921] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[ 56.470077] sof-audio-pci 0000:00:0e.0: pcm: close stream 6 dir 1
Logger-error.log
CORE LEVEL COMP_ID TIMESTAMP DELTA FILE_NAME CONTENT
0 1 SA 33866550.833333 33866552.000000 src/lib/agent.c:57 validate(), ll drift detected, delta = 20195
0 1 SA 50650545.625000 16783994.000000 src/lib/agent.c:57 validate(), ll drift detected, delta = 20163
0 1 SA 51198546.250000 548000.625000 src/lib/agent.c:57 validate(), ll drift detected, delta = 20175
0 1 SA 51713549.322917 515003.062500 src/lib/agent.c:57 validate(), ll drift detected, delta = 20234
Activity
fredoh9 commentedon Oct 31, 2019
If this is real issue, this is good catch. But i couldn't reprodce this on a APL_UP2_NOCODEC.
Sometime overrun warning came out but recovered well. I do more than 100 times manually and 500+ times with below script.
#########################+ | 48%overrun!!! (at least 0.145 ms long)For more testing, I attached a simple script to run 100 times of pause/resume recording on hw:0,6.
run_arecord_pause_resume.sh.txt
Liviali155 commentedon Nov 1, 2019
I tested twice used your script ,not reproduced
but I used the command "arecord -D hw:0,6 -r 48000 -c 2 -f s32_le -vv -i -d 55 test.wav -q" tested twice manually,all can reproduced it :
1.reproduced it at 64 time
2.reproduced it at 32 time
I think you can pause/resume more quickly,
dmesg1.log
in addition，0,6 is DMIC01 known from arecord -l as capture
[-][BUG][APL-nocodec]arecord use 0,6 then pause/resume ,it will I/O error(ipc timed out )[/-][+][BUG][APL-nocodec]arecord use 0,6 then pause/resume ,it will I/O error(ipc timed out for 0x60060000 )[/+][-][BUG][APL-nocodec]arecord use 0,6 then pause/resume ,it will I/O error(ipc timed out for 0x60060000 )[/-][+][BUG][APL-nocodec]arecord use 0,6(DMIC) then pause/resume ,it will I/O error(ipc timed out for 0x60060000 )[/+]Liviali155 commentedon Nov 7, 2019
Bi-sect result: Caused by firmwire commit 8e4d0c9. Might related with #2044
Liviali155 commentedon Nov 11, 2019
error not seen with PR #2078
lgirdwood commentedon Nov 11, 2019
Clsoing since #2078 now merged.