Pulseaudio causes ~10 second login delays

[daboross]

I've got my system running pretty quickly with Gentoo, but logging is currently around 5 times as slow as booting up.

I suspect the problem is pulseaudio, and I've looked at a few other posts (1, 2), but I'm really not sure where to go from here.

I set log-level to debug and log-time to true in /etc/pulse/daemon.conf to get more information, but this is about as far as I know what to do. Here's what I got from journalctl, cut off when logging in completes:

https://gist.githubusercontent.com/daboross/3aeb6917be2b902b42777b907a48d6a4/raw/2a9b254b3b3ef43f90d2c2495845ad49b5288650/gistfile1.txt

Here's my full system log (from boot up to starting firefox):

https://gist.githubusercontent.com/daboross/5bca3d8a17505ad87dc993b7d13fa00c/raw/cfa764b87220232b84a3feebd954282a73b02a9c/journalctl.txt

[Logicien]

Why do you suspect Pulseaudio to be the cause of 10 seconds login delay? By enabling Pulseaudio debugging logs it take a lot of space in the logs but this do not mean it is the cause of the problem. I haven't check all the Pulseaudio lines in the logs but I haven't seen any issue with it.

Pulseaudio is started per user login. I have arrive to the conclusion that it is better to not touch the global default configuration in /etc/pulse. It can be done per user only. It can other process, graphical services who cause the delay. Gnome do not show the desktop fast.
_________________
Paul

[daboross]

You're right that I really don't know exactly what it is, but one thing I've tried is logging off and logging back in without restarting the computer. If I just directly log in again, the delay doesn't occur. If I go into tty1 and kill all of my user processes though before logging on, it does delay - by elimination I tried killing each running service separately, and determined that if I kill just pluseaudio, the delay occurs again, and if I kill all but pluseaudio there is no delay.

Sorry, to be completely clear, I am using gnome-session, but not the gnome desktop environment. Rather just gnome-session with i3 as the window manager. When I login to a pure i3 session without starting gnome-session, it starts fairly instantly.

[Logicien]

On a first login, all applications need to be load in memory from the hard drive. On subsequent logins, all aplicaitions are already in memory unless you have few memory. The delay is shorter.

According with what you say, if you kill Pulseaudio only, the delay exist and if you kill all applications but not Pulseaudio, there is no delay. This mean that Pulseaudio is not the cause of the delay and you must look to something else. When you use I3 only it will launch less applications than Gnome.
_________________
Paul

[daboross]

Sorry, I don't exactly follow.

Logging in is fairly instant if I've already logged in, and I don't kill pulseaudio.

The delay only happens when pulseaudio is not already running when I log in. I would assume this means that the delay is caused by pulseaudio being started fresh - something that only needs to happen when pulseaudio wasn't already running (I killed it, or I restarted).

Could you elaborate on how this means the opposite?

Edit: I've tried to reproduce this by just killing & starting pulseaudio when I'm already logged in, and it does seem to take ~13 seconds to start pulseaudio even when logged in.

[Logicien]

I reverse the sense of what you did. You are right Pulseaudio can be the cause of the delay. Have-you try to setup it with Pavucontrol? The most important is that your X session work fine. Reduce the time it take to show the desktop is about optimisation.

Try to prevent Pulseaudio from being started with your X session to see if it reduce the delay compare when it is started using the same desktop environment.
_________________
Paul

[daboross]

Ah, ok.

I have pavucontrol installed, I haven't done any real configuration in it though.

[Ant P.]

You can use app-benchmarks/bootchart2 to see what's really causing the delay. Pulseaudio shouldn't be blocking anything at startup but maybe you have something in your xsession scripts that does things backwards.

[daboross]

Ah, thank you for that!

It does seem to contain a lot of useful information, not much of which I'm knowing how to interpret. I guess 'gnome-session-binary' is taking a long time to start?

I'm still kind of wondering why having pulseaudio previously running would stop it from having the delay, though I guess as you say my login scripts may be messed up.

Here's a link to the png file generated, I would appreciate any insight that I may not be able to get from this: http://i.imgur.com/Tss8Xow.png.

