rsync hang during intense filesystem activity

[Valmar33]

Using bcachefs master ~ commit 17299843342b6095a7853220aeb4ae1d45ab2ba5

For context, I have a whole KDE Git installation on my bcachefs partition, used as a data partition separated from my root partition.

When I have this instance of KDE running, and an additional rsync task pushing a ton of data to a backup drive that is also bcachefs-based ~ 250 GB including KDE, massive games files, etc ~ the rsync task will occasionally just get stuck forever more.

bcachefs super:

Device:                                     (unknown device)
External UUID:                              8d86b6aa-0ed4-4335-b10d-9f8f990832e5
Internal UUID:                              929a67ea-0da8-4eba-98b0-4e8891559f60
Magic number:                               c68573f6-66ce-90a9-d96a-60cf803df7ef
Device index:                               0
Label:                                      LinuxBackup
Version:                                    1.7: mi_btree_bitmap
Version upgrade complete:                   1.7: mi_btree_bitmap
Oldest version on disk:                     1.7: mi_btree_bitmap
Created:                                    Tue Apr 16 20:20:44 2024
Sequence number:                            217
Time of last write:                         Tue Apr 16 22:57:25 2024
Superblock size:                            4.66 KiB/1.00 MiB
Clean:                                      0
Devices:                                    1
Sections:                                   members_v1,crypt,replicas_v0,clean,journal_seq_blacklist,journal_v2,counters,members_v2,errors,ext,downgrade
Features:                                   journal_seq_blacklist_v3,new_siphash,inline_data,new_extent_overwrite,btree_ptr_v2,extents_above_btree_updates,btree_updates_journalled,new_varint,journal_no_flush,alloc_v2,extents_across_btree_nodes
Compat features:                            alloc_info,alloc_metadata,extents_above_btree_updates_done,bformat_overflow_done

Options:
  block_size:                               4.00 KiB
  btree_node_size:                          256 KiB
  errors:                                   continue [ro] panic
  metadata_replicas:                        2
  data_replicas:                            1
  metadata_replicas_required:               1
  data_replicas_required:                   1
  encoded_extent_max:                       64.0 KiB
  metadata_checksum:                        none crc32c [crc64] xxhash
  data_checksum:                            none crc32c [crc64] xxhash
  compression:                              none
  background_compression:                   none
  str_hash:                                 crc32c crc64 [siphash]
  metadata_target:                          none
  foreground_target:                        none
  background_target:                        none
  promote_target:                           none
  erasure_code:                             0
  inodes_32bit:                             1
  shard_inode_numbers:                      1
  inodes_use_key_cache:                     1
  gc_reserve_percent:                       8
  gc_reserve_bytes:                         0 B
  root_reserve_percent:                     0
  wide_macs:                                0
  acl:                                      1
  usrquota:                                 0
  grpquota:                                 0
  prjquota:                                 0
  journal_flush_delay:                      1000
  journal_flush_disabled:                   0
  journal_reclaim_delay:                    100
  journal_transaction_names:                1
  version_upgrade:                          [compatible] incompatible none
  nocow:                                    0

members_v2 (size 152):
Device:                                     0
  Label:                                    (none)
  UUID:                                     40826614-0839-41ec-8935-991c9016ffa0
  Size:                                     3.64 TiB
  read errors:                              0
  write errors:                             0
  checksum errors:                          0
  seqread iops:                             0
  seqwrite iops:                            0
  randread iops:                            0
  randwrite iops:                           0
  Bucket size:                              512 KiB
  First bucket:                             0
  Buckets:                                  7630892
  Last mount:                               Tue Apr 16 22:19:43 2024
  Last superblock write:                    217
  State:                                    rw
  Data allowed:                             journal,btree,user
  Has data:                                 journal,btree,user
  Durability:                               1
  Discard:                                  0
  Freespace initialized:                    1

errors (size 8):

Decoded backtrace:

