Slow login -- waiting for bluetooth?

[chconnor]

Hi - recently upgraded to 16.04; when I log in, there is a ~20+ second delay after entering the password, before the desktop appears. Apparently there are reported bugs (against 15.10 ?) regarding async calls to a bluetooth service that block login. I see in journalctl:

...
Jun 25 10:35:24 machinename org.kde.KScreen[10587]: kscreen: Primary output changed from KScreen::Output(Id: 68 , Name: "HDMI1" ) ( "HDMI1" ) to KScreen::Output(Id: 68 , Name: "HDMI1" ) ( "HDMI1" )
Jun 25 10:35:47 machinename dbus[957]: [system] Failed to activate service 'org.bluez': timed out

...note the 23 second delay before the second line. This is apparently my issue. Does anyone know a workaround? I've had slow login issues since 14.10, and was never able to find any cause; I'm hoping this one can be fixed! All the bug reports I find report it as "fixed" and don't mention workarounds...

I tried disabling bluetooth in the services GUI for kubuntu; that shifted the error to a similar pulseaudio error where it times out trying to talk to bluetooth. (Really irritating that bluetooth is relevant at all to anything ever, since I don't even have it or use it on this desktop...) If I have to install/configure bluetooth somehow just to get these things to not wait for it, I can accept that. I just want to log in efficiently. :-)

Thanks!

[GreyGeek]

Open a console and issue
systemd-analyze blame
and paste the output in a posting here.

[chconnor]

Thanks GG -- nothing obviously wrong in there?

          2.305s networking.service
          2.057s sendmail.service
          1.939s bups1.mount
          1.707s proj3.mount
          1.197s apache2.service
          1.067s aud2.mount
          1.015s mysql.service
           849ms proj1.mount
           794ms proj2.mount
           607ms aud1.mount
           301ms dev-sda2.device
           281ms dev-disk-by\x2duuid-cbcc27d1\x2dd0bb\x2d459c\x2dae56\x2d1d4ea447eda3.swap
           252ms winbind.service
           248ms nmbd.service
           226ms gpu-manager.service
           219ms samba-ad-dc.service
           209ms ModemManager.service
           204ms accounts-daemon.service
           176ms bups2.mount
           162ms systemd-logind.service
           155ms timidity.service
           135ms apport.service
           133ms smbd.service
           132ms irqbalance.service                                                                                                                                                                              
           125ms saslauthd.service                                                                                                                                                                               
           116ms gdomap.service                                                                                                                                                                                  
           106ms alsa-restore.service                                                                                                                                                                            
           101ms pppd-dns.service                                                                                                                                                                                
            95ms vboxdrv.service                                                                                                                                                                                 
            92ms NetworkManager-wait-online.service                                                                                                                                                              
            91ms systemd-user-sessions.service                                                                                                                                                                   
            90ms rsyslog.service                                                                                                                                                                                 
            89ms minidlna.service                                                                                                                                                                                
            74ms NetworkManager.service                                                                                                                                                                          
            66ms thermald.service                                                                                                                                                                                
            66ms udisks2.service                                                                                                                                                                                 
            63ms upower.service                                                                                                                                                                                  
            62ms sysstat.service                                                                                                                                                                                 
            58ms vmware-USBArbitrator.service                                                                                                                                                                    
            54ms avahi-daemon.service                                                                                                                                                                            
            46ms systemd-timesyncd.service                                                                                                                                                                       
            46ms apparmor.service                                                                                                                                                                                
            44ms systemd-udevd.service                                                                                                                                                                           
            41ms systemd-udev-trigger.service                                                                                                                                                                    
            39ms systemd-modules-load.service                                                                                                                                                                    
            34ms systemd-journald.service                                                                                                                                                                        
            34ms kmod-static-nodes.service                                                                                                                                                                       
            31ms binfmt-support.service                                                                                                                                                                          
            29ms [email]systemd-fsck@dev-disk-by\x2duuid-a488db6e\x2d3bc3\x2d492c\x2db5e9\x2df381f441531a.servic[/email]e                                                                                                       
            28ms ufw.service                                                                                                                                                                                     
            26ms dev-mqueue.mount                                                                                                                                                                                
            25ms systemd-hostnamed.service                                                                                                                                                                       
            23ms ssh.service                                                                                                                                                                                     
            22ms sys-kernel-debug.mount                                                                                                                                                                          
            22ms [email]user@1000.servic[/email]e                                                                                                                                                                               
            21ms console-setup.service                                                                                                                                                                           
            20ms grub-common.service                                                                                                                                                                             
            19ms fast.mount                                                                                                                                                                                      
            17ms [email]user@127.servic[/email]e                                                                                                                                                                                
            16ms systemd-update-utmp.service                                                                                                                                                                     
            16ms colord.service                                                                                                                                                                                  
            15ms win.mount                                                                                                                                                                                       
            14ms lm-sensors.service                                                                                                                                                                              
            14ms systemd-random-seed.service                                                                                                                                                                     
            14ms dev-hugepages.mount                                                                                                                                                                             
            13ms pulseaudio.service                                                                                                                                                                              
            12ms [email]systemd-backlight@backlight:acpi_video0.servic[/email]e                                                                                                                                                 
            12ms home.mount                                                                                                                                                                                      
            12ms wol.service                                                                                                                                                                                     
            12ms plymouth-read-write.service                                                                                                                                                                     
            11ms polkitd.service                                                                                                                                                                                 
            11ms systemd-journal-flush.service                                                                                                                                                                   
            11ms plymouth-quit.service                                                                                                                                                                           
            10ms ondemand.service                                                                                                                                                                                
             8ms systemd-remount-fs.service                                                                                                                                                                      
             8ms systemd-sysctl.service                                                                                                                                                                          
             8ms rtkit-daemon.service                                                                                                                                                                            
             7ms dns-clean.service                                                                                                                                                                               
             7ms vboxautostart-service.service                                                                                                                                                                   
             7ms console-kit-daemon.service                                                                                                                                                                      
             7ms systemd-tmpfiles-setup-dev.service                                                                                                                                                              
             7ms resolvconf.service                                                                                                                                                                              
             6ms systemd-tmpfiles-setup.service                                                                                                                                                                  
             6ms console-kit-log-system-start.service                                                                                                                                                            
             5ms snapd.socket                                                                                                                                                                                    
             5ms proc-sys-fs-binfmt_misc.mount                                                                                                                                                                   
             4ms rc-local.service                                                                                                                                                                                
             4ms vboxballoonctrl-service.service                                                                                                                                                                 
             4ms vboxweb-service.service                                                                                                                                                                         
             2ms ureadahead-stop.service
             2ms systemd-update-utmp-runlevel.service
             1ms sddm.service
             1ms sys-fs-fuse-connections.mount

Incidentally, here are some possibly-relevant links I found:

https://bugs.launchpad.net/ubuntu/+s...m/+bug/1509334
https://bugs.kde.org/show_bug.cgi?id=354230
https://www.reddit.com/r/linux/comme...ry_slow_login/

...kinda seems like there are still blocking calls to bluez?

[GreyGeek]

No, there's not. You have a clean boot which, as you say, takes about 20 seconds. Org.bluez is broken on my installation too, and adds about 20 seconds to Plasma5's boot time for it to time out. I don't use Bluetooth either but I ignored its boot problem. It's after midnight so I'll look into it tomorrow.

[chconnor]

Great, thanks! I look forward to whatever you discover. I'll poke around tomorrow myself as well.

[GreyGeek]

Well, it looks like the problem WAS related to the Bluetooth service bug in 15.10, but that was fixed in 16.04and the fix was backported to 15.10. However, in one of the 16.04 updates a regression occurred which is not related to Bluetooth but to a persistent KDE splash screen.

https://bugs.launchpad.net/ubuntu/+s...m/+bug/1584604

So, apparently, disabling the Bluetooth service will not fix this regression. I'm going to investigate farther.

BTW, on a cold boot the apt.daily.service took 40 seconds but on a warm boot doesn't appear.

systemd-analyze blame
         40.003s apt-daily.service
         20.657s dev-sda1.device
         14.584s systemd-udevd.service
          6.119s NetworkManager-wait-online.service
          5.767s postfix.service
          4.228s NetworkManager.service
...

Dmesg showed

[   79.584093] audit: type=1400 audit(1466944745.504:25): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld-akonadi" name="/etc/ld.so.preload" pid=2334 comm="mysqld-akonadi" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
[   [B]79.666501[/B]] audit: type=1400 audit(1466944745.588:26): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld-akonadi///usr/sbin/mysqld" name="/etc/ld.so.preload" pid=2334 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
[B][  337.420591] audit: type=1400 audit(1466945003.341:27): apparmor="DENIED" operation="open" profile="/usr/sbin/cupsd" name="/etc/ld.so.preload" pid=2888 comm="cupsd" requested_mask="r" denied_mask="r" fsuid=0 ouid=0[/B]

I have a ton of apparmor error msgs. If its not working I will disable it.

I used the kcmshell5 splashscreen command to call up the splash screen dialog and set it to "None". Here is what happened.

:~$ kcmshell5 splashscreen
Error loading plugin "kcm_splashscreen" "The shared library was not found." 
Plugin search paths are ("/usr/lib/x86_64-linux-gnu/qt5/plugins", "/usr/bin") 
The environment variable QT_PLUGIN_PATH might be not correctly set
Trying to use rootObject before initialization is completed, whilst using setInitializationDelayed. Forcing completion
Couldn't find node shadow. Skipping rendering.

LOL!

My wife is wanting her breakfast! I'll address this later...

EDIT: Ha! While exploring another issue I noticed that Workplace Theme in System Settings has a splash screen setting.

[GreyGeek]

Despite those errors using kcmshell5 splashscreen the KDE splashscreen was shut off.
The desktop wallpaper appeared within five seconds. The penel took another 10-15 seconds to display and then the desktop was usable.
systemd-analyze blame showed

:~$ systemd-analyze blame
         20.368s dev-sda1.device
         13.311s systemd-udevd.service
          6.412s NetworkManager-wait-online.service

The attempt by apparmor to protect cupsd got worse:

[   66.119560] audit: type=1400 audit(1466945926.361:26): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld-akonadi///usr/sbin/mysqld" name="/etc/ld.so.preload" pid=1819 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
[  444.244486] audit: type=1400 audit(1466946304.297:27): apparmor="DENIED" operation="open" profile="/usr/sbin/cupsd" name="/etc/ld.so.preload" pid=2089 comm="cups-exec" requested_mask="r" denied_mask="r" fsuid=0 ouid=0

but that is another issue.

[GreyGeek]

I disabled apparmor on cupsd with

:~$ sudo ln -s /etc/apparmor.d/usr.sbin.cupsd /etc/apparmor.d/disable
jerry@jerry-Aspire-7739:~$ sudo apparmor_parser -R /etc/apparmor.d/usr.sbin.cupsd

[GreyGeek]

Well, after all that, it appears that the KDE login time remains at around 40 seconds.
Except now, instead of watching a pretty splash screen I stare at a black splash screen for about 20 seconds and then, with my desktop wall paper showing I have to wait another 20 seconds or so for the panel to appear and the desktop to become usable. All in all, I have to wait about 100 seconds from a cold boot to a working desktop.
The apparmor problem with cupsd was solved, however, so my time hasn't been a total waste.

I also removed the annoying bluez bluetooth problem:

sudo systemctl stop bluetooth.service
sudo systemctl disable bluetooth.service

and checked the result:

sudo systemctl status bluetooth.service

[GreyGeek]

Removing apparmor and disabling bluetooth knocked about 35 seconds off of my time to a Plasma5 desktop.

:~$ systemd-analyze
Startup finished in 4.013s (kernel) + 40.857s (userspace) = 44.871s

My numbers:

sec    event
   0  - bootup begins
  15 - kubuntu bootup logo appears
  50 - Password requested
  60 - KDE setup begins
 100 - Desktop usable

While my boot messages are a lot cleaner and show much less time spent on processes, the overall time from turn on to usable desktop is still about 100 seconds.
Nothing I have done reduced the time following entering my password and being presented with a usable desktop. I restored the splash screen because it is prettier to look at.

While I may have "recovered" 30+ seconds of apparmor cupsd processing the overall time has not changes, probably because those apparmor processes were asynchronous.

It would be nice if there was a plasma-analyze command with blame and plot parameters that would allow us to explore which processes are consuming the most time during the Plasma5 setup.

[Rog131]

It would be nice if there was a plasma-analyze command with blame and plot parameters that would allow us to explore which processes are consuming the most time during the Plasma5 setup.

There is the 'PLASMA_TRACK_STARTUP' enviroment variable: https://community.kde.org/Plasma/Environment_Variables
BUT it is not working (neither at here) : https://mail.kde.org/pipermail/plasm...il/052327.html

The systemd journal can be used to show the plasma start process : https://www.digitalocean.com/communi...e-systemd-logs

At here, clicking the 'Enter' key (sddm) and when the Plasma desktop is available starting a konsole:

june 26 19:35:00 archfox sddm[477]: Message received from greeter: Login
.
.
.
june 26 19:35:11 archfox konsole[1097]: kf5.kcoreaddons.kaboutdata: Could not initialize the equivalent properties of Q*Application: no instance (yet) existing.

Konsole:

journalctl -b > whatsup.txt

At here the Plasma start is taking about 11 s.

Analyze at here:

$ systemd-analyze
Startup finished in 4.903s (kernel) + 1.892s (userspace) = 6.795s

A bug report: Bug 360777 - Due to faulty configuration desktop loading time is ~20 seconds longer - https://bugs.kde.org/show_bug.cgi?id=360777

[chconnor]

Got it! For me, anyway: tipped off by this I edited /etc/pulse/default.pa and commented out both bluetooth lines ("load-module module-bluetooth-policy" and "load-module module-bluetooth-discover") -- not sure if only the discover line is needed or what, but I did both.

Voila, instant desktop. It'd probably be better to sort out how to get bluetooth running properly, but i don't ever use it and have no way to test it, so I can't be bothered. :-)

If you log in, and you immediately pull up a terminal and do "date" for reference's sake, then check the end of journalctl, do you find any gaps in the log lines like I did?

E.g.

Jun 26 [B]10:43:42[/B] capybara org.kde.KScreen[1988]: kscreen: Primary output changed from KScreen::Output(Id: 68 , Name: "HDMI1" ) ( "HDMI1" ) to KScreen::Output(Id: 68 , Name: "HDMI1" ) ( "HDMI1" )
Jun 26 [B]10:44:02[/B] capybara dbus[982]: [system] Failed to activate service 'org.bluez': timed out
Jun 26 10:44:02 capybara pulseaudio[2121]: [pulseaudio] bluez5-util.c: GetManagedObjects() failed: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application \
did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

...that's what sent me down the bluetooth path. From that line it seems like pulseaudio is doing a blocking call, which apparently was the case.

I filed a bug here: https://bugs.launchpad.net/ubuntu/+s...o/+bug/1596344

Now if there would only be a workaround for autohide panels starting visible.

[GreyGeek]

... The systemd journal can be used to show the plasma start process : https://www.digitalocean.com/communi...e-systemd-logs

I had glanced through that link previously and didn't appreciate what it contained. After your reference I went back to it and even printed a copy of it. It truly gives what I was looking for, a copy-cat to systemd-analyze. Even though it is lacking the blame and plot features it supplies the ability to keep separate copies of each Plasma5 bootup and to compare between them, if one makes the directory
sudo mkdir -p /var/log/journal

I was able to resolve minor problems I was having with the printer, dbus, bluez and some other things that contributed to slow plasma install times and now I have the cleanest, quickest plasma bootup I've ever had. Gone are the endless musb.c, errors, the multiple org.bluez errors, etc... Journalctl is like an enhanced dmesg.

Got it! For me, anyway: tipped off by this I edited /etc/pulse/default.pa and commented out both bluetooth lines ("load-module module-bluetooth-policy" and "load-module module-bluetooth-discover") -- not sure if only the discover line is needed or what, but I did both.

Voila, instant desktop. It'd probably be better to sort out how to get bluetooth running properly, but i don't ever use it and have no way to test it, so I can't be bothered. :-)

If you log in, and you immediately pull up a terminal and do "date" for reference's sake, then check the end of journalctl, do you find any gaps in the log lines like I did?

E.g.

Jun 26 [B]10:43:42[/B] capybara org.kde.KScreen[1988]: kscreen: Primary output changed from KScreen::Output(Id: 68 , Name: "HDMI1" ) ( "HDMI1" ) to KScreen::Output(Id: 68 , Name: "HDMI1" ) ( "HDMI1" )
Jun 26 [B]10:44:02[/B] capybara dbus[982]: [system] Failed to activate service 'org.bluez': timed out
Jun 26 10:44:02 capybara pulseaudio[2121]: [pulseaudio] bluez5-util.c: GetManagedObjects() failed: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application \
did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

...that's what sent me down the bluetooth path. From that line it seems like pulseaudio is doing a blocking call, which apparently was the case.

I filed a bug here: https://bugs.launchpad.net/ubuntu/+s...o/+bug/1596344

Now if there would only be a workaround for autohide panels starting visible.

I read that journalctl also allows filtering by boot#, by time, by unit (service), by process, user or group ID, by component path, kernel msgs and by priority. The output can be formatted in one of ten different styles, but no analyze of plot type of output is available. You can use the "-n N" option to give journalctl a "tail" like output, specifying how many lines of the latest output you want displayed. Ditto for "-f".

Quite a tool!

EDIT: I used to get many bluez errors. Now I get only a couple, as listed by ohconner.