Skip to content

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

Closed

Description

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

Activity

  1. libinyang commented on Apr 10, 2019

    @libinyang
    Author
  2. ranj063 commented on Apr 11, 2019

    @ranj063
    Collaborator

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

  3. keyonjie commented on Apr 11, 2019

    @keyonjie

    @libinyang please attached sof-logger logs also.

  4. libinyang commented on Apr 11, 2019

    @libinyang
    Author

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

  5. changed the title [-][WHL] IPC timeout when stop playback[/-] [+][WHL][BYT][ipc position update feature]IPC timeout when stop playback[/+] on Apr 11, 2019
  6. xiulipan commented on Apr 11, 2019

    @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

    static int snd_pcm_update_hw_ptr0(struct snd_pcm_substream *substream,

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

  7. tlauda commented on Apr 11, 2019

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

  8. xiulipan commented on Apr 11, 2019

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

  9. xun2z commented on Apr 11, 2019

    @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

  10. keyonjie commented on Apr 12, 2019

    @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
    
  11. xiulipan commented on Apr 12, 2019

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

  12. added
    bugSomething isn't working
    BYTApplies to Baytrail platform
    on Apr 12, 2019
  13. xun2z commented on Apr 12, 2019

    @xun2z
    @@ -462,10 +472,12 @@ static int snd_pcm_update_hw_ptr0(struct snd_pcm_substream *substream,
                    snd_BUG_ON(crossed_boundary != 1);
                    runtime->hw_ptr_wrap += runtime->boundary;
            }
    -
    +       pcm_err(substream->pcm,"snd_pcm_update_hw_ptr16");
            update_audio_tstamp(substream, &curr_tstamp, &audio_tstamp);
    -
    -       return snd_pcm_update_state(substream, runtime);
    +       pcm_err(substream->pcm,"snd_pcm_update_hw_ptr17");
    +       ret = snd_pcm_update_state(substream, runtime);
    +       pcm_err(substream->pcm,"snd_pcm_update_hw_ptr18");
    +       return ret;
    
    [  598.069014] sof-audio-acpi 80860F28:01: ipc rx: 0x600a0001: GLB_STREAM_MSG: POSITION
    [  598.069053] sof-audio-acpi 80860F28:01: posn : host 0xfb40 dai 0xbef80 wall 0x254c5cb
    [  598.069069] sof-audio-acpi 80860F28:01: xun: ipc_period_elapsed1
    [  598.069108] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr0
    [  598.069144] sof-audio-acpi 80860F28:01: PCM: stream 0 dir 0 DMA position 16080 DAI position 195552
    [  598.069160] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr1
    [  598.069186] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr5
    [  598.069210] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr6
    [  598.069235] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr7
    [  598.069260] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr8
    [  598.069285] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr9
    [  598.069310] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr10
    [  598.069334] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr11
    [  598.069359] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr14
    [  598.069384] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr15
    [  598.069409] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr16
    [  598.069434] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr17
    [  598.069464] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 0
    [  598.069491] sof-audio-acpi 80860F28:01: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
    [  598.375533] sof-audio-acpi 80860F28:01: error: ipc timed out for 0x60050000 size 12
    [  598.376223] sof-audio-acpi 80860F28:01: error: unexpected fault 0x600a0001 trace 0x00000000
    [  598.376267] sof-audio-acpi 80860F28:01: error: waking up any trace sleepers
    [  598.376336]  Low Latency: ASoC: trigger FE failed -110
    [  598.376426] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr18
    [  598.376476] sof-audio-acpi 80860F28:01: xun: ipc_period_elapsed25
    [  598.376519] sof-audio-acpi 80860F28:01: ipc rx done: 0x600a0001: GLB_STREAM_MSG: POSITION
    
  14. keyonjie commented on Apr 12, 2019

    @keyonjie
    @@ -462,10 +472,12 @@ static int snd_pcm_update_hw_ptr0(struct snd_pcm_substream *substream,
                    snd_BUG_ON(crossed_boundary != 1);
                    runtime->hw_ptr_wrap += runtime->boundary;
            }
    -
    +       pcm_err(substream->pcm,"snd_pcm_update_hw_ptr16");
            update_audio_tstamp(substream, &curr_tstamp, &audio_tstamp);
    -
    -       return snd_pcm_update_state(substream, runtime);
    +       pcm_err(substream->pcm,"snd_pcm_update_hw_ptr17");
    +       ret = snd_pcm_update_state(substream, runtime);
    +       pcm_err(substream->pcm,"snd_pcm_update_hw_ptr18");
    +       return ret;
    [  598.069014] sof-audio-acpi 80860F28:01: ipc rx: 0x600a0001: GLB_STREAM_MSG: POSITION
    [  598.069053] sof-audio-acpi 80860F28:01: posn : host 0xfb40 dai 0xbef80 wall 0x254c5cb
    [  598.069069] sof-audio-acpi 80860F28:01: xun: ipc_period_elapsed1
    [  598.069108] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr0
    [  598.069144] sof-audio-acpi 80860F28:01: PCM: stream 0 dir 0 DMA position 16080 DAI position 195552
    [  598.069160] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr1
    [  598.069186] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr5
    [  598.069210] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr6
    [  598.069235] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr7
    [  598.069260] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr8
    [  598.069285] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr9
    [  598.069310] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr10
    [  598.069334] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr11
    [  598.069359] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr14
    [  598.069384] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr15
    [  598.069409] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr16
    [  598.069434] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr17
    [  598.069464] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 0
    [  598.069491] sof-audio-acpi 80860F28:01: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
    

    so this trigger stop is initiated by ALSA, maybe xrun happen here. need debug into snd_pcm_update_state() for more infos.

    [ 598.375533] sof-audio-acpi 80860F28:01: error: ipc timed out for 0x60050000 size 12

    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.

    [ 598.376223] sof-audio-acpi 80860F28:01: error: unexpected fault 0x600a0001 trace 0x00000000
    [ 598.376267] sof-audio-acpi 80860F28:01: error: waking up any trace sleepers
    [ 598.376336] Low Latency: ASoC: trigger FE failed -110
    [ 598.376426] sof_rt5682 sof_rt5682: snd_pcm_update_hw_ptr18
    [ 598.376476] sof-audio-acpi 80860F28:01: xun: ipc_period_elapsed25
    [ 598.376519] sof-audio-acpi 80860F28:01: ipc rx done: 0x600a0001: GLB_STREAM_MSG: POSITION

  15. 6 remaining items

  16. xiulipan commented on Apr 15, 2019

    @xiulipan

    @libinyang
    Yes, the bug for IPC STOP timeout is related to the IPC position update.

  17. juimonen commented on Apr 15, 2019

    @juimonen

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

  18. juimonen commented on Apr 15, 2019

    @juimonen

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

  19. xiulipan commented on Apr 15, 2019

    @xiulipan

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

  20. Jiangxinx commented on Apr 16, 2019

    @Jiangxinx

    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

  21. xiulipan commented on Apr 16, 2019

    @xiulipan

    @Jiangxinx Not fixed on BYT (only IPC position update user).
    Please help to check if any more issue if PulseAudio is enabled.

  22. juimonen commented on Apr 17, 2019

    @juimonen

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

  23. xiulipan commented on May 7, 2019

    @xiulipan

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

  24. changed the title [-][BYT][ipc position update feature]IPC timeout when stop playback[/-] [+][BYT][ipc position update feature]IPC timed out when stop playback[/+] on May 7, 2019
  25. wenqingfu commented on May 22, 2019

    @wenqingfu

    @Jiangxinx @stevyan please retest if thesofproject/sof#1451 fixes this too along with #873

  26. Jiangxinx commented on May 23, 2019

    @Jiangxinx

    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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

BYTApplies to Baytrail platformIPC timeoutIPC timeout observedbugSomething isn't working

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions