Zygo / bees

Best-Effort Extent-Same, a btrfs dedupe agent
GNU General Public License v3.0
647 stars 55 forks source link

After few hours bees process become unresponsive / high cpu / directory not accessible #161

Open samywee opened 3 years ago

samywee commented 3 years ago

I have been trying to run bees for few days on a backup data set of size ~500GB on a 1800GB btrfs filesystem. In testing on a small data set bees seems to achive what I wanted it to do. But on this larger fileset bees go into hang often.

Here are my settings. Ubuntu 18.01 with kernel version 4.19.0 (upgraded manually to this version to run bees) , btrfs-progs v4.15.1

Have a 384MB - DB_SIZE
3CPU / 6GB memory on server where I run bees (VM - intel )

I have a combination avarage files as well as few .vhd files (vhd => microsoft backup imagefiles)

After about 2 hrs or so, server start to increase load, bees process at 100% cpu and hangs at this stage. When I try to stop at this stage bees become a defunt process and //.beeshome - not accessessible (cannot do a ls).

Thre are multiple messages in the log. I am pasting here last parts of it (I was running with Verbose=6). Note that since 02:40:44 no logs till I tried to stop. Any precautions that I can take to avoid this? Can I get bees to work for me or do I have to give up due to some kernel incompatibility as many have discussed? Have I hit a issue with a large files trying to de-dupe?

