Announcement

Collapse
No announcement yet.

Slow login -- waiting for bluetooth?

Collapse
This topic is closed.
X
X
 
  • Filter
  • Time
  • Show
Clear All
new posts

    Slow login -- waiting for bluetooth?

    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!

    #2
    Open a console and issue
    systemd-analyze blame
    and paste the output in a posting here.
    "A nation that is afraid to let its people judge the truth and falsehood in an open market is a nation that is afraid of its people.”
    – John F. Kennedy, February 26, 1962.

    Comment


      #3
      Thanks GG -- nothing obviously wrong in there?

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

      Comment


        #4
        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.
        "A nation that is afraid to let its people judge the truth and falsehood in an open market is a nation that is afraid of its people.”
        – John F. Kennedy, February 26, 1962.

        Comment


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

          Comment


            #6
            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.
            Code:
            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
            Code:
            [   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.
            Code:
            :~$ 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.
            Last edited by GreyGeek; Jun 26, 2016, 07:48 AM. Reason: ...
            "A nation that is afraid to let its people judge the truth and falsehood in an open market is a nation that is afraid of its people.”
            – John F. Kennedy, February 26, 1962.

            Comment


              #7
              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
              Code:
              :~$ 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:
              Code:
              [   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.
              "A nation that is afraid to let its people judge the truth and falsehood in an open market is a nation that is afraid of its people.”
              – John F. Kennedy, February 26, 1962.

              Comment


                #8
                I disabled apparmor on cupsd with
                Code:
                :~$ 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
                "A nation that is afraid to let its people judge the truth and falsehood in an open market is a nation that is afraid of its people.”
                – John F. Kennedy, February 26, 1962.

                Comment


                  #9
                  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
                  "A nation that is afraid to let its people judge the truth and falsehood in an open market is a nation that is afraid of its people.”
                  – John F. Kennedy, February 26, 1962.

                  Comment


                    #10
                    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:
                    Code:
                    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.
                    Last edited by GreyGeek; Jun 26, 2016, 08:50 AM.
                    "A nation that is afraid to let its people judge the truth and falsehood in an open market is a nation that is afraid of its people.”
                    – John F. Kennedy, February 26, 1962.

                    Comment


                      #11
                      Originally posted by GreyGeek View Post

                      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:
                      Code:
                      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
                      Last edited by Rog131; Jun 26, 2016, 11:27 AM.
                      Before you edit, BACKUP !

                      Why there are dead links ?
                      1. Thread: Please explain how to access old kubuntu forum posts
                      2. Thread: Lost Information

                      Comment


                        #12
                        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.

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

                        Comment


                          #13
                          Originally posted by Rog131 View Post
                          ... 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.

                          Originally posted by chconnor View Post
                          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.

                          Code:
                          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.
                          "A nation that is afraid to let its people judge the truth and falsehood in an open market is a nation that is afraid of its people.”
                          – John F. Kennedy, February 26, 1962.

                          Comment

                          Working...
                          X