userspace taking over a minute to boot!

golferjoe99 · 2022-08-20 22:11:28

I've noticed my linux booting is very slow compared to windows which i think is weird, i will attach output of systemd analyze and systemd analyze critical chain below

 
Startup finished in 8.798s (firmware) + 2.642s (loader) + 7.854s (kernel) + 1min 2.466s (userspace) = 1min 21.762s

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

graphical.target @1min 2.466s
└─multi-user.target @1min 2.466s
  └─tor.service @56.067s +6.398s
    └─network.target @56.062s
      └─NetworkManager.service @54.884s +1.176s
        └─dbus.service @53.661s +1.217s
          └─basic.target @53.661s
            └─sockets.target @53.661s
              └─dbus.socket @53.661s
                └─sysinit.target @53.650s
                  └─systemd-update-done.service @53.632s +17ms
                    └─ldconfig.service @50.763s +2.867s
                      └─local-fs.target @50.761s
                        └─home.mount @50.203s +557ms
                          └─systemd-fsck@dev-disk-by\x2duuid-4fffd8f3\x2d2624\x2d43e2\x2d97aa\x2d2c1d1ce2eedb.service @14.019s +36.111s
                            └─dev-disk-by\x2duuid-4fffd8f3\x2d2624\x2d43e2\x2d97aa\x2d2c1d1ce2eedb.device @14.017s

Trilby · 2022-08-20 23:01:37

And what do you see in the output you posted? Clearly that boot included a fsck on one of your partitions ... which itself took a while to become available. Does this happen every boot? If so, something's likely wrong with your drive. Is this an HDD or SSD? Have you run a SMART test on the drive?

Last edited by Trilby (2022-08-20 23:02:18)

golferjoe99 · 2022-08-21 03:03:03

Trilby wrote:

And what do you see in the output you posted? Clearly that boot included a fsck on one of your partitions ... which itself took a while to become available. Does this happen every boot? If so, something's likely wrong with your drive. Is this an HDD or SSD? Have you run a SMART test on the drive?

I am running a long smartctl test on it right now, its a HDD and quite old. harvested from a laptop. I understand the speeds will be slow, but is there anything i can do to make them faster? or am i stuck with slow speed until i move to an SSD?

seth · 2022-08-21 07:30:49

That level of delay and frequent/constant fsck's rather indicate that the drive is falling apart.
Post the "smartctl -a" output on it now - there'll usually be indicators for that.

golferjoe99 · 2022-08-21 12:34:25

seth wrote:

That level of delay and frequent/constant fsck's rather indicate that the drive is falling apart.
Post the "smartctl -a" output on it now - there'll usually be indicators for that.

Here you go!

=== START OF INFORMATION SECTION ===
Model Family:     Western Digital Blue Mobile
Device Model:     WDC WD5000LPCX-00VHAT0
Serial Number:    WD-WX51A87LX80D
LU WWN Device Id: 5 0014ee 607e7c216
Firmware Version: 01.01A01
User Capacity:    500,107,862,016 bytes [500 GB]
Sector Sizes:     512 bytes logical, 4096 bytes physical
Rotation Rate:    5400 rpm
Form Factor:      2.5 inches
Device is:        In smartctl database 7.3/5319
ATA Version is:   ACS-3 T13/2161-D revision 5
SATA Version is:  SATA 3.1, 6.0 Gb/s (current: 6.0 Gb/s)
Local Time is:    Sun Aug 21 14:32:59 2022 CEST
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:  (0x00) Offline data collection activity
                                        was never started.
                                        Auto Offline Data Collection: Disabled.
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:                ( 8700) seconds.
Offline data collection
capabilities:                    (0x7b) SMART execute Offline immediate.
                                        Auto Offline data collection on/off support.
                                        Suspend Offline collection upon new
                                        command.
                                        Offline surface scan supported.
                                        Self-test supported.
                                        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:        (   2) minutes.
