I/O blocked after booting

I/O blocked after booting

[Massimo B.]

Hello everybody,

I have this issue since years on all my desktop machines (but with almost
identical distribution and configurations):

Sometimes when booting the system, it comes up until the window manager with
login screen appears. But no further login is possible. Trying to login via
virtual terminals, SSH or trying to reboot, it appears that all I/O to the btrfs
is blocked. Also waiting for ~20 minutes doesn't help the filesystem is
blocking.

I thought that might happen on unclean shutdowns or stuff. But it's not
reproducible and also clean shutdowns sometimes lead to the same issue.

First I thought it's some of the btrfsmaintenance jobs. So finally I disabled
all of them:

# grep PERIOD /etc/default/btrfsmaintenance
BTRFS_DEFRAG_PERIOD="none"
BTRFS_BALANCE_PERIOD="none"
BTRFS_SCRUB_PERIOD="monthly"
BTRFS_TRIM_PERIOD="none"

No success.

What I can confirm, after doing a forced reboot by holy SYSRQ series R,E,I,S,U,B
the next startup is always fine and gets a working btrfs.
Then the first line on the screen before doing the reboot are:

sysrq: Keyboard mode set to system default
sysrq: Terminate All Tasks
elogind-daemon[4481]: Received signal 15 [TERM]

