Repository navigation
[BYT][ipc position update feature]IPC timed out when stop playback #808
Description
kernel: 75d88bd1 + patch #807 (fix NULL pointer)
sof: 1:1:0-cbbc6
When playback, press ctrl+c to stop (or wait for playback finish) the playback, the ipc timeout will happen.
dmesg:
[ 62.081405] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x600a0000: GLB_STREAM_MSG: POSITION
[ 62.124326] sof-audio-pci 0000:00:1f.3: ipc rx: 0x600a0000: GLB_STREAM_MSG: POSITION
[ 62.124400] sof-audio-pci 0000:00:1f.3: posn : host 0x9900 dai 0x109b60 wall 0x40dd152
[ 62.124406] sof-audio-pci 0000:00:1f.3: PCM: stream 1 dir 0 DMA position 4896 DAI position 136044
[ 62.124412] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 1 dir 0 cmd 0
[ 62.124427] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 62.426826] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[ 62.426843] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 62.427078] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 62.427083] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 62.427089] HDMI1: ASoC: trigger FE failed -110
[ 62.427101] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x600a0000: GLB_STREAM_MSG: POSITION
[ 62.427130] sof-audio-pci 0000:00:1f.3: pcm: free stream 1 dir 0
[ 62.427154] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 62.427159] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 62.427211] sof-audio-pci 0000:00:1f.3: pcm: close stream 1 dir 0
[ 62.427245] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[ 62.766317] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 62.766354] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 63.266264] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 63.266294] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 64.970155] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 64.970282] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 64.970314] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
[ 64.970323] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1000f0f successful
[ 64.970328] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
[ 64.970378] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000010 at 00000044
reproduce steps:
- run aplay -Dhw:0,n file.wav
- press ctrl+c to stop (or wait for playback finish)
Activity
libinyang commentedon Apr 10, 2019
dmesg.txt
ranj063 commentedon Apr 11, 2019
@libinyang whats surprising in the attached logs is that even after the STOP trigger ipc fails, the PCM_FREE ipc succeeds right after followed by the CTX_SAVE.
keyonjie commentedon Apr 11, 2019
@libinyang please attached sof-logger logs also.
libinyang commentedon Apr 11, 2019
@ranj063 Yes, I think there may be something wrong to handle STOP in driver or FW. It seems to be just the STOP related.
[-][WHL] IPC timeout when stop playback[/-][+][WHL][BYT][ipc position update feature]IPC timeout when stop playback[/+]xiulipan commentedon Apr 11, 2019
@tlauda @ranj063 @plbossart @lgirdwood
Today I checked with @xun2z about this issue on byt.
It should be some issue only happen with IPC position update feature enabled platform.
EG: BYT: legacy; WHL: Timer driven HDA ( @tlauda @keyonjie @bardliao I think for I2S playback there will be no IPC postion update on APL or WHL?)
Here is the analysis from dmesg
To check more detail, we find the blocker call trace is
irq_thread -> snd_sof_ipc_msgs_rx -> ipc_stream_message -> ipc_period_elapsed -> snd_pcm_period_elapsed -> snd_pcm_update_hw_ptr0linux/sound/core/pcm_lib.c
Line 262 in 85c400e
Any idea? @xun2z and me will try to dig into that tomorrow
tlauda commentedon Apr 11, 2019
@xiulipan I don't know what is the problem on WHL, but on BYT we are simply exceeding ipc timeout. If I'm not wrong it's currently set to 0.3 ms, but even with my patch for dw-dma stop it takes around 0.34 ms to stop dma channel.
xiulipan commentedon Apr 11, 2019
@tlauda
Actually the IRQ comes. but can not wake the irq_thread. Please see my analyze above.
Something inside ALSA layer block the previous irq_thread.
xun2z commentedon Apr 11, 2019
@tlauda I did a lot of work-around on sof and also tried to take off "dw_dma_stop", the timeout still exist, so the root cause is not on firmware. Increasing ipc_time_out value does not help
keyonjie commentedon Apr 12, 2019
@xiulipan how did you know about this? are you saying handling to A is blocking at snd_pcm_update_hw_ptr0?
xiulipan commentedon Apr 12, 2019
@keyonjie
@xun2z add a lot of logs and analysis from the timestamp.
Could @xun2z upload some here?
BTW, I think with #826. WHL will not have this issue.
xun2z commentedon Apr 12, 2019
keyonjie commentedon Apr 12, 2019
so this trigger stop is initiated by ALSA, maybe xrun happen here. need debug into snd_pcm_update_state() for more infos.
we can check from fw logs about this, but the issue above may be more worthy to check, that may be common issue for IPC position update.
6 remaining items
xiulipan commentedon Apr 15, 2019
@libinyang
Yes, the bug for IPC STOP timeout is related to the IPC position update.
juimonen commentedon Apr 15, 2019
@xiulipan @libinyang when aplay gets ctrl-c alsa core is immediately put PCM_STATE_SETUP and pcm_stop is called. We still get position update which will notice the state change and call stop again. However now we are in irq handler and we have not yet called byt_host_done. So we are waiting for stop response with busy bit enabled (so not accepting messages).
juimonen commentedon Apr 15, 2019
@xiulipan correction to above: aplay ctrl-c causes "drain" before stop. We don't do anything to drain, but the stream goes to draining state. Now the position update comes, and because we are at state "draining" it calls stop. pos update + stop is ran in irq handler and we have busy bit enabled-> hence the timeout. The another stop caused by aplay comes later, but error has happened.
I'm not sure of proper way to correct this. There's a possibility that stop is called from position update when stream state is "draining" or "xrun" and those calls to dsp will fail (because we got nothing back as we are running in irq handler)... I can put to pcm.c a check that stop is not called in draining state, but that's pretty ugly (but it will fix this).
xiulipan commentedon Apr 15, 2019
@juimonen
Thanks for analysis, that should be the root cause. @xun2z
I will also check the code for more detail.
@lgirdwood @plbossart
Any idea about the right sequence about handling this situation.
Jiangxinx commentedon Apr 16, 2019
This issue can still be reproduced on daily test version.
Step
1.aplay -Dhw:0,0 audio.wav
2.ctrl+c
Env
sof master: 1b15fad
kernel sof-dev: 2de29fa(compiled with PR #823 )
tplg: sof-byt-rt5651.tplg
xiulipan commentedon Apr 16, 2019
@Jiangxinx Not fixed on BYT (only IPC position update user).
Please help to check if any more issue if PulseAudio is enabled.
juimonen commentedon Apr 17, 2019
@plbossart could we just change all period_elapsed calls to be deferred (despite the stream state)? So could there be some critical delay to userspace position reporting? The code would be much cleaner and we could be sure not to hit timeout with ipc... looking at pcm_lib.c snd_pcm_update_state() we just can't rely solely on stream state if there's stop coming or not. for e.g. xrun will issue stop also, but it is not dependent on stream state. And I'm not sure other "hidden" paths that might call back ipc from this irq handling.
xiulipan commentedon May 7, 2019
@stevyan @DarrenxWang
Please help to check #873 and this issue still exists on BYT.
I can see that my first playback will be failed and hang for long time. Maybe #873 is a duplicate for this.
I think this should be fixed by #849, maybe some regression happen.
Please confirm and @keyonjie to check.
[-][BYT][ipc position update feature]IPC timeout when stop playback[/-][+][BYT][ipc position update feature]IPC timed out when stop playback[/+]wenqingfu commentedon May 22, 2019
@Jiangxinx @stevyan please retest if thesofproject/sof#1451 fixes this too along with #873
Jiangxinx commentedon May 23, 2019
From daily test report, this issue is fixed by thesofproject/sof#1451 .
Test recipe
date: 2019-05-23
sof (master): 56b8776
linux (topic/sof-dev): 4d1fc20
topology: sof-byt-rt5651.tplg & sof-byt-nocodec.tplg
KVM: x86: Drop WARNs that assert a triple fault never "escapes" from L2