Slow boot on SSD

vasuman · 2015-05-08 12:36:18

I just installed a new SSD on my laptop and reinstalled Arch.

Running systemd-analyze gives,

         17.095s dev-sda1.device
         16.660s systemd-logind.service
         16.634s connman.service
           259ms systemd-journald.service
            73ms systemd-udev-trigger.service
            69ms systemd-binfmt.service
            58ms systemd-journal-flush.service
            57ms kmod-static-nodes.service
            55ms systemd-vconsole-setup.service
            52ms udisks2.service
            50ms systemd-remount-fs.service
            50ms sys-kernel-debug.mount
            47ms wpa_supplicant.service
            46ms dev-mqueue.mount
            44ms polkit.service
            43ms systemd-udevd.service
            39ms systemd-update-utmp.service
            38ms tmp.mount
            35ms systemd-sysctl.service
            31ms alsa-restore.service
            26ms dev-hugepages.mount
            24ms connman-vpn.service
            22ms user@1001.service
            21ms systemd-timesyncd.service
            20ms systemd-tmpfiles-setup-dev.service
            19ms sys-kernel-config.mount
            19ms systemd-user-sessions.service
            19ms systemd-tmpfiles-clean.service
            13ms systemd-backlight@backlight:acpi_video0.service
            10ms proc-sys-fs-binfmt_misc.mount
            10ms systemd-random-seed.service
            10ms systemd-tmpfiles-setup.service
             8ms systemd-rfkill@rfkill0.service
             4ms sys-fs-fuse-connections.mount

Anyway I can reduce the time dev-sda1.device takes or figure out what the underlying problem is.

Thanks

Durden · 2015-05-08 15:09:04

Can you post your /etc/fstab ?

Head_on_a_Stick · 2015-05-08 21:23:26

This will give you a better idea of how long the individual components are taking:

systemd-analyze critical-chain

I think it may be conman taking the lion's share of the time rather than dev-sda1.device

vasuman · 2015-05-09 03:29:10

Hey,
My /etc/fstab is empty since I have only one partition that is mounted with rw on boot itself,

I've rebooted so, I don't have the chain from that boot. I've rebooted a bunch of times and everything seems to change but dev-sda1.device consistently takes around ~17s. Also, funnily enough, dev-sda1.device doesn't show up in the critical-chain,

graphical.target @17.416s
└─multi-user.target @17.414s
  └─getty.target @17.411s
    └─getty@tty1.service @17.403s
      └─systemd-user-sessions.service @17.343s +30ms
        └─remote-fs.target @17.336s
          └─connman.service @17.183s +115ms
            └─basic.target @17.092s
              └─sockets.target @17.089s
                └─dbus.socket @17.080s
                  └─sysinit.target @17.067s
                    └─systemd-rfkill@rfkill0.service @17.393s +30ms
                      └─system-systemd\x2drfkill.slice @17.390s
                        └─system.slice @100ms
                          └─-.slice @88ms

Also, Plot

Last edited by vasuman (2015-05-09 07:24:39)

mauritiusdadd · 2015-05-09 05:03:30

Hi vasuman,

vasuman wrote:

I've rebooted so, I don't have the chain from that boot. I've rebooted a bunch of times and everything seems to change but dev-sda1.device consistently takes around ~17s. Also, funnily enough, dev-sda1.device doesn't show up in the critical-chain,

In my experience the critical-chain is not very reliable, but from the plot you posted It seems that the culprit is systemd-journald trying to flush the journal. What is the output of the following commands?

systemctl status systemd-journald
journalctl --verify

Last edited by mauritiusdadd (2015-05-09 05:05:38)

vasuman · 2015-05-09 05:19:15

Everytime I reboot the offending service seems to change, the only thing that consistently slow is the dev-sda1.device.

Anyways, here is,

Running status

● systemd-journald.service - Journal Service
   Loaded: loaded (/usr/lib/systemd/system/systemd-journald.service; static; vendor preset: disabled)
   Active: active (running) since Sat 2015-05-09 08:39:19 IST; 2h 3min ago
     Docs: man:systemd-journald.service(8)
           man:journald.conf(5)
 Main PID: 124 (systemd-journal)
   Status: "Processing requests..."
   CGroup: /system.slice/systemd-journald.service
           └─124 /usr/lib/systemd/systemd-journald

May 09 08:39:19 vostro systemd-journal[124]: Runtime journal is using 8.0M (max allowed 197.4M, trying to leave 296.1M free of 1.9G available → c…it 197.4M).
May 09 08:39:19 vostro systemd-journal[124]: Permanent journal is using 40.0M (max allowed 4.0G, trying to leave 4.0G free of 105.4G available → …imit 4.0G).
May 09 08:39:19 vostro systemd-journal[124]: Time spent on flushing to /var is 72.424ms for 2 entries.
May 09 08:39:19 vostro systemd-journal[124]: Journal started

