Bug 212331

Summary: btrfs NULL pointer dereference compress_file_range+0x6e9/0x7a0
Product: File System Reporter: Tomas Thiemel (thiemel)
Component: btrfsAssignee: BTRFS virtual assignee (fs_btrfs)
Status: RESOLVED CODE_FIX    
Severity: normal CC: dsterba, l, thiemel
Priority: P1    
Hardware: x86-64   
OS: Linux   
Kernel Version: 5.10.23-gentoo Subsystem:
Regression: No Bisected commit-id:
Attachments: output of "strace -f rsync" before the kernel bug

Description Tomas Thiemel 2021-03-18 16:26:57 UTC
How to reproduce:
- launch "bees" (best-effort extent-same deduplication on btrfs) on filesystem
- launch rsync on the same filesystem with "--inplace" option



### KERNEL ###
ftp1 ~ # uname -a
Linux ftp1 5.10.23-gentoo-xeon #1 SMP Thu Mar 18 12:09:07 CET 2021 x86_64 Intel(R) Xeon(R) CPU E3-1265L V2 @ 2.50GHz GenuineIntel GNU/Linux



### BEES dedup application ###
ftp1 ~ # beesd|head
Usage: beesd [options] <btrfs_uuid>
- - -
bees version v0.6.4
Usage: /usr/libexec/bees [options] fs-root-path [fs-root-path-2...]
Performs best-effort extent-same deduplication on btrfs.



