[BYT][ipc position update feature]IPC timed out when stop playback

[libinyang]

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:

1. run aplay -Dhw:0,n file.wav
2. press ctrl+c to stop (or wait for playback finish)

[libinyang]

dmesg.txt

[ranj063]

@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]

@libinyang please attached sof-logger logs also.

[libinyang]

@ranj063 Yes, I think there may be something wrong to handle STOP in driver or FW. It seems to be just the STOP related.

@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.

[xiulipan]

@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

[ 62.124326] sof-audio-pci 0000:00:1f.3: ipc rx: 0x600a0000: GLB_STREAM_MSG: POSITION
// irq_thread A is wake
[ 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
// irq_handler B comes, try to wake irq_thread B. But failed due to irq_thread is awaken by irq A
[ 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
// IPC irq B timeout
[ 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
// irq_thread A is handled, thread is free to be waken
[ 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
// irq_handler C try to wake thread
[ 62.427159] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
// irq_thread C waked.
[ 62.427211] sof-audio-pci 0000:00:1f.3: pcm: close stream 1 dir 0

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_ptr0

linux/sound/core/pcm_lib.c

Line 262 in 85c400e

static int snd_pcm_update_hw_ptr0(struct snd_pcm_substream *substream,

Any idea? @xun2z and me will try to dig into that tomorrow

[tlauda]

@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]

@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]

@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]

@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

[ 62.124326] sof-audio-pci 0000:00:1f.3: ipc rx: 0x600a0000: GLB_STREAM_MSG: POSITION
// irq_thread A is wake
[ 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
// irq_handler B comes, try to wake irq_thread B. But failed due to irq_thread is awaken by irq A

@xiulipan how did you know about this? are you saying handling to A is blocking at snd_pcm_update_hw_ptr0?

[ 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
// IPC irq B timeout
[ 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
// irq_thread A is handled, thread is free to be waken
[ 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
// irq_handler C try to wake thread
[ 62.427159] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
// irq_thread C waked.
[ 62.427211] sof-audio-pci 0000:00:1f.3: pcm: close stream 1 dir 0

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_ptr0`

[linux/sound/core/pcm_lib.c](https://github.com/thesofproject/linux/blob/85c400e2385902920a033f0f26b476b485a56a14/sound/core/pcm_lib.c#L262)

Line 262 in [85c400e](/thesofproject/linux/commit/85c400e2385902920a033f0f26b476b485a56a14)

 static int snd_pcm_update_hw_ptr0(struct snd_pcm_substream *substream, 
Any idea? @xun2z and me will try to dig into that tomorrow

[xiulipan]

@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.