You are not logged in.

Pages: 1

#1 2021-07-14 15:59:52

Mr Victory
Member
Registered: 2021-06-10
Posts: 41

Slow boot

Hello, I am experiencing slow boot. Here are the details:

  • I boot to console.

  • I have an HDD. The HDD is healthy.

  • Slow boot sometimes occurs, often (but not always) the first boot of every day. I am facing this issue for a few weeks, I am not sure when exactly it started.

  • Usually the boot time is around 10 seconds. When it is slow, it is between 20-30 seconds.

  • What I think is that whatever slowing down my boot process triggers before any systemd services and prevents systemd and other processes from accessing the disk. I may be wrong though.

  • If the boot is slow, everything is fine until "Welcome to Arch Linux" appears. Normally, after welcome message, more text is printed shortly. If the boot is slow, no text is printed for around 10 seconds.

Output of systemd-analyze:

Startup finished in 3.520s (kernel) + 25.851s (userspace) = 29.372s
graphical.target reached after 25.849s in userspace

Output of systemd-analyze blame:

5.009s dev-sda7.device
3.611s systemd-tmpfiles-setup-dev.service
3.334s dev-hugepages.mount
3.331s dev-mqueue.mount
3.328s sys-kernel-debug.mount
3.325s sys-kernel-tracing.mount
3.303s kmod-static-nodes.service
3.300s modprobe@configfs.service
3.297s modprobe@drm.service
3.294s modprobe@fuse.service
2.295s systemd-sysctl.service
 971ms systemd-tmpfiles-setup.service
 697ms dev-disk-by\x2duuid-bcd1afaf\x2d601a\x2d4a35\x2dbfea\x2d649b61bd97cd.swap
 626ms systemd-logind.service
 614ms polkit.service
 486ms systemd-modules-load.service
 434ms systemd-udevd.service
 368ms systemd-udev-trigger.service
 332ms user@1000.service
 324ms upower.service
 307ms dhcpcd.service
 305ms systemd-random-seed.service
 181ms systemd-journald.service
 135ms systemd-rfkill.service
 130ms systemd-backlight@backlight:intel_backlight.service
 115ms systemd-journal-flush.service
 112ms systemd-update-utmp.service
  91ms sys-kernel-config.mount
  80ms systemd-tmpfiles-clean.service
  28ms tmp.mount
  18ms rtkit-daemon.service
  13ms user-runtime-dir@1000.service
  12ms systemd-user-sessions.service
   4ms sys-fs-fuse-connections.mount

Output of systemd-analyze critical-chain:

graphical.target @25.849s
└─multi-user.target @25.846s
  └─systemd-logind.service @25.216s +626ms
    └─basic.target @25.202s
      └─sockets.target @25.201s
        └─dbus.socket @25.201s
          └─sysinit.target @25.166s
            └─systemd-update-utmp.service @25.053s +112ms
              └─systemd-tmpfiles-setup.service @24.080s +971ms
                └─local-fs.target @24.078s
                  └─tmp.mount @24.049s +28ms
                    └─swap.target @24.022s
                      └─dev-disk-by\x2duuid-bcd1afaf\x2d601a\x2d4a35\x2dbfea\x2d649b61bd97cd.swap @23.307s +697ms
                        └─dev-sda6.device @23.306s

I do not think that these systemd-analyze commands are helpful in this situation, I sent them just in case.
But systemd-analyze plot is interesting (systemd busy loading unit files):
https://paste.debian.net/1204346/
File will show up as text, it is an SVG file. Download and open with a web browser. An image viewer may work too.
Output of lsmod:

Module                  Size  Used by
dm_mod                163840  0
ccm                    20480  6
8021q                  40960  0
garp                   16384  1 8021q
mrp                    20480  1 8021q
stp                    16384  1 garp
llc                    16384  2 stp,garp
intel_rapl_msr         20480  0
intel_rapl_common      28672  1 intel_rapl_msr
x86_pkg_temp_thermal    20480  0
intel_powerclamp       20480  0
coretemp               20480  0
iTCO_wdt               16384  0
intel_pmc_bxt          16384  1 iTCO_wdt
iTCO_vendor_support    16384  1 iTCO_wdt
wmi_bmof               16384  0
hp_wmi                 20480  0
mei_hdcp               24576  0
sparse_keymap          16384  1 hp_wmi
kvm_intel             331776  0
kvm                  1015808  1 kvm_intel
btusb                  69632  0
snd_hda_codec_hdmi     73728  1
btrtl                  28672  1 btusb
btbcm                  16384  1 btusb
btintel                32768  1 btusb
snd_hda_codec_realtek   151552  1
uvcvideo              118784  0
irqbypass              16384  1 kvm
snd_hda_codec_generic    98304  1 snd_hda_codec_realtek
bluetooth             724992  5 btrtl,btintel,btbcm,btusb
videobuf2_vmalloc      20480  1 uvcvideo
videobuf2_memops       20480  1 videobuf2_vmalloc
videobuf2_v4l2         36864  1 uvcvideo
ledtrig_audio          16384  1 snd_hda_codec_generic
mousedev               24576  0
videobuf2_common       65536  4 videobuf2_vmalloc,videobuf2_v4l2,uvcvideo,videobuf2_memops
crct10dif_pclmul       16384  1
videodev              278528  3 videobuf2_v4l2,uvcvideo,videobuf2_common
snd_soc_skl           180224  0
rtl8723be             122880  0
snd_soc_hdac_hda       24576  1 snd_soc_skl
btcoexist             217088  1 rtl8723be
mc                     65536  4 videodev,videobuf2_v4l2,uvcvideo,videobuf2_common
crc32_pclmul           16384  0
joydev                 28672  0
snd_hda_ext_core       36864  2 snd_soc_hdac_hda,snd_soc_skl
snd_soc_sst_ipc        20480  1 snd_soc_skl
snd_soc_sst_dsp        40960  1 snd_soc_skl
rtl8723_common         28672  1 rtl8723be
snd_soc_acpi_intel_match    49152  1 snd_soc_skl
rtl_pci                36864  1 rtl8723be
snd_soc_acpi           16384  2 snd_soc_acpi_intel_match,snd_soc_skl
ecdh_generic           16384  1 bluetooth
ghash_clmulni_intel    16384  0
snd_soc_core          335872  2 snd_soc_hdac_hda,snd_soc_skl
rtlwifi               131072  4 rtl_pci,rtl8723be,btcoexist,rtl8723_common
aesni_intel           376832  4
ecc                    36864  1 ecdh_generic
crc16                  16384  1 bluetooth
i915                 2801664  24
crypto_simd            16384  1 aesni_intel
snd_compress           32768  1 snd_soc_core
cryptd                 24576  2 crypto_simd,ghash_clmulni_intel
ac97_bus               16384  1 snd_soc_core
mac80211             1167360  3 rtl_pci,rtl8723be,rtlwifi
snd_pcm_dmaengine      16384  1 snd_soc_core
snd_hda_intel          57344  3
rapl                   16384  0
intel_cstate           20480  0
intel_uncore          172032  0
snd_intel_dspcfg       28672  2 snd_hda_intel,snd_soc_skl
snd_intel_sdw_acpi     20480  1 snd_intel_dspcfg
pktcdvd                49152  0
snd_hda_codec         172032  5 snd_hda_codec_generic,snd_hda_codec_hdmi,snd_hda_intel,snd_hda_codec_realtek,snd_soc_hdac_hda
snd_hda_core          106496  8 snd_hda_codec_generic,snd_hda_codec_hdmi,snd_hda_intel,snd_hda_ext_core,snd_hda_codec,snd_hda_codec_realtek,snd_soc_hdac_hda,snd_soc_skl
r8169                  98304  0
realtek                28672  1
i2c_algo_bit           16384  1 i915
mdio_devres            16384  1 r8169
cfg80211             1040384  2 rtlwifi,mac80211
drm_kms_helper        290816  1 i915
intel_xhci_usb_role_switch    16384  0
rfkill                 32768  6 hp_wmi,bluetooth,cfg80211
cec                    73728  2 drm_kms_helper,i915
libphy                151552  3 r8169,mdio_devres,realtek
snd_hwdep              16384  1 snd_hda_codec
roles                  16384  1 intel_xhci_usb_role_switch
libarc4                16384  1 mac80211
intel_gtt              24576  1 i915
snd_pcm               147456  8 snd_hda_codec_hdmi,snd_hda_intel,snd_hda_codec,snd_compress,snd_soc_core,snd_soc_skl,snd_hda_core,snd_pcm_dmaengine
syscopyarea            16384  1 drm_kms_helper
mac_hid                16384  0
sysfillrect            16384  1 drm_kms_helper
i2c_i801               36864  0
mei_me                 45056  1
sysimgblt              16384  1 drm_kms_helper
snd_timer              45056  1 snd_pcm
fb_sys_fops            16384  1 drm_kms_helper
i2c_smbus              20480  1 i2c_i801
snd                   114688  16 snd_hda_codec_generic,snd_hda_codec_hdmi,snd_hwdep,snd_hda_intel,snd_hda_codec,snd_hda_codec_realtek,snd_timer,snd_compress,snd_soc_core,snd_pcm
mei                   151552  3 mei_hdcp,mei_me
video                  53248  1 i915
soundcore              16384  1 snd
pcspkr                 16384  0
wmi                    36864  2 hp_wmi,wmi_bmof
acpi_pad               24576  0
vboxnetflt             32768  0
vboxnetadp             28672  0
vboxdrv               528384  2 vboxnetadp,vboxnetflt
pkcs8_key_parser       16384  0
crypto_user            20480  0
drm                   581632  10 drm_kms_helper,i915
fuse                  159744  5
agpgart                45056  2 intel_gtt,drm
bpf_preload            16384  0
ip_tables              32768  0
x_tables               53248  1 ip_tables
usbhid                 65536  0
btrfs                1630208  1
blake2b_generic        20480  0
libcrc32c              16384  1 btrfs
crc32c_generic         16384  0
xor                    24576  1 btrfs
raid6_pq              122880  1 btrfs
ums_realtek            24576  0
uas                    32768  0
usb_storage            81920  2 uas,ums_realtek
sr_mod                 28672  0
xhci_pci               20480  0
crc32c_intel           24576  2
cdrom                  77824  2 pktcdvd,sr_mod
xhci_pci_renesas       20480  1 xhci_pci

