Gentoo Forums
Gentoo Forums
Gentoo Forums
Quick Search: in
Pulseaudio causes ~10 second login delays
View unanswered posts
View posts from last 24 hours

 
Reply to topic    Gentoo Forums Forum Index Desktop Environments
View previous topic :: View next topic  
Author Message
daboross
n00b
n00b


Joined: 25 Dec 2015
Posts: 12

PostPosted: Sun Nov 27, 2016 8:16 pm    Post subject: Pulseaudio causes ~10 second login delays Reply with quote

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
Back to top
View user's profile Send private message
Logicien
Veteran
Veteran


Joined: 16 Sep 2005
Posts: 1360
Location: Montréal

PostPosted: Mon Nov 28, 2016 1:17 am    Post subject: Reply with quote

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
Back to top
View user's profile Send private message
daboross
n00b
n00b


Joined: 25 Dec 2015
Posts: 12

PostPosted: Mon Nov 28, 2016 2:18 am    Post subject: Reply with quote

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.
Back to top
View user's profile Send private message
Logicien
Veteran
Veteran


Joined: 16 Sep 2005
Posts: 1360
Location: Montréal

PostPosted: Mon Nov 28, 2016 4:07 am    Post subject: Reply with quote

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
Back to top
View user's profile Send private message
daboross
n00b
n00b


Joined: 25 Dec 2015
Posts: 12

PostPosted: Mon Nov 28, 2016 5:55 am    Post subject: Reply with quote

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.

Code:

daboross:/home/daboross/
$ pulseaudio -k && time pulseaudio -D
(   0.000|   0.000) I: [pulseaudio] main.c: Daemon startup successful.
pulseaudio -D  0.00s user 0.00s system 0% cpu 13.074 total
daboross:/home/daboross/
$
Back to top
View user's profile Send private message
Logicien
Veteran
Veteran


Joined: 16 Sep 2005
Posts: 1360
Location: Montréal

PostPosted: Mon Nov 28, 2016 6:31 am    Post subject: Reply with quote

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
Back to top
View user's profile Send private message
daboross
n00b
n00b


Joined: 25 Dec 2015
Posts: 12

PostPosted: Mon Nov 28, 2016 6:45 am    Post subject: Reply with quote

Ah, ok.

I have pavucontrol installed, I haven't done any real configuration in it though.
Back to top
View user's profile Send private message
Ant P.
Watchman
Watchman


Joined: 18 Apr 2009
Posts: 5591

PostPosted: Mon Nov 28, 2016 9:16 am    Post subject: Reply with quote

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.
Back to top
View user's profile Send private message
daboross
n00b
n00b


Joined: 25 Dec 2015
Posts: 12

PostPosted: Mon Nov 28, 2016 10:10 am    Post subject: Reply with quote

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:

Code:

$ cat /usr/share/xsessions/gnome-i3.desktop
[Desktop Entry]
Name=i3-gnome
Comment=A GNOME session using the i3 window manager.
Exec=gnome-session-i3
TryExec=gnome-session
Icon=
Type=Application

$ cat /usr/local/bin/gnome-session-i3
#!/bin/sh
gnome-session --session=i3 "$@"

$ cat /usr/share/gnome-session/sessions/i3.session
[GNOME Session]
Name=i3
RequiredComponents=i3;gnome-settings-daemon

$ cat /usr/local/bin/gnome-i3-session-fix.sh
#!/bin/bash

# https://github.com/lvillani/i3-gnome/blob/master/session/i3-gnome

# Register with gnome-session so that it does not kill the whole session thinking it is dead.
if [[ ! -z "$DESKTOP_AUTOSTART_ID" ]]; then
    dbus-send --print-reply --session --dest=org.gnome.SessionManager "/org/gnome/SessionManager" org.gnome.SessionManager.RegisterClient "string:i3-gnome" "string:$DESKTOP_AUTOSTART_ID"
fi

