[alsa-devel] snd_pcm_open() taking very long, starting from kernel 4.17
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?
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
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@alsa-project.org http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
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@alsa-project.org http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
On 12/17/18 5: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?
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.
I found out that this is actually due to a change in the debian kernel configuration. Starting from version 4.17, the kernel is configured with CONFIG_SND_HDA_POWER_SAVE_DEFAULT=1 (was =0 before).
I could confirm that this is what makes snd_pcm_open() take much more time.
I opened a bug at https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=917906.
Thanks for the support!
Arnaud
participants (2)
-
Arnaud Rebillout -
Takashi Iwai