mounting btrfs FS on zfs zvol hangs

[behlendorf]

yes, you'll probably think that is crazy, but after observing better performance with btrfs in some work loads on md RAID5 than btrfs builtin RAID10, I thought I'd try btrfs on zfs (in-kernel, not fuse) zvol (on raidz) just for a laugh.

While this procedure worked for ext4 and xfs, for btrfs, the mount hangs suggesting there might be something wrong with btrfs and/or zfs.

Here's what I'm doing:

zpool create X raidz /dev/sd{a,b,c,d,e,f}
zfs create -V 6T -o refreservation=0 X/Y
mkfs.btrfs /dev/zvol/X/Y
mount /dev/zvol/X/Y /mnt

backtrace for mount:

mount           D 0000000000000009     0  2193   1761 0x00000000
 ffff880401b4d9a8 0000000000000082 0000000000000001 0000000000000000
 ffff880401b4dfd8 ffff880401b4dfd8 ffff880401b4dfd8 0000000000012a40
 ffff8802092f0000 ffff88040ef7dc80 ffff880401b4d988 ffff88041fa732c0
Call Trace:
 [] ? __lock_page+0x70/0x70
 [] schedule+0x3f/0x60
 [] io_schedule+0x8f/0xd0
 [] sleep_on_page+0xe/0x20
 [] __wait_on_bit+0x5f/0x90
 [] wait_on_page_bit+0x78/0x80
 [] ? autoremove_wake_function+0x40/0x40
 [] read_extent_buffer_pages+0x3ca/0x430 [btrfs]
 [] ? btrfs_destroy_pinned_extent+0xb0/0xb0 [btrfs]
 [] btree_read_extent_buffer_pages.isra.62+0x8a/0xc0 [btrfs]
 [] read_tree_block+0x41/0x60 [btrfs]
 [] open_ctree+0xe75/0x1760 [btrfs]
 [] ? snprintf+0x34/0x40
 [] btrfs_fill_super.isra.38+0x78/0x150 [btrfs]
 [] ? disk_name+0xba/0xc0
 [] ? strlcpy+0x47/0x60
 [] btrfs_mount+0x3c6/0x470 [btrfs]
 [] mount_fs+0x43/0x1b0
 [] vfs_kern_mount+0x6a/0xc0
 [] do_kern_mount+0x54/0x110
 [] do_mount+0x1a4/0x260
 [] sys_mount+0x90/0xe0
 [] system_call_fastpath+0x16/0x1b

3.0.0-13-generic #22-Ubuntu SMP Wed Nov 2 13:27:26 UTC 2011
x86_64

Best regards,
Stephane

[ryao]

I tried this too and I encountered a hang. I tested this against 34037af.

However, I do not recall seeing a backtrace at the time.

[ryao]

Pull request #669 appears to have helped.

Doing mount /dev/zvol/rpool/btrfs /mnt/gentoo hangs on my desktop running Linux 3.3.2. It has the following output in dmesg:

[ 568.978048] Btrfs loaded
[ 568.982061] device fsid 7fb60b7a-3825-477c-8cbd-46ea997f75db devid 1 transid 7 /dev/zd32
[ 568.985777] btrfs bad tree block start 20971520 20975616
[ 568.985786] btrfs end < start 20975615 20975616
[ 568.985788] ------------[ cut here ]------------
[ 568.985807] WARNING: at fs/btrfs/extent_io.c:331 insert_state+0x9b/0xd0 btrfs
[ 568.985810] Hardware name: P5K Deluxe
[ 568.985812] Modules linked in: btrfs crc32c libcrc32c bridge ipv6 stp llc snd_hda_codec_analog arc4 rtl8187 mac80211 nvidia(PO) cfg80211 snd_hda_intel snd_hda_codec firewire_ohci eeprom_93cx6 r8169 firewire_core snd_pcm sky2 rtc_cmos mii floppy crc_itu_t asus_atk0110 snd_timer hwmon i2c_i801 iTCO_wdt agpgart evdev snd processor i2c_core soundcore snd_page_alloc unix sha256_generic fuse zfs(PO) zunicode(PO) zavl(PO) zcommon(PO) znvpair(PO) spl(O) xfs nfs nfs_acl auth_rpcgss lockd sunrpc reiserfs zlib_deflate ext4 jbd2 mbcache scsi_wait_scan hid_monterey hid_microsoft hid_logitech hid_ezkey hid_cypress hid_chicony hid_cherry hid_belkin hid_apple hid_a4tech usbhid uhci_hcd usb_storage ehci_hcd usbcore usb_common sr_mod cdrom sg pata_jmicron
[ 568.985890] Pid: 7184, comm: btrfs-endio-met Tainted: P O 3.3.2 #20
[ 568.985893] Call Trace:
[ 568.985901] [] warn_slowpath_common+0x7a/0xb0
[ 568.985905] [] warn_slowpath_null+0x15/0x20
[ 568.985918] [] insert_state+0x9b/0xd0 [btrfs]
[ 568.985932] [] set_extent_bit+0x384/0x4a0 [btrfs]
[ 568.985950] [] set_extent_bits+0x20/0x30 [btrfs]
[ 568.985960] [] end_bio_extent_readpage+0x2aa/0x880 [btrfs]
[ 568.985964] [] bio_endio+0x18/0x30
[ 568.985971] [] end_workqueue_fn+0x53/0x130 [btrfs]
[ 568.985980] [] worker_loop+0x16c/0x5b0 [btrfs]
[ 568.985993] [] ? btrfs_queue_worker+0x300/0x300 [btrfs]
[ 568.986003] [] kthread+0x8e/0xa0
[ 568.986024] [] kernel_thread_helper+0x4/0x10
[ 568.986027] [] ? __init_kthread_worker+0x40/0x40
[ 568.986029] [] ? gs_change+0x13/0x13
[ 568.986031] ---[ end trace 1c3ab15e3317e7ab ]---
[ 572.137056] INFO: task mount:7165 blocked for more than 3 seconds.
[ 572.137059] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 572.137061] mount D ffffffff814051e0 0 7165 6824 0x00000000
[ 572.137065] ffff8802205dd998 0000000000000086 0000000000000000 ffffea000570a580
[ 572.137070] ffff880201fdd100 ffff8802205ddfd8 ffff8802205ddfd8 ffff8802205ddfd8
[ 572.137073] ffffffff8160d020 ffff880201fdd100 0000000000000286 ffff88022fc11738
[ 572.137077] Call Trace:
[ 572.137085] [] ? __lock_page+0x70/0x70
[ 572.137089] [] schedule+0x3a/0x50
[ 572.137091] [] io_schedule+0x8a/0xd0
[ 572.137094] [] sleep_on_page+0x9/0x10
[ 572.137096] [] __wait_on_bit+0x57/0x80
[ 572.137099] [] wait_on_page_bit+0x70/0x80
[ 572.137102] [] ? autoremove_wake_function+0x40/0x40
[ 572.137117] [] read_extent_buffer_pages+0x4dd/0x540 [btrfs]
[ 572.137120] [] ? get_parent_ip+0x11/0x50
[ 572.137128] [] ? verify_parent_transid+0x160/0x160 [btrfs]
[ 572.137136] [] btree_read_extent_buffer_pages.isra.103+0x8a/0xc0 [btrfs]
[ 572.137145] [] read_tree_block+0x3c/0x60 [btrfs]
[ 572.137153] [] open_ctree+0x10ac/0x1a20 [btrfs]
[ 572.137158] [] ? ida_get_new_above+0x237/0x300
[ 572.137164] [] btrfs_mount+0x569/0x670 [btrfs]
[ 572.137168] [] ? pcpu_alloc+0x8ab/0x9b0
[ 572.137171] [] mount_fs+0x1b/0xd0
[ 572.137174] [] vfs_kern_mount+0x6d/0x110
[ 572.137177] [] do_kern_mount+0x4f/0x100
[ 572.137180] [] do_mount+0x54a/0x850
[ 572.137182] [] ? memdup_user+0x54/0xa0
[ 572.137184] [] ? strndup_user+0x53/0x70
[ 572.137187] [] sys_mount+0x8b/0xe0
[ 572.137190] [] system_call_fastpath+0x16/0x1b

