Open marcin-github opened 10 months ago
I have couple filesystems on box, but I suspect this is related also to this fs:
External UUID: 2fc82775-653c-4995-89f9-5df5f626314c
Internal UUID: 1ec747b3-ea96-485b-bdc5-745565da4b69
Device index: 0
Label: media2
Version: 1.3: rebalance_work
Version upgrade complete: 1.3: rebalance_work
Oldest version on disk: 1.2: deleted_inodes
Created: Mon Oct 23 14:33:09 2023
Sequence number: 84
Superblock size: 4504
Clean: 0
Devices: 1
Sections: members_v1,replicas_v0,clean,journal_seq_blacklist,journal_v2,counters,members_v2,errors
Features: lz4,zstd,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: 1.00 MiB
metadata_checksum: none [crc32c] crc64 xxhash
data_checksum: none [crc32c] crc64 xxhash
compression: none
background_compression: lz4
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: 5
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 144):
Device: 0
Label: (none)
UUID: 36d40aff-eaad-4218-8d08-4f44b2150dae
Size: 2.00 TiB
read errors: 0
write errors: 1
checksum errors: 0
seqread iops: 0
seqwrite iops: 0
randread iops: 0
randwrite iops: 0
Bucket size: 512 KiB
First bucket: 0
Buckets: 4194304
Last mount: Fri Nov 3 20:28:16 2023
State: rw
Data allowed: journal,btree,user
Has data: journal,btree,user
Discard: 0
Freespace initialized: 1
replicas_v0 (size 24):
btree: 1 [0] journal: 1 [0] user: 1 [0]
The warning was firing incorrectly when we weren't holding the srcu lock - should be fixed now
Thanks, i'm not sure if this is in master branch, as for now, at commit #6c5850f4860d issue exists.
yeah, something funny is going on.
I also get this issue. It seemingly leads to an OOM on boot which is eventually "reclaimed" when it loops back around past the total memory. Unfortunately, the kernel treats the OOM as if it's real, which it may or may not be. Thankfully it only happens once.
Hmm, this happens also in userspace:
# bcachefs fsck -n /dev/vg-ZA1C3NKP/burp
mounting version 1.3: rebalance_work opts=metadata_replicas=2,compression=lz4,background_compression=zstd:6,degraded,journal_reclaim_delay=1000,fsck,fix_errors=no,nochanges,nodirect_io
recovering from clean shutdown, journal seq 23150366
journal read done, replaying entries 23150366-23150366
alloc_read... done
stripes_read... done
snapshots_read... done
WARNING at libbcachefs/btree_iter.c:2729: btree trans held srcu lock (delaying memory reclaim) for 68 seconds
WARNING at libbcachefs/btree_iter.c:2729: btree trans held srcu lock (delaying memory reclaim) for 16 seconds
Interestingly, I have not seen this in linux 6.7-rc1 or 6.7-rc2.
That said, I have also reinstalled with linux 6.7-rc1, so it may be an upgrade path problem.
Edit: I didn't wait long enough lol. This happens in 6.7-rc2.
I'm not sure if this is the same error, but I'm seeing this with 6.7.0-rc6
:
And fsck
seemed okay, but did report some similar warnings:
In case it helps, this is on an external disk connected through a powered usb3 hub that also has a couple other disks connected.
So in your case it's probably being caused by high IO latency - we do btree node prefetching in the snapshot read path, so that can multiply latency of a particular btree node read depending on submit order.
The main suspected cause I'm hunting for right now is memory reclaim related - I suspect there's places where we're holding btree node locks while doing memory reclaim; tracking those down won't be too hard once I teach lockdep to check for it.
also been seeing this for a while now, most recently on 6.8-rc2 dmesg.txt
fsck completes successfully as well
will post the output of bcachefs fs usage
in an edit shortly
EDIT:
bcachefs fs usage
Filesystem: 00345bfa-2c4a-434f-a6ff-73f3874dbb26
Size: 1840376583680
Used: 992210965504
Online reserved: 2531328
Data type Required/total Durability Devices
reserved: 1/0 [] 5621252096
btree: 1/1 1 [nvme0n1] 12130189312
user: 1/1 1 [nvme0n1] 621832521728
user: 1/1 1 [sda] 343939324416
cached: 1/1 1 [nvme0n1] 45736656384
cached: 1/1 1 [sda] 199923758080
fast.big (device 2): nvme0n1 rw
data buckets fragmented
free: 305063788544 581863
sb: 3149824 7 520192
journal: 4294967296 8192
btree: 12130189312 36176 6836453376
user: 621832521728 1189049 1571600384
cached: 45736656384 92452
parity: 0 0
stripe: 0 0
need_gc_gens: 0 0
need_discard: 0 0
capacity: 1000204664832 1907739
slow (device 1): sda rw
data buckets fragmented
free: 421821153280 804560
sb: 3149824 7 520192
journal: 4294967296 8192
btree: 0 0
user: 343939324416 680391 12782702080
cached: 199923758080 414587
parity: 0 0
stripe: 0 0
need_gc_gens: 0 0
need_discard: 1048576 2
capacity: 1000204664832 1907739
This is still an issue for me with Git master as of https://github.com/koverstreet/bcachefs/commit/b3c7fd35c03c17a950737fb56a06b730a7962d28
Apr 01 17:26:09 archlinux kernel: ------------[ cut here ]------------
Apr 01 17:26:09 archlinux kernel: btree trans held srcu lock (delaying memory reclaim) for 14 seconds
Apr 01 17:26:09 archlinux kernel: WARNING: CPU: 6 PID: 4947 at fs/bcachefs/btree_iter.c:2871 bch2_trans_srcu_unlock+0x112/0x120 [bcachefs]
Apr 01 17:26:09 archlinux kernel: Modules linked in: poly1305_generic libpoly1305 poly1305_x86_64 chacha_generic chacha_x86_64 libchacha uas usb_storage snd_seq_dummy snd_hrtimer snd_seq bridge stp llc hid_playstation mousedev led_class_mu>
Apr 01 17:26:09 archlinux kernel: snd_timer mac_hid snd soundcore usbhid winesync(OE) i2c_dev sg vhba(OE) crypto_user fuse dm_mod loop nfnetlink ip_tables x_tables ext4 crc32c_generic crc16 mbcache jbd2 nvme crc32c_intel nvme_core xhci_pc>
Apr 01 17:26:09 archlinux kernel: CPU: 6 PID: 4947 Comm: bch-rebalance/s Tainted: G OE 6.9.0-rc2-1-custom-bcachefs-git-00032-gb3c7fd35c03c #1 5c48e1afc39b4f295430db40cd48f5e24e7376f2
Apr 01 17:26:09 archlinux kernel: Hardware name: Micro-Star International Co., Ltd. MS-7B85/B450 GAMING PRO CARBON AC (MS-7B85), BIOS 1.G0 07/25/2022
Apr 01 17:26:09 archlinux kernel: RIP: 0010:bch2_trans_srcu_unlock+0x112/0x120 [bcachefs]
Apr 01 17:26:09 archlinux kernel: Code: 7f 95 c5 48 b8 cf f7 53 e3 a5 9b c4 20 48 c7 c7 18 0f 9d c1 48 29 ca 48 c1 ea 03 48 f7 e2 48 89 d6 48 c1 ee 04 e8 5e 3d df c3 <0f> 0b e9 69 ff ff ff 0f 0b e9 78 ff ff ff 66 0f 1f 00 0f 1f 44 00
Apr 01 17:26:09 archlinux kernel: RSP: 0018:ffffc103413bf728 EFLAGS: 00010282
Apr 01 17:26:09 archlinux kernel: RAX: 0000000000000000 RBX: ffff9f1aceeac000 RCX: 0000000000000027
Apr 01 17:26:09 archlinux kernel: RDX: ffff9f1b2ef219c8 RSI: 0000000000000001 RDI: ffff9f1b2ef219c0
Apr 01 17:26:09 archlinux kernel: RBP: ffff9f1a36700000 R08: 0000000000000000 R09: 0000000000000003
Apr 01 17:26:09 archlinux kernel: R10: ffffc103413bf5b8 R11: ffffffff872c6e28 R12: ffffc103413bfea0
Apr 01 17:26:09 archlinux kernel: R13: dead000000000122 R14: dead000000000100 R15: ffff9f18bf947800
Apr 01 17:26:09 archlinux kernel: FS: 0000000000000000(0000) GS:ffff9f1b2ef00000(0000) knlGS:0000000000000000
Apr 01 17:26:09 archlinux kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Apr 01 17:26:09 archlinux kernel: CR2: 00007cbc1beef000 CR3: 000000024b05b000 CR4: 0000000000f50ef0
Apr 01 17:26:09 archlinux kernel: PKRU: 55555554
Apr 01 17:26:09 archlinux kernel: Call Trace:
Apr 01 17:26:09 archlinux kernel: <TASK>
Apr 01 17:26:09 archlinux kernel: ? __warn+0x80/0x120
Apr 01 17:26:09 archlinux kernel: ? bch2_trans_srcu_unlock+0x112/0x120 [bcachefs 1f8b0db9c530aa78f3137e0f0ae4a2b54d9a1466]
Apr 01 17:26:09 archlinux kernel: ? report_bug+0x160/0x190
Apr 01 17:26:09 archlinux kernel: ? prb_read_valid+0x1b/0x20
Apr 01 17:26:09 archlinux kernel: ? handle_bug+0x38/0x70
Apr 01 17:26:09 archlinux kernel: ? exc_invalid_op+0x17/0x60
Apr 01 17:26:09 archlinux kernel: ? asm_exc_invalid_op+0x1a/0x20
Apr 01 17:26:09 archlinux kernel: ? bch2_trans_srcu_unlock+0x112/0x120 [bcachefs 1f8b0db9c530aa78f3137e0f0ae4a2b54d9a1466]
Apr 01 17:26:09 archlinux kernel: ? bch2_trans_srcu_unlock+0x112/0x120 [bcachefs 1f8b0db9c530aa78f3137e0f0ae4a2b54d9a1466]
Apr 01 17:26:09 archlinux kernel: bch2_moving_ctxt_do_pending_writes+0x75/0x220 [bcachefs 1f8b0db9c530aa78f3137e0f0ae4a2b54d9a1466]
Apr 01 17:26:09 archlinux kernel: bch2_data_update_init+0x680/0x1380 [bcachefs 1f8b0db9c530aa78f3137e0f0ae4a2b54d9a1466]
Apr 01 17:26:09 archlinux kernel: ? bch2_move_extent+0x3d4/0xb20 [bcachefs 1f8b0db9c530aa78f3137e0f0ae4a2b54d9a1466]
Apr 01 17:26:09 archlinux kernel: bch2_move_extent+0x3d4/0xb20 [bcachefs 1f8b0db9c530aa78f3137e0f0ae4a2b54d9a1466]
Apr 01 17:26:09 archlinux kernel: ? do_rebalance_extent+0x2e8/0x710 [bcachefs 1f8b0db9c530aa78f3137e0f0ae4a2b54d9a1466]
Apr 01 17:26:09 archlinux kernel: do_rebalance_extent+0x2e8/0x710 [bcachefs 1f8b0db9c530aa78f3137e0f0ae4a2b54d9a1466]
Apr 01 17:26:09 archlinux kernel: do_rebalance+0x309/0x8b0 [bcachefs 1f8b0db9c530aa78f3137e0f0ae4a2b54d9a1466]
Apr 01 17:26:09 archlinux kernel: ? mempool_alloc+0x83/0x1a0
Apr 01 17:26:09 archlinux kernel: ? __alloc_pages+0x1a5/0x360
Apr 01 17:26:09 archlinux kernel: ? local_clock_noinstr+0xd/0xb0
Apr 01 17:26:09 archlinux kernel: ? local_clock+0x15/0x30
Apr 01 17:26:09 archlinux kernel: ? __bch2_trans_get+0x153/0x230 [bcachefs 1f8b0db9c530aa78f3137e0f0ae4a2b54d9a1466]
Apr 01 17:26:09 archlinux kernel: ? do_rebalance+0x8b0/0x8b0 [bcachefs 1f8b0db9c530aa78f3137e0f0ae4a2b54d9a1466]
Apr 01 17:26:09 archlinux kernel: bch2_rebalance_thread+0x66/0xa0 [bcachefs 1f8b0db9c530aa78f3137e0f0ae4a2b54d9a1466]
Apr 01 17:26:09 archlinux kernel: ? bch2_rebalance_thread+0x5c/0xa0 [bcachefs 1f8b0db9c530aa78f3137e0f0ae4a2b54d9a1466]
Apr 01 17:26:09 archlinux kernel: kthread+0xcf/0x100
Apr 01 17:26:09 archlinux kernel: ? kthread_complete_and_exit+0x20/0x20
Apr 01 17:26:09 archlinux kernel: ret_from_fork+0x31/0x50
Apr 01 17:26:09 archlinux kernel: ? kthread_complete_and_exit+0x20/0x20
Apr 01 17:26:09 archlinux kernel: ret_from_fork_asm+0x11/0x20
Apr 01 17:26:09 archlinux kernel: </TASK>
Apr 01 17:26:09 archlinux kernel: ---[ end trace 0000000000000000 ]---
I seem to be able to trigger it reliably when there is a rebalance process running for any filesystem, and I then try and copy any large mass of files. All bcachefs filesystems tend to lockup at that point. Though I didn't think to check and see whether it would correct itself once the rebalance had finished.
I seem to be able to trigger it reliably when there is a rebalance process running for any filesystem, and I then try and copy any large mass of files. All bcachefs filesystems tend to lockup at that point. Though I didn't think to check and see whether it would correct itself once the rebalance had finished.
I am seeing the same thing - not sure if it is because I am transferring a large amount of data to a new BCFS (which has an NVME LV device and a large RUST LV. - NB Both VG's are LUKS encrypted.) Is the rust too slow?
Kernel 6.9.0-rc7 Data_replicas = 1 (for now) Compression/Background = none/zstd:10 (and lz4, tried both)
[Wed May 8 04:05:27 2024] ------------[ cut here ]------------ [Wed May 8 04:05:27 2024] btree trans held srcu lock (delaying memory reclaim) for 40 seconds [Wed May 8 04:05:27 2024] ------------[ cut here ]------------ [Wed May 8 04:05:27 2024] btree trans held srcu lock (delaying memory reclaim) for 40 seconds [Wed May 8 04:05:27 2024] btree trans held srcu lock (delaying memory reclaim) for 39 seconds [Wed May 8 04:05:27 2024] btree trans held srcu lock (delaying memory reclaim) for 40 seconds [Wed May 8 04:05:27 2024] WARNING: CPU: 4 PID: 14740 at fs/bcachefs/btree_iter.c:2871 bch2_trans_put+0x250/0x290 [Wed May 8 04:05:27 2024] WARNING: CPU: 11 PID: 83823 at fs/bcachefs/btree_iter.c:2871 bch2_trans_srcu_unlock+0x136/0x150 [Wed May 8 04:05:27 2024] WARNING: CPU: 5 PID: 80226 at fs/bcachefs/btree_iter.c:2871 bch2_trans_put+0x250/0x290 ...
[Wed May 8 04:05:27 2024] Workqueue: bcachefs_btree_io btree_node_write_work [Wed May 8 04:05:27 2024] R13: ffff88aa6ef4bf38 R14: ffff88aa9c800000 R15: 0000000000000000
[Wed May 8 04:05:27 2024] FS: 00007fbe73fa3c40(0000) GS:ffff88ae4ee00000(0000) knlGS:0000000000000000 [Wed May 8 04:05:27 2024] FS: 00007fbe73fa3c40(0000) GS:ffff88ae4f100000(0000) knlGS:0000000000000000 [Wed May 8 04:05:27 2024] RIP: 0010:bch2_trans_put+0x250/0x290 [Wed May 8 04:05:27 2024] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [Wed May 8 04:05:27 2024] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [Wed May 8 04:05:27 2024] CR2: 0000556e27ebc000 CR3: 00000003d7120000 CR4: 0000000000350ef0 [Wed May 8 04:05:27 2024] Code: c6 f8 71 01 48 c7 c7 38 1c 86 84 48 b8 cf f7 53 e3 a5 9b c4 20 48 29 ca 48 d1 ea 48 f7 e2 48 89 d6 48 c1 ee 04 e8 30 2e a1 ff <0f> 0b 41 8b b4 24 a8 00 00 00 49 8d be 68 36 00 00 83 fe 01 77 1b [Wed May 8 04:05:27 2024] CR2: 00007f818dbe9c3c CR3: 00000003d45a4000 CR4: 0000000000350ef0 [Wed May 8 04:05:27 2024] Call Trace: [Wed May 8 04:05:27 2024] RSP: 0018:ffff98f10710fdb8 EFLAGS: 00010246 [Wed May 8 04:05:27 2024] Call Trace:
[Wed May 8 04:05:27 2024]
Requires a long reboot to recover, although I can still read the fs, writes hang. There is no IO on dm-1 and dm-17 so it does not appear to be doing any balancing or compression.
I see a lot of these too, but one of my block devices is network backed, and the network can be occasionally slow. It would be nice to disable these warnings, because they are expected, are not signs of a problem, but still fill up the system log
Kernel 6.8.9-arch1-2 I only trigger this issue when doing heavy downloading that exceeds my cache drive.
it seems that sabnzbd and the file system ends up in some form of "write-stalemate".
I'm running into the same issue as @basso. Seems to be going OOM, which then starts killing all of my other daemons until everything bogs down. Unless I'm logged in before this happens, I'm unable to log in even when physically in front of it.
Update, I can reliably trigger this with any large movement of data. Running a rebalance will eventually OOM. I later did a hard shutdown and needed to fsck
but while repairing ran into the OOM again.
If there's any recommendations on logs to attempt outputting I can try to snag one before things start getting OOM killed and I lose access to the system.
This warnings appears since upgrade to 6.6.0 (branch master):