Bad PCM stream after a suspend/resume cycle

Bad PCM stream after a suspend/resume cycle

[Mirza Krak]

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.

Information about my system:

Using a RK3288 SoC (RK3288-FireFly board) with 4.14.13 Linux kernel
(latest stable).

alsa-lib version 1.1.4.1

Playback using I2S

$ cat /proc/asound/cards
 0 [I2S            ]: I2S - I2S
                      I2S
$ cat /proc/asound/card0/pcm0p/info
card: 0
device: 0
subdevice: 0
stream: PLAYBACK
id: Audio es8328-hifi-analog-0
name:
subname: subdevice #0
class: 0
subclass: 0
subdevices_count: 1
subdevices_avail: 1

Let me know if there is additional information that I need to provide.

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

Mirza Krak

_______________________________________________
Linux-rockchip mailing list
Linux-rockchip@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-rockchip

Re: Bad PCM stream after a suspend/resume cycle

[Takashi Iwai]

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.


Takashi

> Information about my system:
> 
> Using a RK3288 SoC (RK3288-FireFly board) with 4.14.13 Linux kernel
> (latest stable).
> 
> alsa-lib version 1.1.4.1
> 
> Playback using I2S
> 
> $ cat /proc/asound/cards
>  0 [I2S            ]: I2S - I2S
>                       I2S
> $ cat /proc/asound/card0/pcm0p/info
> card: 0
> device: 0
> subdevice: 0
> stream: PLAYBACK
> id: Audio es8328-hifi-analog-0
> name:
> subname: subdevice #0
> class: 0
> subclass: 0
> subdevices_count: 1
> subdevices_avail: 1
> 
> Let me know if there is additional information that I need to provide.
> 
> -- 
> Med Vänliga Hälsningar / Best Regards
> 
> Mirza Krak
> _______________________________________________
> Alsa-devel mailing list
> Alsa-devel@alsa-project.org
> http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: Bad PCM stream after a suspend/resume cycle

[Mirza Krak]

On 12 January 2018 at 11:26, Takashi Iwai <tiwai@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
_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: 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@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

Re: Bad PCM stream after a suspend/resume cycle

[Mirza Krak]

On 12 January 2018 at 19:04, Takashi Iwai <tiwai@suse.de> wrote:
> On Fri, 12 Jan 2018 14:36:45 +0100,
> Mirza Krak wrote:
>>

< snip >

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

Thank you for you patience with me.

I have looked further in to my hardware drivers and I can not really
see any faults here.

But I did some further testing and applying the following diff on
aplay "resolves" the problem (v1.1.4 of alsa-utils):

