[alsa-devel] Bad PCM stream after a suspend/resume cycle

[Takashi Iwai]

On Fri, 12 Jan 2018 14:36:45 +0100,
Mirza Krak wrote:
> 
> On 12 January 2018 at 11:26, Takashi Iwai <tiwai at suse.de> wrote:
> > On Thu, 11 Jan 2018 10:06:12 +0100,
> > Mirza Krak wrote:
> >>
> >> Hi.
> >>
> >> I have a quite simple problem really (simple test-case at least).
> >>
> >> Following describes the test case:
> >>
> >> $ aplay test.wav
> >>
> >> # While the .wav is playing suspend the system
> >> $ systemctl suspend
> >>
> >> # When system is resumed I get the following error on my aplay command
> >> aplay: pcm_write:2030: write error: File descriptor in bad state
> >>
> >> I was expecting for the playback to resume.
> >>
> >> I did some debugging using "aplay" and what I can see that happens
> >> before the EBADFD error is that the "writei_func()" returns a positive
> >> value once which results in a call to "snd_pcm_wait()" and on the next
> >> "writei_func()" call -EBADFD is returned.
> >>
> >> I would expect a -ESTRPIPE error which should then result in that the
> >> PCM stream to be "resumed" (according to documentation at least). I
> >> have tried "forcing" a call to "suspend()" on the first write error in
> >> aplay after system is resumed and it actually works, kinda. The
> >> playback is resumed even-though the "snd_pcm_resume()" call returns an
> >> error.
> >>
> >> I have not worked much with the sound subsystem before and I am having
> >> a hard time following all the call paths to see who/what is to blame
> >> for this behavior. Maybe it expected to work like this? And I do not
> >> know if this is only on my SoC or if this is a generic sound problem.
> >
> > It's no generic issue but specific to platform / SoC driver
> > implementation.
> 
> Thank you for the answer.
> 
> I have done some more digging.
> 
> With the help of the amazing "printf" I was able to capture the below sequence
> 
> [  124.133306] snd_pcm_common_ioctl [2873]: command=0xc0844123
> [  124.133307] snd_pcm_common_ioctl [2875]
> [  124.133308] snd_pcm_common_ioctl [2880]
> [  124.133309] snd_pcm_common_ioctl [2886]
> [  124.133313] snd_pcm_ioctl
> [  124.133314] snd_pcm_common_ioctl [2873]: command=0x400c4150
> [  124.133315] snd_pcm_common_ioctl [2875]
> [  124.133317] snd_pcm_common_ioctl [2880]
> [  124.133318] snd_pcm_common_ioctl [2886]
> [  124.133319] snd_pcm_xferi_frames_ioctl
> [  124.133320] __snd_pcm_lib_xfer
> [  124.133322] __snd_pcm_lib_xfer [2186]
> [  124.133326] __snd_pcm_lib_xfer [2195]
> [  124.133367] wait_for_avail [1851]
> [  124.188805] Freezing user space processes ...
> [  124.188915] wait_for_avail [1906]
> [  124.188917] __snd_pcm_lib_xfer [2257]
> [  124.188919] __snd_pcm_lib_xfer [2262]: xfer: 1523
> [  124.274008] (elapsed 0.085 seconds) done.
> [  124.283733] OOM killer disabled.
> [  124.287323] Freezing remaining freezable tasks ... (elapsed 0.001
> seconds) done.
> [  124.382438] Rockchip I2S suspend/stop/pause called
> [  124.588929] vdd_cpu: No configuration
> [  124.593028] vdd_gpu: No configuration
> [  124.598441] Disabling non-boot CPUs ...
> [  124.763337] Enabling non-boot CPUs ...
> [  124.768869] CPU1 is up
> [  124.772788] CPU2 is up
> [  124.776722] CPU3 is up
> [  125.496875] rk_gmac-dwmac ff290000.ethernet: init for RGMII
> [  125.771693] usb 1-1: reset high-speed USB device number 2 using dwc2
> [  126.142175] OOM killer enabled.
> [  126.145679] Restarting tasks ...
> [  126.145897] snd_pcm_ioctl
> [  126.148204] done.
> [  126.154667] snd_pcm_common_ioctl [2873]: command=0xc0844123
> aplay: return writei_func: 1523
> [  126.154669] snd_pcm_common_ioctl [2875]
> aplay: pcm_write:2025: [  126.154671] snd_pcm_common_ioctl [2880]
> EAGAIN: 1523
> aplay: call writei_func
> aplay: return writei_func[  126.154672] snd_pcm_common_ioctl [2886]
> : -77
> aplay: pcm_write:2035: write error: File descriptor in ba[
> 126.168420] snd_pcm_ioctl
> d state
> [  126.168422] snd_pcm_common_ioctl [2873]: command=0xc0844123
> [  126.168423] snd_pcm_common_ioctl [2875]
> [  126.168424] snd_pcm_common_ioctl [2880]
> [  126.168425] snd_pcm_common_ioctl [2886]
> [  126.168435] snd_pcm_ioctl
> [  126.168437] snd_pcm_common_ioctl [2873]: command=0xc0844123
> [  126.168438] snd_pcm_common_ioctl [2875]
> [  126.168439] snd_pcm_common_ioctl [2880]
> [  126.168440] snd_pcm_common_ioctl [2886]
> [  126.168470] snd_pcm_ioctl
> [  126.168472] snd_pcm_common_ioctl [2873]: command=0xc0844123
> [  126.168473] snd_pcm_common_ioctl [2875]
> [  126.168474] snd_pcm_common_ioctl [2880]
> [  126.168476] snd_pcm_common_ioctl [2886]
> [  126.168478] snd_pcm_ioctl
> [  126.168480] snd_pcm_common_ioctl [2873]: command=0x00004143
> [  126.168481] snd_pcm_common_ioctl [2875]
> [  126.168482] snd_pcm_common_ioctl [2880]
> [  126.168483] snd_pcm_common_ioctl [2886]
> [  126.168491] snd_pcm_ioctl
> [  126.168493] snd_pcm_common_ioctl [2873]: command=0x00004112
> [  126.168494] snd_pcm_common_ioctl [2875]
> [  126.168495] snd_pcm_common_ioctl [2880]
> [  126.168496] snd_pcm_common_ioctl [2886]
> [  126.168870] snd_pcm_set_state: state: 0
> [  126.303963] PM: suspend exit
> 
> The interesting takeaways here are:
> 
> - It seems that it always "freezes" in the __snd_pcm_lib_xfer (I guess
> that is expected as my system currently only does a audio playback and
> the rest is idle)
>     - This means that aplay has a write in progress that it will
> resume when system is woken
>     - My hardware does not support "pause", because the DMA does not
> support this
>     - "__snd_pcm_lib_xfer" will return a positive value indicating
> "partial write" when system is suspended, guessing due to DMA being
> torn down.
> - When "aplay" resumes it will get an positive return value on the
> write command which will trigger a re-write with the chunk remaining
> to write
>     - And here is my problem I believe, because the stream has been
> suspended I am not allowed to write to it again until it has been
> restored/recovered, which in turn triggers the -EBADFD error.
> 
> Above maybe is what is expected since there seem to be some limitation
> in hardware, but I would greatly appropriate any pointers in how this
> should be handled. Is there something that can be done in platform /
> SoC code to notify the sound/core to handle this "more
> smoothly"(underrun error?)
> 
> or is my only option only to catch the -EBADFD error and restart the
> playback "manually".

The EBADFD is already indicating a fatal error, and something is wrong
in the driver.  Basically the driver should suspend the stream via
snd_pcm_suspend*() call in the PM resume ops.  Most likely your driver
misses that.

That said, it's specific to your using driver, and you'd need to take
a look at that code there.


Takashi