Extended self-test routine
recommended polling time:        ( 101) minutes.
Conveyance self-test routine
recommended polling time:        (   5) minutes.
SCT capabilities:              (0x3035) SCT Status supported.
                                        SCT Feature Control supported.
                                        SCT Data Table supported.

SMART Attributes Data Structure revision number: 16
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x002f   200   200   051    Pre-fail  Always       -       0
  3 Spin_Up_Time            0x0027   151   147   021    Pre-fail  Always       -       1416
  4 Start_Stop_Count        0x0032   084   084   000    Old_age   Always       -       16278
  5 Reallocated_Sector_Ct   0x0033   200   200   140    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x002e   200   200   000    Old_age   Always       -       0
  9 Power_On_Hours          0x0032   064   064   000    Old_age   Always       -       26694
 10 Spin_Retry_Count        0x0032   100   100   000    Old_age   Always       -       0
 11 Calibration_Retry_Count 0x0032   100   100   000    Old_age   Always       -       0
 12 Power_Cycle_Count       0x0032   098   098   000    Old_age   Always       -       2747
192 Power-Off_Retract_Count 0x0032   198   198   000    Old_age   Always       -       1856
193 Load_Cycle_Count        0x0032   109   109   000    Old_age   Always       -       275490
194 Temperature_Celsius     0x0022   106   094   000    Old_age   Always       -       37
196 Reallocated_Event_Count 0x0032   200   200   000    Old_age   Always       -       0
197 Current_Pending_Sector  0x0032   200   200   000    Old_age   Always       -       0
198 Offline_Uncorrectable   0x0030   100   253   000    Old_age   Offline      -       0
199 UDMA_CRC_Error_Count    0x0032   200   200   000    Old_age   Always       -       0
200 Multi_Zone_Error_Rate   0x0008   200   200   000    Old_age   Offline      -       0

SMART Error Log Version: 1
No Errors Logged

SMART Self-test log structure revision number 1
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Extended offline    Completed without error       00%     26686         -
# 2  Short offline       Completed without error       00%     26685         -

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.

seth · 2022-08-21 13:05:34

The disk looks actually healthy - do you hard-reboot the system (w/ the power button)?
Is there a parallel windows installation?

golferjoe99 · 2022-08-21 15:26:27

seth wrote:

The disk looks actually healthy - do you hard-reboot the system (w/ the power button)?
Is there a parallel windows installation?

There is a windows installation, but its on another disk.

I do actually hard reboot, its a bad habit of mine. I'm assuming i should stop doing it, will stopping it fix the problem or just stop it from spreading more?

seth · 2022-08-21 15:37:47

but its on another disk

Does absolutely not matter, see the 3rd link below. No, it's not the BIOS setting and windows keeps re-enabling it, so look. Don't believe.

I do actually hard reboot, its a bad habit of mine. I'm assuming i should stop doing it

D'ohh, yes and yes.
You (hopefully) won't have to fsck on every boot - not sure what impact that alone will have on the other delay.

golferjoe99 · 2022-08-22 12:26:50

seth wrote:

but its on another disk
Does absolutely not matter, see the 3rd link below. No, it's not the BIOS setting and windows keeps re-enabling it, so look. Don't believe.

I do actually hard reboot, its a bad habit of mine. I'm assuming i should stop doing it
D'ohh, yes and yes.
You (hopefully) won't have to fsck on every boot - not sure what impact that alone will have on the other delay.

I'll get to disabling fast boot today, thank you!

I started turning off my computer normally and the boot time did went down by a lot!

 Startup finished in 8.849s (firmware) + 5.978s (loader) + 3.692s (kernel) + 34.669s (userspace) = 53.190s

34S still isn't the best. but way better than 1 minute! thank you!

Last edited by golferjoe99 (2022-08-22 12:27:11)

seth · 2022-08-22 12:52:17

Do you have an updated critical chain? System journal?

golferjoe99 · 2022-08-22 12:55:47

seth wrote:

