Slowdowns due to disk writes on startup

LithoUser · 2024-09-01 16:07:53

Hello everyone!

I use Arch with lightdm as a display manager to launch my Openbox session. When I installed my system (4 years ago, in September 2020), I could hear my hard disk “scratching” a bit (i.e. I could hear it working, data being written to it, for a few seconds, say 4 or 5 seconds) at the moment lightdm was displayed. This wasn't a problem: it was about as long as it took me to type in my user password, and when my Openbox session opened, everything was fully operational immediately (i.e. I was already connected to the Internet, and could start working straight away).

The problem is that the 4 or 5 seconds of disk writes turned into 10 seconds, then 15, then 20, then today around 25 seconds... Now, if I open my Openbox session immediately (without waiting for those 25 seconds to elapse), I hear that the disk is still spinning, and it takes another 20 seconds or so before NetworkManager is connected to the Internet and I can start working.

So I need some help to find out where these disk writes are coming from: what logs can I look at? What can I do to find out where the problem is coming from and fix it?

Many thanks in advance for your help!

seth · 2024-09-01 16:38:16

* https://wiki.archlinux.org/title/SMART
* https://wiki.archlinux.org/title/SMART
* https://wiki.archlinux.org/title/SMART
* https://wiki.archlinux.org/title/SMART
* https://wiki.archlinux.org/title/SMART
* https://wiki.archlinux.org/title/SMART
* https://wiki.archlinux.org/title/SMART
* sudo journalctl / dmesg (look for IO errors)
* sudo journalctl / dmesg (look for IO errors)
* sudo journalctl / dmesg (look for IO errors)
* sudo journalctl / dmesg (look for IO errors)
* sudo journalctl / dmesg (look for IO errors)
* sudo journalctl / dmesg (look for IO errors)
* iotop

LithoUser · 2024-09-01 19:55:34

seth wrote:

* https://wiki.archlinux.org/title/SMART

I have 2 HDDs, so I've run a test on both of them:

$ sudo smartctl -t conveyance /dev/sda
...
$ sudo smartctl -l selftest /dev/sda
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Conveyance offline  Completed without error       00%     11065         -

$ sudo smartctl -t conveyance /dev/sdc
...
$ sudo smartctl -l selftest /dev/sdc
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Conveyance offline  Completed without error       00%     43073         -

So they both seem OK.

seth wrote:

* sudo journalctl

