Re: btrfs hang (deadlock?) when trying to create a ext4 filesystem in KVM guest
On Thu, Oct 28, 2010 at 1:29 AM, Tomasz Chmielewski man...@wpkg.org wrote: On 28.10.2010 00:55, Chris Mason wrote: On Wed, Oct 27, 2010 at 03:29:38PM +0200, Tomasz Chmielewski wrote: There are a couple of problems when running KVM guests with images stored on btrfs filesystem. One of them is inability to create a filesystem (i.e. ext4) in the guest: - btrfs filesystem on the host was mounted with noatime,compress-force - guest was using a 50 GB sparse file, - attempt to create a ext4 filesystem within the guest does not succeed (hangs); host prints below messages in dmesg - some deadlock in btrfs? kernel: 2.6.36 qemu-kvm: 0.13.0 Is this the full dmesg output? I think there are other messages hiding in there. There were indeed bad ordered accounting left (see below), I think they are coming from btrfs? Is this a single disk btrfs? Yes. [ 8072.773053] device fsid 1142843480ad2d13-4bdc742fd9b1f7b0 devid 1 transid 1508 /dev/sdb4 [ 8072.773674] btrfs: forcing compression [ 8122.052221] device tap0 entered promiscuous mode [ 8122.052245] br0: port 2(tap0) entering learning state [ 8122.052248] br0: port 2(tap0) entering learning state [ 8122.451587] br0: port 2(tap0) entering learning state [ 8122.543477] br0: port 2(tap0) entering disabled state [ 8122.609645] device tap0 left promiscuous mode [ 8122.609650] br0: port 2(tap0) entering disabled state [ 8131.325647] EXT4-fs (md4): recovery complete [ 8131.325809] EXT4-fs (md4): mounted filesystem with ordered data mode. Opts: (null) [ 8133.392100] device tap0 entered promiscuous mode [ 8133.392127] br0: port 2(tap0) entering learning state [ 8133.392131] br0: port 2(tap0) entering learning state [ 8134.106594] kvm: 5004: cpu0 unhandled wrmsr: 0x198 data 0 [ 8134.106618] kvm: 5004: cpu1 unhandled wrmsr: 0x198 data 0 [ 8143.460927] tap0: no IPv6 routers present [ 8148.359485] br0: port 2(tap0) entering forwarding state [ 8309.103502] bad ordered accounting left 65536 size 385024 [ 8309.106206] bad ordered accounting left 65536 size 385024 [ 8309.108915] bad ordered accounting left 65536 size 385024 [ 8309.111630] bad ordered accounting left 36864 size 385024 [ 8501.965625] INFO: task qemu-system-x86:5148 blocked for more than 120 seconds. [ 8501.965629] echo 0 /proc/sys/kernel/hung_task_timeout_secs disables this message. [ 8501.965632] qemu-system-x D 880001e14cc0 0 5148 4924 0x [ 8501.965638] 880223bc3b38 0086 880223bc3fd8 00014cc0 [ 8501.965642] 00014cc0 880223bc3fd8 00014cc0 880223bc3fd8 [ 8501.965647] 00014cc0 880221965f18 880221965f20 880221965b80 [ 8501.965651] Call Trace: [ 8501.965678] [a024c52c] btrfs_start_ordered_extent+0x6c/0xb0 [btrfs] [ 8501.965685] [81083200] ? autoremove_wake_function+0x0/0x40 [ 8501.965701] [a024d1c2] btrfs_wait_ordered_range+0xd2/0x160 [btrfs] [ 8501.965716] [a0240059] btrfs_file_aio_write+0x269/0x990 [btrfs] [ 8501.965721] [8105ca94] ? try_to_wake_up+0xf4/0x3f0 [ 8501.965726] [81168119] ? __pollwake+0x49/0x50 [ 8501.965730] [8105cd90] ? default_wake_function+0x0/0x20 [ 8501.965733] [8105ca94] ? try_to_wake_up+0xf4/0x3f0 [ 8501.965737] [8116813b] ? pollwake+0x1b/0x20 [ 8501.965752] [a023fdf0] ? btrfs_file_aio_write+0x0/0x990 [btrfs] [ 8501.965761] [8115664b] do_sync_readv_writev+0xcb/0x110 [ 8501.965769] [81294d98] ? apparmor_file_permission+0x18/0x20 [ 8501.965776] [8126356e] ? security_file_permission+0x1e/0x80 [ 8501.965781] [811576e0] do_readv_writev+0xd0/0x1d0 [ 8501.965787] [81076d72] ? kill_something_info+0x42/0x130 [ 8501.965793] [81076ee0] ? sys_kill+0x80/0x90 [ 8501.965798] [8115781e] vfs_writev+0x3e/0x60 [ 8501.965802] [811578e7] sys_pwritev+0xa7/0xc0 [ 8501.965806] [8100b0f2] system_call_fastpath+0x16/0x1b [ 8501.965810] INFO: task qemu-system-x86:5150 blocked for more than 120 seconds. [ 8501.965812] echo 0 /proc/sys/kernel/hung_task_timeout_secs disables this message. [ 8501.965814] qemu-system-x D 880001e94cc0 0 5150 4924 0x [ 8501.965819] 8801aba4bb38 0086 8801aba4bfd8 00014cc0 [ 8501.965823] 00014cc0 8801aba4bfd8 00014cc0 8801aba4bfd8 [ 8501.965827] 00014cc0 880226d14838 880226d14840 880226d144a0 [ 8501.965832] Call Trace: [ 8501.965847] [a024c52c] btrfs_start_ordered_extent+0x6c/0xb0 [btrfs] [ 8501.965852] [81083200] ? autoremove_wake_function+0x0/0x40 [ 8501.965867] [a024d1c2] btrfs_wait_ordered_range+0xd2/0x160 [btrfs] [ 8501.965883] [a0240059] btrfs_file_aio_write+0x269/0x990 [btrfs] [ 8501.965887] [8105ca94] ? try_to_wake_up+0xf4/0x3f0 [ 8501.965891] [81168119] ?
Re: btrfs hang (deadlock?) when trying to create a ext4 filesystem in KVM guest
Excerpts from C Anthony Risinger's message of 2010-12-15 11:46:11 -0500: On Thu, Oct 28, 2010 at 1:29 AM, Tomasz Chmielewski man...@wpkg.org wrote: On 28.10.2010 00:55, Chris Mason wrote: On Wed, Oct 27, 2010 at 03:29:38PM +0200, Tomasz Chmielewski wrote: There are a couple of problems when running KVM guests with images stored on btrfs filesystem. One of them is inability to create a filesystem (i.e. ext4) in the guest: - btrfs filesystem on the host was mounted with noatime,compress-force - guest was using a 50 GB sparse file, - attempt to create a ext4 filesystem within the guest does not succeed (hangs); host prints below messages in dmesg - some deadlock in btrfs? kernel: 2.6.36 qemu-kvm: 0.13.0 Is this the full dmesg output? I think there are other messages hiding in there. There were indeed bad ordered accounting left (see below), I think they are coming from btrfs? Is this a single disk btrfs? Yes. [ 8072.773053] device fsid 1142843480ad2d13-4bdc742fd9b1f7b0 devid 1 transid 1508 /dev/sdb4 [ 8072.773674] btrfs: forcing compression [ 8122.052221] device tap0 entered promiscuous mode [ 8122.052245] br0: port 2(tap0) entering learning state [ 8122.052248] br0: port 2(tap0) entering learning state [ 8122.451587] br0: port 2(tap0) entering learning state [ 8122.543477] br0: port 2(tap0) entering disabled state [ 8122.609645] device tap0 left promiscuous mode [ 8122.609650] br0: port 2(tap0) entering disabled state [ 8131.325647] EXT4-fs (md4): recovery complete [ 8131.325809] EXT4-fs (md4): mounted filesystem with ordered data mode. Opts: (null) [ 8133.392100] device tap0 entered promiscuous mode [ 8133.392127] br0: port 2(tap0) entering learning state [ 8133.392131] br0: port 2(tap0) entering learning state [ 8134.106594] kvm: 5004: cpu0 unhandled wrmsr: 0x198 data 0 [ 8134.106618] kvm: 5004: cpu1 unhandled wrmsr: 0x198 data 0 [ 8143.460927] tap0: no IPv6 routers present [ 8148.359485] br0: port 2(tap0) entering forwarding state [ 8309.103502] bad ordered accounting left 65536 size 385024 [ 8309.106206] bad ordered accounting left 65536 size 385024 [ 8309.108915] bad ordered accounting left 65536 size 385024 [ 8309.111630] bad ordered accounting left 36864 size 385024 [ 8501.965625] INFO: task qemu-system-x86:5148 blocked for more than 120 seconds. [ 8501.965629] echo 0 /proc/sys/kernel/hung_task_timeout_secs disables this message. [ 8501.965632] qemu-system-x D 880001e14cc0 0 5148 4924 0x [ 8501.965638] 880223bc3b38 0086 880223bc3fd8 00014cc0 [ 8501.965642] 00014cc0 880223bc3fd8 00014cc0 880223bc3fd8 [ 8501.965647] 00014cc0 880221965f18 880221965f20 880221965b80 [ 8501.965651] Call Trace: [ 8501.965678] [a024c52c] btrfs_start_ordered_extent+0x6c/0xb0 [btrfs] [ 8501.965685] [81083200] ? autoremove_wake_function+0x0/0x40 [ 8501.965701] [a024d1c2] btrfs_wait_ordered_range+0xd2/0x160 [btrfs] [ 8501.965716] [a0240059] btrfs_file_aio_write+0x269/0x990 [btrfs] [ 8501.965721] [8105ca94] ? try_to_wake_up+0xf4/0x3f0 [ 8501.965726] [81168119] ? __pollwake+0x49/0x50 [ 8501.965730] [8105cd90] ? default_wake_function+0x0/0x20 [ 8501.965733] [8105ca94] ? try_to_wake_up+0xf4/0x3f0 [ 8501.965737] [8116813b] ? pollwake+0x1b/0x20 [ 8501.965752] [a023fdf0] ? btrfs_file_aio_write+0x0/0x990 [btrfs] [ 8501.965761] [8115664b] do_sync_readv_writev+0xcb/0x110 [ 8501.965769] [81294d98] ? apparmor_file_permission+0x18/0x20 [ 8501.965776] [8126356e] ? security_file_permission+0x1e/0x80 [ 8501.965781] [811576e0] do_readv_writev+0xd0/0x1d0 [ 8501.965787] [81076d72] ? kill_something_info+0x42/0x130 [ 8501.965793] [81076ee0] ? sys_kill+0x80/0x90 [ 8501.965798] [8115781e] vfs_writev+0x3e/0x60 [ 8501.965802] [811578e7] sys_pwritev+0xa7/0xc0 [ 8501.965806] [8100b0f2] system_call_fastpath+0x16/0x1b [ 8501.965810] INFO: task qemu-system-x86:5150 blocked for more than 120 seconds. [ 8501.965812] echo 0 /proc/sys/kernel/hung_task_timeout_secs disables this message. [ 8501.965814] qemu-system-x D 880001e94cc0 0 5150 4924 0x [ 8501.965819] 8801aba4bb38 0086 8801aba4bfd8 00014cc0 [ 8501.965823] 00014cc0 8801aba4bfd8 00014cc0 8801aba4bfd8 [ 8501.965827] 00014cc0 880226d14838 880226d14840 880226d144a0 [ 8501.965832] Call Trace: [ 8501.965847] [a024c52c] btrfs_start_ordered_extent+0x6c/0xb0 [btrfs] [ 8501.965852] [81083200] ? autoremove_wake_function+0x0/0x40 [ 8501.965867] [a024d1c2] btrfs_wait_ordered_range+0xd2/0x160 [btrfs] [
Re: btrfs hang (deadlock?) when trying to create a ext4 filesystem in KVM guest
On 28.10.2010 00:55, Chris Mason wrote: On Wed, Oct 27, 2010 at 03:29:38PM +0200, Tomasz Chmielewski wrote: There are a couple of problems when running KVM guests with images stored on btrfs filesystem. One of them is inability to create a filesystem (i.e. ext4) in the guest: - btrfs filesystem on the host was mounted with noatime,compress-force - guest was using a 50 GB sparse file, - attempt to create a ext4 filesystem within the guest does not succeed (hangs); host prints below messages in dmesg - some deadlock in btrfs? kernel: 2.6.36 qemu-kvm: 0.13.0 Is this the full dmesg output? I think there are other messages hiding in there. There were indeed bad ordered accounting left (see below), I think they are coming from btrfs? Is this a single disk btrfs? Yes. [ 8072.773053] device fsid 1142843480ad2d13-4bdc742fd9b1f7b0 devid 1 transid 1508 /dev/sdb4 [ 8072.773674] btrfs: forcing compression [ 8122.052221] device tap0 entered promiscuous mode [ 8122.052245] br0: port 2(tap0) entering learning state [ 8122.052248] br0: port 2(tap0) entering learning state [ 8122.451587] br0: port 2(tap0) entering learning state [ 8122.543477] br0: port 2(tap0) entering disabled state [ 8122.609645] device tap0 left promiscuous mode [ 8122.609650] br0: port 2(tap0) entering disabled state [ 8131.325647] EXT4-fs (md4): recovery complete [ 8131.325809] EXT4-fs (md4): mounted filesystem with ordered data mode. Opts: (null) [ 8133.392100] device tap0 entered promiscuous mode [ 8133.392127] br0: port 2(tap0) entering learning state [ 8133.392131] br0: port 2(tap0) entering learning state [ 8134.106594] kvm: 5004: cpu0 unhandled wrmsr: 0x198 data 0 [ 8134.106618] kvm: 5004: cpu1 unhandled wrmsr: 0x198 data 0 [ 8143.460927] tap0: no IPv6 routers present [ 8148.359485] br0: port 2(tap0) entering forwarding state [ 8309.103502] bad ordered accounting left 65536 size 385024 [ 8309.106206] bad ordered accounting left 65536 size 385024 [ 8309.108915] bad ordered accounting left 65536 size 385024 [ 8309.111630] bad ordered accounting left 36864 size 385024 [ 8501.965625] INFO: task qemu-system-x86:5148 blocked for more than 120 seconds. [ 8501.965629] echo 0 /proc/sys/kernel/hung_task_timeout_secs disables this message. [ 8501.965632] qemu-system-x D 880001e14cc0 0 5148 4924 0x [ 8501.965638] 880223bc3b38 0086 880223bc3fd8 00014cc0 [ 8501.965642] 00014cc0 880223bc3fd8 00014cc0 880223bc3fd8 [ 8501.965647] 00014cc0 880221965f18 880221965f20 880221965b80 [ 8501.965651] Call Trace: [ 8501.965678] [a024c52c] btrfs_start_ordered_extent+0x6c/0xb0 [btrfs] [ 8501.965685] [81083200] ? autoremove_wake_function+0x0/0x40 [ 8501.965701] [a024d1c2] btrfs_wait_ordered_range+0xd2/0x160 [btrfs] [ 8501.965716] [a0240059] btrfs_file_aio_write+0x269/0x990 [btrfs] [ 8501.965721] [8105ca94] ? try_to_wake_up+0xf4/0x3f0 [ 8501.965726] [81168119] ? __pollwake+0x49/0x50 [ 8501.965730] [8105cd90] ? default_wake_function+0x0/0x20 [ 8501.965733] [8105ca94] ? try_to_wake_up+0xf4/0x3f0 [ 8501.965737] [8116813b] ? pollwake+0x1b/0x20 [ 8501.965752] [a023fdf0] ? btrfs_file_aio_write+0x0/0x990 [btrfs] [ 8501.965761] [8115664b] do_sync_readv_writev+0xcb/0x110 [ 8501.965769] [81294d98] ? apparmor_file_permission+0x18/0x20 [ 8501.965776] [8126356e] ? security_file_permission+0x1e/0x80 [ 8501.965781] [811576e0] do_readv_writev+0xd0/0x1d0 [ 8501.965787] [81076d72] ? kill_something_info+0x42/0x130 [ 8501.965793] [81076ee0] ? sys_kill+0x80/0x90 [ 8501.965798] [8115781e] vfs_writev+0x3e/0x60 [ 8501.965802] [811578e7] sys_pwritev+0xa7/0xc0 [ 8501.965806] [8100b0f2] system_call_fastpath+0x16/0x1b [ 8501.965810] INFO: task qemu-system-x86:5150 blocked for more than 120 seconds. [ 8501.965812] echo 0 /proc/sys/kernel/hung_task_timeout_secs disables this message. [ 8501.965814] qemu-system-x D 880001e94cc0 0 5150 4924 0x [ 8501.965819] 8801aba4bb38 0086 8801aba4bfd8 00014cc0 [ 8501.965823] 00014cc0 8801aba4bfd8 00014cc0 8801aba4bfd8 [ 8501.965827] 00014cc0 880226d14838 880226d14840 880226d144a0 [ 8501.965832] Call Trace: [ 8501.965847] [a024c52c] btrfs_start_ordered_extent+0x6c/0xb0 [btrfs] [ 8501.965852] [81083200] ? autoremove_wake_function+0x0/0x40 [ 8501.965867] [a024d1c2] btrfs_wait_ordered_range+0xd2/0x160 [btrfs] [ 8501.965883] [a0240059] btrfs_file_aio_write+0x269/0x990 [btrfs] [ 8501.965887] [8105ca94] ? try_to_wake_up+0xf4/0x3f0 [ 8501.965891] [81168119] ? __pollwake+0x49/0x50 [ 8501.965894] [8105cd90] ? default_wake_function+0x0/0x20 [ 8501.965897] [8105ca94] ? try_to_wake_up+0xf4/0x3f0 [ 8501.965901]
Re: btrfs hang (deadlock?) when trying to create a ext4 filesystem in KVM guest
On Wed, Oct 27, 2010 at 03:29:38PM +0200, Tomasz Chmielewski wrote: There are a couple of problems when running KVM guests with images stored on btrfs filesystem. One of them is inability to create a filesystem (i.e. ext4) in the guest: - btrfs filesystem on the host was mounted with noatime,compress-force - guest was using a 50 GB sparse file, - attempt to create a ext4 filesystem within the guest does not succeed (hangs); host prints below messages in dmesg - some deadlock in btrfs? kernel: 2.6.36 qemu-kvm: 0.13.0 Is this the full dmesg output? I think there are other messages hiding in there. Is this a single disk btrfs? -chris [22748.830644] INFO: task qemu-system-x86:5186 blocked for more than 120 seconds. [22748.830649] echo 0 /proc/sys/kernel/hung_task_timeout_secs disables this message. [22748.830653] qemu-system-x D 880001e34cc0 0 5186 4768 0x0004 [22748.830660] 8801ed3f9b38 0086 8801ed3f9fd8 00014cc0 [22748.830666] 00014cc0 8801ed3f9fd8 00014cc0 8801ed3f9fd8 [22748.830672] 00014cc0 88002dc43158 88002dc43160 88002dc42dc0 [22748.830678] Call Trace: [22748.830712] [a024252c] btrfs_start_ordered_extent+0x6c/0xb0 [btrfs] [22748.830723] [81083200] ? autoremove_wake_function+0x0/0x40 [22748.830744] [a02431c2] btrfs_wait_ordered_range+0xd2/0x160 [btrfs] [22748.830762] [a0236059] btrfs_file_aio_write+0x269/0x990 [btrfs] [22748.830767] [8105ca94] ? try_to_wake_up+0xf4/0x3f0 [22748.830773] [81168119] ? __pollwake+0x49/0x50 [22748.830776] [8105cd90] ? default_wake_function+0x0/0x20 [22748.830780] [8116813b] ? pollwake+0x1b/0x20 [22748.830795] [a0235df0] ? btrfs_file_aio_write+0x0/0x990 [btrfs] [22748.830799] [8115664b] do_sync_readv_writev+0xcb/0x110 [22748.830804] [81076736] ? send_signal+0x56/0xa0 [22748.830808] [81294d98] ? apparmor_file_permission+0x18/0x20 [22748.830813] [8126356e] ? security_file_permission+0x1e/0x80 [22748.830817] [811576e0] do_readv_writev+0xd0/0x1d0 [22748.830821] [8115781e] vfs_writev+0x3e/0x60 [22748.830824] [811578e7] sys_pwritev+0xa7/0xc0 [22748.830828] [8100b0f2] system_call_fastpath+0x16/0x1b [22748.830832] INFO: task qemu-system-x86:5187 blocked for more than 120 seconds. [22748.830834] echo 0 /proc/sys/kernel/hung_task_timeout_secs disables this message. [22748.830837] qemu-system-x D 880001ed4cc0 0 5187 4768 0x0004 [22748.830841] 8801b264db38 0086 8801b264dfd8 00014cc0 [22748.830846] 00014cc0 8801b264dfd8 00014cc0 8801b264dfd8 [22748.830850] 00014cc0 88002dc45f18 88002dc45f20 88002dc45b80 [22748.830854] Call Trace: [22748.830869] [a024252c] btrfs_start_ordered_extent+0x6c/0xb0 [btrfs] [22748.830874] [81083200] ? autoremove_wake_function+0x0/0x40 [22748.830889] [a02431c2] btrfs_wait_ordered_range+0xd2/0x160 [btrfs] [22748.830904] [a0236059] btrfs_file_aio_write+0x269/0x990 [btrfs] [22748.830910] [81044221] ? gup_pud_range+0xb1/0x100 [22748.830915] [812c5590] ? vsnprintf+0x390/0x530 [22748.830930] [a0235df0] ? btrfs_file_aio_write+0x0/0x990 [btrfs] [22748.830934] [8115664b] do_sync_readv_writev+0xcb/0x110 [22748.830938] [8115753d] ? rw_copy_check_uvector+0x7d/0x150 [22748.830942] [81294d98] ? apparmor_file_permission+0x18/0x20 [22748.830946] [8126356e] ? security_file_permission+0x1e/0x80 [22748.830949] [811576e0] do_readv_writev+0xd0/0x1d0 [22748.830953] [8115781e] vfs_writev+0x3e/0x60 [22748.830956] [811578e7] sys_pwritev+0xa7/0xc0 [22748.830960] [8100b0f2] system_call_fastpath+0x16/0x1b [22748.830963] INFO: task qemu-system-x86:5188 blocked for more than 120 seconds. [22748.830965] echo 0 /proc/sys/kernel/hung_task_timeout_secs disables this message. [22748.830968] qemu-system-x D 880001e34cc0 0 5188 4768 0x0004 [22748.830972] 880134911b38 0086 880134911fd8 00014cc0 [22748.830976] 00014cc0 880134911fd8 00014cc0 880134911fd8 [22748.830980] 00014cc0 88002dc41a78 88002dc41a80 88002dc416e0 [22748.830984] Call Trace: [22748.830999] [a024252c] btrfs_start_ordered_extent+0x6c/0xb0 [btrfs] [22748.831004] [81083200] ? autoremove_wake_function+0x0/0x40 [22748.831019] [a02431c2] btrfs_wait_ordered_range+0xd2/0x160 [btrfs] [22748.831034] [a0236059] btrfs_file_aio_write+0x269/0x990 [btrfs] [22748.831038] [8105b564] ? find_busiest_group+0x544/0xa70 [22748.831054] [a0235df0] ? btrfs_file_aio_write+0x0/0x990 [btrfs] [22748.831058] [8115664b]