### KERNEL BUG ###
[10596.479433] BUG: kernel NULL pointer dereference, address: 0000000000000018
[10596.487325] #PF: supervisor read access in kernel mode
[10596.487326] #PF: error_code(0x0000) - not-present page
[10596.487327] PGD 0 P4D 0
[10596.487331] Oops: 0000 [#1] SMP
[10596.487333] CPU: 5 PID: 17902 Comm: kworker/u16:13 Tainted: G       A          5.10.23-gentoo-xeon #1
[10596.487334] Hardware name: MSI MS-7759/Z77MA-G45 (MS-7759), BIOS V1.9 03/01/2013
[10596.487339] Workqueue: btrfs-delalloc btrfs_work_helper
[10596.525468] RIP: 0010:compress_file_range+0x6e9/0x7a0
[10596.525472] Code: 01 00 4d 85 ff 0f 84 83 fc ff ff 31 db 31 c0 48 83 7c 24 48 00 75 0f eb 33 83 c3 01 48 63 c3 48 3b 44 24 48 73 26 49 8b 3c c7 <48> 83 7f 18 00 75 2b 48 8b 47 08 48 8d 50 ff a8 01 48 0f 45 fa f0
[10596.558098] RSP: 0018:ffffc9000047fd38 EFLAGS: 00010202
[10596.558100] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[10596.558101] RDX: 0000000000000000 RSI: 00000000000007db RDI: 0000000000000000
[10596.558102] RBP: ffff88816d1829a8 R08: 00000000001e7600 R09: 0000000000000020
[10596.558103] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000001000
[10596.558106] R13: 0000000000000000 R14: 0000000000000000 R15: ffff8883b90d3808
[10596.604744] FS:  0000000000000000(0000) GS:ffff8887fee00000(0000) knlGS:0000000000000000
[10596.604745] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[10596.604748] CR2: 0000000000000018 CR3: 0000000006212002 CR4: 00000000001726e0
[10596.628549] Call Trace:
[10596.628555]  async_cow_start+0xd/0x40
[10596.636489]  btrfs_work_helper+0xdd/0x200
[10596.636492]  process_one_work+0x201/0x3e0
[10596.636493]  ? process_one_work+0x1a4/0x3e0
[10596.636495]  worker_thread+0x4b/0x3a0
[10596.636497]  ? process_one_work+0x3e0/0x3e0
[10596.636500]  kthread+0x110/0x160
[10596.636502]  ? kthread_park+0x80/0x80
[10596.636505]  ret_from_fork+0x1f/0x30
[10596.674744] Modules linked in: xt_state xt_nat tun xt_CHECKSUM ebtable_filter ebtables xt_MASQUERADE xt_conntrack ipt_REJECT nf_reject_ipv4 xt_tcpudp ip6table_mangle ip6table_nat ip6table_filter ip6_tables iptable_mangle iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_filter ip_tables x_tables fuse nfsd auth_rpcgss oid_registry lockd grace sunrpc f2fs nls_iso8859_1 vfat fat dm_raid raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx binfmt_misc at24 regmap_i2c pm80xx iTCO_wdt iTCO_vendor_support dummy x86_pkg_temp_thermal f71882fg kvm_intel coretemp kvm crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel crypto_simd cryptd glue_helper r8169 xhci_pci xhci_hcd i2c_i801 realtek i2c_smbus i2c_core ehci_pci mdio_devres ehci_hcd libphy lpc_ich fan mfd_core usbcore thermal mei_me evdev video backlight mei usb_common
[10596.674807] CR2: 0000000000000018
[10596.674809] ---[ end trace fa12a3e10fc91d45 ]---
[10596.674810] BUG: kernel NULL pointer dereference, address: 0000000000000018
[10596.674814] RIP: 0010:compress_file_range+0x6e9/0x7a0
[10596.674815] #PF: supervisor read access in kernel mode
[10596.674818] Code: 01 00 4d 85 ff 0f 84 83 fc ff ff 31 db 31 c0 48 83 7c 24 48 00 75 0f eb 33 83 c3 01 48 63 c3 48 3b 44 24 48 73 26 49 8b 3c c7 <48> 83 7f 18 00 75 2b 48 8b 47 08 48 8d 50 ff a8 01 48 0f 45 fa f0
[10596.674819] #PF: error_code(0x0000) - not-present page
[10596.674820] PGD 0 P4D 0
[10596.674823] Oops: 0000 [#2] SMP
[10596.674825] CPU: 1 PID: 17901 Comm: kworker/u16:1 Tainted: G      DA          5.10.23-gentoo-xeon #1
[10596.674826] Hardware name: MSI MS-7759/Z77MA-G45 (MS-7759), BIOS V1.9 03/01/2013
[10596.674829] Workqueue: btrfs-delalloc btrfs_work_helper
[10596.674831] RIP: 0010:compress_file_range+0x6e9/0x7a0
[10596.674833] Code: 01 00 4d 85 ff 0f 84 83 fc ff ff 31 db 31 c0 48 83 7c 24 48 00 75 0f eb 33 83 c3 01 48 63 c3 48 3b 44 24 48 73 26 49 8b 3c c7 <48> 83 7f 18 00 75 2b 48 8b 47 08 48 8d 50 ff a8 01 48 0f 45 fa f0
[10596.674834] RSP: 0018:ffffc900009a7d38 EFLAGS: 00010202
[10596.674835] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[10596.674836] RDX: 0000000000000000 RSI: 00000000000007db RDI: 0000000000000000
[10596.674837] RBP: ffff88816d1be098 R08: 00000000001e7600 R09: 0000000000000020
[10596.674838] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000001000
[10596.674839] R13: 0000000000000000 R14: 0000000000000000 R15: ffff8881014bad28
[10596.674841] FS:  0000000000000000(0000) GS:ffff8887fe600000(0000) knlGS:0000000000000000
[10596.674842] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[10596.674843] CR2: 0000000000000018 CR3: 0000000006212002 CR4: 00000000001726e0
[10596.674843] Call Trace:
[10596.674846]  async_cow_start+0xd/0x40
[10596.674848]  btrfs_work_helper+0xdd/0x200
[10596.674851]  process_one_work+0x201/0x3e0
[10596.674852]  ? process_one_work+0x1a4/0x3e0
[10596.674854]  worker_thread+0x4b/0x3a0
[10596.674856]  ? process_one_work+0x3e0/0x3e0
[10596.674858]  kthread+0x110/0x160
[10596.674860]  ? kthread_park+0x80/0x80
[10596.674862]  ret_from_fork+0x1f/0x30
[10596.674864] Modules linked in: xt_state xt_nat tun xt_CHECKSUM ebtable_filter ebtables xt_MASQUERADE xt_conntrack ipt_REJECT nf_reject_ipv4 xt_tcpudp ip6table_mangle ip6table_nat ip6table_filter ip6_tables iptable_mangle iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_filter ip_tables x_tables fuse nfsd auth_rpcgss oid_registry lockd grace sunrpc f2fs nls_iso8859_1 vfat fat dm_raid raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx binfmt_misc at24 regmap_i2c pm80xx iTCO_wdt iTCO_vendor_support dummy x86_pkg_temp_thermal f71882fg kvm_intel coretemp kvm crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel crypto_simd cryptd glue_helper r8169 xhci_pci xhci_hcd i2c_i801 realtek i2c_smbus i2c_core ehci_pci mdio_devres ehci_hcd libphy lpc_ich fan mfd_core usbcore thermal mei_me evdev video backlight mei usb_common
[10596.674911] CR2: 0000000000000018
[10596.674912] ---[ end trace fa12a3e10fc91d46 ]---
[10596.674914] BUG: kernel NULL pointer dereference, address: 0000000000000018
[10596.674916] RIP: 0010:compress_file_range+0x6e9/0x7a0
[10596.674917] #PF: supervisor read access in kernel mode
[10596.674918] Code: 01 00 4d 85 ff 0f 84 83 fc ff ff 31 db 31 c0 48 83 7c 24 48 00 75 0f eb 33 83 c3 01 48 63 c3 48 3b 44 24 48 73 26 49 8b 3c c7 <48> 83 7f 18 00 75 2b 48 8b 47 08 48 8d 50 ff a8 01 48 0f 45 fa f0
[10596.674919] #PF: error_code(0x0000) - not-present page
[10596.674920] RSP: 0018:ffffc9000047fd38 EFLAGS: 00010202
[10596.674921] PGD 0

[10596.674923] P4D 0
[10596.674923] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000

[10596.674925] RDX: 0000000000000000 RSI: 00000000000007db RDI: 0000000000000000
[10596.674926] Oops: 0000 [#3] SMP
[10596.674927] RBP: ffff88816d1829a8 R08: 00000000001e7600 R09: 0000000000000020
[10596.674929] CPU: 7 PID: 6263 Comm: kworker/u16:8 Tainted: G      DA          5.10.23-gentoo-xeon #1
[10596.674930] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000001000
[10596.674931] Hardware name: MSI MS-7759/Z77MA-G45 (MS-7759), BIOS V1.9 03/01/2013
[10596.674932] R13: 0000000000000000 R14: 0000000000000000 R15: ffff8883b90d3808
[10596.674934] Workqueue: btrfs-delalloc btrfs_work_helper
[10596.674935] FS:  0000000000000000(0000) GS:ffff8887fe600000(0000) knlGS:0000000000000000

[10596.674936] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[10596.674939] RIP: 0010:compress_file_range+0x6e9/0x7a0
[10596.674940] CR2: 0000000000000018 CR3: 0000000006212002 CR4: 00000000001726e0
[10596.674941] Code: 01 00 4d 85 ff 0f 84 83 fc ff ff 31 db 31 c0 48 83 7c 24 48 00 75 0f eb 33 83 c3 01 48 63 c3 48 3b 44 24 48 73 26 49 8b 3c c7 <48> 83 7f 18 00 75 2b 48 8b 47 08 48 8d 50 ff a8 01 48 0f 45 fa f0
[10596.674943] RSP: 0018:ffffc90000b77d38 EFLAGS: 00010202
[10596.674944] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[10596.674945] RDX: 0000000000000000 RSI: 00000000000007db RDI: 0000000000000000
[10596.674946] RBP: ffff88816d28ce48 R08: 00000000001e7600 R09: 0000000000000020
[10596.674947] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000001000
[10596.674948] R13: 0000000000000000 R14: 0000000000000000 R15: ffff88810105f440
[10596.674949] FS:  0000000000000000(0000) GS:ffff8887ff200000(0000) knlGS:0000000000000000
[10596.674950] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[10596.674951] CR2: 0000000000000018 CR3: 0000000006212002 CR4: 00000000001726e0
[10596.674952] Call Trace:
[10596.674956]  async_cow_start+0xd/0x40
[10596.674957]  btrfs_work_helper+0xdd/0x200
[10596.674961]  process_one_work+0x201/0x3e0
[10596.674962]  ? process_one_work+0x1a4/0x3e0
[10596.674964]  worker_thread+0x4b/0x3a0
[10596.674965]  ? process_one_work+0x3e0/0x3e0
[10596.674967]  kthread+0x110/0x160
[10596.674969]  ? kthread_park+0x80/0x80
[10596.674971]  ret_from_fork+0x1f/0x30
[10596.674972] Modules linked in: xt_state xt_nat tun xt_CHECKSUM ebtable_filter ebtables xt_MASQUERADE xt_conntrack ipt_REJECT nf_reject_ipv4 xt_tcpudp ip6table_mangle ip6table_nat ip6table_filter ip6_tables iptable_mangle iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_filter ip_tables x_tables fuse nfsd auth_rpcgss oid_registry lockd grace sunrpc f2fs nls_iso8859_1 vfat fat dm_raid raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx binfmt_misc at24 regmap_i2c pm80xx iTCO_wdt iTCO_vendor_support dummy x86_pkg_temp_thermal f71882fg kvm_intel coretemp kvm crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel crypto_simd cryptd glue_helper r8169 xhci_pci xhci_hcd i2c_i801 realtek i2c_smbus i2c_core ehci_pci mdio_devres ehci_hcd libphy lpc_ich fan mfd_core usbcore thermal mei_me evdev video backlight mei usb_common
[10596.675008] CR2: 0000000000000018
[10596.675009] ---[ end trace fa12a3e10fc91d47 ]---
[10596.675010] RIP: 0010:compress_file_range+0x6e9/0x7a0
[10596.675011] Code: 01 00 4d 85 ff 0f 84 83 fc ff ff 31 db 31 c0 48 83 7c 24 48 00 75 0f eb 33 83 c3 01 48 63 c3 48 3b 44 24 48 73 26 49 8b 3c c7 <48> 83 7f 18 00 75 2b 48 8b 47 08 48 8d 50 ff a8 01 48 0f 45 fa f0
[10596.675012] RSP: 0018:ffffc9000047fd38 EFLAGS: 00010202
[10596.675014] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[10596.675014] RDX: 0000000000000000 RSI: 00000000000007db RDI: 0000000000000000
[10596.675015] RBP: ffff88816d1829a8 R08: 00000000001e7600 R09: 0000000000000020
[10596.675016] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000001000
[10596.675017] R13: 0000000000000000 R14: 0000000000000000 R15: ffff8883b90d3808
[10596.675018] FS:  0000000000000000(0000) GS:ffff8887ff200000(0000) knlGS:0000000000000000
[10596.675018] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[10596.675019] CR2: 0000000000000018 CR3: 0000000006212002 CR4: 00000000001726e0
[10596.675020] BUG: sleeping function called from invalid context at include/linux/percpu-rwsem.h:49
[10596.675021] in_atomic(): 0, irqs_disabled(): 1, non_block: 0, pid: 6263, name: kworker/u16:8
[10596.675021] INFO: lockdep is turned off.
[10596.675022] CPU: 7 PID: 6263 Comm: kworker/u16:8 Tainted: G      DA          5.10.23-gentoo-xeon #1
[10596.675023] Hardware name: MSI MS-7759/Z77MA-G45 (MS-7759), BIOS V1.9 03/01/2013
[10596.675024] Workqueue: btrfs-delalloc btrfs_work_helper
[10596.675025] Call Trace:
[10596.675028]  dump_stack+0x57/0x6a
[10596.675030]  ___might_sleep.cold+0x95/0xa2
[10596.675032]  exit_signals+0x2b/0x220
[10596.675035]  do_exit+0xd0/0xb20
[10596.675036]  ? process_one_work+0x3e0/0x3e0
[10596.675037]  ? kthread+0x110/0x160
[10596.675038]  rewind_stack_do_exit+0x17/0x20
[10596.675040] RIP: 0000:0x0
[10596.675043] Code: Unable to access opcode bytes at RIP 0xffffffffffffffd6.
[10596.675043] RSP: 0000:0000000000000000 EFLAGS: 00000000 ORIG_RAX: 0000000000000000
[10596.675044] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[10596.675047] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[10596.675047] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[10596.675048] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[10596.675048] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[10597.772792] RSP: 0018:ffffc9000047fd38 EFLAGS: 00010202
[10597.779457] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[10597.779458] RDX: 0000000000000000 RSI: 00000000000007db RDI: 0000000000000000
[10597.779459] RBP: ffff88816d1829a8 R08: 00000000001e7600 R09: 0000000000000020
[10597.779459] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000001000
[10597.779460] R13: 0000000000000000 R14: 0000000000000000 R15: ffff8883b90d3808
[10597.779462] FS:  0000000000000000(0000) GS:ffff8887fee00000(0000) knlGS:0000000000000000
[10597.831517] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[10597.831519] CR2: 0000000000000018 CR3: 0000000006212002 CR4: 00000000001726e0
[10597.847142] BUG: sleeping function called from invalid context at include/linux/percpu-rwsem.h:49
[10597.847143] in_atomic(): 0, irqs_disabled(): 1, non_block: 0, pid: 17902, name: kworker/u16:13
[10597.847143] INFO: lockdep is turned off.
[10597.847145] CPU: 5 PID: 17902 Comm: kworker/u16:13 Tainted: G      DAW         5.10.23-gentoo-xeon #1
[10597.847146] Hardware name: MSI MS-7759/Z77MA-G45 (MS-7759), BIOS V1.9 03/01/2013
[10597.847150] Workqueue: btrfs-delalloc btrfs_work_helper
[10597.847152] Call Trace:
[10597.902463]  dump_stack+0x57/0x6a
[10597.902466]  ___might_sleep.cold+0x95/0xa2
[10597.912639]  exit_signals+0x2b/0x220
[10597.912642]  do_exit+0xd0/0xb20
[10597.922123]  ? process_one_work+0x3e0/0x3e0
[10597.922125]  ? kthread+0x110/0x160
[10597.922127]  rewind_stack_do_exit+0x17/0x20
[10597.922129] RIP: 0000:0x0
[10597.922132] Code: Unable to access opcode bytes at RIP 0xffffffffffffffd6.
[10597.950305] RSP: 0000:0000000000000000 EFLAGS: 00000000 ORIG_RAX: 0000000000000000
[10597.950308] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[10597.967741] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[10597.967742] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[10597.967742] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[10597.967743] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
                                                                                                                                                                                


### FROZEN PROCESSES AFTER THE BUG ###
ftp1 ~ # ps auxw|grep -E "D|bees"|grep -v -- "-D"|grep -v grep|grep -v tee|grep -v CRON|sed 's:-avH.*::'
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root       340  0.0  0.0      0     0 ?        D    12:42   0:05 [kcompactd0]
root      6174  0.6  0.0  13504  4784 ?        SNs  14:43   0:29 SCREEN beesd 2cf62913-9dc0-489e-b8fc-310f6e181c13
root      6176  0.0  0.0  11708  3488 pts/4    SNs+ 14:43   0:00 /bin/bash /usr/sbin/beesd 2cf62913-9dc0-489e-b8fc-310f6e181c13
root      6296 32.4  0.0      0     0 pts/4    ZNl+ 14:43  24:38 [bees] <defunct>
root      6708  0.6  0.0      0     0 ?        D    14:43   0:30 [kworker/u16:16+flush-btrfs-4]
root      7854  0.4  0.0      0     0 ?        D    12:43   0:53 [btrfs-transacti]
root     11524  0.4  0.0      0     0 ?        D    15:04   0:13 [kworker/u16:6+btrfs-delayed-meta]
root     24021  0.0  0.0  49208 10120 pts/15   D+   15:36   0:00 rsync
root     25110  0.0  0.0  41056  8148 pts/18   D+   15:36   0:00 rsync
root     25435  0.0  0.0  98108  5048 pts/16   D+   15:38   0:01 rsync
root     25646  0.0  0.0  48448  4540 pts/17   D+   15:40   0:00 rsync



### FILESYSTEM structure (subvolumes) ###
ftp1 ~ # btrfs subvol list /BACKUP/AUTOBACKUP/
ID 259 gen 22639 top level 5 path BACKUP
ID 274 gen 22639 top level 259 path AUTOBACKUP/hosts/fff/backup/actual
ID 282 gen 19610 top level 259 path AUTOBACKUP/hosts/ggg/backup/actual
ID 285 gen 22639 top level 259 path AUTOBACKUP/hosts/uuu/backup/actual
ID 287 gen 22639 top level 259 path AUTOBACKUP/hosts/zzz/backup/actual
ID 288 gen 22639 top level 259 path AUTOBACKUP/hosts/aaa/backup/actual
ID 827 gen 22639 top level 5 path .beeshome
ID 2170 gen 19694 top level 259 path AUTOBACKUP/hosts/uuu/backup/monthly/20201103-308
ID 2231 gen 19689 top level 259 path AUTOBACKUP/hosts/aaa/backup/monthly/20201103-308
ID 2235 gen 19689 top level 259 path AUTOBACKUP/hosts/aaa/backup/monthly/20201106-311
ID 2237 gen 19610 top level 259 path AUTOBACKUP/hosts/fff/backup/monthly/20201106-311
ID 2239 gen 19610 top level 259 path AUTOBACKUP/hosts/ggg/backup/monthly/20201106-311
ID 2264 gen 19694 top level 259 path AUTOBACKUP/hosts/uuu/backup/monthly/20201106-311
ID 2266 gen 19610 top level 259 path AUTOBACKUP/hosts/zzz/backup/monthly/20201106-311
ID 2334 gen 19615 top level 259 path win10virt/actual
ID 2398 gen 19689 top level 259 path AUTOBACKUP/hosts/aaa/backup/monthly/20201205-340
ID 2400 gen 18108 top level 259 path AUTOBACKUP/hosts/fff/backup/monthly/20201205-340
ID 2402 gen 18342 top level 259 path AUTOBACKUP/hosts/ggg/backup/monthly/20201205-340
ID 2425 gen 19694 top level 259 path AUTOBACKUP/hosts/uuu/backup/monthly/20201205-340
ID 2427 gen 18341 top level 259 path AUTOBACKUP/hosts/zzz/backup/monthly/20201205-340
ID 2651 gen 19688 top level 259 path AUTOBACKUP/hosts/aaa/backup/monthly/20210103-003
ID 2653 gen 19610 top level 259 path AUTOBACKUP/hosts/fff/backup/monthly/20210103-003
ID 2655 gen 19694 top level 259 path AUTOBACKUP/hosts/uuu/backup/monthly/20210103-003
ID 2657 gen 19543 top level 259 path AUTOBACKUP/hosts/zzz/backup/monthly/20210103-003
ID 2711 gen 21750 top level 259 path AUTOBACKUP/hosts/aaa/backup/weekly/20210207-038
ID 2712 gen 21744 top level 259 path AUTOBACKUP/hosts/aaa/backup/monthly/20210207-038
ID 2713 gen 21750 top level 259 path AUTOBACKUP/hosts/fff/backup/weekly/20210207-038
ID 2714 gen 21743 top level 259 path AUTOBACKUP/hosts/fff/backup/monthly/20210207-038
ID 2716 gen 21750 top level 259 path AUTOBACKUP/hosts/uuu/backup/weekly/20210207-038
ID 2717 gen 21750 top level 259 path AUTOBACKUP/hosts/uuu/backup/monthly/20210207-038
ID 2718 gen 21756 top level 259 path AUTOBACKUP/hosts/zzz/backup/weekly/20210207-038
ID 2719 gen 21750 top level 259 path AUTOBACKUP/hosts/zzz/backup/monthly/20210207-038
ID 2726 gen 22638 top level 259 path AUTOBACKUP/hosts/aaa/backup/weekly/20210214-045
ID 2727 gen 22632 top level 259 path AUTOBACKUP/hosts/fff/backup/weekly/20210214-045
ID 2729 gen 22629 top level 259 path AUTOBACKUP/hosts/uuu/backup/weekly/20210214-045
ID 2731 gen 22630 top level 259 path AUTOBACKUP/hosts/zzz/backup/weekly/20210214-045
ID 2740 gen 22639 top level 259 path AUTOBACKUP/hosts/aaa/backup/weekly/20210221-052
ID 2741 gen 22632 top level 259 path AUTOBACKUP/hosts/fff/backup/weekly/20210221-052
ID 2743 gen 22630 top level 259 path AUTOBACKUP/hosts/uuu/backup/weekly/20210221-052
ID 2745 gen 22630 top level 259 path AUTOBACKUP/hosts/zzz/backup/weekly/20210221-052
ID 2747 gen 22639 top level 259 path AUTOBACKUP/hosts/aaa/backup/weekly/20210228-059
ID 2748 gen 22633 top level 259 path AUTOBACKUP/hosts/fff/backup/weekly/20210228-059
ID 2751 gen 22638 top level 259 path AUTOBACKUP/hosts/uuu/backup/weekly/20210228-059
ID 2753 gen 22630 top level 259 path AUTOBACKUP/hosts/zzz/backup/weekly/20210228-059
ID 2760 gen 22639 top level 259 path AUTOBACKUP/hosts/aaa/backup/weekly/20210307-066
ID 2761 gen 22639 top level 259 path AUTOBACKUP/hosts/aaa/backup/monthly/20210307-066
ID 2762 gen 22633 top level 259 path AUTOBACKUP/hosts/fff/backup/weekly/20210307-066
ID 2763 gen 22633 top level 259 path AUTOBACKUP/hosts/fff/backup/monthly/20210307-066
ID 2765 gen 22638 top level 259 path AUTOBACKUP/hosts/uuu/backup/weekly/20210307-066
ID 2766 gen 22638 top level 259 path AUTOBACKUP/hosts/uuu/backup/monthly/20210307-066
ID 2767 gen 22630 top level 259 path AUTOBACKUP/hosts/zzz/backup/weekly/20210307-066
ID 2768 gen 22630 top level 259 path AUTOBACKUP/hosts/zzz/backup/monthly/20210307-066
ID 2772 gen 22639 top level 259 path AUTOBACKUP/hosts/aaa/backup/weekly/20210314-073
ID 2773 gen 22635 top level 259 path AUTOBACKUP/hosts/fff/backup/weekly/20210314-073
ID 2775 gen 22639 top level 259 path AUTOBACKUP/hosts/uuu/backup/weekly/20210314-073




Probably should be marked as duplicate of Bug #209153 - same issue for all kernels above kernel 5.8.2
Comment 1 Tomas Thiemel 2021-03-18 21:15:37 UTC
I recompiled kernel with additional debug options enabled.
Now only "rsync" processes got "frozen", I was able to terminate "beesd" process.

[ 1849.948199] Writes:  Total: 3842202977  Max/Min: 252639718/224667097   Fail: 0
[ 1911.388986] Writes:  Total: 3967429104  Max/Min: 261158600/232085522   Fail: 0
[ 1972.827311] Writes:  Total: 4097789115  Max/Min: 270021155/239960758   Fail: 0
[ 1996.755392] BUG: kernel NULL pointer dereference, address: 0000000000000018
[ 1996.764336] #PF: supervisor read access in kernel mode
[ 1996.771313] #PF: error_code(0x0000) - not-present page
[ 1996.778258] PGD 0 P4D 0
[ 1996.782580] Oops: 0000 [#1] SMP DEBUG_PAGEALLOC
[ 1996.789268] CPU: 4 PID: 19405 Comm: kworker/u16:27 Tainted: G       A          5.10.23-gentoo-xeon #2
[ 1996.800524] Hardware name: MSI MS-7759/Z77MA-G45 (MS-7759), BIOS V1.9 03/01/2013
[ 1996.809913] Workqueue: btrfs-delalloc btrfs_work_helper
[ 1996.816968] RIP: 0010:compress_file_range+0x56a/0x7e0
[ 1996.823972] Code: 00 0f 84 cb 00 00 00 31 db 31 c0 48 83 7c 24 48 00 74 6c 48 89 2c 24 eb 0d 83 c3 01 48 63 c3 48 3b 44 24 48 73 55 4d 8b 24 c7 <49> 83 7c 24 18 00 0f 85 3c 01 00 00 49 8b 44 24 08 48 8d 50 ff a8
[ 1996.846085] RSP: 0018:ffffc9000112fd48 EFLAGS: 00010206
[ 1996.853185] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[ 1996.862260] RDX: ffffffff844b5700 RSI: ffffffff815e10e8 RDI: ffffc9000112fd98
[ 1996.871355] RBP: ffff88862418e190 R08: ffff88828b055260 R09: ffff88828b055260
[ 1996.880435] R10: 0000000000000000 R11: ffffea0007ef6208 R12: 0000000000000000
[ 1996.889512] R13: 0000000000005000 R14: 0000000000007fff R15: ffff888224606ba0
[ 1996.898586] FS:  0000000000000000(0000) GS:ffff8887fa400000(0000) knlGS:0000000000000000
[ 1996.908616] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1996.916304] CR2: 0000000000000018 CR3: 0000000213491006 CR4: 00000000001706e0
[ 1996.925385] Call Trace:
[ 1996.929758]  ? submit_compressed_extents+0x440/0x440
[ 1996.936647]  async_cow_start+0x12/0x40
[ 1996.942331]  btrfs_work_helper+0xf4/0x640
[ 1996.948289]  process_one_work+0x27c/0x620
[ 1996.954284]  worker_thread+0x50/0x3a0
[ 1996.959870]  ? process_one_work+0x620/0x620
[ 1996.966003]  kthread+0x137/0x160
[ 1996.966006]  ? kthread_unuse_mm+0xa0/0xa0
[ 1996.966009]  ret_from_fork+0x1f/0x30
[ 1996.966012] Modules linked in: xt_state xt_nat tun xt_CHECKSUM xt_MASQUERADE xt_conntrack ipt_REJECT nf_reject_ipv4 xt_tcpudp ip6table_mangle ip6table_nat ip6table_filter ip6_tables iptable_mangle iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_filter ip_tables x_tables fuse nfsd auth_rpcgss oid_registry lockd grace sunrpc f2fs nls_iso8859_1 vfat fat dm_raid raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx binfmt_misc at24 regmap_i2c iTCO_wdt iTCO_vendor_support x86_pkg_temp_thermal pm80xx kvm_intel dummy kvm f71882fg coretemp xhci_pci ehci_pci crct10dif_pclmul ehci_hcd xhci_hcd crc32_pclmul crc32c_intel r8169 ghash_clmulni_intel aesni_intel crypto_simd cryptd realtek usbcore i2c_i801 glue_helper mei_me mdio_devres i2c_smbus libphy mei i2c_core lpc_ich mfd_core usb_common video fan thermal backlight evdev
[ 1997.067424] CR2: 0000000000000018
[ 1997.072905] ---[ end trace dda3e19fd119c566 ]---
[ 1997.079657] RIP: 0010:compress_file_range+0x56a/0x7e0
[ 1997.086873] Code: 00 0f 84 cb 00 00 00 31 db 31 c0 48 83 7c 24 48 00 74 6c 48 89 2c 24 eb 0d 83 c3 01 48 63 c3 48 3b 44 24 48 73 55 4d 8b 24 c7 <49> 83 7c 24 18 00 0f 85 3c 01 00 00 49 8b 44 24 08 48 8d 50 ff a8
[ 1997.109628] RSP: 0018:ffffc9000112fd48 EFLAGS: 00010206
[ 1997.116978] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[ 1997.126281] RDX: ffffffff844b5700 RSI: ffffffff815e10e8 RDI: ffffc9000112fd98
[ 1997.135601] RBP: ffff88862418e190 R08: ffff88828b055260 R09: ffff88828b055260
[ 1997.144901] R10: 0000000000000000 R11: ffffea0007ef6208 R12: 0000000000000000
[ 1997.154348] R13: 0000000000005000 R14: 0000000000007fff R15: ffff888224606ba0
[ 1997.163612] FS:  0000000000000000(0000) GS:ffff8887fa400000(0000) knlGS:0000000000000000
[ 1997.173825] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1997.182000] CR2: 0000000000000018 CR3: 0000000213491006 CR4: 00000000001706e0
[ 1997.191394] BUG: sleeping function called from invalid context at include/linux/percpu-rwsem.h:49
[ 1997.202439] in_atomic(): 0, irqs_disabled(): 1, non_block: 0, pid: 19405, name: kworker/u16:27
[ 1997.213238] INFO: lockdep is turned off.
[ 1997.219309] irq event stamp: 0
[ 1997.224492] hardirqs last  enabled at (0): [<0000000000000000>] 0x0
[ 1997.233076] hardirqs last disabled at (0): [<ffffffff8108bfb9>] copy_process+0x6b9/0x1bc0
[ 1997.243551] softirqs last  enabled at (0): [<ffffffff8108bfb9>] copy_process+0x6b9/0x1bc0
[ 1997.254195] softirqs last disabled at (0): [<0000000000000000>] 0x0
[ 1997.262484] CPU: 4 PID: 19405 Comm: kworker/u16:27 Tainted: G      DA          5.10.23-gentoo-xeon #2
[ 1997.273839] Hardware name: MSI MS-7759/Z77MA-G45 (MS-7759), BIOS V1.9 03/01/2013
[ 1997.283418] Workqueue: btrfs-delalloc btrfs_work_helper
[ 1997.290953] Call Trace:
[ 1997.295647]  dump_stack+0x77/0x97
[ 1997.301002]  ___might_sleep.cold+0xa6/0xf7
[ 1997.307245]  exit_signals+0x31/0x340
[ 1997.312837]  do_exit+0xd5/0xd80
[ 1997.318123]  ? process_one_work+0x620/0x620
[ 1997.324308]  ? kthread+0x137/0x160
[ 1997.329688]  rewind_stack_do_exit+0x17/0x30
[ 1997.335999] RIP: 0000:0x0
[ 1997.340591] Code: Unable to access opcode bytes at RIP 0xffffffffffffffd6.
[ 1997.349571] RSP: 0000:0000000000000000 EFLAGS: 00000000 ORIG_RAX: 0000000000000000
[ 1997.359269] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[ 1997.368522] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[ 1997.377317] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[ 1997.386550] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[ 1997.395777] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 2034.267977] Writes:  Total: 4225174685  Max/Min: 278649288/247500023   Fail: 0
[ 2095.707657] Writes:  Total: 4358162757  Max/Min: 288107501/255241090   Fail: 0
[ 2157.146350] Writes:  Total: 4488950387  Max/Min: 297439692/263035196   Fail: 0


ftp1 ~ # ps auxw|grep -E "D|bees"|grep -v -- "-D"|grep -v grep|grep -v tee|grep -v CRON|sed 's:-avH.*::'
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root      1049  0.9  0.0      0     0 ?        D    21:35   0:21 [kworker/u16:10+flush-btrfs-4]
root     22963  0.3  0.0 104744  9804 pts/3    D+   22:06   0:01 rsync
root     23885  0.0  0.0  55652  8116 pts/12   D+   22:06   0:00 rsync
root     24143  0.0  0.0  16856  2932 pts/7    D+   22:08   0:00 rsync
root     24200  0.0  0.0  74708  3960 pts/11   D+   22:09   0:00 rsync
Comment 2 Tomas Thiemel 2021-03-18 23:10:17 UTC
See attached log with "strace -f rsync" - rsync.strace.log.gz

[  682.608387] Writes:  Total: 1414336205  Max/Min: 94414206/82701511   Fail: 0
[  744.047039] Writes:  Total: 1540175798  Max/Min: 102202069/90216536   Fail: 0
[  768.862978] BUG: kernel NULL pointer dereference, address: 0000000000000018
[  768.871959] #PF: supervisor read access in kernel mode
[  768.879090] #PF: error_code(0x0000) - not-present page
[  768.886212] PGD 0 P4D 0
[  768.890722] Oops: 0000 [#1] SMP DEBUG_PAGEALLOC
[  768.896714] CPU: 6 PID: 13068 Comm: kworker/u16:7 Tainted: G       A          5.10.23-gentoo-xeon #3
[  768.907317] Hardware name: MSI MS-7759/Z77MA-G45 (MS-7759), BIOS V1.9 03/01/2013
[  768.916183] Workqueue: btrfs-delalloc btrfs_work_helper
[  768.922878] RIP: 0010:compress_file_range+0x6fd/0x7c0
[  768.929452] Code: e1 20 31 db 41 83 c9 0f e8 a0 1a 02 00 31 c0 48 83 7c 24 48 00 75 0f eb 5c 83 c3 01 48 63 c3 48 3b 44 24 48 73 4f 49 8b 2c c7 <48> 83 7d 18 00 75 59 48 8b 45 08 48 8d 50 ff a8 01 48 0f 45 ea 8b
[  768.951568] RSP: 0018:ffffc900021cfd48 EFLAGS: 00010202
[  768.958771] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000200669
[  768.967788] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff8252265e
[  768.976947] RBP: 0000000000000000 R08: 0000000000000020 R09: ffff88881b607000
[  768.985947] R10: 0000000000000000 R11: 0000000000000025 R12: 00000000000003e7
[  768.994936] R13: 0000000000000000 R14: 0000000000000fff R15: ffff888101f89f18
[  769.004069] FS:  0000000000000000(0000) GS:ffff8887fac00000(0000) knlGS:0000000000000000
[  769.014143] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  769.021742] CR2: 0000000000000018 CR3: 000000076023c001 CR4: 00000000001706e0
[  769.030864] Call Trace:
[  769.035143]  ? submit_compressed_extents+0x440/0x440
[  769.042079]  async_cow_start+0x12/0x40
[  769.047677]  btrfs_work_helper+0xf4/0x640
[  769.053675]  process_one_work+0x27c/0x620
[  769.059791]  worker_thread+0x50/0x3a0
[  769.065346]  ? process_one_work+0x620/0x620
[  769.071429]  kthread+0x137/0x160
[  769.076475]  ? kthread_unuse_mm+0xa0/0xa0
[  769.082398]  ret_from_fork+0x1f/0x30
[  769.087750] Modules linked in: xt_state xt_nat tun xt_CHECKSUM ebtable_filter ebtables xt_MASQUERADE xt_conntrack ipt_REJECT nf_reject_ipv4 xt_tcpudp ip6table_mangle ip6table_nat ip6table_filter ip6_tables iptable_mangle iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_filter ip_tables x_tables fuse nfsd auth_rpcgss oid_registry lockd grace sunrpc f2fs nls_iso8859_1 vfat fat dm_raid raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx binfmt_misc at24 regmap_i2c iTCO_wdt iTCO_vendor_support x86_pkg_temp_thermal kvm_intel pm80xx dummy kvm xhci_pci f71882fg xhci_hcd crct10dif_pclmul coretemp crc32_pclmul crc32c_intel ehci_pci ghash_clmulni_intel ehci_hcd r8169 aesni_intel mei_me i2c_i801 crypto_simd i2c_smbus cryptd i2c_core realtek usbcore glue_helper lpc_ich mdio_devres mfd_core mei libphy video usb_common backlight evdev thermal fan
[  769.174259] CR2: 0000000000000018
[  769.179609] ---[ end trace 2f90fe4fe855789c ]---
[  769.186399] RIP: 0010:compress_file_range+0x6fd/0x7c0
[  769.193480] Code: e1 20 31 db 41 83 c9 0f e8 a0 1a 02 00 31 c0 48 83 7c 24 48 00 75 0f eb 5c 83 c3 01 48 63 c3 48 3b 44 24 48 73 4f 49 8b 2c c7 <48> 83 7d 18 00 75 59 48 8b 45 08 48 8d 50 ff a8 01 48 0f 45 ea 8b
[  769.216042] RSP: 0018:ffffc900021cfd48 EFLAGS: 00010202
[  769.223371] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000200669
[  769.232608] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff8252265e
[  769.242022] RBP: 0000000000000000 R08: 0000000000000020 R09: ffff88881b607000
[  769.251314] R10: 0000000000000000 R11: 0000000000000025 R12: 00000000000003e7
[  769.260519] R13: 0000000000000000 R14: 0000000000000fff R15: ffff888101f89f18
[  769.270058] FS:  0000000000000000(0000) GS:ffff8887fac00000(0000) knlGS:0000000000000000
[  769.280443] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  769.288577] CR2: 0000000000000018 CR3: 000000076023c001 CR4: 00000000001706e0
[  769.298130] BUG: sleeping function called from invalid context at include/linux/percpu-rwsem.h:49
[  769.309407] in_atomic(): 0, irqs_disabled(): 1, non_block: 0, pid: 13068, name: kworker/u16:7
[  769.320348] INFO: lockdep is turned off.
[  769.326759] irq event stamp: 0
[  769.332219] hardirqs last  enabled at (0): [<0000000000000000>] 0x0
[  769.340893] hardirqs last disabled at (0): [<ffffffff8108bfb9>] copy_process+0x6b9/0x1bc0
[  769.351623] softirqs last  enabled at (0): [<ffffffff8108bfb9>] copy_process+0x6b9/0x1bc0
[  769.362216] softirqs last disabled at (0): [<0000000000000000>] 0x0
[  769.370851] CPU: 6 PID: 13068 Comm: kworker/u16:7 Tainted: G      DA          5.10.23-gentoo-xeon #3
[  769.382429] Hardware name: MSI MS-7759/Z77MA-G45 (MS-7759), BIOS V1.9 03/01/2013
[  769.392269] Workqueue: btrfs-delalloc btrfs_work_helper
[  769.399978] Call Trace:
[  769.404909]  dump_stack+0x77/0x97
[  769.410613]  ___might_sleep.cold+0xa6/0xf7
[  769.416760]  exit_signals+0x31/0x340
[  769.422389]  do_exit+0xd5/0xd80
[  769.427710]  ? process_one_work+0x620/0x620
[  769.433863]  ? kthread+0x137/0x160
[  769.439522]  rewind_stack_do_exit+0x17/0x30
[  769.445667] RIP: 0000:0x0
[  769.450384] Code: Unable to access opcode bytes at RIP 0xffffffffffffffd6.
[  769.459233] RSP: 0000:0000000000000000 EFLAGS: 00000000 ORIG_RAX: 0000000000000000
[  769.468801] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[  769.478086] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[  769.487360] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[  769.496477] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[  769.505732] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[  805.486724] Writes:  Total: 1669878746  Max/Min: 110429415/97813827   Fail: 0
[  866.984707] Writes:  Total: 1800906730  Max/Min: 119167108/105612344   Fail: 0



