Bug 1165374

Summary:	btrfs: dmesg flooded with BTRFS info (device dm-2): found 1 extents, command btrfs balance stuck
Product:	[openSUSE] openSUSE Distribution	Reporter:	Olaf Hering <ohering>
Component:	Kernel	Assignee:	E-mail List <kernel-maintainers>
Status:	RESOLVED FIXED	QA Contact:	E-mail List <qa-bugs>
Severity:	Normal
Priority:	P5 - None	CC:	msuchanek
Version:	Leap 15.1
Target Milestone:	---
Hardware:	x86-64
OS:	Linux
See Also:	http://bugzilla.suse.com/show_bug.cgi?id=1163994
Whiteboard:
Found By:	---	Services Priority:
Business Priority:		Blocker:	---
Marketing QA Status:	---	IT Deployment:	---
Attachments:	syslog-btrfs-suspend.txt

Description Olaf Hering 2020-03-01 20:00:17 UTC

Leap 15.1, 4.12.14-lp151.28.36-default #1 SMP Fri Dec 6 13:50:27 UTC 2019 (8f4a495) x86_64

The cron job is running since hours:

  480 ? Ss     0:00 /bin/sh /usr/share/btrfsmaintenance/btrfs-scrub.sh
  502 ? S      0:00  \_ /bin/sh /usr/share/btrfsmaintenance/btrfs-scrub.sh
  512 ? Sl     2:21  |   \_ btrfs scrub start -Bd /
  503 ? S      0:00  \_ /bin/sh /usr/share/btrfsmaintenance/btrfs-scrub.sh
  506 ? S      0:00      \_ cat
  484 ? Ss     0:00 /bin/sh /usr/share/btrfsmaintenance/btrfs-balance.sh
  495 ? S      0:00  \_ /bin/sh /usr/share/btrfsmaintenance/btrfs-balance.sh
  583 ? D    391:14  |   \_ btrfs balance start -v -dusage 1 /
  496 ? S      0:00  \_ /bin/sh /usr/share/btrfsmaintenance/btrfs-balance.sh
  501 ? S      0:00      \_ cat

Mar 01 00:00:07 latitude systemd[1]: Started Discard unused blocks on a mounted filesystem.
Mar 01 00:00:07 latitude systemd[1]: Starting Rotate log files...
Mar 01 00:00:07 latitude systemd[1]: Started Scrub btrfs filesystem, verify block checksums.
Mar 01 00:00:07 latitude systemd[1]: Starting update of the root trust anchor for DNSSEC validation in unbound...
Mar 01 00:00:07 latitude systemd[1]: Starting Do daily mandb update...
Mar 01 00:00:07 latitude systemd[1]: Started Balance block groups on a btrfs filesystem.
Mar 01 00:00:07 latitude btrfs-balance.sh[484]: Before balance of /
Mar 01 00:00:07 latitude systemd[1]: Started Rotate log files.
Mar 01 00:00:07 latitude btrfs-scrub.sh[480]: Running scrub on /
Mar 01 00:00:07 latitude btrfs-trim.sh[475]: Running fstrim on /
Mar 01 00:00:07 latitude btrfs-balance.sh[484]: Data, single: total=291.96GiB, used=248.47GiB
Mar 01 00:00:07 latitude btrfs-balance.sh[484]: System, single: total=32.00MiB, used=48.00KiB
Mar 01 00:00:07 latitude btrfs-balance.sh[484]: Metadata, single: total=8.01GiB, used=5.67GiB
Mar 01 00:00:07 latitude btrfs-balance.sh[484]: GlobalReserve, single: total=512.00MiB, used=0.00B
Mar 01 00:00:07 latitude btrfs-balance.sh[484]: Filesystem                                       Size  Used Avail Use% Mounted on
Mar 01 00:00:07 latitude btrfs-balance.sh[484]: /dev/mapper/$NAME  323G  274G   47G  86% /
Mar 01 00:00:07 latitude kernel: BTRFS info (device dm-2): relocating block group 650800791552 flags data
Mar 01 00:00:07 latitude systemd[1]: Started update of the root trust anchor for DNSSEC validation in unbound.
Mar 01 00:00:07 latitude systemd[1]: Started Do daily mandb update.
Mar 01 00:00:10 latitude kernel: BTRFS info (device dm-2): relocating block group 650800791552 flags data
Mar 01 00:00:13 latitude btrfs-balance.sh[484]: Done, had to relocate 0 out of 307 chunks
Mar 01 00:00:13 latitude kernel: BTRFS info (device dm-2): relocating block group 650800791552 flags data
Mar 01 00:00:15 latitude kernel: BTRFS info (device dm-2): relocating block group 650800791552 flags data
Mar 01 00:00:18 latitude kernel: BTRFS info (device dm-2): relocating block group 669846077440 flags data
Mar 01 00:00:23 latitude kernel: btrfs_printk: 44 callbacks suppressed
Mar 01 00:00:28 latitude kernel: btrfs_printk: 49 callbacks suppressed
Mar 01 00:00:33 latitude kernel: btrfs_printk: 20 callbacks suppressed
Mar 01 00:08:39 latitude btrfs-trim.sh[475]: /: 52.3 GiB (56112553984 bytes) trimmed
Mar 01 00:08:48 latitude kernel: btrfs_printk: 4 callbacks suppressed

Since this time dmesg (and syslog!) is flooded:
...
[133288.707878] BTRFS info (device dm-2): found 1 extents
[133288.789487] BTRFS info (device dm-2): found 1 extents
[133288.863970] BTRFS info (device dm-2): found 1 extents
[133288.942187] BTRFS info (device dm-2): found 1 extents
...

Situation unclear: will shutdown or suspend trash my filesystem?

Comment 1 Olaf Hering 2020-03-02 08:01:45 UTC

Created attachment 831662 [details]
syslog-btrfs-suspend.txt

killall -v btrfs does nothing
suspend fails too

Will it ever recover?

Comment 2 Michal Suchanek 2020-03-02 10:35:24 UTC

Seems to recover, eventually. But it also seems creating a snapshot in this state (eg by adding/removing packages with zypper) crashes the system.

This should be resolved with next MU or KOTD.