On Fri, Dec 24, 2021 at 11:40:56AM +0000, Libor Klepáč wrote:

Hi, i think, we hit it on 5.10.x

Over the last week I've hit it every ~400 machine-hours on 5.10.80+
as well.  Compare to once every ~3 machine-hours for kernels after
5.11-rc1.

It does get worse when there is more contention for various locks,
so more bees threads or a different distribution of work between the
threads will reproduce it faster.

Not sure what version is it
Linux nakivo 5.10.0-051000-generic #202012132330 SMP Sun Dec 13
23:33:36 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

It is taken from
https://kernel.ubuntu.com/~kernel-ppa/mainline/v5.10/

Maybe i should go for specific version like
https://kernel.ubuntu.com/~kernel-ppa/mainline/v5.10.88/

It was running fine for few days with bees doing it's job.
One thing i changed yesterday was changing
--loadavg-target 5
to
--loadavg-target 6
(VM has 6 virtual CPUs)

Here is trace from machine
https://download.bcom.cz/btrfs/trace6.txt

Thanks,
Libor

On St, 2021-12-08 at 23:44 -0500, Zygo Blaxell wrote:

quoted

On Fri, Nov 26, 2021 at 02:36:30PM +0000, Libor Klepáč wrote:

quoted

Hi,
we are trying to use btrfs with compression and deduplication using
bees to host filesystem for nakivo repository.
Nakivo repository is in "incremental with full backups" format -
ie.
one file per VM snapshot transferred from vmware, full backup every
x
days, no internal deduplication. 
We have also disabled internal compression in nakivo repository and
put
compression-force=zstd:13 on filesystem.

It's a VM on vmware 6.7.0 Update 3 (Build 17700523) on Dell R540.
It has 6vCPU, 16GB of ram.

Bees is run with this parameters
OPTIONS="--strip-paths --no-timestamps --verbose 5 --loadavg-target
5 
--thread-min 1"
DB_SIZE=$((8*1024*1024*1024)) # 8G in bytes



Until today it was running ubuntu provided kernel 5.11.0-
40.44~20.04.2
(not sure about exact upstream version),
today we switched to 5.13.0-21.21~20.04.1 after first crash.

It was working ok for 7+days, all data were in (around 10TB), so i
started bees. 
It now locks the FS, bees runs on 100% CPU, i cannot enter
directory
with btrfs

# btrfs filesystem usage /mnt/btrfs/repo02/
Overall:
    Device size:                  20.00TiB
    Device allocated:             10.88TiB
    Device unallocated:            9.12TiB
    Device missing:                  0.00B
    Used:                         10.87TiB
    Free (estimated):              9.13TiB      (min: 4.57TiB)
    Data ratio:                       1.00
    Metadata ratio:                   1.00
    Global reserve:              512.00MiB      (used: 0.00B)

Data,single: Size:10.85TiB, Used:10.83TiB (99.91%)
   /dev/sdd       10.85TiB

Metadata,single: Size:35.00GiB, Used:34.71GiB (99.17%)
   /dev/sdd       35.00GiB

System,DUP: Size:32.00MiB, Used:1.14MiB (3.56%)
   /dev/sdd       64.00MiB

Unallocated:
   /dev/sdd        9.12TiB

This happened yesterday on kernel 5.11
https://download.bcom.cz/btrfs/trace1.txt

This is today, on 5.13
https://download.bcom.cz/btrfs/trace2.txt

this is trace from sysrq later, when i noticed it happened again
https://download.bcom.cz/btrfs/trace3.txt


Any clue what can be done?

I am currently hitting this bug on all kernel versions starting from
5.11.
Test runs end with the filesystem locked up, 100% CPU usage in bees
and the following lockdep dump:

        [Wed Dec  8 14:14:03 2021] Linux version 5.11.22-zb64-
e4d48558d24c+ (zblaxell@waya) (gcc (Debian 10.2.1-6) 10.2.1 20210110,
GNU ld (GNU Binutils for Debian) 2.37) #1 SMP Sun Dec 5 04:18:31 EST
2021

        [Wed Dec  8 23:17:32 2021] sysrq: Show Locks Held
        [Wed Dec  8 23:17:32 2021] 
                                   Showing all locks held in the
system:
        [Wed Dec  8 23:17:32 2021] 1 lock held by in:imklog/3603:
        [Wed Dec  8 23:17:32 2021] 1 lock held by dmesg/3720:
        [Wed Dec  8 23:17:32 2021]  #0: ffff8a1406ac80e0 (&user-

quoted