$ sudo journalctl -b0 --no-pager
[sudo] Mot de passe de sanfix :
sept. 01 21:44:36 ORDIBUREAU kernel: core: CPUID marked event: 'bus cycles' unavailable
sept. 01 21:44:36 ORDIBUREAU kernel: MDS CPU bug present and SMT on, data leak possible. See https://www.kernel.org/doc/html/latest/admin-guide/hw-vuln/mds.html for more details.
sept. 01 21:44:36 ORDIBUREAU kernel: pnp 00:09: disabling [mem 0x000c0000-0x000cffff] because it overlaps 0000:01:00.0 BAR 6 [mem 0x000c0000-0x000dffff]
sept. 01 21:44:36 ORDIBUREAU kernel: i8042: PNP: PS/2 appears to have AUX port disabled, if this is incorrect please boot with i8042.nopnp
sept. 01 21:44:36 ORDIBUREAU kernel: resource: resource sanity check: requesting [mem 0x00000000000c0000-0x00000000000dffff], which spans more than PCI Bus 0000:00 [mem 0x000d0000-0x000dffff window]
sept. 01 21:44:36 ORDIBUREAU kernel: caller pci_map_rom+0x69/0x1a0 mapping multiple BARs
sept. 01 21:44:36 ORDIBUREAU systemd-journald[278]: Journal started
sept. 01 21:44:36 ORDIBUREAU systemd-journald[278]: [?] Runtime Journal (/run/log/journal/c7417cc90b4f47e4bb049ba60f8da9e6) is 640K, max 5M, 4.3M free.
sept. 01 21:44:36 ORDIBUREAU systemd-journald[278]: [?] Runtime Journal (/run/log/journal/c7417cc90b4f47e4bb049ba60f8da9e6) is 640K, max 5M, 4.3M free.
sept. 01 21:44:37 ORDIBUREAU kernel: ACPI Warning: SystemIO range 0x0000000000000828-0x000000000000082F conflicts with OpRegion 0x0000000000000800-0x000000000000084F (\PMRG) (20240322/utaddress-204)
sept. 01 21:44:37 ORDIBUREAU kernel: ACPI Warning: SystemIO range 0x0000000000000540-0x000000000000054F conflicts with OpRegion 0x0000000000000500-0x000000000000054F (\GPS1) (20240322/utaddress-204)
sept. 01 21:44:37 ORDIBUREAU kernel: ACPI Warning: SystemIO range 0x0000000000000530-0x000000000000053F conflicts with OpRegion 0x0000000000000500-0x000000000000054F (\GPS1) (20240322/utaddress-204)
sept. 01 21:44:37 ORDIBUREAU kernel: ACPI Warning: SystemIO range 0x0000000000000530-0x000000000000053F conflicts with OpRegion 0x0000000000000500-0x000000000000053F (\GPS0) (20240322/utaddress-204)
sept. 01 21:44:37 ORDIBUREAU kernel: ACPI Warning: SystemIO range 0x0000000000000500-0x000000000000052F conflicts with OpRegion 0x0000000000000500-0x000000000000054F (\GPS1) (20240322/utaddress-204)
sept. 01 21:44:37 ORDIBUREAU kernel: ACPI Warning: SystemIO range 0x0000000000000500-0x000000000000052F conflicts with OpRegion 0x0000000000000500-0x000000000000053F (\GPS0) (20240322/utaddress-204)
sept. 01 21:44:37 ORDIBUREAU kernel: lpc_ich: Resource conflict(s) found affecting gpio_ich
sept. 01 21:44:37 ORDIBUREAU kernel: ACPI Warning: SystemIO range 0x0000000000000400-0x000000000000041F conflicts with OpRegion 0x0000000000000400-0x000000000000040F (\SMRG) (20240322/utaddress-204)
sept. 01 21:44:37 ORDIBUREAU kernel: r8169 0000:02:00.0: can't disable ASPM; OS doesn't have ASPM control
sept. 01 21:44:37 ORDIBUREAU kernel: kvm_intel: VM_EXIT_LOAD_IA32_PERF_GLOBAL_CTRL does not work properly. Using workaround
sept. 01 21:44:44 ORDIBUREAU lvm[614]: PV /dev/dm-0 online, VG vgroup_new is complete.
sept. 01 21:44:44 ORDIBUREAU lvm[632]: PV /dev/dm-3 online, VG vgroup is complete.
sept. 01 21:44:46 ORDIBUREAU systemctl[761]: Failed to stop systemd-ask-password-plymouth.path: Unit systemd-ask-password-plymouth.path not loaded.
sept. 01 21:44:46 ORDIBUREAU systemctl[761]: Failed to stop systemd-ask-password-plymouth.service: Unit systemd-ask-password-plymouth.service not loaded.
sept. 01 21:44:46 ORDIBUREAU lightdm[760]: Error getting user list from org.freedesktop.Accounts: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name is not activatable
sept. 01 21:44:47 ORDIBUREAU dbus-broker-launch[690]: Activation request for 'org.freedesktop.Avahi' failed: The systemd unit 'dbus-org.freedesktop.Avahi.service' could not be found.
sept. 01 21:44:47 ORDIBUREAU lightdm[793]: Error getting user list from org.freedesktop.Accounts: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name is not activatable
sept. 01 21:44:47 ORDIBUREAU dbus-broker-launch[690]: Activation request for 'org.freedesktop.home1' failed: The systemd unit 'dbus-org.freedesktop.home1.service' could not be found.
sept. 01 21:44:48 ORDIBUREAU dbus-broker-launch[690]: Activation request for 'org.freedesktop.resolve1' failed: The systemd unit 'dbus-org.freedesktop.resolve1.service' could not be found.
sept. 01 21:44:49 ORDIBUREAU dbus-broker-launch[824]: Service file '/usr/share/dbus-1/services/org.knopwob.dunst.service' is not named after the D-Bus name 'org.freedesktop.Notifications'.
sept. 01 21:44:49 ORDIBUREAU dbus-broker-launch[824]: Service file '/usr/share/dbus-1/services/org.xfce.Thunar.FileManager1.service' is not named after the D-Bus name 'org.freedesktop.FileManager1'.
sept. 01 21:44:49 ORDIBUREAU nm-openvpn[825]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
sept. 01 21:44:50 ORDIBUREAU nm-openvpn[825]: NOTE: setsockopt TCP_NODELAY=1 failed
sept. 01 21:44:50 ORDIBUREAU nm-openvpn[825]: sitnl_send: rtnl: generic error (-101): Network is unreachable
sept. 01 21:44:50 ORDIBUREAU NetworkManager[711]: <warn>  [1725219890.5043] ndisc[0x5a831b0b3f80,"enp2s0"]: solicit: failure sending router solicitation: Opération non permise (1)
sept. 01 21:45:06 ORDIBUREAU lightdm[853]: Error getting user list from org.freedesktop.Accounts: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name is not activatable
sept. 01 21:45:08 ORDIBUREAU dbus-broker-launch[908]: Service file '/usr/share/dbus-1/services/org.knopwob.dunst.service' is not named after the D-Bus name 'org.freedesktop.Notifications'.
sept. 01 21:45:08 ORDIBUREAU dbus-broker-launch[908]: Service file '/usr/share/dbus-1/services/org.xfce.Thunar.FileManager1.service' is not named after the D-Bus name 'org.freedesktop.FileManager1'.
sept. 01 21:45:09 ORDIBUREAU polkitd[962]: Error compiling script /etc/polkit-1/rules.d/10-my-polkit-rules.rules: SyntaxError: parse error (line 9)

