What I learned while trying to diagnose a slow boot


I spent the weekend trying to figure out why SuperMario boots so slowly. I ended up overturning my ideas about what the problem was and learned a lot of new techniques. The only bad thing is that while I’m a lot closer to the problem, I’m still unsure of the root cause. So that the proper helpers can get credit, let me point you to the LinuxQuestions.org thread in which I worked this out. If you haven’t already clicked, don’t worry, I’m going to bring the relevant info over.

First off, there’s an hdparm test you can run to make sure your hard drive is running well. This will be followed by a command that will let you know if your hard drive is running as SATA-I, II, or III.

# hdparm -tT /dev/sda

/dev/sda:
 Timing cached reads:   7992 MB in  2.00 seconds = 4002.41 MB/sec
 Timing buffered disk reads: 190 MB in  3.00 seconds =  63.27 MB/sec

# hdparm -I /dev/sda | grep -i speed
           *    Gen1 signaling speed (1.5Gb/s)
           *    Gen2 signaling speed (3.0Gb/s)
for comparison purposes:

# hdparm -I /dev/sdb | grep -i speed
           *    Gen1 signaling speed (1.5Gb/s)
           *    Gen2 signaling speed (3.0Gb/s)
# hdparm -I /dev/sdc | grep -i speed
           *    Gen1 signaling speed (1.5Gb/s)
           *    Gen2 signaling speed (3.0Gb/s)
           *    Gen3 signaling speed (6.0Gb/s)

As you can see, two of my three hard drives are SATA-IIs so they aren’t as fast as they could be. Next up is how to view the SMART data on your hard drive. Nothing in the SMART data is a guarantee of WHEN your hard drive is going to die, but it can let you know that it’s in a bad state.

# smartctl -a /dev/sda
smartctl 6.4 2015-06-04 r4109 [x86_64-linux-4.0.8-300.fc22.x86_64] (local build)
Copyright (C) 2002-15, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF INFORMATION SECTION ===
Model Family:     Seagate Barracuda 7200.10
Device Model:     ST3160815AS
Serial Number:    6RA313Q3
Firmware Version: 3.AAD
User Capacity:    160,041,885,696 bytes [160 GB]
Sector Size:      512 bytes logical/physical
Device is:        In smartctl database [for details use: -P show]
ATA Version is:   ATA/ATAPI-7 (minor revision not indicated)
Local Time is:    Thu Jul 30 17:49:06 2015 EDT
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

General SMART Values:
Offline data collection status:  (0x82) Offline data collection activity
                                        was completed without error.
                                        Auto Offline Data Collection: Enabled.
Self-test execution status:      (   0) The previous self-test routine completed
                                        without error or no self-test has ever 
                                        been run.
Total time to complete Offline 
data collection:                (  430) seconds.
Offline data collection
capabilities:                    (0x5b) SMART execute Offline immediate.
                                        Auto Offline data collection on/off support.
                                        Suspend Offline collection upon new
                                        command.
                                        Offline surface scan supported.
                                        Self-test supported.
                                        No Conveyance Self-test supported.
                                        Selective Self-test supported.
SMART capabilities:            (0x0003) Saves SMART data before entering
                                        power-saving mode.
                                        Supports SMART auto save timer.
Error logging capability:        (0x01) Error logging supported.
                                        General Purpose Logging supported.
Short self-test routine 
recommended polling time:        (   1) minutes.
Extended self-test routine
recommended polling time:        (  54) minutes.

SMART Attributes Data Structure revision number: 10
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x000f   109   099   006    Pre-fail  Always       -       0
  3 Spin_Up_Time            0x0003   097   097   000    Pre-fail  Always       -       0
  4 Start_Stop_Count        0x0032   099   099   020    Old_age   Always       -       1809
  5 Reallocated_Sector_Ct   0x0033   100   100   036    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x000f   089   060   030    Pre-fail  Always       -       878752509
  9 Power_On_Hours          0x0032   062   062   000    Old_age   Always       -       33741
 10 Spin_Retry_Count        0x0013   100   100   097    Pre-fail  Always       -       0
 12 Power_Cycle_Count       0x0032   099   099   020    Old_age   Always       -       1837