lock){+.+.}-{3:3}, at: devkmsg_read+0x4d/0x320

        [Wed Dec  8 23:17:32 2021] 3 locks held by bash/3721:
        [Wed Dec  8 23:17:32 2021]  #0: ffff8a142a589498
(sb_writers#4){.+.+}-{0:0}, at: ksys_write+0x70/0xf0
        [Wed Dec  8 23:17:32 2021]  #1: ffffffff98f199a0
(rcu_read_lock){....}-{1:2}, at: __handle_sysrq+0x5/0xa0
        [Wed Dec  8 23:17:32 2021]  #2: ffffffff98f199a0
(rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x23/0x187
        [Wed Dec  8 23:17:32 2021] 1 lock held by btrfs-
transacti/6161:
        [Wed Dec  8 23:17:32 2021]  #0: ffff8a14e0178850 (&fs_info-

quoted

transaction_kthread_mutex){+.+.}-{3:3}, at:

transaction_kthread+0x5a/0x1b0
        [Wed Dec  8 23:17:32 2021] 3 locks held by
crawl_257_265/6491:
        [Wed Dec  8 23:17:32 2021] 3 locks held by
crawl_257_291/6494:
        [Wed Dec  8 23:17:32 2021]  #0: ffff8a14bd092498
(sb_writers#12){.+.+}-{0:0}, at: vfs_dedupe_file_range_one+0x3b/0x180
        [Wed Dec  8 23:17:32 2021]  #1: ffff8a1410d7c848 (&sb-

quoted

s_type->i_mutex_key#17){+.+.}-{3:3}, at:

lock_two_nondirectories+0x6b/0x70
        [Wed Dec  8 23:17:32 2021]  #2: ffff8a14161a39c8 (&sb-

quoted

s_type->i_mutex_key#17/4){+.+.}-{3:3}, at:

lock_two_nondirectories+0x59/0x70
        [Wed Dec  8 23:17:32 2021] 4 locks held by
crawl_257_292/6502:
        [Wed Dec  8 23:17:32 2021]  #0: ffff8a14bd092498
(sb_writers#12){.+.+}-{0:0}, at: vfs_dedupe_file_range_one+0x3b/0x180
        [Wed Dec  8 23:17:32 2021]  #1: ffff8a131637a908 (&sb-

quoted

s_type->i_mutex_key#17){+.+.}-{3:3}, at:

lock_two_nondirectories+0x6b/0x70
        [Wed Dec  8 23:17:32 2021]  #2: ffff8a14161a39c8 (&sb-

quoted

s_type->i_mutex_key#17/4){+.+.}-{3:3}, at:

lock_two_nondirectories+0x59/0x70
        [Wed Dec  8 23:17:32 2021]  #3: ffff8a14bd0926b8
(sb_internal#2){.+.+}-{0:0}, at: btrfs_start_transaction+0x1e/0x20
        [Wed Dec  8 23:17:32 2021] 2 locks held by
crawl_257_293/6503:
        [Wed Dec  8 23:17:32 2021]  #0: ffff8a14bd092498
(sb_writers#12){.+.+}-{0:0}, at: vfs_dedupe_file_range_one+0x3b/0x180
        [Wed Dec  8 23:17:32 2021]  #1: ffff8a14161a39c8 (&sb-

quoted

s_type->i_mutex_key#17){+.+.}-{3:3}, at:

btrfs_remap_file_range+0x2eb/0x3c0
        [Wed Dec  8 23:17:32 2021] 3 locks held by
crawl_256_289/6504:
        [Wed Dec  8 23:17:32 2021]  #0: ffff8a14bd092498
(sb_writers#12){.+.+}-{0:0}, at: vfs_dedupe_file_range_one+0x3b/0x180
        [Wed Dec  8 23:17:32 2021]  #1: ffff8a140f2c4748 (&sb-

quoted

s_type->i_mutex_key#17){+.+.}-{3:3}, at:

lock_two_nondirectories+0x6b/0x70
        [Wed Dec  8 23:17:32 2021]  #2: ffff8a14161a39c8 (&sb-

quoted

s_type->i_mutex_key#17/4){+.+.}-{3:3}, at:

lock_two_nondirectories+0x59/0x70

        [Wed Dec  8 23:17:32 2021]
=============================================

There's only one commit touching vfs_dedupe_file_range_one
between v5.10 and v5.15 (3078d85c9a10 "vfs: verify source area in
vfs_dedupe_file_range_one()"), so I'm now testing 5.11 with that
commit
reverted to see if it introduced a regression.

quoted

We would really like to use btrfs for this use case, because
nakivo,
with this type of repository format, needs to be se to do full
backup
every x days and does not do deduplication on its own.


With regards,
Libor