Slow boot after update to 17.04

[Schöbi]

systemd-analyze outputs:

Startup finished in 2.055s (kernel) + 8.961s (userspace) = 11.017s

After login it takes 32 seconds until the desktop appears - anyone an idea?

How can I protocol the plasma bootup?

[GreyGeek]

Swap ya!

[FONT=monospace][COLOR=#000000]$ [B]systemd-analyze[/B][/COLOR]
Startup finished in 10.465s (kernel) + 20.445s (userspace) = 30.911s

[COLOR=#000000]$ [B]systemd-analyze blame[/B][/COLOR]
          8.694s NetworkManager-wait-online.service
          5.344s [EMAIL="udev-configure-printer@-devices-pci0000:00-0000:00:14.0-usb3-3\x2d2.service"]udev-configure-printer@-devices-pci0000:00-0000:00:14.0-usb3-3\x2d2.service[/EMAIL]
          5.174s dev-sda1.device
          3.748s irqbalance.service
          3.638s ondemand.service
          3.619s grub-common.service
          2.936s networking.service
          2.876s pppd-dns.service
          2.821s avahi-daemon.service
          2.777s lm-sensors.service
          2.718s iio-sensor-proxy.service
          2.285s upower.service
          1.821s ufw.service
          1.435s lvm2-monitor.service
          1.300s ModemManager.service
          1.298s systemd-udevd.service
          1.149s gpu-manager.service
          1.093s accounts-daemon.service
           930ms colord.service
...
[/FONT]

After login my big time user is the network (dmesg)

[FONT=monospace][COLOR=#18B218] 27.736042 [/COLOR][COLOR=#B26818]usblp 3-2:1.0[/COLOR][COLOR=#000000]: usblp1: USB Bidirectional printer dev 2 if 0 alt 0 proto 2 vid 0x03F0 pid 0x0A2A[/COLOR]
[COLOR=#18B218]32.130486 [/COLOR][COLOR=#B26818]sit[/COLOR][COLOR=#000000]: IPv6, IPv4 and MPLS over IPv4 tunneling driver
[/COLOR] 9 second gap
[COLOR=#18B218]41.972643 [/COLOR][COLOR=#B26818]IPv6[/COLOR][COLOR=#000000]: ADDRCONF(NETDEV_UP): wlp13s0: link is not ready
[/COLOR]  32 second gap
[COLOR=#18B218]73.960628 [/COLOR][COLOR=#B26818]wlp13s0[/COLOR][COLOR=#000000]: authenticate with 20:**:**:**:**:e3[/COLOR]
[COLOR=#18B218]73.971336 [/COLOR][COLOR=#B26818]wlp13s0[/COLOR][COLOR=#000000]: send auth to 20:**:**:**:**:e3 (try 1/3)[/COLOR]
[COLOR=#18B218]73.973285 [/COLOR][COLOR=#B26818]wlp13s0[/COLOR][COLOR=#000000]: authenticated[/COLOR]
[/FONT]

[NoWorries]

I must be living a charmed life as my system is quite fast, namely:

:~$ systemd-analyze
Startup finished in 2.087s (kernel) + 1.702s (userspace) = 3.790s

Thanks for letting me know about this command as it gives a lot of insight into what is happening.

I must confess that my system has an SSD which helps with boot up time. When I use the blame option I get the following:

:~$ systemd-analyze blame
         602ms dev-sda5.device
         447ms systemd-resolved.service
         246ms upower.service
         237ms apparmor.service
         229ms networking.service
         225ms systemd-timesyncd.service
         137ms systemd-logind.service
         129ms grub-common.service
          97ms bluetooth.service
          91ms systemd-udev-trigger.service
          90ms alsa-restore.service
          87ms pppd-dns.service
          86ms thermald.service
          85ms gpu-manager.service
          83ms snapd.autoimport.service
          82ms rsyslog.service
          79ms avahi-daemon.service
          75ms plymouth-quit.service
          72ms keyboard-setup.service
          70ms systemd-fsck@dev-disk-by\x2duuid-0290ccdc\x2d167f\x2d4fde\x2dbffc\x2da65ad5f04756.service
          67ms NetworkManager.service
          51ms udisks2.service
          46ms systemd-journald.service
          32ms dev-disk-by\x2duuid-04ea4469\x2d9213\x2d407e\x2db05b\x2d03ee2b59a075.swap
          31ms proc-fs-nfsd.mount
          26ms systemd-udevd.service
          23ms packagekit.service
          23ms systemd-tmpfiles-setup-dev.service
          22ms ureadahead-stop.service
          21ms home.mount
          21ms irqbalance.service
          18ms user@1000.service
          17ms run-rpc_pipefs.mount
          17ms user@119.service
          16ms nfs-mountd.service
          16ms systemd-modules-load.service
          15ms plymouth-start.service
          15ms nfs-server.service
          14ms systemd-tmpfiles-setup.service
          14ms apport.service
          13ms resolvconf.service
          12ms plymouth-read-write.service
          12ms rpcbind.service
          10ms systemd-sysctl.service
          10ms sys-kernel-debug.mount
           9ms nfs-idmapd.service
           8ms ufw.service
           8ms systemd-update-utmp.service
           8ms setvtrgb.service
           8ms dev-mqueue.mount
           7ms systemd-rfkill.service
           7ms dev-hugepages.mount
           7ms systemd-remount-fs.service
           5ms systemd-backlight@backlight:intel_backlight.service
           5ms systemd-journal-flush.service
           4ms kmod-static-nodes.service
           3ms rtkit-daemon.service
           3ms wpa_supplicant.service
           3ms systemd-update-utmp-runlevel.service
           2ms systemd-random-seed.service
           2ms nvidia-persistenced.service
           2ms console-setup.service
           2ms systemd-backlight@leds:asus::kbd_backlight.service
           2ms sddm.service
           1ms nfs-config.service
           1ms systemd-user-sessions.service
           1ms sys-fs-fuse-connections.mount
         243us snapd.socket

So it is possible to have a fast response. This system is also installed as a dual boot with Windows 7. So I am not using anything different to a standard install.

I hope someone can help you get a faster response from your system.

[GreyGeek]

The SSD makes a world of difference. I looked into replacing my two RAID1 750Gb 7,000 RPM WD 2.5" drives with SSD's but it wasn't in my budget, so I bought just one $48 WD HD. I have 8Gb of RAM, which helps the speed, and my i7 isn't shabby either, but nothing beats a fast SSD when pulling files off of a fs.

[Schöbi]

It's a new Computer with SSD and Pentium CPU.

[GreyGeek]

It's a new Computer with SSD and Pentium CPU.

Right after a fresh cold boot do
systemd-analyze blame
and
dmesg
and paste the output into your reply using the quote boxes.

[Schöbi]

Right after a fresh cold boot do
systemd-analyze blame
and
dmesg
and paste the output into your reply using the quote boxes.

https://pastebin.com/UNfdGcX1

Did it again after removing the USB memory stick, now it takes "only" 14 seconds:
https://pastebin.com/f1CVJ9zP

The "kauditd_printk_skb: 30 callbacks suppressed" uses 10 seconds. I Tried to find out more but couldn't figure out something - this post seems to relate to my problem: https://bugs.launchpad.net/ubuntu/+s...r/+bug/1458014

[GreyGeek]

You had several long gaps:

3.010800 sd 6:0:0:0: sdb Attached SCSI removable disk
* 3.7 second gap *
6.717435 e1000e: enp0s31f6 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx
6.717480 IPv6: ADDRCONF(NETDEV_CHANGE): enp0s31f6: link becomes ready
* 11.2 second gap *
17.920998 FAT-fs (sdb1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
* 1.8 second gap *
19.715615 systemd1: snapd.refresh.timer: Adding 3h 18min 14.459279s random time.


20.804985 audit: type=1400 audit(1495136722.473:27): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld-akonadi///usr/sbin/mysqld" name="/proc/1494/status" pid=1494 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=1000 ouid=1000
* 9 second gap *
29.847105 systemd1: snapd.refresh.timer: Adding 3h 58min 30.714182s random time.


The second run:
5.601440 IPv6: ADDRCONF(NETDEV_CHANGE): enp0s31f6: link becomes ready
* 9.5 second gap *
15.158976 kauditd_printk_skb: 30 callbacks suppressed

My kaudit_printk_Skb gives only 12 callbacks suppressed and a 3.3 second delay.

My IPv6 tunnel takes over 40 seconds:

22.524947 IPv6: ADDRCONF(NETDEV_UP): wlp13s0: link is not ready
28.364574 IPv6: ADDRCONF(NETDEV_UP): wlp13s0: link is not ready
28.551951 sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver
61.016870 IPv6: ADDRCONF(NETDEV_UP): wlp13s0: link is not ready
78.847296 IPv6: ADDRCONF(NETDEV_CHANGE): wlp13s0: link becomes ready

BUT, these processes are not happening sequentially. Systemd is running most of them concurrently. Generally only the big time wasters run outside their bounds and cause other processes using them as targets to wait till they respond.

Systemd-analyze critical-chain gives the reverse sequence from the disk boot to the graphical target.

systemd-analyze critical-chain

The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

graphical.target @17.656s
└─multi-user.target @17.656s
  └─getty.target @17.633s
    └─getty@tty1.service @17.633s
      └─[COLOR=#FF5454][B]rc-local.service @17.436s +192ms[/B][/COLOR]
        └─network-online.target @17.412s
          └─[COLOR=#FF5454][B]NetworkManager-wait-online.service @10.201s +7.210s[/B][/COLOR]
            └─[COLOR=#FF5454][B]NetworkManager.service @9.001s +1.180s[/B][/COLOR]
              └─dbus.service @7.623s
                └─basic.target @7.622s
                  └─sockets.target @7.622s
                    └─[COLOR=#FF5454][B]snapd.socket @7.524s +97ms[/B][/COLOR]
                      └─sysinit.target @7.523s
                        └─[COLOR=#FF5454][B]apparmor.service @6.646s +877ms[/B][/COLOR]
                          └─local-fs.target @6.609s
                            └─[COLOR=#FF5454][B]home.mount @6.436s +172ms[/B][/COLOR]
                              └─[COLOR=#FF5454][B]systemd-fsck@dev-disk-by\x2duuid-12980ae8\x2d4117\x2d4cc5\x2dbbb8\x2d8065e82af93d.service @6.249s +159ms[/B][/COLOR]
                                └─dev-disk-by\x2duuid-12980ae8\x2d4117\x2d4cc5\x2dbbb8\x2d8065e82af93d.device @6.217s
[COLOR=#000000]
[/COLOR]

To see a graphical display of all the processes from start to finish, showing overlap, you can use
systemd-analyze plot > somename.svg
and you can use your browser to view it.

[NoWorries]

https://pastebin.com/UNfdGcX1

Did it again after removing the USB memory stick, now it takes "only" 14 seconds:
https://pastebin.com/f1CVJ9zP

The "kauditd_printk_skb: 30 callbacks suppressed" uses 10 seconds. I Tried to find out more but couldn't figure out something - this post seems to relate to my problem: https://bugs.launchpad.net/ubuntu/+s...r/+bug/1458014

My impression is that a lot of time is spent waiting for network connections, ie

9.836s NetworkManager-wait-online.service

Have you checked your internet connection? I am connected to the internet by fibre optic cable and that connection is always up.

[GreyGeek]

... Have you checked your internet connection? I am connected to the internet by fibre optic cable and that connection is always up.

I have a 70Mbs copper wire connection from what was TimeWarner, now called Spectrum. It is up 24/7/365. My IPv6 tunnel is via Hurricane Electric. It takes around 30 seconds to connect to the tunnel but once connected I can get 70 Mbps from IPv6. For years I had an SIXXS tunnel which, because of the aiccu driver, gave me a 20/20 at ipv6-test.com and behaved like it was native IPv6. Spectrum doesn't offer IPv6 to its residential customers. I'm paying $65/mo for what is supposed to be 60Mbps, so they have mis-adjusted their bandwidth settings, but I'm not going to complain. We have a local company that is planting fiber optic as I write this and they are offering 1Gbps for $90/mo including IPv6. As soon as they turn it on I am switching. I'll have to get a DOC 3.0 IPv6 compatible router though.

[steve7233]

My new fresh install of 17.04 is very slow but this is an old lap top, 2007 if I remember right.

[GreyGeek]

You can run
Systems-analyze blame
to see what's taking the most time.


Sent from my iPhone using Tapatalk