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

[Mirza Krak]

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

-- 
Med Vänliga Hälsningar / Best Regards

Mirza Krak