Constant BTRFS warning regarding excessive times.

[relink2013]

Operating system

Unraid 7.0.0-rc2

Description

Sorry in advance if there are any formatting issues, I’m on my phone right now.

I have my vDSM setup with a 1TB vDisk on a NVMe ZFS mirror, this is for all the appdata and databases for DSM.

Then all my storage is on a 30TB ZFS pool of 6 mirrors.

No matter what I do I will constantly get these errors and I’m not sure what’s causing them. I can hammer my ZFS pool for hours on end outside of vDSM and have no issues at all. The hosts storage can saturate a 10Gb/s network connection.

[10131.584866] prepare phase: time: 0, refs[before/process/after]:[449/225/0][10131.584866] wait prev trans completed: time: 0
[10131.584866] pre-run delayed item phase: time: 0, inodes/items:[46/74]
[10131.584866] wait join end trans: time: 0
[10131.584866] run data refs for usrquota: time: 0, refs:[0]
[10131.584866] create snpashot: time: 0, inodes/items:[0/0], refs:[0]
[10131.584866] delayed item phase: time: 0, inodes/items:[0/0]
[10131.584866] delayed refs phase: time: 0, refs:[0]
[10131.584866] commit roots phase: time: 0
[10131.584866] writeback phase: time: 152323
[10486.282158] BTRFS warning (device sdb1): commit trans:
[10486.282158] total_time: 253132, meta-read[miss/total]:[1465/836776], meta-write[count/size]:[11/5936 K]

On the ZFS datasets I have tried:

• disabling atime and xattr to reduce
• Different compressions and disabling compression.
• matched the block size of 4k between BTRFS and ZFS.
• Increased ZFS ARC to 32GB
• vDSM has 8 cores, 4 of them are dedicated to vDSM, and 16GB of RAM is dedicated.
• Tried changing ARC between “all” and “metadata”
• Tried toggling between synchronous only writes.
• Tried with only a single vDisk.
• Tried RAW & qcow2

Im currently copying data from my DS918+ with only has 1GbE and when the transfer first starts it saturates that 1Gb connection (between 110-115MB/s), but after a while it begins throwing these errors and the transfer begins to fluctuate between 0-70MB/s. Once this happens DSM becomes slow as dirt but not totally unresponsive.

Docker compose

usr/local/emhttp/plugins/dynamix.docker.manager/scripts/docker create --name='virtual-dsm' --net='br0' --ip='172.17.89.12' --cpuset-cpus='0,1,2,3,4,5,6,7,8,9,10,11' --pids-limit 4096 -e TZ="America/New_York" -e HOST_OS="Unraid" -e HOST_HOSTNAME="SERVER" -e HOST_CONTAINERNAME="virtual-dsm" -e 'TCP_PORT_5000'='5000' -e 'TCP_PORT_5001'='5001' -e 'DISK_SIZE'='1000G' -e 'RAM_SIZE'='16G' -e 'CPU_CORES'='8' -e 'DHCP'='Y' -e 'DISK_FMT'='qcow2' -e 'TCP_PORT_6522'='6522' -e 'MAC'='REDACTED' -e 'GUEST_SERIAL'='REDACTED' -e 'HOST_SERIAL'='REDACTED' -e 'HOST_MAC'='REDACTED' -e 'HOST_MODEL'='DS918+' -e 'ALLOCATE'='N' -e 'DISK2_SIZE'='30000G' -l net.unraid.docker.managed=dockerman -l net.unraid.docker.webui='http://[IP]:[PORT:5000]' -l net.unraid.docker.icon='/mnt/user/Docker_Icons/V-DSM2.png' -v '/mnt/user/vDSM-Appdata/':'/storage':'rw' -v '/mnt/user/vDSM-Storage/':'/storage2':'rw' --device='/dev/kvm' --device='/dev/vhost-net' --stop-timeout 60 --cap-add NET_ADMIN --device-cgroup-rule='c *:* rwm' 'vdsm/virtual-dsm:latest' 

Docker log

                                                                              ❯ -----------------------------------------------------------                   ❯  You can now login to DSM at http://172.17.89.211:5000                        ❯ -----------------------------------------------------------                                                                                                   [   32.417905] fuse init (API version 7.23)                                     [  376.479393] BTRFS info (device sdc1): setting 16 feature flag                [  460.918763] BTRFS info (device sdb1): setting 16 feature flag                [  584.374808] Synotify use 16384 event queue size                              [  589.307563] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)                                                                         [  713.985410] Synotify use 16384 event queue size                              [  713.986038] Synotify use 16384 event queue size                              [  715.367068] Synotify use 16384 event queue size                              [  715.368703] Synotify use 16384 event queue size                              [  716.249030] Synotify use 16384 event queue size                              