Interestingly, none of this involves ZFS code.

[ryao]

I contacted Chris Mason at Oracle on IRC. According to him, ZFS is returning the wrong blocks. The header used by metadata blocks stores their block number, and if it does not match, btrfs will return messages such as "btrfs bad tree block start 20971520 20975616". These block positions are in byte offsets from the start of the filesystem. Chris Mason suggested that we might have an off by 1 error in our code, because the two numbers are 4096 bytes apart.

[behlendorf]

That would be surprising since I've heard of no other similar issues with the zvols. Still this is clearly something which should be explained. Since we have a simple test case it should be possible to verify exactly what written and what was read back.

[ryao]

I made a 1GB file, formatted it btrfs, created a loop device for it and then mounted btrfs. This worked. I then umounted it, created a 1GB zvol, used dd to transfer the contents of the file to a zvol and tried mounting btrfs, which failed with the same issue as earlier.

I took a brief look at the contents of the zvol, but I have not spent enough time on this to make sense of what I saw.

[ryao]

This is what happens when trying to mount btrfs on Linux 3.4.1:

[ 1121.022988] Btrfs loaded
[ 1121.026525] device fsid 431844fe-1439-43cf-a8ec-31e7cb362939 devid 1 transid 7 /dev/zd32
[ 1148.933062] INFO: task mount:9378 blocked for more than 15 seconds.
[ 1148.933065] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1148.933068] mount D 0000000000000000 0 9378 9062 0x00000000
[ 1148.933073] ffff880213813978 0000000000000082 ffff880213813978 ffffffff811cd855
[ 1148.933079] ffff88015ce92fb0 ffff880213813fd8 ffff880213813fd8 ffff880213813fd8
[ 1148.933084] ffff88022611a8e0 ffff88015ce92fb0 0000000000000292 ffff88022fc12ad8
[ 1148.933089] Call Trace:
[ 1148.933097] [] ? submit_bio+0x85/0x110
[ 1148.933102] [] ? __lock_page+0x70/0x70
[ 1148.933107] [] schedule+0x29/0x70
[ 1148.933110] [] io_schedule+0x8f/0xd0
[ 1148.933113] [] sleep_on_page+0xe/0x20
[ 1148.933118] [] __wait_on_bit+0x5f/0x90
[ 1148.933121] [] wait_on_page_bit+0x78/0x80
[ 1148.933132] [] ? autoremove_wake_function+0x40/0x40
[ 1148.933151] [] read_extent_buffer_pages+0x32d/0x370 [btrfs]
[ 1148.933160] [] ? verify_parent_transid+0x170/0x170 [btrfs]
[ 1148.933170] [] btree_read_extent_buffer_pages.constprop.114+0xbd/0x130 [btrfs]
[ 1148.933180] [] read_tree_block+0x3a/0x50 [btrfs]
[ 1148.933190] [] open_ctree+0x112d/0x1bb0 [btrfs]
[ 1148.933194] [] ? ida_get_new_above+0x237/0x300
[ 1148.933201] [] btrfs_mount+0x579/0x670 [btrfs]
[ 1148.933204] [] ? pcpu_alloc+0x8ab/0x9b0
[ 1148.933208] [] ? __kmalloc_track_caller+0x1d3/0x220
[ 1148.933211] [] mount_fs+0x20/0xe0
[ 1148.933214] [] vfs_kern_mount+0x76/0x110
[ 1148.933217] [] do_kern_mount+0x54/0x110
[ 1148.933220] [] do_mount+0x54a/0x850
[ 1148.933222] [] ? memdup_user+0x59/0xa0
[ 1148.933224] [] ? strndup_user+0x5b/0x80
[ 1148.933227] [] sys_mount+0x90/0xe0
[ 1148.933230] [] system_call_fastpath+0x16/0x1b

[cwedgwood]

On 3.5.3+