Apr 16 20:48:04 archlinux kernel: task:rsync           state:D stack:0     pid:368618 tgid:368618 ppid:368617 flags:0x00000002
Apr 16 20:48:04 archlinux kernel: Call Trace:
Apr 16 20:48:04 archlinux kernel:  <TASK>
Apr 16 20:48:04 archlinux kernel: __schedule (linux-bcachefs/kernel/sched/core.c:5409 linux-bcachefs/kernel/sched/core.c:6746)
Apr 16 20:48:04 archlinux kernel: schedule (linux-bcachefs/./arch/x86/include/asm/preempt.h:84 (discriminator 13) linux-bcachefs/kernel/sched/core.c:6824 (discriminator 13) linux-bcachefs/kernel/sched/core.c:6838 (discriminator 13))
Apr 16 20:48:04 archlinux kernel: io_schedule (linux-bcachefs/kernel/sched/core.c:9019 (discriminator 1) linux-bcachefs/kernel/sched/core.c:9045 (discriminator 1))
Apr 16 20:48:04 archlinux kernel: folio_wait_bit_common (linux-bcachefs/mm/filemap.c:1275 (discriminator 4))
Apr 16 20:48:04 archlinux kernel: ? filemap_invalidate_unlock_two (linux-bcachefs/mm/filemap.c:1091)
Apr 16 20:48:04 archlinux kernel: migrate_pages_batch (linux-bcachefs/./include/linux/pagemap.h:1048 linux-bcachefs/mm/migrate.c:1486 linux-bcachefs/mm/migrate.c:1700)
Apr 16 20:48:04 archlinux kernel: ? defer_compaction (linux-bcachefs/mm/compaction.c:1907)
Apr 16 20:48:04 archlinux kernel: ? isolate_freepages_block (linux-bcachefs/mm/compaction.c:1855)
Apr 16 20:48:04 archlinux kernel: ? set_ptes.constprop.0 (linux-bcachefs/arch/x86/xen/grant-table.c:34)
Apr 16 20:48:04 archlinux kernel: ? isolate_freepages_block (linux-bcachefs/mm/compaction.c:1855)
Apr 16 20:48:04 archlinux kernel: migrate_pages (linux-bcachefs/mm/migrate.c:1948)
Apr 16 20:48:04 archlinux kernel: ? defer_compaction (linux-bcachefs/mm/compaction.c:1907)
Apr 16 20:48:04 archlinux kernel: ? isolate_freepages_block (linux-bcachefs/mm/compaction.c:1855)
Apr 16 20:48:04 archlinux kernel: ? isolate_freepages_block (linux-bcachefs/mm/compaction.c:1855)
Apr 16 20:48:04 archlinux kernel: compact_zone (linux-bcachefs/mm/compaction.c:2663)
Apr 16 20:48:04 archlinux kernel: compact_zone_order (linux-bcachefs/mm/compaction.c:2801 (discriminator 1))
Apr 16 20:48:04 archlinux kernel: try_to_compact_pages (linux-bcachefs/mm/compaction.c:2855)
Apr 16 20:48:04 archlinux kernel: __alloc_pages_direct_compact (linux-bcachefs/./include/linux/sched/mm.h:333 (discriminator 1) linux-bcachefs/./include/linux/sched/mm.h:434 (discriminator 1) linux-bcachefs/mm/page_alloc.c:3534 (discriminator 1))
Apr 16 20:48:04 archlinux kernel: __alloc_pages_slowpath.constprop.0 (linux-bcachefs/mm/page_alloc.c:4130)
Apr 16 20:48:04 archlinux kernel: __alloc_pages (linux-bcachefs/mm/page_alloc.c:4580)
Apr 16 20:48:04 archlinux kernel: alloc_pages_mpol (linux-bcachefs/mm/mempolicy.c:2266 (discriminator 1))
Apr 16 20:48:04 archlinux kernel: folio_alloc (linux-bcachefs/mm/mempolicy.c:2342)
Apr 16 20:48:04 archlinux kernel: page_cache_ra_order (linux-bcachefs/mm/readahead.c:468 linux-bcachefs/mm/readahead.c:517)
Apr 16 20:48:04 archlinux kernel: filemap_get_pages (linux-bcachefs/mm/filemap.c:2522)
Apr 16 20:48:04 archlinux kernel: filemap_read (linux-bcachefs/mm/filemap.c:2601)
Apr 16 20:48:04 archlinux kernel: ? __mod_memcg_state (linux-bcachefs/mm/memcontrol.c:723 (discriminator 1) linux-bcachefs/mm/memcontrol.c:824 (discriminator 1) linux-bcachefs/mm/memcontrol.c:818 (discriminator 1))
Apr 16 20:48:04 archlinux kernel: bch2_read_iter+0x1a2/0x680 bcachefs
Apr 16 20:48:04 archlinux kernel: ? skb_copy_datagram_from_iter (linux-bcachefs/net/core/datagram.c:595)
Apr 16 20:48:04 archlinux kernel: ? skb_queue_tail (linux-bcachefs/./include/linux/spinlock.h:406 linux-bcachefs/net/core/skbuff.c:3975)
Apr 16 20:48:04 archlinux kernel: ? sock_def_readable (linux-bcachefs/net/core/sock.c:3352 (discriminator 2))
Apr 16 20:48:04 archlinux kernel: ? unix_stream_sendmsg (linux-bcachefs/./include/net/scm.h:77 linux-bcachefs/net/unix/af_unix.c:2352)
Apr 16 20:48:04 archlinux kernel: vfs_read (linux-bcachefs/./include/linux/fs.h:2102 linux-bcachefs/fs/read_write.c:395 linux-bcachefs/fs/read_write.c:476)
Apr 16 20:48:04 archlinux kernel: ksys_read (linux-bcachefs/fs/read_write.c:619)
Apr 16 20:48:04 archlinux kernel: do_syscall_64 (linux-bcachefs/arch/x86/entry/common.c:52 (discriminator 1) linux-bcachefs/arch/x86/entry/common.c:83 (discriminator 1))
Apr 16 20:48:04 archlinux kernel: ? syscall_exit_to_user_mode (linux-bcachefs/kernel/entry/common.c:221)
Apr 16 20:48:04 archlinux kernel: ? do_syscall_64 (linux-bcachefs/./arch/x86/include/asm/cpufeature.h:173 linux-bcachefs/arch/x86/entry/common.c:98)
Apr 16 20:48:04 archlinux kernel: ? do_syscall_64 (linux-bcachefs/./arch/x86/include/asm/cpufeature.h:173 linux-bcachefs/arch/x86/entry/common.c:98)
Apr 16 20:48:04 archlinux kernel: ? do_syscall_64 (linux-bcachefs/./arch/x86/include/asm/cpufeature.h:173 linux-bcachefs/arch/x86/entry/common.c:98)
Apr 16 20:48:04 archlinux kernel: ? do_syscall_64 (linux-bcachefs/./arch/x86/include/asm/cpufeature.h:173 linux-bcachefs/arch/x86/entry/common.c:98)
Apr 16 20:48:04 archlinux kernel: ? __irq_exit_rcu (linux-bcachefs/kernel/softirq.c:616 (discriminator 1) linux-bcachefs/kernel/softirq.c:635 (discriminator 1))
Apr 16 20:48:04 archlinux kernel: entry_SYSCALL_64_after_hwframe (linux-bcachefs/arch/x86/entry/entry_64.S:129)
Apr 16 20:48:04 archlinux kernel: RIP: 0033:0x7e7d4e319681
Apr 16 20:48:04 archlinux kernel: RSP: 002b:00007fff32d859e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
Apr 16 20:48:04 archlinux kernel: RAX: ffffffffffffffda RBX: 0000561de1241200 RCX: 00007e7d4e319681
Apr 16 20:48:04 archlinux kernel: RDX: 0000000000040000 RSI: 0000561de1263c80 RDI: 0000000000000003
Apr 16 20:48:04 archlinux kernel: RBP: 0000000000040000 R08: 000000003b6e7b50 R09: 0000000000040000
Apr 16 20:48:04 archlinux kernel: R10: 00007fff32d85a80 R11: 0000000000000246 R12: 0000000000000000
Apr 16 20:48:04 archlinux kernel: R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000040000
Apr 16 20:48:04 archlinux kernel:  </TASK>