### Here is output of "beesd" dedup tool after it froze: ###
2021-03-18 23:47:03 9291.9293<6> crawl_2740: scan: 12K 0xc0000 [Ddd] 0xc3000 BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210221-052/windows/ProgramData/Microsoft/Network/Downloader/edb0005B.log
2021-03-18 23:47:04 9291.9293<6> crawl_2747: dedup: src 16K [0xe90a000..0xe90e000] {0x181fe2bb000z1f000} BACKUP/AUTOBACKUP/hosts/ccc/backup/monthly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:04 9291.9293<6> crawl_2747:        dst 16K [0x4c3bc000..0x4c3c0000] {0x18b24139000} BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210228-059/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:04 9291.9293<6> crawl_2747: dedup: src 48K [0x3f21b000..0x3f227000] {0x1201ee0e000z5000} BACKUP/AUTOBACKUP/hosts/ccc/backup/monthly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:04 9291.9293<6> crawl_2747:        dst 48K [0x4c3c0000..0x4c3cc000] {0x18b2413d000} BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210228-059/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:04 9291.9293<6> crawl_2747: scan: 64K 0x4c3bc000 [DdddDddddddddddd] 0x4c3cc000 BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210228-059/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:04 9291.9293<6> crawl_2760: dedup: src 60K [0x398c5000..0x398d4000] {0x1897e3a6000z1000} BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210221-052/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/[Gmail].sbd/V&AWE-echny zpr&AOE-vy
2021-03-18 23:47:04 9291.9293<6> crawl_2760:        dst 60K [0x4af7c000..0x4af8b000] {0x18e07339000} BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:04 9291.9293<6> crawl_2760: dedup: src 84K [0x53a93000..0x53aa8000] {0x18b2b6e7000} BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210228-059/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:04 9291.9293<6> crawl_2760:        dst 84K [0x4af8b000..0x4afa0000] {0x18e07348000} BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:04 9291.9293<6> crawl_2760: copy: 240K [0x4af40000..0x4af7c000] fd = 2792 'BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX'
2021-03-18 23:47:04 9291.9293<6> crawl_2760: dedup: src 240K [0x566000..0x5a2000] {HOLE} #272 (deleted)
2021-03-18 23:47:04 9291.9293<6> crawl_2760:        dst 240K [0x4af40000..0x4af7c000] {0x18e072fd000} BACKUP/AUTOBACKUP/hosts/ccc/backup/monthly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:05 9291.9294<6> crawl_2760: dedup: src 80K [0x4af87000..0x4af9b000] {0x18b2b6e3000} BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:05 9291.9294<6> crawl_2760:        dst 80K [0x4b26c000..0x4b280000] {0x18e073d9000zc000} BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:05 9291.9294<6> crawl_2760: copy: 48K [0x4b260000..0x4b26c000] fd = 2792 'BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX'
2021-03-18 23:47:05 9291.9294<6> crawl_2760: dedup: src 48K [0x2b7000..0x2c3000] {HOLE} #269 (deleted)
2021-03-18 23:47:05 9291.9294<6> crawl_2760:        dst 48K [0x4b260000..0x4b26c000] {0x18e073d9000z0} BACKUP/AUTOBACKUP/hosts/ccc/backup/monthly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:05 9291.9292<6> crawl_2760: dedup: src 20K [0x4af9b000..0x4afa0000] {0x18b2b6f7000} BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:05 9291.9292<6> crawl_2760:        dst 20K [0x4b280000..0x4b285000] {0x18e073db000z0} BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:05 9291.9292<6> crawl_2760: dedup: src 8K [0x53aa8000..0x53aaa000] {0x18b2b6fc000} BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210228-059/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:05 9291.9292<6> crawl_2760:        dst 8K [0x4b285000..0x4b287000] {0x18e073db000z5000} BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:05 9291.9292<6> crawl_2760: dedup: src 28K [0x4af7c000..0x4af83000] {0x1897e3a6000z1000} BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:05 9291.9292<6> crawl_2760:        dst 28K [0x4b288000..0x4b28f000] {0x18e073db000z8000} BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
2021-03-18 23:47:05 9291.9292<6> crawl_2760: copy: 4K [0x4b287000..0x4b288000] fd = 2792 'BACKUP/AUTOBACKUP/hosts/ccc/backup/weekly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX'
2021-03-18 23:47:05 9291.9292<6> crawl_2760: dedup: src 4K [0x1000..0x2000] {HOLE} #273 (deleted)
2021-03-18 23:47:05 9291.9292<6> crawl_2760:        dst 4K [0x4b287000..0x4b288000] {0x18e073db000z7000} BACKUP/AUTOBACKUP/hosts/ccc/backup/monthly/20210307-066/windows/Users/rrr/AppData/Roaming/Thunderbird/Profiles/bbbggg.default/ImapMail/imap.xyz.com/INBOX
^C^C^C^C
Comment 3 Tomas Thiemel 2021-03-18 23:11:18 UTC
Created attachment 295943 [details]
output of "strace -f rsync" before the kernel bug

