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

[Takashi Iwai]

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?

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.


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