BTRFS info (device dm-2): first mount of filesystem 1d677-.....
BTRFS info (device dm-2): using crc32c (crc32c-intel checksum algorithm
BTRFS info (device dm-2): force zstd compression, level 15
BTRFS info (device dm-2): using free space tree
BTRFS warmomg (device dm-0): failed to trim 30 block group(s), last error -512
BTRFS warmomg (device dm-0): failed to trim 1 device(s), last error -512

I guess this dm-0 is my main btrfs on PCIe NVMe.

When successfully mounted the mount looks like this:

/dev/mapper/luks-801... on / type btrfs (rw,noatime,nodiratime,compress-
force=zstd:3,ssd,discard=async,noacl,space_cache=v2,subvolid=524,subvol=/volumes
/root)

Current kernel is 6.6.13-gentoo, though I don't think that is important as I
have the issue for years with all previous kernels.
I'm not only using the self-configured kernel from gentoo-sources but also a
universal binary 6.6.16-gentoo-dist.

I thought, maybe my btrbk run by cron could be the culprit. Looking at the
syslogs, before the blocked I/O I see some very last lines in the log, where
btrbk was started. Right after that the next line is the next boot:

Mar 19 07:43:40 [chronyd] System clock wrong by -3.227396 seconds
Mar 19 07:43:40 [chronyd] System clock was stepped by -3.227396 seconds
Mar 19 07:44:00 [fcron] pam_unix(fcron:session): session opened for user clamav(uid=130) by (uid=0)
Mar 19 07:44:00 [fcron] Job 'fangfrisch -c /etc/fangfrisch.conf refresh' started for user clamav (pid 4977)
Mar 19 07:44:00 [fcron] Job 'ionice -c 3 schedtool -D -e btrbk -c /etc/btrbk/btrbk.conf run cron && /usr/local/bin/1update_btrbksnapshotlinks -c /etc/btrbk/btrbk.conf /mnt/archive/*/* / (truncated)
Mar 19 07:44:00 [fcron] Job 'run-parts /etc/cron.daily' started for user systab (pid 4984)
Mar 19 07:44:00 [fcron] Job 'run-parts /etc/cron.weekly' started for user systab (pid 4987)
Mar 19 07:47:32 [kernel] Linux version 6.6.13-gentoo (root@gentoo) (gcc (Gentoo 13.2.1_p20230826 p7) 13.2.1 20230826, GNU ld (Gentoo 2.40 p7) 2.40.0) #1 SMP PREEMPT_DYNAMIC Mon Jan 22 11:11:15 CET 2024

Actually btrbk works fine when the system is up and running, either started
manually or from the cron job. What could happen to block all btrfs IO? How can
I debug that?

Best regards,
Massimo

Re: I/O blocked after booting

[HAN Yuwei]

[-- Attachment #1.1: Type: text/plain, Size: 3826 bytes --]

在 2024/3/21 21:13, Massimo B. 写道:
> Hello everybody,
>
> I have this issue since years on all my desktop machines (but with almost
> identical distribution and configurations):
>
> Sometimes when booting the system, it comes up until the window manager with
> login screen appears. But no further login is possible. Trying to login via
> virtual terminals, SSH or trying to reboot, it appears that all I/O to the btrfs
> is blocked. Also waiting for ~20 minutes doesn't help the filesystem is
> blocking.

Since you can have login screen, btrfs had read all programs, thus done 
effective IO.

Why do you think login issue is due to btrfs I/O? any logs?

> I thought that might happen on unclean shutdowns or stuff. But it's not
> reproducible and also clean shutdowns sometimes lead to the same issue.
>
> First I thought it's some of the btrfsmaintenance jobs. So finally I disabled
> all of them:
>
> # grep PERIOD /etc/default/btrfsmaintenance
> BTRFS_DEFRAG_PERIOD="none"
> BTRFS_BALANCE_PERIOD="none"
> BTRFS_SCRUB_PERIOD="monthly"
> BTRFS_TRIM_PERIOD="none"
>
> No success.
>
> What I can confirm, after doing a forced reboot by holy SYSRQ series R,E,I,S,U,B
> the next startup is always fine and gets a working btrfs.
> Then the first line on the screen before doing the reboot are:
>
> sysrq: Keyboard mode set to system default
> sysrq: Terminate All Tasks
> elogind-daemon[4481]: Received signal 15 [TERM]
>
> BTRFS info (device dm-2): first mount of filesystem 1d677-.....
> BTRFS info (device dm-2): using crc32c (crc32c-intel checksum algorithm
> BTRFS info (device dm-2): force zstd compression, level 15
> BTRFS info (device dm-2): using free space tree
> BTRFS warmomg (device dm-0): failed to trim 30 block group(s), last error -512
> BTRFS warmomg (device dm-0): failed to trim 1 device(s), last error -512
>
> I guess this dm-0 is my main btrfs on PCIe NVMe.
>
> When successfully mounted the mount looks like this:
>
> /dev/mapper/luks-801... on / type btrfs (rw,noatime,nodiratime,compress-
> force=zstd:3,ssd,discard=async,noacl,space_cache=v2,subvolid=524,subvol=/volumes
> /root)
>
> Current kernel is 6.6.13-gentoo, though I don't think that is important as I
> have the issue for years with all previous kernels.
> I'm not only using the self-configured kernel from gentoo-sources but also a
> universal binary 6.6.16-gentoo-dist.
>
> I thought, maybe my btrbk run by cron could be the culprit. Looking at the
> syslogs, before the blocked I/O I see some very last lines in the log, where
> btrbk was started. Right after that the next line is the next boot:
>
> Mar 19 07:43:40 [chronyd] System clock wrong by -3.227396 seconds
> Mar 19 07:43:40 [chronyd] System clock was stepped by -3.227396 seconds
> Mar 19 07:44:00 [fcron] pam_unix(fcron:session): session opened for user clamav(uid=130) by (uid=0)
> Mar 19 07:44:00 [fcron] Job 'fangfrisch -c /etc/fangfrisch.conf refresh' started for user clamav (pid 4977)
> Mar 19 07:44:00 [fcron] Job 'ionice -c 3 schedtool -D -e btrbk -c /etc/btrbk/btrbk.conf run cron && /usr/local/bin/1update_btrbksnapshotlinks -c /etc/btrbk/btrbk.conf /mnt/archive/*/* / (truncated)
> Mar 19 07:44:00 [fcron] Job 'run-parts /etc/cron.daily' started for user systab (pid 4984)
> Mar 19 07:44:00 [fcron] Job 'run-parts /etc/cron.weekly' started for user systab (pid 4987)
> Mar 19 07:47:32 [kernel] Linux version 6.6.13-gentoo (root@gentoo) (gcc (Gentoo 13.2.1_p20230826 p7) 13.2.1 20230826, GNU ld (Gentoo 2.40 p7) 2.40.0) #1 SMP PREEMPT_DYNAMIC Mon Jan 22 11:11:15 CET 2024
>
> Actually btrbk works fine when the system is up and running, either started
> manually or from the cron job. What could happen to block all btrfs IO? How can
> I debug that?
>
> Best regards,
> Massimo
>

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: I/O blocked after booting

[Qu Wenruo]

在 2024/3/21 23:43, Massimo B. 写道:
> Hello everybody,
>
> I have this issue since years on all my desktop machines (but with almost
> identical distribution and configurations):
>
> Sometimes when booting the system, it comes up until the window manager with
> login screen appears. But no further login is possible. Trying to login via
> virtual terminals, SSH or trying to reboot, it appears that all I/O to the btrfs
> is blocked. Also waiting for ~20 minutes doesn't help the filesystem is
> blocking.
>
> I thought that might happen on unclean shutdowns or stuff. But it's not
> reproducible and also clean shutdowns sometimes lead to the same issue.
>
> First I thought it's some of the btrfsmaintenance jobs. So finally I disabled
> all of them:
>
> # grep PERIOD /etc/default/btrfsmaintenance
> BTRFS_DEFRAG_PERIOD="none"
> BTRFS_BALANCE_PERIOD="none"
> BTRFS_SCRUB_PERIOD="monthly"
> BTRFS_TRIM_PERIOD="none"
>
> No success.
>
> What I can confirm, after doing a forced reboot by holy SYSRQ series R,E,I,S,U,B
> the next startup is always fine and gets a working btrfs.
> Then the first line on the screen before doing the reboot are:
>
> sysrq: Keyboard mode set to system default
> sysrq: Terminate All Tasks
> elogind-daemon[4481]: Received signal 15 [TERM]
>
> BTRFS info (device dm-2): first mount of filesystem 1d677-.....
> BTRFS info (device dm-2): using crc32c (crc32c-intel checksum algorithm
> BTRFS info (device dm-2): force zstd compression, level 15
> BTRFS info (device dm-2): using free space tree
> BTRFS warmomg (device dm-0): failed to trim 30 block group(s), last error -512
> BTRFS warmomg (device dm-0): failed to trim 1 device(s), last error -512
>
> I guess this dm-0 is my main btrfs on PCIe NVMe.
>
> When successfully mounted the mount looks like this:
>
> /dev/mapper/luks-801... on / type btrfs (rw,noatime,nodiratime,compress-
> force=zstd:3,ssd,discard=async,noacl,space_cache=v2,subvolid=524,subvol=/volumes
> /root)

Disable disable (nodiscard mount option), as it looks like there is
something wrong with the auto discard, then retry.

This is mostly related to your NVME device's discard implementation, and
I believe manually fstrim may be a better and more reliable solution.

Thanks,
Qu

>
> Current kernel is 6.6.13-gentoo, though I don't think that is important as I
> have the issue for years with all previous kernels.
> I'm not only using the self-configured kernel from gentoo-sources but also a
> universal binary 6.6.16-gentoo-dist.
>
> I thought, maybe my btrbk run by cron could be the culprit. Looking at the
> syslogs, before the blocked I/O I see some very last lines in the log, where
> btrbk was started. Right after that the next line is the next boot:
>
> Mar 19 07:43:40 [chronyd] System clock wrong by -3.227396 seconds
> Mar 19 07:43:40 [chronyd] System clock was stepped by -3.227396 seconds
> Mar 19 07:44:00 [fcron] pam_unix(fcron:session): session opened for user clamav(uid=130) by (uid=0)
> Mar 19 07:44:00 [fcron] Job 'fangfrisch -c /etc/fangfrisch.conf refresh' started for user clamav (pid 4977)
> Mar 19 07:44:00 [fcron] Job 'ionice -c 3 schedtool -D -e btrbk -c /etc/btrbk/btrbk.conf run cron && /usr/local/bin/1update_btrbksnapshotlinks -c /etc/btrbk/btrbk.conf /mnt/archive/*/* / (truncated)
> Mar 19 07:44:00 [fcron] Job 'run-parts /etc/cron.daily' started for user systab (pid 4984)
> Mar 19 07:44:00 [fcron] Job 'run-parts /etc/cron.weekly' started for user systab (pid 4987)
> Mar 19 07:47:32 [kernel] Linux version 6.6.13-gentoo (root@gentoo) (gcc (Gentoo 13.2.1_p20230826 p7) 13.2.1 20230826, GNU ld (Gentoo 2.40 p7) 2.40.0) #1 SMP PREEMPT_DYNAMIC Mon Jan 22 11:11:15 CET 2024
>
> Actually btrbk works fine when the system is up and running, either started
> manually or from the cron job. What could happen to block all btrfs IO? How can
> I debug that?
>
> Best regards,
> Massimo
>

Re: I/O blocked after booting

[Massimo B.]

On Thu, 2024-03-28 at 20:40 +1030, Qu Wenruo wrote:
> Disable disable (nodiscard mount option), as it looks like there is
> something wrong with the auto discard, then retry.
> 
> This is mostly related to your NVME device's discard implementation, and
> I believe manually fstrim may be a better and more reliable solution.

Ok, I'm going to try.
Beside that I'm using different NVMe models and also an SATA SSD "Samsung SSD
860" and all are affected by that issue.

So you mean a daily cronjob for fstrim would be preferable?

Trying  fstrim -a -v  here with the very common Samsung SSD 970 PRO 1TB NVMe,
the command started discarding small partitions:

/boot/efi: 31,6 MiB (33183744 bytes) trimmed on /dev/nvme1n1p1
/boot: 0 B (0 bytes) trimmed on /dev/nvme1n1p2

but then does not return after 20 minutes. There is no IO on the disk which
might be ok for fstrim only communicating with the controler. But fstrim process
has some CPU usage...

And I see the same syslog entries after starting the fstrim:

Mar 28 11:38:26 [kernel] [14826.740669] BTRFS warning (device dm-0): failed to trim 698 block group(s), last error -512
Mar 28 11:38:26 [kernel] [14826.741731] BTRFS warning (device dm-0): failed to trim 1 device(s), last error -512

Best regards,
Massimo

Re: I/O blocked after booting

[Massimo B.]

On Thu, 2024-03-28 at 11:39 +0100, Massimo B. wrote:

> Mar 28 11:38:26 [kernel] [14826.740669] BTRFS warning (device dm-0): failed to
> trim 698 block group(s), last error -512
> Mar 28 11:38:26 [kernel] [14826.741731] BTRFS warning (device dm-0): failed to
> trim 1 device(s), last error -512


I have set nodiscard now on all my btrfs on SSDs...
For not rebooting I did  mount -o remount,nodiscard /
and I see in the syslog: turning off async discard

 Eventhough fstrim was finishing one time with
/: 157,3 GiB (168907370496 bytes) trimmed on /dev/mapper/luks-6745....

... now running again, it does not return, and in the syslog I see:
[kernel] BTRFS warning (device dm-0): failed to trim 143 block group(s), last
error -512

dmsetup table
shows allow_discards on that device.


Again I did  mount -o remount,nodiscard /

But this time I don't see in the syslog  "turning off async discard"   so it
seems to be still disabled.

grep " / " /proc/mounts
shows nothing about discard or nodiscard in the options.

What can I do about that failed to trim?
I have tried this on different disks like

Samsung SSD 970 EVO Plus 1TB NVMe
and
Samsung SSD 860 EVO 1TB SATA

Trying again after the failed to trim, I got it finished again with
156,8 GiB (168413265920 bytes) trimmed

Should fstrim be fast if it was just finished some minutes before? Why there are
again more than 100GiB to be trimmed shortly after the last run?

Is there anything broken with the trim on these devices?

Best regards,
Massimo

Re: I/O blocked after booting

[Roman Mamedov]

On Thu, 28 Mar 2024 15:55:15 +0100
"Massimo B." <massimo.b@gmx.net> wrote:

> What can I do about that failed to trim?
> I have tried this on different disks like
> 
> Samsung SSD 970 EVO Plus 1TB NVMe
> and
> Samsung SSD 860 EVO 1TB SATA
> 
> Trying again after the failed to trim, I got it finished again with
> 156,8 GiB (168413265920 bytes) trimmed
> 
> Should fstrim be fast if it was just finished some minutes before? Why there are
> again more than 100GiB to be trimmed shortly after the last run?
> 
> Is there anything broken with the trim on these devices?

860 EVO do have a bad history with TRIM and NCQ on some controllers:
https://bugzilla.kernel.org/show_bug.cgi?id=203475
But IIRC the affected combinations should have a fix in the kernel by now.

970 is not known to be affected.

Most importantly, do you see any ata errors in dmesg? Such as "SEND FPDMA
QUEUED", or any other.

-- 
With respect,
Roman

Re: I/O blocked after booting

[Qu Wenruo]

在 2024/3/29 01:25, Massimo B. 写道:
> On Thu, 2024-03-28 at 11:39 +0100, Massimo B. wrote:
>
>> Mar 28 11:38:26 [kernel] [14826.740669] BTRFS warning (device dm-0): failed to
>> trim 698 block group(s), last error -512
>> Mar 28 11:38:26 [kernel] [14826.741731] BTRFS warning (device dm-0): failed to
>> trim 1 device(s), last error -512
>
>
> I have set nodiscard now on all my btrfs on SSDs...
> For not rebooting I did  mount -o remount,nodiscard /
> and I see in the syslog: turning off async discard

I mean you should not do any fstrim/discard to see if everything works
fine first.

This is to make sure the problem is really from the trim/discard part.

Thanks,
Qu
>
>   Eventhough fstrim was finishing one time with
> /: 157,3 GiB (168907370496 bytes) trimmed on /dev/mapper/luks-6745....
>
> ... now running again, it does not return, and in the syslog I see:
> [kernel] BTRFS warning (device dm-0): failed to trim 143 block group(s), last
> error -512
>
> dmsetup table
> shows allow_discards on that device.
>
>
> Again I did  mount -o remount,nodiscard /
>
> But this time I don't see in the syslog  "turning off async discard"   so it
> seems to be still disabled.
>
> grep " / " /proc/mounts
> shows nothing about discard or nodiscard in the options.
>
> What can I do about that failed to trim?
> I have tried this on different disks like
>
> Samsung SSD 970 EVO Plus 1TB NVMe
> and
> Samsung SSD 860 EVO 1TB SATA
>
> Trying again after the failed to trim, I got it finished again with
> 156,8 GiB (168413265920 bytes) trimmed
>
> Should fstrim be fast if it was just finished some minutes before? Why there are
> again more than 100GiB to be trimmed shortly after the last run?
>
> Is there anything broken with the trim on these devices?
>
> Best regards,
> Massimo