[86837.289593] Btrfs loaded
[86837.297483] device fsid 9501ecbf-f919-420e-962d-48c9045ef815 devid 1 transid 4 /dev/zd16
[86837.311631] btrfs: disk space caching is enabled

[86857.585831] INFO: task mount:21406 blocked for more than 20 seconds.
[86857.592535] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[86857.600894] mount D ffff88062ebf5e20 3384 21406 17620 0x00000000
[86857.608477] ffff8804650c3988 0000000000000086 ffff88062ebf5a80 ffff8804650c3fd8
[86857.616354] ffff8804650c3fd8 0000000000012780 ffffffff817633f0 ffff88062ebf5a80
[86857.624230] ffff880333c12780 ffff880333c12780 ffff88062ebf5a80 ffff8804650c3a40
[86857.632149] Call Trace:
[86857.634731] [] ? __lock_page+0x68/0x68
[86857.640534] [] schedule+0x65/0x67
[86857.645812] [] io_schedule+0x60/0x7a
[86857.651336] [] sleep_on_page+0xe/0x12
[86857.657101] [<ffffffff814ea8aake_function+0x38/0x38
[86857.675803] [] read_extent_buffer_pages+0x1f1/0x244 [btrfs]
[86857.683491] [] ? btrfs_end_buffer_write_sync+0x6e/0x6e [btrfs]
[86857.691406] [] btree_read_extent_buffer_pages.constprop.109+0x66/0xfd [btrfs]
[86857.700770] [] read_tree_block+0x31/0x3d [btrfs]
[86857.707501] [] open_ctree+0xf9a/0x16c9 [btrfs]
[86857.713957] [] btrfs_mount+0x408/0x535 [btrfs]
[86857.720487] [] ? cpumask_next+0x19/0x1b
[86857.726326] [] mount_fs+0x16/0xb1
[86857.731588] [] vfs_kern_mount+0x66/0xea
[86857.742605] [] do_kern_mount+0x4d/0xe3
[86857.748347] [] do_mount+0x645/0x6c8
[86857.753742] [] ? memdup_user+0x3d/0x65
[86857.759502] [] ? strndup_user+0x3b/0x51
[86857.765284] [] sys_mount+0x84/0xc4
[86857.770655] [] system_call_fastpath+0x16/0x1b

[fajarnugraha]

As additional data, createing a loopback device (or scst_local) on TOP of the zvol, then mounting it, made it work. So my guess is some part of block emulation code is wrong, and both losetup and scst_local "fix" it since they basically treat the zvol as a regular file and use their own block device emulation on top of that.

# uname -a
Linux HP 3.5.0-16-generic #25-Ubuntu SMP Fri Sep 28 22:31:15 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux
# zfs create -V 1G -s C/vbd/btrfs
# mkfs.btrfs /dev/zvol/C/vbd/btrfs 
WARNING! - Btrfs Btrfs v0.19 IS EXPERIMENTAL
WARNING! - see http://btrfs.wiki.kernel.org before using
fs created label (null) on /dev/zvol/C/vbd/btrfs
    nodesize 4096 leafsize 4096 sectorsize 4096 size 1.00GB
Btrfs Btrfs v0.19
# losetup /dev/loop0 /dev/zvol/C/vbd/btrfs
# mount /dev/loop0 /mnt/tmp
# df -h /mnt/tmp
Filesystem      Size  Used Avail Use% Mounted on
/dev/loop0      1.0G   56K  894M   1% /mnt/tmp
# umount /mnt/tmp
# losetup -d /dev/loop0

[behlendorf]

@cwedgwood @fajarnugraha Could you please verify/review the proposed fix f6a8d27 , it passes basic sanity testing for me. Chris was nice enough to do all the leg work on this one to get to the root cause.

[cwedgwood]

@behlendorf so far so good, it's not measurably slower (though zvol testing over a ramdisk shows very poor performance for some unrelated reason)

using fio i was able to do some somewhat heavy-io testing to a file-system on top of a zvol with this patch and saw no measurable degradation nor any obvious leaks (if you want to do this use ext2 or xfs not btrfs and the later bogs down to a completely unusable speed)

(let me know if you want the fio config file or test details)