Output of dmesg:
https://paste.debian.net/1204345/
There is nothing between 4 seconds and 18 seconds in dmesg.
Output of journalctl -b :
https://paste.ubuntu.com/p/b23273g97h/

Offline

#2 2021-07-14 16:39:26

seth
Member
From: Won't reply 2 private help req
Registered: 2012-09-03
Posts: 77,435

Re: Slow boot

The journal doesn't seem to be from a slow boot (there's 10-11 seconds action and then a failed login attempt after 17seconds, assuming it took you 6 seconds to enter the creds…)?
Also please use eg. xi.io (esp. the ubuntu service is terrible and requires a login for the raw text):

sudo journalctl -b -1 | curl -F 'f:1=<-' ix.io # assuming the previous boot was slow

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

Online

#3 2021-07-14 17:10:46

Mr Victory
Member
Registered: 2021-06-10
Posts: 41

Re: Slow boot

Dmesg: http://ix.io/3t0W
Journal: http://ix.io/3t11
systemd-analyze plot: http://ix.io/3t12 (this is an SVG file, not text)
All of the files are from a slow boot, it took more than 20 seconds until the console. The journal file displays incorrect times, dmesg is accurate.

seth wrote:

and then a failed login attempt after 17seconds, assuming it took you 6 seconds to enter the creds…

I don't remember exactly but I could have spent 6 seconds typing(and type wrong), this is possible. My password is long and I am a slow typer smile

Offline

#4 2021-07-14 17:27:22

seth
Member
From: Won't reply 2 private help req
Registered: 2012-09-03
Posts: 77,435

Re: Slow boot

Same journal as before, this segment is 8 seconds in:

Jul 14 17:04:38 mr-victory systemd[1]: Reached target Graphical Interface.
Jul 14 17:04:38 mr-victory systemd[1]: Startup finished in 3.520s (kernel) + 25.851s (userspace) = 29.372s.
Jul 14 17:04:38 mr-victory dbus-daemon[417]: [system] Activating via systemd: service name='org.freedesktop.resolve1' unit='dbus-org.freedesktop.resolve1.service' requested by ':1.3' (uid=0 pid=446 comm="resolvconf -d wlan0.link -f ")
Jul 14 17:04:38 mr-victory dbus-daemon[417]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.resolve1.service': Unit dbus-org.freedesktop.resolve1.service not found.
Jul 14 17:04:38 mr-victory kernel: Generic FE-GE Realtek PHY r8169-100:00: attached PHY driver (mii_bus:phy_addr=r8169-100:00, irq=MAC)
Jul 14 17:04:38 mr-victory dhcpcd[424]: enp1s0: waiting for carrier
Jul 14 17:04:38 mr-victory kernel: r8169 0000:01:00.0 enp1s0: Link is Down
Jul 14 17:04:39 mr-victory dhcpcd[424]: wlan0: waiting for carrier
Jul 14 17:04:39 mr-victory dhcpcd[424]: enp1s0: carrier acquired
Jul 14 17:04:39 mr-victory dhcpcd[424]: enp1s0: IAID 82:db:8e:5f
Jul 14 17:04:39 mr-victory dhcpcd[424]: enp1s0: adding address fe80::fc7c:d637:9cdc:c377
Jul 14 17:04:39 mr-victory dhcpcd[424]: enp1s0: carrier lost
Jul 14 17:04:39 mr-victory dbus-daemon[417]: [system] Activating via systemd: service name='org.freedesktop.resolve1' unit='dbus-org.freedesktop.resolve1.service' requested by ':1.4' (uid=0 pid=449 comm="resolvconf -d enp1s0.link -f ")
Jul 14 17:04:39 mr-victory dbus-daemon[417]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.resolve1.service': Unit dbus-org.freedesktop.resolve1.service not found.
Jul 14 17:04:39 mr-victory dhcpcd[424]: enp1s0: deleting address fe80::fc7c:d637:9cdc:c377
Jul 14 17:04:39 mr-victory dhcpcd[424]: wlan0: carrier acquired
Jul 14 17:04:39 mr-victory dhcpcd[424]: wlan0: IAID 19:53:4b:c9
Jul 14 17:04:39 mr-victory dhcpcd[424]: wlan0: adding address fe80::a681:c7b4:5969:2167
Jul 14 17:04:39 mr-victory dhcpcd[424]: wlan0: carrier lost
Jul 14 17:04:39 mr-victory dbus-daemon[417]: [system] Activating via systemd: service name='org.freedesktop.resolve1' unit='dbus-org.freedesktop.resolve1.service' requested by ':1.5' (uid=0 pid=452 comm="resolvconf -d wlan0.link -f ")
Jul 14 17:04:39 mr-victory dbus-daemon[417]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.resolve1.service': Unit dbus-org.freedesktop.resolve1.service not found.
Jul 14 17:04:39 mr-victory dhcpcd[424]: wlan0: deleting address fe80::a681:c7b4:5969:2167
Jul 14 17:04:41 mr-victory systemd[1]: systemd-rfkill.service: Deactivated successfully.
Jul 14 17:04:41 mr-victory audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jul 14 17:04:41 mr-victory kernel: kauditd_printk_skb: 5 callbacks suppressed
Jul 14 17:04:41 mr-victory kernel: audit: type=1131 audit(1626271481.888:35): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jul 14 17:04:47 mr-victory login[441]: pam_unix(login:auth): authentication failure; logname=LOGIN uid=0 euid=0 tty=/dev/tty1 ruser= rhost=  user=mr-victory
Jul 14 17:04:47 mr-victory dbus-daemon[417]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.6' (uid=0 pid=441 comm="/bin/login -p --            ")
Jul 14 17:04:47 mr-victory dbus-daemon[417]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
Jul 14 17:04:47 mr-victory login[441]: pam_systemd_home(login:auth): systemd-homed is not available: Unit dbus-org.freedesktop.home1.service not found.
Jul 14 17:04:47 mr-victory audit[441]: USER_AUTH pid=441 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=? acct="mr-victory" exe="/usr/bin/login" hostname=mr-victory addr=? terminal=/dev/tty1 res=failed'
Jul 14 17:04:47 mr-victory kernel: audit: type=1100 audit(1626271487.158:36): pid=441 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=? acct="mr-victory" exe="/usr/bin/login" hostname=mr-victory addr=? terminal=/dev/tty1 res=failed'
Jul 14 17:04:48 mr-victory login[441]: FAILED LOGIN SESSION FROM tty1 FOR mr-victory, Permission denied
Jul 14 17:04:52 mr-victory systemd[1]: getty@tty1.service: Deactivated successfully.
Jul 14 17:04:52 mr-victory audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=getty@tty1 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jul 14 17:04:52 mr-victory kernel: audit: type=1131 audit(1626271492.485:37): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=getty@tty1 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jul 14 17:04:52 mr-victory systemd[1]: getty@tty1.service: Scheduled restart job, restart counter is at 1.
Jul 14 17:04:52 mr-victory systemd[1]: Stopped Getty on tty1.
Jul 14 17:04:52 mr-victory audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=getty@tty1 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jul 14 17:04:52 mr-victory audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=getty@tty1 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jul 14 17:04:52 mr-victory kernel: audit: type=1130 audit(1626271492.502:38): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=getty@tty1 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jul 14 17:04:52 mr-victory kernel: audit: type=1131 audit(1626271492.502:39): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=getty@tty1 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jul 14 17:04:52 mr-victory systemd[1]: Started Getty on tty1.
Jul 14 17:04:52 mr-victory audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=getty@tty1 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jul 14 17:04:52 mr-victory kernel: audit: type=1130 audit(1626271492.505:40): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=getty@tty1 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jul 14 17:04:59 mr-victory audit[454]: USER_AUTH pid=454 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_securetty,pam_shells,pam_faillock,pam_permit,pam_faillock acct="mr-victory" exe="/usr/bin/login" hostname=mr-victory addr=? terminal=/dev/tty1 res=success'
Jul 14 17:04:59 mr-victory kernel: audit: type=1100 audit(1626271499.275:41): pid=454 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_securetty,pam_shells,pam_faillock,pam_permit,pam_faillock acct="mr-victory" exe="/usr/bin/login" hostname=mr-victory addr=? terminal=/dev/tty1 res=success'
Jul 14 17:04:59 mr-victory dbus-daemon[417]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.7' (uid=0 pid=454 comm="/bin/login -p --            ")
Jul 14 17:04:59 mr-victory dbus-daemon[417]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
Jul 14 17:04:59 mr-victory login[454]: pam_systemd_home(login:account): systemd-homed is not available: Unit dbus-org.freedesktop.home1.service not found.
Jul 14 17:04:59 mr-victory audit[454]: USER_ACCT pid=454 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_permit,pam_time acct="mr-victory" exe="/usr/bin/login" hostname=mr-victory addr=? terminal=/dev/tty1 res=success'
Jul 14 17:04:59 mr-victory audit[454]: CRED_ACQ pid=454 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_securetty,pam_shells,pam_faillock,pam_permit,pam_faillock acct="mr-victory" exe="/usr/bin/login" hostname=mr-victory addr=? terminal=/dev/tty1 res=success'
Jul 14 17:04:59 mr-victory audit[454]: SYSCALL arch=c000003e syscall=1 success=yes exit=4 a0=5 a1=7ffe10f38230 a2=4 a3=3e8 items=0 ppid=1 pid=454 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=1000 fsgid=0 tty=tty1 ses=1 comm="login" exe="/usr/bin/login" key=(null)
Jul 14 17:04:59 mr-victory audit: PROCTITLE proctitle=2F62696E2F6C6F67696E002D70002D2D
Jul 14 17:04:59 mr-victory kernel: audit: type=1101 audit(1626271499.315:42): pid=454 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_permit,pam_time acct="mr-victory" exe="/usr/bin/login" hostname=mr-victory addr=? terminal=/dev/tty1 res=success'
Jul 14 17:04:59 mr-victory kernel: audit: type=1103 audit(1626271499.315:43): pid=454 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_securetty,pam_shells,pam_faillock,pam_permit,pam_faillock acct="mr-victory" exe="/usr/bin/login" hostname=mr-victory addr=? terminal=/dev/tty1 res=success'
Jul 14 17:04:59 mr-victory kernel: audit: type=1006 audit(1626271499.315:44): pid=454 uid=0 old-auid=4294967295 auid=1000 tty=tty1 old-ses=4294967295 ses=1 res=1
Jul 14 17:04:59 mr-victory kernel: audit: type=1300 audit(1626271499.315:44): arch=c000003e syscall=1 success=yes exit=4 a0=5 a1=7ffe10f38230 a2=4 a3=3e8 items=0 ppid=1 pid=454 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=1000 fsgid=0 tty=tty1 ses=1 comm="login" exe="/usr/bin/login" key=(null)
Jul 14 17:04:59 mr-victory kernel: audit: type=1327 audit(1626271499.315:44): proctitle=2F62696E2F6C6F67696E002D70002D2D
Jul 14 17:04:59 mr-victory login[454]: pam_unix(login:session): session opened for user mr-victory(uid=1000) by LOGIN(uid=0)