[  716.431184] Synotify use 16384 event queue size                              
[ 1110.020404] Synotify use 16384 event queue size                              
[ 2895.295311] BTRFS warning (device sdb1): commit trans:
[ 2895.295311] total_time: 245429, meta-read[miss/total]:[1492/863202], meta-write[count/size]:[15/6336 K][ 2895.295311] prepare phase: time: 4548, refs[before/process/after]:[868/515/74][ 2895.295311] wait prev trans completed: time: 0[ 2895.295311] pre-run delayed item phase: time: 0, inodes/items:[48/78][ 2895.295311] wait join end trans: time: 0[ 2895.295311] run data refs for usrquota: time: 0, refs:[0][ 2895.295311] create snpashot: time: 0, inodes/items:[0/0], refs:[0][ 2895.295311] delayed item phase: time: 0, inodes/items:[1/1][ 2895.295311] delayed refs phase: time: 0, refs:[0][ 2895.295311] commit roots phase: time: 0[ 2895.295311] writeback phase: time: 245427[ 3387.604881] BTRFS warning (device sdb1): commit trans:[ 3387.604881] total_time: 146861, meta-read[miss/total]:[861/477147], meta-write[count/size]:[23/6960 K][ 3387.604881] prepare phase: time: 0, refs[before/process/after]:[8/6/0][ 3387.604881] wait prev trans completed: time: 0[ 3387.604881] pre-run delayed item phase: time: 0, inodes/items:[14/17][ 3387.604881] wait join end trans: time: 0[ 3387.604881] run data refs for usrquota: time: 0, refs:[0][ 3387.604881] create snpashot: time: 0, inodes/items:[0/0], refs:[0][ 3387.604881] delayed item phase: time: 0, inodes/items:[0/0][ 3387.604881] delayed refs phase: time: 0, refs:[6][ 3387.604881] commit roots phase: time: 0[ 3387.604881] writeback phase: time: 146861[ 3625.067150] BTRFS warning (device sdb1): commit trans:[ 3625.067150] total_time: 118277, meta-read[miss/total]:[717/387170], meta-write[count/size]:[32/9504 K]

Screenshots (optional)

No response

[relink2013]

UPDATE:

Eventually this always ends up starting to happen too.

[13565.264685] BTRFS warning (device sdb1): commit trans: [13565.264685] total_time: 130682, meta-read[miss/total]:[109/11893], meta-write[count/size]:[82/51616 K] [13565.264685] prepare phase: time: 1, refs[before/process/after]:[0/0/0] [13565.264685] wait prev trans completed: time: 0 [13565.264685] pre-run delayed item phase: time: 0, inodes/items:[9/13] [13565.264685] wait join end trans: time: 0 [13565.264685] run data refs for usrquota: time: 0, refs:[0] [13565.264685] create snpashot: time: 0, inodes/items:[0/0], refs:[0] [13565.264685] delayed item phase: time: 0, inodes/items:[0/0] [13565.264685] delayed refs phase: time: 0, refs:[2] [13565.264685] commit roots phase: time: 0 [13565.264685] writeback phase: time: 130682 [13565.391678] BTRFS info (device sdb1): using free space tree [13565.392685] BTRFS info (device sdb1): using free block group cache tree [13567.925216] Synotify use 16384 event queue size [13567.925938] Synotify use 16384 event queue size [13585.965072] BTRFS info (device sdc1): using free space tree [13585.965802] BTRFS info (device sdc1): using free block group cache tree [13801.926669] INFO: task SYNO.Storage.CG:1993 blocked for more than 120 seconds. [13801.927914] Tainted: P O 4.4.302+ #72806 [13801.928844] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [13801.930125] SYNO.Storage.CG D ffff8801537bba10 0 1993 1 0x00000000 [13801.931304] ffff8801537bba10 ffff8801537b8000 ffff88046da00180 ffff8803e78383c0 [13801.932623] ffff8801537bc000 ffff8800662de498 ffff8801537bbb00 ffff88043730ede0 [13801.933846] ffff8800662de440 ffff8801537bba28 ffffffff81547bb0 ffff8800662de418 [13801.934998] Call Trace: [13801.935329] [<ffffffff81547bb0>] schedule+0x30/0x80 [13801.935936] [<ffffffffa0b2484e>] wait_for_commit.constprop.0+0x2e/0x60 [btrfs] [13801.936883] [<ffffffff8108ff40>] ? prepare_to_wait_event+0xf0/0xf0 [13801.937635] [<ffffffffa0b2737a>] btrfs_commit_transaction+0x25a/0xf00 [btrfs] [13801.938465] [<ffffffff81094881>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x20 [13801.939424] [<ffffffffa0bd6b9e>] btrfs_syno_usage_enable+0x2ae/0x3c0 [btrfs] [13801.940264] [<ffffffffa0b6b241>] btrfs_ioctl_syno_usage_ctl+0x441/0x910 [btrfs] [13801.941122] [<ffffffff811a600f>] ? mntput+0x1f/0x30 [13801.941749] [<ffffffff8118cae3>] ? terminate_walk+0xb3/0xd0 [13801.942474] [<ffffffffa0b72c33>] btrfs_ioctl+0xc53/0x3400 [btrfs] [13801.943249] [<ffffffff81195628>] ? do_filp_open+0x78/0xf0 [13801.943941] [<ffffffff8119ccb2>] ? dput.part.0+0x92/0x200 [13801.944624] [<ffffffff811bb7f3>] ? do_statfs_native+0x93/0xa0 [13801.945324] [<ffffffff81094881>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x20 [13801.946557] [<ffffffff8119801c>] do_vfs_ioctl+0x93c/0xae0 [13801.947435] [<ffffffff81193ae5>] ? putname+0x45/0x50 [13801.948244] [<ffffffff81198257>] SyS_ioctl+0x97/0xc0 [13801.949043] [<ffffffff8154ac21>] entry_SYSCALL_64_fastpath+0x1e/0x9a