diff --git a/aplay/aplay.c b/aplay/aplay.c
index f793c82..040cec1 100644
--- a/aplay/aplay.c
+++ b/aplay/aplay.c
@@ -2020,6 +2020,8 @@ static ssize_t pcm_write(u_char *data, size_t count)
                if (test_position)
                        do_test_position();
                if (r == -EAGAIN || (r >= 0 && (size_t)r < count)) {
+                       if (snd_pcm_state(handle) == SND_PCM_STATE_SUSPENDED)
+                               suspend();
                        if (!test_nowait)
                                snd_pcm_wait(handle, 100);
                } else if (r == -EPIPE) {

Which means that there is no error in regard to suspending the stream
as it properly reports this when checked.

My problem is that this condition:

    (r >= 0 && (size_t)r < count)

Is always true after a suspend/resume cycle. Which normally does not
result in a "resume" call from aplay nor from snd_pcm_recover, which
means that it will try to write data to a suspended stream which
results in -EBADFD due to this (from alsa-lib):

snd_pcm_sframes_t snd_pcm_writei(snd_pcm_t *pcm, const void *buffer,
snd_pcm_uframes_t size)
{
    < snip >

    if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
        return -EBADFD;
    return _snd_pcm_writei(pcm, buffer, size);
}

Because SUSPENDED is not part of the P_STATE_RUNNABLE, which maybe it should be?

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

Mirza Krak
_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: Bad PCM stream after a suspend/resume cycle

[Takashi Iwai]

On Wed, 17 Jan 2018 15:08:27 +0100,
Mirza Krak wrote:
> 
> On 12 January 2018 at 19:04, Takashi Iwai <tiwai@suse.de> wrote:
> > On Fri, 12 Jan 2018 14:36:45 +0100,
> > Mirza Krak wrote:
> >>
> 
> < snip >
> 
> >
> > 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.
> 
> Thank you for you patience with me.
> 
> I have looked further in to my hardware drivers and I can not really
> see any faults here.
> 
> But I did some further testing and applying the following diff on
> aplay "resolves" the problem (v1.1.4 of alsa-utils):
> 
> diff --git a/aplay/aplay.c b/aplay/aplay.c
> index f793c82..040cec1 100644
> --- a/aplay/aplay.c
> +++ b/aplay/aplay.c
> @@ -2020,6 +2020,8 @@ static ssize_t pcm_write(u_char *data, size_t count)
>                 if (test_position)
>                         do_test_position();
>                 if (r == -EAGAIN || (r >= 0 && (size_t)r < count)) {
> +                       if (snd_pcm_state(handle) == SND_PCM_STATE_SUSPENDED)
> +                               suspend();
>                         if (!test_nowait)
>                                 snd_pcm_wait(handle, 100);
>                 } else if (r == -EPIPE) {
> 
> Which means that there is no error in regard to suspending the stream
> as it properly reports this when checked.
> 
> My problem is that this condition:
> 
>     (r >= 0 && (size_t)r < count)
> 
> Is always true after a suspend/resume cycle. Which normally does not
> result in a "resume" call from aplay nor from snd_pcm_recover, which
> means that it will try to write data to a suspended stream which
> results in -EBADFD due to this (from alsa-lib):
> 
> snd_pcm_sframes_t snd_pcm_writei(snd_pcm_t *pcm, const void *buffer,
> snd_pcm_uframes_t size)
> {
>     < snip >
> 
>     if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
>         return -EBADFD;
>     return _snd_pcm_writei(pcm, buffer, size);
> }
> 
> Because SUSPENDED is not part of the P_STATE_RUNNABLE, which maybe it should be?

OK, that's a bug in alsa-lib, then.  The sanity check is good, but it
returns the inconsistent error code that doesn't match with the PCM
state.

Could you try the patch below?


thanks,

Takashi

-- 8< --
From: Takashi Iwai <tiwai@suse.de>
Subject: [PATCH] pcm: Return the consistent error code for unexpected PCM
 states

Some PCM functions have the sanity check of the expected PCM states,
and most of them return -EBADFD if the current state doesn't match.
This is bad for some programs like aplay that expect the function
returning a proper code corresponding to the state, e.g. -ESTRPIPE for
the suspend.

This patch is an attempt to address such inconsistencies.  The sanity
checker bad_pcm_state() now returns the error code instead of bool, so
that the caller can pass the returned code as is.  And it calls a new
helper, pcm_state_to_error(), for obtaining the error code to certain
known PCM error state.

While we're at it, use the new pcm_state_to_error() for simplifying
the existing code to retrieve the error code, too.

Signed-off-by: Takashi Iwai <tiwai@suse.de>
---
 src/pcm/pcm.c | 170 +++++++++++++++++++++++++++++++++-------------------------
 1 file changed, 98 insertions(+), 72 deletions(-)

diff --git a/src/pcm/pcm.c b/src/pcm/pcm.c
index e9ebf383c31b..69d7d66500ea 100644
--- a/src/pcm/pcm.c
+++ b/src/pcm/pcm.c
@@ -657,6 +657,21 @@ playback devices.
 #include "pcm_local.h"
 
 #ifndef DOC_HIDDEN
+/* return specific error codes for known bad PCM states */
+static int pcm_state_to_error(snd_pcm_state_t state)
+{
+	switch (state) {
+	case SND_PCM_STATE_XRUN:
+		return -EPIPE;
+	case SND_PCM_STATE_SUSPENDED:
+		return -ESTRPIPE;
+	case SND_PCM_STATE_DISCONNECTED:
+		return -ENODEV;
+	default:
+		return 0;
+	}
+}
+
 #define P_STATE(x)	(1U << SND_PCM_STATE_ ## x)
 #define P_STATE_RUNNABLE (P_STATE(PREPARED) | \
 			  P_STATE(RUNNING) | \
@@ -667,9 +682,18 @@ playback devices.
 /* check whether the PCM is in the unexpected state */
 static int bad_pcm_state(snd_pcm_t *pcm, unsigned int supported_states)
 {
+	snd_pcm_state_t state;
+	int err;
+
 	if (pcm->own_state_check)
 		return 0; /* don't care, the plugin checks by itself */
-	return !(supported_states & (1U << snd_pcm_state(pcm)));
+	state = snd_pcm_state(pcm);
+	if (supported_states & (1U << state))
+		return 0; /* OK */
+	err = pcm_state_to_error(state);
+	if (err < 0)
+		return err;
+	return -EBADFD;
 }
 #endif
 
@@ -1143,8 +1167,9 @@ int snd_pcm_prepare(snd_pcm_t *pcm)
 		SNDMSG("PCM not set up");
 		return -EIO;
 	}
-	if (bad_pcm_state(pcm, ~P_STATE(DISCONNECTED)))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, ~P_STATE(DISCONNECTED));
+	if (err < 0)
+		return err;
 	snd_pcm_lock(pcm);
 	err = pcm->fast_ops->prepare(pcm->fast_op_arg);
 	snd_pcm_unlock(pcm);