That doesn't  cover one of the slower boots, does it?

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

Online

#5 2021-07-14 17:31:37

Mr Victory
Member
Registered: 2021-06-10
Posts: 41

Re: Slow boot

They are the same files.

Mr Victory wrote:

All of the files are from a slow boot, it took more than 20 seconds until the console. The journal file displays incorrect times, dmesg is accurate.

Last edited by Mr Victory (2021-07-14 17:31:56)

Offline

#6 2021-07-14 17:51:55

seth
Member
From: Won't reply 2 private help req
Registered: 2012-09-03
Posts: 77,435

Re: Slow boot

Great. So we've essentially no log for the dead time and an unreliable clock.
crng is done before the stall - is there a disc in the cdrom drive?

Because of the "time is useless"

Jul 14 17:04:30 mr-victory systemd[1]: RTC configured in localtime, applying delta of 180 minutes to system time.

Why's the RTC in local time? Is there a parallel windows installation?

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

Online

#7 2021-07-14 18:06:23

Mr Victory
Member
Registered: 2021-06-10
Posts: 41

Re: Slow boot

There is no disc in the cdrom drive.
Windows 10 is also installed and fast boot/hibernation are disabled.
Dmesg does not provide clock times but the times it give can be used to compare dmesg entries with each other.

Offline

#8 2021-07-14 20:23:13

seth
Member
From: Won't reply 2 private help req
Registered: 2012-09-03
Posts: 77,435

Re: Slow boot

The fact that we can't trust the clock doesn't really relate to the benefit of the monotic timer in dmesg - but if it slides once, it might slide ever so often.
There might be a problem syncing the journal to the disc (and running into a corrupt filesystem, forcing an fsck or IO errors) but there're no records for that at all.

Best thing I'd know is to raise the verbosity and see whether that produces more data… https://wiki.archlinux.org/title/Genera … bug_output

Also, just for good measure, post the "smartctl -a" for the drive ("overall disk status: healthy" is not a reliable indicator for potential problems)

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

Online

#9 2021-07-15 09:46:45

Mr Victory
Member
Registered: 2021-06-10
Posts: 41

Re: Slow boot

Here is the smartctl:

=== START OF INFORMATION SECTION ===
Model Family:     Western Digital Blue
Device Model:     WDC WD10EZEX-60WN4A0
Serial Number:    <omitted>
LU WWN Device Id: 5 0014ee 20ed199c6
Firmware Version: 01.01A01
User Capacity:    1,000,204,886,016 bytes [1.00 TB]
Sector Sizes:     512 bytes logical, 4096 bytes physical
Rotation Rate:    7200 rpm
Form Factor:      3.5 inches
Device is:        In smartctl database [for details use: -P show]
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:    Thu Jul 15 12:19:33 2021 +03
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:      (  41)	The self-test routine was interrupted
					by the host with a hard or soft reset.
Total time to complete Offline
data collection: 		(11280) 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: 	 (   2) minutes.
Extended self-test routine
recommended polling time: 	 ( 117) minutes.
SCT capabilities: 	       (0x303d)	SCT Status supported.
					SCT Error Recovery Control 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   174   171   021    Pre-fail  Always       -       2300
  4 Start_Stop_Count        0x0032   097   097   000    Old_age   Always       -       3332
  5 Reallocated_Sector_Ct   0x0033   200   200   140    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x002f   200   200   051    Pre-fail  Always       -       0
  9 Power_On_Hours          0x0032   089   089   000    Old_age   Always       -       8218
 10 Spin_Retry_Count        0x0033   100   100   051    Pre-fail  Always       -       0
 11 Calibration_Retry_Count 0x0032   100   100   000    Old_age   Always       -       0
 12 Power_Cycle_Count       0x0032   097   097   000    Old_age   Always       -       3326
183 Runtime_Bad_Block       0x0032   100   100   000    Old_age   Always       -       0
184 End-to-End_Error        0x0033   100   100   097    Pre-fail  Always       -       0
187 Reported_Uncorrect      0x0032   100   100   000    Old_age   Always       -       0
188 Command_Timeout         0x0032   100   099   000    Old_age   Always       -       1
190 Airflow_Temperature_Cel 0x0022   056   049   040    Old_age   Always       -       44 (Min/Max 42/44)
192 Power-Off_Retract_Count 0x0032   200   200   000    Old_age   Always       -       457
193 Load_Cycle_Count        0x0032   199   199   000    Old_age   Always       -       3304
194 Temperature_Celsius     0x0022   099   092   000    Old_age   Always       -       44
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   200   200   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    Interrupted (host reset)      90%      8195         -
# 2  Short offline       Completed without error       00%      8138         -
# 3  Short offline       Completed without error       00%      8095         -
# 4  Short offline       Completed without error       00%      8086         -
# 5  Short offline       Completed without error       00%      8018         -
# 6  Extended offline    Interrupted (host reset)      30%      8000         -
# 7  Short offline       Completed without error       00%      7866         -
# 8  Short offline       Completed without error       00%      7820         -
# 9  Extended offline    Interrupted (host reset)      60%      7790         -
#10  Short offline       Completed without error       00%      7559         -
#11  Short offline       Completed without error       00%      7553         -
#12  Short offline       Completed without error       00%      7548         -
#13  Short offline       Completed without error       00%      7507         -
#14  Extended offline    Aborted by host               80%      7502         -
#15  Short offline       Completed without error       00%      7463         -
#16  Short offline       Completed without error       00%      7457         -
#17  Short offline       Completed without error       00%      7390         -
#18  Short offline       Completed without error       00%      7381         -
#19  Short offline       Completed without error       00%      7369         -
#20  Short offline       Completed without error       00%      7331         -
#21  Short offline       Completed without error       00%      7327         -

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.

When sending the first post, I had ran the same command, read this:

SMART overall-health self-assessment test result: PASSED

and reached the conclusion my drive is healthy. This time I paid more attention, there are a lot of Pre-Fail and Old_Age in the output. Does this mean my drive is reaching end of life? My backup is ready for such a case.

For the verbosity, I added debug to kernel parameters. To avoid tty slowing down boot, I added i915 (the module for my graphics card) to MODULES array of /etc/mkinitcpio.conf.

Offline

#10 2021-07-15 12:04:00

Lone_Wolf
Administrator
From: Netherlands, Europe
Registered: 2005-10-04
Posts: 15,332

Re: Slow boot

Pre-Fail and Old_Age are what's most likely to cause those values to deteriorate.
I'm not sure of the temperature values, but all others look good .

190 Airflow_Temperature_Cel 0x0022   056   049   040    Old_age   Always       -       44 (Min/Max 42/44)

194 Temperature_Celsius     0x0022   099   092   000    Old_age   Always       -       44

Does the drive or case run hot often ?


rootflags=subvol=@/arch

What filesystem are you using ?

[   18.216297] systemd[1]: Starting Load Kernel Module fuse.

Are you mounting non-native or networked stuff ?

Disliking systemd intensely, but not satisfied with alternatives so focusing on taming systemd.

clean chroot building not flexible enough ?
Try clean chroot manager by graysky

Offline

#11 2021-07-15 12:49:26

Mr Victory
Member
Registered: 2021-06-10
Posts: 41

Re: Slow boot

Lone_Wolf wrote:

What filesystem are you using ?

I use BTRFS and the subvolume flag is set because
Arch Linux is installed on /@/arch
Linux Mint is installed on /@/mint
Fedora is installed on /@/fedora
openSUSE Tumbleweed is installed on /@
all on the same partition, different subvolumes.
I tried doing a full balance and defragmentation on BTRFS, it did not help.

Lone_Wolf wrote:

Are you mounting non-native or networked stuff ?

On boot, only the root partition is mounted and swap partition is activated. There are NTFS partitions on the same drive, I sometimes manually mount them. I do not mount any network storage.

Lone_Wolf wrote:

Does the drive or case run hot often ?

The processors idle around 45 degrees celsius, stay around 70 degrees when I use %25-%50 power and reach above 90 degrees if I do a power intensive task (e.g. video encoding). I usually use %25-50 power but the computer is mostly idling for a month, which is the period I am experiencing slow boot.

Offline

#12 2021-07-15 13:44:15

seth
Member
From: Won't reply 2 private help req
Registered: 2012-09-03
Posts: 77,435

Re: Slow boot

The disk is rather warm but doesn't show degradation (the raw_value column is most interesting here)

I'll pitch a screwball:
https://wiki.archlinux.org/title/Kernel … _KMS_start

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

Online

Pages: 1

Board footer

Powered by FluxBB