btrfs scrub prevents system suspend

btrfs scrub prevents system suspend

[Trolli Schmittlauch]

[-- Attachment #1.1.1: Type: text/plain, Size: 753 bytes --]

Hi

I noticed that a running `btrfs scrub` operation prevents a system from suspending to RAM. I wonder whether this is a known issue and being worked on.
A kernel trace leading to btrfs scrub can be found attached.

My current system setup:
NixOS 19.09
kernel 4.19.98
btrfs-progs v5.2.1

I can also try to reproduce this issue with a more recent kernel version. (am currently on a train with bad link)

In the downstream bug report [1] suggests that this could be resolved/ worked around in systemd by adding `Conflicts=suspend.target sleep.target? to the scrubbing service's systemd unit.
So should this be managed at btrfs (kernel) level or in systemd?

All the best
schmittlauch

[1] https://github.com/NixOS/nixpkgs/issues/79086

[-- Attachment #1.1.2: btrfs-scrub-suspend_partial.log --]
[-- Type: text/x-log, Size: 4125 bytes --]

systemd[1]: Starting Suspend...
systemd-sleep[15702]: Suspending system...
kernel: PM: Syncing filesystems ... done.
kernel: Freezing user space processes ... 
kernel: Freezing of tasks failed after 20.007 seconds (1 tasks refusing to freeze, wq_busy=0):
kernel: btrfs           D    0 12483      1 0x00000004
kernel: Call Trace:
kernel:  ? __schedule+0x1f4/0x820
kernel:  ? scrub_missing_raid56_end_io+0x40/0x40 [btrfs]
kernel:  schedule+0x28/0x80
kernel:  scrub_add_page_to_rd_bio+0x211/0x2c0 [btrfs]
kernel:  ? wait_woken+0x80/0x80
kernel:  scrub_pages+0x239/0x430 [btrfs]
kernel:  scrub_stripe+0x72b/0xee0 [btrfs]
kernel:  ? kmem_cache_alloc+0x158/0x1c0
kernel:  ? btrfs_check_space_for_delayed_refs+0xc7/0x100 [btrfs]
kernel:  ? btrfs_block_rsv_check+0x20/0x60 [btrfs]
kernel:  ? scrub_chunk+0xd2/0x130 [btrfs]
kernel:  scrub_chunk+0xd2/0x130 [btrfs]
kernel:  scrub_enumerate_chunks+0x20f/0x570 [btrfs]
kernel:  ? wait_woken+0x60/0x80
kernel:  btrfs_scrub_dev+0x1e2/0x580 [btrfs]
kernel:  ? __kmalloc_track_caller+0x167/0x210
kernel:  btrfs_ioctl+0xfea/0x31b0 [btrfs]
kernel:  ? __switch_to_asm+0x41/0x70
kernel:  ? __switch_to_asm+0x35/0x70
kernel:  ? __switch_to_asm+0x41/0x70
kernel:  ? __switch_to_asm+0x35/0x70
kernel:  ? do_vfs_ioctl+0xa4/0x620
kernel:  do_vfs_ioctl+0xa4/0x620
kernel:  ? __switch_to_asm+0x41/0x70
kernel:  ? __switch_to_asm+0x35/0x70
kernel:  ? __switch_to_asm+0x41/0x70
kernel:  ? get_task_io_context+0x43/0x80
kernel:  ksys_ioctl+0x60/0x90
kernel:  ? __switch_to+0x115/0x440
kernel:  __x64_sys_ioctl+0x16/0x20
kernel:  do_syscall_64+0x4e/0x100
kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xa9
kernel: RIP: 0033:0x7f7da656cb57
kernel: Code: Bad RIP value.
kernel: RSP: 002b:00007f7da647dd48 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
kernel: RAX: ffffffffffffffda RBX: 0000000000b163e0 RCX: 00007f7da656cb57
kernel: RDX: 0000000000b163e0 RSI: 00000000c400941b RDI: 0000000000000003
kernel: RBP: 0000000000000000 R08: 00007f7da647e700 R09: 0000000000000000
kernel: R10: 00007f7da647e700 R11: 0000000000000246 R12: 00007ffd7f26ddce
kernel: R13: 00007ffd7f26ddcf R14: 00007f7da647e700 R15: 00007f7da67c9000
kernel: OOM killer enabled.
kernel: Restarting tasks ... done.
kernel: PM: suspend exit
kernel: PM: suspend entry (s2idle)
rtkit-daemon[2121]: Demoted 5 threads.
kernel: PM: Syncing filesystems ... done.
kernel: Freezing user space processes ... 
kernel: Freezing of tasks failed after 20.001 seconds (1 tasks refusing to freeze, wq_busy=0):
kernel: btrfs           D    0 12483      1 0x00000004
kernel: Call Trace:
kernel:  ? __schedule+0x1f4/0x820
kernel:  ? scrub_missing_raid56_end_io+0x40/0x40 [btrfs]
kernel:  schedule+0x28/0x80
kernel:  scrub_add_page_to_rd_bio+0x211/0x2c0 [btrfs]
kernel:  ? wait_woken+0x80/0x80
kernel:  scrub_pages+0x239/0x430 [btrfs]
kernel:  ? btrfs_lookup_csums_range+0x93/0x450 [btrfs]
kernel:  scrub_stripe+0x72b/0xee0 [btrfs]
kernel:  ? start_transaction+0xef/0x3f0 [btrfs]
kernel:  ? kmem_cache_alloc+0x158/0x1c0
kernel:  ? btrfs_check_space_for_delayed_refs+0xc7/0x100 [btrfs]
kernel:  ? btrfs_block_rsv_check+0x20/0x60 [btrfs]
kernel:  ? scrub_chunk+0xd2/0x130 [btrfs]
kernel:  ? scrub_chunk+0xd2/0x130 [btrfs]
kernel:  ? scrub_enumerate_chunks+0x20f/0x570 [btrfs]
kernel:  ? wait_woken+0x60/0x80
kernel:  ? btrfs_scrub_dev+0x1e2/0x580 [btrfs]
kernel:  ? __kmalloc_track_caller+0x167/0x210
kernel:  ? btrfs_ioctl+0xfea/0x31b0 [btrfs]
kernel:  ? __switch_to_asm+0x41/0x70
kernel:  ? __switch_to_asm+0x35/0x70
kernel:  ? __switch_to_asm+0x41/0x70
kernel:  ? __switch_to_asm+0x35/0x70
kernel:  ? do_vfs_ioctl+0xa4/0x620
kernel:  ? do_vfs_ioctl+0xa4/0x620
kernel:  ? __switch_to_asm+0x41/0x70
kernel:  ? __switch_to_asm+0x35/0x70
kernel:  ? __switch_to_asm+0x41/0x70
kernel:  ? get_task_io_context+0x43/0x80
kernel:  ? ksys_ioctl+0x60/0x90
kernel:  ? __switch_to+0x115/0x440
kernel:  ? __x64_sys_ioctl+0x16/0x20
kernel:  ? do_syscall_64+0x4e/0x100
kernel:  ? entry_SYSCALL_64_after_hwframe+0x44/0xa9
kernel: OOM killer enabled.
kernel: Restarting tasks ... done.

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

Re: btrfs scrub prevents system suspend

[Trolli Schmittlauch]

[-- Attachment #1.1.1: Type: text/plain, Size: 87 bytes --]

I can confirm that this issue still appears in a recent 5.4 kernel, see attached log.

[-- Attachment #1.1.2: btrfsscrub_suspend_54.log --]
[-- Type: text/x-log, Size: 5257 bytes --]

systemd[1]: Starting Pre-Sleep Actions...
systemd[1]: Starting TLP suspend/resume...
systemd[1]: pre-sleep.service: Succeeded.
systemd[1]: Started Pre-Sleep Actions.
systemd[1]: Started TLP suspend/resume.
systemd[1]: Reached target Sleep.
systemd[1]: Starting Suspend...
systemd-sleep[22694]: Suspending system...
kernel: PM: suspend entry (deep)
kernel: Filesystems sync: 0.285 seconds
kernel: Freezing user space processes ... 
kernel: Freezing of tasks failed after 20.004 seconds (1 tasks refusing to freeze, wq_busy=0):
kernel: btrfs           R  running task        0 22389      1 0x00004004
kernel: Call Trace:
kernel:  ? __schedule+0x35f/0x6a0
kernel:  ? scrub_missing_raid56_end_io+0x40/0x40 [btrfs]
kernel:  ? schedule+0x2f/0xa0
kernel:  ? scrub_add_page_to_rd_bio+0x22c/0x2e0 [btrfs]
kernel:  ? wait_woken+0x80/0x80
kernel:  ? scrub_pages+0x236/0x420 [btrfs]
kernel:  ? scrub_stripe+0x718/0xeb0 [btrfs]
kernel:  ? btrfs_create_pending_block_groups+0xc0/0x230 [btrfs]
kernel:  ? kmem_cache_alloc+0x158/0x210
kernel:  ? join_transaction+0x22/0x3e0 [btrfs]
kernel:  ? scrub_chunk+0xd8/0x140 [btrfs]
kernel:  ? scrub_chunk+0xd8/0x140 [btrfs]
kernel:  ? scrub_enumerate_chunks+0x1f8/0x560 [btrfs]
kernel:  ? woken_wake_function+0x10/0x20
kernel:  ? btrfs_scrub_dev+0x1f4/0x590 [btrfs]
kernel:  ? _cond_resched+0x15/0x30
kernel:  ? __kmalloc_track_caller+0x169/0x250
kernel:  ? btrfs_ioctl+0xf0d/0x3230 [btrfs]
kernel:  ? btrfs_ioctl+0xf57/0x3230 [btrfs]
kernel:  ? do_vfs_ioctl+0xa4/0x620
kernel:  ? do_vfs_ioctl+0xa4/0x620
kernel:  ? ksys_ioctl+0x60/0x90
kernel:  ? __switch_to_asm+0x40/0x70
kernel:  ? __x64_sys_ioctl+0x16/0x20
kernel:  ? do_syscall_64+0x4e/0x120
kernel:  ? entry_SYSCALL_64_after_hwframe+0x44/0xa9
kernel: OOM killer enabled.
kernel: Restarting tasks ... done.
X[1517]: (EE) client bug: timer event20 tap: offset negative (-14101ms)
rtkit-daemon[2131]: The canary thread is apparently starving. Taking action.
systemd[1]: NetworkManager-dispatcher.service: Succeeded.
rtkit-daemon[2131]: Demoting known real-time threads.
rtkit-daemon[2131]: Successfully demoted thread 8662 of process 30654 (/nix/store/bzr1jrf17ypd6l1rhxi4zn572sa0288b-firefox-unwrapped-7).
rtkit-daemon[2131]: Successfully demoted thread 5305 of process 4568 (/nix/store/bzr1jrf17ypd6l1rhxi4zn572sa0288b-firefox-unwrapped-7).
rtkit-daemon[2131]: Successfully demoted thread 4581 of process 4518 (/nix/store/bzr1jrf17ypd6l1rhxi4zn572sa0288b-firefox-unwrapped-7).
rtkit-daemon[2131]: Successfully demoted thread 2198 of process 2123 (/nix/store/kbvkchb68g00clwqav4kfy934navrrlc-pulseaudio-12.2/bin).
rtkit-daemon[2131]: Successfully demoted thread 2197 of process 2123 (/nix/store/kbvkchb68g00clwqav4kfy934navrrlc-pulseaudio-12.2/bin).
rtkit-daemon[2131]: Successfully demoted thread 2123 of process 2123 (/nix/store/kbvkchb68g00clwqav4kfy934navrrlc-pulseaudio-12.2/bin).
rtkit-daemon[2131]: Demoted 6 threads.
nscd[22558]: 22558 checking for monitored file `/etc/netgroup': No such file or directory
kernel: PM: suspend exit
kernel: PM: suspend entry (s2idle)
xsession[1939]: Connecting to deprecated signal QDBusConnectionInterface::serviceOwnerChanged(QString,QString,QString)
kernel: Filesystems sync: 0.374 seconds
kernel: Freezing user space processes ... 
kernel: Freezing of tasks failed after 20.000 seconds (1 tasks refusing to freeze, wq_busy=0):
kernel: btrfs           D    0 22389      1 0x00004004
kernel: Call Trace:
kernel:  ? __schedule+0x218/0x6a0
kernel:  ? scrub_missing_raid56_end_io+0x40/0x40 [btrfs]
kernel:  schedule+0x2f/0xa0
kernel:  scrub_add_page_to_rd_bio+0x22c/0x2e0 [btrfs]
kernel:  ? wait_woken+0x80/0x80
kernel:  scrub_pages+0x236/0x420 [btrfs]
kernel:  scrub_stripe+0x718/0xeb0 [btrfs]
kernel:  ? btrfs_create_pending_block_groups+0xc0/0x230 [btrfs]
kernel:  ? kmem_cache_alloc+0x158/0x210
kernel:  ? join_transaction+0x22/0x3e0 [btrfs]
kernel:  ? scrub_chunk+0xd8/0x140 [btrfs]
kernel:  scrub_chunk+0xd8/0x140 [btrfs]
kernel:  scrub_enumerate_chunks+0x1f8/0x560 [btrfs]
kernel:  ? woken_wake_function+0x10/0x20
kernel:  btrfs_scrub_dev+0x1f4/0x590 [btrfs]
kernel:  ? _cond_resched+0x15/0x30
kernel:  ? __kmalloc_track_caller+0x169/0x250
kernel:  ? btrfs_ioctl+0xf0d/0x3230 [btrfs]
kernel:  btrfs_ioctl+0xf57/0x3230 [btrfs]
kernel:  ? do_vfs_ioctl+0xa4/0x620
kernel:  do_vfs_ioctl+0xa4/0x620
kernel:  ksys_ioctl+0x60/0x90
kernel:  ? __switch_to_asm+0x40/0x70
kernel:  __x64_sys_ioctl+0x16/0x20
kernel:  do_syscall_64+0x4e/0x120
kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xa9
kernel: RIP: 0033:0x7fbf64f62b57
kernel: Code: Bad RIP value.
kernel: RSP: 002b:00007fbf64e73d48 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
kernel: RAX: ffffffffffffffda RBX: 0000000000fd33e0 RCX: 00007fbf64f62b57
kernel: RDX: 0000000000fd33e0 RSI: 00000000c400941b RDI: 0000000000000003
kernel: RBP: 0000000000000000 R08: 00007fbf64e74700 R09: 0000000000000000
kernel: R10: 00007fbf64e74700 R11: 0000000000000246 R12: 00007ffe6edbc67e
kernel: R13: 00007ffe6edbc67f R14: 00007fbf64e74700 R15: 00007fbf651bf000
kernel: OOM killer enabled.
rtkit-daemon[2131]: The canary thread is apparently starving. Taking action.
kernel: Restarting tasks ... done.

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