seth wrote:

dmesg (look for IO errors)

I don't see any error; should I upload the output (about 1100 lines) somewhere?

seth wrote:

* iotop

Sorry, I have installed it, but I'm not sure what I should do with it; is it possible to use it to monitor the startup?

In any case, thank you very much for the help!

Last edited by LithoUser (2024-09-01 19:57:12)

seth · 2024-09-01 20:39:28

have 2 HDDs, so I've run a test on both of them:

Actually check the entire "smartctl -a" output, the conveyance selftest doesn't tell much.

sudo journalctl -b0 --no-pager

That's only one page of the journal?

I don't see any error; should I upload the output (about 1100 lines) somewhere?

You can post it to 0x0.st,

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

but if you're confident there're no IO errors that's also not necessary.

Sorry, I have installed it, but I'm not sure what I should do with it; is it possible to use it to monitor the startup?

You could switch to another TTY and run it there before and head back while logging in and the disk is still hyperactive.

LithoUser · 2024-09-02 06:12:29

* Result of `sudo smartctl -a /dev/sda`
* Result of `sudo smartctl -a /dev/sdc`

seth wrote:

That's only one page of the journal?

No, that's all for the last boot; but I've configured it in `/etc/systemd/journald.conf` so that it doesn't take too much disk space:

SystemMaxUse=5M
MaxLevelStore=warning

seth wrote:

but if you're confident there're no IO errors that's also not necessary

I'm not confident at all... So: result of `sudo dmesg` Edit: I'm a bit worried that my dmesg might reveal personal info. Could this be the case?

seth wrote:

You could switch to another TTY and run it there before and head back while logging in and the disk is still hyperactive.

Great idea! So the only command writing on disk at this moment (I mean just after lightdm starts) is "ext4lazyinit"; it's writing about 4 MB/s during those 25 seconds. Is this expected?

Last edited by LithoUser (2024-09-02 07:19:09)

seth · 2024-09-02 07:49:15

