[alsa-devel] snd_pcm_open() taking very long, starting from kernel 4.17

[Arnaud Rebillout]

On 12/17/18 4:54 PM, Takashi Iwai wrote:
> On Fri, 14 Dec 2018 18:36:11 +0100,
> Arnaud Rebillout wrote:
>>   Dear ALSA maintainers,
>>
>> I noticed big change in how long `snd_pcm_open()` takes, between kernel 4.16
>> and 4.17. With a kernel 4.16, this function consistently returns in less
>> than 1
>> millisecond, with occasional, but rare, peaks that go up to 25ms. While with
>> kernel 4.17 and above, I measure an average of 40ms, with frequent peaks
>> to 1s.
>> The maximum I measured was 3 seconds!
>>
>> Is this change known, intended? Or is it a regression?
> If this happens at opening the PCM stream, it's likely a stall in
> runtime PM resume by some reason.  But I have no idea what actually
> broke.
>
> Are you sure that it's a kernel regression, i.e. this doesn't happen
> at all when booting the old kernel on the same system?

100% sure.

> If yes, the best would be to perform bisection.  At least it'd be
> helpful to narrow the regression a bit.
>
> And, this might be a known issue; I remember some report about the
> long runtime PM resume on Dell XPS, which I can't see on other
> machines.  So it might be device-specific.

OK I will try more Debian kernels to narrow down two version, I think it
will be between 4.16 and 4.17. Then I will try to find my way compiling
a kernel :)

Thanks for the reply, I'll be back when I have smoe more details

  Arnaud

> thanks,
>
> Takashi
>
>
>> Please read below for more details, thanks.
>>
>> ----
>>
>>   The long story
>>
>> Starting with kernel 4.17, I started to experience frequent lags on
>> mylaptop,
>> which seemed to happen in the terminal, while hitting the TAB for
>> completion.
>> I clearly didn't experience this behavior with 4.16. Later on, 4.18 was
>> released, I tried it: same issue. So I kept using the kernel 4.16.
>>
>> So it took me a while to investigate this issue. What happens is that
>> the GNOME
>> terminal, or Emacs, might generate event sounds when you hit tab, or
>> something.
>> This happen fairly often (you know, this kind of bell sound), it's very
>> annoying, so usually the first thing I'd do is to disable these sounds.
>>
>> Turns out that, even when disabled, this sounds are still generated, because
>> GNOME doesn't really disable it, it just mutes it [1].
>>
>> After understanding that, I tracked down how these event sounds are
>> generated.
>> As incredible as it seems, it all happens synchronously, from the
>> calling app,
>> through GTK, then mutter, then libcanberra, and ultimately the call ends
>> up in
>> pulseaudio.  Pulseaudio is the one calling `snd_pcm_open()`, so that's
>> where I
>> did my measurements.
>>
>> Like I said, it's all synchronous, so when the call takes 3 seconds to
>> return,
>> I wait 3 seconds in front of my screen :) Pulseaudio has a plugin
>> (enabled by
>> default in my distrib) `suspend-on-idle`, which means that it closes the
>> soundcard connection on inactivity, and re-opens it again with
>> `snd_pcm_open()`
>> when a sound is played.
>>
>> So, to sum that up: during a normal workday on my laptop, PA will constantly
>> close the soundcard connection (due to the suspend-on-idle plugin), and
>> open it
>> again (due to event sounds generated by GNOME, despite being disabled).
>> And all
>> of that synchronously, in the GTK mainloop. While this could go
>> un-noticed for
>> a while, starting with kernel 4.17, the call `snd_pcm_open()` might take
>> up to
>> 3 seconds to return, and it made my system almost unusable.
>>
>> I found out that it's possible to disable these event sounds finally,
>> it's just
>> not possible through the GNOME settings, it needs to be done from the
>> command-
>> line. So I live happy, no problem for me. I'm merely reporting the
>> problem, as
>> you might be interested.
>>
>> [1] https://gitlab.gnome.org/GNOME/gnome-control-center/issues/259
>>
>> ----
>>
>>   Some hardware details:
>>
>> $ sudo dmidecode | grep 'System Information' -A 2
>> System Information
>>     Manufacturer: Dell Inc.
>>     Product Name: XPS 13 9360
>>
>> $ cat /proc/asound/cards
>>  0 [PCH            ]: HDA-Intel - HDA Intel PCH
>>                       HDA Intel PCH at 0xdc428000 irq 144
>>
>> $ aplay --list-devices
>> **** List of PLAYBACK Hardware Devices ****
>> card 0: PCH [HDA Intel PCH], device 0: ALC3246 Analog [ALC3246 Analog]
>>   Subdevices: 1/1
>>   Subdevice #0: subdevice #0
>> card 0: PCH [HDA Intel PCH], device 3: HDMI 0 [HDMI 0]
>>   Subdevices: 1/1
>>   Subdevice #0: subdevice #0
>> card 0: PCH [HDA Intel PCH], device 7: HDMI 1 [HDMI 1]
>>   Subdevices: 1/1
>>   Subdevice #0: subdevice #0
>> card 0: PCH [HDA Intel PCH], device 8: HDMI 2 [HDMI 2]
>>   Subdevices: 1/1
>>   Subdevice #0: subdevice #0
>> card 0: PCH [HDA Intel PCH], device 9: HDMI 3 [HDMI 3]
>>   Subdevices: 1/1
>>   Subdevice #0: subdevice #0
>> card 0: PCH [HDA Intel PCH], device 10: HDMI 4 [HDMI 4]
>>   Subdevices: 1/1
>>   Subdevice #0: subdevice #0
>>
>> $ sudo lspci -v | grep -i audio -A 7
>> 00:1f.3 Audio device: Intel Corporation Sunrise Point-LP HD Audio (rev
>> 21) (prog-if 80)
>>     Subsystem: Dell Sunrise Point-LP HD Audio
>>     Flags: bus master, fast devsel, latency 32, IRQ 128
>>     Memory at dc428000 (64-bit, non-prefetchable) [size=16K]
>>     Memory at dc400000 (64-bit, non-prefetchable) [size=64K]
>>     Capabilities: [50] Power Management version 3
>>     Capabilities: [60] MSI: Enable+ Count=1/1 Maskable- 64bit+
>>     Kernel driver in use: snd_hda_intel
>>     Kernel modules: snd_hda_intel, snd_soc_skl
>>
>> ----
>>
>> Feel free to ask more details, I'd be glad to help.
>>
>> Best regards,
>>
>>   Arnaud
>>
>> _______________________________________________
>> Alsa-devel mailing list
>> Alsa-devel at alsa-project.org
>> http://mailman.alsa-project.org/mailman/listinfo/alsa-devel