@@ -1191,8 +1216,9 @@ int snd_pcm_start(snd_pcm_t *pcm)
 		SNDMSG("PCM not set up");
 		return -EIO;
 	}
-	if (bad_pcm_state(pcm, P_STATE(PREPARED)))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, P_STATE(PREPARED));
+	if (err < 0)
+		return err;
 	snd_pcm_lock(pcm);
 	err = __snd_pcm_start(pcm);
 	snd_pcm_unlock(pcm);
@@ -1221,9 +1247,10 @@ int snd_pcm_drop(snd_pcm_t *pcm)
 		SNDMSG("PCM not set up");
 		return -EIO;
 	}
-	if (bad_pcm_state(pcm, P_STATE_RUNNABLE | P_STATE(SETUP) |
-			     P_STATE(SUSPENDED)))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, P_STATE_RUNNABLE | P_STATE(SETUP) |
+			    P_STATE(SUSPENDED));
+	if (err < 0)
+		return err;
 	snd_pcm_lock(pcm);
 	err = pcm->fast_ops->drop(pcm->fast_op_arg);
 	snd_pcm_unlock(pcm);
@@ -1247,13 +1274,16 @@ int snd_pcm_drop(snd_pcm_t *pcm)
  */
 int snd_pcm_drain(snd_pcm_t *pcm)
 {
+	int err;
+
 	assert(pcm);
 	if (CHECK_SANITY(! pcm->setup)) {
 		SNDMSG("PCM not set up");
 		return -EIO;
 	}
-	if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, P_STATE_RUNNABLE);
+	if (err < 0)
+		return err;
 	/* lock handled in the callback */
 	return pcm->fast_ops->drain(pcm->fast_op_arg);
 }
@@ -1279,8 +1309,9 @@ int snd_pcm_pause(snd_pcm_t *pcm, int enable)
 		SNDMSG("PCM not set up");
 		return -EIO;
 	}
-	if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, P_STATE_RUNNABLE);
+	if (err < 0)
+		return err;
 	snd_pcm_lock(pcm);
 	err = pcm->fast_ops->pause(pcm->fast_op_arg, enable);
 	snd_pcm_unlock(pcm);
@@ -1301,14 +1332,16 @@ int snd_pcm_pause(snd_pcm_t *pcm, int enable)
 snd_pcm_sframes_t snd_pcm_rewindable(snd_pcm_t *pcm)
 {
 	snd_pcm_sframes_t result;
+	int err;
 
 	assert(pcm);
 	if (CHECK_SANITY(! pcm->setup)) {
 		SNDMSG("PCM not set up");
 		return -EIO;
 	}
-	if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, P_STATE_RUNNABLE);
+	if (err < 0)
+		return err;
 	snd_pcm_lock(pcm);
 	result = pcm->fast_ops->rewindable(pcm->fast_op_arg);
 	snd_pcm_unlock(pcm);