[koverstreet]

Are you using zswap?

[Valmar33]

Are you using zswap?

Yes. Does it have known bad interactions?

[koverstreet]

It's known to be buggy - should be fixed in 6.9, unless there's more bugs.

[koverstreet]

Reopen if you repro it without zswap

[Valmar33]

It's known to be buggy - should be fixed in 6.9, unless there's more bugs.

Cheers. Will disable. :)

[Valmar33]

Rebooted, confirmed zswap was disabled, mounted my backup drive (fsck seems to not hang anymore!), went to do my backup routine with rsync.

Hangs as soon as there is intense activity on the same bcachefs data partition...

(Mind you, I'm running bcachefs master ~ bcachefs: Kill gc_init_recurse() ~ rebased on top of https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=71b1543c83d65af8215d7558d70fc2ecbee77dcf but I'm not sure how much difference it makes much difference here...)

24/4/24 9:24 AM kernel  task:rsync           state:D stack:0     pid:4045  tgid:4045  ppid:4044   flags:0x00000002
24/4/24 9:24 AM kernel  Call Trace:
24/4/24 9:24 AM kernel   <TASK>
24/4/24 9:24 AM kernel __schedule (kernel/sched/core.c:5409 kernel/sched/core.c:6746) 
24/4/24 9:24 AM kernel ? __blk_mq_alloc_requests (block/blk-mq.c:515 (discriminator 1) block/blk-mq.c:333 (discriminator 1) block/blk-mq.c:516 (discriminator 1)) 
24/4/24 9:24 AM kernel schedule (./arch/x86/include/asm/preempt.h:84 (discriminator 13) kernel/sched/core.c:6824 (discriminator 13) kernel/sched/core.c:6838 (discriminator 13)) 
24/4/24 9:24 AM kernel io_schedule (kernel/sched/core.c:9019 (discriminator 1) kernel/sched/core.c:9045 (discriminator 1)) 
24/4/24 9:24 AM kernel folio_wait_bit_common (mm/filemap.c:1275 (discriminator 4)) 
24/4/24 9:24 AM kernel ? filemap_invalidate_unlock_two (mm/filemap.c:1091) 
24/4/24 9:24 AM kernel migrate_pages_batch (./include/linux/pagemap.h:1048 mm/migrate.c:1486 mm/migrate.c:1700) 
24/4/24 9:24 AM kernel ? defer_compaction (mm/compaction.c:1907) 
24/4/24 9:24 AM kernel ? isolate_freepages_block (mm/compaction.c:1855) 
24/4/24 9:24 AM kernel ? isolate_freepages_block (mm/compaction.c:1855) 
24/4/24 9:24 AM kernel migrate_pages (mm/migrate.c:1948) 
24/4/24 9:24 AM kernel ? defer_compaction (mm/compaction.c:1907) 
24/4/24 9:24 AM kernel ? isolate_freepages_block (mm/compaction.c:1855) 
24/4/24 9:24 AM kernel ? isolate_freepages_block (mm/compaction.c:1855) 
24/4/24 9:24 AM kernel compact_zone (mm/compaction.c:2663) 
24/4/24 9:24 AM kernel compact_zone_order (mm/compaction.c:2801 (discriminator 1)) 
24/4/24 9:24 AM kernel try_to_compact_pages (mm/compaction.c:2855) 
24/4/24 9:24 AM kernel __alloc_pages_direct_compact (./include/linux/sched/mm.h:333 (discriminator 1) ./include/linux/sched/mm.h:434 (discriminator 1) mm/page_alloc.c:3534 (discriminator 1)) 
24/4/24 9:24 AM kernel __alloc_pages_slowpath.constprop.0 (mm/page_alloc.c:4130) 
24/4/24 9:24 AM kernel ? try_charge_memcg (mm/memcontrol.c:2749 (discriminator 1)) 
24/4/24 9:24 AM kernel __alloc_pages (mm/page_alloc.c:4580) 
24/4/24 9:24 AM kernel alloc_pages_mpol (mm/mempolicy.c:2266 (discriminator 1)) 
24/4/24 9:24 AM kernel folio_alloc (mm/mempolicy.c:2342) 
24/4/24 9:24 AM kernel page_cache_ra_order (mm/readahead.c:468 mm/readahead.c:517) 
24/4/24 9:24 AM kernel filemap_get_pages (mm/filemap.c:2522) 
24/4/24 9:24 AM kernel filemap_read (mm/filemap.c:2601) 
24/4/24 9:24 AM kernel bch2_read_iter (fs/bcachefs/fs-io-direct.c:208) bcachefs
24/4/24 9:24 AM kernel vfs_read (./include/linux/fs.h:2104 fs/read_write.c:395 fs/read_write.c:476) 
24/4/24 9:24 AM kernel ksys_read (fs/read_write.c:619) 
24/4/24 9:24 AM kernel do_syscall_64 (arch/x86/entry/common.c:52 (discriminator 1) arch/x86/entry/common.c:83 (discriminator 1)) 
24/4/24 9:24 AM kernel ? do_syscall_64 (./arch/x86/include/asm/cpufeature.h:175 arch/x86/entry/common.c:98) 
24/4/24 9:24 AM kernel ? syscall_exit_to_user_mode (kernel/entry/common.c:221) 
24/4/24 9:24 AM kernel ? do_syscall_64 (./arch/x86/include/asm/cpufeature.h:175 arch/x86/entry/common.c:98) 
24/4/24 9:24 AM kernel ? do_syscall_64 (./arch/x86/include/asm/cpufeature.h:175 arch/x86/entry/common.c:98) 
24/4/24 9:24 AM kernel ? do_syscall_64 (./arch/x86/include/asm/cpufeature.h:175 arch/x86/entry/common.c:98) 
24/4/24 9:24 AM kernel ? do_syscall_64 (./arch/x86/include/asm/cpufeature.h:175 arch/x86/entry/common.c:98) 
24/4/24 9:24 AM kernel entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:130) 
24/4/24 9:24 AM kernel  RIP: 0033:0x7cea9a1196a1
24/4/24 9:24 AM kernel  RSP: 002b:00007fff5219ba18 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
24/4/24 9:24 AM kernel  RAX: ffffffffffffffda RBX: 0000637ea2e153f0 RCX: 00007cea9a1196a1
24/4/24 9:24 AM kernel  RDX: 0000000000040000 RSI: 0000637ea2e200d0 RDI: 0000000000000003
24/4/24 9:24 AM kernel  RBP: 0000000000040000 R08: 00000000160c1f20 R09: 0000000000040000
24/4/24 9:24 AM kernel  R10: 00007fff5219bab0 R11: 0000000000000246 R12: 0000000000000000
24/4/24 9:24 AM kernel  R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000040000
24/4/24 9:24 AM kernel   </TASK>

[Valmar33]

If I don't start KDE and run the rsync command in pure vt, then the rsync process never gets stuck and completes perfectly fine.

KDE never freezes, though... nor anything else on the SSD partition. Seems to be the external drive partition that gets stuck? But, I'm at a loss as to why having KDE running from the SSD bcachefs partition can cause rsync to get stuck reading data from the SSD and writing it to the external drive. External drive is in a USB caddy, though the drive itself isn't slow. It easily reaches 200MB/s when transferring big files.

But... it also seems to most easily get stuck when transferring massive files at high speeds.

[Valmar33]

Would it help if I trigger a freeze again? What would I need to do to get the state of the filesystem in that moment? I guess I'd need to get the current transaction or something it's stuck on. I'd appreciate it if you could walk me through the basics.

[koverstreet]

If you can get it to hang again, check echo w > /proc/sysrq-trigger; dmesg /sys/kernel/debug/bcachefs//btree_transactions /sys/fs/bcachefs//dev-0/alloc_debug /sys/fs/bcachefs/*/internal/journal_debug

[Valmar33]

I haven't been able to reproduce it since. Maybe another commit you pushed fixed something...

But, I'll keep trying.