What I learned while trying to diagnose a slow boot
By EricMesa
- 6 minutes read - 1261 wordsI 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.