# Fix the missing cursor problem
dconf write /org/gnome/settings-daemon/plugins/cursor/active false

# Disable Gnome Shell's App Menu, so that lost menu items are shown again.
gsettings set org.gnome.settings-daemon.plugins.xsettings overrides '@a{sv} {"Gtk/ShellShowsAppMenu": <int32 0>}'


I also have the following things auto-opening with i3:
Code:

exec_always --no-startup-id gnome-i3-session-fix.sh
exec_always --no-startup-id ~/.bin/backdrop.sh
exec --no-startup-id dbus-launch nm-applet
exec --no-startup-id breakit
exec --no-startup-id redshift-gtk-autostart.sh
exec --no-startup-id "sh -c 'sleep 5; exec SpiderOakONE'"
exec --no-startup-id "sh -c 'systemd-cat echo i3 logged in as $USER.'"
Back to top
View user's profile Send private message
Ant P.
Watchman
Watchman


Joined: 18 Apr 2009
Posts: 5591

PostPosted: Mon Nov 28, 2016 7:14 pm    Post subject: Reply with quote

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...
Back to top
View user's profile Send private message
daboross
n00b
n00b


Joined: 25 Dec 2015
Posts: 12

PostPosted: Mon Nov 28, 2016 8:25 pm    Post subject: Reply with quote

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.
Back to top
View user's profile Send private message
daboross
n00b
n00b


Joined: 25 Dec 2015
Posts: 12

PostPosted: Mon Dec 05, 2016 4:02 am    Post subject: Reply with quote

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?
Back to top
View user's profile Send private message
Ant P.
Watchman
Watchman


Joined: 18 Apr 2009
Posts: 5591

PostPosted: Mon Dec 05, 2016 1:29 pm    Post subject: Reply with quote

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.
Back to top
View user's profile Send private message
daboross
n00b
n00b


Joined: 25 Dec 2015
Posts: 12

PostPosted: Tue Dec 06, 2016 5:45 am    Post subject: Reply with quote

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.
Back to top
View user's profile Send private message
daboross
n00b
n00b


Joined: 25 Dec 2015
Posts: 12

PostPosted: Thu Jan 19, 2017 6:49 am    Post subject: Reply with quote

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
Code:

; autospawn = yes

to
Code:

autospawn = no

similarly to what Fitzcarraldo suggests below.

I guess I had done this a while ago and did not believe it fixed my problem, but removing the edits from `/usr/local/bin/gnome-i3-session-fix.sh` and my i3 config made no difference, it seems the pulse client.conf file was the true fix.[/code]


Last edited by daboross on Fri Jan 20, 2017 1:56 am; edited 2 times in total
Back to top
View user's profile Send private message
Fitzcarraldo
Veteran
Veteran


Joined: 30 Aug 2008
Posts: 1631
Location: United Kingdom

PostPosted: Fri Jan 20, 2017 1:15 am    Post subject: Reply with quote

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:

Code:
# mv /etc/xdg/autostart/pulseaudio.desktop /home/fitzcarraldo/


2. Edit /etc/pulse/client.conf and change the following two commented lines:

Code:
; autospawn = yes
; daemon-binary = /usr/bin/pulseaudio

to the following two uncommented lines:

Code:
autospawn = no
daemon-binary = /bin/true

_________________
Clevo W230SS: amd64 OpenRC elogind nvidia-drivers & xf86-video-intel.
Compal NBLB2: ~amd64 OpenRC elogind xf86-video-ati. Dual boot Win 7 Pro 64-bit.
KDE on both.

Fitzcarraldo's blog
Back to top
View user's profile Send private message
daboross
n00b
n00b


Joined: 25 Dec 2015
Posts: 12

PostPosted: Fri Jan 20, 2017 1:41 am    Post subject: Reply with quote

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!
Back to top
View user's profile Send private message
Display posts from previous:   
Reply to topic    Gentoo Forums Forum Index Desktop Environments All times are GMT
Page 1 of 1

 
Jump to:  
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum