You are not logged in.
Pages: 1
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
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
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
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
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
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
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
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
Offline
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
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
vacuum should™ only delete the journal, not limit it and it's also not supposed to delete the active journal.
--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
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
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
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
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
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
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
I mounted root partition only on live only then I tried ls /mnt/var there was no output.
Offline
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
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
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
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
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
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 (2020-11-26 10:30:47)
Offline
Pages: 1