Not sure if this is related to the old thread (https://github.com/Zygo/bees/issues/63 - I thought I will start a new thread as it was old.)

I can provide additional info at your request. Your help is appreciated.

Dec 27 02:40:37 ubu16 beesd[1906]: crawl_5[2510]: src = 7 sw_pc/201225-1900_Image_C/Image_C_201225-1900.vhd
Dec 27 02:40:37 ubu16 beesd[1906]: crawl_5[2510]: dst = 6 sw_pc/201225-2237_Image_C/Image_C_201225-2237.vhd
Dec 27 02:40:38 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: toxic address: addr = 0x96a15c4000, sys_usage_delta = 0.164, user_usage_delta = 0, rt_age = 0.170681, refs 4
Dec 27 02:40:38 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: discovered toxic match at found_addr 0x96a15c4000z1000 matching bbd BeesBlockData { 4K 0x7df290000 fd = 6 'sw_pc/201
Dec 27 02:40:38 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: abandoned toxic match for hash 0x2840d8449491a741 addr 0xdb405000tz13000 matching bbd BeesBlockData { 4K 0x7dfbe0000
Dec 27 02:40:39 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: abandoned toxic match for hash 0x335e118399015e5f addr 0xfed10000tz19000 matching bbd BeesBlockData { 4K 0x7dfda8000
Dec 27 02:40:39 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: abandoned toxic match for hash 0xb5de27b901a41e26 addr 0x9ed2c000tz10000 matching bbd BeesBlockData { 4K 0x7dff1a000
Dec 27 02:40:39 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: toxic address: addr = 0x71d3865000, sys_usage_delta = 0.132, user_usage_delta = 0, rt_age = 0.155273, refs 7
Dec 27 02:40:39 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: discovered toxic match at found_addr 0x71d3865000z16000 matching bbd BeesBlockData { 4K 0x7e028d000 fd = 6 'sw_pc/20
Dec 27 02:40:39 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: discovered toxic match at found_addr 0x71d3865000z18000 matching bbd BeesBlockData { 4K 0x7e028f000 fd = 6 'sw_pc/20
Dec 27 02:40:39 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: abandoned toxic match for hash 0xf7169b42f1caf171 addr 0x4b5f6f000tz7000 matching bbd BeesBlockData { 4K 0x7e02cc000
Dec 27 02:40:39 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: abandoned toxic match for hash 0xa6a6086e13ceea6a addr 0x4b5f6f000tz1a000 matching bbd BeesBlockData { 4K 0x7e02df00
Dec 27 02:40:40 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: toxic address: addr = 0xfed10000, sys_usage_delta = 0.224, user_usage_delta = 0, rt_age = 0.893976, refs 92
Dec 27 02:40:40 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: discovered toxic match at found_addr 0xfed10000z17000 matching bbd BeesBlockData { 4K 0x7e0173000 fd = 6 'sw_pc/2012
Dec 27 02:40:40 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: toxic address: addr = 0x4b5fa2000, sys_usage_delta = 0.114, user_usage_delta = 0, rt_age = 0.1209, refs 4
Dec 27 02:40:40 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: not growing matching pair forward because src is toxic:
Dec 27 02:40:40 ubu16 beesd[1906]: crawl_5[2510]: BeesRangePair: 96K src[0x103f05c000..0x103f074000] dst[0x7e034e000..0x7e0366000]
Dec 27 02:40:40 ubu16 beesd[1906]: crawl_5[2510]: src = 7 sw_pc/201225-1900_Image_C/Image_C_201225-1900.vhd
Dec 27 02:40:40 ubu16 beesd[1906]: crawl_5[2510]: dst = 6 sw_pc/201225-2237_Image_C/Image_C_201225-2237.vhd
Dec 27 02:40:40 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: toxic address: addr = 0x75c2acc000, sys_usage_delta = 0.133, user_usage_delta = 0, rt_age = 0.158313, refs 6
Dec 27 02:40:40 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: discovered toxic match at found_addr 0x75c2acc000z6000 matching bbd BeesBlockData { 4K 0x7e03ec000 fd = 6 'sw_pc/201
Dec 27 02:40:41 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: abandoned toxic match for hash 0x585111fecb2671cc addr 0x620b25000tz12000 matching bbd BeesBlockData { 4K 0x7e041c00
Dec 27 02:40:41 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: toxic address: addr = 0x34b280c000, sys_usage_delta = 0.214, user_usage_delta = 0.001, rt_age = 0.256483, refs 18
Dec 27 02:40:41 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: discovered toxic match at found_addr 0x34b280c000z0 matching bbd BeesBlockData { 4K 0x7e03f0000 fd = 6 'sw_pc/201225
Dec 27 02:40:41 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: toxic address: addr = 0x9a5473b000, sys_usage_delta = 0.181, user_usage_delta = 0, rt_age = 0.355729, refs 4
Dec 27 02:40:41 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: discovered toxic match at found_addr 0x9a5473b000 matching bbd BeesBlockData { 4K 0x7e04c2000 fd = 6 'sw_pc/201225-2
Dec 27 02:40:41 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: abandoned toxic match for hash 0x288ead79ef74ab3d addr 0x5a2784000tze000 matching bbd BeesBlockData { 4K 0x7e076b000
Dec 27 02:40:41 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: abandoned toxic match for hash 0x658357734e0d90fd addr 0x43c2e61000tz8000 matching bbd BeesBlockData { 4K 0x7e074a00
Dec 27 02:40:42 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: toxic address: addr = 0x52c5709000, sys_usage_delta = 0.101, user_usage_delta = 0, rt_age = 0.113247, refs 11
Dec 27 02:40:42 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: discovered toxic match at found_addr 0x52c5709000z0 matching bbd BeesBlockData { 4K 0x7e09cd000 fd = 6 'sw_pc/201225
Dec 27 02:40:42 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: toxic address: addr = 0x5e5d38a000, sys_usage_delta = 0.102, user_usage_delta = 0, rt_age = 0.109883, refs 2
Dec 27 02:40:42 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: discovered toxic match at found_addr 0x5e5d38a000zf000 matching bbd BeesBlockData { 4K 0x7e0a0d000 fd = 6 'sw_pc/201
Dec 27 02:40:42 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: abandoned toxic match for hash 0x6e0f525c6d53af60 addr 0x73f6f11000tz10000 matching bbd BeesBlockData { 4K 0x7e10c70
Dec 27 02:40:43 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: toxic address: addr = 0x34a4030000, sys_usage_delta = 0.104, user_usage_delta = 0.001, rt_age = 0.109964, refs 30
Dec 27 02:40:43 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: discovered toxic match at found_addr 0x34a4030000z4000 matching bbd BeesBlockData { 4K 0x7e111d000 fd = 6 'sw_pc/201
Dec 27 02:40:44 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: toxic address: addr = 0x8d8b497000, sys_usage_delta = 0.114, user_usage_delta = 0, rt_age = 0.154837, refs 2
Dec 27 02:40:44 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: discovered toxic match at found_addr 0x8d8b497000z10000 matching bbd BeesBlockData { 4K 0x7e2efb000 fd = 6 'sw_pc/20
Dec 27 02:40:44 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: discovered toxic match at found_addr 0x8d8b497000z1000 matching bbd BeesBlockData { 4K 0x7e2eec000 fd = 6 'sw_pc/201
Dec 27 02:40:44 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: abandoned toxic match for hash 0x3777d670b37c2bf addr 0xb3bfaa7000tz9000 matching bbd BeesBlockData { 4K 0x7e2f4f000
Dec 27 02:40:44 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: abandoned toxic match for hash 0x1f02b894086e6258 addr 0xa4961000tz1b000 matching bbd BeesBlockData { 4K 0x7e2fb9000
Dec 27 02:40:44 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: abandoned toxic match for hash 0xa57ca9df9ecf75dc addr 0x7e3ab86000tzc000 matching bbd BeesBlockData { 4K 0x7e2ffe00
Dec 27 02:40:44 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: toxic address: addr = 0x9a37655000, sys_usage_delta = 0.111, user_usage_delta = 0, rt_age = 0.117905, refs 2
Dec 27 02:40:44 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: discovered toxic match at found_addr 0x9a37655000zc000 matching bbd BeesBlockData { 4K 0x7e3006000 fd = 6 'sw_pc/201
Dec 27 02:40:44 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: toxic address: addr = 0x3339ad2000, sys_usage_delta = 0.113, user_usage_delta = 0, rt_age = 0.133456, refs 5
Dec 27 02:40:44 ubu16 beesd[1906]: crawl_5[2512]: WORKAROUND: discovered toxic match at found_addr 0x3339ad2000z4000 matching bbd BeesBlockData { 4K 0x7e30b4000 fd = 6 'sw_pc/201
Dec 27 02:40:44 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: toxic address: addr = 0x4699a93000, sys_usage_delta = 0.118, user_usage_delta = 0, rt_age = 0.126217, refs 4
Dec 27 02:40:44 ubu16 beesd[1906]: crawl_5[2510]: WORKAROUND: discovered toxic match at found_addr 0x4699a93000z4000 matching bbd BeesBlockData { 4K 0x7e3107000 fd = 6 'sw_pc/201
Dec 27 08:18:09 ubu16 systemd[1]: Stopping Bees (fe151c71-0f9c-4205-b47f-3b1c91b5f678)...
Dec 27 08:18:21 ubu16 beesd[1906]: bees[2507]: Received signal 15 info siginfo_t { signo = 15 (SIGTERM), errno = 0, code = 0, pid = 1, uid = 0, status = 0, utime = 0, stime = 0,
Dec 27 08:18:21 ubu16 beesd[1906]: bees[2507]: Stopping bees...
Dec 27 08:19:39 ubu16 systemd[1]: beesd@fe151c71-0f9c-4205-b47f-3b1c91b5f678.service: State 'stop-sigterm' timed out. Killing.
Dec 27 08:19:39 ubu16 systemd[1]: beesd@fe151c71-0f9c-4205-b47f-3b1c91b5f678.service: Killing process 1906 (beesd) with signal SIGKILL.
Dec 27 08:19:39 ubu16 systemd[1]: beesd@fe151c71-0f9c-4205-b47f-3b1c91b5f678.service: Killing process 2507 (bees) with signal SIGKILL.
Dec 27 08:19:39 ubu16 systemd[1]: beesd@fe151c71-0f9c-4205-b47f-3b1c91b5f678.service: Main process exited, code=killed, status=9/KILL
Dec 27 08:21:09 ubu16 systemd[1]: beesd@fe151c71-0f9c-4205-b47f-3b1c91b5f678.service: State 'stop-final-sigterm' timed out. Killing.
Dec 27 08:21:09 ubu16 systemd[1]: beesd@fe151c71-0f9c-4205-b47f-3b1c91b5f678.service: Killing process 2510 (crawl_5) with signal SIGKILL.
Dec 27 08:22:39 ubu16 systemd[1]: beesd@fe151c71-0f9c-4205-b47f-3b1c91b5f678.service: Processes still around after final SIGKILL. Entering failed mode.
Dec 27 08:22:39 ubu16 systemd[1]: beesd@fe151c71-0f9c-4205-b47f-3b1c91b5f678.service: Failed with result 'timeout'.
samywee commented 3 years ago

Here is few more additional info when this is happenning

my pid of bees process is 2176 At this time bees is not logging anything and CPU is 100% by the bees process.

head /proc/2176/task/*/stack
==> /proc/2176/task/2176/stack <==
[<0>] do_sigtimedwait.isra.43+0x19b/0x230
[<0>] __do_sys_rt_sigtimedwait+0x85/0xf0
[<0>] __x64_sys_rt_sigtimedwait+0x1e/0x20
[<0>] do_syscall_64+0x5a/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[<0>] 0xffffffffffffffff

==> /proc/2176/task/2177/stack <==
[<0>] futex_wait_queue_me+0xc4/0x120
[<0>] futex_wait+0x15b/0x250
[<0>] do_futex+0x2ec/0xb10
[<0>] __x64_sys_futex+0x14c/0x188
[<0>] do_syscall_64+0x5a/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[<0>] 0xffffffffffffffff

==> /proc/2176/task/2178/stack <==
[<0>] futex_wait_queue_me+0xc4/0x120
[<0>] futex_wait+0x15b/0x250
[<0>] do_futex+0x2ec/0xb10
[<0>] __x64_sys_futex+0x14c/0x188
[<0>] do_syscall_64+0x5a/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[<0>] 0xffffffffffffffff

==> /proc/2176/task/2181/stack <==
[<0>] hrtimer_nanosleep+0xd6/0x1f0
[<0>] __x64_sys_nanosleep+0x7b/0xa0
[<0>] do_syscall_64+0x5a/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[<0>] 0xffffffffffffffff

==> /proc/2176/task/2182/stack <==
[<0>] futex_wait_queue_me+0xc4/0x120
[<0>] futex_wait+0x15b/0x250
[<0>] do_futex+0x2ec/0xb10
[<0>] __x64_sys_futex+0x14c/0x188
[<0>] do_syscall_64+0x5a/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[<0>] 0xffffffffffffffff

==> /proc/2176/task/2183/stack <==
[<0>] balance_dirty_pages+0x42c/0xd80
[<0>] balance_dirty_pages_ratelimited+0x2c6/0x3c0
[<0>] btrfs_buffered_write.isra.28+0x4c7/0x760 [btrfs]
[<0>] btrfs_file_write_iter+0x3f6/0x590 [btrfs]
[<0>] __vfs_write+0x131/0x190
[<0>] vfs_write+0xab/0x1b0
[<0>] ksys_pwrite64+0x66/0xa0
[<0>] __x64_sys_pwrite64+0x1e/0x20
[<0>] do_syscall_64+0x5a/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9

==> /proc/2176/task/2184/stack <==
[<0>] futex_wait_queue_me+0xc4/0x120
[<0>] futex_wait+0x15b/0x250
[<0>] do_futex+0x2ec/0xb10
[<0>] __x64_sys_futex+0x14c/0x188
[<0>] do_syscall_64+0x5a/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[<0>] 0xffffffffffffffff

==> /proc/2176/task/2185/stack <==
[<0>] wait_current_trans+0xd5/0x110 [btrfs]
[<0>] start_transaction+0x330/0x410 [btrfs]
[<0>] btrfs_start_transaction+0x1e/0x20 [btrfs]
[<0>] btrfs_create+0x59/0x200 [btrfs]
[<0>] lookup_open+0x512/0x760
[<0>] path_openat+0x54d/0xe70
[<0>] do_filp_open+0x93/0x100
[<0>] do_sys_open+0x184/0x210
[<0>] __x64_sys_openat+0x20/0x30
[<0>] do_syscall_64+0x5a/0x110

==> /proc/2176/task/4880/stack <==
[<0>] wait_current_trans+0xd5/0x110 [btrfs]
[<0>] start_transaction+0x1e2/0x410 [btrfs]
[<0>] btrfs_join_transaction+0x1d/0x20 [btrfs]
[<0>] iterate_extent_inodes+0x271/0x320 [btrfs]
[<0>] iterate_inodes_from_logical+0x9c/0xd0 [btrfs]
[<0>] btrfs_ioctl_logical_to_ino+0x10e/0x1b0 [btrfs]
[<0>] btrfs_ioctl+0xd3b/0x2ce0 [btrfs]
[<0>] do_vfs_ioctl+0xa8/0x620
[<0>] ksys_ioctl+0x67/0x90
[<0>] __x64_sys_ioctl+0x1a/0x20

==> /proc/2176/task/4881/stack <==
[<0>] 0xffffffffffffffff
strace  -p 2176
strace: Process 2176 attached
gettid()                                = 2176
write(2, "<7>bees[2176]: Restarting sigwai"..., 38) = 38
rt_sigtimedwait([INT TERM],

Command line options (Started from systemctl)

/usr/lib/bees/bees --no-timestamps --strip-paths --no-timestamps --verbose=8 --loadavg-target=6 /run/bees/mnt/fe151c71-0f9c-4205-b47f-3b1c91b5f678
samywee commented 3 years ago

Found these kernel messages in syslog - hope it helps as well.

Dec 27 11:46:55 ubu16 kernel: [  605.415765] kworker/u4:5    D    0   260      2 0x80000000
Dec 27 11:46:55 ubu16 kernel: [  605.415804] Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.415805] Call Trace:
Dec 27 11:46:55 ubu16 kernel: [  605.415813]  __schedule+0x29e/0x840
Dec 27 11:46:55 ubu16 kernel: [  605.415815]  schedule+0x2c/0x80
Dec 27 11:46:55 ubu16 kernel: [  605.415833]  wait_current_trans+0xd5/0x110 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.415837]  ? wait_woken+0x80/0x80
Dec 27 11:46:55 ubu16 kernel: [  605.415853]  start_transaction+0x1e2/0x410 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.415868]  btrfs_join_transaction+0x1d/0x20 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.415882]  btrfs_finish_ordered_io+0x278/0x830 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.415885]  ? bio_free+0x51/0x70
Dec 27 11:46:55 ubu16 kernel: [  605.415886]  ? bio_put+0x29/0x30
Dec 27 11:46:55 ubu16 kernel: [  605.415900]  ? end_compressed_bio_write+0x11/0x140 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.415914]  finish_ordered_fn+0x15/0x20 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.415928]  normal_work_helper+0xbd/0x2f0 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.415942]  btrfs_endio_write_helper+0x12/0x20 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.415944]  process_one_work+0x20f/0x410
Dec 27 11:46:55 ubu16 kernel: [  605.415946]  worker_thread+0x34/0x400
Dec 27 11:46:55 ubu16 kernel: [  605.415947]  kthread+0x120/0x140
Dec 27 11:46:55 ubu16 kernel: [  605.415948]  ? pwq_unbound_release_workfn+0xd0/0xd0
Dec 27 11:46:55 ubu16 kernel: [  605.415950]  ? kthread_bind+0x40/0x40
Dec 27 11:46:55 ubu16 kernel: [  605.415952]  ret_from_fork+0x35/0x40
Dec 27 11:46:55 ubu16 kernel: [  605.415955] INFO: task kworker/u4:7:262 blocked for more than 120 seconds.
Dec 27 11:46:55 ubu16 kernel: [  605.416126]       Not tainted 4.19.0-041900-generic #201810221809
Dec 27 11:46:55 ubu16 kernel: [  605.416258] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 27 11:46:55 ubu16 kernel: [  605.416419] kworker/u4:7    D    0   262      2 0x80000000
Dec 27 11:46:55 ubu16 kernel: [  605.416438] Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.416439] Call Trace:
Dec 27 11:46:55 ubu16 kernel: [  605.416458]  __schedule+0x29e/0x840
Dec 27 11:46:55 ubu16 kernel: [  605.416460]  schedule+0x2c/0x80
Dec 27 11:46:55 ubu16 kernel: [  605.416473]  wait_current_trans+0xd5/0x110 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.416476]  ? wait_woken+0x80/0x80
Dec 27 11:46:55 ubu16 kernel: [  605.416799]  start_transaction+0x1e2/0x410 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.416813]  btrfs_join_transaction+0x1d/0x20 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.416824]  btrfs_finish_ordered_io+0x278/0x830 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.416826]  ? __switch_to_asm+0x40/0x70
Dec 27 11:46:55 ubu16 kernel: [  605.416827]  ? __switch_to_asm+0x34/0x70
Dec 27 11:46:55 ubu16 kernel: [  605.416828]  ? __switch_to_asm+0x40/0x70
Dec 27 11:46:55 ubu16 kernel: [  605.416829]  ? syscall_return_via_sysret+0x14/0x83
Dec 27 11:46:55 ubu16 kernel: [  605.416840]  finish_ordered_fn+0x15/0x20 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.416853]  normal_work_helper+0xbd/0x2f0 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.416865]  btrfs_endio_write_helper+0x12/0x20 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.416867]  process_one_work+0x20f/0x410
Dec 27 11:46:55 ubu16 kernel: [  605.416868]  worker_thread+0x34/0x400
Dec 27 11:46:55 ubu16 kernel: [  605.416870]  kthread+0x120/0x140
Dec 27 11:46:55 ubu16 kernel: [  605.416871]  ? pwq_unbound_release_workfn+0xd0/0xd0
Dec 27 11:46:55 ubu16 kernel: [  605.416872]  ? kthread_bind+0x40/0x40
Dec 27 11:46:55 ubu16 kernel: [  605.416873]  ret_from_fork+0x35/0x40
Dec 27 11:46:55 ubu16 kernel: [  605.416876] INFO: task kworker/u4:8:263 blocked for more than 120 seconds.
Dec 27 11:46:55 ubu16 kernel: [  605.417273]       Not tainted 4.19.0-041900-generic #201810221809
Dec 27 11:46:55 ubu16 kernel: [  605.464361] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 27 11:46:55 ubu16 kernel: [  605.465160] kworker/u4:8    D    0   263      2 0x80000000
Dec 27 11:46:55 ubu16 kernel: [  605.465190] Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.465191] Call Trace:
Dec 27 11:46:55 ubu16 kernel: [  605.465200]  __schedule+0x29e/0x840
Dec 27 11:46:55 ubu16 kernel: [  605.465215]  schedule+0x2c/0x80
Dec 27 11:46:55 ubu16 kernel: [  605.465232]  wait_current_trans+0xd5/0x110 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.465235]  ? wait_woken+0x80/0x80
Dec 27 11:46:55 ubu16 kernel: [  605.465249]  start_transaction+0x1e2/0x410 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.465262]  btrfs_join_transaction+0x1d/0x20 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.465275]  btrfs_finish_ordered_io+0x278/0x830 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.465277]  ? bio_free+0x51/0x70
Dec 27 11:46:55 ubu16 kernel: [  605.465278]  ? bio_put+0x29/0x30
Dec 27 11:46:55 ubu16 kernel: [  605.465293]  ? end_compressed_bio_write+0x11/0x140 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.465306]  finish_ordered_fn+0x15/0x20 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.465320]  normal_work_helper+0xbd/0x2f0 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.465334]  btrfs_endio_write_helper+0x12/0x20 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.465336]  process_one_work+0x20f/0x410
Dec 27 11:46:55 ubu16 kernel: [  605.465337]  worker_thread+0x34/0x400
Dec 27 11:46:55 ubu16 kernel: [  605.465339]  kthread+0x120/0x140
Dec 27 11:46:55 ubu16 kernel: [  605.465340]  ? pwq_unbound_release_workfn+0xd0/0xd0
Dec 27 11:46:55 ubu16 kernel: [  605.465341]  ? kthread_bind+0x40/0x40
Dec 27 11:46:55 ubu16 kernel: [  605.465343]  ret_from_fork+0x35/0x40
Dec 27 11:46:55 ubu16 kernel: [  605.465356] INFO: task btrfs-transacti:1240 blocked for more than 120 seconds.
Dec 27 11:46:55 ubu16 kernel: [  605.466043]       Not tainted 4.19.0-041900-generic #201810221809
Dec 27 11:46:55 ubu16 kernel: [  605.466589] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 27 11:46:55 ubu16 kernel: [  605.467150] btrfs-transacti D    0  1240      2 0x80000000
Dec 27 11:46:55 ubu16 kernel: [  605.467152] Call Trace:
Dec 27 11:46:55 ubu16 kernel: [  605.467157]  __schedule+0x29e/0x840
Dec 27 11:46:55 ubu16 kernel: [  605.467158]  ? mutex_lock+0x12/0x30
Dec 27 11:46:55 ubu16 kernel: [  605.467176]  ? btrfs_scrub_pause+0xd1/0xf0 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.467178]  schedule+0x2c/0x80
Dec 27 11:46:55 ubu16 kernel: [  605.467190]  btrfs_commit_transaction+0x228/0x870 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.467192]  ? wait_woken+0x80/0x80
Dec 27 11:46:55 ubu16 kernel: [  605.467204]  transaction_kthread+0x15c/0x190 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.467206]  kthread+0x120/0x140
Dec 27 11:46:55 ubu16 kernel: [  605.467217]  ? btrfs_cleanup_transaction+0x560/0x560 [btrfs]
Dec 27 11:46:55 ubu16 kernel: [  605.467219]  ? kthread_bind+0x40/0x40
Dec 27 11:46:55 ubu16 kernel: [  605.467220]  ret_from_fork+0x35/0x40
samywee commented 3 years ago

As a next step, I mounted the same drive on a Ubuntu 20.04 LTS with Kernel 5.4. Started with a clean hash-table and DB_SIZE of 640MB. OS crashed completly (Froze), without the ability to interact with the OS. Here is the last few lines from the bees, log I saw, before freeze.

At this point I assume, my data may not be a dedup cadidate.

<4>crawl_5[2514]: WORKAROUND: abandoned toxic match for hash 0xe5d0535390900090 addr 0x75fb52e000tz16000 matching bbd BeesBlockData { 4K 0x4c2e000 fd = 895 'DESKTOP-5BNIGNB/201225-1851_Image_C/Image_C_201225-1851.vhd', address = 0xcc642000z9000, hash = 0xe5d0535390900090, data[4096] }
<4>crawl_5[2513]: WORKAROUND: abandoned toxic match for hash 0x2e529a0b159a639c addr 0x63d09000tzf000 matching bbd BeesBlockData { 4K 0x4cf2000 fd = 895 'DESKTOP-5BNIGNB/201225-1851_Image_C/Image_C_201225-1851.vhd', address = 0x63d09000zf000, hash = 0x2e529a0b159a639c, data[4096] }
<5>crawl_5[2514]: WORKAROUND: toxic address: addr = 0x89724000, sys_usage_delta = 1.684, user_usage_delta = 0, rt_age = 2.20284, refs 790
<5>crawl_5[2514]:
<5>crawl_5[2514]:
<5>crawl_5[2514]: *** EXCEPTION ***
<5>crawl_5[2514]:       exception type std::runtime_error: failed constraint check (!m_is_toxic) at bees-resolve.cc:260
<5>crawl_5[2514]: ***
<4>crawl_5[2514]: WORKAROUND: abandoned toxic match for hash 0xe5d0535390900090 addr 0x75fb52e000tz16000 matching bbd BeesBlockData { 4K 0x511d000 fd = 895 'DESKTOP-5BNIGNB/201225-1851_Image_C/Image_C_201225-1851.vhd', address = 0xa3853000z1a000, hash = 0xe5d0535390900090, data[4096] }
<4>crawl_5[2514]: WORKAROUND: abandoned toxic match for hash 0xe5d0535390900090 addr 0x75fb52e000tz16000 matching bbd BeesBlockData { 4K 0x512b000 fd = 895 'DESKTOP-5BNIGNB/201225-1851_Image_C/Image_C_201225-1851.vhd', address = 0xd6c2d000z8000, hash = 0xe5d0535390900090, data[4096] }
<4>crawl_5[2514]: WORKAROUND: abandoned toxic match for hash 0xe5d0535390900090 addr 0x75fb52e000tz16000 matching bbd BeesBlockData { 4K 0x54f6000 fd = 895 'DESKTOP-5BNIGNB/201225-1851_Image_C/Image_C_201225-1851.vhd', address = 0xd6d96000z19000, hash = 0xe5d0535390900090, data[4096] }
<4>crawl_5[2514]: WORKAROUND: abandoned toxic match for hash 0xe5d0535390900090 addr 0x75fb52e000tz16000 matching bbd BeesBlockData { 4K 0x59e0000 fd = 895 'DESKTOP-5BNIGNB/201225-1851_Image_C/Image_C_201225-1851.vhd', address = 0xd6fc5000z15000, hash = 0xe5d0535390900090, data[4096] }
<4>crawl_5[2514]: WORKAROUND: abandoned toxic match for hash 0xe5d0535390900090 addr 0x75fb52e000tz16000 matching bbd BeesBlockData { 4K 0x59eb000 fd = 895 'DESKTOP-5BNIGNB/201225-1851_Image_C/Image_C_201225-1851.vhd', address = 0xd6fcb000z0, hash = 0xe5d0535390900090, data[4096] }
<5>crawl_5[2514]: WORKAROUND: toxic address: addr = 0x622f1000, sys_usage_delta = 0.706, user_usage_delta = 0, rt_age = 0.864383, refs 562
<4>crawl_5[2514]: WORKAROUND: discovered toxic match at found_addr 0x622f1000z1b000 matching bbd BeesBlockData { 4K 0x5cb7000 fd = 895 'DESKTOP-5BNIGNB/201225-1851_Image_C/Image_C_201225-1851.vhd', address = 0xcacb3000z2000, hash = 0x560caf0ff3c63669, data[4096] }
<4>crawl_5[2514]: WORKAROUND: discovered toxic match at found_addr 0x622f1000z13000 matching bbd BeesBlockData { 4K 0x5e8d000 fd = 895 'DESKTOP-5BNIGNB/201225-1851_Image_C/Image_C_201225-1851.vhd', address = 0xd218b000z1d000, hash = 0x9e4f081497506c1a, data[4096] }
<4>crawl_5[2514]: WORKAROUND: abandoned toxic match for hash 0x9e4f081497506c1a addr 0x622f1000tz13000 matching bbd BeesBlockData { 4K 0x5e96000 fd = 895 'DESKTOP-5BNIGNB/201225-1851_Image_C/Image_C_201225-1851.vhd', address = 0xbe777000z6000, hash = 0x9e4f081497506c1a, data[4096] }
<5>crawl_5[2513]: WORKAROUND: toxic address: addr = 0x90b5d000, sys_usage_delta = 3.628, user_usage_delta = 0, rt_age = 4.30109, refs 3826
<5>crawl_5[2513]:
<5>crawl_5[2513]:
<5>crawl_5[2513]: *** EXCEPTION ***
<5>crawl_5[2513]:       exception type std::runtime_error: failed constraint check (!m_is_toxic) at bees-resolve.cc:260
<5>crawl_5[2513]: ***
<5>crawl_5[2514]: WORKAROUND: toxic address: addr = 0xe1d0c000, sys_usage_delta = 1.065, user_usage_delta = 0, rt_age = 1.19397, refs 464
<5>crawl_5[2514]:
<5>crawl_5[2514]:
<5>crawl_5[2514]: *** EXCEPTION ***
<5>crawl_5[2514]:       exception type std::runtime_error: failed constraint check (!m_is_toxic) at bees-resolve.cc:260
<5>crawl_5[2514]: ***
<5>crawl_5[2514]: WORKAROUND: toxic address: addr = 0xdbac0000, sys_usage_delta = 1.677, user_usage_delta = 0, rt_age = 1.97478, refs 1071
<5>crawl_5[2514]:
<5>crawl_5[2514]:
<5>crawl_5[2514]: *** EXCEPTION ***
<5>crawl_5[2514]:       exception type std::runtime_error: failed constraint check (!m_is_toxic) at bees-resolve.cc:260
<5>crawl_5[2514]: ***
<4>crawl_5[2514]: PERFORMANCE: 29.286 sec: Resolving addr 0xb424e000 in /run/bees/mnt/fe151c71-0f9c-4205-b47f-3b1c91b5f678 refs 146804
<5>crawl_5[2514]: WORKAROUND: toxic address: addr = 0xb424e000, sys_usage_delta = 25.671, user_usage_delta = 0, rt_age = 29.2875, refs 146804
kakra commented 3 years ago

I've seen similar dmesg logs lately (hung task with btrfs calls in the backtrace) but not triggered by bees for me. I'm seeing it when Steam downloads data at 100 MB/s and rewrites files using binary delta patches. This makes the system go to 300+ loadavg but it eventually recovers after 30-60 minutes. This behavior seems to have evolved somewhere between 5.4.40 and 5.4.60. As soon as the high load is gone, bees kicks in again and processes the new data just fine.

So did you see high write rates just before this issue raises?

samywee commented 3 years ago

In the case of kernel 5.4 testing (Ubuntu 20.04), this OS is dedicated for bees. OS was 100% hung, no logins, open ssh connections were disconnected. Console was not responding. OS had 4GB of memory / 2 CPU / ~ 500GB data set and 640MB DB_Size. I did not collect, disk io information from OS, but by looking from vm history from hypervisor level disk has more reads than writes before io stopeed.

Zygo commented 3 years ago

Kernels before 5.7 have problems with very high reference counts starting with files as small as 1GB. bees detects that (see all the references to "toxic extents" in the logs) and will avoid them, but in this case bees seems to be overwhelmed by the sheer number of them:

<5>crawl_5[2514]: WORKAROUND: toxic address: addr = 0xb424e000, sys_usage_delta = 25.671, user_usage_delta = 0, rt_age = 29.2875, refs 146804

That extent has almost 150,000 references, and takes just over 25 CPU seconds to enumerate backrefs. It's not even 4GB into the file, so if the file is very large, this will only get worse on old kernels. This will also affect overwriting and deleting the file, not just dedupe (dedupe is affected because it is an overwrite and delete).

You might have better luck with bees -c1 (force only one worker thread to avoid running LOGICAL_INO calls in parallel, because this seems to trigger aggressive lock contention in the kernel that makes all the problems worse).

If you can, try with kernel 5.8 or 5.9. Since 5.7 there has been significant improvement in the kernel here. I disabled the toxic extent detector in a test build and I haven't had to turn it back on when running newer kernels.

samywee commented 3 years ago

Yes these image files are about 100GB in size. I will see if I can create a test-bed with kernel 5.8.

samywee commented 3 years ago

If you can, try with kernel 5.8 or 5.9. Since 5.7 there has been significant improvement in the kernel here. I disabled the toxic extent detector in a test build and I haven't had to turn it back on when running newer kernels.

I installed kernel 5.8 and has been running for about 8Hrs. Seems to be no hangs as before. Not understanding what you meant "I disabled the toxic extent detector in a test build and I haven't had to turn it back on when running newer kernels.". Is there a particular version that you want me to try? Don't understand the verbiage "toxic extent"?

Not sure what these exceptions are ; (Few lines pasted)

Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]: *** EXCEPTION ***
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         exception type std::invalid_argument: *this = ExtentWalker { fd = DESKTOP-CQL6TOH/201228-2355_Image_C/Image_C_201228-2355.raw, stat.st_size = 0x69bbe7f000, extents = ExtentWalker::Vec {
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fb3000, end = 0x1fe1fb5000, physical = 0xa2f2d000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0xb000, logical_len = 0x2000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fb5000, end = 0x1fe1fb6000, physical = 0x6be4de000, flags = , physical_len = 0x1000, logical_len = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fb6000, end = 0x1fe1fb7000, physical = 0xa2f2d000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0xb000, logical_len = 0x1000, offset = 0x3000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fb7000, end = 0x1fe1fb8000, physical = 0xa2f2d000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0xb000, logical_len = 0x1000, offset = 0x4000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fb8000, end = 0x1fe1fb9000, physical = 0x6be4e0000, flags = , physical_len = 0x1000, logical_len = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fb9000, end = 0x1fe1fba000, physical = 0x1d7d63000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x3000, logical_len = 0x1000, offset = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fba000, end = 0x1fe1fbb000, physical = 0x6be4e1000, flags = , physical_len = 0x1000, logical_len = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fbb000, end = 0x1fe1fbc000, physical = 0xa2f2d000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0xb000, logical_len = 0x1000, offset = 0x8000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fbc000, end = 0x1fe1fbd000, physical = 0x6be4e2000, flags = , physical_len = 0x1000, logical_len = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fbd000, end = 0x1fe1fbe000, physical = 0x5d7822000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x2000, logical_len = 0x1000, offset = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fbe000, end = 0x1fe1fbf000, physical = 0xa6254000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x1000, offset = 0x14000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fbf000, end = 0x1fe1fc0000, physical = 0x78de27000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x4000, logical_len = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fc0000, end = 0x1fe1fc3000, physical = 0x6be4e4000, flags = FIEMAP_EXTENT_ENCODED, physical_len = 0x3000, logical_len = 0x3000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fc3000, end = 0x1fe1fc4000, physical = 0x1d7e15000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x12000, logical_len = 0x1000, offset = 0x4000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fc4000, end = 0x1fe1fc8000, physical = 0x6be4e5000, flags = FIEMAP_EXTENT_ENCODED, physical_len = 0x4000, logical_len = 0x4000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]:         Extent { begin = 0x1fe1fc8000, end = 0x1fe1fc9000, physical = 0x214bbed000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x5000, logical_len = 0x1000, offset = 0x4000 }}, current = [16] }, m_extents.size() = 16 failed constraint check (m_current != m_extents.end()) at extentwalker.cc:386
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[11117]: ***
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]: *** EXCEPTION ***
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         exception type std::invalid_argument: *this = ExtentWalker { fd = DESKTOP-CQL6TOH/201228-2351_Image_C/Image_C_201228-2351.raw, stat.st_size = 0x69bbe7f000, extents = ExtentWalker::Vec {
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33db000, end = 0x1fe33dd000, physical = 0x0, flags = Extent::HOLE| }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33dd000, end = 0x1fe33de000, physical = 0xa2f41000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x7000, logical_len = 0x1000, offset = 0x3000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33de000, end = 0x1fe33df000, physical = 0x29a1900000, flags = , physical_len = 0x1000, logical_len = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33df000, end = 0x1fe33e0000, physical = 0x1c2556000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x2000, logical_len = 0x1000, offset = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33e0000, end = 0x1fe33e1000, physical = 0xa2f41000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x7000, logical_len = 0x1000, offset = 0x6000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33e1000, end = 0x1fe33e2000, physical = 0xa6254000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x1000, offset = 0x14000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33e2000, end = 0x1fe33e3000, physical = 0xa2f57000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x2000, logical_len = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33e3000, end = 0x1fe33e4000, physical = 0x29a1901000, flags = , physical_len = 0x1000, logical_len = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33e4000, end = 0x1fe33e5000, physical = 0xa6254000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x1000, offset = 0x14000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33e5000, end = 0x1fe33e6000, physical = 0xa2f59000, flags = , physical_len = 0x1000, logical_len = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33e6000, end = 0x1fe33e7000, physical = 0xa6254000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x1000, offset = 0x14000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33e7000, end = 0x1fe33e8000, physical = 0x1d5e4a000, flags = , physical_len = 0x1000, logical_len = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33e8000, end = 0x1fe33e9000, physical = 0x29a1902000, flags = , physical_len = 0x1000, logical_len = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33e9000, end = 0x1fe33ea000, physical = 0x1d7f2e000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x9000, logical_len = 0x1000, offset = 0x1000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33ea000, end = 0x1fe33ed000, physical = 0x1c37ff3a000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x3000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33ed000, end = 0x1fe33ee000, physical = 0x1d7f2e000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x9000, logical_len = 0x1000, offset = 0x5000 }
Dec 29 21:47:18 ubu20 beesd[1971]: crawl_2317[21917]:         Extent { begin = 0x1fe33ee000, end = 0x1fe33ef000, physical = 0x1cb1b31d000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x1000 }}, current = [17] }, m_extents.size() = 17 failed constraint check (m_current != m_extents.end()) at extentwalker.cc:386

Here is the stat - file ;

Now:     2020-12-29-21-14-11
Uptime:  25227.5 seconds
Version: v0.6-126-g10af3f9

Hash table page occupancy histogram (19134503/41943040 cells occupied, 45%)
                                                                 32768 pages
                           ####                                  16384
                         ########                                8192
                        ##########                               4096
                       ############                              2048
                      ##############                             1024
                      ###############                            512
                     #################                           256
                     #################                           128
                    ###################                          64
                    ###################                          32
                   #####################                         16
                   ######################                        8
                   ######################                        4
                 ########################                      # 2
                 #########################                     # 1
0%      |      25%      |      50%      |      75%      |   100% page fill
compressed 11565489 (60%)
uncompressed 7569014 (39%) unaligned_eof 6962 (0%) toxic 41 (0%)

TOTAL:
  addr_block=122369890 addr_compressed_offset=69510068 addr_eof_e=83 addr_from_fd=87270591 addr_from_root_fd=5286182 addr_hole=7162940 addr_magic=7162940 addr_ms=1149703 addr_uncompressed=52859822
  adjust_compressed_offset_correct=1112669 adjust_eof_haystack=3 adjust_eof_hit=3 adjust_eof_needle=3 adjust_exact=450290 adjust_exact_correct=189269 adjust_hit=1301938 adjust_miss=278850 adjust_needle_too_long=2 adjust_offset_high=1612893 adjust_offset_hit=1130500 adjust_offset_low=695403 adjust_try=3889089
  block_bytes=438139428914 block_hash=64346518 block_ms=6993478 block_read=106967654 block_zero=1899470
  bug_dedup_same_physical=4
  chase_corrected=367376 chase_hit=1301941 chase_no_data=2587148 chase_try=5286535 chase_uncorrected=934565 chase_wrong_addr=1385474 chase_wrong_magic=11619
  crawl_blacklisted=5990 crawl_create=2262 crawl_empty=1085 crawl_gen_high=146144 crawl_gen_low=34246 crawl_hole=110718 crawl_inline=476 crawl_items=1739616 crawl_ms=4716 crawl_nondata=5447 crawl_push=1436595 crawl_restart=1071 crawl_scan=1436521 crawl_search=218551
  dedup_bytes=117197692142 dedup_copy=12350459904 dedup_hit=1280737 dedup_ms=1866361 dedup_try=1280737
  exception_caught=2905 exception_caught_silent=18432
  hash_already=10213758 hash_bump=7405576 hash_erase=725266 hash_erase_miss=626716 hash_evict=127552 hash_extent_in=5120 hash_extent_out=228560 hash_front=298213 hash_front_already=522061 hash_insert=22077402 hash_lookup=60706100
  inserted_block=29643704 inserted_clobbered=626872
  matched_0=32145172 matched_1_or_more=1184584 matched_2_or_more=18130 matched_3_or_more=8830
  open_clear=76 open_file=5939 open_hit=5939 open_ino_ms=31539 open_lookup_ok=5939 open_root_ms=685
  pairbackward_bof_first=3385 pairbackward_hit=182699 pairbackward_miss=262556 pairbackward_ms=1953230 pairbackward_overlap=9 pairbackward_same=4286 pairbackward_stop=1283098 pairbackward_toxic_addr=4 pairbackward_try=452988 pairbackward_zero=3
  pairforward_eof_first=108707 pairforward_eof_malign=3203 pairforward_hit=27173852 pairforward_miss=320376 pairforward_ms=15625923 pairforward_overlap=2415 pairforward_same=6663 pairforward_stop=1280750 pairforward_toxic_hash=747 pairforward_try=27621160 pairforward_zero=2849
  replacedst_dedup_hit=836193 replacedst_grown=652571 replacedst_overlaps=276 replacedst_same=18432 replacedst_try=1201771
  replacesrc_dedup_hit=444544 replacesrc_grown=358998 replacesrc_try=290567
  resolve_fail=126214 resolve_ms=17845788 resolve_ok=1261711 resolve_toxic=14
  root_clear=76 root_found=936 root_ok=936 root_parent_open_ok=936 root_parent_open_try=936
  scan_block=33962998 scan_bump=836193 scan_dup_block=23479304 scan_dup_hit=836193 scan_dup_miss=344434 scan_erase_redundant=677 scan_extent=1458489 scan_forward=1436488 scan_found=19251826 scan_hash_hit=836193 scan_hash_miss=344434 scan_hash_preinsert=33962998 scan_hole=2529 scan_lookup=33348802 scan_no_rewrite=451426 scan_push_front=820253 scan_reinsert=2647456 scan_resolve_hit=1269955 scan_resolve_zero=379999 scan_rewrite=290430 scan_toxic_hash=19024 scan_toxic_match=21 scan_twice=17582826 scan_zero_compressed=8909 scan_zero_uncompressed=940
  scanf_extent=1437181 scanf_extent_ms=47467729 scanf_total=1436485 scanf_total_ms=49635801
  tmp_aligned=290593 tmp_block=2649360 tmp_block_zero=365889 tmp_bytes=10851778560 tmp_copy=290593 tmp_copy_ms=4373 tmp_create=2 tmp_resize=581188 tmp_resize_ms=36782

RATES:
  addr_block=4850.66 addr_compressed_offset=2755.34 addr_eof_e=0.004 addr_from_fd=3459.35 addr_from_root_fd=209.541 addr_hole=283.935 addr_magic=283.935 addr_ms=45.574 addr_uncompressed=2095.33
  adjust_compressed_offset_correct=44.106 adjust_eof_haystack=0.001 adjust_eof_hit=0.001 adjust_eof_needle=0.001 adjust_exact=17.85 adjust_exact_correct=7.503 adjust_hit=51.608 adjust_miss=11.054 adjust_needle_too_long=0.001 adjust_offset_high=63.935 adjust_offset_hit=44.813 adjust_offset_low=27.566 adjust_try=154.161
  block_bytes=1.73676e+07 block_hash=2550.66 block_ms=277.217 block_read=4240.13 block_zero=75.294
  bug_dedup_same_physical=0.001
  chase_corrected=14.563 chase_hit=51.609 chase_no_data=102.553 chase_try=209.555 chase_uncorrected=37.046 chase_wrong_addr=54.92 chase_wrong_magic=0.461
  crawl_blacklisted=0.238 crawl_create=0.09 crawl_empty=0.044 crawl_gen_high=5.794 crawl_gen_low=1.358 crawl_hole=4.389 crawl_inline=0.019 crawl_items=68.958 crawl_ms=0.187 crawl_nondata=0.216 crawl_push=56.946 crawl_restart=0.043 crawl_scan=56.943 crawl_search=8.664
  dedup_bytes=4.64564e+06 dedup_copy=489564 dedup_hit=50.768 dedup_ms=73.982 dedup_try=50.768
  exception_caught=0.116 exception_caught_silent=0.731
  hash_already=404.867 hash_bump=293.553 hash_erase=28.75 hash_erase_miss=24.843 hash_evict=5.057 hash_extent_in=0.203 hash_extent_out=9.06 hash_front=11.821 hash_front_already=20.695 hash_insert=875.134 hash_lookup=2406.35
  inserted_block=1175.06 inserted_clobbered=24.849
  matched_0=1274.21 matched_1_or_more=46.957 matched_2_or_more=0.719 matched_3_or_more=0.351
  open_clear=0.004 open_file=0.236 open_hit=0.236 open_ino_ms=1.251 open_lookup_ok=0.236 open_root_ms=0.028
  pairbackward_bof_first=0.135 pairbackward_hit=7.243 pairbackward_miss=10.408 pairbackward_ms=77.425 pairbackward_overlap=0.001 pairbackward_same=0.17 pairbackward_stop=50.862 pairbackward_toxic_addr=0.001 pairbackward_try=17.957 pairbackward_zero=0.001
  pairforward_eof_first=4.31 pairforward_eof_malign=0.127 pairforward_hit=1077.15 pairforward_miss=12.7 pairforward_ms=619.402 pairforward_overlap=0.096 pairforward_same=0.265 pairforward_stop=50.769 pairforward_toxic_hash=0.03 pairforward_try=1094.88 pairforward_zero=0.113
  replacedst_dedup_hit=33.147 replacedst_grown=25.868 replacedst_overlaps=0.011 replacedst_same=0.731 replacedst_try=47.638
  replacesrc_dedup_hit=17.622 replacesrc_grown=14.231 replacesrc_try=11.518
  resolve_fail=5.004 resolve_ms=707.396 resolve_ok=50.014 resolve_toxic=0.001
  root_clear=0.004 root_found=0.038 root_ok=0.038 root_parent_open_ok=0.038 root_parent_open_try=0.038
  scan_block=1346.27 scan_bump=33.147 scan_dup_block=930.705 scan_dup_hit=33.147 scan_dup_miss=13.654 scan_erase_redundant=0.027 scan_extent=57.814 scan_forward=56.942 scan_found=763.13 scan_hash_hit=33.147 scan_hash_miss=13.654 scan_hash_preinsert=1346.27 scan_hole=0.101 scan_lookup=1321.92 scan_no_rewrite=17.895 scan_push_front=32.515 scan_reinsert=104.944 scan_resolve_hit=50.341 scan_resolve_zero=15.063 scan_rewrite=11.513 scan_toxic_hash=0.755 scan_toxic_match=0.001 scan_twice=696.972 scan_zero_compressed=0.354 scan_zero_uncompressed=0.038
  scanf_extent=56.969 scanf_extent_ms=1881.59 scanf_total=56.942 scanf_total_ms=1967.53
  tmp_aligned=11.519 tmp_block=105.019 tmp_block_zero=14.504 tmp_bytes=430157 tmp_copy=11.519 tmp_copy_ms=0.174 tmp_create=0.001 tmp_resize=23.038 tmp_resize_ms=1.459
kakra commented 3 years ago

"toxic extents" are extents that require more time to process in the kernel than a specified (hard-coded) timeout. Bees will remove those from the hash table as far as I understood to not reuse those extents for deduplication as it would only slow down bees and ordinary file system operations on the affected files. I'm pretty sure @Zygo has some "define" in the source code to disable that detection. You could change it and recompile but you usually wouldn't need to switch that behavior at all. What that sentence is saying: With newer kernel, the toxic extent detector seems not to be needed any longer, turning it off does no harm. But for you it means: Leaving it on does no harm, either. For all older kernels, the detector is needed to not slow the file system down.

I think it may make sense to just defragment the files affected by toxic extents, given that you can live with them no longer being deduplicated. Bees will re-scan such files then but the previous toxic extents will now be deduplicated with non-toxic extents as bees has removed previous knowledge of toxic hashes from the hash table. Over time, when those extents reach a high deduplication rate, those extents may become toxic again - that's the whole problem of btrfs which was fixed in newer kernels: The backref walking can become really slow with higher sharing rates and block concurrent file system operations, and bees does a lot of those.

Zygo commented 3 years ago

A toxic extent is simply an extent with references that trigger a very long CPU loop in the btrfs kernel code that deals with extent references. They can be produced by any deduper on btrfs, and possibly also by writing to several different snapshots or clones of a file. While the loop is running, the filesystem cannot be modified (the current transaction cannot end and new transactions cannot start), objects with exclusive locks can't be read (which is why the directory is inaccessible), and the CPU core cannot run any other task (so if you have a single-core system or if the problem affects all the bees threads at once, the system appears to lock up entirely).

bees marks extents toxic with a bit in the hash table. This means that once a block in a toxic extent is identified, any block containing the same data will also be considered toxic in the future. That will prevent any extent containing the same data from being deduped later, even if the original file is defragmented or deleted. The goal is to have bees identify which data is likely to trigger the kernel bug, and avoid it in the future.

Normally a filesystem only has 0.001% toxic extents, and once they are identified and excluded (which will lock up the kernel for a few seconds) everything is fine; however, a 100G file has such bad performance on old kernels that even 0.001% of extents is far too many.

In older kernels, a backref search will search the entire file for a matching reference, instead of just the small region of the file where a match is possible. On 100G files, that search will take a long time (we see 30 seconds per search in the logs above, but a btrfs deduper with no toxic extent detector can trigger kernel CPU stalls lasting hours). On big files there are many thousands of searches at different places in the file as well.

Newer kernels have several optimizations of the backref search, so it takes much less time, and is not affected by file size.

The toxic extent detector simply measures kernel CPU usage. This means it can get false positives from high-CPU kernel operations that are not backref search (e.g. flush and delayed refs operations are performed by whichever kernel thread detects they are required, so a random process thread can be forced to perform most of the work of a full transaction commit). On kernels before 5.7, the backref searches are 99% of the kernel CPU time or more, so false positives are fewer than 1%. On 5.7 and later, the toxic extent detector only finds false positives, since true positives have been eliminated in the kernel, so bees avoids a few blocks at random that it does not need to. This affects less than 1% of deduped extents, so it's not a big problem right now.

kakra commented 3 years ago

I was under the impression that "abandoned toxic match" means discarding the hash from the table, and future duplicates would be created from another copy of the extent. But since you're keeping them, defragmentation would just unshare the extents that are already toxic and bees will leave those hashes untouched in the future.

How does bees handle LRU for such hashes? Since they are no longer used, they will be pushed out of the hash table earlier, correct?

samywee commented 3 years ago

So what does this HOLE deletion step mean, Does HOLE deletion achive any storage-space gain? Or it is done to reduce the allocated space?

Dec 30 15:19:54 ubu20 beesd[22767]: crawl_2324[27202]: scan: 128K 0x420b71000 [++++++++++++++++++++++++++++++++] 0x420b91000 DESKTOP-CQL6TOH/201229-0042_Image_C/Image_C_201229-0042.raw
Dec 30 15:19:54 ubu20 beesd[22767]: crawl_2324[27202]: copy: 128K [0x420bb1000..0x420bd1000] fd = 8 'DESKTOP-CQL6TOH/201229-0042_Image_C/Image_C_201229-0042.raw'
Dec 30 15:19:54 ubu20 beesd[22767]: crawl_2324[27202]: dedup: src 128K [0x1000..0x21000] {HOLE} #488401 (deleted)
Dec 30 15:19:54 ubu20 beesd[22767]: crawl_2324[27202]:        dst 128K [0x420bb1000..0x420bd1000] {0x1c01c7dd000z0} DESKTOP-CQL6TOH/201229-0042_Image_C/Image_C_201229-0042.raw
Zygo commented 3 years ago

If bees encounters zero blocks within an extent, it will copy the non-zero data to a new extent and then dedupe the newly created extent (with holes where the zeroes were) to remove the old extent. So the sequence "scan, copy, dedup src: HOLE" usually means that one or more zero blocks have been removed, i.e. they no longer take up space, there is the absence of an extent entry in the metadata).

It is also possible to get src: HOLE extents even when no zero bytes are present. If the extent has not yet been allocated (i.e. because it's a write still in progress) then there's no src address because the extent exists only in memory. The dedupe operation flushes the data to disk, but the log message is already emitted by then.

Zygo commented 3 years ago

How does bees handle LRU for [toxic] hashes? Since they are no longer used, they will be pushed out of the hash table earlier, correct?

Toxic hashes are pushed to the front of the LRU when they are encountered, just like data blocks when a scan matches an existing hash table entry. On old kernels we never want to forget a toxic hash until the data has been completely removed from the filesystem.

samywee commented 3 years ago

Curious..

Following 2 files in 2 directories are identical, and one directorory is a snapshot of the other. It is already not taking extra space due to the fact that it is a snap shot. Bees behavior seems to be try to depup these 2 files. Is there a way to avoid this step as it is not necessary due to the fact they are part of a snapshot?

201230-1308/daVinci/TBMC_Vas05.mov 201228-2138/daVinci/TBMC_Vas05.mov

Dec 31 15:07:52 ubu20 beesd[22767]: crawl_2303[92204]: scan: 276K 0x49d3b000 [Ddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddd] 0x49d80000 DESKTOP-CQL6TOH/201228-2138/daVinci/TBMC_Vas05.mov
Dec 31 15:07:52 ubu20 beesd[22767]: crawl_2303[92205]: dedup: src 140K [0x49ecc000..0x49eef000] {0x19f8d48c000} DESKTOP-CQL6TOH/201230-1308/daVinci/TBMC_Vas05.mov
Dec 31 15:07:52 ubu20 beesd[22767]: crawl_2303[92205]:        dst 140K [0x49ecc000..0x49eef000] {0x19fe153e000} DESKTOP-CQL6TOH/201228-2138/daVinci/TBMC_Vas05.mov
Zygo commented 3 years ago

They had different physical addresses (0x19f8d48c000 vs 0x19fe153e000). If there is a third file with the same content, bees will dedupe all of them against the first one it finds (yes, it could be smarter than that, been working on that for a while).

You can use btrfs ins log 0x19fe153e000 /path/to/fs to see what other files that extent appears in.

kakra commented 3 years ago

In older kernels, a backref search will search the entire file for a matching reference, instead of just the small region of the file where a match is possible. On 100G files, that search will take a long time (we see 30 seconds per search in the logs above, but a btrfs deduper with no toxic extent detector can trigger kernel CPU stalls lasting hours). On big files there are many thousands of searches at different places in the file as well.

So I finally could upgrade to kernel 5.10.4 and purged my hash file empty and removed the crawl status so bees would restart from scratch: This looks fantastic so far: All the files which previously would trigger the toxic extent warning pretty early were successfully processed by bees now, even deduping some gigabytes of data so far that was previously avoided by bees.

BTW: Happy new year!

kakra commented 3 years ago

I'm not sure if the toxic hash detector could be disabled for current kernels: I'm still seeing toxic hashes found in large files with extremely common hashes (some game data, probably common asset headers). But the situation has vastly improved with updating to kernel 5.10.4 (from 5.4.85 and older). dmesg is clean, tho: No mention of "hung tasks" so far.

samywee commented 3 years ago

Since I installed 5.8 kernel, things are bit stable, no krashes / hangups for about 2 days now. One thing I am noticing is that compsize /path/to/btrfs takes a long time now since the fs is deduped. Is this a known phenomenon of dedup? Prior to dedup, it used to complete in 20 seconds or so. Now it take 300 seconds. Why that is happenning no idea? Any input?

Happy New Year!