output of "strace -f rsync" before the kernel bug
Comment 4 Su Yue 2021-03-23 04:20:38 UTC
Could you try this patch?

https://www.spinics.net/lists/linux-btrfs/msg103808.html
Comment 5 Tomas Thiemel 2021-03-23 11:03:22 UTC
(In reply to Su Yue from comment #4)
> Could you try this patch?
> 
> https://www.spinics.net/lists/linux-btrfs/msg103808.html

Thank you 😍! Initial "crash test" (parallel rsync) completed smoothly without any error/problem. 

PS: Your patch may also fix the bug #209153 (all kernels after 5.8.2 have similar problem).
Comment 6 Su Yue 2021-03-24 04:47:06 UTC
According to records of bug #209153, I personally think the another trace seems not related to the fix. I'm not author of the patch though.
The trace of bug #209153 is different and martin@urbackup.org reported it could happened with ext4.
Comment 7 David Sterba 2021-03-26 22:13:55 UTC
> https://www.spinics.net/lists/linux-btrfs/msg103808.html

I'll have a look why this patch is not merged, there's some sort of fallback when ther's no compression although it's in the compression path, but it's missing the reset of out_pages, the return code is not enough.
Comment 8 David Sterba 2021-04-19 19:57:22 UTC
Patch pushed to devel queue and will appear on 5.10+ stables once it's merged.