Neither smartctl nor the dmesg look concerning, though I don't believe the WD to not have had a single raw read error in 40k+ h (so that value is probably BS)
The Seagate has ~270 raw read errors per minute, what's a bit much? I assume it's the cause of the noise and slow-ish in https://wiki.archlinux.org/title/Benchmarking#dd ?
(friendly reminder to always be extra careful when using dd, understand what you're doing, double and triple-check that you've not typo'd in stray blanks or anything)

ext4lazyinit is likely prefetching blocks, https://bbs.archlinux.org/viewtopic.php?id=270111
And here's a SO response from some Ted Ts'o guy - not sure whether he knows anything about ext4, though:
https://superuser.com/questions/1584873 … ables-in-e

Did you recently (re)create the filesystem or somehow run tune2fs in boot scripts or something like that?

LithoUser · 2024-09-02 09:05:25

seth wrote:

ext4lazyinit is likely prefetching blocks

Yes, that was the source of the "problem"; I've added the `no_prefetch_block_bitmaps` option in my /etc/fstab for my HDDs, and there's no more writings; I can connect to my session immediately. However, I don't know if there are any downsides or if this could cause any trouble in the future...

seth wrote:

Did you recently (re)create the filesystem or somehow run tune2fs in boot scripts or something like that?

Not really; I don't think I have ever used tune2fs; however, 2 years ago, I've installed a new hard drive and edited my /etc/fstab (reference: https://bbs.archlinux.org/viewtopic.php?id=275665). I'm not sure if that's exactly what you meant by "recreate the filesystem"...

seth wrote:

The Seagate has ~270 raw read errors per minute, what's a bit much? I assume it's the cause of the noise and slow-ish in https://wiki.archlinux.org/title/Benchmarking#dd ?

Thanks a lot for noticing this! But the wiki talks about SSD drives, and that's an HDD; does it matter?
From what I understand, for benchmarking, I should:
1. cd /somewhere/inside/of/my/HDD
2. dd if=/dev/zero of=./tempfile bs=1M count=1024 conv=fdatasync,notrunc status=progress
3. sudo echo 3 > /proc/sys/vm/drop_caches
4. dd if=tempfile of=/dev/null bs=1M count=1024 status=progress
5. dd if=tempfile of=/dev/null bs=1M count=1024 status=progress
And then I should compare the results; am I right?

Last edited by LithoUser (2024-09-02 09:37:32)

seth · 2024-09-02 11:13:10

dd is HW agnostic, it works on SSDs and HDDs alike.
The 5th step is a cached read, it'll vastly outperform the 4th on, you're interested in the results of step 2 & 4 and want to compare them to the performance on the WD drive.
Also you of course need writing permissions for the tempfile location.

LithoUser · 2024-09-02 11:31:50

So, here are the results; the following test has been run inside of a folder that is in the mountpoint of my Seagate HDD (/dev/sda):

$ LC_ALL=C dd if=/dev/zero of=./tempfile bs=1M count=1024 conv=fdatasync,notrunc status=progress
935329792 bytes (935 MB, 892 MiB) copied, 3 s, 306 MB/s1073741824 bytes (1.1 GB, 1.0 GiB) copied, 3.83276 s, 280 MB/s
1024+0 records in
1024+0 records out
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 5.97485 s, 180 MB/s

$ sudo -i
# echo 3 > /proc/sys/vm/drop_caches
# exit

$ LC_ALL=C dd if=tempfile of=/dev/null bs=1M count=1024 status=progress
918552576 bytes (919 MB, 876 MiB) copied, 4 s, 229 MB/s
1024+0 records in
1024+0 records out
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 4.66329 s, 230 MB/s

seth · 2024-09-02 11:40:11

The sales pamphlet data sheet suggests sustained 255MB/s throughput (probably w/ three asterisks for reading consecutive sectors) but the speed isn't bad and very much in the ballpark of what you'd expect.

Remains the question why you're (still) running the lazy init (now)

Not really; I don't think I have ever used tune2fs; however, 2 years ago, I've installed a new hard drive and edited my /etc/fstab (reference: https://bbs.archlinux.org/viewtopic.php?id=275665). I'm not sure if that's exactly what you meant by "recreate the filesystem"...

No, more like running "makefs", repartitioning the drive etcetc. - maybe some internal housecleaning. You're also not booting w/ dirty filesystems (after a hard reboot) or so?

LithoUser · 2024-09-02 12:20:09

seth wrote:

No, more like running "makefs", repartitioning the drive etcetc.

No, I've never done that since I installed Arch Linux 4 years ago.

seth wrote:

maybe some internal housecleaning

Apart from running `sudo pacman -Scc` from time to time, no, I don't see what I could have done...

I've been trying to minimize the activity on my hard drives a bit, but I don't think it could have come from there? Just in case:

$ cat /etc/systemd/journald.conf
[Journal]
Storage=volatile
SystemMaxUse=5M
RuntimeMaxUse=5M
ForwardToSyslog=no
MaxLevelStore=warning

seth wrote:

You're also not booting w/ dirty filesystems (after a hard reboot) or so?

No, I've never needed to do a hard reboot...

seth wrote:

The Seagate has ~270 raw read errors per minute

How can you tell? I didn't notice it... Is it a sign that this hard disk will soon stop working?

Last edited by LithoUser (2024-09-02 12:23:53)

seth · 2024-09-02 14:20:00

I don't think it could have come from there?

Nope, this is on the FS level - any userspace config won't affect this.
Since the process is finite, you'd expect it to be done at some point, though after 4 years, "some point" should™ be in the past unless something has re-triggered this.

How can you tell?

smart data has the total value and the the power-on hours.
bc can turn that into a ratio

LithoUser · 2024-09-02 14:33:07

seth wrote:

smart data has the total value

OK: Raw_Read_Error_Rate / Power_On_Hours / 60 = 178061006 / 11068 / 60 = 268.13 errors/minute. Thanks!

seth wrote:

Since the process is finite, you'd expect it to be done at some point, though after 4 years, "some point" should™ be in the past unless something has re-triggered this.

Do you think it'd be SMARTer to let it finish, then? In other words: should I remove the `no_prefetch_block_bitmaps` option from my /etc/fstab? After all, it's only a few seconds per day... 365*25/60=152 minutes lost per year... Well, I lost much more than that oversleeping

But above all:

LithoUser wrote:

Is it a sign that this hard disk will soon stop working?

Last edited by LithoUser (2024-09-02 14:33:56)

seth · 2024-09-02 14:44:01

You read Ted - it's only important in extreme cases. And if you don't have backups

Is it a sign that this hard disk will soon stop working?

No. Not if it's static (then it's just the drives strategy to be fast)
Keep an eye on the value and if in a week or so it's up to 300/m, that becomes a reason to be mildly concerned (but also keep in mind that the drive could be powered on for hours w/o any reads - the relation to the actual transaction counts at the bottom of the table is a better indicator for the trajectory)

LithoUser · 2024-09-02 14:53:52

I do have some backups of all my important data. I have an old Synology NAS that still does a pretty good job!

Well, I think I haven't been clear enough: what I meant is, are all those errors (270 per minutes seems huge, considering that I only have this HDD for two years!) the sign that the HDD will soon die?

Arch Linux

#1 2024-09-01 16:07:53

Slowdowns due to disk writes on startup

#2 2024-09-01 16:38:16

Re: Slowdowns due to disk writes on startup

#3 2024-09-01 19:55:34

Re: Slowdowns due to disk writes on startup

#4 2024-09-01 20:39:28

Re: Slowdowns due to disk writes on startup

#5 2024-09-02 06:12:29

Re: Slowdowns due to disk writes on startup

#6 2024-09-02 07:49:15

Re: Slowdowns due to disk writes on startup

#7 2024-09-02 09:05:25

Re: Slowdowns due to disk writes on startup

#8 2024-09-02 11:13:10

Re: Slowdowns due to disk writes on startup

#9 2024-09-02 11:31:50

Re: Slowdowns due to disk writes on startup

#10 2024-09-02 11:40:11

Re: Slowdowns due to disk writes on startup

#11 2024-09-02 12:20:09

Re: Slowdowns due to disk writes on startup

#12 2024-09-02 14:20:00

Re: Slowdowns due to disk writes on startup

#13 2024-09-02 14:33:07

Re: Slowdowns due to disk writes on startup

#14 2024-09-02 14:44:01

Re: Slowdowns due to disk writes on startup

#15 2024-09-02 14:53:52

Re: Slowdowns due to disk writes on startup

Board footer