@@ -1327,6 +1360,7 @@ snd_pcm_sframes_t snd_pcm_rewindable(snd_pcm_t *pcm)
 snd_pcm_sframes_t snd_pcm_rewind(snd_pcm_t *pcm, snd_pcm_uframes_t frames)
 {
 	snd_pcm_sframes_t result;
+	int err;
 
 	assert(pcm);
 	if (CHECK_SANITY(! pcm->setup)) {
@@ -1335,8 +1369,9 @@ snd_pcm_sframes_t snd_pcm_rewind(snd_pcm_t *pcm, snd_pcm_uframes_t frames)
 	}
 	if (frames == 0)
 		return 0;
-	if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, P_STATE_RUNNABLE);
+	if (err < 0)
+		return err;
 	snd_pcm_lock(pcm);
 	result = pcm->fast_ops->rewind(pcm->fast_op_arg, frames);
 	snd_pcm_unlock(pcm);
@@ -1357,14 +1392,16 @@ snd_pcm_sframes_t snd_pcm_rewind(snd_pcm_t *pcm, snd_pcm_uframes_t frames)
 snd_pcm_sframes_t snd_pcm_forwardable(snd_pcm_t *pcm)
 {
 	snd_pcm_sframes_t result;
+	int err;
 
 	assert(pcm);
 	if (CHECK_SANITY(! pcm->setup)) {
 		SNDMSG("PCM not set up");
 		return -EIO;
 	}
-	if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, P_STATE_RUNNABLE);
+	if (err < 0)
+		return err;
 	snd_pcm_lock(pcm);
 	result = pcm->fast_ops->forwardable(pcm->fast_op_arg);
 	snd_pcm_unlock(pcm);
@@ -1387,6 +1424,7 @@ snd_pcm_sframes_t snd_pcm_forward(snd_pcm_t *pcm, snd_pcm_uframes_t frames)
 #endif
 {
 	snd_pcm_sframes_t result;
+	int err;
 
 	assert(pcm);
 	if (CHECK_SANITY(! pcm->setup)) {
@@ -1395,8 +1433,9 @@ snd_pcm_sframes_t snd_pcm_forward(snd_pcm_t *pcm, snd_pcm_uframes_t frames)
 	}
 	if (frames == 0)
 		return 0;
-	if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, P_STATE_RUNNABLE);
+	if (err < 0)
+		return err;
 	snd_pcm_lock(pcm);
 	result = pcm->fast_ops->forward(pcm->fast_op_arg, frames);
 	snd_pcm_unlock(pcm);
@@ -1425,6 +1464,8 @@ use_default_symbol_version(__snd_pcm_forward, snd_pcm_forward, ALSA_0.9.0rc8);
  */ 
 snd_pcm_sframes_t snd_pcm_writei(snd_pcm_t *pcm, const void *buffer, snd_pcm_uframes_t size)
 {
+	int err;
+
 	assert(pcm);
 	assert(size == 0 || buffer);
 	if (CHECK_SANITY(! pcm->setup)) {
@@ -1435,8 +1476,9 @@ snd_pcm_sframes_t snd_pcm_writei(snd_pcm_t *pcm, const void *buffer, snd_pcm_ufr
 		SNDMSG("invalid access type %s", snd_pcm_access_name(pcm->access));
 		return -EINVAL;
 	}
-	if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, P_STATE_RUNNABLE);
+	if (err < 0)
+		return err;
 	return _snd_pcm_writei(pcm, buffer, size);
 }
 