Do you have an updated critical chain? System journal?

 
graphical.target @34.669s
└─multi-user.target @34.669s
  └─tor.service @29.565s +5.103s
    └─network.target @29.560s
      └─NetworkManager.service @28.576s +983ms
        └─dbus.service @20.955s +7.615s
          └─basic.target @20.953s
            └─sockets.target @20.953s
              └─dbus.socket @20.952s
                └─sysinit.target @20.945s
                  └─systemd-update-utmp.service @20.826s +118ms
                    └─systemd-tmpfiles-setup.service @20.533s +280ms
                      └─systemd-journal-flush.service @6.117s +14.415s
                        └─systemd-journald.service @5.536s +577ms
                          └─systemd-journald.socket @5.507s
                            └─-.mount @5.291s
                              └─-.slice @5.291s

How do i get the journal output? cheers!

seth · 2022-08-22 13:01:27

sudo journalctl -b | curl -F 'file=@-' 0x0.st

golferjoe99 · 2022-08-22 13:03:31

seth wrote:

sudo journalctl -b | curl -F 'file=@-' 0x0.st

http://0x0.st/o9Mj.txt

Trilby · 2022-08-22 13:17:42

Have you rebooted a couple times since disabling the windows fastboot? I believe the journal flush, which is taking a chunk of time in that critical chain, should be a sporadic thing and should not regularly run and / or take any notable amount of time.

In otherwords, which elements of that criticial chain are pattern vs one-off exception?

seth · 2022-08-22 13:20:47

Aug 22 06:29:23 milfhunter audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=shadow comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Aug 22 06:29:26 milfhunter dbus-daemon[554]: dbus[554]: Unknown group "netdev" in message bus configuration file
Aug 22 06:29:29 milfhunter dbus-daemon[554]: dbus[554]: Unknown group "netdev" in message bus configuration file
Aug 22 06:29:30 milfhunter systemd[1]: Started D-Bus System Message Bus.

Aug 22 06:29:07 milfhunter systemd[1]: Starting Flush Journal to Persistent Storage...
Aug 22 06:29:07 milfhunter systemd-journald[300]: Time spent on flushing to /var/log/journal/1afc8684837f4cc5925f2230d3bc178c is 445.011ms for 847 entries.
Aug 22 06:29:07 milfhunter systemd-journald[300]: System Journal (/var/log/journal/1afc8684837f4cc5925f2230d3bc178c) is 1.8G, max 3.5G, 1.6G free.
Aug 22 06:29:22 milfhunter systemd-journald[300]: Received client request to flush runtime journal.
Aug 22 06:29:22 milfhunter kernel: audit: type=1130 audit(1661142547.994:3): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-udev-trigger comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'

See whether that delay is still there on the next reboot.

Arch Linux

#1 2022-08-20 22:11:28

userspace taking over a minute to boot!

#2 2022-08-20 23:01:37

Re: userspace taking over a minute to boot!

#3 2022-08-21 03:03:03

Re: userspace taking over a minute to boot!

#4 2022-08-21 07:30:49

Re: userspace taking over a minute to boot!

#5 2022-08-21 12:34:25

Re: userspace taking over a minute to boot!

#6 2022-08-21 13:05:34

Re: userspace taking over a minute to boot!

#7 2022-08-21 15:26:27

Re: userspace taking over a minute to boot!

#8 2022-08-21 15:37:47

Re: userspace taking over a minute to boot!

#9 2022-08-22 12:26:50

Re: userspace taking over a minute to boot!

#10 2022-08-22 12:52:17

Re: userspace taking over a minute to boot!

#11 2022-08-22 12:55:47

Re: userspace taking over a minute to boot!

#12 2022-08-22 13:01:27

Re: userspace taking over a minute to boot!

#13 2022-08-22 13:03:31

Re: userspace taking over a minute to boot!

#14 2022-08-22 13:17:42

Re: userspace taking over a minute to boot!

#15 2022-08-22 13:20:47

Re: userspace taking over a minute to boot!

Board footer