187 Reported_Uncorrect      0x0032   100   100   000    Old_age   Always       -       0
189 High_Fly_Writes         0x003a   100   100   000    Old_age   Always       -       0
190 Airflow_Temperature_Cel 0x0022   053   048   045    Old_age   Always       -       47 (Min/Max 40/47)
194 Temperature_Celsius     0x0022   047   052   000    Old_age   Always       -       47 (0 16 0 0 0)
195 Hardware_ECC_Recovered  0x001a   087   073   000    Old_age   Always       -       119456045
197 Current_Pending_Sector  0x0012   100   100   000    Old_age   Always       -       0
198 Offline_Uncorrectable   0x0010   100   100   000    Old_age   Offline      -       0
199 UDMA_CRC_Error_Count    0x003e   200   200   000    Old_age   Always       -       0
200 Multi_Zone_Error_Rate   0x0000   100   253   000    Old_age   Offline      -       0
202 Data_Address_Mark_Errs  0x0032   100   253   000    Old_age   Always       -       0

SMART Error Log Version: 1
No Errors Logged

SMART Self-test log structure revision number 1

SMART Selective self-test log data structure revision number 1
 SPAN  MIN_LBA  MAX_LBA  CURRENT_TEST_STATUS
    1        0        0  Not_testing
    2        0        0  Not_testing
    3        0        0  Not_testing
    4        0        0  Not_testing
    5        0        0  Not_testing
Selective self-test flags (0x0):
  After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute delay.

But here is where I got to the most interesting data command, systemd-analyze. This will tell you how long it took to boot and why it took so long. First is the simplest set of numbers:

# systemd-analyze
Startup finished in 1.389s (kernel) + 11.939s (initrd) + 2min 36.838s (userspace) = 2min 50.166s

As you can see, not exactly great numbers for boot. But why? Well, there’s where we get to assign blame!

# systemd-analyze blame
    1min 25.354s initial-setup-graphical.service
         47.561s abrtd.service
         42.233s dev-sda3.device
         37.338s home.mount
         27.617s firewalld.service
         21.944s akmods.service
         21.569s smb.service
         18.883s NetworkManager-wait-online.service
         18.856s systemd-journal-flush.service
         17.703s NetworkManager.service
         16.135s systemd-udevd.service
         12.757s libvirtd.service
         12.379s cups.service
          9.896s plymouth-start.service
          8.033s nfs-idmapd.service
          7.771s console-kit-log-system-start.service
          7.769s vmware.service
          7.769s gssproxy.service
          7.767s mcelog.service
          7.421s rpcbind.service
          7.419s netcf-transaction.service
          6.405s rsyslog.service
          6.114s media-Photos.mount
          5.884s nfs-server.service
          5.827s colord.service
          5.089s proc-fs-nfsd.mount
          4.535s dnf-makecache.service
          4.057s vmware-USBArbitrator.service
          3.940s fedora-loadmodules.service
          3.744s systemd-binfmt.service
          3.597s media-nfs-xbmc\x2dmount.mount

Blame is pretty useful, but the usefulness is limited by the fact that some services are dependent upon other services before they can complete. So that’s where the critical-chain comes in:

# 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 @2min 36.827s
??multi-user.target @2min 36.827s
  ??smb.service @2min 15.256s +21.569s
    ??network.target @2min 15.199s
      ??NetworkManager.service @1min 38.605s +17.703s
        ??firewalld.service @1min 10.985s +27.617s
          ??basic.target @1min 10.598s
            ??sockets.target @1min 10.598s
              ??cups.socket @1min 10.598s
                ??sysinit.target @1min 10.534s
                  ??systemd-update-utmp.service @1min 10.313s +220ms
                    ??systemd-tmpfiles-setup.service @1min 9.938s +370ms
                      ??fedora-import-state.service @1min 9.008s +926ms
                        ??local-fs.target @1min 9.005s
                          ??home.mount @31.665s +37.338s
                            ??systemd-fsck@dev-disk-by\x2duuid-89cfd56a\x2d06c7\x2d4805\x2d9526\x2d7be4d24a2872.service @31.306s +88ms
                              ??dev-disk-by\x2duuid-89cfd56a\x2d06c7\x2d4805\x2d9526\x2d7be4d24a2872.device @31.306s

This was the most useful command in the entire exercise because it led me to the true culprit. I’d been ready to reinstall Fedora, sure that it was getting tripped up by a series of in-place installs or a slow, dying root hard drive. Instead, I found out that the biggest culprit was the mounting of home. This led to me my slightly inconclusive, but evidence-based conclusion that I perhaps didn’t buy the best drive for a /home drive. When I did some research based on what I now know, it seems that the hard drive I bought was meant for Tivos and stuff and so was not meant to have a fast mount time. Additionally, it changes its speed from 5400 to 7200 RPM depending on the situation. My /Photos drive is also a 3TB drive with btrfs, but it mounts instantaneously. Additionally, this did let me know that I still had VMWare services running so I WAS able to stop those and get about 30 seconds less boot time.

If any of my readers have some ideas, I’m willing to investigate some more. If not, I hope you at least learned some new, neat commands for diagnosing boot times and hard drive issues.