Edit: Here's another bootchart: http://i.imgur.com/dSB2xkf.png - it does somewhat look like pulseaudio is blocking it in this, but I'm not entirely sure how to read it.

This is all the session scripts/configuration files I have:

[Ant P.]

I'm not sure if pulseaudio has something to do with it, but I notice something else in those graphs (particularly visible in the first): the rest of the desktop seems to be waiting on gvfsd.

I wonder if that's actually delaying pulseaudio startup, which in turn blocks something trying to play a login sound...

[daboross]

I hadn't noticed gvfsd, but that's totally happening - yeah. I don't have any login sounds enabled, but I dug around in dconf and set 'org.gnome.desktop.sound event-sounds' to false, in case that was causing it.

After that it still seems to happen, but I made another bootchart with logging in as quickly as possible, and starting a terminal as soon as the desktop loaded:
http://i.imgur.com/LAXxHwk.png.

For comparison, I restarted and went directly into an i3 session without gnome, then started gnome-terminal. Interestingly, the delay happened this time when gnome-terminal was started, I assume because I didn't have gnome-session already running? Here's the bootchart: http://i.imgur.com/tFUZBOn.png.

[daboross]

Since just killing and restarting pulseaudio takes this long, I'm inclined to believe that it isn't directly waiting on gvfsd, but just that the last non-idle period of gvfsd is when all the applications start.

If I read it correctly, the program making the graph only includes each program up until the last non-idle CPU usage - if this is the case, it would make sense that gvfsd appears to stop when everything starts - one of those applications is using gvfsd, and the gvfsd stopping there is caused by the desktop starting, not the other way around.

Does that fit with your understanding of bootchart2?

[Ant P.]

bootchart2 uses the kernel audit log functionality, so it should be accurate there. Hard for me to guess what's going on because I don't use Gnome software.

[daboross]

Would maybe the kernel audit log functionality work that way then?

There are a few other things that just don't reach to the end of the graph, which I do know for sure kept running, like nm-applet, SpiderOakONE, redshift, breakit, and X. All of those have a blue bar at the end, and then don't reach to the end of the graph - but I know for sure that they are still running at the end of the graph.

[daboross]

I managed to fix this, at least temporarily.

My workaround now is to have a line `sh -c "sleep 2; killall pulseaudio &> /dev/null" & disown` run at the start of the xsession, and then `exec --no-startup-id "sh -c 'pulseaudio -D'"` in my i3 config file. This successfully allows my desktop to start in 2 seconds rather than 30, and although I don't have audio for the first 30 seconds, that's good enough for me.

To note: I added the `sh -c "sleep 2; killall pulseaudio &> /dev/null" & disown` line in my `/usr/local/bin/gnome-i3-session-fix.sh` file, which I do remember creating at some point that I got from reading a blog post about running gnome-session and i3 in parallel. To be honest, I have no idea where this file is referenced, though I assumed it was run at the start of my xsession, and that assumption seems to be correct enough.

If anyone has any idea as to the actual cause of pulseaudio taking so long to load, or why gnome-session is waiting for the initial instance to start up before starting i3, I would love to have more input. This is a workaround, and although it works it does avoid the real problem.

Edit:

to be clear, this didn't actually fix my problem. I had also, in addition to editing these things, copied /etc/pulse/client.conf to ~/.config/pulse/client.conf, and changed

[Fitzcarraldo]

I'm not sure if it will be of any help in your case (I'm using KDE Plasma 5), but you could try the steps below. PulseAudio should then only be auto-spawned on demand at the point in time when the libpulse* libraries are first used (see http://unix.stackexchange.com/questions/204522/how-does-pulseaudio-start#245799). I have done the following and audio still works, albeit I have not made any timings for comparison.

1. Stop X Windows from launching PulseAudio automatically at start-up:

[daboross]

Fitzcarraido, thank you for that!

Turns out that setting autospawn = no fixed the problem! I didn't have to re-set daemon-binary or remove pulseaudio.desktop, but I can try those.

At the moment I still do start pulseaudio manually via my i3 config though, because without pulseaudio running it seems no sound ever switches to my alternate (usb) speakers when I plug them in, and that's a feature that's nice to have.

Thank you for posting that!