Result of --verify

PASS: /var/log/journal/8dceb35aeb9440d48bc5877527a83c69/user-1000.journal                                                 
PASS: /var/log/journal/8dceb35aeb9440d48bc5877527a83c69/system.journal                                                    
PASS: /var/log/journal/8dceb35aeb9440d48bc5877527a83c69/user-1001.journal

mauritiusdadd · 2015-05-09 07:15:49

Can you reboot and post the full output of the journal for that boot?

vasuman wrote:

Everytime I reboot the offending service seems to change, the only thing that consistently slow is the dev-sda1.device.

Also, just to be sure your issue isn't journal related, after the reboot can you take another plot and see if systemd-journal-flush.service still takes so long for being activated?

PS: please, don't post full size images, use thumbnails or links: https://wiki.archlinux.org/index.php/Fo … s_and_code

Last edited by mauritiusdadd (2015-05-09 08:50:14)

vasuman · 2015-05-09 07:52:17

Hey,

I rebooted and this was my blame output.

         17.223s dev-sda1.device
           278ms systemd-journald.service
           196ms systemd-logind.service
           190ms upower.service
           179ms alsa-restore.service
           108ms connman.service
           106ms systemd-binfmt.service
            60ms systemd-journal-flush.service
            46ms tmp.mount
            44ms systemd-udevd.service
            43ms wpa_supplicant.service
            40ms systemd-remount-fs.service
            39ms sys-kernel-debug.mount
            38ms systemd-udev-trigger.service
            37ms kmod-static-nodes.service
            37ms dev-hugepages.mount
            36ms systemd-update-utmp.service
            34ms connman-vpn.service
            33ms systemd-user-sessions.service
            33ms systemd-timesyncd.service
            28ms systemd-vconsole-setup.service
            26ms user@1001.service
            25ms systemd-sysctl.service
            19ms sys-kernel-config.mount
            18ms systemd-tmpfiles-setup-dev.service
            17ms dev-mqueue.mount
            15ms systemd-tmpfiles-setup.service
            10ms proc-sys-fs-binfmt_misc.mount
            10ms systemd-random-seed.service
            10ms systemd-backlight@backlight:acpi_video0.service
             7ms systemd-rfkill@rfkill0.service

The funny part is that it consistently takes around 17s - it doesn't even fluctuate.

So, I checked

journalctl -b

And I found this,

May 09 13:06:40 vostro kernel: ata1: drained 8 bytes to clear DRQ
May 09 13:06:40 vostro kernel: ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
May 09 13:06:40 vostro kernel: ata1.00: ST-ATAPI: DRQ=1 with device error, dev_stat 0x59
May 09 13:06:40 vostro kernel: ata1.00: cmd a0/00:00:00:08:00/00:00:00:00:00/a0 tag 0 pio 16392 in
                                        opcode=0x46 46 00 00 00 00 00 00 00 08 00res 59/40:03:00:08:00/00:00:00:00:00/a0 Emask 0x2 (HSM violation)
May 09 13:06:40 vostro kernel: ata1.00: status: { DRDY DRQ ERR }

Which led me to, this. So I think it is a hardware issue, I'll try replacing the SATA port or something of that sort.

Anyways, thanks for the help. Also, is it appropriate to mark this thread solved?

Last edited by vasuman (2015-05-09 07:53:38)

mauritiusdadd · 2015-05-09 09:04:46

Since you issue is not resolved, I think it's better not to mark the thread as solved. Searching the forum for 'Emask 0x2 (HSM violation)' returns a long list of threads reporting similar issues. Since you installed a new SSD your problem is unlikely an hardware fault, it is more probable a connection issue: you may want to check/replace the SATA cable and/or unplug and re-insert it.

Last edited by mauritiusdadd (2015-05-09 10:13:02)

Durden · 2015-05-09 14:08:55

Try a different SATA port. Could be bad connectors. Could also just be the SSD, they have onboard controllers and can, when not functioning correctly, lead to issues like this.

Arch Linux

#1 2015-05-08 12:36:18

Slow boot on SSD

#2 2015-05-08 15:09:04

Re: Slow boot on SSD

#3 2015-05-08 21:23:26

Re: Slow boot on SSD

#4 2015-05-09 03:29:10

Re: Slow boot on SSD

#5 2015-05-09 05:03:30

Re: Slow boot on SSD

#6 2015-05-09 05:19:15

Re: Slow boot on SSD

#7 2015-05-09 07:15:49

Re: Slow boot on SSD

#8 2015-05-09 07:52:17

Re: Slow boot on SSD

#9 2015-05-09 09:04:46

Re: Slow boot on SSD

#10 2015-05-09 14:08:55

Re: Slow boot on SSD

Board footer