@@ -1461,6 +1503,8 @@ snd_pcm_sframes_t snd_pcm_writei(snd_pcm_t *pcm, const void *buffer, snd_pcm_ufr
  */ 
 snd_pcm_sframes_t snd_pcm_writen(snd_pcm_t *pcm, void **bufs, snd_pcm_uframes_t size)
 {
+	int err;
+
 	assert(pcm);
 	assert(size == 0 || bufs);
 	if (CHECK_SANITY(! pcm->setup)) {
@@ -1471,8 +1515,9 @@ snd_pcm_sframes_t snd_pcm_writen(snd_pcm_t *pcm, void **bufs, snd_pcm_uframes_t
 		SNDMSG("invalid access type %s", snd_pcm_access_name(pcm->access));
 		return -EINVAL;
 	}
-	if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, P_STATE_RUNNABLE);
+	if (err < 0)
+		return err;
 	return _snd_pcm_writen(pcm, bufs, size);
 }
 
@@ -1497,6 +1542,8 @@ snd_pcm_sframes_t snd_pcm_writen(snd_pcm_t *pcm, void **bufs, snd_pcm_uframes_t
  */ 
 snd_pcm_sframes_t snd_pcm_readi(snd_pcm_t *pcm, void *buffer, snd_pcm_uframes_t size)
 {
+	int err;
+
 	assert(pcm);
 	assert(size == 0 || buffer);
 	if (CHECK_SANITY(! pcm->setup)) {
@@ -1507,8 +1554,9 @@ snd_pcm_sframes_t snd_pcm_readi(snd_pcm_t *pcm, void *buffer, snd_pcm_uframes_t
 		SNDMSG("invalid access type %s", snd_pcm_access_name(pcm->access));
 		return -EINVAL;
 	}
-	if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, P_STATE_RUNNABLE);
+	if (err < 0)
+		return err;
 	return _snd_pcm_readi(pcm, buffer, size);
 }
 
@@ -1533,6 +1581,8 @@ snd_pcm_sframes_t snd_pcm_readi(snd_pcm_t *pcm, void *buffer, snd_pcm_uframes_t
  */ 
 snd_pcm_sframes_t snd_pcm_readn(snd_pcm_t *pcm, void **bufs, snd_pcm_uframes_t size)
 {
+	int err;
+
 	assert(pcm);
 	assert(size == 0 || bufs);
 	if (CHECK_SANITY(! pcm->setup)) {
@@ -1543,8 +1593,9 @@ snd_pcm_sframes_t snd_pcm_readn(snd_pcm_t *pcm, void **bufs, snd_pcm_uframes_t s
 		SNDMSG("invalid access type %s", snd_pcm_access_name(pcm->access));
 		return -EINVAL;
 	}
-	if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, P_STATE_RUNNABLE);
+	if (err < 0)
+		return err;
 	return _snd_pcm_readn(pcm, bufs, size);
 }
 
@@ -2695,18 +2746,12 @@ int snd_pcm_wait(snd_pcm_t *pcm, int timeout)
 /* locked version */
 int __snd_pcm_wait_in_lock(snd_pcm_t *pcm, int timeout)
 {
+	int err;
+
 	if (!snd_pcm_may_wait_for_avail_min(pcm, snd_pcm_mmap_avail(pcm))) {
 		/* check more precisely */
-		switch (__snd_pcm_state(pcm)) {
-		case SND_PCM_STATE_XRUN:
-			return -EPIPE;
-		case SND_PCM_STATE_SUSPENDED:
-			return -ESTRPIPE;
-		case SND_PCM_STATE_DISCONNECTED:
-			return -ENODEV;
-		default:
-			return 1;
-		}
+		err = pcm_state_to_error(__snd_pcm_state(pcm));
+		return err < 0 ? err : 1;
 	}
 	return snd_pcm_wait_nocheck(pcm, timeout);
 }
@@ -2753,16 +2798,8 @@ int snd_pcm_wait_nocheck(snd_pcm_t *pcm, int timeout)
 			return err;
 		if (revents & (POLLERR | POLLNVAL)) {
 			/* check more precisely */
-			switch (__snd_pcm_state(pcm)) {
-			case SND_PCM_STATE_XRUN:
-				return -EPIPE;
-			case SND_PCM_STATE_SUSPENDED:
-				return -ESTRPIPE;
-			case SND_PCM_STATE_DISCONNECTED:
-				return -ENODEV;
-			default:
-				return -EIO;
-			}
+			err = pcm_state_to_error(__snd_pcm_state(pcm));
+			return err < 0 ? err : -EIO;
 		}
 	} while (!(revents & (POLLIN | POLLOUT)));
 #if 0 /* very useful code to test poll related problems */
@@ -7010,8 +7047,9 @@ int snd_pcm_mmap_begin(snd_pcm_t *pcm,
 {
 	int err;
 
-	if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, P_STATE_RUNNABLE);
+	if (err < 0)
+		return err;
 	snd_pcm_lock(pcm);
 	err = __snd_pcm_mmap_begin(pcm, areas, offset, frames);
 	snd_pcm_unlock(pcm);
@@ -7106,9 +7144,11 @@ snd_pcm_sframes_t snd_pcm_mmap_commit(snd_pcm_t *pcm,
 				      snd_pcm_uframes_t frames)
 {
 	snd_pcm_sframes_t result;
+	int err;
 
-	if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
-		return -EBADFD;
+	err = bad_pcm_state(pcm, P_STATE_RUNNABLE);
+	if (err < 0)
+		return err;
 	snd_pcm_lock(pcm);
 	result = __snd_pcm_mmap_commit(pcm, offset, frames);
 	snd_pcm_unlock(pcm);
@@ -7204,17 +7244,10 @@ snd_pcm_sframes_t snd_pcm_read_areas(snd_pcm_t *pcm, const snd_pcm_channel_area_
 		case SND_PCM_STATE_DRAINING:
 		case SND_PCM_STATE_PAUSED:
 			break;
-		case SND_PCM_STATE_XRUN:
-			err = -EPIPE;
-			goto _end;
-		case SND_PCM_STATE_SUSPENDED:
-			err = -ESTRPIPE;
-			goto _end;
-		case SND_PCM_STATE_DISCONNECTED:
-			err = -ENODEV;
-			goto _end;
 		default:
-			err = -EBADFD;
+			err = pcm_state_to_error(state);
+			if (!err)
+				err = -EBADFD;
 			goto _end;
 		}
 		avail = __snd_pcm_avail_update(pcm);
@@ -7280,17 +7313,10 @@ snd_pcm_sframes_t snd_pcm_write_areas(snd_pcm_t *pcm, const snd_pcm_channel_area
 			if (err < 0)
 				goto _end;
 			break;
-		case SND_PCM_STATE_XRUN:
-			err = -EPIPE;
-			goto _end;
-		case SND_PCM_STATE_SUSPENDED:
-			err = -ESTRPIPE;
-			goto _end;
-		case SND_PCM_STATE_DISCONNECTED:
-			err = -ENODEV;
-			goto _end;
 		default:
-			err = -EBADFD;
+			err = pcm_state_to_error(state);
+			if (!err)
+				err = -EBADFD;
 			goto _end;
 		}
 		avail = __snd_pcm_avail_update(pcm);
-- 
2.15.1

Re: Bad PCM stream after a suspend/resume cycle

[Mirza Krak]

On 17 January 2018 at 16:05, Takashi Iwai <tiwai@suse.de> wrote:
> On Wed, 17 Jan 2018 15:08:27 +0100,
> Mirza Krak wrote:
>>
>> On 12 January 2018 at 19:04, Takashi Iwai <tiwai@suse.de> wrote:
>> > On Fri, 12 Jan 2018 14:36:45 +0100,
>> > Mirza Krak wrote:
>> >>
>>
>> < snip >
>>
>> >
>> > 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.
>>
>> Thank you for you patience with me.
>>
>> I have looked further in to my hardware drivers and I can not really
>> see any faults here.
>>
>> But I did some further testing and applying the following diff on
>> aplay "resolves" the problem (v1.1.4 of alsa-utils):
>>
>> diff --git a/aplay/aplay.c b/aplay/aplay.c
>> index f793c82..040cec1 100644
>> --- a/aplay/aplay.c
>> +++ b/aplay/aplay.c
>> @@ -2020,6 +2020,8 @@ static ssize_t pcm_write(u_char *data, size_t count)
>>                 if (test_position)
>>                         do_test_position();
>>                 if (r == -EAGAIN || (r >= 0 && (size_t)r < count)) {
>> +                       if (snd_pcm_state(handle) == SND_PCM_STATE_SUSPENDED)
>> +                               suspend();
>>                         if (!test_nowait)
>>                                 snd_pcm_wait(handle, 100);
>>                 } else if (r == -EPIPE) {
>>
>> Which means that there is no error in regard to suspending the stream
>> as it properly reports this when checked.
>>
>> My problem is that this condition:
>>
>>     (r >= 0 && (size_t)r < count)
>>
>> Is always true after a suspend/resume cycle. Which normally does not
>> result in a "resume" call from aplay nor from snd_pcm_recover, which
>> means that it will try to write data to a suspended stream which
>> results in -EBADFD due to this (from alsa-lib):
>>
>> snd_pcm_sframes_t snd_pcm_writei(snd_pcm_t *pcm, const void *buffer,
>> snd_pcm_uframes_t size)
>> {
>>     < snip >
>>
>>     if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
>>         return -EBADFD;
>>     return _snd_pcm_writei(pcm, buffer, size);
>> }
>>
>> Because SUSPENDED is not part of the P_STATE_RUNNABLE, which maybe it should be?
>
> OK, that's a bug in alsa-lib, then.  The sanity check is good, but it
> returns the inconsistent error code that doesn't match with the PCM
> state.
>
> Could you try the patch below?

Yeah, the patch resolved my issues and the stream is resumed/reset
after suspend properly. Tested with aplay and with custom application
that uses snd_pcm_recover to handle return values from write.

You can add my:

Tested-by: Mirza Krak <mirza.krak@gmail.com>

If you like.

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

Mirza Krak
_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: Bad PCM stream after a suspend/resume cycle

[Takashi Iwai]

On Thu, 18 Jan 2018 09:49:53 +0100,
Mirza Krak wrote:
> 
> On 17 January 2018 at 16:05, Takashi Iwai <tiwai@suse.de> wrote:
> > On Wed, 17 Jan 2018 15:08:27 +0100,
> > Mirza Krak wrote:
> >>
> >> On 12 January 2018 at 19:04, Takashi Iwai <tiwai@suse.de> wrote:
> >> > On Fri, 12 Jan 2018 14:36:45 +0100,
> >> > Mirza Krak wrote:
> >> >>
> >>
> >> < snip >
> >>
> >> >
> >> > 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.
> >>
> >> Thank you for you patience with me.
> >>
> >> I have looked further in to my hardware drivers and I can not really
> >> see any faults here.
> >>
> >> But I did some further testing and applying the following diff on
> >> aplay "resolves" the problem (v1.1.4 of alsa-utils):
> >>
> >> diff --git a/aplay/aplay.c b/aplay/aplay.c
> >> index f793c82..040cec1 100644
> >> --- a/aplay/aplay.c
> >> +++ b/aplay/aplay.c
> >> @@ -2020,6 +2020,8 @@ static ssize_t pcm_write(u_char *data, size_t count)
> >>                 if (test_position)
> >>                         do_test_position();
> >>                 if (r == -EAGAIN || (r >= 0 && (size_t)r < count)) {
> >> +                       if (snd_pcm_state(handle) == SND_PCM_STATE_SUSPENDED)
> >> +                               suspend();
> >>                         if (!test_nowait)
> >>                                 snd_pcm_wait(handle, 100);
> >>                 } else if (r == -EPIPE) {
> >>
> >> Which means that there is no error in regard to suspending the stream
> >> as it properly reports this when checked.
> >>
> >> My problem is that this condition:
> >>
> >>     (r >= 0 && (size_t)r < count)
> >>
> >> Is always true after a suspend/resume cycle. Which normally does not
> >> result in a "resume" call from aplay nor from snd_pcm_recover, which
> >> means that it will try to write data to a suspended stream which
> >> results in -EBADFD due to this (from alsa-lib):
> >>
> >> snd_pcm_sframes_t snd_pcm_writei(snd_pcm_t *pcm, const void *buffer,
> >> snd_pcm_uframes_t size)
> >> {
> >>     < snip >
> >>
> >>     if (bad_pcm_state(pcm, P_STATE_RUNNABLE))
> >>         return -EBADFD;
> >>     return _snd_pcm_writei(pcm, buffer, size);
> >> }
> >>
> >> Because SUSPENDED is not part of the P_STATE_RUNNABLE, which maybe it should be?
> >
> > OK, that's a bug in alsa-lib, then.  The sanity check is good, but it
> > returns the inconsistent error code that doesn't match with the PCM
> > state.
> >
> > Could you try the patch below?
> 
> Yeah, the patch resolved my issues and the stream is resumed/reset
> after suspend properly. Tested with aplay and with custom application
> that uses snd_pcm_recover to handle return values from write.
> 
> You can add my:
> 
> Tested-by: Mirza Krak <mirza.krak@gmail.com>
> 
> If you like.

Good to hear, I pushed the fix to git tree now.


thanks,

Takashi