You are not logged in.

#1 2020-11-19 05:47:52

avneesh
Member
Registered: 2017-07-19
Posts: 51

Slow boot

I just installed arch(dual boot w/ windows 10) yesterday, it's boot time seems quite long when I tried to check through systemd-analyze critical chain journal flush service is taking ~40s alone. I've already checked journalctl and dmesg but I didn't find anything.

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 3.283s
└─sddm.service @1min 3.282s
  └─optimus-manager.service @50.863s +12.417s
    └─basic.target @50.856s
      └─sockets.target @50.856s
        └─dbus.socket @50.856s
          └─sysinit.target @50.838s
            └─systemd-timesyncd.service @49.839s +998ms
              └─systemd-tmpfiles-setup.service @49.098s +444ms
                └─systemd-journal-flush.service @14.534s +34.561s
                  └─var.mount @13.697s +775ms
                    └─systemd-fsck@dev-disk-by\x2duuid-177de2c6\x2dde1a\x2d4937\x2da94f\x2d13dd41b279dc.service @10.433s +3.263s
                      └─local-fs-pre.target @10.432s
                        └─lvm2-monitor.service @3.750s +6.681s
                          └─lvm2-lvmetad.service @6.325s
                            └─systemd-udevd.service @5.233s +1.088s
                              └─systemd-tmpfiles-setup-dev.service @4.592s +636ms
                                └─kmod-static-nodes.service @3.747s +223ms
                                  └─systemd-journald.socket @3.734s
                                    └─system.slice @3.429s
                                      └─-.slice @3.429s

Offline

#2 2020-11-19 06:38:21

seth
Member
Registered: 2012-09-03
Posts: 17,220

Re: Slow boot

Very slow /var partition or very many errors before the /var partition is mounted.
Ensure that windows fast boot is disabled (link in my signature)

Offline

#3 2020-11-19 17:46:30

avneesh
Member
Registered: 2017-07-19
Posts: 51

Re: Slow boot

Thanks for reply. I've already turned off fast boot and hibernation and I don't have ~/.xinitrc, I'm using kde. I verified running systemctl get-default it gave me graphical.target.

Offline

#4 2020-11-19 21:29:41

seth
Member
Registered: 2012-09-03
Posts: 17,220

Re: Slow boot

Not the link about the xinitrc or the target, but about windows fast boot.
So, how long is your journal before var is mounted? Are there many errors?

Offline

#5 2020-11-20 06:21:37

avneesh
Member
Registered: 2017-07-19
Posts: 51

Re: Slow boot

Just cross checked dmesg there is no error. It's ~890 lines before /var is mounted. Here's is output till mounting of /var: https://pastebin.com/raw/eXYStc3H. This is my partition scheme:

NAME   MAJ:MIN RM   SIZE RO TYPE MOUNTPOINT
sda      8:0    0 931.5G  0 disk 
├─sda1   8:1    0   579M  0 part 
├─sda2   8:2    0  71.4G  0 part 
├─sda3   8:3    0 711.7G  0 part /home
├─sda4   8:4    0     1K  0 part 
├─sda5   8:5    0    20G  0 part /
├─sda6   8:6    0    40G  0 part /var
└─sda7   8:7    0  10.5G  0 part [SWAP]
sr0     11:0    1  1024M  0 rom  

Offline

#6 2020-11-20 06:35:57

seth
Member
Registered: 2012-09-03
Posts: 17,220

Re: Slow boot

First, how big is your /var/log/journal?


Second, apparently you don't use LVM, so you could try to mask the services

systemctl mask lvm2-lvmetad.service
systemctl mask lvm2-monitor.service

and ensure "use_lvmetad = 0" in /etc/lvm/lvm.conf

(idk whether that will improve the situation but there're known issues at least w/ reboots, https://bbs.archlinux.org/viewtopic.php?id=245020 and it removes a variable)

Offline

#7 2020-11-20 13:25:07

avneesh
Member
Registered: 2017-07-19
Posts: 51

Re: Slow boot

First, how big is your /var/log/journal?

51M

I tried disabling it but it doesn't affect journal-flush time. Moreover I'm getting this in dmesg:

[    8.961916] systemd[1]: lvm2-lvmetad.socket: Socket service lvm2-lvmetad.service not loaded, refusing.
[    8.961925] systemd[1]: Failed to listen on LVM2 metadata daemon socket.

I read dmesg carefully. The fault is my /var drive is mounted after journal flush service is started maybe that is causing delay.

[    9.409721] systemd[1]: Started Journal Service.
[    9.409811] audit: type=1130 audit(1605874573.476:2): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    9.428316] audit: type=1130 audit(1605874573.496:3): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-sysctl comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    9.967820] audit: type=1130 audit(1605874574.036:4): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-udevd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   10.109707] ACPI: AC Adapter [ADP0] (off-line)
[   10.172036] input: PC Speaker as /devices/platform/pcspkr/input/input5
[   10.191821] wmi_bus wmi_bus-PNP0C14:00: WQ data block query control method not found
[   10.191824] wmi_bus wmi_bus-PNP0C14:00: WQ data block query control method not found
[   10.191827] wmi_bus wmi_bus-PNP0C14:00: WQ data block query control method not found
[   10.191829] wmi_bus wmi_bus-PNP0C14:00: WQ data block query control method not found
[   10.399140] tpm_crb MSFT0101:00: [Firmware Bug]: Bad ACPI memory layout
[   10.540610] i801_smbus 0000:00:1f.4: SPD Write Disable is set
[   10.540657] i801_smbus 0000:00:1f.4: SMBus using PCI interrupt
[   10.542185] i2c i2c-0: 2/2 memory slots populated (from DMI)
[   10.568318] mei_me 0000:00:16.0: enabling device (0000 -> 0002)
[   10.649579] battery: ACPI: Battery Slot [BAT0] (battery present)
[   10.650810] input: Ideapad extra buttons as /devices/pci0000:00/0000:00:1f.0/PNP0C09:00/VPC2004:00/input/input6
[   10.791745] libphy: Fixed MDIO Bus: probed
[   10.804661] RAPL PMU: API unit is 2^-32 Joules, 5 fixed counters, 655360 ms ovfl timer
[   10.804663] RAPL PMU: hw unit of domain pp0-core 2^-14 Joules
[   10.804664] RAPL PMU: hw unit of domain package 2^-14 Joules
[   10.804665] RAPL PMU: hw unit of domain dram 2^-14 Joules
[   10.804666] RAPL PMU: hw unit of domain pp1-gpu 2^-14 Joules
[   10.804667] RAPL PMU: hw unit of domain psys 2^-14 Joules
[   10.875943] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[   10.883462] snd_hda_intel 0000:03:00.1: Disabling MSI
[   10.883470] snd_hda_intel 0000:03:00.1: Handle vga_switcheroo audio client
[   10.886721] snd_hda_intel 0000:03:00.1: no codecs found!
[   10.888139] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[   10.904669] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
[   10.904672] cfg80211: failed to load regulatory.db
[   10.943921] r8169 0000:01:00.0: can't disable ASPM; OS doesn't have ASPM control
[   10.967647] iTCO_vendor_support: vendor-support=0
[   10.970919] cryptd: max_cpu_qlen set to 1000
[   10.971194] libphy: r8169: probed
[   10.971403] r8169 0000:01:00.0 eth0: RTL8168gu/8111gu, 54:e1:ad:03:36:ce, XID 509, IRQ 128
[   10.971406] r8169 0000:01:00.0 eth0: jumbo features [frames: 9194 bytes, tx checksumming: ko]
[   11.066339] r8169 0000:01:00.0 enp1s0: renamed from eth0
[   11.094650] AVX2 version of gcm_enc/dec engaged.
[   11.094652] AES CTR mode by8 optimization enabled
[   11.121883] iTCO_wdt: Intel TCO WatchDog Timer Driver v1.11
[   11.121953] iTCO_wdt: Found a Intel PCH TCO device (Version=4, TCOBASE=0x0400)
[   11.122075] iTCO_wdt: initialized. heartbeat=30 sec (nowayout=0)
[   11.165242] checking generic (b0000000 7f0000) vs hw (a2000000 1000000)
[   11.165244] checking generic (b0000000 7f0000) vs hw (b0000000 10000000)
[   11.165245] fb0: switching to inteldrmfb from VESA VGA
[   11.165330] Console: switching to colour dummy device 80x25
[   11.165388] i915 0000:00:02.0: vgaarb: deactivate vga console
[   11.167286] i915 0000:00:02.0: vgaarb: changed VGA decodes: olddecodes=io+mem,decodes=io+mem:owns=io+mem
[   11.168126] mei_hdcp 0000:00:16.0-b638ab7e-94e2-4ea2-a552-d1c54b627f04: bound 0000:00:02.0 (ops i915_hdcp_component_ops [i915])
[   11.617090] psmouse serio1: synaptics: queried max coordinates: x [..5670], y [..4794]
[   11.657684] i915 0000:00:02.0: [drm] Finished loading DMC firmware i915/kbl_dmc_ver1_04.bin (v1.4)
[   11.672024] psmouse serio1: synaptics: queried min coordinates: x [1314..], y [1098..]
[   11.764307] psmouse serio1: synaptics: Touchpad model: 1, fw: 8.1, id: 0x1e2b1, caps: 0xf00323/0x840300/0x2a800/0x0, board id: 2848, fw id: 1960267
[   11.822905] input: SynPS/2 Synaptics TouchPad as /devices/platform/i8042/serio1/input/input7
[   11.825163] ath10k_pci 0000:02:00.0: pci irq msi oper_irq_mode 2 irq_mode 0 reset_mode 0
[   11.834178] mousedev: PS/2 mouse device common for all mice
[   11.948745] intel_rapl_common: Found RAPL domain package
[   11.948751] intel_rapl_common: Found RAPL domain core
[   11.948756] intel_rapl_common: Found RAPL domain uncore
[   11.948759] intel_rapl_common: Found RAPL domain dram
[   12.030954] Adding 10985172k swap on /dev/sda7.  Priority:-2 extents:1 across:10985172k FS
[   12.225047] input:  USB OPTICAL MOUSE as /devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0/0003:0000:3825.0001/input/input8
[   12.228939] hid-generic 0003:0000:3825.0001: input,hidraw0: USB HID v1.11 Mouse [ USB OPTICAL MOUSE] on usb-0000:00:14.0-1/input0
[   12.245758] ath10k_pci 0000:02:00.0: qca9377 hw1.1 target 0x05020001 chip_id 0x003821ff sub 17aa:0901
[   12.245768] ath10k_pci 0000:02:00.0: kconfig debug 1 debugfs 1 tracing 1 dfs 0 testmode 0
[   12.247703] ath10k_pci 0000:02:00.0: firmware ver WLAN.TF.2.1-00021-QCARMSWP-1 api 6 features wowlan,ignore-otp crc32 42e41877
[   12.255125] mc: Linux media interface: v0.10
[   12.327017] videodev: Linux video capture interface: v2.00
[   12.348609] Bluetooth: Core ver 2.22
[   12.348624] NET: Registered protocol family 31
[   12.348625] Bluetooth: HCI device and connection manager initialized
[   12.348629] Bluetooth: HCI socket layer initialized
[   12.348631] Bluetooth: L2CAP socket layer initialized
[   12.348637] Bluetooth: SCO socket layer initialized
[   12.388826] ath10k_pci 0000:02:00.0: board_file api 2 bmi_id N/A crc32 8aedfa4a
[   12.485810] ath10k_pci 0000:02:00.0: htt-ver 3.56 wmi-op 4 htt-op 3 cal otp max-sta 32 raw 0 hwcrypto 1
[   12.529187] usbcore: registered new interface driver btusb
[   12.558000] [drm] Initialized i915 1.6.0 20200715 for 0000:00:02.0 on minor 0
[   12.566878] ACPI: Video Device [GFX0] (multi-head: yes  rom: no  post: no)
[   12.567760] input: Video Bus as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A08:00/LNXVIDEO:00/input/input9
[   12.568255] [Firmware Bug]: ACPI(PXSX) defines _DOD but not _DOS
[   12.568346] ACPI: Video Device [PXSX] (multi-head: yes  rom: yes  post: no)
[   12.568459] input: Video Bus as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A08:00/device:45/LNXVIDEO:01/input/input10
[   12.569307] snd_hda_intel 0000:00:1f.3: bound 0000:00:02.0 (ops i915_audio_component_bind_ops [i915])
[   12.572762] ath: EEPROM regdomain: 0x6c
[   12.572766] ath: EEPROM indicates we should expect a direct regpair map
[   12.572770] ath: Country alpha2 being used: 00
[   12.572773] ath: Regpair used: 0x6c
[   12.593933] fbcon: i915drmfb (fb0) is primary device
[   12.604422] Console: switching to colour frame buffer device 240x67
[   12.609689] uvcvideo: Found UVC 1.00 device EasyCamera (5986:06b1)
[   12.616142] input: EasyCamera:  EasyCamera as /devices/pci0000:00/0000:00:14.0/usb1/1-4/1-4:1.0/input/input11
[   12.616415] usbcore: registered new interface driver uvcvideo
[   12.616417] USB Video Class driver (1.1.1)
[   12.639276] i915 0000:00:02.0: [drm] fb0: i915drmfb frame buffer device
[   12.640663] ath10k_pci 0000:02:00.0 wlp2s0: renamed from wlan0
[   12.718185] snd_hda_codec_conexant hdaudioC0D0: CX20751/2: BIOS auto-probing.
[   12.718519] snd_hda_codec_conexant hdaudioC0D0: autoconfig for CX20751/2: line_outs=1 (0x17/0x0/0x0/0x0/0x0) type:speaker
[   12.718521] snd_hda_codec_conexant hdaudioC0D0:    speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
[   12.718523] snd_hda_codec_conexant hdaudioC0D0:    hp_outs=1 (0x16/0x0/0x0/0x0/0x0)
[   12.718524] snd_hda_codec_conexant hdaudioC0D0:    mono: mono_out=0x0
[   12.718525] snd_hda_codec_conexant hdaudioC0D0:    inputs:
[   12.718527] snd_hda_codec_conexant hdaudioC0D0:      Internal Mic=0x1a
[   12.718528] snd_hda_codec_conexant hdaudioC0D0:      Mic=0x19
[   12.764667] input: HDA Intel PCH Mic as /devices/pci0000:00/0000:00:1f.3/sound/card0/input12
[   12.764742] input: HDA Intel PCH Headphone as /devices/pci0000:00/0000:00:1f.3/sound/card0/input13
[   12.764803] input: HDA Intel PCH HDMI/DP,pcm=3 as /devices/pci0000:00/0000:00:1f.3/sound/card0/input14
[   12.764854] input: HDA Intel PCH HDMI/DP,pcm=7 as /devices/pci0000:00/0000:00:1f.3/sound/card0/input15
[   12.764893] input: HDA Intel PCH HDMI/DP,pcm=8 as /devices/pci0000:00/0000:00:1f.3/sound/card0/input16
[   12.764930] input: HDA Intel PCH HDMI/DP,pcm=9 as /devices/pci0000:00/0000:00:1f.3/sound/card0/input17
[   12.764968] input: HDA Intel PCH HDMI/DP,pcm=10 as /devices/pci0000:00/0000:00:1f.3/sound/card0/input18
[   12.885027] audit: type=1130 audit(1605874576.953:5): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-udev-settle comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   13.303680] audit: type=1130 audit(1605874577.373:6): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=lvm2-activation-early comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   13.303687] audit: type=1131 audit(1605874577.373:7): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=lvm2-activation-early comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   13.415214] audit: type=1130 audit(1605874577.483:8): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=lvm2-activation comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   13.415224] audit: type=1131 audit(1605874577.483:9): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=lvm2-activation comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   13.810762] audit: type=1130 audit(1605874577.876:10): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-fsck@dev-disk-by\x2duuid-3061acac\x2d1a1a\x2d44a8\x2dadc5\x2d58be69dd48c9 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   14.110569] audit: type=1130 audit(1605874578.176:11): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-fsck@dev-disk-by\x2duuid-177de2c6\x2dde1a\x2d4937\x2da94f\x2d13dd41b279dc comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   14.128617] EXT4-fs (sda3): mounted filesystem with ordered data mode. Opts: (null)
[   14.382343] EXT4-fs (sda6): mounted filesystem with ordered data mode. Opts: (null)
[   14.868137] audit: type=1130 audit(1605874578.936:12): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-backlight@backlight:intel_backlight comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   15.082910] audit: type=1130 audit(1605874579.149:13): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   15.149738] audit: type=1130 audit(1605874579.216:14): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-random-seed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   20.204115] audit: type=1131 audit(1605874584.269:15): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   28.122338] audit: type=1130 audit(1605874592.189:16): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-journal-flush comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success

Offline

#8 2020-11-20 13:35:18

seth
Member
Registered: 2012-09-03
Posts: 17,220

Re: Slow boot

It's more likely that systemd-journald.service triggers the /var mount because of

RequiresMountsFor=/var/log/journal

Please just post the complete system journal.

Offline

#9 2020-11-20 13:40:40

avneesh
Member
Registered: 2017-07-19
Posts: 51

Offline

#10 2020-11-20 14:16:37

seth
Member
Registered: 2012-09-03
Posts: 17,220

Re: Slow boot

Nope.
The only thing that looks fishy is "usb 1-2"

[    6.054422] usb usb1-port2: unable to enumerate USB device

It's on the same hub as

[  282.869142] usb 1-1: Product:  USB OPTICAL MOUSE

but doesn't seem to be the keyboard?
Do you have other external usb devices?

As for the journal, first test whether this is entropy starvation, https://wiki.debian.org/BoottimeEntropyStarvation and https://wiki.archlinux.org/index.php/Ra … generation
Then brute force "journalctl --vacuum-size 0" in case there's some weird entry that stalls things.

Offline

#11 2020-11-21 07:06:13

avneesh
Member
Registered: 2017-07-19
Posts: 51

Re: Slow boot

Do you have other external usb devices?

yes, I've connected external keyboard and mouse.

As for the journal, first test whether this is entropy starvation, https://wiki.debian.org/BoottimeEntropyStarvation and https://wiki.archlinux.org/index.php/Ra … generation

I tested after removing external keyboard and mouse there is no error regarding usb. Here's output of dmesg and journalctl:
dmesg: https://pastebin.com/raw/aSB0wx3F
journalctl: https://pastebin.com/raw/d3PjEmKu

Wouldn't vacuum size to 0 cause problem? Means it won't record future logs?

EDIT: Added systemd-analyze critical-chain

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 @44.860s
└─sddm.service @44.860s
  └─optimus-manager.service @35.538s +9.320s
    └─basic.target @35.531s
      └─sockets.target @35.531s
        └─dbus.socket @35.531s
          └─sysinit.target @35.439s
            └─systemd-timesyncd.service @33.706s +1.731s
              └─systemd-tmpfiles-setup.service @33.132s +494ms
                └─systemd-journal-flush.service @12.944s +20.185s
                  └─var.mount @12.666s +211ms
                    └─systemd-fsck@dev-disk-by\x2duuid-177de2c6\x2dde1a\x2d4937\x2da94f\x2d13dd41b279dc.service @11.843s +819ms
                      └─local-fs-pre.target @11.841s
                        └─systemd-tmpfiles-setup-dev.service @5.154s +292ms
                          └─systemd-sysusers.service @4.058s +1.093s
                            └─systemd-remount-fs.service @3.876s +98ms
                              └─systemd-journald.socket @3.775s
                                └─system.slice @3.486s
                                  └─-.slice @3.486s

Last edited by avneesh (2020-11-21 07:08:20)

Offline

#12 2020-11-21 07:46:10

seth
Member
Registered: 2012-09-03
Posts: 17,220

Re: Slow boot

vacuum should™ only delete the journal, not limit it and it's also not supposed to delete the active journal.

man journalctl wrote:

       --vacuum-size=, --vacuum-time=, --vacuum-files=
           Removes the oldest archived journal files until the disk space they use falls below
           the specified size (specified with the usual "K", "M", "G" and "T" suffixes), or all
           archived journal files contain no data older than the specified timespan (specified
           with the usual "s", "m", "h", "days", "months", "weeks" and "years" suffixes), or no
           more than the specified number of separate journal files remain. Note that running
           --vacuum-size= has only an indirect effect on the output shown by --disk-usage, as the
           latter includes active journal files, while the vacuuming operation only operates on
           archived journal files. Similarly, --vacuum-files= might not actually reduce the
           number of journal files to below the specified number, as it will not remove active
           journal files.

           --vacuum-size=, --vacuum-time= and --vacuum-files= may be combined in a single
           invocation to enforce any combination of a size, a time and a number of files limit on
           the archived journal files. Specifying any of these three parameters as zero is
           equivalent to not enforcing the specific limit, and is thus redundant.

           These three switches may also be combined with --rotate into one command. If so, all
           active files are rotated first, and the requested vacuuming operation is executed
           right after. The rotation has the effect that all currently active files are archived
           (and potentially new, empty journal files opened as replacement), and hence the
           vacuuming operation has the greatest effect as it can take all log data written so far
           into account.

Offline

#13 2020-11-21 14:13:24

avneesh
Member
Registered: 2017-07-19
Posts: 51

Re: Slow boot

That didn't solve either. I tried to check time taken to flush by running journalctl -b --unit systemd-journald.service and it gave me no entries.

-- Logs begin at Wed 2020-11-18 11:00:20 IST, end at Sat 2020-11-21 19:30:44 IST. --
-- No entries --

Offline

#14 2020-11-21 15:32:20

seth
Member
Registered: 2012-09-03
Posts: 17,220

Re: Slow boot

So it's not the existing journal, /var mounts fast and doesn't throw a bunch of IO errors either.
Did you check the entropy starvation articles?

Next, https://wiki.archlinux.org/index.php/Systemd/Journal
=> If you set Storage=auto and remove /var/log/journal/ (or just move it to /var/log/not.journal/) does that have any impact?

Offline

#15 2020-11-22 07:50:08

avneesh
Member
Registered: 2017-07-19
Posts: 51

Re: Slow boot

Did you check the entropy starvation articles?

Yeah, I checked by jiggling mouse it didn't affected boot time.

=> If you set Storage=auto and remove /var/log/journal/ (or just move it to /var/log/not.journal/) does that have any impact?

Yeah, now time reduced by ~12-15 sec. Here's critical chain

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 @19.307s
└─sddm.service @19.307s
  └─optimus-manager.service @12.097s +7.208s
    └─basic.target @12.090s
      └─sockets.target @12.090s
        └─dbus.socket @12.090s
          └─sysinit.target @11.821s
            └─systemd-timesyncd.service @10.951s +869ms
              └─systemd-tmpfiles-setup.service @10.295s +517ms
                └─systemd-journal-flush.service @9.825s +467ms
                  └─var.mount @9.456s +307ms
                    └─systemd-fsck@dev-disk-by\x2duuid-177de2c6\x2dde1a\x2d4937\x2da94f\x2d13dd41b279dc.service @8.615s +839ms
                      └─local-fs-pre.target @8.614s
                        └─systemd-tmpfiles-setup-dev.service @3.399s +244ms
                          └─kmod-static-nodes.service @3.185s +62ms
                            └─systemd-journald.socket @3.171s
                              └─-.mount @2.859s
                                └─system.slice @2.859s
                                  └─-.slice @2.859s

Now I got the output of journalctl -b --unit systemd-journald.service:

-- Logs begin at Sun 2020-11-22 13:04:38 IST, end at Sun 2020-11-22 13:15:17 IST. --
Nov 22 13:04:38 ghoul systemd-journald[211]: Journal started
Nov 22 13:04:38 ghoul systemd-journald[211]: Runtime Journal (/run/log/journal/76dbb67612474625a07db20fde220224) is 8.0M, max 392.9M, 384.9M free.
Nov 22 13:04:44 ghoul systemd-journald[211]: Runtime Journal (/run/log/journal/76dbb67612474625a07db20fde220224) is 8.0M, max 392.9M, 384.9M free.

Does this mean it wasn't able to write this on /var due to some reasons?

Offline

#16 2020-11-22 07:58:37

seth
Member
Registered: 2012-09-03
Posts: 17,220

Re: Slow boot

mount | grep var

Also umount /var (or boot a live distro for an offline check) and see what's in /var on the root partition.

Offline

#17 2020-11-22 12:52:43

avneesh
Member
Registered: 2017-07-19
Posts: 51

Re: Slow boot

Output of mount | grep var

/dev/sda6 on /var type ext4 (rw,relatime)

Also umount /var (or boot a live distro for an offline check) and see what's in /var on the root partition.

But I won't be able to see contents of /var on root unless I mount that.

Offline

#18 2020-11-22 13:17:42

seth
Member
Registered: 2012-09-03
Posts: 17,220

Re: Slow boot

Not (re-)mounted read-only, so no problem there.

Yes, you'll have to mount the root partition. (?)
In case: there's a /var path on the ROOT partition and the VAR partition gets mounted into that.
But things could get written into /var path on the ROOT partition before the VAR partition is mounted.
That's what we want to check.

Offline

#19 2020-11-22 13:36:47

avneesh
Member
Registered: 2017-07-19
Posts: 51

Re: Slow boot

I mounted root partition only on live only then I tried ls /mnt/var there was no output.

Offline

#20 2020-11-22 15:05:29

seth
Member
Registered: 2012-09-03
Posts: 17,220

Re: Slow boot

If you reboot into a live system and fsck the VAR partition, do you get any errors, fix requirements?

After a regular boot, how's the writing performance on /var

dd if=/dev/zero of=/var/test.file count=1M # don't be fooled, that's probably 512MB

Offline

#21 2020-11-23 06:13:03

avneesh
Member
Registered: 2017-07-19
Posts: 51

Re: Slow boot

Running fsck gives:

/dev/sda6: clean, 6041/1335296 files, 1641285/5326848 blocks

After a regular boot, how's the writing performance on /var

1048576+0 records in
1048576+0 records out
536870912 bytes (537 MB, 512 MiB) copied, 2.84376 s, 189 MB/s

Offline

#22 2020-11-23 10:59:06

seth
Member
Registered: 2012-09-03
Posts: 17,220

Re: Slow boot

So the disk isn't slow, the FS is intact, there's no existing journal to cause some conflict and not flushing the log to /var is fast…

If you boot w/o /var/log/journal/ (so it's not flushed) and then create that directory and then run

#time journalctl --flush

how long does that take?

Offline

#23 2020-11-23 12:51:23

avneesh
Member
Registered: 2017-07-19
Posts: 51

Re: Slow boot

Quite less time

0.00user 0.00system 0:00.20elapsed 2%CPU (0avgtext+0avgdata 8596maxresident)k
0inputs+0outputs (0major+482minor)pagefaults 0swaps

I also noticed one thing since setting storage to auto and removing journal folder from /var/log time gap between splash screen and loading desktop also reduced. I don't know if they are related but I thought I should tell you.

EDIT: I tried to boot after creating directory again and there was slight change of time command

0.00user 0.00system 0:01.53elapsed 0%CPU (0avgtext+0avgdata 8244maxresident)k
0inputs+0outputs (0major+480minor)pagefaults 0swaps

Also here is critical chain

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 @25.012s
└─sddm.service @25.011s
  └─optimus-manager.service @18.719s +6.285s
    └─basic.target @18.706s
      └─sockets.target @18.706s
        └─dbus.socket @18.706s
          └─sysinit.target @18.659s
            └─systemd-timesyncd.service @18.107s +552ms
              └─systemd-tmpfiles-setup.service @17.847s +215ms
                └─systemd-journal-flush.service @10.924s +6.921s
                  └─var.mount @10.751s +146ms
                    └─systemd-fsck@dev-disk-by\x2duuid-177de2c6\x2dde1a\x2d4937\x2da94f\x2d13dd41b279dc.service @9.668s +1.080s
                      └─local-fs-pre.target @9.665s
                        └─systemd-tmpfiles-setup-dev.service @4.659s +213ms
                          └─systemd-sysusers.service @3.953s +703ms
                            └─systemd-remount-fs.service @3.833s +31ms
                              └─systemd-journald.socket @3.765s
                                └─-.mount @3.552s
                                  └─system.slice @3.552s
                                    └─-.slice @3.552s

Last edited by avneesh (2020-11-23 13:02:30)

Offline

#24 2020-11-25 07:17:30

seth
Member
Registered: 2012-09-03
Posts: 17,220

Re: Slow boot

Flushing time went down from ~35s to ~7s - the latter is still quite some, but has it remained at that level since then?
Looking at your OP, lvm-monitor and esp. optimus-manager are also fairly slow and the latter takes, after incrementally speedin up across this thread, half the time in your last one. Any movement there?

The behavior is weird, though and because of the drastic impact when not flushing, I still suspect some issue with the disk - maybe another partition that /var
Check https://wiki.archlinux.org/index.php/SMART (all attributes and a test) to be sure. Is it an HDD or an SSD?

Offline

#25 Yesterday 10:24:31

avneesh
Member
Registered: 2017-07-19
Posts: 51

Re: Slow boot

has it remained at that level since then?

Yeah, now flush takes ~7s with directory.

Any movement there?

I tried to search in journalctl but no clue.
I tried to run long test it's stuck at 10% even after 165 min
I ran all test and it doesn't reported any error

=== START OF READ SMART DATA SECTION ===
SMART Self-test log structure revision number 1
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Conveyance offline  Completed without error       00%      2016         -
# 2  Extended offline    Completed without error       00%      2015         -
# 3  Short offline       Completed without error       00%      2012         -
# 4  Extended offline    Interrupted (host reset)      00%       608         -
# 5  Extended offline    Interrupted (host reset)      00%       562         -
# 6  Extended offline    Interrupted (host reset)      00%       535         -
# 7  Extended offline    Interrupted (host reset)      00%       533         -
# 8  Extended offline    Interrupted (host reset)      00%       501         -
# 9  Extended offline    Interrupted (host reset)      00%       416         -
#10  Extended offline    Interrupted (host reset)      00%       354         -
#11  Extended offline    Interrupted (host reset)      00%       295         -
#12  Extended offline    Interrupted (host reset)      00%       276         -
#13  Extended offline    Completed without error       00%       264         -
#14  Extended offline    Interrupted (host reset)      00%       259         -
#15  Extended offline    Interrupted (host reset)      00%       256         -
#16  Extended offline    Completed without error       00%       254         -
#17  Extended offline    Interrupted (host reset)      00%       244         -
#18  Extended offline    Interrupted (host reset)      00%       241         -

Is it an HDD or an SSD?

HDD Seagate ST1000LM035-1RK172

Last edited by avneesh (Yesterday 10:30:47)

Offline

Board footer

Powered by FluxBB